How to make dmesg timestamp human readable

 Article, Howto  Add comments
Nov 132011
 

After the update to Ubuntu 11.10 my wireless goes up and down, and so i’m trying to debug this problem looking into dmesg.

But this brought me to another small issue, dmesg prints timestamps in the form of seconds.nanoseconds since the system booted. And no, there seems to be no -h option to make it human readable. so you should check your boot time and make some calculations to see where the events logged are happened.

This don’t seem so useful !
Let’s see how to have these information in a better format.



First a really short introduction to dmesg, from the man page:

dmesg is used to examine or control the kernel ring buffer.

In short, giving the command dmesg from a terminal you can see the boot message or any message regarding the kernel while your system is running. And now back on the logs.

Debian and Ubuntu

While I was looking around for a solution i’ve discovered that for these distributions there is an easy way to solve the problem, instead of using the command dmesg just check the file /var/log/kern.log

There you’ll see entry like mine, with the date nicely formatted:

Nov 13 18:37:19 xubuntu-home kernel: [14850.508867] airo(eth1): link lost (missed beacons)
Nov 13 18:38:29 xubuntu-home kernel: [14920.467041] airo(eth1): link lost (missed beacons)
Nov 13 18:38:44 xubuntu-home kernel: [14935.605833] ADDRCONF(NETDEV_UP): eth0: link is not ready
Nov 13 18:38:53 xubuntu-home kernel: [14943.868439] ADDRCONF(NETDEV_UP): eth0: link is not ready
Nov 13 18:39:03 xubuntu-home kernel: [14954.592045] eth1: no IPv6 routers present
Nov 13 18:39:08 xubuntu-home kernel: [14958.742806] type=1400 audit(1321205948.113:29): apparmor="DENIED" operation="open" parent=13015 profile="/sbin/dhclient" name="/var/lib/wicd/dhclient.conf" pid=13067 comm="dhclient" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Nov 13 19:22:46 xubuntu-home kernel: [17577.082369] airo(eth1): link lost (missed beacons)

So, problem solved on these distributions.

Fedora, CentOS and all the others

Ok, so your distribution don’t use /var/log/kern.log and so your dmesg show lines like these:

[14614.647880] airo(eth1): link lost (missed beacons)
[14850.508867] airo(eth1): link lost (missed beacons)
[14920.467041] airo(eth1): link lost (missed beacons)
[14935.605833] ADDRCONF(NETDEV_UP): eth0: link is not ready
[14943.868439] ADDRCONF(NETDEV_UP): eth0: link is not ready
[14954.592045] eth1: no IPv6 routers present
[14958.742806] type=1400 audit(1321205948.113:29): apparmor="DENIED" operation="open" parent=13015 profile="/sbin/dhclient" name="/var/lib/wicd/dhclient.conf" pid=13067 comm="dhclient" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
[17577.082369] airo(eth1): link lost (missed beacons)

I’ve found 2 solutions to parse the dmesg output and have it human readable one in Perl and one in Python.

This is the solution in perl:

#!/usr/bin/perl
 
use strict;
use warnings;
 
my @dmesg_new = ();
my $dmesg = "/bin/dmesg";
my @dmesg_old = `$dmesg`;
my $now = time();
my $uptime = `cat /proc/uptime | cut -d"." -f1`;
my $t_now = $now - $uptime;
 
sub format_time {
 my @time = localtime $_[0];
 $time[4]+=1;    # Adjust Month
 $time[5]+=1900;    # Adjust Year
 return sprintf '%4i-%02i-%02i %02i:%02i:%02i', @time[reverse 0..5];
}
 
foreach my $line ( @dmesg_old )
{
 chomp( $line );
 if( $line =~ m/\[\s*(\d+)\.(\d+)\](.*)/i )
 {
 # now - uptime + sekunden
 my $t_time = format_time( $t_now + $1 );
 push( @dmesg_new , "[$t_time] $3" );
 }
}
 
print join( "\n", @dmesg_new );
print "\n";

Just copy and paste these lines in a file, make it executable and run it, you’ll have the dmesg output but with an human readable time format:

[2011-11-13 16:57:10]  airo(eth1): link lost (missed beacons)
[2011-11-13 16:57:34]  ADDRCONF(NETDEV_UP): eth0: link is not ready
[2011-11-13 16:57:50]  eth1: no IPv6 routers present
[2011-11-13 17:01:22]  ADDRCONF(NETDEV_UP): eth0: link is not ready
[2011-11-13 17:01:33]  eth1: no IPv6 routers present
[2011-11-13 17:02:04]  ADDRCONF(NETDEV_UP): eth0: link is not ready
[2011-11-13 17:04:47]  ADDRCONF(NETDEV_UP): eth0: link is not ready
[2011-11-13 17:04:54]  type=1400 audit(1321200294.812:28): apparmor="DENIED" operation="open" parent=9097 profile="/sbin/dhclient" name="/var/lib/wicd/dhclient.conf" pid=9139 comm="dhclient" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
[2011-11-13 17:04:58]  eth1: no IPv6 routers present
[2011-11-13 17:08:16]  airo(eth1): link lost (missed beacons)


And if you prefer python this is a solution for this language:

#!/usr/bin/env python
# coding=utf8
 
# Copyright (C) 2010 Saúl ibarra Corretgé <[email protected]>
#
 
"""
pydmesg: dmesg with human-readable timestamps
"""
 
from __future__ import with_statement
 
import re
import subprocess
import sys
 
from datetime import datetime, timedelta
 
_datetime_format = "%Y-%m-%d %H:%M:%S"
_dmesg_line_regex = re.compile("^\[(?P<time>\d+\.\d+)\](?P<line>.*)$")
 
def exec_process(cmdline, silent, input=None, **kwargs):
    """Execute a subprocess and returns the returncode, stdout buffer and stderr buffer.
       Optionally prints stdout and stderr while running."""
    try:
        sub = subprocess.Popen(cmdline, stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.PIPE, **kwargs)
        stdout, stderr = sub.communicate(input=input)
        returncode = sub.returncode
        if not silent:
            sys.stdout.write(stdout)
            sys.stderr.write(stderr)
    except OSError,e:
        if e.errno == 2:
            raise RuntimeError('"%s" is not present on this system' % cmdline[0])
        else:
            raise
    if returncode != 0:
        raise RuntimeError('Got return value %d while executing "%s", stderr output was:\n%s' % (returncode, " ".join(cmdline), stderr.rstrip("\n")))
    return stdout
 
def human_dmesg():
    now = datetime.now()
    uptime_diff = None
    try:
        with open('/proc/uptime') as f:
            uptime_diff = f.read().strip().split()[0]
    except IndexError:
        return
    else:
        try:
            uptime = now - timedelta(seconds=int(uptime_diff.split('.')[0]), microseconds=int(uptime_diff.split('.')[1]))
        except IndexError:
            return
 
    dmesg_data = exec_process(['dmesg'], True)
    for line in dmesg_data.split('\n'):
        if not line:
            continue
        match = _dmesg_line_regex.match(line)
        if match:
            try:
                seconds = int(match.groupdict().get('time', '').split('.')[0])
                nanoseconds = int(match.groupdict().get('time', '').split('.')[1])
                microseconds = int(round(nanoseconds * 0.001))
                line = match.groupdict().get('line', '')
                t = uptime + timedelta(seconds=seconds, microseconds=microseconds)
            except IndexError:
                pass
            else:
                print "[%s]%s" % (t.strftime(_datetime_format), line)
 
if __name__ == '__main__':
    human_dmesg()

Copy and paste or download the code from here.
Run the script and once again you’ll get the result that we want:

[2011-11-13 18:37:19] airo(eth1): link lost (missed beacons)
[2011-11-13 18:38:29] airo(eth1): link lost (missed beacons)
[2011-11-13 18:38:44] ADDRCONF(NETDEV_UP): eth0: link is not ready
[2011-11-13 18:38:52] ADDRCONF(NETDEV_UP): eth0: link is not ready
[2011-11-13 18:39:03] eth1: no IPv6 routers present
[2011-11-13 18:39:07] type=1400 audit(1321205948.113:29): apparmor="DENIED" operation="open" parent=13015 profile="/sbin/dhclient" name="/var/lib/wicd/dhclient.conf" pid=13067 comm="dhclient" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
[2011-11-13 19:22:46] airo(eth1): link lost (missed beacons)

Conclusions

It seem my problem is related to apparmor and some configuration missing for wicd, so at the moment i’ve add in /etc/apparmor.d/sbin.dhclient an entry:

