Reading ESA Message Log

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. 

cheers, more than i needed, but this will get the right stuff into our SIEM :)

hi sir your comment here really helped me. i wanted to know what is r= and b= here.

Glad to help.

Not sure about the b= .. I believe its a labs internal check that has something to do with AV results.

the r= is the ip of the last mta that relayed the message. In most cases it with also be the same as the FUR unless the ip is whitelisted.

test

test