Home / server / Questions / 959629
In Process
dstonek
Asked: 2019-03-24 08:14:12 +0800 CST

Why this email wasn't delivered by Postfix/Dovecot/Procmail?

  • 772

During that day sender sent four other emails after this one. All of them were delivered as usual.
These are the lines of maillog corresponding to that email that was not delivered to recipient.

Mar 22 06:36:19 host postfix/smtpd[10898]: connect from mail-eopbgr20115.outbound.protection.outlook.com[40.107.X.X]

Mar 22 06:36:20 host postfix/smtpd[10898]: setting up TLS connection from mail-eopbgr20115.outbound.protection.outlook.com[40.107.X.X]

Mar 22 06:36:20 host postfix/smtpd[10898]: Anonymous TLS connection established from mail-eopbgr20115.outbound.protection.outlook.com[40.107.X.X]: TLSv1.2 with cipher AES256-SHA256 (256/256 bits)

Mar 22 06:36:20 host postgrey[2424]: action=pass, reason=client whitelist, client_name=mail-eopbgr20115.outbound.protection.outlook.com, client_address=40.107.X.X, sender=sender@sender, [email protected]

Mar 22 06:36:20 host postfix/smtpd[10898]: D6D441CA09A0: client=mail-eopbgr20115.outbound.protection.outlook.com[40.107.X.X]

Mar 22 06:36:21 host postfix/cleanup[12463]: D6D441CA09A0: message-id=< VI1PR01MB4271639DA076BEED2736C9BBA3430@VI1PR01MB4271.eurprd01.prod.exchangelabs.com>

Mar 22 06:36:21 host postfix/cleanup[12463]: D6D441CA09A0: discard: header x-microsoft-antispam-message-info:? 5rSUbtg9a+8v7qvflcvdu8ODNNDgy6QCo+jk8ASeowDSfUDlGtYCfDanPZJMgeVPyAkrokaTR/GTVXYWmsdxNjKqfXtMFFV5oeBuVMt16oe4C6HjA720zoIc55J2J/Mgzz9DS6vIKQ3BUcbQjjryRvMopmcnkloE8rBr from mail-eopbgr20115.outbound.protection.outlook.com[40.107.X.X]; from=< sender@sender> to=< [email protected]> proto=ESMTP helo=< EUR02-VE1-obe.outbound.protection.outlook.com>

Mar 22 06:36:21 host postfix/smtpd[10898]: disconnect from mail-eopbgr20115.outbound.protection.outlook.com[40.107.X.X]

Spamassassin is running but Procmail is set to deliver normally.

These lines are also from maillog of one of the delivered ones.

Mar 22 12:44:03 host postfix/smtpd[2197]: connect from mail-eopbgr00132.outbound.protection.outlook.com[40.107.X.X]

Mar 22 12:44:03 host postfix/smtpd[2197]: setting up TLS connection from mail-eopbgr00132.outbound.protection.outlook.com[40.107.X.X]

Mar 22 12:44:03 host postfix/smtpd[2197]: Anonymous TLS connection established from mail-eopbgr00132.outbound.protection.outlook.com[40.107.X.X]: TLSv1.2 with cipher AES256-SHA256 (256/256 bits)

Mar 22 12:44:03 host postgrey[2424]: action=pass, reason=client whitelist, client_name=mail-eopbgr00132.outbound.protection.outlook.com, client_address=40.107.X.X, sender=sender@sender, recipient=rec@rec

Mar 22 12:44:03 host postfix/smtpd[2197]: BB5741CA09A0: client=mail-eopbgr00132.outbound.protection.outlook.com[40.107.X.X]

Mar 22 12:44:03 host postfix/cleanup[3184]: BB5741CA09A0: message-id=< VI1PR01MB4271B2A2EA25E7D9246BB185A3430@VI1PR01MB4271.eurprd01.prod.exchangelabs.com>

Mar 22 12:44:04 host opendkim[2109]: BB5741CA09A0: mail-eopbgr00132.outbound.protection.outlook.com [40.107.X.X] not internal

Mar 22 12:44:04 host opendkim[2109]: BB5741CA09A0: not authenticated

Mar 22 12:44:04 host opendkim[2109]: BB5741CA09A0: failed to parse authentication-results: header field

