systemd-journald is missing logs on fresh droplets. journalctl shows nothing for any unit.
$ journalctl No journal files were found. -- No entries --
That's not right. There should at least be some system logs there. Check any unit and find no entries.
It seems like restarting systemd-journald or rebooting works around the issue, so its present only on fresh droplets. Originally observed on DigitalOcean's 20180424.4 image and doing a rolling upgrade to 28.20180425.0 addressed the issue - but that probably only worked because of the reboot. Since fresh 28.20180425.0 droplets now also have the systemd-journald issue.
systemd-journald
20180424.4
28.20180425.0
● ostree://fedora-atomic:fedora/28/x86_64/atomic-host Version: 28.20180425.0 (2018-04-25 19:14:57) Commit: 94a9d06eef34aa6774c056356d3d2e024e57a0013b6f8048dbae392a84a137ca GPGSignature: Valid signature by 128CF232A9371991C8A65695E08E7E629DB62FB1
https://twitter.com/dghubble/status/993277668828168192
I booted up an F28AH in Digital Ocean and started to look around.
There's definitely a journal file present, but I'm not sure why the systemd-journald service isn't reading it.
[root@fedoraatomic-s-1vcpu-1gb-nyc1-01 ~]# ls -latr /var/log/journal/4eddc7982ffd4847a32ecd3f6d3170d7/ total 8192 drwxr-sr-x+ 3 root systemd-journal 46 May 11 14:40 .. drwxr-sr-x+ 2 root systemd-journal 28 May 11 14:40 . -rw-r-----+ 1 root systemd-journal 8388608 May 11 14:42 system.journal [root@fedoraatomic-s-1vcpu-1gb-nyc1-01 ~]# file /var/log/journal/4eddc7982ffd4847a32ecd3f6d3170d7/system.journal /var/log/journal/4eddc7982ffd4847a32ecd3f6d3170d7/system.journal: Journal file, online [root@fedoraatomic-s-1vcpu-1gb-nyc1-01 ~]# journalctl -n 10 --file=/var/log/journal/4eddc7982ffd4847a32ecd3f6d3170d7/system.journal -- Logs begin at Fri 2018-05-11 14:40:34 UTC, end at Fri 2018-05-11 14:42:03 UTC. -- May 11 14:41:00 fedoraatomic-s-1vcpu-1gb-nyc1-01 systemd[1]: Startup finished in 1.716s (kernel) + 2.671s (initrd) + 23.610s (userspace) = 27.998s. May 11 14:41:00 fedoraatomic-s-1vcpu-1gb-nyc1-01 rpm-ostree[1287]: In idle state; will auto-exit in 60 seconds May 11 14:41:00 fedoraatomic-s-1vcpu-1gb-nyc1-01 rpm-ostree[1287]: Allowing active client :1.21 (uid 0) May 11 14:41:00 fedoraatomic-s-1vcpu-1gb-nyc1-01 rpm-ostree[1287]: client :1.21 (uid 0) added; new total=1 May 11 14:41:00 fedoraatomic-s-1vcpu-1gb-nyc1-01 rpm-ostree[1287]: client :1.21 (uid 0) vanished; remaining=0 May 11 14:41:00 fedoraatomic-s-1vcpu-1gb-nyc1-01 rpm-ostree[1287]: In idle state; will auto-exit in 63 seconds May 11 14:41:05 fedoraatomic-s-1vcpu-1gb-nyc1-01 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/l> May 11 14:41:21 fedoraatomic-s-1vcpu-1gb-nyc1-01 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/syste> May 11 14:42:03 fedoraatomic-s-1vcpu-1gb-nyc1-01 rpm-ostree[1287]: In idle state; will auto-exit in 61 seconds May 11 14:42:03 fedoraatomic-s-1vcpu-1gb-nyc1-01 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=rpm-ostreed comm="systemd" exe="/usr/lib/systemd/sys [root@fedoraatomic-s-1vcpu-1gb-nyc1-01 ~]# journalctl -u systemd-journald --file=/var/log/journal/4eddc7982ffd4847a32ecd3f6d3170d7/system.journal -- Logs begin at Fri 2018-05-11 14:40:34 UTC, end at Fri 2018-05-11 14:42:03 UTC. -- May 11 14:40:34 localhost systemd-journald[185]: Journal started May 11 14:40:34 localhost systemd-journald[185]: Runtime journal (/run/log/journal/4eddc7982ffd4847a32ecd3f6d3170d7) is 6.1M, max 49.2M, 43.0M free. May 11 14:40:37 localhost systemd-journald[185]: Journal stopped May 11 14:40:38 localhost.localdomain systemd-journald[612]: Journal started May 11 14:40:38 localhost.localdomain systemd-journald[612]: Runtime journal (/run/log/journal/4eddc7982ffd4847a32ecd3f6d3170d7) is 6.1M, max 49.2M, 43.0M free. May 11 14:40:39 localhost.localdomain systemd-journald[612]: Runtime journal (/run/log/journal/4eddc7982ffd4847a32ecd3f6d3170d7) is 6.1M, max 49.2M, 43.0M free. May 11 14:40:40 localhost.localdomain systemd-journald[612]: Time spent on flushing to /var is 46.350ms for 768 entries.
When the systemd-journald service is restarted, it creates a new directory under /var/log/journal
/var/log/journal
[root@fedoraatomic-s-1vcpu-1gb-nyc1-01 ~]# systemctl restart systemd-journald [root@fedoraatomic-s-1vcpu-1gb-nyc1-01 ~]# journalctl --list-boots 0 619b79e423a8400bbc348657c5c641d9 Fri 2018-05-11 15:07:24 UTC—Fri 2018-05-11 15:07:24 UTC [root@fedoraatomic-s-1vcpu-1gb-nyc1-01 ~]# ls -la /var/log/journal/ total 0 drwxr-sr-x+ 4 root systemd-journal 86 May 11 15:07 . drwxr-xr-x. 8 root root 199 May 11 14:40 .. drwxr-sr-x+ 2 root systemd-journal 28 May 11 14:40 4eddc7982ffd4847a32ecd3f6d3170d7 drwxr-sr-x+ 2 root systemd-journal 28 May 11 15:07 821032e961bc6d04ca1012bc5af5ab7c [root@fedoraatomic-s-1vcpu-1gb-nyc1-01 ~]# ls -la /var/log/journal/821032e961bc6d04ca1012bc5af5ab7c/ total 8192 drwxr-sr-x+ 2 root systemd-journal 28 May 11 15:07 . drwxr-sr-x+ 4 root systemd-journal 86 May 11 15:07 .. -rw-r-----+ 1 root systemd-journal 8388608 May 11 15:07 system.journal [root@fedoraatomic-s-1vcpu-1gb-nyc1-01 ~]# journalctl -b -- Logs begin at Fri 2018-05-11 15:07:24 UTC, end at Fri 2018-05-11 15:07:24 UTC. -- May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 systemd-journald[612]: Received SIGTERM from PID 1 (systemd). May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 systemd[1]: Stopping Journal Service... May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 systemd[1]: Stopped Journal Service. May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 systemd[1]: Starting Journal Service... May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 systemd-journald[1655]: Journal started May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 systemd-journald[1655]: System journal (/var/log/journal/821032e961bc6d04ca1012bc5af5ab7c) is 8.0M, max 2.3G, 2.3G free. May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/system> May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 systemd[1]: Started Journal Service. May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 audit: CONFIG_CHANGE audit_enabled=1 old=1 auid=4294967295 ses=4294967295 subj=system_u:system_r:syslogd_t:s0 res=1 May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/syste> May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 systemd[1]: Starting Flush Journal to Persistent Storage... May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-journal-flush comm="systemd" exe="/usr/lib/> May 11 15:07:24 fedoraatomic-s-1vcpu-1gb-nyc1-01 systemd[1]: Started Flush Journal to Persistent Storage.
I booted the corresponding qcow2 locally on my workstation and did not observe the same issue.
Hmm...this might get us closer to the answer. On the local VM which did not observe the problem, the value of /etc/machine-id matches the value of the directory where the journal is stored on disk:
/etc/machine-id
# cat /etc/machine-id ecb200d1e3564c7f86ec7d31dc967204 # ls -l /var/log/journal/ total 0 drwxr-sr-x+ 2 root systemd-journal 28 May 11 15:21 ecb200d1e3564c7f86ec7d31dc967204
But on the Digital Ocean droplet, those values are out of sync:
[root@fedoraatomic-s-1vcpu-1gb-nyc1-01 ~]# cat /etc/machine-id 821032e961bc6d04ca1012bc5af5ab7c [root@fedoraatomic-s-1vcpu-1gb-nyc1-01 ~]# ls -l /var/log/journal/ total 0 drwxr-sr-x+ 2 root systemd-journal 28 May 11 14:40 4eddc7982ffd4847a32ecd3f6d3170d7
Only after the systemd-journald service is restarted, does the matching entry show up.
I'm unable to find any smoking gun in the journal file as to where that early machine-id is coming from, though.
The Digital Ocean droplets look like they are initializing the machine-id twice, the second time looks like something getting passed in via cloud-init. Compare the entries in the journal between the Digital Ocean droplet and the local VM:
cloud-init
Digital Ocean:
# journalctl --no-pager --file /var/log/journal/05f14c08dd2f423d9dd490477487bc74/system.journal | grep machine May 11 15:35:45 localhost systemd[1]: Initializing machine ID from KVM UUID. May 11 15:35:48 localhost.localdomain systemd[1]: Initializing machine ID from KVM UUID. May 11 15:35:48 localhost.localdomain systemd[1]: Installed transient /etc/machine-id file. May 11 15:35:49 localhost.localdomain systemd[1]: Starting Commit a transient machine-id on disk... May 11 15:35:49 localhost.localdomain systemd[1]: Started Commit a transient machine-id on disk. May 11 15:35:49 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-machine-id-commit comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' May 11 15:35:49 localhost.localdomain kernel: audit: type=1130 audit(1526052949.238:77): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-machine-id-commit comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' May 11 15:36:01 fedoraatomic-s-1vcpu-1gb-nyc1-01 cloud-init[1235]: Initializing machine ID from D-Bus machine ID.
Local VM:
# journalctl --no-pager --file /var/log/journal/ecb200d1e3564c7f86ec7d31dc967204/system.journal | grep machine May 11 15:21:23 localhost systemd[1]: Initializing machine ID from KVM UUID. May 11 15:21:27 localhost.localdomain systemd[1]: Initializing machine ID from KVM UUID. May 11 15:21:27 localhost.localdomain systemd[1]: Installed transient /etc/machine-id file. May 11 15:21:28 localhost.localdomain systemd[1]: Starting Commit a transient machine-id on disk... May 11 15:21:28 localhost.localdomain systemd[1]: Started Commit a transient machine-id on disk. May 11 15:21:28 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-machine-id-commit comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' May 11 15:22:52 atomichost-by-dustymabe dbus-daemon[735]: [system] Activating via systemd: service name='org.freedesktop.machine1' unit='dbus-org.freedesktop.machine1.service' requested by ':1.18' (uid=0 pid=1277 comm="machinectl " label="unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023") May 11 15:22:52 atomichost-by-dustymabe dbus-daemon[735]: [system] Successfully activated service 'org.freedesktop.machine1' May 11 15:22:52 atomichost-by-dustymabe audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-machined comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
I think we need to talk to someone on the Digital Ocean side about what they are doing in cloud-init to cause this to happen.
Metadata Update from @dustymabe: - Issue assigned to katrinaeg
Assigning to @katrinaeg from DO
This is a bit of a pickle because the fedora-27-x64-atomic image has disappeared. I suppose just restarting systemd-journald via cloudinit on first boot (i.e. bootcmd) would be a workaround for now.
fedora-27-x64-atomic
To followup, bootcmd seems too early to be a workaround. What I suggested does NOT work.
bootcmd: - [systemctl, restart, systemd-journald]
To followup, bootcmd seems too early to be a workaround. What I suggested does NOT work. bootcmd: - [systemctl, restart, systemd-journald]
yeah since that probably happens before cloud-init stuff runs. What about a runcmd? You might need to add --no-block: - [systemctl, restart, --no-block, systemd-journald]
runcmd
--no-block
- [systemctl, restart, --no-block, systemd-journald]
We have deployed a fix for this issue. Newly created Fedora Atomic droplets on DigitalOcean now have a working systemd-journald with logs at boot.
Woo! Just confirmed this myself! Thanks DO peeps!
Thanks @ryanpq
Metadata Update from @dustymabe: - Issue close_status updated to: Fixed - Issue status updated to: Closed (was: Open)
Login to comment on this ticket.