Linux Embedded

Le blog des technologies libres et embarquées

HowTo

Une introduction à journald

Par le  •  pas de commentaire

Introduction

Mal connu, souvent décrié mais maintenant inévitable, journald est l'un des composants de systemd où le manque de connaissance est le plus regrettable.

Journald est la nouvelle infrastructure de gestion des logs introduite par le projet systemd. Jounald centralise l'ensemble des logs d'un système et gère de façon transparente les différentes sources. 

  • Les logs "traditionnels" provenant des appels syslog et de /dev/log
  • Les sorties standards des différents services (printf et autres mécanismes de trace)
  • Les logs noyau (/dev/kmsg, traditionnellement lus grâce à la commande dmesg)
  • Les logs d'audit du noyau lorsque ceux-ci sont activés
  • Les logs des différents conteneurs lorsque le gestionnaire de conteneur le supporte.

Dans cet article nous allons vous présenter quelques exemples "main dans le cambouis" d'utilisation de journald qui vous permettront de facilement retrouver vos marques et commencer à découvrir toute la puissance de cet outil comparé à un système de log traditionnel.

Quelques exemples d'utilisation

Afin de comprendre l'intérêt de journald nous allons présenter quelques exemples.

Récupération des logs noyau

Journald sait lire les logs noyau depuis /dev/kmsg. La commande suivante permet donc d'afficher les mêmes traces que dmesg.

$ journalctl -k

