Bug 1057883 - systemd journal corrupted, everything slows down
Summary: systemd journal corrupted, everything slows down
Keywords:
Status: CLOSED DUPLICATE of bug 1043212
Alias: None
Product: Fedora
Classification: Fedora
Component: systemd
Version: 20
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: systemd-maint
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-01-25 18:20 UTC by Tom Horsley
Modified: 2014-02-17 14:49 UTC (History)
10 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2014-02-17 14:49:23 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
The /var/log/messages showing yum update around 11:06 (1.57 MB, text/x-log)
2014-01-25 18:20 UTC, Tom Horsley
no flags Details

Description Tom Horsley 2014-01-25 18:20:29 UTC
Created attachment 855423 [details]
The /var/log/messages showing yum update around 11:06

Description of problem:

I once thought this issue was caused only by cron.daily, but I rebooted recently to clear the previous corruption, and just a few hours later with nothing special having happened to my system, I see this nonsense happening again in the log and things like ssh sessions taking a long time to start as all these errors timeout:

...
Jan 25 12:58:00 zooty systemd-journald[7468]: Failed to write entry (19 items, 554 bytes), ignoring: Invalid argument
Jan 25 12:58:00 zooty systemd-journald[7468]: Failed to write entry (19 items, 481 bytes), ignoring: Invalid argument
Jan 25 12:59:00 zooty systemd-journald[7468]: Failed to write entry (19 items, 554 bytes), ignoring: Invalid argument
Jan 25 12:59:01 zooty systemd-journald[7468]: Failed to write entry (18 items, 597 bytes), ignoring: Invalid argument
Jan 25 12:59:26 zooty dbus[7686]: [system] Failed to activate service 'org.freedesktop.login1': timed out
Jan 25 12:59:26 zooty systemd-journald[7468]: Failed to write entry (18 items, 547 bytes), ignoring: Invalid argument
Jan 25 12:59:48 zooty dbus[7686]: [system] Activating systemd to hand-off: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service'
Jan 25 12:59:48 zooty systemd-journald[7468]: Failed to write entry (18 items, 597 bytes), ignoring: Invalid argument
Jan 25 13:00:00 zooty systemd-journald[7468]: Failed to write entry (19 items, 481 bytes), ignoring: Invalid argument
Jan 25 13:00:13 zooty dbus[7686]: [system] Failed to activate service 'org.freedesktop.login1': timed out
Jan 25 13:00:13 zooty systemd-journald[7468]: Failed to write entry (18 items, 547 bytes), ignoring: Invalid argument
Jan 25 13:00:13 zooty systemd-journald[7468]: Failed to write entry (22 items, 574 bytes), ignoring: Invalid argument
Jan 25 13:00:13 zooty systemd-journald[7468]: Failed to write entry (18 items, 549 bytes), ignoring: Invalid argument
Jan 25 13:00:19 zooty dbus[7686]: [system] Activating systemd to hand-off: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service'
Jan 25 13:00:44 zooty dbus[7686]: [system] Failed to activate service 'org.freedesktop.login1': timed out
Jan 25 13:00:44 zooty systemd-journald[7468]: Failed to write entry (18 items, 547 bytes), ignoring: Invalid argument
Jan 25 13:00:48 zooty su: (to root) tom on pts/0
Jan 25 13:00:48 zooty dbus[7686]: [system] Activating systemd to hand-off: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service'
Jan 25 13:00:48 zooty systemd-journald[7468]: Failed to write entry (18 items, 597 bytes), ignoring: Invalid argument
Jan 25 13:01:13 zooty dbus[7686]: [system] Failed to activate service 'org.freedesktop.login1': timed out
Jan 25 13:01:13 zooty systemd-journald[7468]: Failed to write entry (18 items, 547 bytes), ignoring: Invalid argument
Jan 25 13:01:13 zooty systemd-journald[7468]: Failed to write entry (23 items, 569 bytes), ignoring: Invalid argument
Jan 25 13:01:13 zooty systemd-journald[7468]: Failed to write entry (18 items, 549 bytes), ignoring: Invalid argument
Jan 25 13:01:13 zooty systemd-journald[7468]: Failed to write entry (13 items, 304 bytes), ignoring: Invalid argument
Jan 25 13:01:13 zooty systemd-journald[7468]: Failed to write entry (13 items, 307 bytes), ignoring: Invalid argument
Jan 25 13:04:00 zooty systemd-journald[7468]: Failed to write entry (19 items, 481 bytes), ignoring: Invalid argument
Jan 25 13:05:01 zooty dbus[7686]: [system] Activating systemd to hand-off: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service'
Jan 25 13:05:01 zooty systemd-journald[7468]: Failed to write entry (18 items, 597 bytes), ignoring: Invalid argument
Jan 25 13:05:26 zooty systemd-journald[7468]: Failed to write entry (18 items, 547 bytes), ignoring: Invalid argument
Jan 25 13:05:29 zooty systemd-journald[7468]: Failed to write entry (20 items, 521 bytes), ignoring: Invalid argument
Jan 25 13:05:29 zooty systemd-journald[7468]: Failed to write entry (20 items, 474 bytes), ignoring: Invalid argument
Jan 25 13:06:00 zooty systemd-journald[7468]: Failed to write entry (19 items, 481 bytes), ignoring: Invalid argument
Jan 25 13:07:00 zooty systemd-journald[7468]: Failed to write entry (19 items, 554 bytes), ignoring: Invalid argument
Jan 25 13:07:00 zooty systemd-journald[7468]: Failed to write entry (19 items, 481 bytes), ignoring: Invalid argument
...

