On 2/12/23 7:11 PM, Viktor Dukhovni wrote:

On Sun, Feb 12, 2023 at 06:49:12PM -0800, David Newman wrote:

Postfix 3.5.17 on Debian 11

Greetings. I could use some help understanding why postfix takes around
60 seconds to accept and forward messages received using submission.

Feb 12 18:02:23 mail10 postfix/submission/smtpd[593931]:
   connect from cpe-2.2.2.2.my.wonderful.isp.com[2.2.2.2]
Feb 12 18:02:23 mail10 postfix/submission/smtpd[593931]: <
cpe-2.2.2.2.my.wonderful.isp.com[2.2.2.2]: AUTH PLAIN <sensitive data>
This was just base64 encoded, not encrypted.  Posting verbose logging
leaked the password of the user in question, change it promptly.  DO NOT
post encoded "AUTH" command content.


No worries. I didn't mention it, but I'd also obfuscated the string following AUTH PLAIN.



Feb 12 18:02:23 mail10 postfix/submission/smtpd[593931]: send attr
client_name = cpe-2.2.2.2.my.wonderful.isp.com
Feb 12 18:02:23 mail10 postfix/submission/smtpd[593931]: send attr
reverse_client_name = cpe-2.2.2.2.my.wonderful.isp.com
Feb 12 18:02:53 mail10 postfix/submission/smtpd[593931]:
permit_mynetworks: cpe-2.2.2.2.my.wonderful.isp.com 2.2.2.2
The 30s delay suggets a slow "cleanup" or a slow policy service.

Feb 12 18:02:53 mail10 postfix/submission/smtpd[593931]: send attr
client_address = 2.2.2.2
Feb 12 18:02:53 mail10 postfix/submission/smtpd[593931]: send attr
client_name = cpe-2.2.2.2.my.wonderful.isp.com
Feb 12 18:02:53 mail10 postfix/submission/smtpd[593931]: send attr
reverse_client_name = cpe-2.2.2.2.my.wonderful.isp.com
Feb 12 18:03:23 mail10 postfix/submission/smtpd[593931]: >
cpe-2.2.2.2.my.wonderful.isp.com[2.2.2.2]: 250 2.0.0 Ok: queued as > 
4PFSKT5m0kzHTbm
Another 30s delay.  Your restrictions include:

     smtpd_recipient_restrictions =
         reject_non_fqdn_recipient
         reject_unlisted_recipient
         check_policy_service inet:127.0.0.1:7777
         permit_mynetworks permit_sasl_authenticated
         reject_unauth_destination
         check_policy_service inet:127.0.0.1:12340

     smtpd_end_of_data_restrictions =
         check_policy_service inet:127.0.0.1:7777

The "7777" service is a strong suspect.

Bingo. That service was timing out due to an incorrect database password in its config file. All good now after entering the correct password and restarting postfix. Thanks for the pointer!

dn



Reply via email to