I am definitely seeing stress adaptives kick in, exactly as they should. So I do understand the reduction in postfix’ willingness to wait around for that next packet. The piece of the puzzle I’m still missing however, is what’s going on that certain mailers aren’t giving up the packet to begin with. It’s too many providers to point fingers at any one, for sure. Adding debug_peer_list = verizon in main.cf, I got this:
Apr 16 13:32:20 mail postfix/smtpd[12387]: connect from vms173009pub.verizon.net[206.46.173.9] Apr 16 13:32:20 mail postfix/smtpd[12387]: match_hostname: vms173009pub.verizon.net ~? 127.0.0.0/8 Apr 16 13:32:20 mail postfix/smtpd[12387]: match_hostaddr: 206.46.173.9 ~? 127.0.0.0/8 Apr 16 13:32:20 mail postfix/smtpd[12387]: match_hostname: vms173009pub.verizon.net ~? 172.16.0.0/17 Apr 16 13:32:20 mail postfix/smtpd[12387]: match_hostaddr: 206.46.173.9 ~? 172.16.0.0/17 Apr 16 13:32:20 mail postfix/smtpd[12387]: match_hostname: vms173009pub.verizon.net ~? 204.2.DD.DDD/27 Apr 16 13:32:20 mail postfix/smtpd[12387]: match_hostaddr: 206.46.173.9 ~? 204.2.DD.DDD/27 Apr 16 13:32:20 mail postfix/smtpd[12387]: match_hostname: vms173009pub.verizon.net ~? 192.168.132.0/24 Apr 16 13:32:20 mail postfix/smtpd[12387]: match_hostaddr: 206.46.173.9 ~? 192.168.132.0/24 Apr 16 13:32:20 mail postfix/smtpd[12387]: match_hostname: vms173009pub.verizon.net ~? [::1]/128 Apr 16 13:32:20 mail postfix/smtpd[12387]: match_hostaddr: 206.46.173.9 ~? [::1]/128 Apr 16 13:32:20 mail postfix/smtpd[12387]: match_list_match: vms173009pub.verizon.net: no match Apr 16 13:32:20 mail postfix/smtpd[12387]: match_list_match: 206.46.173.9: no match Apr 16 13:32:20 mail postfix/smtpd[12387]: auto_clnt_open: connected to private/anvil Apr 16 13:32:20 mail postfix/smtpd[12387]: send attr request = connect Apr 16 13:32:20 mail postfix/smtpd[12387]: send attr ident = smtp:206.46.173.9 Apr 16 13:32:20 mail postfix/smtpd[12387]: private/anvil: wanted attribute: status Apr 16 13:32:20 mail postfix/smtpd[12387]: input attribute name: status Apr 16 13:32:20 mail postfix/smtpd[12387]: input attribute value: 0 Apr 16 13:32:20 mail postfix/smtpd[12387]: private/anvil: wanted attribute: count Apr 16 13:32:20 mail postfix/smtpd[12387]: input attribute name: count Apr 16 13:32:20 mail postfix/smtpd[12387]: input attribute value: 1 Apr 16 13:32:20 mail postfix/smtpd[12387]: private/anvil: wanted attribute: rate Apr 16 13:32:20 mail postfix/smtpd[12387]: input attribute name: rate Apr 16 13:32:20 mail postfix/smtpd[12387]: input attribute value: 1 Apr 16 13:32:20 mail postfix/smtpd[12387]: private/anvil: wanted attribute: (list terminator) Apr 16 13:32:20 mail postfix/smtpd[12387]: input attribute name: (end) Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 220 mail.AAAAA.com ESMTP Postfix Apr 16 13:32:20 mail postfix/smtpd[12387]: xsasl_cyrus_server_create: SASL service=smtp, realm=(null) Apr 16 13:32:20 mail postfix/smtpd[12387]: name_mask: noanonymous Apr 16 13:32:20 mail postfix/smtpd[12387]: watchdog_pat: 0x1a6d430 Apr 16 13:32:20 mail postfix/smtpd[12387]: < vms173009pub.verizon.net[206.46.173.9]: EHLO vms173009pub.verizon.net Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 250-mail.AAAAA.com Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 250-PIPELINING Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 250-SIZE 30720000 Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 250-VRFY Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 250-ETRN Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 250-STARTTLS Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 250-AUTH LOGIN PLAIN Apr 16 13:32:20 mail postfix/smtpd[12387]: match_list_match: vms173009pub.verizon.net: no match Apr 16 13:32:20 mail postfix/smtpd[12387]: match_list_match: 206.46.173.9: no match Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 250-AUTH=LOGIN PLAIN Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 250-ENHANCEDSTATUSCODES Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 250-8BITMIME Apr 16 13:32:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 250 DSN Apr 16 13:32:20 mail postfix/smtpd[12387]: watchdog_pat: 0x1a6d430 Apr 16 13:37:20 mail postfix/smtpd[12387]: > vms173009pub.verizon.net[206.46.173.9]: 421 4.4.2 mail.AAAAA.com Error: timeout exceeded Apr 16 13:37:20 mail postfix/smtpd[12387]: match_hostname: vms173009pub.verizon.net ~? 127.0.0.0/8 Apr 16 13:37:20 mail postfix/smtpd[12387]: match_hostaddr: 206.46.173.9 ~? 127.0.0.0/8 Apr 16 13:37:20 mail postfix/smtpd[12387]: match_hostname: vms173009pub.verizon.net ~? 172.16.0.0/17 Apr 16 13:37:20 mail postfix/smtpd[12387]: match_hostaddr: 206.46.173.9 ~? 172.16.0.0/17 Apr 16 13:37:20 mail postfix/smtpd[12387]: match_hostname: vms173009pub.verizon.net ~? 204.2.DD.DDD/27 Apr 16 13:37:20 mail postfix/smtpd[12387]: match_hostaddr: 206.46.173.9 ~? 204.2.DD.DDD/27 Apr 16 13:37:20 mail postfix/smtpd[12387]: match_hostname: vms173009pub.verizon.net ~? 192.168.132.0/24 Apr 16 13:37:20 mail postfix/smtpd[12387]: match_hostaddr: 206.46.173.9 ~? 192.168.132.0/24 Apr 16 13:37:20 mail postfix/smtpd[12387]: match_hostname: vms173009pub.verizon.net ~? [::1]/128 Apr 16 13:37:20 mail postfix/smtpd[12387]: match_hostaddr: 206.46.173.9 ~? [::1]/128 Apr 16 13:37:20 mail postfix/smtpd[12387]: match_list_match: vms173009pub.verizon.net: no match Apr 16 13:37:20 mail postfix/smtpd[12387]: match_list_match: 206.46.173.9: no match Apr 16 13:37:20 mail postfix/smtpd[12387]: send attr request = disconnect Apr 16 13:37:20 mail postfix/smtpd[12387]: send attr ident = smtp:206.46.173.9 Apr 16 13:37:20 mail postfix/smtpd[12387]: private/anvil: wanted attribute: status Apr 16 13:37:20 mail postfix/smtpd[12387]: input attribute name: status Apr 16 13:37:20 mail postfix/smtpd[12387]: input attribute value: 0 Apr 16 13:37:20 mail postfix/smtpd[12387]: private/anvil: wanted attribute: (list terminator) Apr 16 13:37:20 mail postfix/smtpd[12387]: input attribute name: (end) Apr 16 13:37:20 mail postfix/smtpd[12387]: timeout after EHLO from vms173009pub.verizon.net[206.46.173.9] Apr 16 13:37:20 mail postfix/smtpd[12387]: disconnect from vms173009pub.verizon.net[206.46.173.9] Postfix may indeed be doing exactly what it’s supposed to, but that certainly isn’t explaining why only certain groups of remote hosts are then choosing to not respond. Any clues, I’m all ears. I’m afraid my Google-fu is running short on this one. Is there something else you think these remote hosts may be expecting in the EHLO, and simply choosing not to continue the session? A problem with TLS maybe? You know, the trouble seems to have started shortly after disclosure of the heartbleed flaw in OpenSSL, perhaps related? Brian On Apr 16, 2014, at 2:35 PM, Wietse Venema <[email protected]> wrote: > Brian Grimal: >> 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] > > Postfix works as expected. Postfix receives *NOTHING* for 5 minutes, > and then Postfix times out. > >> 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 > > Here Postfix times out after 10 seconds. Postfix reduces time > limits when all server are busy. > > Look in your MAILLOG file for warnings like this: > > service XXX(XXX) has reached its process limit XXX: new clients may > experience noticeable delays > to avoid this condition, increase the process count in master.cf or reduce > the service time per client > see http://www.postfix.org/STRESS_README.html for examples of stress-adapting > configuration settings > > Wietse > Wietse
