My apologies, Wietse. I’m having issues with timeouts after ehlo (or helo), before postfix responds with a 250 status. Some senders don’t have any issue at all (gmail). Some senders can’t get any mail through (verizon). Some are hit and miss, with a long (multiple minute) delay on the ones which make it.
The first clue I believe I’m missing, is the source of the 421 timeout expired messages. I haven’t quite grasped or found what in postfix triggers the daemon to send this response. I’m probably (hopefully) missing something simple here. postconf -n ------------------ alias_maps = hash:/etc/aliases always_add_missing_headers = yes always_bcc = [email protected] bounce_notice_recipient = postmaster bounce_queue_lifetime = 5d broken_sasl_auth_clients = yes command_directory = /opt/zimbra/postfix/sbin config_directory = /opt/zimbra/postfix-2.7.8.3z/conf content_filter = smtp-amavis:[127.0.0.1]:10024 daemon_directory = /opt/zimbra/postfix/libexec delay_warning_time = 0h disable_dns_lookups = no header_checks = in_flow_delay = 1s inet_protocols = ipv4 lmtp_connection_cache_destinations = lmtp_connection_cache_time_limit = 4s lmtp_host_lookup = dns local_header_rewrite_clients = permit_mynetworks,permit_sasl_authenticated mail_owner = postfix mailbox_size_limit = 0 mailq_path = /opt/zimbra/postfix/sbin/mailq manpage_directory = /opt/zimbra/postfix/man maximal_backoff_time = 4000s message_size_limit = 30720000 minimal_backoff_time = 300s mydestination = localhost myhostname = mail.AAAAA.com mynetworks = 127.0.0.0/8 172.16.0.0/17 204.2.DD.DDD/27 192.168.132.0/24 [::1]/128 newaliases_path = /opt/zimbra/postfix/sbin/newaliases non_smtpd_milters = notify_classes = resource,software propagate_unmatched_extensions = canonical queue_directory = /opt/zimbra/data/postfix/spool queue_run_delay = 300s recipient_delimiter = relayhost = sender_canonical_maps = proxy:ldap:/opt/zimbra/conf/ldap-scm.cf sendmail_path = /opt/zimbra/postfix/sbin/sendmail setgid_group = postdrop smtpd_client_restrictions = reject_unauth_pipelining smtpd_data_restrictions = reject_unauth_pipelining smtpd_helo_required = yes smtpd_milters = smtpd_recipient_restrictions = reject_non_fqdn_recipient, permit_sasl_authenticated, permit_mynetworks, reject_unauth_destination, reject_unlisted_recipient, reject_non_fqdn_sender, reject_unknown_sender_domain, reject_rbl_client cbl.abuseat.org reject_rbl_client dnsbl.sorbs.net, permit smtpd_reject_unlisted_recipient = no smtpd_sasl_auth_enable = yes smtpd_sasl_authenticated_header = no smtpd_sender_restrictions = smtpd_tls_auth_only = no smtpd_tls_cert_file = /opt/zimbra/conf/smtpd.crt smtpd_tls_key_file = /opt/zimbra/conf/smtpd.key smtpd_tls_loglevel = 1 smtpd_tls_security_level = may transport_maps = proxy:ldap:/opt/zimbra/conf/ldap-transport.cf virtual_alias_domains = proxy:ldap:/opt/zimbra/conf/ldap-vad.cf virtual_alias_maps = proxy:ldap:/opt/zimbra/conf/ldap-vam.cf virtual_mailbox_domains = proxy:ldap:/opt/zimbra/conf/ldap-vmd.cf virtual_mailbox_maps = proxy:ldap:/opt/zimbra/conf/ldap-vmm.cf virtual_transport = error relevant (I believe) log output (note the timestamps - verizon waits 5 minutes and gives up): ------------------ Apr 16 12:57:45 mail postfix/smtpd[18647]: connect from vms173001pub.verizon.net[206.46.173.1] Apr 16 13:02:45 mail postfix/smtpd[18647]: timeout after EHLO from vms173001pub.verizon.net[206.46.173.1] Apr 16 13:02:45 mail postfix/smtpd[18647]: disconnect from vms173001pub.verizon.net[206.46.173.1] gmail, however, delivers quite reasonably: ------------------ Apr 16 13:54:29 mail postfix/smtpd[18169]: connect from mail-ob0-f180.google.com[209.85.214.180] Apr 16 13:54:29 mail postfix/smtpd[18169]: setting up TLS connection from mail-ob0-f180.google.com[209.85.214.180] Apr 16 13:54:29 mail postfix/smtpd[18169]: Anonymous TLS connection established from mail-ob0-f180.google.com[209.85.214.180]: TLSv1 with cipher RC4-SHA (128/128 bits) Apr 16 13:54:29 mail postfix/smtpd[18169]: 985792F872FF: client=mail-ob0-f180.google.com[209.85.214.180] Apr 16 13:54:29 mail postfix/cleanup[14592]: 985792F872FF: message-id=<[email protected]> Apr 16 13:54:29 mail postfix/qmgr[10700]: 985792F872FF: from=<[email protected]>, size=1824, nrcpt=2 (queue active) Apr 16 13:54:29 mail postfix/smtpd[18169]: disconnect from mail-ob0-f180.google.com[209.85.214.180] Apr 16 13:54:35 mail postfix/cleanup[14592]: C46762F872A4: message-id=<[email protected]> Apr 16 13:54:36 mail postfix/qmgr[10700]: C46762F872A4: from=<[email protected]>, size=2562, nrcpt=2 (queue active) Apr 16 13:54:36 mail postfix/smtpd[11502]: disconnect from localhost[127.0.0.1] Apr 16 13:54:36 mail postfix/smtp[18542]: 985792F872FF: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=6.5, delays=0.15/0/0/6.4, dsn=2.0.0, status=sent (250 2.0.0 from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as C46762F872A4) Apr 16 13:54:36 mail postfix/qmgr[10700]: 985792F872FF: removed Apr 16 13:54:36 mail postfix/lmtp[20839]: C46762F872A4: to=<[email protected]>, relay=mail.AAAAA.com[172.16.5.8]:7025, delay=0.3, delays=0.21/0/0/0.08, dsn=2.1.5, status=sent (250 2.1.5 Delivery OK) Apr 16 13:54:36 mail postfix/qmgr[10700]: C46762F872A4: removed tcpdump transcript from a session from verizon: ————————— 14:04:31.380151 IP 206.46.173.11.19129 > 172.16.5.8.25: Flags [S], seq 2166779183, win 32850, options [mss 1460,nop,nop,TS val 1770681371 ecr 0,nop,wscale 1,nop,nop,sackOK], length 0 E..@[email protected]....&m/.......Rr.......... i.t............. 14:04:31.380189 IP 172.16.5.8.25 > 206.46.173.11.19129: Flags [S.], seq 231398915, ack 2166779184, win 5792, options [mss 1460,sackOK,TS val 386720902 ecr 1770681371,nop,wscale 7], length 0 ....&m0...............J. ....i.t..... 14:04:31.402044 IP 206.46.173.11.19129 > 172.16.5.8.25: Flags [.], ack 1, win 33304, options [nop,nop,TS val 1770681373 ecr 386720902], length 0 ....................J....&m0 i.t..... 14:04:31.404948 IP 172.16.5.8.25 > 206.46.173.11.19129: Flags [P.], seq 1:35, ack 1, win 46, options [nop,nop,TS val 386720904 ecr 1770681373], length 34 ....&m0....,..........J. ....i.t.220 mail.AAAAA.com ESMTP Postfix 14:04:31.425056 IP 206.46.173.11.19129 > 172.16.5.8.25: Flags [.], ack 35, win 33304, options [nop,nop,TS val 1770681376 ecr 386720904], length 0 ..&.................J....&m0 i.t .... 14:04:31.425332 IP 206.46.173.11.19129 > 172.16.5.8.25: Flags [P.], seq 1:32, ack 35, win 33304, options [nop,nop,TS val 1770681376 ecr 386720904], length 31 ..&.....4...........J....&m0 i.t ....EHLO vms173011pub.verizon.net 14:04:31.425346 IP 172.16.5.8.25 > 206.46.173.11.19129: Flags [.], ack 32, win 46, options [nop,nop,TS val 386720906 ecr 1770681376], length 0 ..&.&mO....K..........J. ....i.t 14:04:31.425682 IP 172.16.5.8.25 > 206.46.173.11.19129: Flags [P.], seq 35:216, ack 32, win 46, options [nop,nop,TS val 386720906 ecr 1770681376], length 181 ..&.&mO....-..........J. ....i.t 250-mail.AAAAA.com 250-PIPELINING 250-SIZE 30720000 250-VRFY 250-ETRN 250-STARTTLS 250-AUTH LOGIN PLAIN 250-AUTH=LOGIN PLAIN 250-ENHANCEDSTATUSCODES 250-8BITMIME 250 DSN 14:04:31.445742 IP 206.46.173.11.19129 > 172.16.5.8.25: Flags [.], ack 216, win 33304, options [nop,nop,TS val 1770681378 ecr 386720906], length 0 ........ ...........J....&mO i.t".... 14:04:41.434870 IP 172.16.5.8.25 > 206.46.173.11.19129: Flags [P.], seq 216:266, ack 32, win 46, options [nop,nop,TS val 386721907 ecr 1770681378], length 50 ....&mO....,..........J. ...si.t"421 4.4.2 mail.AAAAA.com Error: timeout exceeded 14:04:41.434892 IP 172.16.5.8.25 > 206.46.173.11.19129: Flags [F.], seq 266, ack 32, win 46, options [nop,nop,TS val 386721907 ecr 1770681378], length 0 .&mO....F.............J. ...si.t" 14:04:41.648557 IP 172.16.5.8.25 > 206.46.173.11.19129: Flags [P.], seq 216:266, ack 32, win 46, options [nop,nop,TS val 386721929 ecr 1770681378], length 50 ....&mO....,..........J. ....i.t"421 4.4.2 mail.AAAAA.com Error: timeout exceeded 14:04:42.088568 IP 172.16.5.8.25 > 206.46.173.11.19129: Flags [P.], seq 216:266, ack 32, win 46, options [nop,nop,TS val 386721973 ecr 1770681378], length 50 ....&mO....,..........J. ....i.t"421 4.4.2 mail.AAAAA.com Error: timeout exceeded (nothing ever showed up after this. after about 6 minutes, a new session started from a different source IP in the same netblock, but otherwise looks identical.) A different transcript, this time from a computer I have control over: ------------------ 13:41:13.780801 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 0 E..<,[email protected]......./..uE........9.QK......... .S' ........ 13:41:13.780841 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..<..@[email protected]...../x.c.uE.......~......... . ...S' .... 13:41:13.801370 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 0 E..4,[email protected]......./..uE..x.c......T..... .S'%. .. 13:41:13.805214 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 34 E..V. @.@..[....ct...../x.c.uE.......o..... . ...S'%220 mail.AAAAA.com ESMTP Postfix 13:41:13.827599 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 0 E..4,[email protected]......./..uE..x.c......*..... .S'+. .. 13:41:27.233026 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 53 E..i,[email protected]......./..uE..x.c............ .S4C. ..helo 99.116.DDD.DDD.lightspeed.hstntx.sbcglobal.net 13:41:27.233080 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..4.!@.@..|....ct...../x.c.uE............. . ...S4C 13:41:27.233226 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 20 E..H."@[email protected]...../x.c.uE.......a..... . ...S4C250 mail.AAAAA.com 13:41:27.252187 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 0 E..4,[email protected]......./..uE..x.c............ .S4H. .. 13:42:48.818799 IP 172.16.5.8.25 > 99.116.DDD.DDD.36397: tcp 50 E..f.!@[email protected]................. . ...R^.421 4.4.2 mail.AAAAA.com Error: timeout exceeded 13:42:48.819487 IP 172.16.5.8.25 > 99.116.DDD.DDD.36397: tcp 0 E..4."@[email protected]{....ct.....-.-.'............... . ...R^. 13:42:49.038559 IP 172.16.5.8.25 > 99.116.DDD.DDD.36397: tcp 50 E..f.#@[email protected]................. . ...R^.421 4.4.2 mail.AAAAA.com Error: timeout exceeded 13:42:49.478546 IP 172.16.5.8.25 > 99.116.DDD.DDD.36397: tcp 50 E..f.$@[email protected]................. . ...R^.421 4.4.2 mail.AAAAA.com Error: timeout exceeded 13:43:28.693793 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 28 E..P,[email protected]......./..uE..x.c............ .S... ..mail from:[email protected] 13:43:28.699349 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 14 E..B.#@[email protected]...../x.c.uE.......[..... . .J.S..250 2.1.0 Ok 13:43:28.719369 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 0 E..4,[email protected]......./..uE..x.c.....FJ..... .S... .J 13:43:39.437059 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 27 E..O,[email protected]......./..uE..x.c......>..... .S.]. .Jrcpt to:[email protected] 13:43:39.468554 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..4.$@[email protected]...../x.c.uE......:...... . ...S.] 13:43:39.540206 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 14 E..B.%@[email protected]...../x.c.uE.......[..... . ...S.]250 2.1.5 Ok 13:43:39.560626 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 0 E..4,[email protected]......./..uE..x.d ....7O..... .S.|. .. 13:43:41.715037 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 6 E..:,[email protected]......./..uE..x.d ....OY..... .S... ..data 13:43:41.715078 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..4.&@[email protected]...../x.d uE......7...... . ._.S.. 13:43:41.715296 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 37 E..Y.'@[email protected]...../x.d uE.......r..... . ._.S..354 End data with <CR><LF>.<CR><LF> 13:43:41.737186 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 0 E..4,[email protected]......./..uE..x.d/....4+..... .S... ._ 13:43:43.300442 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 2 E..6,[email protected]......./..uE..x.d/....%...... .S.#. ._ 13:43:43.338557 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..4.(@[email protected]...../x.d/uE......5b..... . ...S.# 13:43:49.732041 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 38 E..Z,[email protected]......./..uE..x.d/..... ..... .S.k. ..From:Brian Grimal <[email protected]> 13:43:49.732072 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..4.)@[email protected]...../x.d/uE.#....,u..... . ...S.k 13:43:55.836217 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 37 E..Y,[email protected]......./..uE.#x.d/.....\..... .S.a. ..To:Brian Grimal <[email protected]> 13:43:55.836237 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..4.*@[email protected]...../x.d/uE.H....#...... .....S.a 13:44:01.372753 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 25 E..M,[email protected]......./..uE.Hx.d/........... .S......Subject:Test via telnet 13:44:01.372778 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..4.+@[email protected]...../x.d/uE.a.....M..... .S.. 13:44:01.524916 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 2 E..6,[email protected]......./..uE.ax.d/........... .S..... 13:44:01.524933 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..4.,@[email protected]...../x.d/uE.c........... .....S.. 13:44:10.324611 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 55 E..k,[email protected]......./..uE.cx.d/........... .S......This email was severely delayed (approx 2 minutes)... 13:44:10.324643 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..4.-@[email protected]...../x.d/uE............. .....S.. 13:44:10.436376 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 2 E..6,[email protected]......./..uE..x.d/.....C..... .S...... 13:44:10.436401 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..4..@[email protected]...../x.d/uE............. .....S.. 13:44:10.948663 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 3 E..7,[email protected]......./..uE..x.d/........... .S.#..... 13:44:10.948685 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 E..4./@[email protected]...../x.d/uE............. .....S.# 13:44:10.957191 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 38 E..Z.0@[email protected]...../x.d/uE.......s..... .....S.#250 2.0.0 Ok: queued as 83C582F872FF 13:44:10.976885 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 0 E..4,[email protected]......./..uE..x.dU.....g..... .S.*.... 13:44:12.101034 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 6 E..:,[email protected]......./..uE..x.dU...."L..... .S.C....quit 13:44:12.101949 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 15 E..C.1@.@..]....ct...../x.dUuE.......\..... ...>.S.C221 2.0.0 Bye 13:44:12.101970 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 (.....@[email protected]...../x.dduE...... ...>.S.C 13:44:12.122931 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 0 E..@,[email protected]......./..uE..x.dU........... .S.I....... x.ddx.de 13:44:12.122955 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 0 E..4,[email protected]......./..uE..x.de.... ...... .S.I...> 13:44:12.123084 IP 99.116.DDD.DDD.36399 > 172.16.5.8.25: tcp 0 E..4,[email protected]......./..uE..x.de.... ...... .S.I...> 13:44:12.123101 IP 172.16.5.8.25 > 99.116.DDD.DDD.36399: tcp 0 ......@[email protected]...../x.deuE...... [email protected] Brian On Apr 16, 2014, at 12:41 PM, Wietse Venema <[email protected]> wrote: > Brian Grimal: >> after ehlo. I?ve telnetted into the box from off-site (regular >> host, not a mail server), and it immediately connects, immediately >> responds with the 220 mail.zzzz.com ESMTP Postfix herald, and >> immediately responds to the helo or ehlo. However, it will take >> about two minutes to respond to mail-from. Once it eventually > > Hey, people here are not telepathic. Follow instructions in the > mailing list welcome message. > > Wietse
