This is a follow-up to my earlier post, which explains my general approach for converting text logs into a SQL database layout.
The SMTP log highlights the differences between the type of logging needed for software development and the type of logging needed for security operations. The current SMTP log has all of the chatter generated by the SMTP engine, including startup and shutdown messages, scheduled task start and stop, incoming connection start and stop, incoming message processing, and outgoing message processing. There is woefully little consistency in these different types of messages, which makes analysis even harder. UTM adds one log entry for each processed message, using its standard format based on keyword=”value” pairs. Since its standard format is different from the other data, the UTM log entry is a mixed blessing.
In my experience, the SMTP engine runs smoothly, so I do not want to know about its every move. I do want to efficiently evaluate my incoming message log to identify spammers that are evading my defenses, while also auditing for desired messages that are getting blocked. I have found that the UTM Mail Manager is a poor tool for doing this type of analysis, and I finally decided that it was time to attempt to parse the SMTP logs. Both Inbound and Outbound entries are identified by a Queue ID, but a different ID applies to each phase. One log entry has both IDs so that inbound and outbound processes can be linked to each other.
Below is a slightly sanitized log excerpt from my UTM. An inbound SMTP connection sends two messages, both of which are forwarded by UTM to the target mail server. In the action column, I indicate what information can be extracted from each record, and which records were ignored because they add no useful information. I could have stripped it down to show only one of the two messages, but I wanted to be clear that log parsing needs to allow for the possibility that related messages may not be adjacent.
After a lot of code, I have an import script which captures all of the information in the UTM record, plus DKIM status, AV status, inbound source, inbound transport protocol and ciphersuite, outbound target, outbound transport protocol and ciphersuite, and delivery status returned from the receiving server. Raw code is available on request, but for purposes of this forum, I thought it might be most instructive to show a sequence of messages and how I used them. That information appears below. It is not as readable as I would like because I could not make my Excel table paste into the forum and still be readable. Consequently, the action statement appears just above the message part of each log entry.
Ignore
exim-in[19237]: 2018-06-05 00:03:20 SMTP connection from [IN-IP1.IP2.IP3-IP4]:51469 (TCP/IP connection count = 1)
Ignore
exim-in[20556]: 2018-06-05 00:03:20 H=mail.example.com [IN-IP1.IP2.IP3-IP4]:51469 Warning: example.com profile excludes greylisting: Skipping greylisting for this message
Ignore
exim-in[20556]: 2018-06-05 00:03:20 H=mail.example.com [IN-IP1.IP2.IP3-IP4]:51469 Warning: example.com profile excludes SANDBOX scan
Ignore, has no QueueID for matching to other records
exim-in[20556]: 2018-06-05 00:03:20 [IN-IP1.IP2.IP3-IP4] F=<update+kwbkqg5n@facebookmail.com> R=<myuser@example.com> Accepted: from relay
Extract InQueueID, DKIM info
exim-in[20556]: 2018-06-05 00:03:20 1fQ3Bo-0005LY-0w DKIM: d=facebookmail.com s=s1024-2013-q3 c=relaxed/simple a=rsa-sha256 t=1528171397 [verification failed - signature did not verify (headers probably modified in transit)]
Extract InQueueID, ClamAV info
exim-in[20556]: 2018-06-05 00:03:20 1fQ3Bo-0005LY-0w ctasd reports 'Unknown' RefID:str=0001.0A020208.5B160B88.0030:SCFMA12945349,ss=1,re=-4.000,recu=0.000,reip=0.000,cl=1,cld=1,fgs=0
Extract InQueueID, FromUser, SourceHost (H=), SourceIP, Transport (P=), Cipher (X=), Message ID (id=)
exim-in[20556]: 2018-06-05 00:03:20 1fQ3Bo-0005LY-0w <= update+kwbkqg5n@facebookmail.com H=mail.example.com [IN-IP1.IP2.IP3-IP4]:51469 P=esmtps X=TLSv1.2:DHE-RSA-AES256-GCM-SHA384:256 S=20301 id=2ca0203b1829f366bca3c4c996649a62@async
Ignore
exim-in[20556]: 2018-06-05 00:03:20 SMTP connection from mail.example.com [IN-IP1.IP2.IP3-IP4]:51469 closed by QUIT
Ignore
smtpd[19225]: QMGR[19225]: 1fQ3Bo-0005LY-0w moved to work queue
Ignore
exim-in[19237]: 2018-06-05 00:03:24 SMTP connection from [IN-IP1.IP2.IP3-IP4]:51473 (TCP/IP connection count = 1)
Ignore
exim-in[20565]: 2018-06-05 00:03:24 H=mail.example.com [IN-IP1.IP2.IP3-IP4]:51473 Warning: example.com profile excludes greylisting: Skipping greylisting for this message
Ignore
exim-in[20565]: 2018-06-05 00:03:24 H=mail.example.com [IN-IP1.IP2.IP3-IP4]:51473 Warning: example.com profile excludes SANDBOX scan
Ignore
exim-in[20565]: 2018-06-05 00:03:24 [IN-IP1.IP2.IP3-IP4] F=<notification+kwbkqg5n@facebookmail.com> R=<myuser@example.com> Accepted: from relay
Extract
InQueueID, DKIM info exim-in[20565]: 2018-06-05 00:03:24 1fQ3Bs-0005Lh-2S DKIM: d=facebookmail.com s=s1024-2013-q3 c=relaxed/simple a=rsa-sha256 t=1528171402 [verification failed - signature did not verify (headers probably modified in transit)]
Extract InQueueID, ClamAV info
exim-in[20565]: 2018-06-05 00:03:24 1fQ3Bs-0005Lh-2S ctasd reports 'Unknown' RefID:str=0001.0A02020D.5B160B8C.004E:SCFMA12945349,ss=1,re=-4.000,recu=0.000,reip=0.000,cl=1,cld=1,fgs=0
Extract InQueueID, FromUser, SourceHost (H=), SourceIP, InTransport (P=), InCipher (X=), Message ID (id=)
exim-in[20565]: 2018-06-05 00:03:24 1fQ3Bs-0005Lh-2S <= notification+kwbkqg5n@facebookmail.com H=mail.example.com [IN-IP1.IP2.IP3-IP4]:51473 P=esmtps X=TLSv1.2:DHE-RSA-AES256-GCM-SHA384:256 S=27542 id=139ec664fb27d1d54762a20f938725b1@async
Ignore
exim-in[20565]: 2018-06-05 00:03:24 SMTP connection from mail.example.com [IN-IP1.IP2.IP3-IP4]:51473 closed by QUIT
Ignore
smtpd[19225]: QMGR[19225]: 1fQ3Bs-0005Lh-2S moved to work queue
Extract OutQueueID, FromUser, InQueueID (R=), maybe size (S=)
smtpd[20586]: SCANNER[20586]: 1fQ3By-0005M2-CK <= update+kwbkqg5n@facebookmail.com R=1fQ3Bo-0005LY-0w P=INPUT S=17104
Extract all fields. Note that QueueID is the OutQueueID, not the InQueueID.
smtpd[20586]: SCANNER[20586]: id="1000" severity="info" sys="SecureMail" sub="smtp" name="email passed" srcip="IN-IP1.IP2.IP3-IP4" user@example.com" subject="YOUR FRIEND commented on a link that you're tagged in" queueid="1fQ3By-0005M2-CK" size="17104"from="update+kwbkqg5n@facebookmail.com" to="my
Ignore
smtpd[20586]: SCANNER[20586]: 1fQ3Bo-0005LY-0w => work R=SCANNER T=SCANNER
Ignore
smtpd[20586]: SCANNER[20586]: 1fQ3Bo-0005LY-0w Completed
Extract OutQueueID, FromUser, InQueueID (R=), maybe size (S=)
smtpd[20586]: SCANNER[20586]: 1fQ3By-0005M2-Fo <= notification+kwbkqg5n@facebookmail.com R=1fQ3Bs-0005Lh-2S P=INPUT S=24505
Extract all fields. Note that QueueID is the OutQueueID, not the InQueueID.
smtpd[20586]: SCANNER[20586]: id="1000" severity="info" sys="SecureMail" sub="smtp" name="email passed" srcip="IN-IP1.IP2.IP3-IP4" from="notification+kwbkqg5n@facebookmail.com" to="myuser@example.com" subject="YOUR FRIEND confirmed your Facebook friend request" queueid="1fQ3By-0005M2-Fo" size="24505"
Ignore
smtpd[20586]: SCANNER[20586]: 1fQ3Bs-0005Lh-2S => work R=SCANNER T=SCANNER
Ignore
smtpd[20586]: SCANNER[20586]: 1fQ3Bs-0005Lh-2S Completed
Extract OutQueueID, ToUser, FromUser (P=), Routing (R=), Transport (T=), DestinationHost (H=), DestinationIP :Port (space delimited), OutCipher (X=), DeliveryResult (C=). This result includes the MessageID, but that is not assured as it depends on the other server.
exim-out[20589]: 2018-06-05 00:03:30 1fQ3By-0005M2-CK => myuser@example.com P=<update+kwbkqg5n@facebookmail.com> R=static_route_hostlist T=static_smtp H=OUT-IP1-IP2.IP3.IP4 [OUT-IP1-IP2.IP3.IP4]:25 X=TLSv1:AES256-SHA:256 C="250 2.6.0 <2ca0203b1829f366bca3c4c996649a62@async> Queued mail for delivery"
Ignore
exim-out[20589]: 2018-06-05 00:03:30 1fQ3By-0005M2-CK Completed
Extract OutQueueID, ToUser, FromUser (P=), Routing (R=), Transport (T=), DestinationHost (H=), DestinationIP :Port (space delimited), OutCipher (X=), DeliveryResult (C=). This result includes the MessageID, but that is not assured as it depends on the other server.
exim-out[20593]: 2018-06-05 00:03:30 1fQ3By-0005M2-Fo => myuser@example.com P=<notification+kwbkqg5n@facebookmail.com> R=static_route_hostlist T=static_smtp H=OUT-IP1-IP2.IP3.IP 4 [OUT-IP1-IP2.IP3.IP4]:25 X=TLSv1:AES256-SHA:256 C="250 2.6.0 <139ec664fb27d1d54762a20f938725b1@async> Queued mail for delivery"
Ignore
exim-out[20593]: 2018-06-05 00:03:30 1fQ3By-0005M2-Fo Completed
Ignore
smtpd[20586]: SCANNER[20586]: Nothing to do, exiting.
This thread was automatically locked due to age.