systemctl und journalctl in der Praxis (3)

Teilen:



Im dritten Teil der Serie “systemctl und journalctl in der Praxis” will ich ein paar wenig genutzte Kommandos zeigen, die aber trotzdem sehr hlfreich sein können. Die Grundlagen von systemctl und journalctl sind in den vorherigen Artikeln der Serie nachzulesen (siehe dazu am Endes Blogbeitrages die Verlinkungen).


Tipps&Tricks

Abhängigkeiten

Mit der Option list-dependencies von systemctl kann man sich Abhängigkeiten eines Service anzeigen lassen, die vor dem eigentlich Dienst gestartet sein müssen um dessen Abhängigkeiten zu erfüllen. Hier im Beispiel werden die Abhängigkeiten des Service nfs-server.service aufgelistet.

 1$ systemctl list-dependencies nfs-server.service 
 2nfs-server.service
 3● ├─-.mount
 4● ├─auth-rpcgss-module.service
 5● ├─mnt-share-usbstation.mount
 6● ├─nfs-config.service
 7● ├─nfs-idmapd.service
 8● ├─nfs-mountd.service
 9● ├─proc-fs-nfsd.mount
10● ├─rpc-svcgssd.service
11● ├─rpcbind.socket
12● ├─system.slice
13● └─network.target


Wildcards nutzen

Im nächsten Praxisbeispiel kann man die Wildcards nutzen um sich die Stati eines oder mehrerer Serviceunits Files anzeigen lassen.

1$ systemctl list-unit-files ssh*
2UNIT FILE    STATE    VENDOR PRESET
3ssh.service  enabled  enabled      
4ssh@.service static   enabled      
5sshd.service enabled  enabled      
6ssh.socket   disabled enabled      

Hier werden die Detail-Stati aller NFS-Services übersichtlich mit Hilfe eines Wildcard dargestellt.

 1$ systemctl status nfs*.service --no-pager 
 2● nfs-idmapd.service - NFSv4 ID-name mapping service
 3     Loaded: loaded (/lib/systemd/system/nfs-idmapd.service; static; vendor preset: enabled)
 4     Active: active (running) since Tue 2020-12-15 07:22:31 CET; 5h 16min ago
 5    Process: 1056 ExecStart=/usr/sbin/rpc.idmapd $RPCIDMAPDARGS (code=exited, status=0/SUCCESS)
 6   Main PID: 1064 (rpc.idmapd)
 7      Tasks: 1 (limit: 18988)
 8     Memory: 1.3M
 9     CGroup: /system.slice/nfs-idmapd.service
10             └─1064 /usr/sbin/rpc.idmapd
11
12Dez 15 07:22:31 neonlight systemd[1]: Starting NFSv4 ID-name mapping service...
13Dez 15 07:22:31 neonlight systemd[1]: Started NFSv4 ID-name mapping service.
14
15● nfs-mountd.service - NFS Mount Daemon
16     Loaded: loaded (/lib/systemd/system/nfs-mountd.service; static; vendor preset: enabled)
17     Active: active (running) since Tue 2020-12-15 07:22:31 CET; 5h 16min ago
18    Process: 1213 ExecStart=/usr/sbin/rpc.mountd $RPCMOUNTDARGS (code=exited, status=0/SUCCESS)
19   Main PID: 1248 (rpc.mountd)
20      Tasks: 1 (limit: 18988)
21     Memory: 25.4M
22     CGroup: /system.slice/nfs-mountd.service
23             └─1248 /usr/sbin/rpc.mountd --manage-gids
24
25Dez 15 07:22:31 neonlight systemd[1]: Starting NFS Mount Daemon...
26Dez 15 07:22:31 neonlight rpc.mountd[1248]: Version 1.3.3 starting
27Dez 15 07:22:31 neonlight systemd[1]: Started NFS Mount Daemon.
28
29● nfs-blkmap.service - pNFS block layout mapping daemon
30     Loaded: loaded (/lib/systemd/system/nfs-blkmap.service; disabled; vendor preset: enabled)
31     Active: active (running) since Tue 2020-12-15 07:22:30 CET; 5h 16min ago
32    Process: 502 ExecStart=/usr/sbin/blkmapd $BLKMAPDARGS (code=exited, status=0/SUCCESS)
33   Main PID: 504 (blkmapd)
34      Tasks: 1 (limit: 18988)
35     Memory: 696.0K
36     CGroup: /system.slice/nfs-blkmap.service
37             └─504 /usr/sbin/blkmapd
38
39Dez 15 07:22:30 neonlight blkmapd[504]: open pipe file /run/rpc_pipefs/nfs/blocklayout failed: No such file or directory
40Warning: journal has been rotated since unit was started, output may be incomplete.
41
42● nfs-server.service - NFS server and services
43     Loaded: loaded (/lib/systemd/system/nfs-server.service; enabled; vendor preset: enabled)
44    Drop-In: /run/systemd/generator/nfs-server.service.d
45             └─order-with-mounts.conf
46     Active: active (exited) since Tue 2020-12-15 07:22:33 CET; 5h 16min ago
47    Process: 1250 ExecStartPre=/usr/sbin/exportfs -r (code=exited, status=0/SUCCESS)
48    Process: 1256 ExecStart=/usr/sbin/rpc.nfsd $RPCNFSDARGS (code=exited, status=0/SUCCESS)
49   Main PID: 1256 (code=exited, status=0/SUCCESS)
50
51Dez 15 07:22:31 neonlight systemd[1]: Starting NFS server and services...
52Dez 15 07:22:33 neonlight systemd[1]: Finished NFS server and services.


