Examinar mensajes de log del kernel Linux con dmesg

Detalles

En los sistemas operativos Linux, el comando dmesg examina y controla el ring buffer del kernel.

El ring buffer del kernel es una estructura de datos que registra los mensajes relacionados a la operación del kernel Linux. Es como una especie de log del kernel, salvo que al ser un buffer, su tamaño es constante y funciona como una anillo (una vez que se llena se sobrescriben los mensajes viejos con los nuevos entrantes).

En el ring buffer típicamente se registran mensajes relacionados al hardware, memoria, CPU y dispositivos. Cabe destacar que no es una característica específica del kernel Linux, sino que es común a todos los sistemas operativos de la familia Unix.

La herramienta dmesg permite examinar el contenido del ring buffer del kernel.

root@hal9000:/home/emi# dmesg | tail
[   73.022847] elogind[1873]: New session 1 of user emi.
[10642.764038] usb 1-5: USB disconnect, device number 2
[10643.072887] usb 1-5: new low-speed USB device number 4 using xhci_hcd
[10643.224726] usb 1-5: New USB device found, idVendor=046d, idProduct=c077, bcdDevice=72.00
[10643.224730] usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[10643.224733] usb 1-5: Product: USB Optical Mouse
[10643.224736] usb 1-5: Manufacturer: Logitech
[10643.227800] input: Logitech USB Optical Mouse as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/0003:046D:C077.0004/input/input22
[10643.228293] hid-generic 0003:046D:C077.0004: input,hidraw0: USB HID v1.11 Mouse [Logitech USB Optical Mouse] on usb-0000:00:14.0-5/input0
[20370.273989] perf: interrupt took too long (2502 > 2500), lowering kernel.perf_event_max_sample_rate to 79750

Por defecto muestra todos los mensajes en el buffer, por ello típicamente resulta práctico filtrar la salida con grep para buscar mensajes específicos. Por ejemplo:

root@hal9000:/home/emi# dmesg | grep file
[    5.543747] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
[   10.859878] EXT4-fs (sda4): mounted filesystem with ordered data mode. Opts: (null)
[   10.916167] EXT4-fs (sda3): mounted filesystem with ordered data mode. Opts: (null)

dmesg lee el ring buffer del kernel Linux desde el dispositivo /dev/kmsg. Sin embargo es capaz de leer desde cualquier archivo (mediante la opción -F) o desde la interfaz del kernel de syslog (-S). Esto permite leer mensajes del kernel de encendidos previos:

root@hal9000:/home/emi# dmesg -F /var/log/dmesg.0 | tail
               [    7.892517] input: HDA Intel PCH HDMI/DP,pcm=10 as /devices/pci0000:00/0000:00:1f.3/sound/card0/input21
               [    9.047393] Adding 7812092k swap on /dev/sda2.  Priority:-2 extents:1 across:7812092k FS
               [    9.112253] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro
               [   10.167842] lp0: using parport0 (interrupt-driven).
               [   10.397027] EXT4-fs (sda4): mounted filesystem with ordered data mode. Opts: (null)
               [   10.452206] EXT4-fs (sda3): mounted filesystem with ordered data mode. Opts: (null)
               [   11.102401] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
               [   13.928757] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
               [   13.928898] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
               [   24.112772] Process accounting resumed

Tener en cuenta que un ring buffer se mantiene durante todo el uptime. Por ejemplo en mi estación de trabajo:

root@hal9000:/home/emi# ll /var/log/dmesg*
-rw-r----- 1 root adm 48445 Oct 25 07:24 /var/log/dmesg
-rw-r----- 1 root adm 48461 Oct 24 07:19 /var/log/dmesg.0
-rw-r----- 1 root adm 14050 Oct 23 09:56 /var/log/dmesg.1.gz
-rw-r----- 1 root adm 14062 Oct 23 07:30 /var/log/dmesg.2.gz
-rw-r----- 1 root adm 14093 Oct 22 07:25 /var/log/dmesg.3.gz
-rw-r----- 1 root adm 14048 Oct 21 07:13 /var/log/dmesg.4.gz

Lógicamente éstos son los archivos de log generados por syslog y no funcionan en modo ring, sino que todos los mensajes generados por el kernel persisten.

El dispositivo /dev/kmesg retorna datos crudos, en cambio syslog utiliza un formato en particular. Es posible leer directamente el dispositivo /dev/kmesg con el siguiente comando:

# dd if=/dev/kmsg iflag=nonblock

Por ejemplo:

