[opensuse] systemd hides important information for diagnosis of rsyslog.
I have an rsyslog with a configuration error. However: Telcontar:~ # systemctl restart rsyslog Telcontar:~ # It claims success, but it is not true, it fails seconds later:
Telcontar:~ # systemctl status rsyslog rsyslog.service - System Logging Service Loaded: loaded (/usr/lib/systemd/system/rsyslog.service; enabled) Active: failed (Result: start-limit) since Thu, 2013-06-13 23:48:23 CEST; 4s ago Process: 13783 ExecReload=/bin/kill -HUP $MAINPID (code=exited, status=0/SUCCESS) Process: 16495 ExecStart=/usr/sbin/rsyslogd -n $RSYSLOGD_PARAMS (code=exited, status=1/FAILURE) Process: 16491 ExecStartPre=/usr/sbin/rsyslog-service-prepare (code=exited, status=0/SUCCESS) CGroup: name=systemd:/system/rsyslog.service
Jun 13 23:48:23 Telcontar.valinor systemd[1]: Failed to start System Logging Service. Jun 13 23:48:23 Telcontar.valinor systemd[1]: Failed to start System Logging Service. Jun 13 23:48:23 Telcontar.valinor systemd[1]: Failed to start System Logging Service. Jun 13 23:48:23 Telcontar.valinor systemd[1]: Failed to start System Logging Service. Jun 13 23:48:23 Telcontar.valinor systemd[1]: Failed to start System Logging Service. Jun 13 23:48:23 Telcontar.valinor systemd[1]: Failed to start System Logging Service. Jun 13 23:48:23 Telcontar.valinor systemd[1]: Failed to start System Logging Service. Jun 13 23:48:23 Telcontar.valinor systemd[1]: Failed to start System Logging Service. Jun 13 23:48:23 Telcontar.valinor systemd[1]: Failed to start System Logging Service. Jun 13 23:48:23 Telcontar.valinor systemd[1]: Failed to start System Logging Service. Telcontar:~ #
journalctl -n says nothing different. Calling rsyslog says something else that is not in systemd log:
Telcontar:~ # rsyslogd rsyslogd: run failed with error -2207 (see rsyslog.h or try http://www.rsyslog.com/e/2207 to learn what that number means) Telcontar:~ #
Looking at the service call I see it uses the parameter "-n". ExecStart=/usr/sbin/rsyslogd -n $RSYSLOGD_PARAMS If I do, then I get this: which tells me the exact and useful error:
Telcontar:~ # /usr/sbin/rsyslogd -n rsyslogd: error during parsing file /etc/rsyslog.conf, on or before line 262: syntax error on token 'isequal' [try http://www.rsyslog.com/e/2207 ] rsyslogd: CONFIG ERROR: could not interpret master config file '/etc/rsyslog.conf'. [try http://www.rsyslog.com/e/2207 ] rsyslogd: run failed with error -2207 (see rsyslog.h or try http://www.rsyslog.com/e/2207 to learn what that number means) Telcontar:~ #
Why is not systemd logging this output? It has its own log system, it does not depend on syslog working... -- Cheers / Saludos, Carlos E. R. (from 12.3 x86_64 "Dartmouth" at Telcontar)
El 13/06/13 17:56, Carlos E. R. escribió:
Why is not systemd logging this output?
Because: 1. that output is sent to stderr. 2. The unit file has StandardOutput=null as expected, otherwise a feedback loop will ocurr (the messages emitted by rsyslog service messages will be logged to the journal, which in turn will be forwarded to the syslog socket, that will cause a request for a syslog implementation to be activated..goto beggining :-) ) 3. By default StandardError= inherits StandardOutput, if you change StandardError= goto 2 ;) -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
On 2013-06-14 00:46, Cristian Rodríguez wrote:
El 13/06/13 17:56, Carlos E. R. escribió:
Why is not systemd logging this output?
Because:
1. that output is sent to stderr.
2. The unit file has StandardOutput=null as expected, otherwise a feedback loop will ocurr (the messages emitted by rsyslog service messages will be logged to the journal, which in turn will be forwarded to the syslog socket, that will cause a request for a syslog implementation to be activated..goto beggining :-) )
3. By default StandardError= inherits StandardOutput, if you change StandardError= goto 2 ;)
Soo... there is no special case to capture the error /somehow/? -- Cheers / Saludos, Carlos E. R. (from 12.3 x86_64 "Dartmouth" at Telcontar)
El 14/06/13 03:54, Carlos E. R. escribió:
On 2013-06-14 00:46, Cristian Rodríguez wrote:
El 13/06/13 17:56, Carlos E. R. escribió:
Why is not systemd logging this output?
Because:
1. that output is sent to stderr.
2. The unit file has StandardOutput=null as expected, otherwise a feedback loop will ocurr (the messages emitted by rsyslog service messages will be logged to the journal, which in turn will be forwarded to the syslog socket, that will cause a request for a syslog implementation to be activated..goto beggining :-) )
3. By default StandardError= inherits StandardOutput, if you change StandardError= goto 2 ;)
Soo... there is no special case to capture the error /somehow/?
Not at the moment for this particular case, syslog implementations _must_ have stdout and stderr connected to /dev/null otherwise they will trigger a loop.. that said, if the daemon can log its own errors to a separate file, it might be possible. -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
On 2013-06-14 22:40, Cristian Rodríguez wrote:
El 14/06/13 03:54, Carlos E. R. escribió:
Soo... there is no special case to capture the error /somehow/?
Not at the moment for this particular case, syslog implementations _must_ have stdout and stderr connected to /dev/null otherwise they will trigger a loop.. that said, if the daemon can log its own errors to a separate file, it might be possible.
Can't stderr be redirected somewhere else? With bash it is possible. -- Cheers / Saludos, Carlos E. R. (from 12.3 x86_64 "Dartmouth" at Telcontar)
Carlos E. R. wrote:
On 2013-06-14 22:40, Cristian Rodr�guez wrote:
El 14/06/13 03:54, Carlos E. R. escribi�:
Soo... there is no special case to capture the error /somehow/? Not at the moment for this particular case, syslog implementations _must_ have stdout and stderr connected to /dev/null otherwise they will trigger a loop.. that said, if the daemon can log its own errors to a separate file, it might be possible.
Can't stderr be redirected somewhere else? With bash it is possible.
I was just thinking along similar lines -- This is a no-brainer with sysVinit -- and a perfect example of how doing the most trivial things are nearly impossible in the Beta-systemd. -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
В Fri, 14 Jun 2013 23:07:59 +0200 "Carlos E. R." <robin.listas@telefonica.net> пишет:
On 2013-06-14 22:40, Cristian Rodríguez wrote:
El 14/06/13 03:54, Carlos E. R. escribió:
Soo... there is no special case to capture the error /somehow/?
Not at the moment for this particular case, syslog implementations _must_ have stdout and stderr connected to /dev/null otherwise they will trigger a loop.. that said, if the daemon can log its own errors to a separate file, it might be possible.
Can't stderr be redirected somewhere else? With bash it is possible.
ExecStart=/bin/sh -c 'exec rsyslogd -n $RSYSLOGD_PARAMS 2> /somewhere/else'
В Thu, 13 Jun 2013 18:46:51 -0400 Cristian Rodríguez <crrodriguez@opensuse.org> пишет:
El 13/06/13 17:56, Carlos E. R. escribió:
Why is not systemd logging this output?
Because:
1. that output is sent to stderr.
2. The unit file has StandardOutput=null as expected, otherwise a feedback loop will ocurr (the messages emitted by rsyslog service messages will be logged to the journal, which in turn will be forwarded to the syslog socket, that will cause a request for a syslog implementation to be activated..goto beggining :-) )
So you think it is better to completely remove any possibility to find out why rsyslogd failed to start instead of rate-limiting number of failed attempts? Does not systemd already disables socket activation if service failed to start several times in a sequence? Which would give user all information needed to fix the problem and re-enable it?
3. By default StandardError= inherits StandardOutput, if you change StandardError= goto 2 ;)
-- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
В Sat, 15 Jun 2013 09:35:37 +0400 Andrey Borzenkov <arvidjaar@gmail.com> пишет:
В Thu, 13 Jun 2013 18:46:51 -0400 Cristian Rodríguez <crrodriguez@opensuse.org> пишет:
El 13/06/13 17:56, Carlos E. R. escribió:
Why is not systemd logging this output?
Because:
1. that output is sent to stderr.
2. The unit file has StandardOutput=null as expected, otherwise a feedback loop will ocurr (the messages emitted by rsyslog service messages will be logged to the journal, which in turn will be forwarded to the syslog socket, that will cause a request for a syslog implementation to be activated..goto beggining :-) )
So you think it is better to completely remove any possibility to find out why rsyslogd failed to start instead of rate-limiting number of failed attempts?
Does not systemd already disables socket activation if service failed to start several times in a sequence? Which would give user all information needed to fix the problem and re-enable it?
Actually I tested behavior with and without disabling rsyslogd stdout/stderr. Both with and without StandardOutput=inherit in rsyslog if I have error that prevents rsuslogd from starting I get exactly the same behavior - systemd permanently attempts to restart syslog.service spending 50% CPU in system and 50% CPU in user mode. Which is more or less obvious as normal system has quite a lot of logging going on, so rsyslog does not add anything significant here. OTOH removing StandardOutput=inherit from rsyslog.conf allows me to see, *WHY* it did not start: journalctl -b /sbin/rsyslogd -- Logs begin at Sat, 2013-06-15 10:12:46 MSK, end at Sat, 2013-06-15 10:17:02 MSK. -- Jun 15 10:14:35 linux-o0ic.site rsyslogd[1526]: rsyslogd: error during parsing file /etc/rsyslog.d/dummy.conf, on or before line 1: syntax error on token '=' [try http://www.rsyslog.com/e/2207 ] Jun 15 10:14:35 linux-o0ic.site rsyslogd[1526]: rsyslogd: CONFIG ERROR: could not interpret master config file '/etc/rsyslog.conf'. [try http://www.rsyslog.com/e/2207 ] Jun 15 10:14:35 linux-o0ic.site rsyslogd[1526]: rsyslogd: run failed with error -2207 (see rsyslog.h or try http://www.rsyslog.com/e/2207 to learn what that number means) ... (unfortunately those lines are not usually visible in "systemctl status", not sure why). So I fail to see any justification for suppressing rsyslog messages. Carlos, I think it warrants bug report so it can be followed. Additionally, it also demonstrates that systemd does not do any rate limiting on socket-activated services. Which is bad actually. -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
On 06/15/2013 02:28 AM, Andrey Borzenkov wrote:
Additionally, it also demonstrates that systemd does not do any rate limiting on socket-activated services. Which is bad actually.
Rate limiting works here..(factory) what rsyslog you tested in what distro ? ps: changing the syslog service file "StandarOutput" will go against the documenation and the specification for the interaction of syslog and the journal/systemd so you will have to makke your case upstream ;) -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
В Sat, 15 Jun 2013 02:48:31 -0400 Cristian Rodríguez <crrodriguez@opensuse.org> пишет:
On 06/15/2013 02:28 AM, Andrey Borzenkov wrote:
Additionally, it also demonstrates that systemd does not do any rate limiting on socket-activated services. Which is bad actually.
Rate limiting works here..(factory) what rsyslog you tested in what distro ?
openSUSE 12.3. We are here on opensuse@ list, are not we?
ps: changing the syslog service file "StandarOutput" will go against the documenation and the specification for the interaction of syslog and the journal/systemd
That's not a technical argument. Please explain, *what* will go wrong in this case instead of referring to holy book. If we rate limit rsyslog.service itself, we get burst of errors from it every now and then. What problem does it cause? Besides I demonstrated that even in default configuration systemd goes amok when rsyslog cannot be started. So what exactly does suppressing diagnostic output improve beyond making diagnostic impossible?
so you will have to makke your case upstream ;)
I did.
-- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
On 06/15/2013 02:57 AM, Andrey Borzenkov wrote:
That's not a technical argument. Please explain, *what* will go wrong in this case instead of referring to holy book.
I already did in another post..the documentation also explains what will go wrong. "Will create a feedback loop with your implementation where the messages your syslog implementation writes out are fed back to it." Yes, this should not happend, but there is no special unit setting to stop the feedback loop (needed just for syslog btw) -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
В Sat, 15 Jun 2013 03:16:48 -0400 Cristian Rodríguez <crrodriguez@opensuse.org> пишет:
On 06/15/2013 02:57 AM, Andrey Borzenkov wrote:
That's not a technical argument. Please explain, *what* will go wrong in this case instead of referring to holy book.
I already did in another post..the documentation also explains what will go wrong.
"Will create a feedback loop with your implementation where the messages your syslog implementation writes out are fed back to it."
This is loop only if syslogd echoes to stdout/stderr messages that are fed to it. Does rsyslog do it?
Yes, this should not happend, but there is no special unit setting to stop the feedback loop (needed just for syslog btw)
-- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
On 06/15/2013 04:04 AM, Andrey Borzenkov wrote:
This is loop only if syslogd echoes to stdout/stderr messages that are fed to it. Does rsyslog do it?
the error messages that rsyslog emits that get "lost" do so because they are sent to STDERR which is connected to /dev/null to avoid the loop. -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
Cristian RodrC-guez wrote:
On 06/15/2013 04:04 AM, Andrey Borzenkov wrote:
This is loop only if syslogd echoes to stdout/stderr messages that are fed to it. Does rsyslog do it?
the error messages that rsyslog emits that get "lost" do so because they are sent to STDERR which is connected to /dev/null to avoid the loop.
---- It's hard to argue with such perfect, logic-proof reasoning. -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
On 2013-06-15 09:16, Cristian Rodríguez wrote:
"Will create a feedback loop with your implementation where the messages your syslog implementation writes out are fed back to it."
Yes, this should not happend, but there is no special unit setting to stop the feedback loop (needed just for syslog btw)
Syslog is a special case deserving that treatment, IMO. If it fails, many problems can not be traced. -- Cheers / Saludos, Carlos E. R. (from 12.3 x86_64 "Dartmouth" at Telcontar)
On 2013-06-15 08:28, Andrey Borzenkov wrote:
В Sat, 15 Jun 2013 09:35:37 +0400 Andrey Borzenkov <> пишет:
Actually I tested behavior with and without disabling rsyslogd stdout/stderr.
Both with and without StandardOutput=inherit in rsyslog if I have error that prevents rsuslogd from starting I get exactly the same behavior - systemd permanently attempts to restart syslog.service spending 50% CPU in system and 50% CPU in user mode. Which is more or less obvious as normal system has quite a lot of logging going on, so rsyslog does not add anything significant here.
This happened to me. On some circumstances, if the looping is fast, sysmtemd notices and stops trying. Under certain limit, it respawn in a loop, consuming 100% cpu of one core, heating it up (the load was not spread, that's why I noticed). I wrote about that in another email.
Carlos, I think it warrants bug report so it can be followed.
Certainly. Huh, impossible, I get the "page is redirecting improperly", impossible to log in, even after clearing cookies (novell and attachmate). Finally... it took a long time. Bug 825135 - systemd rsyslog unit has problems in 12.3 (and factory) with reporting errors about itself What component do we use for systemd? There is no init, systemd, syslog... I selected maintenance. :-?
Additionally, it also demonstrates that systemd does not do any rate limiting on socket-activated services. Which is bad actually.
It does, but not always. I reported about that here. -- Cheers / Saludos, Carlos E. R. (from 12.3 x86_64 "Dartmouth" at Telcontar)
El 13/06/13 17:56, Carlos E. R. escribió:
I have an rsyslog with a configuration error.
However:
Telcontar:~ # systemctl restart rsyslog Telcontar:~ #
It claims success, but it is not true, it fails seconds later:
Fixed, I will send a patch to rsyslog upstream ;) systemctl restart rsyslog.service Job for rsyslog.service failed. See 'systemctl status rsyslog.service' and 'journalctl -xn' for details. -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
El 13/06/13 21:04, Cristian Rodríguez escribió:
El 13/06/13 17:56, Carlos E. R. escribió:
I have an rsyslog with a configuration error.
However:
Telcontar:~ # systemctl restart rsyslog Telcontar:~ #
It claims success, but it is not true, it fails seconds later:
To explain it better, it doesnt claim success, they daemon fails later, remember systemctl start/stop/restart is asynchronous ! I crafted a one-liner for the rsyslog package, so it notifies systemd when the startup is really a success. --- rsyslog-7.3.14.orig/tools/syslogd.c +++ rsyslog-7.3.14/tools/syslogd.c @@ -2033,7 +2033,7 @@ int realMain(int argc, char **argv) close(2); ourConf->globals.bErrMsgToStderr = 0; } - + sd_notify(0, "READY=1"); mainloop(); /* do any de-init's that need to be done AFTER this comment */ -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
On 6/14/2013 12:22 AM, Cristian Rodríguez wrote:
El jue 13 jun 2013 21:17:08 CLT, Cristian Rodríguez escribió:
- + sd_notify(0, "READY=1"); mainloop();
fixed in SR #178930
Just for the record I do notice and appreciate that you do a lot of work to fix things in other code that doesn't play well with systemd where possible. I just hate that the assumption is that that's always an option, and when it's not an option, oh well too bad get other software. -- bkw -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
On 06/14/2013 01:00 AM, Brian K. White wrote:
On 6/14/2013 12:22 AM, Cristian Rodríguez wrote:
El jue 13 jun 2013 21:17:08 CLT, Cristian Rodríguez escribió:
- + sd_notify(0, "READY=1"); mainloop();
fixed in SR #178930
Just for the record I do notice and appreciate that you do a lot of work to fix things in other code that doesn't play well with systemd where possible.
In this case it is an option as rsyslog has native systemd/journal/socket activation upstream, plus, as you can see the fix is a one-liner. submitted to upstream also. ;) -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
On 06/14/2013 12:22 AM, Cristian Rodríguez wrote:
El jue 13 jun 2013 21:17:08 CLT, Cristian Rodríguez escribió:
- + sd_notify(0, "READY=1"); mainloop();
fixed in SR #178930
Accepted now in upstream.. neeeeeeeeeeeeeext :-) -- To unsubscribe, e-mail: opensuse+unsubscribe@opensuse.org To contact the owner, e-mail: opensuse+owner@opensuse.org
participants (5)
-
Andrey Borzenkov -
Brian K. White -
Carlos E. R. -
Cristian Rodríguez -
Linda Walsh