Verbosemode

Oft steht man vor dem Problem das eine Fehlermeldung aus dem Journal nicht aussagekräftig genug oder zu allgemein gehalten ist. Hier kommt die Option -o verbose ins Spiel. Im nachfolgenden Beispiel werden alle Einträge des heutigen Tages ausführlich angezeigt.

 1$ journalctl --since="today" -o verbose
 2-- Logs begin at Thu 2020-10-22 07:05:36 CEST, end at Fri 2020-12-11 14:09:01 CET. --
 3Fri 2020-12-11 07:03:56.543319 CET [s=ddb75740754a4ed18c6b697acb4c0b20;i=452604;b=bda9b7e029764346a00e1863fa74a6ad;m=466893;t=5b62a0ec9d557;x=6a39129fd772c7db]
 4    _SOURCE_MONOTONIC_TIMESTAMP=0
 5    _TRANSPORT=kernel
 6    PRIORITY=6
 7    SYSLOG_FACILITY=0
 8    SYSLOG_IDENTIFIER=kernel
 9    MESSAGE=microcode: microcode updated early to revision 0x21, date = 2019-02-13
10    _BOOT_ID=bda9b7e029764346a00e1863fa74a6ad
11    _MACHINE_ID=ae3a742cfe764ac696883d6ac7107ec5
12    _HOSTNAME=neonlight
13    
14    -- Logs begin at Thu 2020-10-22 07:05:36 CEST, end at Fri 2020-12-11 14:12:30 CET. --

Hier ein Beispiel um ausführliche Logmeldungen und Erklärungen (Option -x) des ssh.service des heutigen Tages gelistet zu bekommen.

 1$ journalctl -u ssh.service -x --since="today"
 2-- Logs begin at Thu 2020-10-22 07:05:36 CEST, end at Fri 2020-12-11 14:21:01 CET. --
 3Dez 11 07:03:58 neonlight systemd[1]: Starting OpenBSD Secure Shell server...
 4-- Subject: A start job for unit ssh.service has begun execution
 5-- Defined-By: systemd
 6-- Support: http://www.ubuntu.com/support
 7-- 
 8-- A start job for unit ssh.service has begun execution.
 9-- 
10-- The job identifier is 119.
11Dez 11 07:03:58 neonlight sshd[1245]: Server listening on 0.0.0.0 port 22.
12Dez 11 07:03:58 neonlight sshd[1245]: Server listening on :: port 22.
13Dez 11 07:03:58 neonlight systemd[1]: Started OpenBSD Secure Shell server.
14-- Subject: A start job for unit ssh.service has finished successfully
15-- Defined-By: systemd
16-- Support: http://www.ubuntu.com/support
17-- 
18-- A start job for unit ssh.service has finished successfully.
19-- 
20-- The job identifier is 119.


