Try to Parsing Postfix Log Using Logstash

Elastic Stack Logstash
1

Hi,

I'm currently parsing postfix logs using Logstash, you can check my config file here.

and here is a sample log that I will parse:

Nov  4 08:51:20 mail /postfix-script[XPIDX]: the Postfix mail system is running: PID: XPIDX
Nov  4 08:51:29 mail postfix/postscreen[]: CONNECT from [SOMEONEIPADDRESS]:PORT to [MYSERVERIPADDRESS]:PORT
Nov  4 08:51:29 mail postfix/postscreen[XPIDX]: ALLOWLISTED [SOMEONEIPADDRESS]:PORT
Nov  4 08:51:29 mail postfix/smtpd[XPIDX]: connect from my.server.hostname[MYSERVERIPADDRESS]
Nov  4 08:51:29 mail postfix/smtpd[XPIDX]: NOQUEUE: filter: RCPT from my.server.hostname[MYSERVERIPADDRESS]: <sender@domain.tld>: Sender address triggers FILTER smtp-amavis:[127.0.0.1]:PORT; from=<sender@domain.tld> to=<recipient@domain.tld> proto=ESMTP helo=<my.server.hostname>
Nov  4 08:51:29 mail postfix/smtpd[XPIDX]: 2797FC2D92: client=my.server.hostname[MYSERVERIPADDRESS]
Nov  4 08:51:29 mail postfix/cleanup[XPIDX]: 2797FC2D92: message-id=<SOME.RANDOM.NUMBER.THAT.DEFINE.MESSAGE.ID@my.server.hostname>
Nov  4 08:51:29 mail postfix/cleanup[XPIDX]: 2797FC2D92: warning: header Subject: THIS IS SUBJECT from my.server.hostname[MYSERVERIPADDRESS]; from=<sender@my.server.hostname> to=<recipient@domain.tld> proto=ESMTP helo=<my.server.hostname>
Nov  4 08:51:29 mail postfix/qmgr[XPIDX]: 2797FC2D92: from=<sender@my.server.hostname>, size=1294, nrcpt=1 (queue active)
Nov  4 08:51:29 mail postfix/smtpd[XPIDX]: disconnect from my.server.hostname[MYSERVERIPADDRESS] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Nov  4 08:51:29 mail postfix/dkimmilter/smtpd[10380]: 36BEBC2D93: client=localhost[127.0.0.1]
Nov  4 08:51:29 mail postfix/cleanup[XPIDX]: 36BEBC2D93: message-id=<SOME.RANDOM.NUMBER.THAT.DEFINE.MESSAGE.ID@my.server.hostname>
Nov  4 08:51:29 mail postfix/cleanup[XPIDX]: 36BEBC2D93: warning: header Subject: THIS IS SUBJECT from localhost[127.0.0.1]; from=<sender@my.server.hostname> to=<recipient@domain.tld> proto=ESMTP helo=<localhost>
Nov  4 08:51:29 mail postfix/qmgr[XPIDX]: 36BEBC2D93: from=<sender@my.server.hostname>, size=1787, nrcpt=1 (queue active)
Nov  4 08:51:29 mail postfix/dkimmilter/smtpd[10380]: disconnect from localhost[127.0.0.1] ehlo=1 mail=2 rcpt=2 data=2 noop=1 quit=1 commands=9
Nov  4 08:51:29 mail postfix/smtp[XPIDX]: 2797FC2D92: to=<recipient@domain.tld>, relay=127.0.0.1[127.0.0.1]:PORT, delay=0.12, delays=0.01/0/0/0.1, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10030): 250 2.0.0 Ok: queued as 36BEBC2D93)
Nov  4 08:51:29 mail postfix/qmgr[XPIDX]: 2797FC2D92: removed
Nov  4 08:51:29 mail postfix/amavisd/smtpd[10381]: 58600C2D92: client=localhost[127.0.0.1]
Nov  4 08:51:29 mail postfix/cleanup[XPIDX]: 58600C2D92: message-id=<SOME.RANDOM.NUMBER.THAT.DEFINE.MESSAGE.ID@my.server.hostname>
Nov  4 08:51:29 mail postfix/amavisd/smtpd[10381]: disconnect from localhost[127.0.0.1] ehlo=1 mail=2 rcpt=2 data=2 noop=1 quit=1 commands=9
Nov  4 08:51:29 mail postfix/qmgr[XPIDX]: 58600C2D92: from=<sender@my.server.hostname>, size=2161, nrcpt=1 (queue active)
Nov  4 08:51:29 mail postfix/smtp[XPIDX]: 36BEBC2D93: to=<recipient@domain.tld>, relay=127.0.0.1[127.0.0.1]:10032, delay=0.15, delays=0.05/0/0/0.1, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 58600C2D92)
Nov  4 08:51:29 mail postfix/qmgr[XPIDX]: 36BEBC2D93: removed
Nov  4 08:51:40 mail postfix/smtp[XPIDX]: 58600C2D92: to=<recipient@domain.tld>, relay=relay.hostname.tld[172.104.50.189]:587, delay=12, delays=0.01/0/10/1.2, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as F13E9BBCF8)
Nov  4 08:51:40 mail postfix/qmgr[XPIDX]: 58600C2D92: removed

