* Noel Jones <njo...@megan.vbhcs.org> [170322 14:38]: > On 3/22/2017 1:08 PM, Marvin Renich wrote: > > Thanks, Wietse and Noel. Once the IPv4 delivery fails for some reason, > > and Postfix tries IPv6 (which must fail for this relayhost), the message > > is deferred. Do subsequent redelivery attempts only try IPv6? This is > > what it looked like was happening, even if the failure was caused by > > something else. > > Each subsequent attempt will try both, but only the last error is > reported in the queue listing.
That is what I expected. > > The message sat in the deferred queue overnight, with more than a dozen > > redelivery attempts, all with the same result, even though during that > > time I was able to correctly resolve the relayhost's IP. postqueue -f > > failed, but changing inet_protocols to ipv4 and restarting Postfix > > delivered the message immediately. > > If DNS lookups were working, the temporary delivery error was > probably something other than a DNS lookup failure. You should be > able to find these other delivery attempts logged by the smtp > delivery process. The mail.log file contains no other intervening messages. zgrep smtp /var/log/* reveals nothing else of any interest. Except for the [snip] in the middle, the following is the complete mail.log from message pickup through delivery of my initial message in this thread. Mar 21 14:42:45 basil postfix/pickup[11818]: 3AF35240229: uid=1001 from=<m...@renich.org> Mar 21 14:42:45 basil postfix/cleanup[12584]: 3AF35240229: message-id=<20170321184244.cxyiq2u6w53qt...@basil.wdw> Mar 21 14:42:45 basil postfix/qmgr[3804]: 3AF35240229: from=<m...@renich.org>, size=8480, nrcpt=2 (queue active) Mar 21 14:42:45 basil postfix/smtp[12587]: 3AF35240229: to=<recipie...@host2.example2.com>, relay=none, delay=0.47, delays=0.25/0.22/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 14:42:45 basil postfix/smtp[12587]: 3AF35240229: to=<m...@renich.org>, relay=none, delay=0.47, delays=0.25/0.22/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 14:52:26 basil postfix/qmgr[3804]: 3AF35240229: from=<m...@renich.org>, size=8480, nrcpt=2 (queue active) Mar 21 14:52:26 basil postfix/smtp[12810]: 3AF35240229: to=<recipie...@host2.example2.com>, relay=none, delay=581, delays=581/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 14:52:26 basil postfix/smtp[12810]: 3AF35240229: to=<m...@renich.org>, relay=none, delay=581, delays=581/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 15:02:26 basil postfix/qmgr[3804]: 3AF35240229: from=<m...@renich.org>, size=8480, nrcpt=2 (queue active) Mar 21 15:02:26 basil postfix/smtp[13022]: 3AF35240229: to=<recipie...@host2.example2.com>, relay=none, delay=1181, delays=1181/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 15:02:26 basil postfix/smtp[13022]: 3AF35240229: to=<m...@renich.org>, relay=none, delay=1181, delays=1181/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 15:22:26 basil postfix/qmgr[3804]: 3AF35240229: from=<m...@renich.org>, size=8480, nrcpt=2 (queue active) Mar 21 15:22:27 basil postfix/smtp[13538]: 3AF35240229: to=<recipie...@host2.example2.com>, relay=none, delay=2381, delays=2381/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 15:22:27 basil postfix/smtp[13538]: 3AF35240229: to=<m...@renich.org>, relay=none, delay=2381, delays=2381/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 16:02:26 basil postfix/qmgr[3804]: 3AF35240229: from=<m...@renich.org>, size=8480, nrcpt=2 (queue active) Mar 21 16:02:26 basil postfix/smtp[14418]: 3AF35240229: to=<recipie...@host2.example2.com>, relay=none, delay=4781, delays=4781/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 16:02:26 basil postfix/smtp[14418]: 3AF35240229: to=<m...@renich.org>, relay=none, delay=4781, delays=4781/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 16:11:19 basil postfix/qmgr[3804]: 3AF35240229: from=<m...@renich.org>, size=8480, nrcpt=2 (queue active) Mar 21 16:11:19 basil postfix/smtp[14667]: 3AF35240229: to=<recipie...@host2.example2.com>, relay=none, delay=5314, delays=5314/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 16:11:19 basil postfix/smtp[14667]: 3AF35240229: to=<m...@renich.org>, relay=none, delay=5314, delays=5314/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 17:22:26 basil postfix/qmgr[3804]: 3AF35240229: from=<m...@renich.org>, size=8480, nrcpt=2 (queue active) Mar 21 17:22:26 basil postfix/smtp[16964]: 3AF35240229: to=<recipie...@host2.example2.com>, relay=none, delay=9581, delays=9581/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 21 17:22:26 basil postfix/smtp[16964]: 3AF35240229: to=<m...@renich.org>, relay=none, delay=9581, delays=9581/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) [snipped a bunch more of the same, and one successful local delivery from root to mrvn.] Mar 22 10:52:33 basil postfix/qmgr[3804]: 3AF35240229: from=<m...@renich.org>, size=8480, nrcpt=2 (queue active) Mar 22 10:52:33 basil postfix/smtp[10498]: 3AF35240229: to=<recipie...@host2.example2.com>, relay=none, delay=72588, delays=72588/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 22 10:52:33 basil postfix/smtp[10498]: 3AF35240229: to=<m...@renich.org>, relay=none, delay=72588, delays=72588/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 22 12:02:33 basil postfix/qmgr[3804]: 3AF35240229: from=<m...@renich.org>, size=8480, nrcpt=2 (queue active) Mar 22 12:02:33 basil postfix/smtp[12474]: 3AF35240229: to=<recipie...@host2.example2.com>, relay=none, delay=76788, delays=76788/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 22 12:02:33 basil postfix/smtp[12474]: 3AF35240229: to=<m...@renich.org>, relay=none, delay=76788, delays=76788/0.01/0/0, dsn=4.4.3, status=deferred (Host or domain name not found. Name service error for name=florina.renich.org type=AAAA: Host not found, try again) Mar 22 12:31:13 basil postfix[13232]: Postfix is running with backwards-compatible default settings Mar 22 12:31:13 basil postfix[13232]: See http://www.postfix.org/COMPATIBILITY_README.html for details Mar 22 12:31:13 basil postfix[13232]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload" Mar 22 12:31:13 basil postfix/master[3783]: terminating on signal 15 Mar 22 12:31:13 basil postfix[13339]: Postfix is running with backwards-compatible default settings Mar 22 12:31:13 basil postfix[13339]: See http://www.postfix.org/COMPATIBILITY_README.html for details Mar 22 12:31:13 basil postfix[13339]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload" Mar 22 12:31:13 basil postfix/master[13378]: daemon started -- version 3.1.4, configuration /etc/postfix Mar 22 12:31:43 basil postfix/qmgr[13382]: 3AF35240229: from=<m...@renich.org>, size=8480, nrcpt=2 (queue active) Mar 22 12:31:44 basil postfix/smtp[13422]: 3AF35240229: to=<recipie...@host2.example2.com>, relay=florina.renich.org[64.150.161.163]:587, delay=78539, delays=78538/0.15/0.55/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as A34BA680B4) Mar 22 12:31:44 basil postfix/smtp[13422]: 3AF35240229: to=<m...@renich.org>, relay=florina.renich.org[64.150.161.163]:587, delay=78539, delays=78538/0.15/0.55/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as A34BA680B4) Mar 22 12:31:44 basil postfix/qmgr[13382]: 3AF35240229: removed Mar 22 13:04:36 basil postfix/pickup[13381]: AAA07240229: uid=1001 from=<m...@renich.org> Mar 22 13:04:36 basil postfix/cleanup[14525]: AAA07240229: message-id=<20170322170436.6e4an4vsimzma...@basil.wdw> Mar 22 13:04:36 basil postfix/qmgr[13382]: AAA07240229: from=<m...@renich.org>, size=4959, nrcpt=1 (queue active) Mar 22 13:04:37 basil postfix/smtp[14527]: AAA07240229: to=<postfix-users@postfix.org>, relay=florina.renich.org[64.150.161.163]:587, delay=0.68, delays=0.1/0.01/0.47/0.1, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as B8AC2680B4) Mar 22 13:04:37 basil postfix/qmgr[13382]: AAA07240229: removed At 12:30 I edited main.cf to add inet_protocols = ipv4, then restarted Postfix. I did not reboot or restart any other services, or (knowingly) clear any dns cache. I have since then removed inet_protocols from main.cf, and all is working fine. I guess this is going to be an unexplained issue that has been resolved without knowing what the real problem was. It would be a very unlikely coincidence for an external dns problem to spontaneously resolve at exactly the same time I restarted Postfix, especially since other programs were able to correctly obtain the relevant dns response at the same time that Postfix was unable to. > > Also, what about my third question: was the serverfault answer only > > useful if an smtp-ipv4 service is manually added to master.cf? > > That answer is useful for a host that delivers some mail via IPv6 > but has some destinations that don't work properly on IPv6 -- for > example, a destination that 5xx rejects IPv6 mail, but accepts IPv4 > mail. Such workarounds are not required for well-behaved > destinations. And yes, a master.cf smtp-ipv4 service would be > needed, so it was not a complete answer. Thanks. I wanted to make sure that my understanding was correct. Thank you both very much for your help. Unless you see something obvious in the log above, I am going to consider this issue closed but unexplained. ...Marvin