Das Journal selbst

Für das Journal ist der Service systemd-journald zuständig, den man natürlich genauso auf sein aktuellen Logmeldungen abfragen kann.

 1$ journalctl -u systemd-journald
 2Okt 23 07:01:08 neonlight systemd-journald[475]: Journal started
 3Okt 23 07:01:08 neonlight systemd-journald[475]: Runtime Journal (/run/log/journal/ae3a742cfe764ac696883d6ac7107ec5) is 8.0M, max 159.1M, 151.1M free.
 4Okt 23 07:01:09 neonlight systemd-journald[475]: Time spent on flushing to /var/log/journal/ae3a742cfe764ac696883d6ac7107ec5 is 51.487ms for 1165 entries.
 5Okt 23 07:01:09 neonlight systemd-journald[475]: System Journal (/var/log/journal/ae3a742cfe764ac696883d6ac7107ec5) is 1.0G, max 1.0G, 0B free.
 6-- Reboot --
 7Okt 24 15:52:12 neonlight systemd-journald[477]: Journal started
 8Okt 24 15:52:12 neonlight systemd-journald[477]: Runtime Journal (/run/log/journal/ae3a742cfe764ac696883d6ac7107ec5) is 8.0M, max 159.1M, 151.1M free.
 9Okt 24 15:52:13 neonlight systemd-journald[477]: Time spent on flushing to /var/log/journal/ae3a742cfe764ac696883d6ac7107ec5 is 79.120ms for 1157 entries.
10Okt 24 15:52:13 neonlight systemd-journald[477]: System Journal (/var/log/journal/ae3a742cfe764ac696883d6ac7107ec5) is 1.0G, max 1.0G, 0B free.


Alternative Anzeige zum Servicenamen

Sollte man statt des Servicenamen lieber den Namen (inklusive dem Pfad) des ausführbaren Binaries bevorzugen, kann man diesen alternativ angeben um die jeweiligen Journaleinträge zu sehen. Alternativ kann man sich die zB. die Einträge NetworkManagers auch über das Journalfeld COMM anzeigen lassen.

 1$ journalctl /usr/sbin/NetworkManager --since="today"
 2-- Logs begin at Thu 2020-10-22 07:05:36 CEST, end at Fri 2020-12-11 14:18:01 CET. --
 3Dez 11 07:03:58 neonlight NetworkManager[1111]: <info>  [1607666638.2461] NetworkManager (version 1.22.10) is starting... (for the first time)
 4Dez 11 07:03:58 neonlight NetworkManager[1111]: <info>  [1607666638.2462] Read config: /etc/NetworkManager/NetworkManager.conf (lib: 10-dns-resolved.conf, 30-connectivity-kde.conf, no-mac-addr-change.conf) (run: 10-globally-managed-devices.conf) (etc: default-wifi-powersave-on.conf)
 5Dez 11 07:03:58 neonlight NetworkManager[1111]: <info>  [1607666638.2931] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
 6Dez 11 07:03:58 neonlight NetworkManager[1111]: <info>  [1607666638.3004] manager[0x5597c3d37020]: monitoring kernel firmware directory '/lib/firmware'.
 7Dez 11 07:03:58 neonlight NetworkManager[1111]: <info>  [1607666638.3005] monitoring ifupdown state file '/run/network/ifstate'.
 8Dez 11 07:03:58 neonlight NetworkManager[1111]: <info>  [1607666638.4789] hostname: hostname: using hostnamed
 9Dez 11 07:03:58 neonlight NetworkManager[1111]: <info>  [1607666638.4789] hostname: hostname changed from (none) to "neonlight"
