illegal attempt to update using time y when last update time is x (minimum one second step)
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Wormly Collectd installer |
New
|
Unknown
|
|||
collectd (Ubuntu) |
Incomplete
|
Undecided
|
Unassigned |
Bug Description
This is a spin off from bug 1971093, not a regression as we had no collectd at all, but waiting on Upstream to respond.
We will link the upstream case and chime in there, hoping to get some insight.
Issue: https:/
Repro (not a 100% hit rate yet):
# Install packages
$ apt install collectd collectd-utils rrdtool
Change default config to (not sure if all are required):
$ vim /etc/collectd/
...
<Plugin rrdtool>
DataDir "/var/lib/
CacheTimeout 10
CacheFlush 900
RandomTimeout 5
WritesPerSecond 50
...
a) as reported upstream
# Enable new config and clean old data
$ systemctl stop collectd
$ rm -rf /var/lib/
$ systemctl start collectd
b) as I've found it on my system
# restart once to enable the new config
$ systemctl restart collectd
# let it collect some data
$ sleep 120s
# remove files, restart again
$ rm -rf /var/lib/
$ systemctl restart collectd
Then check the service output:
$ journalctl -u collectd
Notes:
- I can only see that
a) while stopping the service
b) after deleting DataDir
Others (https:/
Sadly this is racy, in 1 of 10 cases I got:
rrdtool plugin: rrd_update_r (/var/lib/
In the others I got only the more expected (and IMHO ok):
rrdtool plugin: rrd_update_r (/var/lib/
description: | updated |
description: | updated |
description: | updated |
Changed in wormly-collectd: | |
status: | Unknown → New |
It does not always show up (makes bisecting hard :-/)
Bad case: collectd/ rrd/j.lxd/ disk-nvme0n1p5/ disk_io_ time.rrd) failed: /var/lib/ collectd/ rrd/j.lxd/ disk-nvme0n1p5/ disk_io_ time.rrd: illegal attempt to update using time 1674629134 when last update time is 1674629143 (minimum one second step) collectd/ rrd/j.lxd/ disk-loop8/ disk_time. rrd) failed: /var/lib/ collectd/ rrd/j.lxd/ disk-loop8/ disk_time. rrd: illegal attempt to update using time 1674629134 when last update time is 1674629143 (minimum one second step)
Jan 25 06:45:55 j collectd[31381]: Exiting normally.
Jan 25 06:45:55 j systemd[1]: Stopping Statistics collection and monitoring daemon...
Jan 25 06:45:55 j collectd[31381]: collectd: Stopping 5 read threads.
Jan 25 06:45:55 j collectd[31381]: rrdtool plugin: rrd_update_r (/var/lib/
Jan 25 06:45:55 j collectd[31381]: collectd: Stopping 5 write threads.
Jan 25 06:45:55 j collectd[31381]: rrdtool plugin: Shutting down the queue thread. This may take a while.
Jan 25 06:45:55 j collectd[31381]: rrdtool plugin: rrd_update_r (/var/lib/
Same config/szenario - good case: collectd/ rrd/j.lxd/ battery- 0/capacity. rrd) failed: opening '/var/lib/ collectd/ rrd/j.lxd/ battery- 0/capacity. rrd': No such file or directory
Jan 25 06:51:14 j collectd[31447]: Exiting normally.
Jan 25 06:51:14 j systemd[1]: Stopping Statistics collection and monitoring daemon...
Jan 25 06:51:14 j collectd[31447]: collectd: Stopping 5 read threads.
Jan 25 06:51:14 j collectd[31447]: collectd: Stopping 5 write threads.
Jan 25 06:51:14 j collectd[31447]: rrdtool plugin: Shutting down the queue thread. This may take a while.
Jan 25 06:51:14 j collectd[31447]: rrdtool plugin: rrd_update_r (/var/lib/
Since this is related to caching and write threads, maybe this is about some info being in memory or those threads - which races on a restart with other content like the removed files on disk or the flushing.
Waiting for others to chime in...