@timestamp milliseconds is always 000

[ofira87]

Log events which occur one after the other (within a difference of milliseconds) sometimes displayed, in services like Elasticsearch\Kibana, in an incorrect order. This is happening because their milliseconds value in '@timestamp' key is always zero (.000).

Looking at Event Viewer, you can see that INFO event 1035 occurred few milliseconds after INFO event 11729 (it happened twice):

And here, looking at Kibana, you can see that because of the lake of milliseconds this events are displayed incorrectly (the first couple of 11729 and 1035 events are displayed correctly*, first 11729 and then 1035, but the other two events are not):

*Please ignore the hours.

Here's the same example logged using NXlog instead. You can see the Event Viewer here:

And here you can see them displayed correctly in Kibana because of the milliseconds value (given from the NXlog logs):

[andrewkroh]

For bug reports please provide:

• Winlogbeat Version:
• Operating System:

For side-by-side comparison, please provide the JSON content of the same event log record as logged by Winlogbeat and the other tool. In Kibana you can expand the event, select the JSON tab, and copy the _source field.

[martinscholz83]

@ofira87 Winlogbeat set time with milliseconds. Here example from my machine "@timestamp": "2016-12-16T07:52:45.994Z". Do you have any filter or logstash between metricbeat and kibana?

[ofira87]

@andrewkroh Will upload soon, both versions and source message.

@maddin2016 I'm sending the data to a service which have a built-in Logstash with specific rules for Winlogbeat messages\logs. As I said, I will take a look at the source itself.

[ofira87]

@andrewkroh

• Winlogbeat Version: 5.1.1 x64
• Operating System: Microsoft Windows Server 2012 R2 Standard x64 Version 6.3.9600

@maddin2016 The @timestamp value inside _source property is: "@timestamp": "2016-12-12T10:37:26.000+00:00" And for the second message\log: "@timestamp": "2016-12-12T10:39:45.000+00:00"

As I mentioned, the logs are sent to a service, which have a built-in Logstash, called logz.io. Here is the winlogbeat.yml config file (minus comments, the real TOKEN value and the real C:/PATH_TO_CERT/MY_CERT.crt value):

winlogbeat.event_logs:
  - name: Application
    ignore_older: 72h
  - name: Security
    ignore_older: 72h
  - name: System
    ignore_older: 72h
fields:
  env: staging
  logzio_codec: json
  token: TOKEN
fields_under_root: true
output.logstash:
  hosts: ["listener.logz.io:5015"]
  ssl.certificate_authorities: ["C:/PATH_TO_CERT/MY_CERT.crt"]

EDIT: I've noticed that not all logs suffer from missing ms value. The ones that DO have ms value have this EXTRA top level fields\properties (inside _source property): process_id (integer), thread_id (integer), opcode (string), version (integer) and user (object).

[martinscholz83]

@ofira87, do you have any logstash conf from logz.io?

[ofira87]

@maddin2016 No. The rules are defined by them. But, as I mentioned, some logs DO have ms value. If you want to try to reproduce my problem then: 1) Download NXlog installer from HERE (no need to intall it, just to open the file!). 2) Click on the installer and then press Cancel > Yes > Finish.

Now, look at Event Viewer and at Kibana and see if the message\log got ms value. You should see 2 Application events, with level Information, occurring at the same time, with this messages: Product: NXLog-CE -- Installation failed. and: Windows Installer installed the product. Product Name: NXLog-CE. Product Version: 2.9.1716. Product Language: 1033. Manufacturer: NXLog Ltd. Installation success or error status: 1602.

[andrewkroh]

@ofira87 Can you please post the the complete _source field (not just the @timestamp) for the same event sent by Winlogbeat and NXlog?

[martinscholz83]

@ofira87, i have test your behavior. Execute the msi and then cancel. In Kibana i see those 2 events with different milliseconds time stamps.

So i don't think its a failure by metricbeat

[ofira87]