10Dez 11 07:03:58 neonlight NetworkManager[1111]: <info>  [1607666638.4792] dns-mgr[0x5597c3d1e290]: init: dns=systemd-resolved rc-manager=symlink, plugin=systemd-resolved
11
12$ journalctl _COMM=NetworkManager --since="today" 
13-- Logs begin at Thu 2020-10-22 07:05:36 CEST, end at Mon 2020-12-14 17:09:01 CET. --
14Dez 14 07:05:12 neonlight NetworkManager[1106]: <info>  [1607925912.7634] NetworkManager (version 1.22.10) is starting... (for the first t>
15Dez 14 07:05:12 neonlight NetworkManager[1106]: <info>  [1607925912.7635] Read config: /etc/NetworkManager/NetworkManager.conf (lib: 10-dn>
16Dez 14 07:05:12 neonlight NetworkManager[1106]: <info>  [1607925912.8505] bus-manager: acquired D-Bus service "org.freedesktop.NetworkMana>
17Dez 14 07:05:12 neonlight NetworkManager[1106]: <info>  [1607925912.8558] manager[0x55e1e118a020]: monitoring kernel firmware directory '/>
18Dez 14 07:05:12 neonlight NetworkManager[1106]: <info>  [1607925912.8558] monitoring ifupdown state file '/run/network/ifstate'.
19Dez 14 07:05:13 neonlight NetworkManager[1106]: <info>  [1607925913.0333] hostname: hostname: using hostnamed

Besonders praxisnah erweist sich anhand einer existenten Prozess-ID sich die dazugehörigen Meldungen anzusehen. Hier im Beispiel werden die Journaleinträge des Prozess rsyslogd mit der ID 1139 angezeigt.

1$ journalctl _PID=1139 --since="today"
2-- Logs begin at Thu 2020-10-22 07:05:36 CEST, end at Fri 2020-12-11 14:24:01 CET. --
3Dez 11 07:03:58 neonlight rsyslogd[1139]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.2001.0]
4Dez 11 07:03:58 neonlight rsyslogd[1139]: rsyslogd's groupid changed to 106
5Dez 11 07:03:58 neonlight rsyslogd[1139]: rsyslogd's userid changed to 102
6Dez 11 07:03:58 neonlight rsyslogd[1139]: [origin software="rsyslogd" swVersion="8.2001.0" x-pid="1139" x-info="https://www.rsyslog.com"] start
7Dez 11 07:03:58 neonlight rsyslogd[1139]: [origin software="rsyslogd" swVersion="8.2001.0" x-pid="1139" x-info="https://www.rsyslog.com"] rsyslogd was HUPed

Hier nochmal um eine Stufe ausführlicher mit der Verbose-Option.

 1$ journalctl -o verbose _PID=1139 --since="today"
 2-- Logs begin at Thu 2020-10-22 07:05:36 CEST, end at Fri 2020-12-11 14:42:01 CET. --
 3Fri 2020-12-11 07:03:58.198627 CET [s=ddb75740754a4ed18c6b697acb4c0b20;i=452bad;b=bda9b7e029764346a00e1863fa74a6ad;m=5fb12e;t=5b62a0e>
 4    PRIORITY=6
 5    _SELINUX_CONTEXT=unconfined
 6    _SYSTEMD_SLICE=system.slice
 7    _MACHINE_ID=ae3a742cfe764ac696883d6ac7107ec5
 8    _HOSTNAME=neonlight
 9    _CAP_EFFECTIVE=0
10    _TRANSPORT=syslog
11    _PID=1139
12    SYSLOG_FACILITY=5
13    SYSLOG_IDENTIFIER=rsyslogd
14    _UID=102
15    _GID=106
16    _COMM=rsyslogd
17    _EXE=/usr/sbin/rsyslogd
18    _CMDLINE=/usr/sbin/rsyslogd -n -iNONE
19    _SYSTEMD_CGROUP=/system.slice/rsyslog.service
20    _SYSTEMD_UNIT=rsyslog.service
21    MESSAGE=imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.2001.0]
22    _BOOT_ID=bda9b7e029764346a00e1863fa74a6ad
23    SYSLOG_TIMESTAMP=Dec 11 07:03:58 
24    _SYSTEMD_INVOCATION_ID=8d33ea15e3e845618e7a90a0e47a706a
25    _SOURCE_REALTIME_TIMESTAMP=1607666638198627

Will man bestimmte Userprozesse im Auge haben, kann man mit dem Journalfeld UID und der Angabe des numerischen UserID sich einen Überblick verschaffen.

1$ journalctl _UID=1000 --since="today"
2-- Logs begin at Thu 2020-10-22 07:05:36 CEST, end at Fri 2020-12-11 14:31:14 CET. --
3Dez 11 07:04:42 neonlight systemd[1755]: Reached target Paths.
4Dez 11 07:04:42 neonlight systemd[1755]: Reached target Timers.
5Dez 11 07:04:42 neonlight systemd[1755]: Starting D-Bus User Message Bus Socket.
6Dez 11 07:04:42 neonlight systemd[1755]: Listening on GnuPG network certificate management daemon.
7Dez 11 07:04:42 neonlight systemd[1755]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
8Dez 11 07:04:42 neonlight systemd[1755]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).

