[SOLVED] repeated connect/session/disconnect from mail-*.outbound.protection.outlook.com and missing emails from outlook

Discuss your pilot or production implementation with other Zimbra admins or our engineers.
Post Reply
lzmarine
Posts: 21
Joined: Fri Sep 12, 2014 10:41 pm

[SOLVED] repeated connect/session/disconnect from mail-*.outbound.protection.outlook.com and missing emails from outlook

Post by lzmarine »

This happens for various *.outbound.protection.outlook.com domains, but not all. I tested from my work O365 and it is fine. I have SPF, DKIM, reputation memberships, and just enabled and verified DANE. I have a self-signed certificate on a VPS for a private server and domains. I have never had this issue before where there are no detailed errors that I can find. I was receiving emails from at least one organization up until about a week or few ago, and this seems correlated. An example log message on my Ubuntu Zimbra 8.8.15_GA_4257 (build 20220324034943). Upgraded and same issue with Zimbra 8.8.15_GA_4304 (build 20220612004933). There are many similar issues on the internet, but none have the same symptoms and none of the solutions have worked for me. Any help or pointers are greatly appreciated! TIA

*** Update 20220627 ***
I found that the working examples do not include the additional lines in the red font BEFORE the TLS connection is established; and, the working examples DO include the additional EHLO and subsequent lines AFTER the TLS connection is established. Does anyone know what config is relevant or what debug logging might be helpful to enable?
WORKING example:
Jun 25 12:01:55 mail postfix/smtpd[25123]: connect from mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 220 my.mail.host ESMTP Postfix
Jun 25 12:01:55 mail postfix/smtpd[25123]: < mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: EHLO NAM10-MW2-obe.outbound.protection.outlook.com
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-my.mail.host
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-PIPELINING
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-SIZE 204800000
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-VRFY
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-ETRN
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-STARTTLS
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-ENHANCEDSTATUSCODES
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-8BITMIME
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-DSN
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250 CHUNKING
Jun 25 12:01:55 mail postfix/smtpd[25123]: < mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: STARTTLS
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 220 2.0.0 Ready to start TLS
Jun 25 12:01:55 mail postfix/smtpd[25123]: auto_clnt_open: connected to private/tlsmgr
Jun 25 12:01:55 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: protocol
Jun 25 12:01:55 mail postfix/smtpd[25123]: input attribute name: protocol
Jun 25 12:01:55 mail postfix/smtpd[25123]: input attribute value: tlsmgr_protocol
Jun 25 12:01:55 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: (list terminator)
Jun 25 12:01:55 mail postfix/smtpd[25123]: input attribute name: (end)
Jun 25 12:01:55 mail postfix/smtpd[25123]: send attr request = seed
Jun 25 12:01:55 mail postfix/smtpd[25123]: send attr size = 32
Jun 25 12:01:55 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: status
Jun 25 12:01:55 mail postfix/smtpd[25123]: input attribute name: status
Jun 25 12:01:55 mail postfix/smtpd[25123]: input attribute value: 0
Jun 25 12:01:55 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: seed
Jun 25 12:01:55 mail postfix/smtpd[25123]: input attribute name: seed
Jun 25 12:01:55 mail postfix/smtpd[25123]: input attribute value: y0JHot0HBBO1qUr6nwE3MaUnridORzfkIr6aa+lNNyU=
Jun 25 12:01:55 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: (list terminator)
Jun 25 12:01:55 mail postfix/smtpd[25123]: input attribute name: (end)
Jun 25 12:01:55 mail postfix/smtpd[25123]: Anonymous TLS connection established from mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Jun 25 12:01:55 mail postfix/smtpd[25123]: < mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: EHLO NAM10-MW2-obe.outbound.protection.outlook.com
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-my.mail.host
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-PIPELINING
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-SIZE 204800000
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-VRFY
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-ETRN
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-AUTH PLAIN LOGIN
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-AUTH=PLAIN LOGIN
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-ENHANCEDSTATUSCODES
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-8BITMIME
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-DSN
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250 CHUNKING
Jun 25 12:01:55 mail postfix/smtpd[25123]: < mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: MAIL FROM:<user@source.mail.host> SIZE=22080
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250 2.1.0 Ok
Jun 25 12:01:55 mail postfix/smtpd[25123]: < mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: RCPT TO:<user@my.mail.host>
Jun 25 12:01:56 mail postfix/smtpd[25123]: A34DE2C157F1: client=mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]
Jun 25 12:01:55 mail postfix/smtpd[25123]: NOQUEUE: filter: RCPT from mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: <user@source.mail.host>: Sender address triggers FILTER smtp-amavis:[::1]:10024; from=<user@source.mail.host> to=<user@my.mail.host> proto=ESMTP helo=<NAM10-MW2-obe.outbound.protection.outlook.com>
Jun 25 12:01:56 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250 2.1.5 Ok
Jun 25 12:01:56 mail postfix/smtpd[25123]: < mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: BDAT 8157 LAST
Jun 25 12:01:56 mail postfix/cleanup[25126]: A34DE2C157F1: message-id=<PH0PR08MB7570C16344E8225A460BC4DD9BB79@PH0PR08MB7570.namprd08.prod.outlook.com>
Jun 25 12:01:56 mail postfix/qmgr[31736]: A34DE2C157F1: from=<user@source.mail.host>, size=8413, nrcpt=1 (queue active)
Jun 25 12:01:56 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250 2.0.0 Ok: 8157 bytes queued as A34DE2C157F1
Jun 25 12:01:56 mail postfix/smtpd[25123]: < mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: QUIT
Jun 25 12:01:56 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 221 2.0.0 Bye
Jun 25 12:01:56 mail postfix/smtpd[25123]: disconnect from mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123] ehlo=2 starttls=1 mail=1 rcpt=1 bdat=1 quit=1 commands=7
[/code]

