18

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 ?

krisFR
  • 12,830
  • 3
  • 31
  • 40
g00gle
  • 313
  • 1
  • 2
  • 5
  • Are you sure your localtime file `/etc/localtime` is right? The `syslog` get time from localtime. – VictorLee Jun 13 '18 at 06:17
  • 2
    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 '19 at 11:11

4 Answers4

18

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.

JxO
  • 191
  • 1
  • 3
8

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.
galaxy
  • 1,974
  • 1
  • 13
  • 15
  • 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 09: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 09:36
  • Sounds like your problem could be correlated with this one: http://www.linuxquestions.org/questions/linux-newbie-8/syslog-time-wrong-but-date-returns-the-correct-time-700986/ – Pitt Nov 01 '16 at 14:42
  • klogd would remove rsyslog and ubuntuminimal? :/ – Aquarius Power Jun 19 '17 at 17:18
  • 2
    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 09:51
8

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 so it appears in dmesg output
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

# or use this instead to keep dmesg colors
dmesg --color=always | tail \
| perl -pe 'BEGIN{$offset=shift} s/^(\x1b\[.*?m)?\[(\d+)\S+/$1.localtime($2+$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
mivk
  • 3,457
  • 1
  • 34
  • 29
  • Brilliant, and exactly what I need for my laptop! :-) Is there a way to allow this to work with the --color=always option for dmesg, whilst still allowing the perl substitution (i.e. allowing for the colour codes)? – AstroFloyd Aug 23 '19 at 18:42
  • 1
    @AstroFloyd : yes. See alternative `dmesg` line with updated regex. – mivk Aug 24 '19 at 11:35
  • would upvote again if I could - thanks a lot! :-) – AstroFloyd Aug 25 '19 at 06:25
  • If replace the final commands with this: dmesg --color=always $@ \ | perl -pe 'BEGIN{$offset=shift} s/^(\x1b\[.*?m)?\[(\d+)\S+/$1.localtime($2+$offset)/e' $offset , it will allow us to: 1) get rid off blocking, as tail stops working, when we need to run all this in, say, "-w" (follow) mode; 2) $@ makes possible to pass cmd params, if we need it... As example, if name the script as dmesg-time-fix, we can run it as: dmesg-time-fix (will show all the output and finish) or dmesg-time-fix -w (will show everything and block, waiting for new messages). – Exterminator13 Mar 07 '21 at 08:46
4

Workaround is journalctl with -k, --dmesg. I am using -k as it is shorter:

journalctl -k

It will show only kernel messages and correct time.

To show only kernel lines matching phrase:

journalctl -kg phrase
16851556
  • 386
  • 2
  • 5
  • 18