Nach dem selben Schema lassen sich die zugehörigen Meldungen zur GID, also Gruppen-ID’s, anzeigen auch mehrere ID’s gleichzeitig.

 1$ journalctl _GID=102 _GID=103 --since="today"
 2-- Logs begin at Sat 2020-11-14 10:57:58 CET, end at Tue 2020-12-15 12:27:01 CET. --
 3Dez 15 07:22:30 neonlight systemd-networkd[527]: bri0: netdev ready
 4Dez 15 07:22:30 neonlight systemd-networkd[527]: Enumeration completed
 5Dez 15 07:22:30 neonlight systemd-networkd[527]: eno1: Link UP
 6Dez 15 07:22:31 neonlight systemd-networkd[527]: bri0: IPv6 successfully enabled
 7Dez 15 07:22:31 neonlight systemd-networkd[527]: bri0: Link UP
 8Dez 15 07:22:31 neonlight systemd-resolved[1075]: Positive Trust Anchors:
 9Dez 15 07:22:31 neonlight systemd-resolved[1075]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e88>
10Dez 15 07:22:31 neonlight systemd-resolved[1075]: Negative trust anchors: 10.in-addr.arpa 16.172.in-addr.>
11Dez 15 07:22:31 neonlight systemd-resolved[1075]: Using system hostname 'neonlight'.
12Dez 15 07:22:35 neonlight systemd-networkd[527]: eno1: Gained carrier
13Dez 15 07:22:35 neonlight systemd-networkd[527]: bri0: Gained carrier
14Dez 15 07:22:37 neonlight systemd-networkd[527]: bri0: Gained IPv6LL

Welche UID (UserID’s) überhaupt im Journal vorkommen ermittelt man wie folgenden Listing dargestellt. Somit kann man die Suche weiter eingrenzen und verfeinern.

 1$ journalctl -F _UID
 21000
 362803
 4101
 5100
 6118
 74000
 8109
 9117
10114
11122
12103
13102
14113
150
16125
172000


Anzeige mit Hilfe eines Journalfeldes

Oftmals schreiben bestimmte Prozesse oder Programme Meldungen auf die Konsole die man in Regel nicht mitbekommt, aber trotzdem im Journal dokumentiert werden. Dazu muss man das Journalfeld TRANSPORT mit dem Wert stdout angeben.

 1$ journalctl _TRANSPORT=stdout 
 2-- Logs begin at Thu 2020-10-22 07:05:36 CEST, end at Fri 2020-12-11 14:36:46 CET. --
 3Dez 11 07:03:56 neonlight lvm[485]:   3 logical volume(s) in volume group "VGdata" monitored
 4Dez 11 07:03:56 neonlight lvm[485]:   6 logical volume(s) in volume group "VGsys" monitored
 5Dez 11 07:03:57 neonlight systemd-fsck[821]: VAR: sauber, 51671/655360 Dateien, 1670233/2621440 Blöcke
 6Dez 11 07:03:57 neonlight lvm[852]:   pvscan[852] PV /dev/sda1 online, VG VGsys is complete.
 7Dez 11 07:03:57 neonlight lvm[852]:   pvscan[852] VG VGsys skip autoactivation.
 8Dez 11 07:03:57 neonlight systemd-fsck[816]: USERDATA: sauber, 12878/1310720 Dateien, 2687549/5242880 Blöcke
 9Dez 11 07:03:57 neonlight systemd-fsck[849]: VM-FAST: sauber, 28/5242880 Dateien, 6936844/20971520 Blöcke