But now I'm stuck because of a problem. The output from logstash is not what I want.

Here's an example of the output:

 {
    "_index" : "My_Elasticsearch_Index",
    "_type" : "_doc",
    "_id" : "The_Document_1_ID",
    "_score" : 1.0,
    "_source" : {
      "path" : "the/path/to/the/log/filter",
      "subject" : "This is the subject value should like to be",
      "postfix_to" : "recipient@domain.tld",
      "postfix_status" : "sent",
      "timestamp" : "Nov  2 02:30:22",,
      "postfix_from" : "sender@domain.tld",
      "@timestamp" : "2021-11-02T02:30:22.656Z",
      "program" : "postfix/smtp",
      "message" : "TheQueueID: to=<recipient@domain.tld>, relay=The_Relay_Hostname[The_Relay_IP]:PORT, delay=0.15, delays=0.01/0.03/0/0.1, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[The_MTA_IP]:PORT): 250 2.0.0 Ok: queued as TheNextQueueID)",
      "postfix_queueid" : "TheQueueID",
      "postfix_message-id" : null,
      "tags" : [
        "_grok_postfix_success"
      ]
    }
  },
  {
    "_index" : "My_Elasticsearch_Index",
    "_type" : "_doc",
    "_id" : "The_Document_2_ID",
    "_score" : 1.0,
    "_source" : {
      "path" : "the/path/to/the/log/filter",
      "subject" : null,
      "postfix_to" : "recipient@domain.tld",
      "postfix_status" : "sent",
      "timestamp" : "Nov  2 02:30:22",,
      "postfix_from" : "sender@domain.tld",
      "@timestamp" : "2021-11-02T02:30:22.656Z",
      "program" : "postfix/smtp",
      "message" : "TheQueueID: to=<recipient@domain.tld>, relay=The_Relay_Hostname[The_Relay_IP]:PORT, delay=0.15, delays=0.01/0.03/0/0.1, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[The_MTA_IP]:PORT): 250 2.0.0 Ok: queued as TheNextQueueID)",
      "postfix_queueid" : "TheQueueID",
      "postfix_message-id" : "Some_Random_Numbers_and_Word_that_define_the_message_ID@domain.tld",,
      "tags" : [
        "_grok_postfix_success"
      ]
    }
  },

I'm currently parsing postfix logs using Logstash, you can check my config file here.

and here is a sample log that I will parse:

Nov  4 08:51:20 mail /postfix-script[XPIDX]: the Postfix mail system is running: PID: XPIDX
Nov  4 08:51:29 mail postfix/postscreen[]: CONNECT from [SOMEONEIPADDRESS]:PORT to [MYSERVERIPADDRESS]:PORT
Nov  4 08:51:29 mail postfix/postscreen[XPIDX]: ALLOWLISTED [SOMEONEIPADDRESS]:PORT
Nov  4 08:51:29 mail postfix/smtpd[XPIDX]: connect from my.server.hostname[MYSERVERIPADDRESS]
Nov  4 08:51:29 mail postfix/smtpd[XPIDX]: NOQUEUE: filter: RCPT from my.server.hostname[MYSERVERIPADDRESS]: <sender@domain.tld>: Sender address triggers FILTER smtp-amavis:[127.0.0.1]:PORT; from=<sender@domain.tld> to=<recipient@domain.tld> proto=ESMTP helo=<my.server.hostname>
Nov  4 08:51:29 mail postfix/smtpd[XPIDX]: 2797FC2D92: client=my.server.hostname[MYSERVERIPADDRESS]
Nov  4 08:51:29 mail postfix/cleanup[XPIDX]: 2797FC2D92: message-id=<SOME.RANDOM.NUMBER.THAT.DEFINE.MESSAGE.ID@my.server.hostname>
Nov  4 08:51:29 mail postfix/cleanup[XPIDX]: 2797FC2D92: warning: header Subject: THIS IS SUBJECT from my.server.hostname[MYSERVERIPADDRESS]; from=<sender@my.server.hostname> to=<recipient@domain.tld> proto=ESMTP helo=<my.server.hostname>
Nov  4 08:51:29 mail postfix/qmgr[XPIDX]: 2797FC2D92: from=<sender@my.server.hostname>, size=1294, nrcpt=1 (queue active)
Nov  4 08:51:29 mail postfix/smtpd[XPIDX]: disconnect from my.server.hostname[MYSERVERIPADDRESS] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Nov  4 08:51:29 mail postfix/dkimmilter/smtpd[10380]: 36BEBC2D93: client=localhost[127.0.0.1]
Nov  4 08:51:29 mail postfix/cleanup[XPIDX]: 36BEBC2D93: message-id=<SOME.RANDOM.NUMBER.THAT.DEFINE.MESSAGE.ID@my.server.hostname>
Nov  4 08:51:29 mail postfix/cleanup[XPIDX]: 36BEBC2D93: warning: header Subject: THIS IS SUBJECT from localhost[127.0.0.1]; from=<sender@my.server.hostname> to=<recipient@domain.tld> proto=ESMTP helo=<localhost>
Nov  4 08:51:29 mail postfix/qmgr[XPIDX]: 36BEBC2D93: from=<sender@my.server.hostname>, size=1787, nrcpt=1 (queue active)
Nov  4 08:51:29 mail postfix/dkimmilter/smtpd[10380]: disconnect from localhost[127.0.0.1] ehlo=1 mail=2 rcpt=2 data=2 noop=1 quit=1 commands=9
Nov  4 08:51:29 mail postfix/smtp[XPIDX]: 2797FC2D92: to=<recipient@domain.tld>, relay=127.0.0.1[127.0.0.1]:PORT, delay=0.12, delays=0.01/0/0/0.1, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10030): 250 2.0.0 Ok: queued as 36BEBC2D93)
Nov  4 08:51:29 mail postfix/qmgr[XPIDX]: 2797FC2D92: removed
Nov  4 08:51:29 mail postfix/amavisd/smtpd[10381]: 58600C2D92: client=localhost[127.0.0.1]
Nov  4 08:51:29 mail postfix/cleanup[XPIDX]: 58600C2D92: message-id=<SOME.RANDOM.NUMBER.THAT.DEFINE.MESSAGE.ID@my.server.hostname>
Nov  4 08:51:29 mail postfix/amavisd/smtpd[10381]: disconnect from localhost[127.0.0.1] ehlo=1 mail=2 rcpt=2 data=2 noop=1 quit=1 commands=9
Nov  4 08:51:29 mail postfix/qmgr[XPIDX]: 58600C2D92: from=<sender@my.server.hostname>, size=2161, nrcpt=1 (queue active)
Nov  4 08:51:29 mail postfix/smtp[XPIDX]: 36BEBC2D93: to=<recipient@domain.tld>, relay=127.0.0.1[127.0.0.1]:10032, delay=0.15, delays=0.05/0/0/0.1, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 58600C2D92)
Nov  4 08:51:29 mail postfix/qmgr[XPIDX]: 36BEBC2D93: removed
Nov  4 08:51:40 mail postfix/smtp[XPIDX]: 58600C2D92: to=<recipient@domain.tld>, relay=relay.hostname.tld[172.104.50.189]:587, delay=12, delays=0.01/0/10/1.2, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as F13E9BBCF8)
Nov  4 08:51:40 mail postfix/qmgr[XPIDX]: 58600C2D92: removed

But now I'm stuck because of a problem. The output from logstash is not what I want.

