#3139 Issue closed: Syslog and journald in rescue system not showing service logs

Labels: bug, critical / security / legal, blocker

schlomo opened issue at 2024-01-26 13:52:

Current ReaR from master shows a strange problem with regard to logging in the rescue system, for example:

RESCUE rear-u2204:~ # journalctl -u ssh --no-pager --boot
-- No entries --

(I'm connected via SSH)

whereas the original system shows me the log:

root@rear-u2204:/src/rear# journalctl -u ssh --no-pager --boot
Jan 26 13:04:26 rear-u2204 systemd[1]: Starting OpenBSD Secure Shell server...
Jan 26 13:04:26 rear-u2204 sshd[634]: Server listening on 0.0.0.0 port 22.
Jan 26 13:04:26 rear-u2204 sshd[634]: Server listening on :: port 22.
Jan 26 13:04:26 rear-u2204 systemd[1]: Started OpenBSD Secure Shell server.
Jan 26 13:04:34 rear-u2204 sshd[873]: Accepted publickey for root from 192.168.11.6 port 44082 ssh2: RSA SHA256:seEU/B1WR98Ck/27Mh9MARstsMqMyMnv63t30+0w1K8
Jan 26 13:04:34 rear-u2204 sshd[873]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)
Jan 26 13:07:38 rear-u2204 sshd[2141]: Accepted publickey for root from 192.168.11.6 port 45826 ssh2: RSA SHA256:seEU/B1WR98Ck/27Mh9MARstsMqMyMnv63t30+0w1K8
Jan 26 13:07:38 rear-u2204 sshd[2141]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)

Also syslog doesn't work as expected, again on the rescue system:

RESCUE rear-u2204:~ # logger reartest
RESCUE rear-u2204:~ # journalctl --boot -g reartest
-- No entries --

and on the source system it works as expected:

root@rear-u2204:/src/rear# logger reartest
root@rear-u2204:/src/rear# journalctl --boot -g reartest
Jan 26 13:40:34 rear-u2204 root[53389]: reartest

I actually observed this while working on #3138 but didn't want to add this problem into that PR. The problem was identical in appearance on all systems (RHEL 7,8,9 and SLES 12,15 and Ubuntu 20,22).

Especially the syslog problem is very strange as it seems that /dev/log is configured correctly:

RESCUE rear-u2204:~ # systemctl list-sockets
LISTEN                      UNIT                         ACTIVATES               
/dev/log                    systemd-journald.socket      systemd-journald.service
/run/systemd/journal/socket systemd-journald.socket      systemd-journald.service
/run/systemd/journal/stdout systemd-journald.socket      systemd-journald.service
/run/udev/control           systemd-udevd-control.socket systemd-udevd.service
kobject-uevent 1            systemd-udevd-kernel.socket  systemd-udevd.service

5 sockets listed.
Pass --all to see loaded but inactive sockets, too.
RESCUE rear-u2204:~ # systemctl status systemd-journald
● systemd-journald.service - Journal Service
     Loaded: loaded (/usr/lib/systemd/system/systemd-journald.service; static)
     Active: active (running) since Fri 2024-01-26 13:31:15 UTC; 12min ago
TriggeredBy: ● systemd-journald.socket
       Docs: man:systemd-journald.service(8)
             man:systemd-journald.conf(5)
   Main PID: 75 (systemd-journal)
     Status: "Processing requests..."
      Tasks: 1 (limit: 4563)
     Memory: 9.1M
        CPU: 35ms
     CGroup: /system.slice/systemd-journald.service
             └─75 /usr/lib/systemd/systemd-journald

Jan 26 13:31:15 rear-u2204 systemd-journald[75]: Journal started
Jan 26 13:31:15 rear-u2204 systemd-journald[75]: Runtime Journal (/run/log/journal/3a64d7109b544834b661896de0e54ded) is 8.0M, max 77.8M, 69.8M free.
Notice: journal has been rotated since unit was started, output may be incomplete.

Starting Rsyslog also doesn't work because some rsyslog modules are missing:

RESCUE rear-u2204:~ # /etc/scripts/run-syslog
rsyslog internal message (3,-2066): could not load module 'lmnet', errors: trying to load module /usr/lib/x86_64-linux-gnu/rsyslog/lmnet.so: /usr/lib/x86_64-linux-gnu/rsyslog/lmnet.so: cannot open shared object file: No such file or directory [v8.2112.0 try https://www.rsyslog.com/e/2066 ]
Error during class init for object 'conf' - failing...
rsyslogd initializiation failed - global classes could not be initialized.
Did you do a "make install"?
Suggested action: run rsyslogd with -d -n options to see what exactly fails.
rsyslogd: run failed with error -2066 (see rsyslog.h or try https://www.rsyslog.com/e/2066 to learn what that number means)

In general the JournalD log looks very different from the one on the source machine, for example it reports all lines as if they belong to systemd, for example

RESCUE rear-u2204:~ # journalctl -ef --no-pager -n 20
Jan 26 13:45:33 rear-u2204 systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Service
Jan 26 13:45:33 rear-u2204 systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Slice
Jan 26 13:45:33 rear-u2204 systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Socket
Jan 26 13:45:33 rear-u2204 systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Swap
Jan 26 13:45:33 rear-u2204 systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Target
Jan 26 13:45:33 rear-u2204 systemd[1]: Registering bus object implementation for path=/org/freedesktop/systemd1/unit iface=org.freedesktop.systemd1.Timer
Jan 26 13:45:33 rear-u2204 systemd[1]: Registering bus object implementation for path=/org/freedesktop/LogControl1 iface=org.freedesktop.LogControl1
Jan 26 13:45:33 rear-u2204 systemd[1]: Accepted new private connection.
Jan 26 13:45:33 rear-u2204 systemd[1]: Bus private-bus-connection: changing state AUTHENTICATING → RUNNING
Jan 26 13:45:33 rear-u2204 systemd[1]: Got message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/rsyslog_2eservice interface=org.freedesktop.DBus.Properties member=GetAll cookie=1 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Jan 26 13:45:33 rear-u2204 systemd[1]: Failed to read pids.max attribute of cgroup root, ignoring: No data available
Jan 26 13:45:33 rear-u2204 systemd[1]: Sent message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=a{sv} error-name=n/a error-message=n/a
Jan 26 13:45:33 rear-u2204 systemd[1]: Got message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/syslog_2esocket interface=org.freedesktop.DBus.Properties member=Get cookie=2 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Jan 26 13:45:33 rear-u2204 systemd[1]: Sent message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=2 reply_cookie=2 signature=v error-name=n/a error-message=n/a
Jan 26 13:45:33 rear-u2204 systemd[1]: Bus private-bus-connection: changing state RUNNING → CLOSING
Jan 26 13:45:33 rear-u2204 systemd[1]: Bus private-bus-connection: changing state CLOSING → CLOSED
Jan 26 13:45:33 rear-u2204 systemd[1]: Got disconnect on private connection.
Jan 26 13:47:17 rear-u2204 systemd[1]: Received SIGCHLD from PID 632 (less).
Jan 26 13:47:17 rear-u2204 systemd[1]: Child 632 (less) died (code=exited, status=0/SUCCESS)
Jan 26 13:47:17 rear-u2204 systemd[1]: sshd.service: Child 632 belongs to sshd.service.

(while running this I connected via SSH to this box and no new log lines appeared)

This problem makes debugging stuff in the rescue system very difficult and I'd consider it a critical bug.

@rear/contributors do you experience the same? Any ideas what could be the problem here?

schlomo commented at 2024-01-26 13:55:

A quick test with ReaR version 2.6 shows unfortunately exactly the same behaviour 😢

pcahyna commented at 2024-01-27 13:33:

The problem was identical in appearance on all systems (RHEL 7,8,9 and SLES 12,15 and Ubuntu 20,22).

strange, I saw the problem on RHEL 9 (this was the motivation for fixing the rsyslog startup in PR #3041 , which is clearly not a working solution on Ubuntu) but not RHEL 8. syslog messages went to journal there.

schlomo commented at 2024-01-27 17:06:

@pcahyna TBH, I didn't do the logger test on all systems - so that it indeed might have not been a problem on all of them. But I did check for service logs and that was as described above (service logs missing from journal) on all systems. The reason for checking was that the PPDM service fails to start on boot, so I had to check for that.

github-actions commented at 2024-03-28 02:04:

Stale issue message


[Export of Github issue for rear/rear.]