FAILING example:
Jun 25 12:00:52 mail postfix/smtpd[25123]: connect from mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 220 my.mail.host ESMTP Postfix
Jun 25 12:00:52 mail postfix/smtpd[25123]: < mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: EHLO NAM10-DM6-obe.outbound.protection.outlook.com
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 250-my.mail.host
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 250-PIPELINING
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 250-SIZE 204800000
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 250-VRFY
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 250-ETRN
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 250-STARTTLS
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 250-ENHANCEDSTATUSCODES
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 250-8BITMIME
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 250-DSN
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 250 CHUNKING
Jun 25 12:00:52 mail postfix/smtpd[25123]: < mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: STARTTLS
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 220 2.0.0 Ready to start TLS
Jun 25 12:00:52 mail postfix/smtpd[25123]: auto_clnt_open: connected to private/tlsmgr
Jun 25 12:00:52 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: protocol
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute name: protocol
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute value: tlsmgr_protocol
Jun 25 12:00:52 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: (list terminator)
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute name: (end)
Jun 25 12:00:52 mail postfix/smtpd[25123]: send attr request = seed
Jun 25 12:00:52 mail postfix/smtpd[25123]: send attr size = 32
Jun 25 12:00:52 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: status
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute name: status
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute value: 0
Jun 25 12:00:52 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: seed
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute name: seed
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute value: iMrqsvN4Ww9p0tguwjxtlzSZUCJtMA/7Q8GSzi99raQ=
Jun 25 12:00:52 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: (list terminator)
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute name: (end)
Jun 25 12:00:52 mail postfix/smtpd[25123]: send attr request = tktkey
Jun 25 12:00:52 mail postfix/smtpd[25123]: send attr keyname = [data 0 bytes]
Jun 25 12:00:52 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: status
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute name: status
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute value: 0
Jun 25 12:00:52 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: keybuf
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute name: keybuf
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute value: +tJztLSFn+gnuX6WxHcHDaNVmeQFiCuOMqY9JfCJuaTJfkBoYnlu4rCjZsMcbcS4uk3zj+a46enKeTgB+9GEXMqzDwbnUhkDWgB8EiXi0dviNbdiAAAAAA==
Jun 25 12:00:52 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: (list terminator)
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute name: (end)