Here's an example of the output:

  {
    "_index" : "My_Elasticsearch_Index",
    "_type" : "_doc",
    "_id" : "The_Document_1_ID",
    "_score" : 1.0,
    "_source" : {
      "path" : "the/path/to/the/log/filter",
      "subject" : "This is the subject value should like to be",
      "postfix_to" : "recipient@domain.tld",
      "postfix_status" : "sent",
      "timestamp" : "Nov  2 02:30:22",,
      "postfix_from" : "sender@domain.tld",
      "@timestamp" : "2021-11-02T02:30:22.656Z",
      "program" : "postfix/smtp",
      "message" : "TheQueueID: to=<recipient@domain.tld>, relay=The_Relay_Hostname[The_Relay_IP]:PORT, delay=0.15, delays=0.01/0.03/0/0.1, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[The_MTA_IP]:PORT): 250 2.0.0 Ok: queued as TheNextQueueID)",
      "postfix_queueid" : "TheQueueID",
      "postfix_message-id" : null,
      "tags" : [
        "_grok_postfix_success"
      ]
    }
  },
  {
    "_index" : "My_Elasticsearch_Index",
    "_type" : "_doc",
    "_id" : "The_Document_2_ID",
    "_score" : 1.0,
    "_source" : {
      "path" : "the/path/to/the/log/filter",
      "subject" : null,
      "postfix_to" : "recipient@domain.tld",
      "postfix_status" : "sent",
      "timestamp" : "Nov  2 02:30:22",,
      "postfix_from" : "sender@domain.tld",
      "@timestamp" : "2021-11-02T02:30:22.656Z",
      "program" : "postfix/smtp",
      "message" : "TheQueueID: to=<recipient@domain.tld>, relay=The_Relay_Hostname[The_Relay_IP]:PORT, delay=0.15, delays=0.01/0.03/0/0.1, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[The_MTA_IP]:PORT): 250 2.0.0 Ok: queued as TheNextQueueID)",
      "postfix_queueid" : "TheQueueID",
      "postfix_message-id" : "Some_Random_Numbers_and_Word_that_define_the_message_ID@domain.tld",,
      "tags" : [
        "_grok_postfix_success"
      ]
    }
  },

The first output has a subject but no message id, the second output has a message id but no subject. So subject and message id cannot be in the same document.

What I want is the subject and message id in the same document.

Is there any way to solve my problem? Please for the help.

2

You could do something like this...

    mutate { gsub => [ "message", "\s+", " " ] }
    dissect { mapping => { "message" => "%{[@metadata][ts]} %{+[@metadata][ts]} %{+[@metadata][ts]} %{} %{program}[%{}]: %{[@metadata][restOfLine]}" } }
    date { match => [ "[@metadata][ts]", "MMM dd HH:mm:ss" ] }
    grok {
        break_on_match => false
        match => {
            "[@metadata][restOfLine]" => [
                "^(?<taskId>[0-9A-Z]{10}):",
                "Subject: (?<subject>[^;]*);",
                " from=(?<postfixFrom>[^,]*),",
                " message-id=%{GREEDYDATA:message_id}",
                " status=%{WORD:status}",
                " to=(?<postfixTo>[^,]*),"
            ]
        }
    }
    if [taskId] {
        aggregate {
            task_id => "%{taskId}"
            code => '
                map["@timestamp"] ||= event.get("@timestamp")
                map["message-id"] ||= event.get("message_id")
                map["postfixTo"] ||= event.get("postfixTo")
                map["postfixFrom"] ||= event.get("postfixFrom")
                map["subject"] ||= event.get("subject")
            '
            push_map_as_event_on_timeout => true
            timeout_task_id_field => "taskId"
            timeout => 10
        }
    }

This is just an outline of an approach, it omits quite a few fields.

2 Likes
3

Hi Badger,

Thank you for your answer,

where exactly should I put the filter?

After the 31 Filter?

4

It is not a drop-in addition to your existing configuration, not is it a complete configuration by itself. You may not need anything from it except some ideas from the aggregate, and that will need to be updated to adjust field names.

As I said, it is just an outline of an approach.

5

Hi Badger,

Can you explain to me what this symbol means in the aggregation filter code section:

||=
=
==

or is there a reference explaining my question that you can share with me?

thanks.

6

That is a conditional assignment. I'm using it to say

If map["postfixTo"] is nil, then set it to the value of event.get("postfixTo") (which may itself be nil). Basically, it sets the map value to the content of the field from the first event that contains it (that's usually what I want for something like @timestamp).

There is more to it. See here for one explanation. You should be able to Google many more pages once you have the wording from that one.

7

Thank you for the help @Badger

its help me so much.

8

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.