Anton Dollmaier

Anton Dollmaier


Fixing timestamps: Rsyslog and Logstash

20 Apr 2020 »

In our hosting infrastructure, we’ve got a “grown environment”. Newer systems are installed using the UTC timezone in the central definition, older systems sometimes still require a local timezone.

For operating them locally, the different timezones do not really cause effects.

But as we use the ELK stack to store, aggregate and view logs of all our systems, different timezones have negative effects. While logs from hosts with UTC timezone are easy to correlate, the non-UTC-nodes sent the timestamps in their local timezone, which means for Europe/Berlin either one or even two hours offset. This offset makes comparison of events hard to almost not usable.

All this is caused by rsyslog sending timestamps without timezone-awareness:

Apr 20 00:00:55 terra postfix/smtpd[5005]: connect from localhost[127.0.0.1]

To overcome this issue, either Logstash is told to convert each timestamp received from a non-UTC node. This is tidious and get’s complicated fast. Or to accept timestamps in a format that already includes the timezone definition.

According to the Syslog input plugin, each received event must contain a timestamp:

The grok pattern must provide a timestamp field. If the timestamp field is omitted, or is unable to be parsed as RFC3164 style or ISO8601, a _dateparsefailure tag will be added.

So, obviously, we need to tell rsyslog to submit all events with a timestamp including the local timezone: RFC3164 and ISO8601 have both been invented exactly for such purposes.

Rsyslog allows to specify the format of an event using templates. From the alternatives that exist, RSYSLOG_ForwardFormat is the one to choose:

RSYSLOG_ForwardFormat - a new high-precision forwarding format very similar to the traditional one, but with high-precision timestamps and timezone information. Recommended to be used when sending messages to rsyslog 3.12.5 or above.

template(name="RSYSLOG_ForwardFormat" type="string"
    string="<%PRI%>%TIMESTAMP:::date-rfc3339% %HOSTNAME% %syslogtag:1:32%%msg:::sp-if-no-1st-sp%%msg%")

Now the single pieces must be put together.

On the receiving side, Logstash is configured simply to accept syslog input. The plugin does, matching the documentation, already handle the different timestamps.

input {
    syslog {
        port => 1514
        type => syslog
        id => "input_syslog"
    }
}

To configure rsyslog on our servers, we rely on the puppet module saz-rsyslog.

This is now configured to use the proper RSYSLOG_ForwardFormat template:

class base::syslog (
  Boolean $log_local = true,
  Boolean $purge_rsyslog_d = true,
  Boolean $preserve_fqdn = true,
  Integer $system_log_rate_limit_interval = 0,
  Integer $system_log_rate_limit_burst = 0,
) {
  $sysloghosts = [
    {
      host   => 'elkhost',
      port   => 1514,
      format => 'RSYSLOG_ForwardFormat',
    },
  ]

  class{ 'rsyslog':
    purge_rsyslog_d                => $purge_rsyslog_d,
    preserve_fqdn                  => $preserve_fqdn,
    system_log_rate_limit_burst    => $system_log_rate_limit_burst,
    system_log_rate_limit_interval => $system_log_rate_limit_interval,
  }
  ->class { 'rsyslog::client':
    log_local      => $log_local,
    log_auth_local => $log_local,
    remote_servers => $sysloghosts,
  }
}

Rsyslog now properly sends out timestamps with TZ-awareness:

<22>2020-04-20T21:20:49.815252+00:00 v5617 postfix/smtpd[29702]: connect from localhost[127.0.0.1]
<22>2020-04-20T23:21:24.612246+02:00 server postfix/smtpd[12624]: connect from localhost[127.0.0.1]

These events are properly parsed and converted to UTC by Logstash, and stored in ElasticSearch.

Goal achieved: Kibana now has the ability to properly display timestamps, regardless of the timezone on the source servers.

© Anton Dollmaier