Description of problem: Just notice a journald suicide last night. The time stamp of the renamed journal seems to co-incide with the time around which I was doing three 'git gc --aggressive' on 3 repos of about ~200MB of objects. # dmesg [348608.053513] systemd-journald[25041]: File /var/log/journal/20d601669974400fb740037534e01eda/system.journal corrupted or uncleanly shut down, renaming and replacing. Oct 1 23:51:05 localhost abrt-server: Deleting problem directory '/var/spool/abrt/ccpp-2016-10-01-23:45:56-597' Oct 1 23:51:05 localhost abrt-server: 'post-create' on '/var/spool/abrt/ccpp-2016-10-01-23:45:56-597' exited with 1 Oct 1 23:51:05 localhost abrt-server: Error writing to 'dso_list' Oct 1 23:51:05 localhost abrt-server: Can't open 'maps': [Errno 2] No such file or directory: 'maps' Oct 1 23:46:21 localhost systemd: Started Flush Journal to Persistent Storage. Oct 1 23:46:18 localhost systemd: Starting Flush Journal to Persistent Storage... Oct 1 23:46:18 localhost abrt-hook-ccpp: Failed to create core_backtrace: dwfl_linux_proc_report failed: no error Oct 1 23:46:18 localhost abrt-hook-ccpp: Failed to open ns path: No such file or directory Oct 1 23:46:18 localhost abrt-hook-ccpp: Can't copy /proc/597/mountinfo to mountinfo at '/var/spool/abrt/ccpp-2016-10-01-23:45:56-597.new' Oct 1 23:46:18 localhost abrt-hook-ccpp: Can't open '/proc/597/mountinfo': No such file or directory Oct 1 23:46:18 localhost abrt-hook-ccpp: Can't copy /proc/597/cgroup to cgroup at '/var/spool/abrt/ccpp-2016-10-01-23:45:56-597.new' Oct 1 23:46:18 localhost abrt-hook-ccpp: Can't open '/proc/597/cgroup': No such file or directory Oct 1 23:46:18 localhost abrt-hook-ccpp: Can't copy /proc/597/limits to limits at '/var/spool/abrt/ccpp-2016-10-01-23:45:56-597.new' Oct 1 23:46:18 localhost abrt-hook-ccpp: Can't open '/proc/597/limits': No such file or directory Oct 1 23:46:18 localhost abrt-hook-ccpp: Can't copy /proc/597/maps to maps at '/var/spool/abrt/ccpp-2016-10-01-23:45:56-597.new' Oct 1 23:46:18 localhost abrt-hook-ccpp: Can't open '/proc/597/maps': No such file or directory Oct 1 23:46:18 localhost abrt-hook-ccpp: Failed to get stat for '/proc/597/root': No such file or directory Oct 1 23:46:18 localhost abrt-hook-ccpp: Process 597 (systemd-journald) of user 0 killed by SIGABRT - dumping core Oct 1 23:46:18 localhost systemd: systemd-journald.service: Watchdog timeout (limit 3min)! Version-Release number of selected component (if applicable): systemd-229-13.fc24.x86_64 How reproducible: Once. Steps to Reproduce: 1. do something very busy, like running 3 'git gc --aggressive' on 3 repos of ~200MB objects. 2. 3. Actual results: journald suicide Expected results: no suicide Additional info:
Based on this information, it's hard to say what happened (all those logs come from after the issue, and it would be interesting to see the ones from before and during the issue). So yeah, journald can be killed by systemd if it missed the watchdog ping, for example. It can also kill itself if an assertion fails. Unless you have earlier logs it's not possible to tell what happened here.
The 15 minutes leading up to 'Watchdog timeout (limit 3min)!' is below. dbus and networkmanager seems to be suffering from timeout also. The "System journal (/var/log/journal/) is ... 0B free." seems to be bogus - grep'ing /var/log/message, I have been 0B free for a while - and yet the partition on which /var/log/journal/ resides is not full. # tac /var/log/messages-20161003 | grep 'Oct 1 23' ... Oct 1 23:46:18 localhost systemd: systemd-journald.service: Watchdog timeout (limit 3min)! Oct 1 23:46:18 localhost audit: 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/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:46:18 localhost wpa_supplicant[967]: nl80211: send_and_recv->nl_recvmsgs failed: -33 Oct 1 23:46:18 localhost audit: CONFIG_CHANGE audit_enabled=1 old=1 auid=4294967295 ses=4294967295 subj=system_u:system_r:syslogd_t:s0 res=1 Oct 1 23:46:18 localhost audit: 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/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:46:18 localhost audit: 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/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:46:18 localhost audit: SERVICE_STOP 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/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:46:18 localhost audit: 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/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:46:18 localhost audit: 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/systemd/systemd" hostname=? addr=? terminal=? res=failed' Oct 1 23:46:18 localhost audit: ANOM_ABEND auid=4294967295 uid=0 gid=0 ses=4294967295 subj=system_u:system_r:syslogd_t:s0 pid=597 comm="systemd-journal" exe="/usr/lib/systemd/systemd-journald" sig=6 Oct 1 23:46:18 localhost systemd-journald: Journal started Oct 1 23:46:16 localhost systemd-journald: System journal (/var/log/journal/) is 808.7M, max 808.7M, 0B free. Oct 1 23:41:32 localhost audit: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=sysstat-collect comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:40:55 localhost audit: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=sysstat-collect comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:40:54 localhost systemd: Started system activity accounting tool. Oct 1 23:40:43 localhost systemd: Starting system activity accounting tool... Oct 1 23:39:11 localhost org.gnome.Shell.desktop: (gnome-shell:1199): Gvc-WARNING **: Card callback failure Oct 1 23:36:14 localhost audit: 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/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:35:57 localhost org.gnome.Shell.desktop: Gjs-Message: JS LOG: System monitor applet enabling done Oct 1 23:35:22 localhost org.gnome.Shell.desktop: Gjs-Message: JS LOG: System monitor applet enabling Oct 1 23:35:09 localhost systemd: Started Hostname Service. Oct 1 23:35:09 localhost dbus-daemon[937]: [system] Successfully activated service 'org.freedesktop.hostname1' Oct 1 23:35:09 localhost audit: SERVICE_START 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/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:35:08 localhost systemd: Starting Hostname Service... Oct 1 23:35:06 localhost dbus-daemon[937]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' Oct 1 23:30:48 localhost audit: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=sysstat-collect comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:30:48 localhost audit: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=sysstat-collect comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:30:47 localhost systemd: Started system activity accounting tool. Oct 1 23:30:41 localhost systemd: Starting system activity accounting tool... Oct 1 23:23:55 localhost systemd: NetworkManager-dispatcher.service: Failed with result 'exit-code'. Oct 1 23:23:55 localhost systemd: NetworkManager-dispatcher.service: Unit entered failed state. Oct 1 23:23:55 localhost systemd: Failed to start Network Manager Script Dispatcher Service. Oct 1 23:23:55 localhost systemd: NetworkManager-dispatcher.service: Main process exited, code=exited, status=1/FAILURE Oct 1 23:23:55 localhost systemd: Starting Network Manager Script Dispatcher Service... Oct 1 23:23:55 localhost NetworkManager[1036]: <info> [1475360507.7472] dhcp4 (wlp3s0): state changed bound -> bound Oct 1 23:23:55 localhost NetworkManager[1036]: <info> [1475360507.5222] nameserver '194.168.8.100' Oct 1 23:23:55 localhost NetworkManager[1036]: <info> [1475360507.5221] nameserver '194.168.4.100' Oct 1 23:23:55 localhost nm-dispatcher: Could not get the system bus (The connection is closed). Make sure the message bus daemon is running! Oct 1 23:23:55 localhost NetworkManager[1036]: <info> [1475360507.5221] lease time 3600 Oct 1 23:23:55 localhost dhclient[1197]: bound to 192.168.0.3 -- renewal in 1495 seconds. Oct 1 23:23:55 localhost NetworkManager[1036]: <info> [1475360507.5221] server identifier 192.168.0.1 Oct 1 23:23:54 localhost dbus-daemon[937]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 30000ms) Oct 1 23:23:54 localhost NetworkManager[1036]: <info> [1475360507.5220] gateway 192.168.0.1 Oct 1 23:23:54 localhost dbus-daemon[937]: [system] Failed to activate service 'org.freedesktop.nm_dispatcher': timed out Oct 1 23:23:54 localhost NetworkManager[1036]: <info> [1475360507.5219] plen 24 (255.255.255.0) Oct 1 23:23:54 localhost audit: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Oct 1 23:23:53 localhost dbus-daemon[937]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' Oct 1 23:23:52 localhost NetworkManager[1036]: <info> [1475360507.4339] address 192.168.0.3 Oct 1 23:23:00 localhost dhclient[1197]: DHCPACK from 192.168.0.1 (xid=0xebd41039) Oct 1 23:21:40 localhost dhclient[1197]: DHCPREQUEST on wlp3s0 to 192.168.0.1 port 67 (xid=0xebd41039) Oct 1 23:21:14 localhost systemd: Started system activity accounting tool. Oct 1 23:21:14 localhost audit: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=sysstat-collect comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:21:14 localhost audit: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=sysstat-collect comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Oct 1 23:20:41 localhost systemd: Starting system activity accounting tool... ...
Oct 1 23:46:16 localhost systemd-journald: System journal (/var/log/journal/) is 808.7M, max 808.7M, 0B free. journald will not fill up the disk. It always tries to keep certain percentage free, so "0B free" means that it will delete older logs to not use more space. If you run 'journalctl -x' it will give a longer explanation for this message. So... in your case watchdog timeout of 3 min is not enough. Dunno, we can make it even higher, but I don't know if this is useful. You machine is basically unresponsive, and killing off some daemons might not be such a bad option.
but "unresponsive" itself is *not* a problem! I was running something quite demanding, and I was *expecting* the machine to be unresponsive! That systemd starts chasing its own tail and going crazy by itself, when the machine is fully behaving *as expected*, is the problem. This is systemd going crazy on it own, over a non-problem.
Also, when did "killing off some daemons might not be such a bad option" become an acceptable idea? The rest of my system was doing useful work. When did killing off daemons become acceptable, when the not-a-problem situation is simply that the system is fully engaged in useful work? Daemons are supposed to be long-running and non-intrusive - instead, now you have a deamon that is so needy in getting some attention from the rest of the system that, it would not only commit suicide, but also tell you that it has corrupted some files, to get that attention.
On the issue of corrupting the journal (or claiming to have done so), the older rsyslogd's behavior, of simply ignoring and dropping logs (?) it hasn't gone time to process, might be preferable to journald's suicide. Triggering abrt, go through the whole cycle of creating coredump, etc and more attention-seeking, when in both situations, the log is rendered unreliable.
When the daemon is killed, it is restarted, and no files are corrupted. It clearly says "corrupted or uncleanly shut down". It's great for you that you know that your machine is OK, but please remember that we need a mechanism that is general enough to work on all machines.
This message is a reminder that Fedora 24 is nearing its end of life. Approximately 2 (two) weeks from now Fedora will stop maintaining and issuing updates for Fedora 24. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as EOL if it remains open with a Fedora 'version' of '24'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora 24 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior this bug is closed as described in the policy above. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete.
Fedora 24 changed to end-of-life (EOL) status on 2017-08-08. Fedora 24 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. If you are unable to reopen this bug, please file a new report against the current release. If you experience problems, please add a comment to this bug. Thank you for reporting this bug and we are sorry it could not be fixed.