# wicd
  /var/lib/wicd/* r,

And restarted apparmor, let’s see if this works out.

Popular Posts:

flattr this!

  18 Responses to “How to make dmesg timestamp human readable”

  1. jason says:
    11/14/2011 at 06:59

    dmesg -T works for me..

    Reply
  2. linuxari says:
    11/14/2011 at 10:11

    Not for me, which version/OS are you using ?

    #dmesg -T
dmesg: invalid option -- 'T'
Usage: dmesg [-c] [-n level] [-r] [-s bufsize]
    Reply
  3. Holger Müller says:
    11/14/2011 at 10:43

    alias dmsg_human = dmesg|perl -ne ‘BEGIN{$a= time()- qx!cat /proc/uptime!};s/\[(\d+)\.\d+\]/localtime($1 + $a)/e; print $_;’

    Reply
  4. Holger Müller says:
    11/14/2011 at 10:55

    Sorry for wrong escaping ;-)
    alias dmsg_human=’dmesg|perl -ne “BEGIN{\$a= time()- qx!cat /proc/uptime!};s/\[(\d+)\.\d+\]/localtime(\$1 + \$a)/e; print ;”‘

    Reply
    • Holger Müller says:
      11/14/2011 at 11:06

      *grrr* even one more copy glitch
      alias dmsg_human=”dmesg|perl -ne \”BEGIN{\\\$a= time()- qx{cat /proc/uptime}};s/\[(\d+)\.\d+\]/localtime(\\\$1 + \\\$a)/e; print \\\$_;\”"

      this should work at least.
      Perhaps someone can drop the wrong quouted ones.

      Explanation for perl-dummies ;-)

      # use program code from argument line and make an implicit loop to read in stdin.
      perl -ne ‘
      # the BEGIN block is executed only once and directly after perl startup.
      BEGIN{
      # calculate the timestamp of systems startup
      $a= time()- qx{cat /proc/uptime}
      };
      # now for every line
      # substitute the integer part of dmsg timestamp with a human readable value
      s/\[(\d+)\.\d+\]/localtime($1 + $a)/e;
      # and print it out
      print;
      ‘

      that’s it

      Reply
  5. dothebart says:
    11/14/2011 at 11:30

    its missing to ignore the blanks in front of lower numbers..
    alias tmesg=’dmesg|perl -ne “BEGIN{\$a= time()- qx!cat /proc/uptime!};s/\[\s*(\d+)\.\d+\]/localtime(\$1 + \$a)/e; print \$_;”‘

    Reply
  6. piR says:
    01/26/2012 at 11:54

    Because you want to keep the arguments you passed, like dmesg -s 65535, in the perl program you just to adapt this line

    my $dmesg = “/bin/dmesg @ARGV”;

    (By the way, there is a not so user-friendly error about the captcha because i waited too long between the page load and the comment posting.)

    Reply
  7. piR says:
    01/30/2012 at 15:12

    There is an error in the python program, there is < and > instead of .

    Plus, i would say that both of the program (perl and python) don’t display an accurate time, i have a ten minute delay here.

    Reply
  8. Andreas Papadopoulos says:
    02/09/2013 at 15:11

    Great post.
    dmesg -T works for me two.
    I suggest you update the post and add a note to the first line about this.

    Reply
  9. Gaspar Fernandez says:
    02/10/2013 at 10:06

    Also in bash version:
    base=$(cat /proc/uptime | cut -d ‘.’ -f1); seconds=`date +%s`; dmesg | sed ‘s/^\[\(.*\)\..*\]\(.*\)$/\1\n\2/’ | while read first; do read second; first=`date +”%d/%m/%Y %H:%M:%S” –date=”@$(($seconds – $base + $first))”`; echo “[$first] $second”; done

    Reply
    • JanT says:
      03/11/2013 at 10:18

      Your bash one-liner looks quite handy. Unfortunately, I am getting these errors:

      -bash: -date=@1362748064: command not found

      Do you happen to know how I can create the Unicode 2013 character before “date” in the segment (…)–date=”@(…), or replace it with something else?

      Reply
      • Gaspar Fernández says:
        03/12/2013 at 00:23

        I think some characters where translated by the comment system. I hope this works: http://pastebin.com/rWRc8BvQ

        Reply
        • JanT says:
          03/12/2013 at 10:25

          Yes that works fine, thank you!
          However, the one-liner does not work sometimes. For example:

          original output from dmesg:
          [ 10.097099] e1000 0000:00:03.0: PCI INT A -> Link[LNKC] -> GSI 11 (level, high) -> IRQ 11

          filtered output:
          -bash: 1363079793 – 73723 + 10.097099] e1000 0000:00:03: syntax error: invalid arithmetic operator (error token is “.097099] e1000 0000:00:03″)
          [] -> GSI 11 (level, high) -> IRQ 11

          Reply

 Leave a Reply

(required)

(required)

CAPTCHA Image

*

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>