root@hal9000:/home/emi# dd if=/dev/kmsg iflag=nonblock | head
5,0,0,-;Linux version 4.19.0-0.bpo.5-amd64 (debian-kernel@lists.debian.org) (gcc version 6.3.0 20170516 (Debian 6.3.0-18+deb9u1)) #1 SMP Debian 4.19.37-5+deb10u2~bpo9+1 (2019-08-16)
6,1,0,-;Command line: BOOT_IMAGE=/boot/vmlinuz-4.19.0-0.bpo.5-amd64 root=UUID=b8683b97-87b4-47b2-8e3e-1b31c3a9c8f7 ro noibrs noibpb nopti nospectre_v2 nospectre_v1 l1tf=off nospec_store_bypass_disable no_stf_barrier mds=off mitigations=off quiet
6,2,0,-;x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
6,3,0,-;x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
6,4,0,-;x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
6,5,0,-;x86/fpu: Supporting XSAVE feature 0x008: 'MPX bounds registers'
6,6,0,-;x86/fpu: Supporting XSAVE feature 0x010: 'MPX CSR'
6,7,0,-;x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
6,8,0,-;x86/fpu: xstate_offset[3]:  832, xstate_sizes[3]:   64
6,9,0,-;x86/fpu: xstate_offset[4]:  896, xstate_sizes[4]:   64

Sin embargo, por compatibilidad, dmesg retorna la información en el formato de syslog.

En los sistemas donde el dispositivo /dev/kmesg es legible (por ejemplo los kernels Linux a partir de la versión 3.5.0), la opción -w permite mantener la salida abierta esperando nuevos mensajes. Similar a lo que ocurre cuando se lanza tail con la opción follow.

Opciones de dmesg

Más allá del uso básico que se le pueda dar, dmesg tiene varias opciones interesantes, especialmente para el formato de la salida.

Por defecto dmesg muestra una estampilla de tiempo para cada entrada expresada en segundos relativos al momento de inicio del kernel. La opción -H permite mostrar la fecha y hora, con deltas entre mensajes consecutivos, en lugar de la estampilla de tiempo:

root@hal9000:/home/emi# dmesg -H | tail
[ +22.582416] elogind[1873]: New session 1 of user emi.
[Oct24 10:16] usb 1-5: USB disconnect, device number 2
[  +0.308849] usb 1-5: new low-speed USB device number 4 using xhci_hcd
[  +0.151839] usb 1-5: New USB device found, idVendor=046d, idProduct=c077, bcdDevice=72.00
[  +0.000004] usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  +0.000003] usb 1-5: Product: USB Optical Mouse
[  +0.000003] usb 1-5: Manufacturer: Logitech
[  +0.003064] input: Logitech USB Optical Mouse as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/0003:046D:C077.0004/input/input22
[  +0.000493] hid-generic 0003:046D:C077.0004: input,hidraw0: USB HID v1.11 Mouse [Logitech USB Optical Mouse] on usb-0000:00:14.0-5/input0
[Oct24 12:58] perf: interrupt took too long (2502 > 2500), lowering kernel.perf_event_max_sample_rate to 79750

-T es similar pero muestra la fecha en formato humano para cada mensaje:

root@hal9000:/home/emi# dmesg -T | tail
[Thu Oct 24 07:19:53 2019] elogind[1873]: New session 1 of user emi.
[Thu Oct 24 10:16:02 2019] usb 1-5: USB disconnect, device number 2
[Thu Oct 24 10:16:03 2019] usb 1-5: new low-speed USB device number 4 using xhci_hcd
[Thu Oct 24 10:16:03 2019] usb 1-5: New USB device found, idVendor=046d, idProduct=c077, bcdDevice=72.00
[Thu Oct 24 10:16:03 2019] usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[Thu Oct 24 10:16:03 2019] usb 1-5: Product: USB Optical Mouse
[Thu Oct 24 10:16:03 2019] usb 1-5: Manufacturer: Logitech
[Thu Oct 24 10:16:03 2019] input: Logitech USB Optical Mouse as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/0003:046D:C077.0004/input/input22
[Thu Oct 24 10:16:03 2019] hid-generic 0003:046D:C077.0004: input,hidraw0: USB HID v1.11 Mouse [Logitech USB Optical Mouse] on usb-0000:00:14.0-5/input0
[Thu Oct 24 12:58:10 2019] perf: interrupt took too long (2502 > 2500), lowering kernel.perf_event_max_sample_rate to 79750

No resulta práctica porque la unidad de tiempo es poco precisa.

