Timestamp processor truncates timestamp and fails to parse

6NMgfDwZ3 · March 14, 2021, 2:25pm

Hello,

I have log messages with a mytimesmap field. This field contains microseconds precision RFC3339/ISO8601 (UTC) style timestamp like 2021-03-14T13:25:49.008906Z.

So I'd like to overwrite @timestamp field with mytimestamp fields content with the timestamp processor.

Here is the relevant Filebeat config:

processors:
  - decode_json_fields:
     fields: ["message"]
     process_array: true
     target: ""
     add_error_key: true
     overwrite_keys: true
  - timestamp:
      field: mytimestamp
      layouts:
        - '2020-01-02T12:34:56.999999Z'
      test:
        - '2020-01-02T12:34:56.123456Z'

if I start the Filebeat with the config above I get an error message:

Exiting: error initializing processors: failed to parse test timestamp: failed parsing time field mytimestamp='2020-01-02T12:34:56.123456Z'

So Filebeat failed to start because timestamp processor can't validate the timestamp but there is no explanation why not.

As per Filebeat documentation (Timestamp | Filebeat Reference [7.11] | Elastic) the test part of the timestamp processor config is not mandatory so I commented it out.

After that Filebeat seems to have worked fine except it did not overwrite @timestamp field.

So I've set logging.level to debug and these error messages appears in the log for every log message

2021-03-14T14:25:49.979+0100    DEBUG   [processor.timestamp]   timestamp/timestamp.go:173      Failure parsing time field.     {"error": "failed parsing time field mytimestamp='2021-03-14T13:25:49.008906Z'", "errorCauses": [{"error": "failed using layout [2020-01-02T12:34:56.999999Z] cannot parse [-03-14T13:25:49.008906Z] as [0-]"}]}
2021-03-14T14:25:49.979+0100    DEBUG   [processors]    processing/processors.go:128    Fail to apply processor global{decode_json_fields=message, timestamp=[field=mytimestamp, target_field=@timestamp, timezone=UTC, layouts=[2020-01-02T12:34:56.999999Z]]}: failed parsing time field mytimestamp='2021-03-14T13:25:49.008906Z'

The input log timestamp was 2021-03-14T13:25:49.008906Z but the timestamp processor somehow lost/chop off the years (or the first 4 ?) character of the timestamp.

Why timestamp processor truncates the timestamp?

How should i construct the layout to allow a plain and simple 2021-03-14T13:25:49.008906Z timestamp?

Filebeat 7.11.2, Elasticsearch 7.11.2, Kibana 7.11.2.

Note:

On Elasticsearch side I've set both @timestamp and mytimestamp fields type to date_nanos with a mapping template:

curl -X PUT "http://$1:9200/_index_template/myindex_date_nano_template" -H 'Content-Type: application/json' -d'
{
  "priority": 200,
  "index_patterns": ["myindex-*"],
  "template": 
  {
    "mappings":
    {
      "properties":
      {
        "@timestamp":
        {
          "type": "date_nanos"
        },
        "mytimestamp":
        {
          "type": "date_nanos"
        }
      }
    }
  }
}
'

after applying that template mytimestamp shows up correctly (with the microsconds parts) in Kibana but @timestamp still not overwritten with the content of mytimestamp.

shaunak · March 15, 2021, 7:32pm

Please read about layouts in the documentation for the timestamp processor. They are based on a specific date; any arbitrary date cannot be used when specifying the layout.

For your case, try this:

layouts:
  - "2006-01-02T15:04:05.999999999Z07:00"

Shaunak

Shawn_McKee · March 16, 2021, 5:41pm

We are seeing the same problem. Elasticsearch 7.11.2, Filebeat 7.11.2 and Kibana 7.11.2

In filebeat we have this timestamp processor configured:

      - timestamp:
          field: timedata
          ignore_failure: false
          timezone: "America/Detroit"
          layouts:
            - '2020-12-01T15:08:05'
            - '2020-12-01T15:08:05.000'
            - '2020-12-01T15:08:05.000Z04:00'
          test:
            - '2006-01-02T15:04:05.000Z07:00'

