influxdata/telegraf

Missing log entry when telegraf restarts in tail | csv

Open

#13,317 opened on May 23, 2023

View on GitHub
 (7 comments) (0 reactions) (0 assignees)Go (4,161 forks)batch import
area/csvarea/tailfeature requesthelp wantedsize/m

Repository metrics

Stars
 (9,892 stars)
PR merge metrics
 (Avg merge 2d 12h) (136 merged PRs in 30d)

Description

Relevant telegraf.conf

[global_tags]

[agent]
  interval = "1s"
  round_interval = true
  metric_batch_size = 10000
  metric_buffer_limit = 100000
  collection_jitter = "1s"
  flush_interval = "11s"
  flush_jitter = "1s"
  precision = "1ms"
  debug = true
  quiet = false
  logfile = "./telegraf.log"
  logtarget = "file"
  logfile_rotation_interval = 0
  logfile_rotation_max_size = "100KB"
  logfile_rotation_max_archives = 50
  hostname = ""
  omit_hostname = true

[[inputs.tail]]
  name_override = "Product_State"
  interval = "2s"
  files = ["C://_ProduData//*//Log//ProductState//Log_ProductState_*.csv"]
  from_beginning = false
  watch_method = "poll"
  character_encoding = "utf-8"
  max_undelivered_lines = 4000
  data_format = "csv"
  csv_header_row_count = 1
  csv_column_names = ["Timestamp","ProductionRunGUID"]
  csv_column_types = ["string", "string"]
  csv_skip_rows = 0
  csv_skip_columns = 0
  csv_delimiter = ";"
  csv_trim_space = false
  csv_tag_columns = []
  csv_measurement_column = ""
  csv_timestamp_column = "Timestamp"
  csv_timestamp_format = "2006-01-02T15:04:05.999Z"
  csv_timezone = "UTC"
  csv_skip_values = [""]
  path_tag = ""
  [inputs.tail.tags]
    _in = "ProductStateTest"

[[outputs.file]]
  files = ["stdout", "./tail_test.out"]
  [outputs.file.tagpass]
   _in = ["ProductStateTest"]

Logs from Telegraf

...
2023-05-23T08:36:34Z I! Loaded inputs: tail
2023-05-23T08:36:34Z I! Loaded aggregators: 
2023-05-23T08:36:34Z I! Loaded processors: 
2023-05-23T08:36:34Z I! Loaded outputs: file
2023-05-23T08:36:34Z I! Tags enabled: 
2023-05-23T08:36:34Z I! [agent] Config: Interval:1s, Quiet:false, Hostname:"", Flush Interval:11s
2023-05-23T08:36:34Z D! [agent] Initializing plugins
2023-05-23T08:36:34Z D! [agent] Connecting outputs
2023-05-23T08:36:34Z D! [agent] Attempting connection to [outputs.file]
2023-05-23T08:36:34Z D! [agent] Successfully connected to outputs.file
2023-05-23T08:36:34Z D! [agent] Starting service inputs
2023-05-23T08:36:34Z D! [inputs.tail] Tail added for "C:\\_ProduData\\99999\\Log\\ProductState\\Log_ProductState_TEST.csv"
2023-05-23T08:36:46Z D! [outputs.file] Buffer fullness: 0 / 100000 metrics
2023-05-23T08:36:57Z D! [outputs.file] Buffer fullness: 0 / 100000 metrics
2023-05-23T08:37:09Z D! [outputs.file] Buffer fullness: 0 / 100000 metrics
2023-05-23T08:37:20Z D! [outputs.file] Buffer fullness: 0 / 100000 metrics
2023-05-23T08:37:32Z D! [outputs.file] Buffer fullness: 0 / 100000 metrics
2023-05-23T08:37:43Z D! [outputs.file] Buffer fullness: 0 / 100000 metrics
2023-05-23T08:37:55Z D! [outputs.file] Buffer fullness: 0 / 100000 metrics
2023-05-23T08:38:06Z D! [outputs.file] Wrote batch of 1 metrics in 359.1µs
2023-05-23T08:38:06Z D! [outputs.file] Buffer fullness: 0 / 100000 metrics
...

System info

Windows10 64 bit, the issue is verified on telegraf versions 1.20.3 and 1.26.3.

Docker

No response

Steps to reproduce

  1. Start telegraf with a tail plugin and csv_header_row_count = 1.
  2. Read in a log file and produce log-entries "A" and "B". In this example Log_ProductState_TEST.csv with content:

Timestamp;ProductionRunGUID; 2023-05-15T04:58:24.001Z;A; 2023-05-15T04:58:25.002Z;B;

  1. Restart telegraf.
  2. Add new log-entry "C" to the tailed log file.
  3. Add a second new log-entry "D" to the tailed log file. Save the file.
  4. Check the telegraf output. Only the second log-entry "D" gets shown, "C" gets missed.

Expected behavior

Telegraf tail csv should check that the header is only at the beginning of a file and not the first new log-entry. Both log-entries "C" and "D" should get shown.

content of ./tail_test.out:

Product_State,_in=ProductStateTest ProductionRunGUID="A" 1684126704001000000 Product_State,_in=ProductStateTest ProductionRunGUID="B" 1684126705002000000 Product_State,_in=ProductStateTest ProductionRunGUID="C" 1684126705003000000 Product_State,_in=ProductStateTest ProductionRunGUID="D" 1684126705004000000

Actual behavior

Only the second log-entry "D" gets shown, the first log-entry "C" gets missed:

content of ./tail_test.out:

Product_State,_in=ProductStateTest ProductionRunGUID="A" 1684126704001000000 Product_State,_in=ProductStateTest ProductionRunGUID="B" 1684126705002000000 Product_State,_in=ProductStateTest ProductionRunGUID="D" 1684126705004000000

Additional info

Workaround 1: Using from_beginning = true. However, this is not a nice solution as the complete files get reread whenever telegraf restarts. Not an option for my use case unfortunatly but maybe for other use cases.

Workaround 2: One can use csv_header_row_count = 0 instead and filter out the header data in a e.g. starlark processor later on. However, this might limit other features, get kind of complex and as well error prone. Therefore a fix of the bug would be highly appreciated.

Contributor guide