Reading ESA Message Log

Question

Hi All, 
 I am having some issues parsing the logs from the appliance i've got the majority off them sorted, its just the Message log I am having issues with. 
 Can anyone point me in the direction of a document or let me know what the fields are in log entries? 
 http://esa.sophos.com/docs/esa/webhelp/index.html#sea/references/SEASyslog.html 
 shows examples, but unlike the equivalent one for the Web appliance, ( http://wsa.sophos.com/docs/wsa/webhelp/index.html#swa/concepts/InterpretingLogFiles.html) 
 it doesnt give you the key to the logs 
 I am trying to get them normalised so i can pass them into our SIEM, I can make educated guesses, but 
 "p=0.151 fur=150.70.236.149 r=155.231.210.253 tm=0.23 a=d/eom" means little to me

Red_Warrior · Accepted Answer

I guess I should really create a KB for that, good question.

In short there are 2 logs, the first is the MTA (postfix) log and the second is called the milter log (aka policy results)

When email is sent or received it flows through the appliance..

like so

postfix accepts message into the front end mail queue

the queue process in turn delivers the message to the milter (127.0.0.1) 10025

the milter generates the maillog / policy hits

the message is delivered to the back end mail queue

back end queue to downstream relay.

When you search in the UI under mail logs, the appliance gatheres all of these parts and stuffs it into the UI.. In the actual logs there is no separation.

For example.

Postfix accepts message into the Front end queue, the first thing it does is assigns it a message ID:

2017-09-19 20:16:53 sea postfix/smtpd[21298]: 983E535C74_9C1DDA5F: client=unknown[192.168.5.8]
2017-09-19 20:16:53 sea postfix/cleanup[21302]: 983E535C74_9C1DDA5F: message-id=<Odi01t29zW-FrYtzM_LUvKgBqiu13gezcxOO45G6eeg.EDqpQPe0B4DBGbfP-Uynf9adw653dqYeLB5Rjs7WTCg@toughhstjn.com>
2017-09-19 20:16:53 sea postfix/qmgr[2686]: 983E535C74_9C1DDA5F: from=<name@devcot.local>, size=13247, nrcpt=1 (queue active)
2017-09-19 20:18:34 sea postfix/smtp[21305]: 983E535C74_9C1DDA5F: to=<name@devcot.local>, relay=127.0.0.1[127.0.0.1]:10025, delay=101, delays=0.09/0.07/0.19/101, dsn=2.0.0, status=sent (250 OK, sent 59C1DDA5_2428_1_1 988DA38A83_9C1DE0AB)
2017-09-19 20:18:34 sea postfix/qmgr[2686]: 983E535C74_9C1DDA5F: removed

the above says, message X arrived from the client 192.168.5.8 to: from: the relay is the loopback device. the removed part sais that the message cleared the milter process.

2017-09-19 20:18:34 sea postfix/backend/smtpd[22021]: 988DA38A83_9C1DE0AB: client=localhost.localdomain[127.0.0.1]

then the milter spits up the message to the back end mail queue, the id is changed from F as above to B .. indicating the frontend and backend mail queues.

2017-09-19 20:18:34 sea postfix/backend/cleanup[22025]: 988DA38A83_9C1DE0AB: message-id=<Odi01t29zW-FrYtzM_LUvKgBqiu13gezcxOO45G6eeg.EDqpQPe0B4DBGbfP-Uynf9adw653dqYeLB5Rjs7WTCg@toughhstjn.com>
2017-09-19 20:18:34 sea postfix/backend/qmgr[2857]: 988DA38A83_9C1DE0AB: from=<name@devcot.local>, size=16205, nrcpt=1 (queue active)
2017-09-19 20:18:35 sea postfix/backend/smtp[22029]: 988DA38A83_9C1DE0AB: to=<name@devcot.local>, relay=192.168.5.8[192.168.5.8]:25, delay=0.7, delays=0.23/0.1/0.31/0.06, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C20A3E03D5)

this is the delivery receipt and SMTP code (250 2.0.0 aka delivered)

2017-09-19 20:18:35 sea postfix/backend/qmgr[2857]: 988DA38A83_9C1DE0AB: removed

message cleared the back end mail queue

Thats the mail log, every message will have at least 1 part.. if the milter deletes a message for spam, there would be a NO_FORWARD message instead of REMOVED

Maillog

This is the log output of policy based on when postfix delivers the message to the milter. For the most part, most of this log will mean absolutely nothing to you. I have highlighted the good bits.

2017-09-20T03:19:14 q=59C1DE2D_2430_3_3 f=<name@devcot.local> t=<name@devcot.local> Rule=Deliver ME! type=rule b=ok DKIM-VERIFY=none action=deliver h=SXL_URI h=IMGSPAM_BODY h=DATE_IN_PAST_96_XX h=HTML_70_90 h=BODYTEXTH_SIZE_10000_LESS h=BODYTEXTH_SIZE_3000_MORE h=BODYTEXTP_SIZE_3000_LESS h=BODY_SIZE_6000_6999 h=BODY_SIZE_7000_LESS h=DATE_TZ_NA h=LINK_TO_IMAGE h=NO_URI_HTTPS h=URI_WITH_PATH_ONLY h=__ANY_URI h=__BAT_BOUNDARY h=__CP_URI_IN_BODY h=__CT h=__CTYPE_HAS_BOUNDARY h=__CTYPE_MULTIPART h=__CTYPE_MULTIPART_ALT h=__HAS_FROM h=__HAS_HTML h=__HAS_MSGID h=__HTML_AHREF_TAG h=__HTML_TAG_DIV h=__HTML_TAG_IMG_X2 h=__HTTP_IMAGE_TAG h=__IMGSPAM_BODY h=__MIME_HTML h=__MIME_TEXT_H h=__MIME_TEXT_H1 h=__MIME_TEXT_H2 h=__MIME_TEXT_P h=__MIME_TEXT_P1 h=__MIME_TEXT_P2 h=__MIME_VERSION h=__MULTIPLE_URI_HTML h=__MULTIPLE_URI_TEXT h=__RATWARE_SIGNATURE_3 h=__RATWARE_SIGNATURE_3_N1 h=__SANE_MSGID h=__SUBJ_ALPHA_END h=__TAG_EXISTS_HTML h=__TO_MALFORMED_2 h=__TO_NO_NAME h=__URI_IN_BODY h=__URI_NOT_IMG h=__URI_NO_MAILTO h=__URI_NO_WWW h=__URI_NS h=__URI_WITH_PATH inbound p=0.803 S=?q?Regrow_thicker_and_fuller_hair fur= r=192.168.5.8 tm=4.22 a=a/eom

q = message id from the front end queue

f = From

t = to

Rule = the highest prioirty rule hit with an action of either quarantine, discard or deliver

DKIM-VERIFY = results of dkim hashing

Action = Deliver (this could be quarantine or discard)

p = Spam score .. (0.803 = 80.3% spam)

s = subject

fur = first untrusted relay IP address (usually the envelope sender unless you have trusted relays configured)

tm = time the message took to scan (i keep debug on so it took 4.2 seconds)

Everything else in this log will translate into absolutely nothing, so don't even bother trying to "decode" it because In short .. it is the collection of spam / labs rules that were triggered, the exact formula is not meant to be analysed and changes all the time.