Category: systemd

Make systemd to save logs on the disk

On some Linux distributions, systemd log files are not saved on your disk, but only temporary in the memory and when you reboot all logs are discarded. So the systemd logs are not persistent, which could lead to missing important information if you want to check them when you are booted in a rescue disk or even if you just reboot your server. for exmaple,

if some important service failed to boot and your server is unreachable and you boot in rescue CD you do not have logs to check why the service failed and the (error) output of the process of starting the services!

Here is how you can enable the systemd logs to be persistent i.e. save them on the disk. This is tested on CentOS 7, which by default saves the systemd logs on memory!

STEP 1) Prepare the systemd log directory

mkdir -p /var/log/journal/
systemd-tmpfiles --create --prefix /var/log/journal/

STEP 2) Edit systemd configuration and reload the daemon

And ensure your configuration uses “Storage=persistent” in /etc/systemd/journald.conf

grep Storage /etc/systemd/journald.conf
Storage=persistent
systemctl restart systemd-journald

The last line with systemctl restart could be replace with

killall -USR1 systemd-journald

if you do not want to lose all your current logs in memory!

Bonus – systemd logs from multiple reboots

Here we have logs from 5 reboots. Here you can also see what are the right owner (systemd-journal) and Selinux labels of the “/var/log/journal/”

[root@srv ~]# ls -altrZ /var/log/journal/
drwxr-sr-x+ root systemd-journal system_u:object_r:var_log_t:s0   dbd91181db6b4c9f900d9b3a1651a8d5
drwxr-sr-x+ root systemd-journal system_u:object_r:var_log_t:s0   .
drwxr-xr-x. root root            system_u:object_r:var_log_t:s0   ..
[root@srv ~]# journalctl --disk-usage
Archived and active journals take up 112.0M on disk.
[root@srv ~]# journalctl --list-boots
-4 ec4146b78ac944b8a8d4116f259e09ee Thu 2019-06-06 23:39:14 UTC—Thu 2019-06-06 23:39:37 UTC
-3 ae3d39db626c4592aa84cc68072fbb32 Thu 2019-06-06 23:41:03 UTC—Thu 2019-06-06 23:42:13 UTC
-2 68c1ca07c05b4d59adcc9888c50f4065 Thu 2019-06-06 23:42:57 UTC—Fri 2019-06-07 00:13:27 UTC
-1 f7e8da6aaa8740faa05c4985c92023fd Fri 2019-06-07 00:14:08 UTC—Fri 2019-06-07 00:16:33 UTC
 0 45c00dc29e1a48298d9f87f5421468b4 Fri 2019-06-07 00:17:13 UTC—Mon 2019-06-10 01:39:17 UTC