févr. 11 15:16:38 logrus kernel: microcode: microcode updated early to revision 0xea, date = 2021-01-06
févr. 11 15:16:38 logrus kernel: Linux version 5.15.0-3-amd64 (debian-kernel@lists.debian.org) (gcc-11 (Debian 11.2.0-14) 11.2.0, GNU ld (GNU Binutils >
févr. 11 15:16:38 logrus kernel: Command line: BOOT_IMAGE=/vmlinuz-5.15.0-3-amd64 root=/dev/mapper/logrus--vg-root ro quiet intel_idle.max_cstate=4 sys>
févr. 11 15:16:38 logrus kernel: x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
févr. 11 15:16:38 logrus kernel: x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
févr. 11 15:16:38 logrus kernel: x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
févr. 11 15:16:38 logrus kernel: x86/fpu: Supporting XSAVE feature 0x008: 'MPX bounds registers'
févr. 11 15:16:38 logrus kernel: x86/fpu: Supporting XSAVE feature 0x010: 'MPX CSR'
févr. 11 15:16:38 logrus kernel: x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
févr. 11 15:16:38 logrus kernel: x86/fpu: xstate_offset[3]:  832, xstate_sizes[3]:   64
févr. 11 15:16:38 logrus kernel: x86/fpu: xstate_offset[4]:  896, xstate_sizes[4]:   64
févr. 11 15:16:38 logrus kernel: x86/fpu: Enabled xstate features 0x1f, context size is 960 bytes, using 'compacted' format.
févr. 11 15:16:38 logrus kernel: signal: max sigframe size: 2032
févr. 11 15:16:38 logrus kernel: BIOS-provided physical RAM map:
févr. 11 15:16:38 logrus kernel: BIOS-e820: [mem 0x0000000000000000-0x0000000000057fff] usable

[...]

Le format n'est pas exactement identique à celui de dmesg, mais les logs sont là. En passant par journald, nous avons quelques bénéfices supplémentaires :

  • Les messages sont sauvegardés avec les autres sources de logs. En particulier les timestamps sont identiques et les messages sont correctement ordonnés
  • Les messages peuvent être filtrés par priorité (option -p) selon l'échelle traditionelle syslog : "emerg" (0), "alert" (1), "crit" (2), "err" (3), "warning" (4), "notice" (5), "info" (6), "debug" (7)

Pour récupérer uniquement les erreurs du noyau, nous avons donc la commande suivante :

$ journalctl -k -p 3

févr. 11 15:16:41 logrus kernel: i915 0000:00:02.0: [drm] *ERROR* DPLL 1 not locked
févr. 14 09:27:21 logrus kernel: Bluetooth: hci0: Reading supported features failed (-16)
févr. 14 17:24:53 logrus kernel: i915 0000:00:02.0: [drm] *ERROR* DPLL 1 not locked
févr. 15 08:04:02 logrus kernel: r8152 2-1.3:1.0: firmware: failed to load rtl_nic/rtl8153a-4.fw (-2)
févr. 15 08:04:02 logrus kernel: firmware_class: See https://wiki.debian.org/Firmware for information about missing firmware
févr. 15 08:04:02 logrus kernel: Bluetooth: hci0: Reading supported features failed (-16)
févr. 15 08:04:03 logrus kernel: hid-generic 0003:0D8C:0134.000D: No inputs registered, leaving
févr. 15 08:04:15 logrus kernel: hid-generic 0003:0D8C:0134.0012: No inputs registered, leaving
févr. 16 06:37:12 logrus kernel: i915 0000:00:02.0: [drm] *ERROR* failed to enable link training
févr. 16 06:37:12 logrus kernel: Bluetooth: hci0: Reading supported features failed (-16)
févr. 16 09:29:26 logrus kernel: Bluetooth: hci0: Reading supported features failed (-16)
févr. 16 18:08:19 logrus kernel: Bluetooth: hci0: Reading supported features failed (-16)
févr. 17 08:03:03 logrus kernel: r8152 2-1.3:1.0: firmware: failed to load rtl_nic/rtl8153a-4.fw (-2)
févr. 17 08:03:04 logrus kernel: Bluetooth: hci0: Reading supported features failed (-16)
févr. 17 08:03:05 logrus kernel: hid-generic 0003:0D8C:0134.001A: No inputs registered, leaving

[..]

 

Suivre les logs de plusieurs services

Il est assez courant de vouloir suivre les logs au fur et à mesure de leur génération. Lorsqu'on débogue des interactions entre plusieurs daemons, on souhaite également ne voir que les traces des unités systemd qui nous intéressent.

$ journalctl -u bluetooth.service -u systemd-udevd.service -f

févr. 11 15:16:38 logrus systemd[1]: Starting Rule-based Manager for Device Events and Files...
févr. 11 15:16:39 logrus systemd[1]: Started Rule-based Manager for Device Events and Files.
févr. 11 15:16:39 logrus mtp-probe[459]: checking bus 1, device 5: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-10"
févr. 11 15:16:39 logrus mtp-probe[460]: checking bus 1, device 3: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-5"
févr. 11 15:16:39 logrus mtp-probe[460]: bus: 1, device: 3 was not an MTP device
févr. 11 15:16:39 logrus mtp-probe[462]: checking bus 1, device 2: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-3"
févr. 11 15:16:39 logrus mtp-probe[462]: bus: 1, device: 2 was not an MTP device
févr. 11 15:16:39 logrus mtp-probe[459]: bus: 1, device: 5 was not an MTP device
févr. 11 15:16:39 logrus systemd-udevd[415]: Using default interface naming scheme 'v250'.
févr. 11 15:16:40 logrus systemd-udevd[413]: Using default interface naming scheme 'v250'.
févr. 11 15:16:41 logrus systemd[1]: Starting Bluetooth service...
févr. 11 15:16:41 logrus bluetoothd[736]: Bluetooth daemon 5.62
févr. 11 15:16:41 logrus systemd[1]: Started Bluetooth service.
févr. 11 15:16:41 logrus bluetoothd[736]: Starting SDP server
févr. 11 15:16:41 logrus bluetoothd[736]: Bluetooth management interface 1.21 initialized
févr. 11 15:16:41 logrus bluetoothd[736]: profiles/sap/server.c:sap_server_register() Sap driver initialization failed.
févr. 11 15:16:41 logrus bluetoothd[736]: sap-server: Operation not permitted (1)
févr. 11 15:16:52 logrus systemd-udevd[1041]: vboxdrvu: /usr/lib/udev/rules.d/60-virtualbox-dkms.rules:2 Only network interfaces can be renamed, ignoring NAME="vboxdrvu".
févr. 11 15:16:52 logrus systemd-udevd[996]: vboxdrv: /usr/lib/udev/rules.d/60-virtualbox-dkms.rules:1 Only network in

Quelques notes sur cette commande :

  • L'option -f fait que journalctl ne rend pas la main lorsqu'il atteint la fin des logs mais bloque en attendant de nouveaux logs qu'il affichera au fur et à mesure
  • Nous voyons des traces de différentes sources :
    • bluetoothd, le programme principal de l'unité bluetooth.service
    • systemd-udevd, le programme principal de l'unité  systemd-udevd.service
    • mtp-probe, un programme démarré par le daemon udev, mais qui n'est pas le programme principal.
    • systemd, mais uniquement les messages qui concernent les unités que nous avons sélectionnées.
  • Ce n'est pas visible ici, mais les timestamps des messages (et donc leur ordre) sont basés sur ceux du kernel. L'ordre des messages est donc fiable.

Changer le format de sortie

Par défaut, les informations affichées par journalctl sont très similaires à celles que l'on obtient d'un fichier de log classique. Cependant, journald sauvegarde beaucoup plus d'informations que ça.

Générons un message et commençons par l'afficher avec tous les détails.

$ logger -p local0.3 -i --id=1 message de test
$ journalctl --facility=local0 -o verbose


Wed 2022-03-09 11:07:09.373580 CET [s=94e13f7bca824c1192e413d758f8882c;i=58e33;b=d56cd947e79841eba251133d2ed810d1;m=9a308c9d5e;t=5d9c642b3a15a;x=5779660f2e08be16]
    _TRANSPORT=syslog
    _UID=1000
    _GID=1000
    _BOOT_ID=d56cd947e79841eba251133d2ed810d1
    _MACHINE_ID=9e7936dad17a4aef95023a89630fc999
    _HOSTNAME=logrus
    PRIORITY=3
    SYSLOG_IDENTIFIER=jerros
    SYSLOG_PID=1
    _COMM=logger
    SYSLOG_FACILITY=16
    SYSLOG_TIMESTAMP=Mar  9 11:07:09 
    MESSAGE=message de test
    _PID=232899
    _SOURCE_REALTIME_TIMESTAMP=1646820429373580

La commande logger nous permet d'écrire dans le syslog :

  • En utilisant une priorité de 3
  • En utilisant la facility syslog local0 (pour nous permettre de retrouver notre message facilement avec journalctl)
  • En prétendant que le message vienne de systemd (PID 1)

L'option -o verbose de journalctl nous permet d'afficher les détails.

  • La première ligne est une clé unique (le curseur) permettant d'identifier le message.
  • Journald stocke ses messages comme des structures clé/valeur
  • Le champ MESSAGE est le texte de notre message
  • Les clés dont le nom commence par un underscore n'ont pas été fournies par le client mais déduites par systemd (en interrogeant le noyau) et sont donc garanties correctes
  • Tous les champs d'un syslog traditionnel sont là. Ils ne sont pas considérés comme fiable car fournis par l'application
  • On observe, en particulier que le SYSLOG_PID vaut 1 (logger a indiqué que son PID était 1 au daemon syslog) mais systemd a vérifé et a constaté la différence (le champ _PID vaut 232899)

L'ensemble des champs connus sont documentés dans man:systemd.journal-fields(7) mais c'est un format ouvert et les applications peuvent ajouter leurs propres champs.

Il existe de nombreux formats de sortie, permettant de choisir le format de la date (format ISO, temps UNIX, UTC...), de générer du JSON (en sélectionnant les champs lisibles ou sur une seule ligne, au format Server-Sent-Event ou Text-Sequence) par exemple.

Voir tous les nouveaux messages depuis "la dernière fois"

Quand on administre une machine, il est classique de vouloir voir les logs "à partir d'un certain point". Journalctl permet évidemment de filtrer par date ( -U, -S ) mais chaque message a un curseur unique qui permet de faire ça de façon plus fiable.

Nous pouvons faire ça à la main :

$ journalctl --show-cursor

[...]
mars 09 11:33:01 logrus py3status[2934]: Module `volume_status`: available sinks: {'0': 'alsa_output.pci-0000_00_1f.3.analog-stereo', '9': 'regroup', '32': 'alsa_output.usb-C-Media_Electronics_Inc._USB_Advanced_>
mars 09 11:33:09 logrus py3status[2934]: Module `volume_status micro`: available sources: {'0': 'alsa_output.pci-0000_00_1f.3.analog-stereo.monitor', '1': 'alsa_input.pci-0000_00_1f.3.analog-stereo', '19': 'regr>
mars 09 11:33:11 logrus py3status[2934]: Module `volume_status`: available sinks: {'0': 'alsa_output.pci-0000_00_1f.3.analog-stereo', '9': 'regroup', '32': 'alsa_output.usb-C-Media_Electronics_Inc._USB_Advanced_>
-- cursor: s=94e13f7bca824c1192e413d758f8882c;i=58fce;b=d56cd947e79841eba251133d2ed810d1;m=9a8da1bcf6;t=5d9c69fc8c0f2;x=c2ed23ddb5d728bd

$ logger ceci est un test
$ journalctl --after-cursor 's=94e13f7bca824c1192e413d758f8882c;i=58fce;b=d56cd947e79841eba251133d2ed810d1;m=9a8da1bcf6;t=5d9c69fc8c0f2;x=c2ed23ddb5d728bd'

mars 09 11:33:53 logrus jerros[241325]: ceci est un test

L'option --show-cursor fait que journalctl affichera le curseur du dernier message après celui-ci. Nous pouvons ensuite utiliser l'option --after-cursor pour voir les nouveaux messages.

Nous pouvons également laisser journalctl enregistrer le curseur pour nous :

$ journalctl --cursor-file=./my_cursor

[...]
mars 09 11:38:21 logrus py3status[2934]: Module `volume_status`: available sinks: {'0': 'alsa_output.pci-0000_00_1f.3.analog-stereo', '9': 'regroup', '32': 'alsa_output.usb-C-Media_Electronics_Inc._USB_Advanced_>
mars 09 11:38:29 logrus py3status[2934]: Module `volume_status micro`: available sources: {'0': 'alsa_output.pci-0000_00_1f.3.analog-stereo.monitor', '1': 'alsa_input.pci-0000_00_1f.3.analog-stereo', '19': 'regr>
mars 09 11:38:31 logrus py3status[2934]: Module `volume_status`: available sinks: {'0': 'alsa_output.pci-0000_00_1f.3.analog-stereo', '9': 'regroup', '32': 'alsa_output.usb-C-Media_Electronics_Inc._USB_Advanced_>
mars 09 11:38:39 logrus py3status[2934]: Module `volume_status micro`: available sources: {'0': 'alsa_output.pci-0000_00_1f.3.analog-stereo.monitor', '1': 'alsa_input.pci-0000_00_1f.3.analog-stereo', '19': 'regr>
mars 09 11:38:41 logrus py3status[2934]: Module `volume_status`: available sinks: {'0': 'alsa_output.pci-0000_00_1f.3.analog-stereo', '9': 'regroup', '32': 'alsa_output.usb-C-Media_Electronics_Inc._USB_Advanced_>
mars 09 11:38:49 logrus py3status[2934]: Module `volume_status micro`: available sources: {'0': 'alsa_output.pci-0000_00_1f.3.analog-stereo.monitor', '1': 'alsa_input.pci-0000_00_1f.3.analog-stereo', '19': 'regr>

$ cat my_cursor
s=94e13f7bca824c1192e413d758f8882c;i=5901d;b=d56cd947e79841eba251133d2ed810d1;m=9aa27ebd47;t=5d9c6b4a5c143;x=236b9957da4e62aa
$ logger ceci est un test
$ journalctl --cursor-file=./my_cursor

mars 09 11:40:01 logrus jerros[243272]: ceci est un test

Si le fichier n'existe pas, journalctl affichera tous les messages et créera le fichier curseur. Si le fichier existe, journalctl n'affichera que les messages générés après le curseur sauvegardé et mettra à jour le fichier.

Il est trivial de mettre ce genre de commandes dans un script shell pour récupérer régulièrement les nouveaux messages.

 

Rechercher des messages avec journalctl

Nous venons de voir les principes de base pour visionner des logs, mais il est au moins aussi important de pouvoir rechercher des logs qui nous intéressent.

Comment se limiter aux messages d'un boot donné.

Il est assez courant de ne s'intéresser qu'aux messages du boot actuel (ou du boot précédent, en cas de plantage)

  • L'option -b limite l'affichage aux messages du boot en cours.
  • Cette même option, suivi d'un chiffre (négatif) permet d'accéder aux boot précédents. (donc, "-b -1" permet d'avoir les messages d'avant le boot en cours.)
  • Enfin cette option peut être suivie d'un identifiant de boot (le champ _BOOT_ID des messages) pour récupérer un boot donné.

Vous pouvez utiliser la commande "journalctl --list-boots" pour obtenir la liste de tous les boot de la machine, leur identifiant et la date du boot.

Comment retrouver les messages correspondant à une regex

Un grand classique, qui n'a jamais lancé une commande de type cat /var/log/mail | grep error

Pour chercher une option correspondante à une regex, journalctl fournit l'option --grep qui appliquera une regex au champ MESSAGE de nos logs et qui retournera les messages correspondants.

$ journalctl --grep test -o verbose

Wed 2022-03-09 11:40:01.968142 CET [s=94e13f7bca824c1192e413d758f8882c;i=5902a;b=d56cd947e79841eba251133d2ed810d1;m=9aa620046d;t=5d9c6b8470868;x=1abc6a59d873087c]
    _TRANSPORT=syslog
    SYSLOG_FACILITY=1
    _UID=1000
    _GID=1000
    _CAP_EFFECTIVE=0
    _BOOT_ID=d56cd947e79841eba251133d2ed810d1
    _MACHINE_ID=9e7936dad17a4aef95023a89630fc999
    _HOSTNAME=logrus
    PRIORITY=5
    SYSLOG_IDENTIFIER=jerros
    MESSAGE=ceci est un test
    _COMM=logger
    SYSLOG_TIMESTAMP=Mar  9 11:40:01 
    _PID=243272
    _SOURCE_REALTIME_TIMESTAMP=1646822401968142

Notons que ce n'est pas un filtre sur la sortie de journalctl mais bien un filtre sur les messages. Nous avons toujours accès à l'ensemble des champs du message.

 

Recherche générique par clé/valeur.

Il est évident que derrière ces options, journalctl fait un filtrage sur les clés des messages. Il y a évidement une syntaxe générique pour faire des recherches directement sur une clé :

$ journalctl -N

_AUDIT_FIELD_CAPABILITY
NM_DEVICE
LIMIT
SLEEP
_TRANSPORT
USERSPACE_USEC
SYSLOG_RAW
_MACHINE_ID
AVAILABLE
_SOURCE_MONOTONIC_TIMESTAMP
NM_LOG_DOMAINS
_COMM
MESSAGE
SYSLOG_FACILITY
_UID
_SELINUX_CONTEXT
UNIT
INVOCATION_ID
MAX_USE_PRETTY
EXIT_STATUS
PRIORITY
CODE_FUNC
_AUDIT_FIELD_NAME
AVAILABLE_PRETTY
[...]

$ journalctl -F CODE_FUNC

udisks_state_check_mounted_fs_entry
handle_unmount
handle_mount
update_timeout
open_watchdog
cryptsetup_log_glue
session_finalize
session_stop_scope
bus_manager_log_shutdown
invoke_main_loop
unit_kill_common
update_complete
deactivate_net_auth_done_cb
impl_manager_activate_connection
manager_timeout
on_spawn_sigchld
[...]


$ journalctl CODE_FUNC=open_watchdog
déc. 10 16:43:10 logrus systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog
-- Boot cf260f9f1fba4eb8ab51da4068b72614 --
janv. 07 09:55:25 logrus systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog
-- Boot c0e74f4ac76c46aabd206e5fa4b2d889 --
janv. 19 16:48:06 logrus systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog
-- Boot 88047eac746b4f5cb4d391a7a3b1b1c2 --
févr. 26 07:42:30 logrus systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog
-- Boot c559220371274b9981c13527974f5b50 --
avril 14 09:08:44 logrus systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog
-- Boot c15e16c79f674475b20f1605d1a195fc --
mai 10 08:39:44 logrus systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog
-- Boot 9f8b1753da794b1daf5d0187a57a59aa --
juil. 12 09:13:25 logrus systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog
-- Boot 546c0c3bc2d14209816219373c0c6991 --
sept. 03 14:01:54 logrus systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog
-- Boot 15a8081591b545f993270bc737c53251 --
oct. 12 08:16:01 logrus systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog
-- Boot a32eb1c0dd3f42d49aac69e2c699c342 --
oct. 15 16:45:33 logrus systemd[1]: Using hardware watchdog 'iTCO_wdt', version 0, device /dev/watchdog
-- Boot caf11531d9e04b78bfff983e5f5afdc2 --
[...]
  • L'option -N demande à journalctl de lister l'ensemble des options qu'il a rencontré
  • L'option -F=<clé> demande à journalctl de lister toutes les valeurs qu'il a rencontré pour une clé
  • L'option <clé>=<valeur> demande à journalctl de filtrer les messages pour n'afficher que les messages où clé vaut valeur
  • Les marqueurs de reboot sont toujours affichés
  • La syntaxe complète est très riche avec des relations logiques applicables entre les opérateurs

Grâce à cette syntaxe générique, et en explorant un peu, il est possible de n'afficher que les messages qui nous intéressent.

Intégration de journald dans vos services systemd

Journald ne fonctionne qu'avec systemd et ce dernier ne peut fonctionner sans journald. L'intégration de journald aux services systemd est donc plus que triviale, elle est automatique.

Par défaut, les stdout et stderr de vos services seront automatiquement connectés à journald et vous pourrez les voir dans vos logs (entremêlés avec les logs des autres services, en respectant l'ordre d'arrivé.

Il existe néanmoins un certain nombre de paramètres que vous pouvez mettre dans la section [Service] de vos services pour paramétrer le comportement de journald vis à vis des logs générés par ce service:

  • LogLevelMax permet d'abandonner automatiquement les messages ayant une priorité haute (rappel: les priorités hautes sont les priorités les moins importantes)
  • LogRateLimitIntervalSec et LogRateLimitBurst permettent de limiter la quantité de messages qu'un service peut émettre. Le service ne pourra pas envoyer plus de burst messages sur une fenêtre glissante de interval en secondes
  • LogExtraFields permet d'ajouter automatiquement une paire clé/valeur à tous les messages provenant d'un service

Enfin, si une ligne de stdout ou stderr commence par "<#>"  où # est une valeur entre 0 et 7, journald enlèvera ce préfixe et l'utilisera pour définir la priorité du message. Vous pouvez donc facilement gérer des messages de différentes priorités en ajoutant un préfixe dans vos affichages.

Configuration de journald

Gestion de la place disque

La hantise des administrateurs système (et l'une des cause de downtime les plus fréquentes) est le disque dur plein. Et lorsque le disque est plein, le coupable habituel est le système de log.

Journald surveille la place que les log consomment et est capable de supprimer automatiquement les anciens fichiers lorsque c'est nécessaire. Via les fichiers de configurations (man:journald.conf) vous pouvez contrôler:

  • La place maximum que journald peut consommer
  • La place minimum que journald doit laisser disponible
  • La durée de vie et le nombre maximum de fichiers de log à conserver
  • La taille/la durée maximum d'un fichier de log avant rotation
  • La fréquence d'écriture sur les disques (les messages de priorité CRIT, EMERG, etc. sont toujours écrits immédiatement)

Enfin, pour voir la place utilisée par les logs, utilisez la commande journalctl --disk-usage

Signature des logs

Journald est capable d'utiliser l'algorithme Forward Secure Signing pour signer périodiquement les logs. Lorsque cette sécurité est activée, journald signera régulièrement les logs (par défaut, toutes les 15 minutes) avec une clé à usage unique déduite de la signature précédente des logs. 

Une clé originale (conservée offline) permet de vérifier l'intégrité des logs. Cet algorithme fait partie des recommandations de l'ANSSI pour la gestion des logs système.

Journald et les conteneurs

Lire les logs d'un conteneur à posteriori

Par défaut, journald va lire les logs dans /var/log/journal/<machine-id>. Pour lire les logs d'un conteneur, il suffit donc de pointer journalctl vers un autre répertoire

  • L'option --directory permet de pointer journalctl vers un autre répertoire
  • Plus simple, l'option --root permet de pointer journalctl vers la racine d'un rootfs. Journalctl trouvera le machine-id, puis les fichiers de log tout seul.
  • Enfin, l'option --image permet de pointer journalctl vers une image disque ou un périphérique bloc. Journalctl montera automatiquement l'image, trouvera la bonne partition si l'image est partitionnée, puis trouvera les logs au sein de la partition.

Ces options permettent de bien simplifier les choses lorsque l'on doit jongler avec de nombreux conteneurs.

Intégrer les logs des différentes conteneurs dans les logs de l'hôte.

Systemd documente comment intégrer proprement un conteneur ici et c'est une lecture que je recommande à toute personne travaillant avec des conteneurs. En ce qui concerne journald, il est très simple de rendre les logs des invités visibles de façon transparente pour l'hôte.

Journald écrit ses logs dans le répertoire /var/log/journal/<machine-id> et journalctl lit depuis ce même répertoire. Comme chaque conteneur a un machine-id différent, il suffit d'utiliser des bind-mounts (ou des liens symboliques) pour que tous les répertoires /var/log/journal/<machine-id> de chaque conteneur apparaissent dans le répertoire /var/log/journal de l'hôte.

Une fois ces manipulations faites, il suffit d'invoquer journalctl avec l'option -m pour que les journaux de toutes les machines soient affichés, au lieu de se limiter au journal de l'hôte.

Journald et le réseau

Lorsque l'on travaille avec de nombreuses machines, on met généralement en place une infrastructure de log permettant d'envoyer vers un serveur centralisé les logs. Journald dispose d'outils permettant de mettre en place ce type d'infrastructure tout en conservant l'ensemble des informations supplémentaires que journald collectes.

La partie réseau de journald est souvent packagée séparément par les distributions. C'est notamment le cas sous Debian où vous trouverez ces outils dans le paquet systemd-journal-remote.

La logique push

Journald vient avec un utilitaire appelé systemd-journal-upload qui peut pousser les messages journald vers un serveur via une liaison HTTPS. L'utilisation du protocole HTTPS permet à la fois le chiffrement et l'authentification du serveur vers lequel les logs sont envoyés.

systemd-journal-upload peut être appelé périodiquement pour envoyer les nouveaux messages ou être lancé en mode follow auquel cas les messages seront envoyés au fur et à mesure de leur génération.

La logique pull

Selon l'organisation de notre architecture, il peut être souhaitable que les machines n'envoient pas leurs logs, mais qu'un serveur central les collecte régulièrement. Journald fournit un serveur HTTPS qui permet de récupérer les logs grâce à une API REST sur le port 19531.

Ici aussi, l'utilisation de HTTPS permet non seulement de chiffrer les flux mais également d'authentifier les connexions.

L'API REST est très complète. Elle permet notamment de filtrer les messages notifiés et de garder la connexion ouverte en attente de nouveaux messages.

Le serveur fournit également un outil de navigation web léger permettant d'explorer les logs d'une machine sans installer d'autres outils.

La collecte des logs

Nous sommes capable de pousser nos logs et nous sommes capable de fournir nos logs à quelqu'un qui vient les chercher. Il ne reste qu'à les collecter.

Journald fournit un programme appelé systemd-journal-remote qui sert à cela. Ce programme peut simultanément recevoir des connexions de systemd-journal-upload et aller chercher des logs sur systemd-journal-gateway. Les logs ainsi récupérés sont stockés dans /var/log/journal/remote (par défaut) et les logs peuvent également être périodiquement signés.

Pour afficher les logs ainsi récupérés, il faut utiliser l'option -m de journalctl.

l'API Journald

Dans le monde de l'embarqué, il est assez courant de devoir faire une application qui traite les logs, que ce soit pour les monitorer, les archiver ou détecter certains messages critiques.

Journald fournit une API permettant d'avoir facilement accès à toutes les possibilités que nous avons vu, mais à travers une API propre et sans jamais avoir à analyser du texte.

L'API permet, en particulier de choisir des filtres sur les messages et de recevoir un file-descriptor qui sera bloquant jusqu'à ce qu'un message correspondant à nos filtres soit reçu.

Voici un petit exemple en Python :

>>> import select
>>> from systemd import journal
>>> j = journal.Reader()
>>> j.seek_tail()
>>> journal.send('testing 1,2,3')   # make sure we have something to read
>>> j.add_match('MESSAGE=testing 1,2,3')
>>> p = select.poll()
>>> p.register(j, j.get_events())
>>> p.poll()                        
[(3, 1)]
>>> j.get_next()                    
{'_AUDIT_LOGINUID': 1000,
 '_CAP_EFFECTIVE': '0',
 '_SELINUX_CONTEXT': 'unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023',
 '_GID': 1000,
 'CODE_LINE': 1,
 '_HOSTNAME': '...',
 '_SYSTEMD_SESSION': 52,
 '_SYSTEMD_OWNER_UID': 1000,
 'MESSAGE': 'testing 1,2,3',
 '__MONOTONIC_TIMESTAMP':
    journal.Monotonic(timestamp=datetime.timedelta(2, 76200, 811585),
                      bootid=UUID('958b7e26-df4c-453a-a0f9-a8406cb508f2')),
 'SYSLOG_IDENTIFIER': 'python3',
 '_UID': 1000,
 '_EXE': '/usr/bin/python3',
 '_PID': 7733,
 '_COMM': '...',
 'CODE_FUNC': '<module>',
 'CODE_FILE': '<doctest journal.rst[4]>',
 '_SOURCE_REALTIME_TIMESTAMP':
     datetime.datetime(2015, 9, 5, 13, 17, 4, 944355),
 '__CURSOR': 's=...',
 '_BOOT_ID': UUID('958b7e26-df4c-453a-a0f9-a8406cb508f2'),
 '_CMDLINE': '/usr/bin/python3 ...',
 '_MACHINE_ID': UUID('263bb31e-3e13-4062-9bdb-f1f4518999d2'),
 '_SYSTEMD_SLICE': 'user-1000.slice',
 '_AUDIT_SESSION': 52,
 '__REALTIME_TIMESTAMP': datetime.datetime(2015, 9, 5, 13, 17, 4, 945110),
 '_SYSTEMD_UNIT': 'session-52.scope',
 '_SYSTEMD_CGROUP': '/user.slice/user-1000.slice/session-52.scope',
 '_TRANSPORT': 'journal'}

Avec cette API, il est assez facile de faire une application de log simple et fiable

  • Pas besoin de la faire démarrer "tôt". Journald récupère les messages et ils seront disponibles quand l'application démarrera
  • Pas besoin de la faire "robuste". En cas de plantage, les messages sont toujours collectés par journald et l'application peut rattraper lorsqu'elle redémarrera

Conclusion

Journald est un système de gestion moderne. Il a été construit en pleine connaissance des limitations des syslog traditionnels UNIX et s'appuie sur cette expérience pour fournir un système qui résout les problèmes auxquels nous sommes régulièrement confrontés dans le déploiement de nos systèmes.

Journalctl demande un peu de temps pour retrouver ses marques sur les commandes que l'on utilise au quotidien dans l'administration, mais une fois que l'on a passé ce cap, c'est un outil dont on ne peut plus se passer au quotidien.

 

Laisser un commentaire

Votre adresse de messagerie ne sera pas publiée.