The SpamTitan mail log contains all the output from the two main mail processing services, Postfix and Amavis. Using the information in the mail log in conjunction with details from Reporting->History you can trace the path of a mail right through the SpamTitan appliance to the destination server, or shed light on why a mail was not delivered.
The mail log entries can be mixed up, there are multiple instances of Postfix and Amavisd processing mail simultaneously so entries for different mails will over lap. The log entries will follow this format:
[ Date & Time] [Sever name] [Service/subservice] [Process id] [Message]
First Contact
The initial log entry for any mail will be the connect from the server:
Aug 15 15:19:57 mail3 postfix/smtpd[14390]: connect from mail-vb0-f68.google.com[209.85.212.68]
This and the following two entries are from the postfix/smtpd (SMTP Daemon) service which listens for and accepts incoming mail.
The next log entry outputs more details about the mail and the server sending it and indicates that the mail will be spam tested (indicated by bold text):
Aug 15 15:19:58 mail3 postfix/smtpd[14390]: NOQUEUE: filter: RCPT from mail-vb0-f68.google.com[209.85.212.68]: <mail-vb0-f68.google.com[209.85.212.68]>: Client host triggers FILTER smtp-amavis:[127.0.0.1]:10024; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<mail-vb0-f68.google.com>
We will see a log entry later where the mail will be passed to 127.0.0.1 on port 10024. This is the mail being passed to Amavis to be scanned.
The mail is then assigned a queue id (highlighted in bold):
Aug 15 15:19:59 mail3 postfix/smtpd[14390]: 5439CE7CAB: client=mail-vb0-f68.google.com[209.85.212.68]
The Queue ID will also be listed in the received headers of a mail. You can search the mail logs from the Logs tab in the SpamTitan web interface for a Queue ID and find the related log entries.
The Message ID is displayed in next, this id is from the headers of the mail and can uniquely identify the mail across servers:
Aug 15 15:19:59 mail3 postfix/cleanup[15853]: 5439CE7CAB: message-id=<CAEvtjCk-97+YqQxHKq6V3-6iRvh6g4NCMh-6vcsttL_-iC=NOg@mail.gmail.com>
This log entry is from the postfix/cleanup service. The cleanup daemon processes inbound mail, inserts it into the incoming mail queue, and informs the queue manager (postfix/qmgr) of its arrival.
The mail is then entered in to the active queue:
Aug 15 15:19:59 mail3 postfix/qmgr[14386]: 5439CE7CAB: from=<[email protected]>, size=2006, nrcpt=1 (queue active)
The mail has now been delivered from the Google server and accepted by SpamTitan so the Google server disconnects:
Aug 15 15:19:59 mail3 postfix/smtpd[14390]: disconnect from mail-vb0-f68.google.com[209.85.212.68]
If SPF is enabled SpamTitan will verify if the mail is being sent from an authorised server:
Aug 15 15:19:59 mail3 postfix/policy-spf[14406]: : SPF pass (Mechanism 'include:_netblocks.google.com' matched): Envelope-from: [email protected]
Aug 15 15:19:59 mail3 postfix/policy-spf[14406]: handler sender_policy_framework: is decisive.
Aug 15 15:19:59 mail3 postfix/policy-spf[14406]: : Policy action=PREPEND Received-SPF: pass (gmail.com ... _spf.google.com: Sender is authorized to use '[email protected]' in 'mfrom' identity (mechanism 'include:_netblocks.google.com' matched)) receiver=mail3; identity=mailfrom; envelope-from="[email protected]"; helo=mail-vb0-f68.google.com; client-ip=209.85.212.68
The text in bold shows that the server is authorized to send mail for the gmail.com domain. If the SPF test was failed the mail would be dropped at this point.
Virus scan, Banned Attachment check & Spam testing
Next the mail is passed to Amavis via the local port 10024:
Aug 15 15:20:06 mail3 postfix/smtp[14387]: 5439CE7CAB: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=8.3, delays=1.4/2/0/4.8, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 59D91E7A6C)
As the mail has left Postfix the queue manager removes the file and queue id. The mail will be assigned a new queue id which we can see at the end of the last log entry (59D91E7A6C)
Aug 15 15:20:06 mail3 postfix/qmgr[14386]: 5439CE7CAB: removed
Next the mail comes back from Amavis and goes through the same frist steps as when initially delivered:
Aug 15 15:20:06 mail3 postfix/smtpd[14440]: connect from localhost.mpt.ie[127.0.0.1]
Aug 15 15:20:06 mail3 postfix/smtpd[14440]: 59D91E7A6C: client=localhost.mpt.ie[127.0.0.1]
Aug 15 15:20:06 mail3 postfix/cleanup[14398]: 59D91E7A6C: message-id=<CAEvtjCk-97+YqQxHKq6V3-6iRvh6g4NCMh-6vcsttL_-iC=NOg@mail.gmail.com>
Then Amavis inserts the results of the scans:
Aug 15 15:20:06 mail3 amavis[15820]: (15820-03) Passed CLEAN {RelayedInbound}, [209.85.212.68]:48820 [209.85.212.68] <[email protected]> -> <[email protected]>, Queue-ID: 5439CE7CAB, Message-ID: <CAEvtjCk-97+YqQxHKq6V3-6iRvh6g4NCMh-6vcsttL_-iC=NOg@mail.gmail.com>, mail_id: S1f_U73_f0gJ, Hits: -1.649, size: 2005, queued_as: 59D91E7A6C, Tests: [BAYES_00=-1.9,DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,FREEMAIL_ENVFROM_END_DIGIT=0.25,FREEMAIL_FROM=0.001,HTML_MES
SAGE=0.001,RCVD_IN_DNSWL_LOW=-0.7,SPF_PASS=-0.001,ST_P0F_UNKN=0.8], dkim_sd=20120113:gmail.com, 4750 ms
This log entry tells us the Mail ID which is also displayed in Reporting->History as the Msg ID. The spam score of the mail (Hits: -1.649). The individual tests that were triggered and resulted in that score:
Tests: [BAYES_00=-1.9,DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,FREEMAIL_ENVFROM_END_DIGIT=0.25,FREEMAIL_FROM=0.001,HTML_MESSAGE=0.001,RCVD_IN_DNSWL_LOW=-0.7,SPF_PASS=-0.001,ST_P0F_UNKN=0.8]
If you get a Msd ID from Reporting->History you can search the mail logs in the Logs tab and it will find an entry like the one above which will show you the tests that that particular mail triggered. A lot of the test descriptions are available on the internet and a quick search will find them.
The next entry tells us the action taken by Amavis, in this case "Passed CLEAN". "Blocked SPAM" is the other option.
Aug 15 15:20:06 mail3 amavis[15820]: (15820-03) Passed CLEAN, <[email protected]> -> <[email protected]>, Hits: -1.649, tag=-999, tag2=5, kill=5, queued_as: 59D91E7A6C, L/Y/0/0
Delivery to destination
The Postfix queue manager then delivers the mail to the recipient (using TLS in this instance):
Aug 15 15:20:06 mail3 postfix/qmgr[14386]: 59D91E7A6C: from=<[email protected]>, size=2505, nrcpt=1 (queue active)
Aug 15 15:20:06 mail3 postfix/smtp[14445]: setting up TLS connection to 10.1.0.15[10.1.0.15]:25
Aug 15 15:20:06 mail3 postfix/smtp[14445]: Untrusted TLS connection established to 10.1.0.15[10.1.0.15]:25: TLSv1 with cipher ADH-CAMELLIA256-SHA (256/256 bits)
Aug 15 15:20:06 mail3 postfix/smtp[14445]: 59D91E7A6C: to=<[email protected]>, relay=10.1.0.15[10.1.0.15]:25, delay=0.1, delays=0.04/0/0.02/0.04, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 172856338E)
Aug 15 15:20:06 mail3 postfix/qmgr[14386]: 59D91E7A6C: removed
The text in bold is the response from the server that SpamTitan delivered the mail too, it the mail was rejected by the server that would also be listed there.
All log entries in sequence
Aug 15 15:19:57 mail3 postfix/smtpd[14390]: connect from mail-vb0-f68.google.com[209.85.212.68]
Aug 15 15:19:58 mail3 postfix/smtpd[14390]: NOQUEUE: filter: RCPT from mail-vb0-f68.google.com[209.85.212.68]: <mail-vb0-f68.google.com[209.85.212.68]>: Client host triggers FILTER smtp-amavis:[127.0.0.1]:10024; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<mail-vb0-f68.google.com>
Aug 15 15:19:59 mail3 postfix/smtpd[14390]: 5439CE7CAB: client=mail-vb0-f68.google.com[209.85.212.68]
Aug 15 15:19:59 mail3 postfix/cleanup[15853]: 5439CE7CAB: message-id=<CAEvtjCk-97+YqQxHKq6V3-6iRvh6g4NCMh-6vcsttL_-iC=NOg@mail.gmail.com>
Aug 15 15:19:59 mail3 postfix/qmgr[14386]: 5439CE7CAB: from=<[email protected]>, size=2006, nrcpt=1 (queue active)Aug 15 15:19:59 mail3 postfix/smtpd[14390]: disconnect from mail-vb0-f68.google.com[209.85.212.68]
Aug 15 15:19:59 mail3 postfix/policy-spf[14406]: : SPF pass (Mechanism 'include:_netblocks.google.com' matched): Envelope-from: [email protected]
Aug 15 15:19:59 mail3 postfix/policy-spf[14406]: handler sender_policy_framework: is decisive.
Aug 15 15:19:59 mail3 postfix/policy-spf[14406]: : Policy action=PREPEND Received-SPF: pass (gmail.com ... _spf.google.com: Sender is authorized to use '[email protected]' in 'mfrom' identity (mechanism 'include:_netblocks.google.com' matched)) receiver=mail3; identity=mailfrom; envelope-from="[email protected]"; helo=mail-vb0-f68.google.com; client-ip=209.85.212.68Aug 15 15:20:06 mail3 postfix/smtp[14387]: 5439CE7CAB: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=8.3, delays=1.4/2/0/4.8, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 59D91E7A6C)
Aug 15 15:20:06 mail3 postfix/qmgr[14386]: 5439CE7CAB: removed
Aug 15 15:20:06 mail3 postfix/smtpd[14440]: connect from localhost.mpt.ie[127.0.0.1]
Aug 15 15:20:06 mail3 postfix/smtpd[14440]: 59D91E7A6C: client=localhost.mpt.ie[127.0.0.1]
Aug 15 15:20:06 mail3 postfix/cleanup[14398]: 59D91E7A6C: message-id=<CAEvtjCk-97+YqQxHKq6V3-6iRvh6g4NCMh-6vcsttL_-iC=NOg@mail.gmail.com>
Aug 15 15:20:06 mail3 amavis[15820]: (15820-03) Passed CLEAN {RelayedInbound}, [209.85.212.68]:48820 [209.85.212.68] <[email protected]> -> <[email protected]>, Queue-ID: 5439CE7CAB, Message-ID: <CAEvtjCk-97+YqQxHKq6V3-6iRvh6g4NCMh-6vcsttL_-iC=NOg@mail.gmail.com>, mail_id: S1f_U73_f0gJ, Hits: -1.649, size: 2005, queued_as: 59D91E7A6C, Tests: [BAYES_00=-1.9,DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,FREEMAIL_ENVFROM_END_DIGIT=0.25,FREEMAIL_FROM=0.001,HTML_MES
SAGE=0.001,RCVD_IN_DNSWL_LOW=-0.7,SPF_PASS=-0.001,ST_P0F_UNKN=0.8], dkim_sd=20120113:gmail.com, 4750 msg 15 15:20:06 mail3 amavis[15820]: (15820-03) Passed CLEAN, <[email protected]> -> <[email protected]>, Hits: -1.649, tag=-999, tag2=5, kill=5, queued_as: 59D91E7A6C, L/Y/0/0Aug 15 15:20:06 mail3 postfix/qmgr[14386]: 59D91E7A6C: from=<[email protected]>, size=2505, nrcpt=1 (queue active)
Aug 15 15:20:06 mail3 postfix/smtp[14445]: setting up TLS connection to 10.1.0.15[10.1.0.15]:25
Aug 15 15:20:06 mail3 postfix/smtp[14445]: Untrusted TLS connection established to 10.1.0.15[10.1.0.15]:25: TLSv1 with cipher ADH-CAMELLIA256-SHA (256/256 bits)
Aug 15 15:20:06 mail3 postfix/smtp[14445]: 59D91E7A6C: to=<[email protected]>, relay=10.1.0.15[10.1.0.15]:25, delay=0.1, delays=0.04/0/0.02/0.04, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 172856338E)
Aug 15 15:20:06 mail3 postfix/qmgr[14386]: 59D91E7A6C: removed