Running journalctl --verify gives:

[root@zooty ~]# journalctl --verify
PASS: /var/log/journal/ce1d14df659e254dad8570fc5d633b2b/system~
PASS: /var/log/journal/ce1d14df659e254dad8570fc5d633b2b/user-2304.journal
397cb8: unused data (entry_offset==0)âââââââââââââââââââââââ   0%
Entry timestamp out of synchronization at 398a58
File corruption detected at /var/log/journal/ce1d14df659e254dad8570fc5d633b2b/system~:398a58 (of 8388608 bytes, 44%).
FAIL: /var/log/journal/ce1d14df659e254dad8570fc5d633b2b/system~ (Bad message)
PASS: /var/log/journal/ce1d14df659e254dad8570fc5d633b2b/system.journal
PASS: /var/log/journal/ce1d14df659e254dad8570fc5d633b2b/system
[root@zooty ~]# ls -lR /var/log/journal
/var/log/journal:
total 8
drwxr-sr-x+ 2 root systemd-journal 4096 Jan 25 11:07 ce1d14df659e254dad8570fc5d633b2b

/var/log/journal/ce1d14df659e254dad8570fc5d633b2b:
total 40968
-rw-r-----+ 1 root systemd-journal 8388608 Jan 25 13:01 system.journal
-rw-r-----+ 1 root systemd-journal 8388608 Jan 25 13:01 system~
-rw-r-----+ 1 root systemd-journal 8388608 Jan 25 13:01 system~
-rw-r-----+ 1 root systemd-journal 8388608 Jan 25 13:02 system
-rw-r-----+ 1 root systemd-journal 8388608 Jan 25 08:47 user-2304.journal

The system was last booted at Jan 25 08:42:22 and now at 13:07 it is already screwed up again with no cron.daily having run. I did run a yum update at 11:06 and that seems to be when the trouble started. Some yum cleanup script must do the same bilge as cron.daily. I'll attach /var/log/messages in case there is a hint in there as to the cause.

Version-Release number of selected component (if applicable):
systemd-208-9.fc20.x86_64

How reproducible:
This one has only happened once so far, but who knows what the next yum update will bring.

Steps to Reproduce:
1.yum update seemed to do it this time
2.
3.

Actual results:
System randomly screwed up.

Expected results:
Not screwed up.

Additional info:

Comment 1 Tom Horsley 2014-01-25 19:51:49 UTC
Looking at the rpm -q --scripts for the packages installed by yum, I see the new version of yum has the most suspicious looking scripts, with several systemctl commands involved, including a daemon-reload in one of the scripts.

Comment 2 chen haochuan 2014-02-02 23:22:23 UTC
Do "yum update" on a fresh f20 can reproduce the problem.

Comment 3 Tom Horsley 2014-02-08 00:24:57 UTC
I'm almost completely convinced this is from the same fundamental cause as bug 1043212, just a different symptom cropping up.

Comment 4 Rahul Sundaram 2014-02-17 14:49:23 UTC

*** This bug has been marked as a duplicate of bug 1043212 ***


Note You need to log in before you can comment on or make changes to this bug.