Bug 1270616 - journald self-destructs when system hibernates, or running 'git gc'
Summary: journald self-destructs when system hibernates, or running 'git gc'
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: systemd
Version: 27
Hardware: x86_64
OS: Linux
unspecified
unspecified
Target Milestone: ---
Assignee: systemd-maint
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-10-11 22:23 UTC by Hin-Tak Leung
Modified: 2018-11-30 18:35 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-11-30 18:35:34 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Hin-Tak Leung 2015-10-11 22:23:08 UTC
Description of problem:
I have seen this behavior twice recently, so decided to report it. After a recent hibernate/resume, I saw in dmesg:

[88711.574250] systemd[1]: systemd-journald.service watchdog timeout (limit 1min)!
[88801.680874] systemd[1]: systemd-journald.service stop-sigabrt timed out. Terminating.
[88891.930829] systemd[1]: systemd-journald.service stop-sigterm timed out. Killing.
[88982.180840] systemd[1]: systemd-journald.service still around after SIGKILL. Ignoring.
[89072.430842] systemd[1]: systemd-journald.service stop-final-sigterm timed out. Killing.
[89103.921474] systemd[1]: Starting system activity accounting tool...
[89106.508213] systemd[1]: Started system activity accounting tool.
[89162.680761] systemd[1]: systemd-journald.service still around after final SIGKILL. Entering failed mode.
[89162.681570] systemd[1]: Unit systemd-journald.service entered failed state.
[89162.681757] systemd[1]: systemd-journald.service failed.
[89162.683315] systemd[1]: systemd-journald.service has no holdoff time, scheduling restart.
[89162.685185] systemd[1]: Stopping Flush Journal to Persistent Storage...
[89162.687910] systemd[1]: Starting Journal Service...
[89163.472244] systemd-journald[9479]: File /var/log/journal/20d601669974400fb740037534e01eda/system.journal corrupted or uncleanly shut down, renaming and replacing.
[89164.332305] systemd[1]: Started Journal Service.
[89164.984684] systemd-journald[9479]: File /var/log/journal/20d601669974400fb740037534e01eda/user-1000.journal corrupted or uncleanly shut down, renaming and replacing.

abrt-cli list gives:

id e9cd0ed88057b981cbe50cd8bcd3473eff842d8b
reason:         systemd-journald killed by SIGABRT
time:           Sun 11 Oct 2015 21:24:16 BST
cmdline:        /usr/lib/systemd/systemd-journald
package:        systemd-219-24.fc22
uid:            0 (root)
count:          1
Directory:      /var/spool/abrt/ccpp-2015-10-11-21:24:15-532

and "gdb /usr/lib/systemd/systemd-journald /var/spool/abrt/ccpp-2015-10-11-21:24:15-532/coredump" gives:

(gdb) bt
#0  0x00005570b3192bc7 in journal_file_find_data_object_with_hash ()
#1  0x00005570b3193502 in journal_file_append_data.lto_priv ()
#2  0x00005570b31a1cf1 in journal_file_append_entry.constprop ()
#3  0x00005570b318dc4b in dispatch_message_real.lto_priv ()
#4  0x00005570b31b55ec in server_dispatch_message ()
#5  0x00005570b3195ea6 in stdout_stream_log ()
#6  0x00005570b31966eb in stdout_stream_line.lto_priv ()
#7  0x00005570b31acc48 in stdout_stream_scan ()
#8  0x00005570b31ace41 in stdout_stream_process ()
#9  0x00005570b31a68a0 in source_dispatch ()
#10 0x00005570b31a7450 in sd_event_dispatch ()
#11 0x00005570b3188d6e in main ()
(gdb) q

