search

rfmoz / tuptime

Report historical and statistical real time of the system, keeping it between restarts. Like uptime command but with more interesting output.
GNU General Public License v2.0
288 stars 40 forks source link

Incorrect uptime with previous downtime equal to 0 #81

Closed rfmoz closed 11 months ago

rfmoz commented 11 months ago

After a normal startup, with a downtime of various days, Tuptime register the previous downtime as current uptime:

# tuptime -t
...
59   11:11:39 05/11/23          9m 48s   11:21:27 05/11/23   OK                  0s
60   11:21:27 05/11/23   34d 3h 4m 25s

Inspecting the journal -b of the system reports this time jumps. Take into account that the current date is 2023-12-09:

-- Journal begins at Fri 2021-12-10 08:01:03 CET, ends at Sat 2023-12-09 14:23:41 CET. --
jun 18 16:55:54 host1 kernel: Linux version 5.10.0-8-amd64 (debian-kernel@lists.debian.org) (gcc-10 (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2) #1 SMP Debian 5.10.46-4 (2021-08-03)
...
jun 18 16:55:56 host1 systemd-timesyncd[450]: System clock time unset or jumped backwards, restoring from recorded timestamp: Sun 2023-11-05 11:21:28 CET
nov 05 11:21:28 host1 kernel: usb 5-2: New USB device found, idVendor=03f0, idProduct=2a41, bcdDevice= 1.00
...
nov 05 11:21:28 host1 systemd[1]: Starting Tuptime service...
...
nov 05 11:21:29 host1 systemd[1]: Finished Tuptime service.
...
nov 05 11:21:43 host1 at-spi-bus-launcher[775]: SpiRegistry daemon is running with well-known name - org.a11y.atspi.Registry
dic 09 14:02:12 host1 systemd-timesyncd[450]: Initial synchronization to time server 162.159.200.1:123 (2.debian.pool.ntp.org).
rfmoz commented 11 months ago

Tuptime registers the time reported by the system, so if it lost their resources to keep the clock updated, the problem is going to be registered at startup.

In this case, is due a drained RTC battery, but analyze the behaviour:

  1. The system started completely outdated, with a date on June.
  2. When systemd-timesyncd was executed, it move forward the time until their last recorded timestamp in November, by checking the mtime of /var/lib/systemd/timesync/clock [1].
  3. Just 15 seconds later, systemd-timesyncd has connected to an external ntp server and that brings the change to the current good date, in Decemeber.

This is a rare situation and that register let us guess that something may be wrong. In case of prefering to reach a valid time sinchronization before executing Tuptime, systemd-time-wait-sync.service must be enabled, but it could never reach that sinchronization and, therefore, never do the expected execution and lost a startup register.

If the event has just happened before the current startup, is it possible to delete the last register on the database and Tuptime will recreate it correctly on next execution.

# cp /var/lib/tuptime/tuptime.db /var/lib/tuptime/tuptime.db.back
# echo "DELETE FROM tuptime WHERE rowid = (SELECT MAX(rowid) FROM tuptime); VACUUM" | sqlite3 /var/lib/tuptime/tuptime.db

[1] - https://www.freedesktop.org/software/systemd/man/latest/systemd-timesyncd.service.html