[root@srv ~]# journalctl --boot=-2
-- Logs begin at Thu 2019-06-06 23:39:14 UTC, end at Mon 2019-06-10 01:39:17 UTC. --
Jun 06 23:42:57 srv systemd-journal[133]: Runtime journal is using 8.0M (max allowed 1.5G, trying to leave 2.3G free of 15.6G available → current limit 1.5G).
Jun 06 23:42:57 srv kernel: microcode: microcode updated early to revision 0x710, date = 2013-06-17
Jun 06 23:42:57 srv kernel: Initializing cgroup subsys cpuset
Jun 06 23:42:57 srv kernel: Initializing cgroup subsys cpu
Jun 06 23:42:57 srv kernel: Initializing cgroup subsys cpuacct
Jun 06 23:42:57 srv kernel: Linux version 3.10.0-514.10.2.el7.x86_64 (builder@kbuilder.dev.centos.org) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-11) (GCC) ) #1 S
Jun 06 23:42:57 srv kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-3.10.0-514.10.2.el7.x86_64 root=UUID=c9bec791-c77d-4189-b18a-9ddc728ee782 ro crashkernel=auto r
Jun 06 23:42:57 srv kernel: e820: BIOS-provided physical RAM map:
....
....
[root@srv ~]# journalctl --boot=-2 -u auditd
-- Logs begin at Thu 2019-06-06 23:39:14 UTC, end at Mon 2019-06-10 01:50:18 UTC. --
Jun 06 23:43:05 srv systemd[1]: Starting Security Auditing Service...
Jun 06 23:43:05 srv auditd[694]: Started dispatcher: /sbin/audispd pid: 698
Jun 06 23:43:05 srv audispd[698]: priority_boost_parser called with: 4
Jun 06 23:43:05 srv audispd[698]: max_restarts_parser called with: 10
Jun 06 23:43:05 srv audispd[698]: audispd initialized with q_depth=150 and 1 active plugins
Jun 06 23:43:05 srv augenrules[695]: /sbin/augenrules: No change
Jun 06 23:43:05 srv auditd[694]: Init complete, auditd 2.6.5 listening for events (startup state enable)
Jun 06 23:43:05 srv augenrules[695]: No rules
Jun 06 23:43:05 srv augenrules[695]: enabled 1
Jun 06 23:43:05 srv augenrules[695]: failure 1
Jun 06 23:43:05 srv augenrules[695]: pid 694
Jun 06 23:43:05 srv augenrules[695]: rate_limit 0
Jun 06 23:43:05 srv augenrules[695]: backlog_limit 320
Jun 06 23:43:05 srv augenrules[695]: lost 0
Jun 06 23:43:05 srv augenrules[695]: backlog 1
Jun 06 23:43:05 srv systemd[1]: Started Security Auditing Service.
Jun 06 23:56:48 srv auditd[694]: The audit daemon is exiting.
Jun 06 23:56:49 srv systemd[1]: Starting Security Auditing Service...
Jun 06 23:56:49 srv auditd[24744]: Started dispatcher: /sbin/audispd pid: 24746
Jun 06 23:56:49 srv audispd[24746]: audispd initialized with q_depth=250 and 1 active plugins
Jun 06 23:56:49 srv auditd[24744]: Init complete, auditd 2.8.4 listening for events (startup state enable)
Jun 06 23:56:49 srv augenrules[24750]: /sbin/augenrules: No change
Jun 06 23:56:49 srv augenrules[24750]: No rules
Jun 06 23:56:49 srv augenrules[24750]: enabled 1
Jun 06 23:56:49 srv augenrules[24750]: failure 1
Jun 06 23:56:49 srv augenrules[24750]: pid 24744
Jun 06 23:56:49 srv augenrules[24750]: rate_limit 0
Jun 06 23:56:49 srv augenrules[24750]: backlog_limit 320
Jun 06 23:56:49 srv augenrules[24750]: lost 0
Jun 06 23:56:49 srv augenrules[24750]: backlog 1
Jun 06 23:56:49 srv systemd[1]: Started Security Auditing Service.
Jun 07 00:13:26 srv systemd[1]: Stopping Security Auditing Service...
Jun 07 00:13:26 srv systemd[1]: Stopped Security Auditing Service.

Now you have logs of your booting process!

The systemd log files are accessible even if you’ve booted from a rescue CD and you chroot in your system!

Be careful with the disk free space when using disk storage for your systemd logs – Clear or delete systemd logs.

systemd service freezes in activating (start-post) status – mysqld or other services

We’ve experienced this with the MySQL server under CentOS 7, but you can have this state with other services!
After updating our MySQL we tried to start it up, but the service got this strange state after “systemctl start” returned:

[root@mysql2 ~]# systemctl start mysqld
Job for mysqld.service failed because a timeout was exceeded. See "systemctl status mysqld.service" and "journalctl -xe" for details.

The timeout is big it’s something like 5 to 10 minutes and so it is typical (do not do it!) to type “ctrl+c” and you end up without this message and a strange state of the mysql:

[root@mysql2 ~]# systemctl status mysqld
● mysqld.service - MySQL Community Server
   Loaded: loaded (/usr/lib/systemd/system/mysqld.service; enabled; vendor preset: disabled)
   Active: activating (start-post) since Fri 2018-11-09 09:00:55 UTC; 6min ago
  Process: 8333 ExecStart=/usr/bin/mysqld_safe --basedir=/usr (code=exited, status=0/SUCCESS)
  Process: 8321 ExecStartPre=/usr/bin/mysql-systemd-start pre (code=exited, status=0/SUCCESS)
 Main PID: 8333 (code=exited, status=0/SUCCESS);         : 8334 (mysql-systemd-s)
   CGroup: /user.slice/user-0.slice/session-2395.scope/system.slice/mysqld.service
           └─control
             ├─ 8334 /bin/bash /usr/bin/mysql-systemd-start post
             └─10152 sleep 1

Nov 09 09:00:55 mysql2.mytv.bg systemd[1]: Starting MySQL Community Server...
Nov 09 09:00:56 mysql2.mytv.bg mysqld_safe[8333]: 181109 09:00:56 mysqld_safe Logging to '/var/log/mysqld.log'.
Nov 09 09:00:56 mysql2.mytv.bg mysqld_safe[8333]: 181109 09:00:56 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql

Meanwhile with “pstree”:

[root@mysql2 ~]# pstree
systemd─┬─agetty
        ├─crond
        ├─dbus-daemon
        ├─mysql-systemd-s───sleep
        ├─rsyslogd───2*[{rsyslogd}]
        ├─sshd─┬─sshd───bash───systemctl─┬─systemctl
        │      │                         └─systemd-tty-ask
        │      └─sshd───bash───pstree
        ├─systemd-journal
        └─systemd-logind

So as you can see no mysqld process! Apparently systemctl had tried to start MySQL server process and it failed.
So the first thing to do was to check the MySQL logs. In our case it was a obsolete option in my.cnf:

2018-11-09 09:10:57 11384 [ERROR] /usr/sbin/mysqld: unknown variable 'default-character-set=utf8'
2018-11-09 09:10:57 11384 [ERROR] Aborting

The interesting part is that

the service got “Active: activating (start-post)” and when you fix the problem you cannot “systemctl start mysqld” it just start to wait for the current timeout.

In fact this state means “I’m trying to start the service…” and it is in an endless loop to start the service and if you the service has a big start timeout like 5-10 minutes you must wait for the next iteration of the loop to start the service successfully (if you fixed the problem!). And if you want not to wait you must execute first stop to the service and then start – you’ll not wait for any timeout and you can check immediately if the service was started successfully:

[root@mysql2 ~]# systemctl status mysqld
● mysqld.service - MySQL Community Server
   Loaded: loaded (/usr/lib/systemd/system/mysqld.service; enabled; vendor preset: disabled)
   Active: activating (start-post) since Fri 2018-11-09 09:20:56 UTC; 2min 50s ago
  Process: 13208 ExecStart=/usr/bin/mysqld_safe --basedir=/usr (code=exited, status=0/SUCCESS)
  Process: 13196 ExecStartPre=/usr/bin/mysql-systemd-start pre (code=exited, status=0/SUCCESS)
 Main PID: 13208 (code=exited, status=0/SUCCESS);         : 13209 (mysql-systemd-s)
   CGroup: /user.slice/user-0.slice/session-2395.scope/system.slice/mysqld.service
           └─control
             ├─13209 /bin/bash /usr/bin/mysql-systemd-start post
             └─14357 sleep 1