Mar 22 12:44:04 host opendkim[2109]: BB5741CA09A0: DKIM verification successful

Mar 22 12:44:04 host postfix/qmgr[2515]: BB5741CA09A0: from=< sender@sender>, size=12328, nrcpt=1 (queue active)

Mar 22 12:44:04 host postfix/pickup[1223]: 362C71CA0B4D: uid=584 from=< rec>

Mar 22 12:44:04 host postfix/cleanup[3184]: 362C71CA0B4D: message-id=< VI1PR01MB4271B2A2EA25E7D9246BB185A3430@VI1PR01MB4271.eurprd01.prod.exchangelabs.com>

Mar 22 12:44:04 host postfix/local[3190]: BB5741CA09A0: to=< rec@XXhost>, orig_to=< rec@rec>, relay=local, delay=0.54, delays=0.46/0/0/0.08, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail-wrapper -o -a $DOMAIN -d $LOGNAME)

Mar 22 12:44:04 host postfix/qmgr[2515]: BB5741CA09A0: removed

Mar 22 12:44:04 host opendkim[2109]: 362C71CA0B4D: no signing table match for 'sender@sender'

Mar 22 12:44:04 host opendkim[2109]: 362C71CA0B4D: failed to parse authentication-results: header field

Mar 22 12:44:04 host opendkim[2109]: 362C71CA0B4D: DKIM verification successful

Mar 22 12:44:04 host postfix/smtpd[2197]: warning: network_biopair_interop: error writing 69 bytes to the network: Connection reset by peer

Mar 22 12:44:04 host postfix/smtpd[2197]: warning: network_biopair_interop: error writing 69 bytes to the network: Broken pipe

Mar 22 12:44:04 host postfix/smtpd[2197]: disconnect from mail-eopbgr00132.outbound.protection.outlook.com[40.107.X.X]

EDIT (Answering some comments/questions)

Postfix Header and Body checks don't contain anything about "Microsoft-antispam" or something like that, only "/Republique du Benin/" and other known strings only are in spam headers/bodies.

Header checks: enter image description here
Body checks: enter image description here 

cat /path-to-Mar22-procmail.log | grep sender's name

outputs the other 4 delivered messages, not the Mar 22 06:36: one
procmai.rc of this user only has a forward directive regarding sender's name

I understand that that Microsoft antispam header might be causing the issue but I don't get what happened.

EDIT 2:
Looking at the header of the second message sent and delivered it also contains MS antispam msg that wasn't explicity recorded in log file:

x-microsoft-antispam-message-info: Dgz3XVK6DEMeeorg2JFa7q8+XuAbKdJSYQ7Q90u5ByPqwwuvuoBx7bfKh4rWYzkdgu4EYFwgk6idK2YswaKyN8uwCuqVh41lQWVja0GMMiyIA3F2r4h0kHmk+E6aIhMoju4h7mNl6/4KaDYx20AAplVJk99gFq6TEm6I7z4GIu8OngM6FkH6UQj/vF89sa2NkI4edRaMidxoXSujy6umqUVl9qEn74mLttPfLxQkl4DDtV95Idt/hGAGuvYYzzkQc1LaxD/F9ICa6F3l6NHE1d9f2t0ZfAFa7tl3OGUJsMtHK5xL5X/vlWAcfdlqCsqOYIs0wJ+gCgjqYQ6GWZmmXIVAwQuyMwAtw7IxwItfod+bne1k9lMk0iZtooT8Kh6abJYGBemL9wGDtPL9JaArmau4h6rkAcjp2pSQmrD5o4o=

This is quite longer than the other one.

postfix

2 Answers

  1. My guess is that your 'header_checks' regex /.icu/ is matching something in the full x-microsoft-antispam-message-info header. Postfix does not log all of very long headers and that's a very loose regex because you have the wildcard. Seems like a very risky pattern to me but do as you want with your own mail...

    Note that "x-microsoft-antispam-message-info" is not documented, but it almost always contains >300 or <100 characters and most often is 428 characters.

    • 1

  2. The main difference I see is that the outlook server where the message originated added a header, "x-microsoft-antispam-message-info", to the message that failed to deliver. Apparently, for whatever reason, outlook tagged the message as possible spam. I would look through all my mail config to see if that header triggers any special processing.

    • 0