Jun 25 12:00:52 mail postfix/smtpd[25123]: Anonymous TLS connection established from mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Jun 25 12:00:52 mail postfix/smtpd[25123]: < mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: QUIT
Jun 25 12:00:52 mail postfix/smtpd[25123]: > mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101]: 221 2.0.0 Bye
Jun 25 12:00:52 mail postfix/smtpd[25123]: disconnect from mail-dm6nam10lp2101.outbound.protection.outlook.com[104.47.58.101] ehlo=1 starttls=1 quit=1 commands=3[/code]
*** End Update ***

SUSPECT LOG (bold text after connection and before disconnect):
Jun 25 11:26:25 mail postfix/smtpd[2954]: connect from mail-bn8nam04lp2043.outbound.protection.outlook.com[104.47.74.43]
Jun 25 11:26:25 mail postfix/smtpd[2954]: > mail-bn8nam04lp2043.outbound.protection.outlook.com[104.47.74.43]: 220 <my.mail.host> ESMTP Postfix
Jun 25 11:26:25 mail postfix/smtpd[2954]: < mail-bn8nam04lp2043.outbound.protection.outlook.com[104.47.74.43]: EHLO NAM04-BN8-obe.outbound.protection.outlook.com
Jun 25 11:26:25 mail postfix/smtpd[2954]: Anonymous TLS connection established from mail-bn8nam04lp2043.outbound.protection.outlook.com[104.47.74.43]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Jun 25 11:26:25 mail postfix/smtpd[2954]: xsasl_cyrus_server_create: SASL service=smtp, realm=(null)
Jun 25 11:26:25 mail postfix/smtpd[2954]: name_mask: noanonymous
Jun 25 11:26:25 mail postfix/smtpd[2954]: match_string: smtpd_sasl_mechanism_filter: plain ~? external
Jun 25 11:26:25 mail postfix/smtpd[2954]: match_string: smtpd_sasl_mechanism_filter: plain ~? static:rest(0,lock|utf8_request)
Jun 25 11:26:25 mail postfix/smtpd[2954]: sasl_mech_filter: keep SASL mechanism: 'PLAIN'
Jun 25 11:26:25 mail postfix/smtpd[2954]: match_string: smtpd_sasl_mechanism_filter: login ~? external
Jun 25 11:26:25 mail postfix/smtpd[2954]: match_string: smtpd_sasl_mechanism_filter: login ~? static:rest(0,lock|utf8_request)
Jun 25 11:26:25 mail postfix/smtpd[2954]: sasl_mech_filter: keep SASL mechanism: 'LOGIN'
Jun 25 11:26:25 mail postfix/smtpd[2954]: < mail-bn8nam04lp2043.outbound.protection.outlook.com[104.47.74.43]: QUIT
Jun 25 11:26:25 mail postfix/smtpd[2954]: > mail-bn8nam04lp2043.outbound.protection.outlook.com[104.47.74.43]: 221 2.0.0 Bye
Jun 25 11:26:25 mail postfix/smtpd[2954]: match_hostname: smtpd_client_event_limit_exceptions: mail-bn8nam04lp2043.outbound.protection.outlook.com ~? 127.0.0.0/8
Jun 25 11:26:25 mail postfix/smtpd[2954]: match_hostaddr: smtpd_client_event_limit_exceptions: 104.47.74.43 ~? 127.0.0.0/8
Jun 25 11:26:25 mail postfix/smtpd[2954]: match_hostname: smtpd_client_event_limit_exceptions: mail-bn8nam04lp2043.outbound.protection.outlook.com ~? 3.220.157.106/32
Jun 25 11:26:25 mail postfix/smtpd[2954]: match_hostaddr: smtpd_client_event_limit_exceptions: 104.47.74.43 ~? <X.X.X.X>/32
Jun 25 11:26:25 mail postfix/smtpd[2954]: match_hostname: smtpd_client_event_limit_exceptions: mail-bn8nam04lp2043.outbound.protection.outlook.com ~? 192.11.231.200/32
Jun 25 11:26:25 mail postfix/smtpd[2954]: match_list_match: mail-bn8nam04lp2043.outbound.protection.outlook.com: no match
Jun 25 11:26:25 mail postfix/smtpd[2954]: match_list_match: 104.47.74.43: no match
Jun 25 11:26:25 mail postfix/smtpd[2954]: send attr request = disconnect
Jun 25 11:26:25 mail postfix/smtpd[2954]: send attr ident = smtpd:104.47.74.43
Jun 25 11:26:25 mail postfix/smtpd[2954]: private/anvil: wanted attribute: status
Jun 25 11:26:25 mail postfix/smtpd[2954]: input attribute name: status
Jun 25 11:26:25 mail postfix/smtpd[2954]: input attribute value: 0
Jun 25 11:26:25 mail postfix/smtpd[2954]: private/anvil: wanted attribute: (list terminator)
Jun 25 11:26:25 mail postfix/smtpd[2954]: input attribute name: (end)

