Issue with 'win_eventlog' plugin timestamp precision

[FramnkRulez]

I've been testing the new 'win_eventlog' plugin in 1.16.0 and I've noticed an issue with timestamp precision when writing to a json file. In the attached config, json is configured for microsecond precision but output entries are rounded to the nearest minute

Relevant telegraf.conf:

[agent]
  interval = "60s"
  round_interval = true
  metric_batch_size = 1000
  metric_buffer_limit = 10000
  collection_jitter = "0s"
  flush_interval = "10s"
  flush_jitter = "0s"
  precision = ""
  debug = true
  quiet = false
  logfile = "telegraf.log"
  hostname = ""
  omit_hostname = true
[[outputs.file]]
  files = ["logs.out"]
  rotation_interval = "24h"
  rotation_max_size = "1MB"
  rotation_max_archives = 5
  data_format = "json"
  json_timestamp_units = "1us"
  
[[inputs.win_eventlog]]
  eventlog_name = ""
  separator = "_"
  only_first_line_of_message = false
  xpath_query = '''
<QueryList>
  <Query Id="0" Path="Application">
    <Select Path="Application">*[System[(Level=1  or Level=2 or Level=3)]]</Select>
    <Select Path="Security">*[System[(Level=1  or Level=2 or Level=3)]]</Select>    
  </Query>
</QueryList>
  '''

System info:

Steps to reproduce:

1. Use the attached telegraf.conf on a Windows system
2. Generate a critical Application log entry (cause a service crash, etc).

Expected behavior:

Expected timestamp to match the "TimeCreated" field from Windows log entries.

Actual behavior:

Timestamp in output is rounded to nearest minute

Additional info:

Here's an example entry from the output json, note that the 'TimeCreated' for the event log entry is 2020-09-30T14:37:03.935143900Z but the recorded timestamp in the output is 1601476680000000 which is actually rounded to 2020-09-30T14:38:00.000000000Z (almost a minute off the actual event time).

{"fields":{"Data_1":"Service.exe","Data_10":"01d6973729e505e9","Data_11":"C:\\test\\service\\target\\debug\\Service.exe","Data_12":"C:\\WINDOWS\\System32\\KERNELBASE.dll","Data_13":"ec4d3cf6-88bf-41bf-98aa-e5d32c3d5963","Data_2":"1.0.0.0","Data_3":"5f748964","Data_4":"KERNELBASE.dll","Data_5":"10.0.18362.1049","Data_6":"c4675baa","Data_7":"e0434352","Data_8":"001144c2","Data_9":"4018","EventRecordID":29827,"Message":"Faulting application name: Service.exe, version: 1.0.0.0, time stamp: 0x5f748964\r\nFaulting module name: KERNELBASE.dll, version: 10.0.18362.1049, time stamp: 0xc4675baa\r\nException code: 0xe0434352\r\nFault offset: 0x001144c2\r\nFaulting process id: 0x4018\r\nFaulting application start time: 0x01d6973729e505e9\r\nFaulting application path: C:\\test\\service\\target\\debug\\Service.exe\r\nFaulting module path: C:\\WINDOWS\\System32\\KERNELBASE.dll\r\nReport Id: ec4d3cf6-88bf-41bf-98aa-e5d32c3d5963\r\nFaulting package full name: \r\nFaulting package-relative application ID: ","OpcodeText":"Info","ProcessName":"[System Process]","Task":100,"TaskText":"Application Crashing Events","TimeCreated":"2020-09-30T14:37:03.935143900Z","UserID":"","Version":0},"name":"win_eventlog","tags":{"Channel":"Application","Computer":"OMITTED","EventID":"1000","Keywords":"Classic","Level":"2","LevelText":"Error","Source":"Application Error"},"timestamp":1601476680000000}

[ssoroka]

I think this is intentional, though I'm not sure if it's the right thing to do or not. It's not unusual for inputs to use the timestamp from when they were collected, which can be useful. Since these events have timestamps, though, I can see why it would make sense to use those as well.

The change is pretty simple.. parse the time out of the TimeCreated field, and pass it to addFields, eg acc.AddFields("win_eventlog", fields, tags, parsedTime)

thoughts @simnv ?

[simnv]

@ssoroka @FramnkRulez. I see the point, will add this with a config switch.