2
Save the SmarterMail routing and spam headers at/in the Message Archive for analyzing and customer support
Idea shared by Etienne Wilderink - 5/13/2019 at 6:49 AM
Under Consideration
It would be very convenient to have an overview of the headers that SmarterMail has added to a message before sending it to its final recipient. At this moment when we want to analyze the spam-score or delivery route, we have to gather the information from different log files, the Message Archive and some positive guesswork. The same applies when we intercept the message at Command Line level (spool and/or antivirus) or the proc-folder (antispam level): neither the .HDR nor the .EML file contain any information about the actions already applied

Currently we are in the progress of setting up a SmarterMail deployment to migrate our current platform, and after analyzing several messages we now started to ask our test-customers to forward the received message to save us time. Perhaps we have become too used to the filter and logging options in our current MDaemon stack, but is there any way to make analyzing message flows easier? I have already tried to combine the logs into Graylog, but I have the feeling that we are missing some crucial information to link all the parts together.

1 Reply

Reply to Thread
0
Tony Scholz Replied
Employee Post
Hello, 

When you are combining the logs what logs are you combining. Generally when I am trying to track an issue I can get 90% of what I need from the SMTP and Delivery logs ( set to Detailed ) and if there is a SPAM scoring/checks issue I would also review the "Spam Checks" log. 

Here is an example of the flow. 

--- SMTP ---
[2019.05.13] 09:56:38.309 [216.167.205.23][27287719] rsp: 250 OK
[2019.05.13] 09:56:38.309 [216.167.205.23][27287719] Received message size: 1739 bytes
[2019.05.13] 09:56:38.309 [216.167.205.23][27287719] Successfully wrote to the HDR file. (c:\SmarterMail\Spool\SubSpool4\43956210.hdr)
[2019.05.13] 09:56:38.309 [216.167.205.23][27287719] Data transfer succeeded, writing mail to 43956210.eml (MessageID: <c66b224822df45adb130661165f5b441@ap-email.com>)
[2019.05.13] 09:56:38.394 [216.167.205.23][27287719] cmd: QUIT
[2019.05.13] 09:56:38.394 [216.167.205.23][27287719] rsp: 221 Service closing transmission channel
[2019.05.13] 09:56:38.394 [216.167.205.23][27287719] disconnected at 5/13/2019 9:56:38 AM

Here you can see that the SMTP session wrote to 43956210.eml. By taking the last 5 of this number you can grab the session information from the DELIVERY and the SPAM CHECK logs. 