10Dez 11 07:03:57 neonlight systemd-fsck[911]: MUSIC: sauber, 10646/4587520 Dateien, 14677765/18350080 Blöcke
11Dez 11 07:03:57 neonlight systemd-fsck[923]: HOME: sauber, 230564/1310720 Dateien, 4505752/5242880 Blöcke
12Dez 11 07:03:57 neonlight lvm[1018]:   pvscan[1018] PV /dev/sdb1 online, VG VGdata is complete.
13Dez 11 07:03:57 neonlight lvm[1018]:   pvscan[1018] VG VGdata skip autoactivation.

Über die verfügbaren Journalfelder kann man sich direkt in den Manpages informieren.

1$ man systemd.journal-fields


Zustand der Standard-Targets abfragen

Auch die Standard-Targets (ehemals Runlevel) lassen sich nach ihren Stati abfragen.

 1$ systemctl status basic.target 
 2● basic.target - Basic System
 3     Loaded: loaded (/lib/systemd/system/basic.target; static; vendor preset: enabled)
 4     Active: active since Mon 2020-12-14 07:05:12 CET; 9h ago
 5       Docs: man:systemd.special(7)
 6
 7Dez 14 07:05:12 neonlight systemd[1]: Reached target Basic System.
 8
 9$ systemctl status multi-user.target
10● multi-user.target - Multi-User System
11     Loaded: loaded (/lib/systemd/system/multi-user.target; static; vendor preset: enabled)
12     Active: active since Mon 2020-12-14 07:05:19 CET; 7h ago
13       Docs: man:systemd.special(7)
14
15Dez 14 07:05:19 neonlight systemd[1]: Reached target Multi-User System.
16
17$ systemctl status graphical.target 
18● graphical.target - Graphical Interface
19     Loaded: loaded (/lib/systemd/system/graphical.target; static; vendor preset: enabled)
20     Active: active since Mon 2020-12-14 07:05:19 CET; 9h ago
21       Docs: man:systemd.special(7)
22
23Dez 14 07:05:19 neonlight systemd[1]: Reached target Graphical Interface.
24
25$ systemctl status emergency.target
26● emergency.target - Emergency Mode
27     Loaded: loaded (/lib/systemd/system/emergency.target; static; vendor preset: enabled)
28     Active: inactive (dead)
29       Docs: man:systemd.special(7)


Service Kill

Über systemctl ist es möglich (nur als root) einzelne Services zu beenden.

1$ systemctl kill crond.service


Handling des Journals

Um sich die Größe des aktuellen Journal anzuzeigen genügt es die Option –disk-usage anzugeben.

1$ journalctl --disk-usage
2Archived and active journals take up 1008.1M in the file system.

Wenn man die Option –vacuum-size verwendt, kann man das Journal durch Angabe einer Größe verkleinern. Dadurch werden alte Einträge entfernt, bis der gesamte auf der Festplatte belegte Journalspeicher die angeforderte Größe erreicht hat.

1$ journalctl --vacuum-size=1G

Eine weitere Möglichkeit, das Journal zu verkleinern, ist die Angabe eines Zeitunktes mit der Option –vacuum-time. Alle Einträge nach diesem Zeitpunkt werden gelöscht. Auf diese Weise kann man die Einträge die nach einem bestimmten Zeitpunkt erstellt wurden beibehalten.

1$ journalctl --vacuum-time=1years


Fazit

Durch spezielle wenig bekannte Optionen kann sich beim Finden von Logmeldungen des systemd in seinem Journal, sehr schnell einen Überblick über eine Fehlersituation eines Dienstes verschaffen.



Weiterführende Informationen

Teil 1: systemctl und journalctl in der Praxis (1)

Teil 2: systemctl und journalctl in der Praxis (2)

Understanding Systemd Units and Unit Files

How To Use Journalctl to View and Manipulate Systemd Logs

Using the systemctl command to manage systemd units opensource.com

Verwendung von Journalctl zum Anzeigen und Bearbeiten von Systemd-Protokollen

ubuntuusers.de - Units



Quelle Teaser-Logo: Photo by Aryan Dhiman on Unsplash