Emails from logstash are sometimes delayed

Elastic Stack Logstash
1

Hi,

I'm a new user of ELK. I have set up logstash to send out emails upon some syslog messages received from remote node. However, the emails sent from logstash are sometimes delayed for a long time (minutes to hours). I don't think the problem is with the mail server as emails not from logstash arrive in the receiver's mail box immediately, and the emails are delayed even if they are sent to local root user root@fqdn_of_elk_server. Can you think of any possible reasons why the emails from logstash are delayed, or suggest any possible way to investigate the reason?

if "mce" in [tags] and "throttled" not in [tags] {
email {
to => "root@fqdn_of_elk_server"
from => "logstash@fqdn_of_elk_server"
subject => "Logstash: MCE Events Detected on %{syslog_hostname}"
body => "Time: %{syslog_timestamp}\nHost: %{syslog_hostname}\nMessage: %{message}"
}
}

Thanks a lot in advance.

2

It's hard to believe that the messages would be delayed inside Logstash. What's in the mail server logs?

3

Many thanks for your swift reply. Here is the mail server log. I received the mail in the mail box of root user at 20:19:44. However the content of the mail shows the event happened at 18:10:28.

Aug 20 20:19:44 kibana postfix/smtpd[19280]: connect from localhost[127.0.0.1]
Aug 20 20:19:44 kibana postfix/smtpd[19280]: 97AEC240433: client=localhost[127.0.0.1]
Aug 20 20:19:44 kibana postfix/cleanup[19283]: 97AEC240433: message-id=<55d5a9c091438_2a6811247659d@fqdn_of_elk_server.mail>
Aug 20 20:19:44 kibana postfix/qmgr[15959]: 97AEC240433: from=<logstash@fqdn_of_elk_server>, size=593, nrcpt=1 (queue active)
Aug 20 20:19:44 kibana postfix/smtpd[19280]: disconnect from localhost[127.0.0.1]
Aug 20 20:19:44 kibana postfix/local[19284]: 97AEC240433: to=<root@fqdn_of_elk_server>, relay=local, delay=0.07, delays=0.05/0/0/0.01, dsn=2.0.0, status=sent (delivered to mailbox)
Aug 20 20:19:44 kibana postfix/qmgr[15959]: 97AEC240433: removed

4

Here is the content of the email received in local root user's mail box:

Time: 2015-08-20T18:10:28+10:00
Host: r443
Message: [Hardware Error]: Machine check events logged

5

Okay, but are you collecting logs in real time? Was the 18:10:28 email really processed by Logstash at that time and not at 20:19:44?

6

Yes I'm collecting logs in real time because they are displayed in Kibana in real time. Can you please let me know how I can find out what time the email was processed by Logstash? If it was processed at 20:19:44 instead of 18:10:28, what are the possible reasons?

Much appreciated.

7

Can you please let me know how I can find out what time the email was processed by Logstash?

If the @timestamp filter isn't set Logstash will populate it with the current time. So, unless that field is set by an upstream Logstash instance you can save that value into a separate field or simply disable any date filter you have. Alternatively, use a ruby filter to create a new field and populate it with the current time.

If it was processed at 20:19:44 instead of 18:10:28, what are the possible reasons?

Depends on what your pipeline looks like. Either Logstash was behind with the input processing or the pipeline was clogged because the outputs were stalled.

8

Thanks a lot. I will disable all the date filters and confirm the timestamp value matches the time of the event or not.

9

Hi,

I have disabled the date filters. The @timestamp shown in Kibana for the events with email delayed still matches the time of the events, so I think the events arrived and were processed by Logstash immediately after it happened. However, for some reason the triggered email was blocked.