--- DELIVERY --- 
[2019.05.13] 09:56:41.126 [56210] Delivery started for {FROM_ADDRESS} at 9:56:41 AM
[2019.05.13] 09:56:47.147 [56210] Added to SpamCheckQueue (1 queued; 0/30 processing)
[2019.05.13] 09:56:47.147 [56210] [SpamCheckQueue] Begin Processing.
[2019.05.13] 09:56:47.241 [56210] Starting Spam Checks.
[2019.05.13] 09:56:47.441 [56210] Spam check results: [REVERSE DNS LOOKUP: 0,None], [NULL SENDER: 0,passed], [_CYREN: 0,Unknown], [_MESSAGESNIFFER: 0,code:0], [_INTERNALSPAMASSASSIN: 0:0], [_SPF: 25,None], [_DKIM: 0,Pass], [BARRACUDA - RBL: 0,passed], [CBL - ABUSE SEAT: 0,passed], [FIVE-TEN: 0,passed], [HOSTKARMA - BLACKLIST: 0,passed], [HOSTKARMA - BROWNLIST: 0,passed], [MAILSPIKE Z: 0,passed], [NOABUSE: 0,passed], [NOPOSTMASTER: 0,passed], [PROTECTED SKY - RED: 0,passed], [PROTECTED SKY - YELLOW: 0,passed], [RFC2 REALTIME LIST: 0,passed], [SEM-FRESH: 0,passed], [SORBS 02 - HTTP: 0,passed], [SORBS 03 - SOCKS: 0,passed], [SORBS 04 - MISC: 0,passed], [SORBS 05 - SMTP: 0,passed], [SORBS 06 - RECENT: 0,passed], [SORBS 07 - WEB: 0,passed], [SORBS 08 - BLOCK: 0,passed], [SORBS 09 - ZOMBIE: 0,passed], [SORBS 10 - DYNAMIC IP: 0,passed], [SORBS 11 - BAD CONFIG: 0,passed], [SORBS 12 - NOMAIL: 0,passed], [SORBS 13 - NOSERVER: 0,passed], [SPAMCOP: 0,passed], [SPAMHAUS - PBL 1: 0,passed], [SPAMHAUS - PBL 2: 0,passed], [SPAMHAUS - SBL 1: 0,passed], [SPAMHAUS - SBL 2: 0,passed], [SPAMHAUS - XBL 1: 0,passed], [SPAMHAUS - XBL 2: 0,passed], [SPAMHAUS - XBL 3: 0,passed], [SPAMHAUS - XBL 4: 0,passed], [SPAMHAUS - ZEN: 0,passed], [SPAMRATS: 0,passed], [SURBL - JWSPAMSPY: 0,passed], [SURBL – MALWARE: 0,passed], [SURBL – PHISHING: 0,passed], [SURBL – SA BLACKLIST: 0,passed], [SURBL - SPAMASSASSIN: 0,passed], [SURBL – SPAMCOP WEB: 0,passed], [SURRIEL: 0,passed], [UCEPROTECT LEVEL 1: 0,passed], [UCEPROTECT LEVEL 2: 0,passed], [UCEPROTECT LEVEL 3: 0,passed], [VIRUS RBL - MSRBL: 0,passed]
[2019.05.13] 09:56:47.441 [56210] Spam Checks completed.
[2019.05.13] 09:56:47.441 [56210] Removed from SpamCheckQueue (0 queued or processing)
[2019.05.13] 09:56:50.158 [56210] Added to LocalDeliveryQueue (0 queued; 1/50 processing)
[2019.05.13] 09:56:50.158 [56210] [LocalDeliveryQueue] Begin Processing.
[2019.05.13] 09:56:50.158 [56210] Starting local delivery to {TO_ADDRESS}
[2019.05.13] 09:56:50.173 [56210] Delivery for {FROM _ADDRESS} to {TO_ADDRESS} has completed (Delivered) Filter: None
[2019.05.13] 09:56:50.173 [56210] End delivery to {TO_ADRESS} (MessageID: <c66b224822df45adb130661165f5b441@ap-email.com>)
[2019.05.13] 09:56:50.173 [56210] Removed from LocalDeliveryQueue (0 queued or processing)
[2019.05.13] 09:56:53.158 [56210] Removing Spool message: Killed: False, Failed: False, Finished: True
[2019.05.13] 09:56:53.158 [56210] Delivery finished for postmaster@ap-email.com at 9:56:53 AM    [id:43956210]

To get detailed Spam check information you grab the same session number and check the spam logs

--- SPAM CHECKS ---
09:56:47.147 [56210] SpamCheck Processing Thread Started
09:56:47.147 [56210] Starting ClamD Check.
09:56:47.163 [56210] ClamD Checks completed.
09:56:47.163 [56210] Starting Cyren checks.
09:56:47.241 [56210] Cyren Checks completed.
09:56:47.241 [56210] Starting Command Line Checks.
09:56:47.241 [56210] Command Line Checks completed.
09:56:47.241 [56210] Starting Filetype Checks.
09:56:47.241 [56210] Filetype Checks completed.
09:56:47.241 [56210] Spam checks to run: Reverse Dns Lookup, Null Sender, Cyren, Message Sniffer, ...
09:56:47.241 [56210] Found 53 spam checks to run: Reverse Dns Lookup, Null Sender, Cyren, Message ...
09:56:47.241 [IP_ADDRESS] Could not parse IP, resolving reverse dns check as None.
09:56:47.301 Running SPF check on 56210
09:56:47.301 Finished SPF check on 56210; result = None
09:56:47.301 [56210] [DKIM] Performing DKIM check...
09:56:47.347 [56210] [DKIM] Result: Good.
09:56:47.441 [56210] Spam Checks completed.
09:56:47.441 [56210] SpamCheck Processing Thread Completed

The three logs here should get most of the data that you need. I would be happy to submit a feature request for you as well. What information are you lookin got have in this new comprehensive log so that I can add that to the feature request. 

Thank you

Tony Scholz System/Network Administrator SmarterTools Inc. www.smartertools.com

Reply to Thread