David Mehler via Postfix-users: > Hello, > > Here is the complete log of the connections, IPS x-d out, but I tried > twice, once on 587, once with smtps enabled. Any help appreciated.
We DID NOT ask for verbose logs. All we asked for is this: > postfix/submission/smtpd[1529]: improper command pipelining after EHLO > from xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: QUIT\r\n and that is logged without verbose logging. I found on-line reports from 2018 where Thunderbird sends EHLO we-guess.mozilla.org\r\nQUIT\r\n I suppose that is an autoconf feature that hopefully can be turned off in Thunderbird, otherwise someone on the mozilla needs to learn how SMTP works. https://bugzilla.mozilla.org/show_bug.cgi?id=1681946 https://bugzilla.mozilla.org/show_bug.cgi?id=538809 Wietse > Dave. > > #tail -f /var/log/mail.log > 2024-04-02T09:48:08.220604-04:00 hostname > postfix/submission/smtpd[1529]: connect from > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx] > 2024-04-02T09:48:08.220939-04:00 hostname > postfix/submission/smtpd[1529]: smtp_stream_setup: maxtime=300 > enable_deadline=0 min_data_rate=0 > 2024-04-02T09:48:08.221246-04:00 hostname > postfix/submission/smtpd[1529]: match_hostname: > smtpd_client_event_limit_exceptions: xxx.xxx.xxx.xxx ~? 127.0.0.0/8 > 2024-04-02T09:48:08.221434-04:00 hostname > postfix/submission/smtpd[1529]: match_hostaddr: > smtpd_client_event_limit_exceptions: xxx.xxx.xxx.xxx ~? 127.0.0.0/8 > 2024-04-02T09:48:08.221704-04:00 hostname > postfix/submission/smtpd[1529]: match_list_match: xxx.xxx.xxx.xxx: no match > 2024-04-02T09:48:08.221881-04:00 hostname > postfix/submission/smtpd[1529]: match_list_match: xxx.xxx.xxx.xxx: no match > 2024-04-02T09:48:08.222386-04:00 hostname > postfix/submission/smtpd[1529]: auto_clnt_open: connected to private/anvil > 2024-04-02T09:48:08.222577-04:00 hostname > postfix/submission/smtpd[1529]: private/anvil: wanted attribute: protocol > 2024-04-02T09:48:08.222801-04:00 hostname > postfix/submission/smtpd[1529]: input attribute name: protocol > 2024-04-02T09:48:08.222935-04:00 hostname > postfix/submission/smtpd[1529]: input attribute value: anvil_protocol > 2024-04-02T09:48:08.223103-04:00 hostname > postfix/submission/smtpd[1529]: private/anvil: wanted attribute: (list > terminator) > 2024-04-02T09:48:08.223264-04:00 hostname > postfix/submission/smtpd[1529]: input attribute name: (end) > 2024-04-02T09:48:08.223453-04:00 hostname > postfix/submission/smtpd[1529]: send attr request = connect > 2024-04-02T09:48:08.223579-04:00 hostname > postfix/submission/smtpd[1529]: send attr ident = submission:xxx.xxx.xxx.xxx > 2024-04-02T09:48:08.223857-04:00 hostname > postfix/submission/smtpd[1529]: private/anvil: wanted attribute: status > 2024-04-02T09:48:08.223987-04:00 hostname > postfix/submission/smtpd[1529]: input attribute name: status > 2024-04-02T09:48:08.224153-04:00 hostname > postfix/submission/smtpd[1529]: input attribute value: 0 > 2024-04-02T09:48:08.224389-04:00 hostname > postfix/submission/smtpd[1529]: private/anvil: wanted attribute: count > 2024-04-02T09:48:08.224565-04:00 hostname > postfix/submission/smtpd[1529]: input attribute name: count > 2024-04-02T09:48:08.224734-04:00 hostname > postfix/submission/smtpd[1529]: input attribute value: 1 > 2024-04-02T09:48:08.225001-04:00 hostname > postfix/submission/smtpd[1529]: private/anvil: wanted attribute: rate > 2024-04-02T09:48:08.225165-04:00 hostname > postfix/submission/smtpd[1529]: input attribute name: rate > 2024-04-02T09:48:08.225314-04:00 hostname > postfix/submission/smtpd[1529]: input attribute value: 1 > 2024-04-02T09:48:08.225465-04:00 hostname > postfix/submission/smtpd[1529]: private/anvil: wanted attribute: (list > terminator) > 2024-04-02T09:48:08.225610-04:00 hostname > postfix/submission/smtpd[1529]: input attribute name: (end) > 2024-04-02T09:48:08.225750-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: 220 > hostname.example.com ESMTP > 2024-04-02T09:48:08.225896-04:00 hostname > postfix/submission/smtpd[1529]: smtp_stream_setup: maxtime=300 > enable_deadline=0 min_data_rate=0 > 2024-04-02T09:48:08.226037-04:00 hostname > postfix/submission/smtpd[1529]: watchdog_pat: 0x55810ef6a110 > 2024-04-02T09:48:08.293029-04:00 hostname > postfix/submission/smtpd[1529]: < xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: EHLO > we-guess.mozilla.org > 2024-04-02T09:48:08.293161-04:00 hostname > 2024-04-02T09:48:08.293252-04:00 hostname > postfix/submission/smtpd[1529]: match_list_match: xxx.xxx.xxx.xxx: no match > 2024-04-02T09:48:08.293413-04:00 hostname > postfix/submission/smtpd[1529]: match_list_match: xxx.xxx.xxx.xxx: no match > 2024-04-02T09:48:08.293480-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: > 250-hostname.example.com > 2024-04-02T09:48:08.293547-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: > 250-PIPELINING > 2024-04-02T09:48:08.293613-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: > 250-SIZE 52428800 > 2024-04-02T09:48:08.293675-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: 250-ETRN > 2024-04-02T09:48:08.293738-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: > 250-STARTTLS > 2024-04-02T09:48:08.293801-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: > 250-ENHANCEDSTATUSCODES > 2024-04-02T09:48:08.293863-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: > 250-8BITMIME > 2024-04-02T09:48:08.293926-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: 250-DSN > 2024-04-02T09:48:08.293992-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: > 250-SMTPUTF8 > 2024-04-02T09:48:08.294065-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: 250 > CHUNKING > 2024-04-02T09:48:08.294135-04:00 hostname > postfix/submission/smtpd[1529]: smtp_stream_setup: maxtime=300 > enable_deadline=0 min_data_rate=0 > 2024-04-02T09:48:08.294196-04:00 hostname > postfix/submission/smtpd[1529]: watchdog_pat: 0x55810ef6a110 > 2024-04-02T09:48:08.294262-04:00 hostname > postfix/submission/smtpd[1529]: < xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: QUIT > 2024-04-02T09:48:08.294326-04:00 hostname > postfix/submission/smtpd[1529]: > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: 221 > 2.0.0 Bye > 2024-04-02T09:48:08.294391-04:00 hostname > postfix/submission/smtpd[1529]: match_hostname: > smtpd_client_event_limit_exceptions: xxx.xxx.xxx.xxx ~? 127.0.0.0/8 > 2024-04-02T09:48:08.294451-04:00 hostname > postfix/submission/smtpd[1529]: match_hostaddr: > smtpd_client_event_limit_exceptions: xxx.xxx.xxx.xxx ~? 127.0.0.0/8 > 2024-04-02T09:48:08.294512-04:00 hostname > postfix/submission/smtpd[1529]: match_list_match: xxx.xxx.xxx.xxx: no match > 2024-04-02T09:48:08.294572-04:00 hostname > postfix/submission/smtpd[1529]: match_list_match: xxx.xxx.xxx.xxx: no match > 2024-04-02T09:48:08.294640-04:00 hostname > postfix/submission/smtpd[1529]: send attr request = disconnect > 2024-04-02T09:48:08.294704-04:00 hostname > postfix/submission/smtpd[1529]: send attr ident = submission:xxx.xxx.xxx.xxx > 2024-04-02T09:48:08.294764-04:00 hostname > postfix/submission/smtpd[1529]: private/anvil: wanted attribute: status > 2024-04-02T09:48:08.294826-04:00 hostname > postfix/submission/smtpd[1529]: input attribute name: status > 2024-04-02T09:48:08.294887-04:00 hostname > postfix/submission/smtpd[1529]: input attribute value: 0 > 2024-04-02T09:48:08.294946-04:00 hostname > postfix/submission/smtpd[1529]: private/anvil: wanted attribute: (list > terminator) > 2024-04-02T09:48:08.295006-04:00 hostname > postfix/submission/smtpd[1529]: input attribute name: (end) > 2024-04-02T09:48:08.295097-04:00 hostname > postfix/submission/smtpd[1529]: disconnect from > xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx] ehlo=1 quit=1 commands=2 > > This is the port 465 atempt. > > #tail -f /var/log/mail.log > 2024-04-02T09:49:02.211864-04:00 hostname postfix/smtps/smtpd[1575]: > connect from xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx] > 2024-04-02T09:49:02.212128-04:00 hostname postfix/smtps/smtpd[1575]: > smtp_stream_setup: maxtime=300 enable_deadline=0 min_data_rate=0 > 2024-04-02T09:49:02.212215-04:00 hostname postfix/smtps/smtpd[1575]: > send attr request = seed > 2024-04-02T09:49:02.212294-04:00 hostname postfix/smtps/smtpd[1575]: > send attr size = 32 > 2024-04-02T09:49:02.212374-04:00 hostname postfix/smtps/smtpd[1575]: > private/tlsmgr: wanted attribute: status > 2024-04-02T09:49:02.212458-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: status > 2024-04-02T09:49:02.212552-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute value: 0 > 2024-04-02T09:49:02.212642-04:00 hostname postfix/smtps/smtpd[1575]: > private/tlsmgr: wanted attribute: seed > 2024-04-02T09:49:02.212733-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: seed > 2024-04-02T09:49:02.212826-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute value: TQH60OxX/hpi07ebSmEWL4g74EdmGTN3avxd+np2j7I= > 2024-04-02T09:49:02.212913-04:00 hostname postfix/smtps/smtpd[1575]: > private/tlsmgr: wanted attribute: (list terminator) > 2024-04-02T09:49:02.212998-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: (end) > 2024-04-02T09:49:02.419571-04:00 hostname postfix/smtps/smtpd[1575]: > SSL_accept error from xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: -1 > 2024-04-02T09:49:02.419716-04:00 hostname postfix/smtps/smtpd[1575]: > warning: TLS library problem: error:0A000412:SSL routines::sslv3 alert > bad certificate:../ssl/record/rec_layer_s3.c:1590:SSL alert number 42: > 2024-04-02T09:49:02.419834-04:00 hostname postfix/smtps/smtpd[1575]: > smtp_stream_setup: maxtime=300 enable_deadline=0 min_data_rate=0 > 2024-04-02T09:49:02.419929-04:00 hostname postfix/smtps/smtpd[1575]: > match_hostname: smtpd_client_event_limit_exceptions: xxx.xxx.xxx.xxx ~? > 127.0.0.0/8 > 2024-04-02T09:49:02.420012-04:00 hostname postfix/smtps/smtpd[1575]: > match_hostaddr: smtpd_client_event_limit_exceptions: xxx.xxx.xxx.xxx ~? > 127.0.0.0/8 > 2024-04-02T09:49:02.420111-04:00 hostname postfix/smtps/smtpd[1575]: > match_list_match: xxx.xxx.xxx.xxx: no match > 2024-04-02T09:49:02.420199-04:00 hostname postfix/smtps/smtpd[1575]: > match_list_match: xxx.xxx.xxx.xxx: no match > 2024-04-02T09:49:02.420275-04:00 hostname postfix/smtps/smtpd[1575]: > auto_clnt_open: connected to private/anvil > 2024-04-02T09:49:02.420356-04:00 hostname postfix/smtps/smtpd[1575]: > private/anvil: wanted attribute: protocol > 2024-04-02T09:49:02.420453-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: protocol > 2024-04-02T09:49:02.420533-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute value: anvil_protocol > 2024-04-02T09:49:02.420615-04:00 hostname postfix/smtps/smtpd[1575]: > private/anvil: wanted attribute: (list terminator) > 2024-04-02T09:49:02.420695-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: (end) > 2024-04-02T09:49:02.420782-04:00 hostname postfix/smtps/smtpd[1575]: > send attr request = disconnect > 2024-04-02T09:49:02.420874-04:00 hostname postfix/smtps/smtpd[1575]: > send attr ident = smtps:xxx.xxx.xxx.xxx > 2024-04-02T09:49:02.420957-04:00 hostname postfix/smtps/smtpd[1575]: > private/anvil: wanted attribute: status > 2024-04-02T09:49:02.421036-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: status > 2024-04-02T09:49:02.421129-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute value: 0 > 2024-04-02T09:49:02.421210-04:00 hostname postfix/smtps/smtpd[1575]: > private/anvil: wanted attribute: (list terminator) > 2024-04-02T09:49:02.421288-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: (end) > 2024-04-02T09:49:02.421374-04:00 hostname postfix/smtps/smtpd[1575]: > lost connection after CONNECT from xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx] > 2024-04-02T09:49:02.421466-04:00 hostname postfix/smtps/smtpd[1575]: > disconnect from xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx] commands=0/0 > 2024-04-02T09:49:25.927626-04:00 hostname postfix/smtps/smtpd[1575]: > connect from xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx] > 2024-04-02T09:49:25.927819-04:00 hostname postfix/smtps/smtpd[1575]: > smtp_stream_setup: maxtime=300 enable_deadline=0 min_data_rate=0 > 2024-04-02T09:49:25.927883-04:00 hostname postfix/smtps/smtpd[1575]: > auto_clnt_open: connected to private/tlsmgr > 2024-04-02T09:49:25.927940-04:00 hostname postfix/smtps/smtpd[1575]: > private/tlsmgr: wanted attribute: protocol > 2024-04-02T09:49:25.928001-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: protocol > 2024-04-02T09:49:25.928074-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute value: tlsmgr_protocol > 2024-04-02T09:49:25.928161-04:00 hostname postfix/smtps/smtpd[1575]: > private/tlsmgr: wanted attribute: (list terminator) > 2024-04-02T09:49:25.928226-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: (end) > 2024-04-02T09:49:25.928280-04:00 hostname postfix/smtps/smtpd[1575]: > send attr request = seed > 2024-04-02T09:49:25.928332-04:00 hostname postfix/smtps/smtpd[1575]: > send attr size = 32 > 2024-04-02T09:49:25.928395-04:00 hostname postfix/smtps/smtpd[1575]: > private/tlsmgr: wanted attribute: status > 2024-04-02T09:49:25.928448-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: status > 2024-04-02T09:49:25.928505-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute value: 0 > 2024-04-02T09:49:25.928557-04:00 hostname postfix/smtps/smtpd[1575]: > private/tlsmgr: wanted attribute: seed > 2024-04-02T09:49:25.928614-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: seed > 2024-04-02T09:49:25.928667-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute value: dxMR9/tWKYBdOzREfYCLCCa75S8/fNs0Nb9cOtIhjM4= > 2024-04-02T09:49:25.928722-04:00 hostname postfix/smtps/smtpd[1575]: > private/tlsmgr: wanted attribute: (list terminator) > 2024-04-02T09:49:25.928774-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: (end) > 2024-04-02T09:49:26.015199-04:00 hostname dovecot: imap-login: > Disconnected: Aborted login by logging out (no auth attempts in 1 secs): > user=<>, rip=xxx.xxx.xxx.xxx, lip=190.92.151.100, session=<Db7QXx0VrS9oDWll> > 2024-04-02T09:49:26.015559-04:00 hostname postfix/smtps/smtpd[1575]: > SSL_accept error from xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx]: -1 > 2024-04-02T09:49:26.015729-04:00 hostname postfix/smtps/smtpd[1575]: > warning: TLS library problem: error:0A000412:SSL routines::sslv3 alert > bad certificate:../ssl/record/rec_layer_s3.c:1590:SSL alert number 42: > 2024-04-02T09:49:26.015818-04:00 hostname postfix/smtps/smtpd[1575]: > smtp_stream_setup: maxtime=300 enable_deadline=0 min_data_rate=0 > 2024-04-02T09:49:26.015875-04:00 hostname postfix/smtps/smtpd[1575]: > match_hostname: smtpd_client_event_limit_exceptions: xxx.xxx.xxx.xxx ~? > 127.0.0.0/8 > 2024-04-02T09:49:26.015932-04:00 hostname postfix/smtps/smtpd[1575]: > match_hostaddr: smtpd_client_event_limit_exceptions: xxx.xxx.xxx.xxx ~? > 127.0.0.0/8 > 2024-04-02T09:49:26.015985-04:00 hostname postfix/smtps/smtpd[1575]: > match_list_match: xxx.xxx.xxx.xxx: no match > 2024-04-02T09:49:26.016045-04:00 hostname postfix/smtps/smtpd[1575]: > match_list_match: xxx.xxx.xxx.xxx: no match > 2024-04-02T09:49:26.016142-04:00 hostname postfix/smtps/smtpd[1575]: > send attr request = disconnect > 2024-04-02T09:49:26.016207-04:00 hostname postfix/smtps/smtpd[1575]: > send attr ident = smtps:xxx.xxx.xxx.xxx > 2024-04-02T09:49:26.016263-04:00 hostname postfix/smtps/smtpd[1575]: > private/anvil: wanted attribute: status > 2024-04-02T09:49:26.016316-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: status > 2024-04-02T09:49:26.016369-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute value: 0 > 2024-04-02T09:49:26.016422-04:00 hostname postfix/smtps/smtpd[1575]: > private/anvil: wanted attribute: (list terminator) > 2024-04-02T09:49:26.016475-04:00 hostname postfix/smtps/smtpd[1575]: > input attribute name: (end) > 2024-04-02T09:49:26.016528-04:00 hostname postfix/smtps/smtpd[1575]: > lost connection after CONNECT from xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx] > 2024-04-02T09:49:26.016584-04:00 hostname postfix/smtps/smtpd[1575]: > disconnect from xxx.xxx.xxx.xxx[xxx.xxx.xxx.xxx] commands=0/0 > > > On 4/1/2024 4:17 PM, Viktor Dukhovni via Postfix-users wrote: > > On Mon, Apr 01, 2024 at 04:09:34PM -0400, David Mehler via Postfix-users > > wrote: > > > >> In my master.cf I do have smtpd_tls_wrappermode but it's in the commented > >> out service for port 465, I'm using submission. > >> > >> I've checked with postconf and smtpd_tls_wrappermode is set to no. > > > > Of course, but Thunderbird might be attempting wrapper-mode (implicit > > TLS), which could then be logged as a pipelining violation. > > > >> Is there any additional information I can provide? > >> > >> Please keep the suggestions coming. > > > > The full unedited log entry has already been requested. For meaningful > > help, post the log entry. > > > > -- > Sent from Mozilla Thunderbird 91.13.1 > _______________________________________________ > Postfix-users mailing list -- postfix-users@postfix.org > To unsubscribe send an email to postfix-users-le...@postfix.org > _______________________________________________ Postfix-users mailing list -- postfix-users@postfix.org To unsubscribe send an email to postfix-users-le...@postfix.org