Bug 62958 - systemd floods its own logs and eats the all the CPU
Summary: systemd floods its own logs and eats the all the CPU
Status: RESOLVED FIXED
Alias: None
Product: systemd
Classification: Unclassified
Component: general (show other bugs)
Version: unspecified
Hardware: Other Linux (All)
: medium normal
Assignee: systemd-bugs
QA Contact: systemd-bugs
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2013-03-31 02:07 UTC by higuita
Modified: 2014-06-25 09:56 UTC (History)
1 user (show)

See Also:
i915 platform:
i915 features:


Attachments

Description higuita 2013-03-31 02:07:32 UTC
Reporting problem upstream, as requested in https://bugs.archlinux.org/task/33990

here is a copy of the problem reported:

+++++++++++++++++++++++++++++++

I made a mistake configuring the syslog-ng (my fault) and a few minutes later found that systemd was eating all the cpu.
A simple dmesg showed the problem:

[ 865.485322] systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.

trying to find the origin of the problem, i got:

# journalctl -xn
-- Logs begin at Sáb 2013-02-23 21:22:54 WET, end at Dom 2013-02-24 01:37:39 WET. --
Fev 24 01:37:39 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:37:39 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:37:39 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:37:39 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:37:39 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:37:39 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:37:39 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:37:39 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:37:39 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:37:39 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.


# systemctl status syslog-ng.service
syslog-ng.service - System Logger Daemon
Loaded: loaded (/usr/lib/systemd/system/syslog-ng.service; enabled)
Active: failed (Result: start-limit) since Dom 2013-02-24 01:37:58 WET; 5s ago
Docs: man:syslog-ng(8)
Process: 2494 ExecStart=/usr/sbin/syslog-ng -F (code=exited, status=1/FAILURE)

Fev 24 01:38:02 paquete.motaleite.net systemd[1]: Failed to start System Logger Daemon.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: Failed to start System Logger Daemon.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: Failed to start System Logger Daemon.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: Failed to start System Logger Daemon.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: Failed to start System Logger Daemon.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: Failed to start System Logger Daemon.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: Failed to start System Logger Daemon.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: Failed to start System Logger Daemon.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.
Fev 24 01:38:02 paquete.motaleite.net systemd[1]: syslog-ng.service start request repeated too quickly, refusing to start.

so only useless info because systemd is busy flooding its own logs, hiding the real problem.

after some tries using systemd, i gave up and debug syslog-ng manually:

# /usr/sbin/syslog-ng -F
Error parsing config, duplicate destination definition in /etc/syslog-ng/syslog-ng.conf at line 96, column 1:

destination d_mail { file("/var/log/maillog"); };
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

syslog-ng documentation: http://www.balabit.com/support/documentation/?product=syslog-ng
mailing list: https://lists.balabit.hu/mailman/listinfo/syslog-ng

So there, this is what systemd should have reported in the very beginning!

So what i recommend is that systemd should merge identical messages or at very least, ignore it own flood messages

++++++++++++++++++++++

Of course, even without the log flooding, the respawn of a failling daemon too fast is also a problem, it only eats cpu and logs... i can also open one bug for this one if you want.
Comment 1 Simon Peeters 2013-04-14 12:32:32 UTC
Could it be that your syslog-ng.service file is missing a "RestartPreventExitStatus=" line?

if syslog-ng uses the exit values from sysexits.h it sould be:
[Service]
RestartPreventExitStatus=78

this will prevent systemd from restarting your service when it exits with code 78 (EX_CONFIG). see systemd.service(5) for more details
Comment 2 Peter Alfredsen 2013-05-30 11:03:31 UTC
Be that as it may, we can't really predict all the conditions that will cause $RANDOM_DAEMON to exit quickly, so systemd really should have some way of detecting at least the:
start....
5 seconds
FAIL!
case if it repeats more than $SMALL_INT times and Do The Right Thing. Defaulting to spamming the logs till drive space runs out just looks Stupid
Comment 3 Lennart Poettering 2014-06-25 09:56:03 UTC
This should be fixed now, as as service failing conitnously will now propagate back to the socket unit that activates it.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.