Filebeat log file (in 'debug') shows the same year truncation reported above:

2021-03-16T13:32:33.603-0400    DEBUG   [processor.timestamp]   timestamp/timestamp.go:173      Failure parsing time field.     {"error": "failed parsing time field timedata='2006-01-02T15:04:05.000Z07:00'", "errorCauses": [{"error": "failed using layout [2020-12-01T15:08:05] cannot parse [-01-02T15:04:05.000Z07:00] as [0-]"}, {"error": "failed using layout [2020-12-01T15:08:05.000] cannot parse [-01-02T15:04:05.000Z07:00] as [0-]"}, {"error": "failed using layout [2020-12-01T15:08:05.000Z04:00] cannot parse [-01-02T15:04:05.000Z07:00] as [0-]"}]}
2021-03-16T13:32:33.603-0400    INFO    instance/beat.go:386    filebeat stopped.
2021-03-16T13:32:33.623-0400    ERROR   instance/beat.go:971    Exiting: error initializing processors: failed to parse test timestamp: failed parsing time field timedata='2006-01-02T15:04:05.000Z07:00'

Note the logging starts with the right value:

timedata='2006-01-02T15:04:05.000Z07:00'

But then, as it tries to pattern match is uses a string with the year removed:

cannot parse [-01-02T15:04:05.000Z07:00]

Seems like there is a bug here? Can someone check?

Thanks - Shawn

sandman0 · March 16, 2021, 8:43pm

I am seeing the same behaviour as @Shawn_McKee on Filebeat 7.11.1.

6NMgfDwZ3 · March 16, 2021, 10:12pm

@shaunak Thank you so much, at least I'm one step ahead because Filebeat does not log any error messages, and the "test dates" passes the test.

Relevant filebeat.yml part:

processors:
  - decode_json_fields:
     fields: ["message"]
     process_array: true
     target: ""
     add_error_key: true
     overwrite_keys: true
  - timestamp:
      field: mytimestamp
      layouts:
        - "2006-01-02T15:04:05.999999999Z07:00"
      test:
        - "2020-01-02T12:34:56.123456Z"
        - "2021-03-15T22:29:34.213223Z"

Apart from that Filebeat still not overwriting @timestamp field but I'll open an other discussion about it.

@Shawn_McKee @sandman0 you have to fiddle with the Mon Jan 2 15:04:05 MST 2006 timestamp and transform that timestamp to an other form what your needs. This madness comes from the Go time package: time · pkg.go.dev More explanation: Go Date and Time Formatting

Sum: You can't write a random datetime to the layout field you have to stick to the specific timestamp (above) so the underlaying Go library can match and confirm the timestamp pieces of your layout samples

Shawn_McKee · March 17, 2021, 12:47am

Thanks, that worked. Here is what I ended up with:

  - timestamp:
      field: timedata
      ignore_failure: false
      timezone: "America/Detroit"
      layouts:
        - '2006-01-02T15:04:05.999999999'
        - '2006-01-02T15:04:05.000'
        - '2006-01-02T15:04:05.000-07:00'
        - '2006-01-02T15:04:05'
      test:
        - '2016-01-02T19:04:05'
        - '2016-01-02T19:04:05.241'
        - '2016-01-02T19:04:05.241-04:00'

The @timestamp field is being correctly updated as well. Thanks again,

Shawn

sandman0 · March 17, 2021, 3:09am

Yes, works for me now as well. I had no idea about that whole fixed reference date thing in go.
Thank you @6NMgfDwZ3 !

system · April 14, 2021, 5:09am

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

Topic		Replies	Views
"failed parsing time field" + "failed using layout" Beats filebeat	1	988	February 25, 2021
Filebeat timestamp processsor doesn't parse microseconds part Beats filebeat	4	1199	October 30, 2020
Filebeat cannot parse a custom @timestamp string Beats docker , filebeat	2	1574	November 20, 2020
Using timestamp processor fails Beats filebeat	2	1186	May 15, 2020
Filebeat process timestamp from JSON Beats filebeat	2	2457	June 16, 2020

Timestamp processor truncates timestamp and fails to parse

Related topics