Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Node Exporter metrics show incorrect timestamp (1970-01-01T00:00:00.000000000Z) #8368

Closed
eresgie opened this issue Jan 12, 2024 · 1 comment · Fixed by #8370
Closed

Node Exporter metrics show incorrect timestamp (1970-01-01T00:00:00.000000000Z) #8368

eresgie opened this issue Jan 12, 2024 · 1 comment · Fixed by #8370
Labels
status: waiting-for-triage

Comments

@eresgie
Copy link

eresgie commented Jan 12, 2024

Bug Report

Describe the bug
When using Node Exporter Metrics, first batch of metrics is returning 1970-01-01T00:00:00.000000000Z as a timestamp. Subsequent metrics shows correct timestamp.
Doesn't matter if it's in a Fluent Bit config or running from command line.

To Reproduce

Run the command: (output log is truncated for brevity, verbosity level set to debug)

fluent-bit -i node_exporter_metrics -o stdout -f 1 -v

Output:

[...]
[2024/01/12 09:32:15] [ info] Configuration:
[2024/01/12 09:32:15] [ info]  flush time     | 1.000000 seconds
[2024/01/12 09:32:15] [ info]  grace          | 5 seconds
[2024/01/12 09:32:15] [ info]  daemon         | 0
[2024/01/12 09:32:15] [ info] ___________
[2024/01/12 09:32:15] [ info]  inputs:
[2024/01/12 09:32:15] [ info]      node_exporter_metrics
[2024/01/12 09:32:15] [ info] ___________
[2024/01/12 09:32:15] [ info]  filters:
[2024/01/12 09:32:15] [ info] ___________
[2024/01/12 09:32:15] [ info]  outputs:
[2024/01/12 09:32:15] [ info]      stdout.0
[2024/01/12 09:32:15] [ info] ___________
[2024/01/12 09:32:15] [ info]  collectors:
[2024/01/12 09:32:15] [ info] [fluent bit] version=2.2.1, commit=, pid=24147
[2024/01/12 09:32:15] [debug] [engine] coroutine stack size: 36864 bytes (36.0K)
[2024/01/12 09:32:15] [ info] [storage] ver=1.5.1, type=memory, sync=normal, checksum=off, max_chunks_up=128
[2024/01/12 09:32:15] [ info] [cmetrics] version=0.6.6
[2024/01/12 09:32:15] [ info] [ctraces ] version=0.4.0
[2024/01/12 09:32:15] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] initializing
[2024/01/12 09:32:15] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] storage_strategy='memory' (memory only)
[2024/01/12 09:32:15] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] path.procfs = /proc
[2024/01/12 09:32:15] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] path.sysfs  = /sys
[2024/01/12 09:32:15] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] enabled metrics cpu
[2024/01/12 09:32:15] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] enabled metrics loadavg
[2024/01/12 09:32:15] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] enabled metrics meminfo
[2024/01/12 09:32:15] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] enabled metrics diskstats
[2024/01/12 09:32:15] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] enabled metrics uname
[2024/01/12 09:32:15] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] enabled metrics netdev
[2024/01/12 09:32:15] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] [thread init] initialization OK
[2024/01/12 09:32:15] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] thread instance initialized
[2024/01/12 09:32:15] [debug] [node_exporter_metrics:node_exporter_metrics.0] created event channels: read=30 write=31
[2024/01/12 09:32:15] [debug] [stdout:stdout.0] created event channels: read=34 write=35
[2024/01/12 09:32:15] [ info] [output:stdout:stdout.0] worker #0 started
[2024/01/12 09:32:15] [ info] [sp] stream processor started

