11

I hope that here is somebody that can help me with this strange problem.

I think that i know why it is happening but i don't know how to solve it. Maybe it is because the BIOS time isn't set correct or something like it. But i don't want to change the BIOS time of approximate 400+ servers. (Or change the BIOS batt)

root@spool:~# echo TEST > /dev/kmsg
root@spool:~# dmesg -T | tail -1
[Mon Feb 17 04:57:03 2014] TEST
root@spool:~# date
Mon Feb 17 11:45:17 CET 2014

The server is running ntp for time sync.

Anybody here that knows how to fix this problem in the OS?

Linux spool 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1+deb7u1 x86_64 GNU/Linux

Why, when echoing to /dev/kmsg, the date/time of my message in dmesg is not synchronized with system date/time ?

  • Are you sure your localtime file /etc/localtime is right? The syslog get time from localtime. – VictorLee Jun 13 '18 at 6:17
  • I tend to use journalctl -k now (on systems with journald) precisely because of this. This includes the correct time, in my time zone. – neingeist Jun 29 at 11:11
5

To verify your theory (which, by the way, is sound), execute the following as root:

hwclock --show

This will show you your hardware clock on the server you are executing the command.

To synchronise your hardware clock with your system-time (which is managed by ntp), run the following command:

hwclock --systohc --utc

The last argument (--utc) tells hwclock to store the time in hardware clock in coordinated universal time.

Additionally, please keep in mind that man page for dmesg(1) say the following, so the behaviour you are experiencing is documented and valid:

   -T, --ctime
          Print human-readable timestamps.

          Be aware that the timestamp could be inaccurate!  The time
          source used for the logs is not updated after system
          SUSPEND/RESUME.
  • 1
    Thanks for your answer. But didn't work unfortunately... What i did is the following: root@spool:~# hwclock --show Mon Feb 17 20:30:14 2014 -0.985068 seconds root@spool:~# hwclock --systohc --utc root@spool:~# echo TEST > /dev/kmsg root@spool:~# dmesg -T | tail -1 [Mon Feb 17 13:50:14 2014] TEST root@spool:~# date Mon Feb 17 20:30:46 CET 2014 – g00gle Feb 17 '14 at 19:31
  • Well, dmesg -T does not guarantee the correctness of the timestamp (according to documentation), so use a proper logging daemon (e.g. klogd) and you will get correct timestamps for kernel messages. – galaxy Feb 17 '14 at 20:01
  • 1
    So there is no solution for the wrong timestamps in dmesg ? – g00gle Feb 18 '14 at 9:16
  • AFAIK, no, there is not. Moreover, this -T option to dmesg is quite a recent addition (by Debian?) and the majority of Linux distros don't know about such an option. Why it's a deal breaker for you? I've provided a solution re: how to get proper timestamps for kernel messages (i.e. klogd). – galaxy Feb 18 '14 at 9:36
  • 1
    I have the same issue on my server and can definitely rule out that the machine was ever Suspended/Resumed. Is there any other reason why the timestamp may be off? (ntp and hardware time are correct and have always been) – Daywalker Mar 30 '18 at 9:51
8

dmesg just prints the kernel ringbuffer which logs messages with uptime in seconds from being started as timestamp.

So if you use the -T option all this uptime values are just added to the date your system was booted. If you had times sleeping in suspend or resume, they are lost, so in this cases -T option is not useful, as date/time values are not right then and back in past.

0

To get accurate times for "recent" entries in dmesg, you could convert the dmesg timestamps to real time with some hacking of the output.

By "recent", I mean times after the last suspend/resume, since (as others already pointed out) suspend times are not counted in the dmesg timestamp.

But if you need it often, like on a notebook, you could put something like the following into functions or aliases:

# write current time to kernel ring buffer
echo "timecheck: $(date +%s) = $(date +%F_%T)" | sudo tee /dev/kmsg

# use our "timecheck" entry to get the difference
# between the dmesg timestamp and real time
offset=$(dmesg | grep timecheck | tail -1 \
| perl -nle '($t1,$t2)=/^.(\d+)\S+ timecheck: (\d+)/; print $t2-$t1')

# pipe dmesg output through a Perl snippet to
# convert it's timestamp to correct readable times
dmesg | tail \
| perl -pe 'BEGIN{$offset=shift} s/^\[(\d+)\S+/localtime($1+$offset)/e' $offset

Sample output:

...
Sat Jun 29 11:12:28 2019 wlp3s0: Limiting TX power to 30 (30 - 0) dBm as advertised by 10:5a:f7:53:1d:0f
Sat Jun 29 11:12:28 2019 IPv6: ADDRCONF(NETDEV_CHANGE): wlp3s0: link becomes ready
Sat Jun 29 11:34:16 2019 timecheck: 1561800856 = 2019-06-29_11:34:16
Sat Jun 29 12:10:11 2019 wlp3s0: cannot understand ECSA IE operating class, 5, ignoring

Compared to original dmesg output (which is off by 3 days):

$ dmesg | tail -4
[249424.746958] wlp3s0: Limiting TX power to 30 (30 - 0) dBm as advertised by 10:5a:f7:53:1d:0f
[249424.749662] IPv6: ADDRCONF(NETDEV_CHANGE): wlp3s0: link becomes ready
[250732.318826] timecheck: 1561800856 = 2019-06-29_11:34:16
[252887.828699] wlp3s0: cannot understand ECSA IE operating class, 5, ignoring

$ dmesg -T | tail -4
[Wed Jun 26 17:59:09 2019] wlp3s0: Limiting TX power to 30 (30 - 0) dBm as advertised by 10:5a:f7:53:1d:0f
[Wed Jun 26 17:59:09 2019] IPv6: ADDRCONF(NETDEV_CHANGE): wlp3s0: link becomes ready
[Wed Jun 26 18:20:57 2019] timecheck: 1561800856 = 2019-06-29_11:34:16
[Wed Jun 26 18:56:52 2019] wlp3s0: cannot understand ECSA IE operating class, 5, ignoring

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.