nov 132011
 

Dopo l’aggiornamento a Ubuntu 11,10 la mia wireless va su e giù, e così sto cercando di eseguire un debug di questo problema guardando dmesg.

Ma questo mi ha portato ad un altro piccolo fastidio, dmesg stampa gli orari in forma di secondi.nanosecondi dall’avvio del sistema. E no, non sembra esserci alcuna opzione -h per renderlo più leggibile. Così si dovrebbe verificare il tempo di avvio e fare qualche calcolo per vedere dove gli eventi registrati sono accaduti.

Questo non mi sembra così utile!
Vediamo come avere queste informazioni in un formato migliore.


In primo luogo una introduzione molto breve a dmesg, dalla pagina man:

dmesg è usato per esaminare o controllare il ring buffer del kernel.

In breve, dando il comando dmesg da terminale si può vedere il messaggio di avvio o qualsiasi messaggio riguardante il kernel mentre il sistema è in esecuzione. Ma ora torniamo ai log.

Debian and Ubuntu

Mentre cercavo in rete per una soluzione ho scoperto che per queste distribuzioni c’è un modo semplice per risolvere il problema, invece di utilizzare il comando dmesg basta controllare il file /var/log/kern.log

Aprendolo potrete vedere delle voci di log come le mie, con la data ben formattata:

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)

Quindi problema risolto su queste distribuzioni.

Fedora, CentOS e tutte le altre

Ok, quindi la vostra distribuzione non usa /var/log/kern.log e così le linee mostrate da dmesg sono simili a queste:

[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)

Ho trovato 2 soluzioni per analizzare l’output di dmesg e renderlo leggibile una in Perl ed una in Python.

Ecco la soluzione 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";

Basta copiare e incollare queste righe in un file, renderlo eseguibile e lanciarlo, avrete l’output di dmesg , ma con un formato di ora leggibile :

[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)


E se preferito il linguaggio Python ecco un’altra soluzione :

#!/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()

Copiata ed incollate questo codice o scaricatelo da qua.
Eseguite lo script e ancora una volta si otterrà il risultato che vogliamo:

[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)

Conclusioni

Sembra che il mio problema sia legato ad apparmor ed a qualche configurazione mancante per wicd , così, al momento ho aggiungere in /etc/apparmor.d/sbin.dhclient una voce:

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

E fatto ripartire apparmor, vediamo se questo funziona.

Popular Posts:

flattr this!

  21 Responses to “Come rendere gli orari di dmesg leggibili”

  1. dmesg -T works for me..

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

    #dmesg -T
    dmesg: invalid option -- 'T'
    Usage: dmesg [-c] [-n level] [-r] [-s bufsize]
    
  3. alias dmsg_human = dmesg|perl -ne ‘BEGIN{$a= time()- qx!cat /proc/uptime!};s/\[(\d+)\.\d+\]/localtime($1 + $a)/e; print $_;’

  4. 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 ;”‘

    • *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

  5. 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 \$_;”‘

  6. 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.)

  7. 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.

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

  9. 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

    • 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?

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

        • 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

  10. dmesg –help

    -T, –ctime show human readable timestamp (could be
    inaccurate if you have used SUSPEND/RESUME)

    • dmesg: invalid option — ‘T’
      Usage: dmesg [-c] [-n level] [-r] [-s bufsize]

      OS=SLES11.2 (kernel 3.0.13-0.27-pae)

  11. Thanks for the post and the examples. This put me on track to write a quick executable in PHP that you can run as a command:

    #!/usr/bin/php
    <?php

    $cmd = '/bin/dmesg';
    $now = time();
    $uptime = shell_exec('/bin/cat /proc/uptime | cut -d\' \' -f1');

    $boot = $now – $uptime;

    print "BOOT TIME: ".date("l, F jS, Y g:i a", $boot)."\n\n";

    foreach ( explode("\n",shell_exec($cmd)) as $l )
    {
    print preg_replace_callback(
    ':\[([\s\d\.]+)\]:',
    function ( $m ) {
    global $boot;
    return '['. date("D M j Y g:ia", $boot + $m[1]) .']';
    },
    $l,
    1) .
    "\n";
    }

 Leave a Reply

(required)

(required)


*

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>