Inbound emails not being sent from MailScanner to Postfix

[robachicken]

I've recently installed EFA (3.0.1.5) and had a few troubles getting emails to deliver correctly.

Emails were showing in in the GUI and watching /var/log/maillog shows the emails were being processed, yet they weren't being delivered. Comparing this between another new/fresh install, it seems the messages were being processed by MailScanner but never passed to postfix to send the email.

Broken messagelog looks like this:

Code: Select all

Nov 28 22:24:56 efa postfix/smtpd[17624]: connect from unknown[216.3.4.66]
Nov 28 22:24:56 efa postfix/smtpd[17624]: warning: unknown[216.3.4.66]: SASL LOGIN authentication failed: authentication failure
Nov 28 22:24:56 efa postfix/smtpd[17624]: lost connection after AUTH from unknown[216.3.4.66]
Nov 28 22:24:56 efa postfix/smtpd[17624]: disconnect from unknown[216.3.4.66] ehlo=1 auth=0/1 rset=1 commands=2/3
Nov 28 22:24:58 efa postfix/smtpd[17624]: connect from mail-eopbgr50090.outbound.protection.outlook.com[40.107.5.90]
Nov 28 22:24:58 efa postfix/smtpd[17624]: Anonymous TLS connection established from mail-eopbgr50090.outbound.protection.outlook.com[40.107.5.90]: TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits)
Nov 28 22:24:59 efa postfix/smtpd[17624]: BB92910005E: client=mail-eopbgr50090.outbound.protection.outlook.com[40.107.5.90]
Nov 28 22:24:59 efa postfix/cleanup[17627]: BB92910005E: hold: header Received: from EUR03-VE1-obe.outbound.protection.outlook.com (mail-eopbgr50090.outbound.protection.outlook.com [40.107.5.90])??(using TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits))??(No c from mail-eopbgr50090.outbound.protection.outlook.com[40.107.5.90]; from=<rob@workdomain.com> to=<rob@mydomain.com> proto=ESMTP helo=<EUR03-VE1-obe.outbound.protection.outlook.com>
Nov 28 22:24:59 efa postfix/cleanup[17627]: BB92910005E: message-id=<VI1PR0301MB2271B0D6E2D5B8B3ED3A6B83C58A0@VI1PR0301MB2271.eurprd03.prod.outlook.com>
Nov 28 22:25:00 efa postfix/smtpd[17624]: disconnect from mail-eopbgr50090.outbound.protection.outlook.com[40.107.5.90] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Nov 28 22:25:00 efa MailScanner[17597]: New Batch: Scanning 1 messages, 8806 bytes
Nov 28 22:25:00 efa MailScanner[17597]: Virus and Content Scanning: Starting
Nov 28 22:25:00 efa MailScanner[17597]: Spam Checks: Starting
Nov 28 22:25:25 efa MailScanner[17597]: Deleted 1 messages from processing-database
Nov 28 22:25:25 efa MailScanner[17597]: Logging message BB92910005E.AE58A to SQL

Working maillog looks like this:

Code: Select all

Nov 28 22:26:59 efa postfix/smtpd[18332]: connect from mail-eopbgr50096.outbound.protection.outlook.com[40.107.5.96]
Nov 28 22:26:59 efa postfix/smtpd[18332]: Anonymous TLS connection established from mail-eopbgr50096.outbound.protection.outlook.com[40.107.5.96]: TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits)
Nov 28 22:26:59 efa postfix/smtpd[18332]: 7365A10005E: client=mail-eopbgr50096.outbound.protection.outlook.com[40.107.5.96]
Nov 28 22:26:59 efa postfix/cleanup[18334]: 7365A10005E: hold: header Received: from EUR03-VE1-obe.outbound.protection.outlook.com (mail-eopbgr50096.outbound.protection.outlook.com [40.107.5.96])??(using TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits))??(No c from mail-eopbgr50096.outbound.protection.outlook.com[40.107.5.96]; from=<rob@workdomain.com> to=<rob@mydomain.com> proto=ESMTP helo=<EUR03-VE1-obe.outbound.protection.outlook.com>
Nov 28 22:26:59 efa postfix/cleanup[18334]: 7365A10005E: message-id=<VI1PR0301MB22710EE7FBE9D8B7EFD916F2C58A0@VI1PR0301MB2271.eurprd03.prod.outlook.com>
Nov 28 22:26:59 efa postfix/smtpd[18332]: disconnect from mail-eopbgr50096.outbound.protection.outlook.com[40.107.5.96] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Nov 28 22:27:01 efa MailScanner[18321]: New Batch: Scanning 1 messages, 8798 bytes
Nov 28 22:27:01 efa MailScanner[18321]: Virus and Content Scanning: Starting
Nov 28 22:27:01 efa MailScanner[18321]: Spam Checks: Starting
Nov 28 22:27:27 efa MailScanner[18321]: Requeue: 7365A10005E.A5397 to D8275100065
Nov 28 22:27:27 efa MailScanner[18321]: Uninfected: Delivered 1 messages
Nov 28 22:27:27 efa postfix/qmgr[8358]: D8275100065: from=<rob@workdomain.com, size=7922, nrcpt=1 (queue active)
Nov 28 22:27:27 efa MailScanner[18321]: Deleted 1 messages from processing-database
Nov 28 22:27:27 efa MailScanner[18321]: Logging message 7365A10005E.A5397 to SQL
Nov 28 22:27:27 efa postfix/smtp[18469]: D8275100065: to=<rob@mydomain.com>, relay=192.168.68.6[192.168.68.6]:25, delay=28, delays=28/0.01/0.06/0.25, dsn=2.6.0, status=sent (250 2.6.0 <VI1PR0301MB22710EE7FBE9D8B7EFD916F2C58A0@VI1PR0301MB2271.eurprd03.prod.outlook.com> [InternalId=62886911148033, Hostname=myhostname] Queued mail for delivery)
Nov 28 22:27:27 efa postfix/qmgr[8358]: D8275100065: removed

Notice the bit between "logging message" and "removed".

After ruling out the Exchange end it seems there's a rather nasty bug within the configuration. I repeated the configuration on a new box, testing after every edit I made. It seems when modifying Non Spam Settings, specifically "Non Spam Inline Signature Settings" (Spam Settings, Non Spam Settings) it clears the "Non Spam Actions = " from /etc/MailScanner/MailScanner.conf which then stops it from being delivered.

To resolve, go to shell and then edit/nano /etc/MailScanner/MailScanner.conf.
Search for Non Spam Actions and change the line to read:

Code: Select all

Non Spam Actions = store deliver header "X-Spam-Status:No"

Or if you want the signatures back, change it to:

Code: Select all

Non Spam Actions = store deliver header "X-Spam-Status:No" custom(nonspam)

Then reload mail scanner (service MailScanner reload)

Hopefully this should save anyone else having the same headache I had...

Any questions give me a shout.
Cheers,
Robachicken

[shawniverson]

Thank you for the detailed update. I am going to attempt to replicate this issue and resolve.

[shawniverson]

https://github.com/E-F-A/v3/issues/340