Jun 25 11:26:25 mail postfix/smtpd[2954]: disconnect from mail-bn8nam04lp2043.outbound.protection.outlook.com[104.47.74.43] ehlo=1 starttls=1 quit=1 commands=3

WORKING EMAIL LOGS (bold text with partial logs of successful email message processing and many more log entries before disconnect in the case of successful inbound from different host/email but still in outbound.protection.outlook.com):
Jun 25 12:01:55 mail postfix/smtpd[25123]: connect from mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 220 <my.mail.host> ESMTP Postfix
Jun 25 12:01:55 mail postfix/smtpd[25123]: < mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: EHLO NAM10-MW2-obe.outbound.protection.outlook.com
Jun 25 12:01:55 mail postfix/smtpd[25123]: Anonymous TLS connection established from mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Jun 25 12:01:55 mail postfix/smtpd[25123]: < mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: EHLO NAM10-MW2-obe.outbound.protection.outlook.com
Jun 25 12:01:56 mail postfix/cleanup[25126]: A34DE2C157F1: message-id=<PH0PR08MB7570C16344E8225A460BC4DD9BB79@PH0PR08MB7570.namprd08.prod.outlook.com>

Jun 25 12:01:56 mail postfix/smtpd[25123]: disconnect from mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123] ehlo=2 starttls=1 mail=1 rcpt=1 bdat=1 quit=1 commands=7
Last edited by lzmarine on Tue Jun 28, 2022 7:04 pm, edited 2 times in total.
lzmarine
Posts: 21
Joined: Fri Sep 12, 2014 10:41 pm

Re: repeated connect/session/disconnect from mail-*.outbound.protection.outlook.com and no more emails from organization

Post by lzmarine »

Added additional log info for diffrences between working and failing receiving of emails. There are always additional lines BEFORE the TLS connection only on failure:

Code: Select all

Jun 25 12:00:52 mail postfix/smtpd[25123]: send attr request = tktkey
Jun 25 12:00:52 mail postfix/smtpd[25123]: send attr keyname = [data 0 bytes]
Jun 25 12:00:52 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: status
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute name: status
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute value: 0
Jun 25 12:00:52 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: keybuf
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute name: keybuf
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute value: +tJztLSFn+gnuX6WxHcHDaNVmeQFiCuOMqY9JfCJuaTJfkBoYnlu4rCjZsMcbcS4uk3zj+a46enKeTgB+9GEXMqzDwbnUhkDWgB8EiXi0dviNbdiAAAAAA==
Jun 25 12:00:52 mail postfix/smtpd[25123]: private/tlsmgr: wanted attribute: (list terminator)
Jun 25 12:00:52 mail postfix/smtpd[25123]: input attribute name: (end)
and always EHLO and other lines AFTER TLS connection only on success:

Code: Select all

Jun 25 12:01:55 mail postfix/smtpd[25123]: < mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: EHLO NAM10-MW2-obe.outbound.protection.outlook.com
un 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-my.mail.host
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-PIPELINING
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-SIZE 204800000
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-VRFY
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-ETRN
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-AUTH PLAIN LOGIN
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-AUTH=PLAIN LOGIN
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-ENHANCEDSTATUSCODES
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-8BITMIME
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250-DSN
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250 CHUNKING
Jun 25 12:01:55 mail postfix/smtpd[25123]: < mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: MAIL FROM:<user@source.mail.host> SIZE=22080
Jun 25 12:01:55 mail postfix/smtpd[25123]: > mail-mw2nam10on2123.outbound.protection.outlook.com[40.107.94.123]: 250 2.1.0 Ok
I event got packet captured from mail-*.outbound.protection.outlook.com connections (1 working and 1 non-working), and the packet captures look nearly identical (no unusual data)
Last edited by lzmarine on Tue Jun 28, 2022 7:00 pm, edited 1 time in total.
lzmarine
Posts: 21
Joined: Fri Sep 12, 2014 10:41 pm

Re: repeated connect/session/disconnect from mail-*.outbound.protection.outlook.com and no more emails from organization

Post by lzmarine »

I was able to resolve the issue by applying a "commercial" certificate.

I previously had a self-signed certificate, created and deployed via Zimbra resources. I followed the process from https://computingforgeeks.com/secure-zi ... ertificate to obtain and deploy a certificate from Let's Encrypt. I did need to install certbot via snap (vs apt on Ubuntu): https://certbot.eff.org/instructions?ws ... untuxenial. This installation is required in order to meet the "preferred-chain" mentioned in the Zibra article: https://wiki.zimbra.com/wiki/Installing ... ertificate. The computingforgeels article was more recent and helpful than any Zimbra sources I found. After this, was was able to receive email from the problem domains, and the behavior in the title was no longer observed without sending the email data.

The upside of Let's Encrypt is that the certificate is free, but the downside is that the certificate is only good for 3 months. I did have to stop the mail server (and my http server on the same host) to run the certbot and obtain the certificate. The output from the certbot CLI (for Let's Encrypt) said that some event was created (a reminder?) to renew the certificate. I created a script to run that I think will renew the certificate, but will have to wait and see if this works in 3 months.

As part of the investigation, I also configured DANE with the new certificate. This requires a TLSA DNS record and the zone of the TLSA RR to be DNSSEC enabled. Configuring the zone for DNSSEC can be done completely via your domain registrar or locally on your DNS server (https://bind9.readthedocs.io/en/latest/ ... guide.html) and including the DS record in the parent zone. Once DNSSEC-enabled, create and add the TLSA record to the zone for the mail server FQDN as the RR owner, not the zone as the owner. Below code assumes DNS RR owner FQDN is mail.domain.com, and creates the TLSA records for SMTP ports 25 and 587 for startts, SMTPS port 465 and the same certificate for the web server (same hostname/IP as the SMTP server) on port 443. Note the trailing "." in the hostname, as it is important for DNS zonefiles.

Code: Select all

#!/bin/sh
h='mail.domain.com.'
t=`openssl x509 -noout -fingerprint -sha256 </opt/zimbra/ssl/zimbra/commercial/commercial.crt |tr -d : |cut -d"=" -f2`
echo "_25._tcp.$h IN TLSA 3 0 1 $t"
echo "_443._tcp.$h IN TLSA 3 0 1 $t"
echo "_465._tcp.$h IN TLSA 3 0 1 $t"
echo "_567._tcp.$h IN TLSA 3 0 1 $t"

# General test of configuration: https://www.huque.com/bin/danecheck-smtp
# Microsoft test of configuration: https://testconnectivity.microsoft.com/ ... tion/input
Post Reply