I have not been satisfied with the Mail Manager user interface, as some data is not included, some data is hard to read, the query capabilities are limited, and the data cannot be exported for further analysis.   GDPR created lots of interest in mandatory TLS, so it was interesting to investigate how one proves that messages are being transmitted with an acceptable ciphersuite.   I was also interested in the question of how often DKIM signatures are used, and whether they validate.

The log file has all of the data needed to answer these questions, but parsing it is a bit of a challenge.   After slogging through the process, I decided to document my results.

Understanding the Data

My discussion will use the following example log entries.   I have extracted all of the log entries related to a single message, and then sanitized the data.   In an actual log file, log entries for other messages can be interspersed with each other.   This means that physical proximity can be expected, but physical adjacency cannot.

1. 2019:06:10-11:04:40 defense exim-in[6854]: 2019-06-10 11:04:40 SMTP connection from [ip1.ip2.ip3.ip4]:53500 (TCP/IP connection count = 1)

2. 2019:06:10-11:04:40 defense exim-in[9103]: 2019-06-10 11:04:40 H=server.serverdomain.tld [ip1.ip2.ip3.ip4]:53500 Warning: targetdomain.tld profile excludes greylisting: Skipping greylisting for this message

3. 2019:06:10-11:04:40 defense exim-in[9103]: 2019-06-10 11:04:40 [ip1.ip2.ip3.ip4] F=<SRS0=tyYMsf=UJ=senderdomain.tld=sendinguser@forwardingdomain.tld> R=<targetuser@targetdomain.tld> Accepted: from relay

4. 2019:06:10-11:04:40 defense exim-in[9103]: 2019-06-10 11:04:40 1haLqi-0002Mp-2G DKIM: d=senderdomain.tld s=dkim c=relaxed/relaxed a=rsa-sha256 [verification succeeded]

5. 2019:06:10-11:04:41 defense exim-in[9103]: 2019-06-10 11:04:41 1haLqi-0002Mp-2G ctasd reports 'Unknown' RefID:str=0001.0A090201.5CFE7189.0011,ss=1,re=0.000,recu=0.000,reip=0.000,cl=1,cld=1,fgs=0

6. 2019:06:10-11:04:41 defense exim-in[9103]: 2019-06-10 11:04:41 1haLqi-0002Mp-2G <= SRS0=tyYMsf=UJ=senderdomain.tld=sendinguser@forwardingdomain.tld H=server.serverdomain.tld [ip1.ip2.ip3.ip4]:53500 P=esmtps X=TLSv1.2:DHE-RSA-AES256-GCM-SHA384:256 S=67579 id=02ec01d51f9d$d1192430$734b6c90$@senderdomain.tld

7. 2019:06:10-11:04:41 defense exim-in[9103]: 2019-06-10 11:04:41 SMTP connection from server.serverdomain.tld [ip1.ip2.ip3.ip4]:53500 closed by QUIT

8. 2019:06:10-11:04:43 defense smtpd[6746]: QMGR[6746]: 1haLqi-0002Mp-2G moved to work queue

9. 2019:06:10-11:04:43 defense smtpd[9095]: SCANNER[9095]: 1haLql-0002Mh-MA <= sendinguser@senderdomain.tld R=1haLqi-0002Mp-2G P=INPUT S=63168

10. 2019:06:10-11:04:43 defense smtpd[9095]: SCANNER[9095]: id="1000" severity="info" sys="SecureMail" sub="smtp" name="email passed" srcip="ip1.ip2.ip3.ip4" from="sendinguser@senderdomain.tld" to="targetuser@targetdomain.tld" subject="Statement" queueid="1haLql-0002Mh-MA" size="63168"

11. 2019:06:10-11:04:43 defense smtpd[9095]: SCANNER[9095]: 1haLqi-0002Mp-2G => work R=SCANNER T=SCANNER

12. 2019:06:10-11:04:43 defense smtpd[9095]: SCANNER[9095]: 1haLqi-0002Mp-2G Completed

13. 2019:06:10-11:04:44 defense exim-out[9113]: 2019-06-10 11:04:44 1haLql-0002Mh-MA => targetuser@targetdomain.tld P=<sendinguser@senderdomain.tld> R=static_route_hostlist T=static_smtp H=192.168.99.3 [192.168.99.3]:25 X=TLSv1.2:AES128-SHA256:128 C="250 2.6.0 <02ec01d51f9d$d1192430$734b6c90$@senderdomain.tld> [InternalId=27538] Queued mail for delivery"

14. 2019:06:10-11:04:44 defense exim-out[9113]: 2019-06-10 11:04:44 1haLql-0002Mh-MA Completed

Noteworthy elements:

• The message flows through three processing stages: exim-in, smtpd, and exim-out.
• First, the incoming communication connection is established (line 1) and closed (line 7).
• Exim-in phase:
  • The exim-in phase occurs next (lines 2-7). The exim process number (exim-in[9103]) uniquely identifies the process for a single message, but the process number will be reused over time.   I have seen the number reused in a single day, several hours apart.   Reuse rates probably depend on message volume.
  • The entries for greylisting (line 2), DKIM (line 4), and Antivirus (line 4) have only the exim-in process number for matching to other records, so the match process needs to consider the process number as well as rough proximity in time and physical position.
  • Line 3 contains the From information (F=address), To information (R=address), and source IP address.
  • Line 4 is the DKIM signature check results. UTM verifies all signatures even though it does not seem to do anything with the result.   A message can have multiple signatures, so there will be one DKIM result line for each signature in the message.   There may also be no result line if the message is not signed.   The DKIM result is in square brackets.   The information prior to the result is the signature parameters.
  • Line 5, “ctasd” is the antispam results. The keyword in single quotes is the important part, the antispam result.
  • In Line 6, the Queue ID “1haLqi-0002Mp-2G” identifies the message transaction during the exim-in phase. I have not seen transaction numbers reused in a 60-day period, so this is close to a unique identifier.  Line 6 also provides the incoming ciphersuite (X=value), the sender hostname (H=value) , and the sender IP address with source port number.  The S=value clause is the message size.  The id=value is the original Message ID provided by the sender.
• Smtpd phase:
  • Line 8 indicates that the exim-in Queue ID has been transferred to smtpd processing. The Queue ID for the smtpd phase is different, and does not appear until line 9.
  • The smtpd process identifier (smtpd[9095]) appears on related entries for this message, but can be used for multiple adjacent messages. As a result it is not a unique identifier, even over short time periods.
  • In line 9, the initial Queue ID “1haLql-0002Mh-MA” identifies the message transaction which will be used during the smtpd and exim-out phases.
  • Line 9 also connects the smtpd transaction to its source. The first QueueID  is the current ID, and the R=value identifier is the referring Queue ID.   The referring ID can be an exim-in queue entry or a prior smtpd entry that failed and was requeued.
  • Intended message disposition is determined doing the smtpd phase. Line 10 uses the UTM-standard log entry format, and contains the disposition.
  • Lines 11 and 12 complete the smtp phase, but add no significant information.
  • In this example, the message was not sent to the sandbox. If sandbox processing is required:
    • When the message is sent for scanning, there will be a UTM-standard entry with a SCANNER[number) clause and id=”1004”
    • When the message returns from scanning, there will be another UTM-standard entry with a SANDBOX[number] clause and an id=”value” clause indicating the scan result and final disposition.
    • The QueueID will be the same on both of these entries.
  • Exim-out phase:
    • The exim-out phase is normally just two entries, indicated in this example by lines 13 and 14. Both entries contain the Queue ID, which is unchanged from the smtpd phase, and an exim-out process ID which is only used to process a single message.   The exim-out process ID is only used for a single message but is reused over time.
    • Line 13 includes the Queue ID, followed by the target email address. The P=value clause indicates the source email address.  The X=value clause indicates the outbound ciphersuite.  The R=value and T=value clauses indicate how the target server was selected.  The H=value clause indicates the remote server name or IP, and is immediately followed by the remote server IP and port.   The C=value clause is the response string returned from the target server.   Based on the SMTP standard, the result will begin with a three-digit result code and a space.   After that, the details seem to vary from one server to another.
  • Outbound Error Handling:
    • If a message cannot be delivered, there will not be no exim-out entry, and the message will be requeued. The reprocessing will begin in the smtpd phase, with a new Queue ID.  The R=value clause will contain the QueueID of the smtpd phase that failed.
    • IF the antivirus lookup fails, the format of the antivirus message changes.  I have seen antivirus error messages with text containing “spam acl condition” and “SMTP data timeout”, but I have no way of knowing if this is a complete list of possible errors.   To help locate errors, I parsed the whole file, and then checked for messages that did not have a “ctasd” antivirus message.   I found that ctasd checking was omitted without a log entry if the message originated from UTM, or was omitted with a log entry if antivirus checking was disabled by an exception rule.  The exception entry has a similar format as the greylisting entry, but with different message text.

Log Parsing

Once I understood how the log entries related to each other, and how the different elements in a log message were labelled, I was able to implement code to parse the file into a structured database.  I used four tables:  one each for exim-in, smtpd, and exim-out, plus one for DKIM entries.   Multiple data records are consolidated into a single row for each message process.  Because the message formats have so little consistency, the code to do this is a bit ugly, so it is not posted.   Send me a PM if you want a copy of the code, which is a SQL stored procedure and related table definitions.