Changes input timestamp

[csobchuk]

I have a problem with logstash-filter-verifier 1.2 that I can't resolve so I am hoping it is a bug. The problem is that the json file specifies a timestamp of 2017-02-22 15:38:34.057, however, upon date match it changes this (and only this particular timestamp) to 2017-01-22 15:38:57.000. I have tested over 25 different entries and this is the only one that has this issue. I verified that this was an issue on the latest release using the binary .tgz adding the --logstash-path argument for the 5.2 paths (/usr/share/) and it shows the same error as the 1.2 version. The json file is below and the conf file is below it.

{
  "fields": {
  },
  "codec": "line",
  "input": [
    "2017-02-22 15:38:34.057 4412 INFO glance.db.sqlalchemy.metadata [-] File /openstack/venvs/glance-13.3.14/etc/glance/metadefs/software-databases.json loaded to database."
    ],
  "expected": [
    {
        "host": "cfa",
        "message": "2017-02-22 15:38:34.057 4412 INFO glance.db.sqlalchemy.metadata [-] File /openstack/venvs/glance-13.3.14/etc/glance/metadefs/software-databases.json loaded to database.",
        "@timestamp": "2017-02-22T15:38:34.057Z",
        "received_at": "2017-07-05T20:55:05.633Z",
        "pid": "4412",
        "loglevel": "INFO",
        "module": "glance.db.sqlalchemy.metadata",
        "logmessage": "File /openstack/venvs/glance-13.3.14/etc/glance/metadefs/software-databases.json loaded to database."
    }
  ]
}

The conf file:

filter {
  grok {
      match => { "message" => "%{TIMESTAMP_ISO8601:[@metadata][timestamp]}%{SPACE}%{NUMBER:pid}%{SPACE}?%{LOGLEVEL:loglevel} \[?\b%{NOTSPACE:module}\b\]?%{SPACE}? (?:\[\-\]|\[(?:(%{NOTSPACE:request_id}|\-) (%{NOTSPACE:user}|\-) (%{NOTSPACE:tenant}|\-) (%{NOTSPACE:domain}|\-) (%{NOTSPACE:user_domain}|\-) (%{NOTSPACE:project_domain}|\-)\]))?%{SPACE}?(?:(?:%{IP:instance},*%{IP:instance}*)|(?<instance>\h{8}-\h{4}-\h{4}-\h{4}-\h{12}))?%{SPACE}?%{GREEDYDATA:logmessage}?" }
      add_field => { "received_at" => "%{@timestamp}" }
    }
    date { match => [ "[@metadata][timestamp]", "YYYY-MM-DD HH:mm:ss.sss", "ISO8601" ] }
    if [module] == "iso8601.iso8601" {
      drop {}
    }
}

[magnusbaeck]

This is caused by a problem with your date pattern. Use "YYYY-MM-dd HH:mm:ss.SSS" instead of "YYYY-MM-DD HH:mm:ss.sss".

[csobchuk]

I just ran in to the same case with another log line. The month gets set to 01 from 03 and the fractional seconds becomes the seconds value and the fractional part dropped.

"message":     "2017-03-07 19:02:29.032 4423 WARNING oslo.service.loopingcall [req-8f79d643-b86f-49d6-9200-d04a4586d7df - - - - -] Function 'cinder.service.Service.report_state' run outlasted interval by 4.61 sec",
-  "@timestamp": "2017-03-07T19:02:29.032Z",
+  "@timestamp": "2017-01-07T19:02:32.000Z",

[csobchuk]

I just noticed that you replied and closed the issue after I posted - I should have refreshed the page first. Thanks Magnus. It was weird that it worked most of the time and only once in a while it wouldn't parse correctly. It works fine now.