This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

Reading ESA Message Log

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



This thread was automatically locked due to age.
Parents
  • 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. 

Reply
  • 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. 

Children