@andrewkroh Winlogbeat _source:

  "_source": {
    "computer_name": "WIN-O3FCDHRLK9U",
    "logzio_codec": "json",
    "keywords": [
      "Classic"
    ],
    "level": "Information",
    "log_name": "Application",
    "@metadata": {
      "beat": "winlogbeat",
      "type": "wineventlog"
    },
    "record_number": "9159",
    "event_data": {
      "param5": "(NULL)",
      "param6": "(NULL)",
      "Binary": "7B46433532363531342D414644392D344135432D383637372D3536323431353339363039447D2C2031363032",
      "param3": "(NULL)",
      "param4": "(NULL)",
      "param1": "Product: NXLog-CE -- Configuration failed.",
      "param2": "(NULL)"
    },
    "env": "staging",
    "type": "wineventlog",
    "opcode": "Info",
    "message": "Product: NXLog-CE -- Configuration failed.",
    "tags": [
      "beats-5015",
      "_logzio_codec_json",
      "_jsonparsefailure"
    ],
    "event_id": 11729,
    "@timestamp": "2016-12-12T10:37:26.000+00:00",
    "beat": {
      "hostname": "WIN-O3FCDHRLK9U",
      "name": "WIN-O3FCDHRLK9U",
      "version": "5.1.1"
    },
    "user": {
      "identifier": "XXX",
      "domain": "YYY",
      "name": "ZZZ",
      "type": "User"
    },
    "source_name": "MsiInstaller"
  }

NXLog _source:

  "_source": {
    "@timestamp": "2016-12-12T10:43:13.351+00:00",
    "message": "2016-12-12 10:43:12 WIN-O3FCDHRLK9U INFO 11729 YYY\\ZZZ Product: NXLog-CE -- Configuration failed.",
    "type": "msevent",
    "tags": [
      "_logz_tcp_tcp_8010"
    ]
  }

NOTE: the values of identifier, domain and name are replaced with XXX, YYY and ZZZ respectively.

@maddin2016 Did you set your host in output.logstash or in output.elasticsearch? Because, as I showed, I'm sending the logs to a Logstash service (please see HERE, under 'Configuring our logging pipeline').

[andrewkroh]

@ofira87 Those two events don't appear to be the same based on the various timestamps but it looks like you are comparing the @timestamp set by Winlogbeat to the @timestamp in the event from NXLog, and not the timestamp embedded in the message from NXLog.

The @timestamp value in the NXLog is probably added by Logstash (or the logz equivalent). It is set to the time that the event is received over TCP and not the time that the event was logged by the source application. The time that the event was logged by the source application appears to be embedded in the message field from NXLog. And this embedded timestamp has resolution in seconds (same as Winlogbeat).

Winlogbeat sets its @timestamp to the time when the event log record was generated by the source application.

Events logged by applications using the older "event logging" API will have a TimeGenerated value whose resolution is in seconds. The field is defined as an integer representing the number of seconds since 00:00:00 January 1, 1970, Universal Coordinated Time.

Events logged by applications using the newer "windows event log" API that was introduced in Vista will have a higher resolution timestamps. These same events can also have some of those fields you mentioned like process_id.

[ofira87]

@andrewkroh Well I guess you figured it out.. @maddin2016 According to @andrewkroh the @timestamp that you're seeing is not generated from the log message. Can you post the _source value for those events that you've uploaded?

[martinscholz83]

@ofira87, the @timestamp from winlogbeat is always the timestamp when the log was created., Depending on the source application like @andrewkroh says with nanoseconds or only with seconds. See here and here. @andrewkroh, correct me if i'm wrong. And the Timecreated i get from the nxlog installer is with nanoseconds. Here example from my eventlog

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
- <System>
  <Provider Name="MsiInstaller" /> 
  <EventID Qualifiers="0">11708</EventID> 
  <Level>4</Level> 
  <Task>0</Task> 
  <Keywords>0x80000000000000</Keywords> 
  <TimeCreated SystemTime="2016-12-22T10:47:22.566143200Z" /> 
  <EventRecordID>111575</EventRecordID> 
  <Channel>Application</Channel> 
  <Computer>4201halwsd00001.ad.lsa-net.de</Computer> 
  <Security UserID="S-1-5-21-910002505-382444473-275461565-75023" /> 
  </System>
- <EventData>
  <Data>Product: NXLog-CE -- Installation failed.</Data> 
  <Data>(NULL)</Data> 
  <Data>(NULL)</Data> 
  <Data>(NULL)</Data> 
  <Data>(NULL)</Data> 
  <Data>(NULL)</Data> 
  <Data /> 
  <Binary>7B46433532363531342D414644392D344135432D383637372D3536323431353339363039447D2C2031363032</Binary> 
  </EventData>
  </Event>

So whatever, i still don't think it has to do with winlogbeat.

[andrewkroh]

Winlogbeat (on Vista and newer) is unmarshalling the event log record XML so it uses whatever timestamp Windows provides. For debugging you can set include_xml: true and Winlogbeat will forward the XML with the event and you can compare the @timestamp to the <TimeCreated> from the XML. If there is a difference then please reopen.