FS#33990 - [systemd] systemd floods its own logs

Attached to Project: Arch Linux
Opened by higuita (higuita) - Sunday, 24 February 2013, 02:04 GMT
Last edited by Tom Gundersen (tomegun) - Thursday, 16 May 2013, 00:47 GMT
Task Type Feature Request
Category Upstream Bugs
Status Closed
Assigned To Dave Reisner (falconindy)
Tom Gundersen (tomegun)
Architecture All
Severity Medium
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 0
Private No

Details

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

also, maybe syslog-ng should not try to respawn so quickly
This task depends upon

Closed by  Tom Gundersen (tomegun)
Thursday, 16 May 2013, 00:47 GMT
Reason for closing:  Upstream
Comment by Alexander F. Rødseth (xyproto) - Monday, 25 February 2013, 23:11 GMT
Thanks for reporting. Please report this feature request upstream, to the systemd developers, and include an url to the ticket here. That way the progress can be easily tracked.
Note that the Arch Linux package maintainers may choose to close this ticket, as it is not solveable on the packaging-level, as far as I know.
Comment by Tom Gundersen (tomegun) - Monday, 25 February 2013, 23:17 GMT
Hm, yeah might make sense to only add one log-entry per timeout period (10 seconds). Now we get a loop as every attempt at starting syslog-ng will write to the log, which will attempt to start syslog-ng.

As Alexander says, please report this upstream.
Comment by higuita (higuita) - Sunday, 31 March 2013, 02:11 GMT
sorry the delay, upstream bug reported here: https://bugs.freedesktop.org/show_bug.cgi?id=62958
Comment by higuita (higuita) - Sunday, 14 April 2013, 14:29 GMT
upstream reports:

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

Loading...