Where do the time fields in my structured log messages come from?

Question

I am writing out json structured log messages to stdout with exactly one time field, called origin_timestamp.

I collect the log messages using Fluent Bit with the tail input plugin, which uses the parser docker. The parser is configured with the Time_Key time.

The documentation about Time_Key says:

If the log entry provides a field with a timestamp, this option specify the name of that field.

Since time != origin_timestamp, I would have thought no time fields will be added by Fluent Bit, however the final log messages ending up in Elasticsearch have the following time fields:

• (origin_timestamp within the field log that contains the original log message)
• origin_timestamp
• time
• @timestamp (sometimes even multiple times).

The @timestamp field is probably added by the es output plugin I am using in Fluent Bit, but where the heck is the time field coming from?

Answer 1

I came across the following issue in the Fluent-bit issue tracker, Duplicate @timestamp fields in elasticsearch output, which sounds like it might be related to your issue in question.

I've deep linked to a particular comment from one of the contributors, which outlines two possible solutions depending on whether you are using their Kubernetes Filter plugin, or are ingesting the logs into Elasticsearch directly.

Hope this helps.

Answer 2

The time field being added by the docker json plugin. Docker logging plugin takes logs from your stdout and logs to a file in following format by default:

{"log":"Log line is here\n","stream":"stdout","**time**":"2019-01-01T11:11:11.111111111Z"}

So, you might observe three timestamps in your final log:

1. Added by you (origin_timestamp)
2. Added by docker driver (time)
3. Added by fluent bit plugin (@timestamp)

Ref - https://docs.docker.com/config/containers/logging/json-file/