I have also seen journald self-destructs like this recently when I did a "git fetch --all" in my misc kernel tree clone, which inadvertently triggers a "git gc --auto" (I think), and journald self-destructs every 15 minutes and generates corrupted /var/log/journal/20d601669974400fb740037534e01eda/*~ every 15 minutes or so, for just over an hour i.e. it repeatedly self-destructs 4 or 5 times like above.

Version-Release number of selected component (if applicable):
systemd-219-24.fc22

How reproducible:
quite often lately, more than twice.

Steps to Reproduce:
1. hibernate (echo -n 'disk' > /sys/power/state), or "git gc" in a large clone to make system busy
2.
3.

Actual results:
journald self-destructs and generates corrupted journals every 15 minutes or so, repeatedly.

Expected results:
journald does not self-destruct.

Additional info:

Comment 1 Michal Sekletar 2015-10-12 07:24:32 UTC
This is known issue. If your I/O is painfully slow and journald is blocked in some system call waiting for I/O request to complete then it can miss to send watchdog ping and will be SIGABRT'ed by systemd.

Recently this has changed upstream and default watchdog timeout is now set to 3min instead of 1min. I think we should backport this change to F22 and F23. In the meantime, please adjust your config locally and bump WatchdogSec to some higher value.

Comment 2 Hin-Tak Leung 2015-10-15 22:59:06 UTC
(In reply to Michal Sekletar from comment #1)
> This is known issue. If your I/O is painfully slow and journald is blocked
> in some system call waiting for I/O request to complete then it can miss to
> send watchdog ping and will be SIGABRT'ed by systemd.
> 
> Recently this has changed upstream and default watchdog timeout is now set
> to 3min instead of 1min. I think we should backport this change to F22 and
> F23. In the meantime, please adjust your config locally and bump WatchdogSec
> to some higher value.

I am surprised that the 'config' is not in
/etc/systemd/journald.conf

but in 
/usr/lib/systemd/system/systemd-journald.service

and not really considered 'config'.
(I did a 'rpm -ql systemd | xargs grep WatchdogSec' to find out where...)

$ grep -R WatchdogSec units/

units/systemd-timedated.service.in:WatchdogSec=1min
units/systemd-timesyncd.service.in:WatchdogSec=1min
units/systemd-journald.service.in:WatchdogSec=1min   <--------------
units/systemd-udevd.service.in:WatchdogSec=1min
units/systemd-importd.service.in:WatchdogSec=1min
units/systemd-hostnamed.service.in:WatchdogSec=1min
units/systemd-resolved.service.m4.in:WatchdogSec=1min
units/systemd-machined.service.in:WatchdogSec=1min
units/systemd-logind.service.in:WatchdogSec=1min
units/systemd-journal-remote.service.in:WatchdogSec=10min
units/systemd-journal-upload.service.in:WatchdogSec=20min
units/systemd-networkd.service.m4.in:WatchdogSec=1min
units/systemd-localed.service.in:WatchdogSec=1min

I just clone'ed the systemd repository and did not see it - it is still 1 min?

Comment 3 Hin-Tak Leung 2015-11-02 22:24:18 UTC
I just observed the same behavior when my system goes into suspend, under f23.

# rpm -q systemd
systemd-222-8.fc23.x86_64

Comment 4 Hin-Tak Leung 2015-11-02 22:27:10 UTC
since the units files are not officially a 'config', the work-around got overwritten after I upgraded from f22 to f23.

Comment 5 Hin-Tak Leung 2015-11-04 21:18:41 UTC
still a prob in f23.

Comment 6 Fedora End Of Life 2016-11-24 12:45:36 UTC
This message is a reminder that Fedora 23 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 23. 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 '23'.

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 23 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.

Comment 7 Fedora End Of Life 2016-12-20 14:57:30 UTC
Fedora 23 changed to end-of-life (EOL) status on 2016-12-20. Fedora 23 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.

Comment 8 Hin-Tak Leung 2017-01-13 10:38:56 UTC
Saw it recently on fedora 25 when icecat dies which causes abrt to run, which in turn causes journald to self-destruct and causes abrt to run afterwards. This effectively doubles the work load of abrt...

Comment 9 Fedora End Of Life 2017-11-16 19:24:12 UTC
This message is a reminder that Fedora 25 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 25. 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 '25'.

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 25 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.

Comment 10 Hin-Tak Leung 2017-12-04 21:53:23 UTC
Seen it in late fc26 / early fc27 . Hence bumping version.

Comment 11 Ben Cotton 2018-11-27 17:56:31 UTC
This message is a reminder that Fedora 27 is nearing its end of life.
On 2018-Nov-30  Fedora will stop maintaining and issuing updates for
Fedora 27. 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 '27'.

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 27 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.

Comment 12 Ben Cotton 2018-11-30 18:35:34 UTC
Fedora 27 changed to end-of-life (EOL) status on 2018-11-30. Fedora 27 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.


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