Kernel Scripting – Human Readable dmesg Time Stamps on OpenWRT

bootdmesgkernelopenwrtscripting

The output of dmesg shows the number of second+milliseconds since the system start.

[   10.470000] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[   14.610000] device eth0 entered promiscuous mode
[   18.750000] cfg80211: Calling CRDA for country: DE
[   18.750000] cfg80211: Regulatory domain changed to country: DE

Q: How to put the seconds+milliseconds in to a readable format?

My dmesg:

root@OpenWrt:/tmp# dmesg -h
dmesg: invalid option -- h
BusyBox v1.19.4 (2013-03-14 11:28:31 UTC) multi-call binary.

Usage: dmesg [-c] [-n LEVEL] [-s SIZE]

Print or control the kernel ring buffer

    -c      Clear ring buffer after printing
    -n LEVEL    Set console logging level
    -s SIZE     Buffer size

To install util-Linux won't be possible, because there is not much available space:

root@OpenWrt:~# df -h
Filesystem                Size      Used Available Use% Mounted on
rootfs                    1.1M    956.0K    132.0K  88% /
/dev/root                 2.0M      2.0M         0 100% /rom
tmpfs                    14.3M    688.0K     13.6M   5% /tmp
tmpfs                   512.0K         0    512.0K   0% /dev
/dev/mtdblock3            1.1M    956.0K    132.0K  88% /overlay
overlayfs:/overlay        1.1M    956.0K    132.0K  88% /

root@OpenWrt:/tmp# which awk  perl sed bash sh shell tcsh
/usr/bin/awk
/bin/sed
/bin/sh


root@OpenWrt:~# date -h
date: invalid option -- h
BusyBox v1.19.4 (2013-03-14 11:28:31 UTC) multi-call binary.

Usage: date [OPTIONS] [+FMT] [TIME]

Display time (using +FMT), or set time

    [-s,--set] TIME Set time to TIME
    -u,--utc    Work in UTC (don't convert to local time)
    -R,--rfc-2822   Output RFC-2822 compliant date string
    -I[SPEC]    Output ISO-8601 compliant date string
            SPEC='date' (default) for date only,
            'hours', 'minutes', or 'seconds' for date and
            time to the indicated precision
    -r,--reference FILE Display last modification time of FILE
    -d,--date TIME  Display TIME, not 'now'
    -D FMT      Use FMT for -d TIME conversion
    -k      Set Kernel timezone from localtime and exit

Best Answer

I think that what you're looking for is -T as documented in man dmesg:

-T, --ctime

Print human readable timestamps. The timestamp could be inaccurate!

The time source used for the logs is not updated after system SUSPEND/RESUME.

So, for example:

[  518.511925] usb 2-1.1: new low-speed USB device number 7 using ehci-pci
[  518.615735] usb 2-1.1: New USB device found, idVendor=1c4f, idProduct=0002
[  518.615742] usb 2-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  518.615747] usb 2-1.1: Product: USB Keykoard

Becomes:

[Mon Jan 27 16:22:42 2014] hid-generic 0003:1C4F:0002.0007: input,hidraw0: USB HID v1.10 Keyboard [USB USB Keykoard] on usb-0000:00:1d.0-1.1/input0
[Mon Jan 27 16:22:42 2014] input: USB USB Keykoard as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.1/2-1.1:1.1/input/input24
[Mon Jan 27 16:22:42 2014] hid-generic 0003:1C4F:0002.0008: input,hidraw1: USB HID v1.10 Device [USB USB Keykoard] on usb-0000:00:1d.0-1.1/input1

I found a cool trick here. The sed expression used there was wrong since it would fail when there was more than one ] in the dmesg line. I have modified it to work with all cases I found in my own dmesg output. So, this should work assuming your date behaves as expected:

base=$(cut -d '.' -f1 /proc/uptime); 
seconds=$(date +%s); 
dmesg | sed 's/\]//;s/\[//;s/\([^.]\)\.\([^ ]*\)\(.*\)/\1\n\3/' | 
while read first; do 
  read second; 
  first=`date +"%d/%m/%Y %H:%M:%S" --date="@$(($seconds - $base + $first))"`;
  printf "[%s] %s\n" "$first" "$second"; 
done

Output looks like:

[27/01/2014 16:14:45] usb 2-1.1: new low-speed USB device number 7 using ehci-pci
[27/01/2014 16:14:45] usb 2-1.1: New USB device found, idVendor=1c4f, idProduct=0002
[27/01/2014 16:14:45] usb 2-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[27/01/2014 16:14:45] usb 2-1.1: Product: USB Keykoard

Related Solutions

How to read dmesg from previous session? (dmesg.0)

To clear up a fundamental misconception, dmesg does not read from /var/log/dmesg. It reads directly from the kernel ring buffer and gives you the most recent N messages. Towards the end of the boot process, dmesg is invoked to write the boot messages to /var/log/dmesg (with older versions of that file being rotated in the usual manner).

Once you have a syslog running (syslogd, rsyslogd, syslog-ng, etc.) it reads from the kernel buffer and writes to a file such as /var/log/kern.log. (This is for Debian; other systems will vary). Assuming your system was able to write to disk and flush the disk buffers before it crashed, that is where you will find the dying screams of the kernel.

On my Debian system the /var/log/kern.log file contains human-readable timestamps.

dmesg – Custom Time Format

Yes, you can, e.g. by re-formatting the time with gawk (GNU awk) like this:

dmesg --time-format iso | gawk '{ printf (strftime("+%F-%T",mktime(gensub("[-+T:,]"," ","g",$1)))) ; $1 = ""; print $0}'

dmesg prints iso dates here like this:

2019-09-02T06:10:30,708864+02:00 this is an important message

We strip the first string of special characters then use the mktime function in (g)awk to parse the string into a date, then strftime to format - use your favourite parameters.

This gives something like

+2019-09-02-06:10:30 this is an important message

Small notes:

We ignore the time zone here assuming this is obvious since we are running the command locally.
Please note that the time given by dmesg can be inaccurate (in fact, sometimes way off) if you suspend and then wake the computer due to the way timestamps are stored, see dmesg(1):
```
man 1 dmesg
```

Best Answer

Related Solutions

How to read dmesg from previous session? (dmesg.0)

dmesg – Custom Time Format

Related Question