Nov 09 09:20:56 mysql2.mytv.bg systemd[1]: Starting MySQL Community Server...
Nov 09 09:20:56 mysql2.mytv.bg mysqld_safe[13208]: 181109 09:20:56 mysqld_safe Logging to '/var/log/mysqld.log'.
Nov 09 09:20:56 mysql2.mytv.bg mysqld_safe[13208]: 181109 09:20:56 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
[root@mysql2 ~]# systemctl start mysqld
Job for mysqld.service failed because a timeout was exceeded. See "systemctl status mysqld.service" and "journalctl -xe" for details.
[root@mysql2 ~]# systemctl status mysqld
● mysqld.service - MySQL Community Server
   Loaded: loaded (/usr/lib/systemd/system/mysqld.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2018-11-09 09:30:59 UTC; 2s ago
  Process: 15656 ExecStartPost=/usr/bin/mysql-systemd-start post (code=exited, status=0/SUCCESS)
  Process: 15643 ExecStartPre=/usr/bin/mysql-systemd-start pre (code=exited, status=0/SUCCESS)
 Main PID: 15655 (mysqld_safe)
   CGroup: /user.slice/user-0.slice/session-2395.scope/system.slice/mysqld.service
           ├─15655 /bin/sh /usr/bin/mysqld_safe --basedir=/usr
           └─16243 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --log-error=/var/log/mysqld.log --open-files-limit=10000...

Nov 09 09:30:56 mysql2.mytv.bg systemd[1]: Starting MySQL Community Server...
Nov 09 09:30:57 mysql2.mytv.bg mysqld_safe[15655]: 181109 09:30:57 mysqld_safe Logging to '/var/log/mysqld.log'.
Nov 09 09:30:57 mysql2.mytv.bg mysqld_safe[15655]: 181109 09:30:57 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
Nov 09 09:30:59 mysql2.mytv.bg systemd[1]: Started MySQL Community Server.

As you can see we even received error again that the service cannot be started and immediately after that the service status is in normal “active (running)” state! And we waited for around 10 minutes! You can see the times in the logs above.
So to summarize it up:

If you have a service in “activating (start-post)” the service cannot be started because of an error, check and fix the problem and then issue “stop and start”:

[root@mysql2 ~]# systemctl start mysqld
Job for mysqld.service failed because a timeout was exceeded. See "systemctl status mysqld.service" and "journalctl -xe" for details.
[root@mysql2 ~]# systemctl status mysqld
● mysqld.service - MySQL Community Server
   Loaded: loaded (/usr/lib/systemd/system/mysqld.service; enabled; vendor preset: disabled)
   Active: activating (start-post) since Fri 2018-11-09 10:05:20 UTC; 2min 17s ago
  Process: 23601 ExecStart=/usr/bin/mysqld_safe --basedir=/usr (code=exited, status=0/SUCCESS)
  Process: 23589 ExecStartPre=/usr/bin/mysql-systemd-start pre (code=exited, status=0/SUCCESS)
 Main PID: 23601 (code=exited, status=0/SUCCESS);         : 23602 (mysql-systemd-s)
   CGroup: /user.slice/user-0.slice/session-2395.scope/system.slice/mysqld.service
           └─control
             ├─23602 /bin/bash /usr/bin/mysql-systemd-start post
             └─24646 sleep 1

Nov 09 10:05:20 mysql2.mytv.bg systemd[1]: Starting MySQL Community Server...
Nov 09 10:05:21 mysql2.mytv.bg mysqld_safe[23601]: 181109 10:05:21 mysqld_safe Logging to '/var/log/mysqld.log'.
Nov 09 10:05:21 mysql2.mytv.bg mysqld_safe[23601]: 181109 10:05:21 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
[root@mysql2 ~]# systemctl stop mysqld
[root@mysql2 ~]# systemctl status mysqld
● mysqld.service - MySQL Community Server
   Loaded: loaded (/usr/lib/systemd/system/mysqld.service; enabled; vendor preset: disabled)
   Active: inactive (dead) since Fri 2018-11-09 10:07:52 UTC; 4s ago
  Process: 23602 ExecStartPost=/usr/bin/mysql-systemd-start post (code=killed, signal=TERM)
  Process: 23601 ExecStart=/usr/bin/mysqld_safe --basedir=/usr (code=exited, status=0/SUCCESS)
  Process: 23589 ExecStartPre=/usr/bin/mysql-systemd-start pre (code=exited, status=0/SUCCESS)
 Main PID: 23601 (code=exited, status=0/SUCCESS)

Nov 09 10:05:20 mysql2.mytv.bg systemd[1]: Starting MySQL Community Server...
Nov 09 10:05:21 mysql2.mytv.bg mysqld_safe[23601]: 181109 10:05:21 mysqld_safe Logging to '/var/log/mysqld.log'.
Nov 09 10:05:21 mysql2.mytv.bg mysqld_safe[23601]: 181109 10:05:21 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
Nov 09 10:07:52 mysql2.mytv.bg systemd[1]: Stopped MySQL Community Server.
[root@mysql2 ~]# systemctl start mysqld
[root@mysql2 ~]# systemctl status mysqld
● mysqld.service - MySQL Community Server
   Loaded: loaded (/usr/lib/systemd/system/mysqld.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2018-11-09 10:08:06 UTC; 3s ago
  Process: 24711 ExecStartPost=/usr/bin/mysql-systemd-start post (code=exited, status=0/SUCCESS)
  Process: 24698 ExecStartPre=/usr/bin/mysql-systemd-start pre (code=exited, status=0/SUCCESS)
 Main PID: 24710 (mysqld_safe)
   CGroup: /user.slice/user-0.slice/session-2395.scope/system.slice/mysqld.service
           ├─24710 /bin/sh /usr/bin/mysqld_safe --basedir=/usr
           └─25298 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --log-error=/var/log/mysqld.log --open-files-limit=10000...

Nov 09 10:08:04 mysql2.mytv.bg systemd[1]: Starting MySQL Community Server...
Nov 09 10:08:04 mysql2.mytv.bg mysqld_safe[24710]: 181109 10:08:04 mysqld_safe Logging to '/var/log/mysqld.log'.
Nov 09 10:08:04 mysql2.mytv.bg mysqld_safe[24710]: 181109 10:08:04 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
Nov 09 10:08:06 mysql2.mytv.bg systemd[1]: Started MySQL Community Server.