[2024/01/12 09:32:20] [debug] [input chunk] update output instances with new chunk size diff=5939, records=0, input=node_exporter_metrics.0
[2024/01/12 09:32:21] [debug] [task] created task=0x6000023f8000 id=0 OK
[2024/01/12 09:32:21] [debug] [output:stdout:stdout.0] task_id=0 assigned to thread #0
1970-01-01T00:00:00.000000000Z node_meminfo_pageins_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_pageouts_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_total_bytes = 0
1970-01-01T00:00:00.000000000Z node_load1 = 0
1970-01-01T00:00:00.000000000Z node_load5 = 0
1970-01-01T00:00:00.000000000Z node_load15 = 0
1970-01-01T00:00:00.000000000Z node_meminfo_free_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_active_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_compressed_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_inactive_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_internal_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_wired_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_purgeable_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_swap_used_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_swap_total_bytes = 0
[2024/01/12 09:32:21] [debug] [out flush] cb_destroy coro_id=0
[2024/01/12 09:32:21] [debug] [task] destroy task=0x6000023f8000 (task_id=0)
[2024/01/12 09:32:25] [debug] [input chunk] update output instances with new chunk size diff=23385, records=0, input=node_exporter_metrics.0
[2024/01/12 09:32:26] [debug] [task] created task=0x6000023fc000 id=0 OK
[2024/01/12 09:32:26] [debug] [output:stdout:stdout.0] task_id=0 assigned to thread #0
2024-01-12T08:32:20.149726834Z node_cpu_seconds_total{cpu="0",mode="user"} = 130898.07000000001
2024-01-12T08:32:20.149726834Z node_cpu_seconds_total{cpu="0",mode="system"} = 93278.589999999997
2024-01-12T08:32:20.149726834Z node_cpu_seconds_total{cpu="0",mode="nice"} = 0
2024-01-12T08:32:20.149726834Z node_cpu_seconds_total{cpu="0",mode="idle"} = 649972.66000000003
[...]

When running the same command, but only for CPU metrics, everything is ok:

fluent-bit -i node_exporter_metrics -p "metrics=cpu" -o stdout -f 1 -v

Output:

