Bug 62958

Summary:	systemd floods its own logs and eats the all the CPU
Product:	systemd	Reporter:	higuita
Component:	general	Assignee:	systemd-bugs
Status:	RESOLVED FIXED	QA Contact:	systemd-bugs
Severity:	normal
Priority:	medium	CC:	freedesktop
Version:	unspecified
Hardware:	Other
OS:	Linux (All)
Whiteboard:
i915 platform:		i915 features:

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.