Con -t directamente se suprimen las estampillas de tiempo:

root@hal9000:/home/emi# dmesg -t | tail
elogind[1873]: New session 1 of user emi.
usb 1-5: USB disconnect, device number 2
usb 1-5: new low-speed USB device number 4 using xhci_hcd
usb 1-5: New USB device found, idVendor=046d, idProduct=c077, bcdDevice=72.00
usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
usb 1-5: Product: USB Optical Mouse
usb 1-5: Manufacturer: Logitech
input: Logitech USB Optical Mouse as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/0003:046D:C077.0004/input/input22
hid-generic 0003:046D:C077.0004: input,hidraw0: USB HID v1.11 Mouse [Logitech USB Optical Mouse] on usb-0000:00:14.0-5/input0
perf: interrupt took too long (2502 > 2500), lowering kernel.perf_event_max_sample_rate to 79750

Puede ser de gran utilidad para simplificar el parseo de la salida con algún script.

-d muestra los deltas (diferencias de tiempo entre dos mensajes consecutivos) además de la estampilla:

root@hal9000:/home/emi# dmesg -d | tail
[   73.022847 <   22.582416>] elogind[1873]: New session 1 of user emi.
[10642.764038 <10569.741191>] usb 1-5: USB disconnect, device number 2
[10643.072887 <    0.308849>] usb 1-5: new low-speed USB device number 4 using xhci_hcd
[10643.224726 <    0.151839>] usb 1-5: New USB device found, idVendor=046d, idProduct=c077, bcdDevice=72.00
[10643.224730 <    0.000004>] usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[10643.224733 <    0.000003>] usb 1-5: Product: USB Optical Mouse
[10643.224736 <    0.000003>] usb 1-5: Manufacturer: Logitech
[10643.227800 <    0.003064>] input: Logitech USB Optical Mouse as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/0003:046D:C077.0004/input/input22
[10643.228293 <    0.000493>] hid-generic 0003:046D:C077.0004: input,hidraw0: USB HID v1.11 Mouse [Logitech USB Optical Mouse] on usb-0000:00:14.0-5/input0
[20370.273989 < 9727.045696>] perf: interrupt took too long (2502 > 2500), lowering kernel.perf_event_max_sample_rate to 79750

-e resulta similar a -H:

root@hal9000:/home/emi# dmesg -e | tail
[ +22.582416] elogind[1873]: New session 1 of user emi.
[Oct24 10:16] usb 1-5: USB disconnect, device number 2
[  +0.308849] usb 1-5: new low-speed USB device number 4 using xhci_hcd
[  +0.151839] usb 1-5: New USB device found, idVendor=046d, idProduct=c077, bcdDevice=72.00
[  +0.000004] usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  +0.000003] usb 1-5: Product: USB Optical Mouse
[  +0.000003] usb 1-5: Manufacturer: Logitech
[  +0.003064] input: Logitech USB Optical Mouse as /devices/pci0000:00/0000:00:14.0/usb1/1-5/1-5:1.0/0003:046D:C077.0004/input/input22
[  +0.000493] hid-generic 0003:046D:C077.0004: input,hidraw0: USB HID v1.11 Mouse [Logitech USB Optical Mouse] on usb-0000:00:14.0-5/input0
[Oct24 12:58] perf: interrupt took too long (2502 > 2500), lowering kernel.perf_event_max_sample_rate to 79750

Por último, es posible filtrar los mensajes por nivel utilizando --level:

root@hal9000:/home/emi# dmesg --level=err
[    7.450930] iTCO_wdt iTCO_wdt: can't request region for resource [mem 0x00c5fffc-0x00c5ffff]
[    7.718017] i915 0000:00:02.0: firmware: failed to load i915/kbl_dmc_ver1_04.bin (-2)
[    7.718020] firmware_class: See https://wiki.debian.org/Firmware for information about missing firmware
[    8.092412] [drm:intel_cpu_fifo_underrun_irq_handler [i915]] *ERROR* CPU pipe B FIFO underrun

Para listar los mensajes de error soportados, abrir la ayuda (no el manual) de dmesg ejecutando:

# dmesg --help

Los niveles de error soportados dependen del sistema. Por ejemplo en Linux 4.19 son los siguientes:

Supported log levels (priorities):
   emerg - system is unusable
   alert - action must be taken immediately
    crit - critical conditions
     err - error conditions
    warn - warning conditions
  notice - normal but significant condition
    info - informational
   debug - debug-level messages

Referencias

Compartí este artículo