[...]
[2024/01/12 09:38:32] [ info] Configuration:
[2024/01/12 09:38:32] [ info]  flush time     | 1.000000 seconds
[2024/01/12 09:38:32] [ info]  grace          | 5 seconds
[2024/01/12 09:38:32] [ info]  daemon         | 0
[2024/01/12 09:38:32] [ info] ___________
[2024/01/12 09:38:32] [ info]  inputs:
[2024/01/12 09:38:32] [ info]      node_exporter_metrics
[2024/01/12 09:38:32] [ info] ___________
[2024/01/12 09:38:32] [ info]  filters:
[2024/01/12 09:38:32] [ info] ___________
[2024/01/12 09:38:32] [ info]  outputs:
[2024/01/12 09:38:32] [ info]      stdout.0
[2024/01/12 09:38:32] [ info] ___________
[2024/01/12 09:38:32] [ info]  collectors:
[2024/01/12 09:38:32] [ info] [fluent bit] version=2.2.1, commit=, pid=24325
[2024/01/12 09:38:32] [debug] [engine] coroutine stack size: 36864 bytes (36.0K)
[2024/01/12 09:38:32] [ info] [storage] ver=1.5.1, type=memory, sync=normal, checksum=off, max_chunks_up=128
[2024/01/12 09:38:32] [ info] [cmetrics] version=0.6.6
[2024/01/12 09:38:32] [ info] [ctraces ] version=0.4.0
[2024/01/12 09:38:32] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] initializing
[2024/01/12 09:38:32] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] storage_strategy='memory' (memory only)
[2024/01/12 09:38:32] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] path.procfs = /proc
[2024/01/12 09:38:32] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] path.sysfs  = /sys
[2024/01/12 09:38:32] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] enabled metrics cpu
[2024/01/12 09:38:32] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] [thread init] initialization OK
[2024/01/12 09:38:32] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] thread instance initialized
[2024/01/12 09:38:32] [debug] [node_exporter_metrics:node_exporter_metrics.0] created event channels: read=30 write=31
[2024/01/12 09:38:32] [debug] [stdout:stdout.0] created event channels: read=34 write=35
[2024/01/12 09:38:32] [ info] [output:stdout:stdout.0] worker #0 started
[2024/01/12 09:38:32] [ info] [sp] stream processor started
[2024/01/12 09:38:38] [debug] [input chunk] update output instances with new chunk size diff=207, records=0, input=node_exporter_metrics.0
[2024/01/12 09:38:38] [debug] [task] created task=0x600002f94000 id=0 OK
[2024/01/12 09:38:38] [debug] [output:stdout:stdout.0] task_id=0 assigned to thread #0
[2024/01/12 09:38:38] [debug] [out flush] cb_destroy coro_id=0
[2024/01/12 09:38:38] [debug] [task] destroy task=0x600002f94000 (task_id=0)
[2024/01/12 09:38:42] [debug] [input chunk] update output instances with new chunk size diff=2049, records=0, input=node_exporter_metrics.0
[2024/01/12 09:38:42] [debug] [task] created task=0x600002f98000 id=0 OK
[2024/01/12 09:38:42] [debug] [output:stdout:stdout.0] task_id=0 assigned to thread #0
2024-01-12T08:38:37.965144142Z node_cpu_seconds_total{cpu="0",mode="user"} = 130933.5
2024-01-12T08:38:37.965144142Z node_cpu_seconds_total{cpu="0",mode="system"} = 93309.729999999996
2024-01-12T08:38:37.965144142Z node_cpu_seconds_total{cpu="0",mode="nice"} = 0
2024-01-12T08:38:37.965144142Z node_cpu_seconds_total{cpu="0",mode="idle"} = 650273.16000000003
2024-01-12T08:38:37.965144142Z node_cpu_seconds_total{cpu="1",mode="user"} = 124245.42999999999
2024-01-12T08:38:37.965144142Z node_cpu_seconds_total{cpu="1",mode="system"} = 96973.039999999994
2024-01-12T08:38:37.965144142Z node_cpu_seconds_total{cpu="1",mode="nice"} = 0
2024-01-12T08:38:37.965144142Z node_cpu_seconds_total{cpu="1",mode="idle"} = 666037.23999999999
2024-01-12T08:38:37.965144142Z node_cpu_seconds_total{cpu="2",mode="user"} = 110251.92999999999
2024-01-12T08:38:37.965144142Z node_cpu_seconds_total{cpu="2",mode="system"} = 87215.179999999993
2024-01-12T08:38:37.965144142Z node_cpu_seconds_total{cpu="2",mode="nice"} = 0
[...]

Adding more metrics results with bad timestamp again:

fluent-bit -i node_exporter_metrics -p "metrics=cpu,meminfo" -o stdout -f 1 -v

Output:

[2024/01/12 09:41:01] [ info] Configuration:
[2024/01/12 09:41:01] [ info]  flush time     | 1.000000 seconds
[2024/01/12 09:41:01] [ info]  grace          | 5 seconds
[2024/01/12 09:41:01] [ info]  daemon         | 0
[2024/01/12 09:41:01] [ info] ___________
[2024/01/12 09:41:01] [ info]  inputs:
[2024/01/12 09:41:01] [ info]      node_exporter_metrics
[2024/01/12 09:41:01] [ info] ___________
[2024/01/12 09:41:01] [ info]  filters:
[2024/01/12 09:41:01] [ info] ___________
[2024/01/12 09:41:01] [ info]  outputs:
[2024/01/12 09:41:01] [ info]      stdout.0
[2024/01/12 09:41:01] [ info] ___________
[2024/01/12 09:41:01] [ info]  collectors:
[2024/01/12 09:41:01] [ info] [fluent bit] version=2.2.1, commit=, pid=24408
[2024/01/12 09:41:01] [debug] [engine] coroutine stack size: 36864 bytes (36.0K)
[2024/01/12 09:41:01] [ info] [storage] ver=1.5.1, type=memory, sync=normal, checksum=off, max_chunks_up=128
[2024/01/12 09:41:01] [ info] [cmetrics] version=0.6.6
[2024/01/12 09:41:01] [ info] [ctraces ] version=0.4.0
[2024/01/12 09:41:01] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] initializing
[2024/01/12 09:41:01] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] storage_strategy='memory' (memory only)
[2024/01/12 09:41:01] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] path.procfs = /proc
[2024/01/12 09:41:01] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] path.sysfs  = /sys
[2024/01/12 09:41:01] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] enabled metrics cpu
[2024/01/12 09:41:01] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] enabled metrics meminfo
[2024/01/12 09:41:01] [debug] [input:node_exporter_metrics:node_exporter_metrics.0] [thread init] initialization OK
[2024/01/12 09:41:01] [ info] [input:node_exporter_metrics:node_exporter_metrics.0] thread instance initialized
[2024/01/12 09:41:01] [debug] [node_exporter_metrics:node_exporter_metrics.0] created event channels: read=30 write=31
[2024/01/12 09:41:01] [debug] [stdout:stdout.0] created event channels: read=34 write=35
[2024/01/12 09:41:01] [ info] [output:stdout:stdout.0] worker #0 started
[2024/01/12 09:41:01] [ info] [sp] stream processor started
[2024/01/12 09:41:06] [debug] [input chunk] update output instances with new chunk size diff=2088, records=0, input=node_exporter_metrics.0
[2024/01/12 09:41:07] [debug] [task] created task=0x600002478000 id=0 OK
[2024/01/12 09:41:07] [debug] [output:stdout:stdout.0] task_id=0 assigned to thread #0
1970-01-01T00:00:00.000000000Z node_meminfo_pageins_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_pageouts_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_total_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_free_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_active_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_compressed_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_inactive_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_internal_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_wired_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_purgeable_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_swap_used_bytes = 0
1970-01-01T00:00:00.000000000Z node_meminfo_swap_total_bytes = 0
[2024/01/12 09:41:07] [debug] [out flush] cb_destroy coro_id=0
[2024/01/12 09:41:07] [debug] [task] destroy task=0x600002478000 (task_id=0)
[2024/01/12 09:41:11] [debug] [input chunk] update output instances with new chunk size diff=4026, records=0, input=node_exporter_metrics.0
[2024/01/12 09:41:12] [debug] [task] created task=0x60000247c000 id=0 OK
[2024/01/12 09:41:12] [debug] [output:stdout:stdout.0] task_id=0 assigned to thread #0
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="0",mode="user"} = 130947.27
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="0",mode="system"} = 93320.580000000002
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="0",mode="nice"} = 0
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="0",mode="idle"} = 650393.62
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="1",mode="user"} = 124257.85000000001
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="1",mode="system"} = 96983.699999999997
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="1",mode="nice"} = 0
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="1",mode="idle"} = 666160.15000000002
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="2",mode="user"} = 110262.63
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="2",mode="system"} = 87224.199999999997
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="2",mode="nice"} = 0
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="2",mode="idle"} = 693854.54000000004
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="3",mode="user"} = 100119.5
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="3",mode="system"} = 77582.589999999997
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="3",mode="nice"} = 0
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="3",mode="idle"} = 716639.04000000004
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="4",mode="user"} = 77001.470000000001
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="4",mode="system"} = 44933.459999999999
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="4",mode="nice"} = 0
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="4",mode="idle"} = 777227.31999999995
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="5",mode="user"} = 56033.07
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="5",mode="system"} = 33279.059999999998
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="5",mode="nice"} = 0
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="5",mode="idle"} = 815270.15000000002
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="6",mode="user"} = 36250.169999999998
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="6",mode="system"} = 21825.119999999999
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="6",mode="nice"} = 0
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="6",mode="idle"} = 848695.56999999995
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="7",mode="user"} = 26350.610000000001
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="7",mode="system"} = 15863.049999999999
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="7",mode="nice"} = 0
2024-01-12T08:41:06.660851762Z node_cpu_seconds_total{cpu="7",mode="idle"} = 865429.57999999996
2024-01-12T08:41:06.661019175Z node_meminfo_pageins_bytes = 2.1258397616072131e+18
2024-01-12T08:41:06.661019175Z node_meminfo_pageouts_bytes = 0
2024-01-12T08:41:06.661019175Z node_meminfo_total_bytes = 8589934592
2024-01-12T08:41:06.661019175Z node_meminfo_free_bytes = 57245696
2024-01-12T08:41:06.661019175Z node_meminfo_active_bytes = 1551663104
2024-01-12T08:41:06.661019175Z node_meminfo_compressed_bytes = 0
2024-01-12T08:41:06.661019175Z node_meminfo_inactive_bytes = 1532690432
2024-01-12T08:41:06.661019175Z node_meminfo_internal_bytes = 0
2024-01-12T08:41:06.661019175Z node_meminfo_wired_bytes = 1688977408
2024-01-12T08:41:06.661019175Z node_meminfo_purgeable_bytes = 303050342400
2024-01-12T08:41:06.661019175Z node_meminfo_swap_used_bytes = 4062904320
2024-01-12T08:41:06.661019175Z node_meminfo_swap_total_bytes = 5368709120
  • Steps to reproduce the problem:

Run the commands above.

Expected behavior
Commands above should return metrics with correct timestamp.

Your Environment

  • Version used: 2.2.1
  • Server type and version: Tested on Macbook Pro, Intel NUC and on some VM in the cloud.
  • Operating System and version: Tested on MacOS Sonoma 14.2.1, Ubuntu 23.10, Debian 11 with the same results.
  • Filters and plugins: None

Additional context
Incorrect timestamp makes it impossible to push to Grafana Mimir.

Similar issue, but for other metrics: #7621
nokute78 added a commit to nokute78/fluent-bit that referenced this issue Jan 13, 2024
@nokute78
in_node_exporter_metrics: collect metrics at startup(fluent#8368)
586b78b 
Signed-off-by: Takahiro Yamashita <[email protected]>
@nokute78 nokute78 mentioned this issue Jan 13, 2024
Merged
2 tasks
@nokute78
Copy link
Collaborator

Thank you for reporting. I sent a patch #8370
This issue is caused by flushing metrics before updating it.
The patch is to update metrics at startup to prevent flushing empty metrics.

edsiper pushed a commit that referenced this issue Jan 13, 2024
@nokute78
in_node_exporter_metrics: collect metrics at startup(#8368) (#8370)
78c8aa4 
Signed-off-by: Takahiro Yamashita <[email protected]>
shaerpour pushed a commit to shaerpour/fluent-bit that referenced this issue Jan 16, 2024
@nokute78
in_node_exporter_metrics: collect metrics at startup(fluent#8368) (fl…
8cbed4a 
…uent#8370)

Signed-off-by: Takahiro Yamashita <[email protected]>
shaerpour pushed a commit to shaerpour/fluent-bit that referenced this issue Jan 16, 2024
@nokute78
in_node_exporter_metrics: collect metrics at startup(fluent#8368) (fl…
b18030c 
…uent#8370)

Signed-off-by: Takahiro Yamashita <[email protected]>
Signed-off-by: ahspw <[email protected]>
pwhelan pushed a commit that referenced this issue Jan 16, 2024
@nokute78 @pwhelan
in_node_exporter_metrics: collect metrics at startup(#8368) (#8370)
808df49 
Signed-off-by: Takahiro Yamashita <[email protected]>
@cianbe cianbe mentioned this issue Jan 19, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
status: waiting-for-triage
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

in_node_exporter_metrics: collect metrics at startup(#8368) nokute78/fluent-bit
2 participants
@eresgie @nokute78