GNOME Bugzilla – Bug 692308
double logging under systemd with journal
Last modified: 2013-02-05 11:34:03 UTC
When running under systemd with the journal, gdm logs everything twice: it configures a syslog log-handler with LOG_PERROR, resulting in one copy of the log message to syslog and one to stderr. systemd captures both syslog messages and stderr, so everything is logged twice. Optionally turning off LOG_PERROR seems the easiest way (or if you'd prefer, it could optionally *only* log to stderr, using printk-style level prefixes: "<3>Something is wrong"). I'd prefer not to set StandardOutput=null or StandardError=null in the .service file, because that would suppress messages from any libraries that aren't GLib-based and complain to stderr instead (e.g. libc complains to stderr just before killing your process, if it detects memory corruption). Because gdm is a cluster of related processes, a command-line option wouldn't work very well: the gdm master would have to pass it on to the slaves, session workers etc. An environment variable passes through nicely, though, so that's what I used. Using sd_booted() would be another option.
Created attachment 234116 [details] [review] Don't use LOG_PERROR under systemd, even when supported systemd logs our stdout/stderr as well as our syslog output, so we'd duplicate most messages otherwise. Signed-off-by: Simon McVittie <simon.mcvittie@collabora.co.uk>
Now that bug 676181 has landed. I think i'd like to drop syslog() stuff entirely if compiled with journald support enabled.
That would work too; I'm not working from bleeding-edge git right now, but I'll try to get a test setup for that going. (Are there any tricks for using a jhbuilt copy of gdm in a virtual machine? Or should I be using ostree?)
gdm doesn't run in a jhbuild environment atm. I personally just do a dirty "make install" with --sysconfdir=/etc --prefix=/usr --localstatedir=/var
What we really should do is: 1) Figure out what the Right Thing for GLib-based daemons is wrt logging when on a no-syslog-only-journald system - basically what do g_log() g_warning() etc. do? 2) Figure out how to make GLib do said Right Thing by default Doing 1) though will involve some experimentation, thought, and "baking time" before we try doing 2) in my opinion. So it's good for us to iterate here in gdm first.
Created attachment 234130 [details] [review] 0001-log-Don-t-use-LOG_PERROR-if-systemd-is-booted.patch Variant of smcv's patch - tested in gnome-ostree (systemd-journal-only system).
Review of attachment 234130 [details] [review]: ::: common/gdm-log.c @@ +32,2 @@ #include <syslog.h> +#ifdef WITH_SYSTEMD maybe should be #ifdef ENABLE_SYSTEMD_JOURNAL @@ +195,3 @@ + * stdout/stderr are already going to the journal, so don't + * duplicate it with syslog. + */ This comment doesn't match the patch. This patch prevents syslog() from doing a fprintf(stderr, ...) internally. It doesn't stop things from going to syslog. But I think we want to stop using openlog()/syslog() when journald is configured, so I'd love a patch that does that. @@ +198,2 @@ #ifdef LOG_PERROR +#ifdef WITH_SYSTEMD definitely should be #ifdef ENABLE_SYSTEMD_JOURNAL @@ +198,3 @@ #ifdef LOG_PERROR +#ifdef WITH_SYSTEMD + if (!(sd_booted > 0)) missing parentheses.
(In reply to comment #7) > Review of attachment 234130 [details] [review]: > > @@ +195,3 @@ > + * stdout/stderr are already going to the journal, so don't > + * duplicate it with syslog. > + */ > > This comment doesn't match the patch. This patch prevents syslog() from doing > a fprintf(stderr, ...) internally. It doesn't stop things from going to > syslog. I'm not sure how to rephrase it better...basically "don't duplicate log output when we're booted as a systemd unit". > But I think we want to stop using openlog()/syslog() when journald is > configured, so I'd love a patch that does that. Sure...but that's a different patch that wouldn't really solve much. Using sd_journal_print() directly is mainly of value when: 1) You want to do structured logging 2) You care about __FILE__ and __LINE__ that the macros inject automatically (Personally I think 2) is kind of lame at the moment since you get build system artifacts like /builddir/buildd/foo/bar/ prepended) > @@ +198,2 @@ > #ifdef LOG_PERROR > +#ifdef WITH_SYSTEMD > > definitely should be #ifdef ENABLE_SYSTEMD_JOURNAL Ok now I thought ENABLE_SYSTEMD_JOURNAL was for "journal only" systems, where we didn't want to change behavior and start dumping everything to syslog. The issue reported here by Simon arises on say Debian booted with systemd (and syslog running), which is quite a different thing. Presumably Debian isn't going to pass --enable-systemd-journal anytime soon. (Perhaps we should rename the option to --enable-journal-only or something) > @@ +198,3 @@ > #ifdef LOG_PERROR > +#ifdef WITH_SYSTEMD > + if (!(sd_booted > 0)) > > missing parentheses. Would you prefer if (sd_booted <= 0) ?
(In reply to comment #8) > > + * stdout/stderr are already going to the journal, so don't > > + * duplicate it with syslog. > > + */ > > > > This comment doesn't match the patch. > I'm not sure how to rephrase it better... An accurate comment would be: * syslog() and GDM's stderr both go to the journal, so don't have syslog() * duplicate its output to stderr. > > But I think we want to stop using openlog()/syslog() when journald is > > configured, so I'd love a patch that does that. > > Sure...but that's a different patch that wouldn't really solve much. Using > sd_journal_print() directly is mainly of value when: I'm not talking about sd_journal_print(). I'm saying: 1) syslog() is a legacy api in a journald world 2) our stdout/err automatically goes to the journal 3) we should never call syslog(), and instead just leverage our stdout/stderr > > @@ +198,3 @@ > > #ifdef LOG_PERROR > > +#ifdef WITH_SYSTEMD > > + if (!(sd_booted > 0)) > > > > missing parentheses. > > Would you prefer if (sd_booted <= 0) ? I was thinking if (!(sd_booted() > 0))
(In reply to comment #9) > > 3) we should never call syslog(), and instead just leverage our stdout/stderr In that model we do lose priority information. Maybe that's not a big deal though. Long term, I *would* like to be able to differentiate as a sysadmin/tester between g_print() and g_critical(). But maybe we just figure out how to solve that GLib side (for example, have it do a query on startup to see if stdout/stderr are systemd journal fds, and automatically doing the right thing).
Created attachment 234156 [details] [review] 0001-log-When-using-systemd-just-log-to-stdout-stderr.patch Ok, I accidentally corrupted my qemu disk, so here's a compile-tested-only patch. But is that more like what you were thinking?
yea. Does that serve your needs, Simon?
Now test booted in gnome-ostree qemu. Noted side effects: We don't get debug logging by default anymore, which appeared to occur before because gdm has this gdm_is_version_unstable () thing which toggled the flag on by default, but it only knows how to do that for syslog, not GLib.
(In reply to comment #8) > Ok now I thought ENABLE_SYSTEMD_JOURNAL was for "journal only" systems, where > we didn't want to change behavior and start dumping everything to syslog. > > The issue reported here by Simon arises on say Debian booted with systemd (and > syslog running), which is quite a different thing. > > Presumably Debian isn't going to pass --enable-systemd-journal anytime soon. > > (Perhaps we should rename the option to --enable-journal-only or something) I'm also interested in having gdm work nicely in Debian, but the environment I'm actually looking at here is one with "native systemd" throughout - the Journal is the only logger, and there is no syslog daemon. Whenever systemd is process 1, it owns /dev/log and collects everyone's syslog() data. This is true whether you have a syslog daemon like rsyslog or not. If you have an external syslog daemon like rsyslog running under systemd, systemd passes on the log messages to that syslog daemon out-of-band. There are three cases that could potentially be supported: 1) init is systemd, /dev/log is owned by systemd, there is a traditional syslog daemon somewhere in the background. (Debian 7 with systemd; Fedora with systemd?) 2) init is systemd, /dev/log is owned by systemd, there is no traditional syslog daemon. (The OS I'm looking at right now.) 3) init is not systemd, there is a traditional syslog daemon, and it owns /dev/log. (Debian 6; Debian 7 with sysvinit; Ubuntu.) As of the latest gdm release, (1) and (2) are actually the same: in both cases, systemd collects both /dev/log and stdout/stderr. In case (1) it feeds both /dev/log messages and stdout/stderr into the traditional syslog daemon for storage, but gdm doesn't need to know that. gdm's logging infrastructure as of the latest release (ignoring the recent changes in master) assumes (3) - it assumes that stdout/stderr don't go anywhere particularly useful, so it has to use syslog for anything that's important. If you use a systemd-specific logging mechanism, cases (1) and (2) remain basically the same: instead of going into stdout/stderr or /dev/log, the log messages get into systemd by a different route, but they still go into the journal, and in case (1), they still get passed on to the traditional syslog daemon for long-term storage. Assuming you condition the systemd-specific logging mechanism on HAVE_SYSTEMD and sd_booted() and have a fallback to syslog() if one of those is false, (3) is still fine too.
Review of attachment 234156 [details] [review]: I think this does what I want; I'll test it. It does lose the priority information, which you could get back by either using syslog() like in my patch, or replacing the GLib log handler with one that uses printk-style priority markers: <2>This is a critical error (I think g_error should be this) <3>This is an error (I think g_critical should be this) <4>This is a warning (I think g_warning should be this) <5>This is a notice (I think g_message should be this) <6>This is informational (I think g_info should be this) <7>This is debug (I think g_debug should be this, if enabled) but that's a pretty minor criticism. Is syslog() (i.e. writing to /dev/log) really all that bad, in the systemd world? It's been around basically forever, it has to stay implemented as long as anyone cares about POSIX or the LSB, systemd hooks up nicely with it (even if there's no rsyslogd or whatever), it preserves priority information, and it means you can use identical code paths for logging under systemd and non-systemd. That sounds pretty good to me...
(In reply to comment #8) > Ok now I thought ENABLE_SYSTEMD_JOURNAL was for "journal only" systems, where > we didn't want to change behavior and start dumping everything to syslog. It looks as though, in commit a505c58cee7 in master, ENABLE_SYSTEMD_JOURNAL means "take everything that used to go in a separate file, and put it in the journal instead"; it doesn't change the disposition of things that already went in the journal (via syslog or the master process' stdout/stderr) on systemd systems. If that's the case, and I'm understanding everything correctly then messages go like this: gdm 3.7.3: master: in the journal, twice (once via stdout/stderr, once via syslog()) slaves: in the journal (via syslog()) and :0-slave.log (via std*) simple-greeter: in the journal (via syslog()) and :0-greeter.log (via std*) Shell greeter, gnome-session etc.: :0-greeter.log (via std*) Xorg: /var/log/Xorg.0.log (itself) and :0.log (via std*) gdm master without E_S_J: master: in the journal, twice (once via stdout/stderr, once via syslog()) slaves: in the journal (via syslog()) and :0-slave.log (via std*) simple-greeter: in the journal (via syslog()) and :0-greeter.log (via std*) Shell greeter, gnome-session etc.: :0-greeter.log (via std*) Xorg: /var/log/Xorg.0.log (itself) and :0.log (via std*) gdm master with E_S_J: master: in the journal, twice (once via stdout/stderr, once via syslog()) slaves: in the journal, twice (via syslog() and std*) simple-greeter: in the journal, twice (via syslog() and std*) Shell greeter, gnome-session etc.: in the journal (via std*) Xorg: /var/log/Xorg.0.log (itself) and the journal (via std*) gdm master without E_S_J, with your proposed patch: master: in the journal (via stdout/stderr) slaves: in :0-slave.log (via std*) simple-greeter: in :0-greeter.log (via std*) Shell greeter, gnome-session etc.: :0-greeter.log (via std*) Xorg: /var/log/Xorg.0.log (itself) and :0.log (via std*) gdm master with E_S_J, with your proposed patch: master: in the journal (via stdout/stderr) slaves: in the journal (via std*) simple-greeter: in the journal (via std*) Shell greeter, gnome-session etc.: in the journal (via std*) Xorg: /var/log/Xorg.0.log (itself) and the journal (via std*) ... which seems like a pretty good sign for the proposed patch, really.
Focusing on the last two cases ( I just track git master =) ), yeah, I think it's right, modulo the debugging-level regression. As far as the syslog-vs-stdout thing - I don't have a strong opinion, so I'd say it's up to Ray who is the gdm maintainer. My interests here lie more along how we get GLib to DTRT by default, what (if any) structured logging API GLib exposes, etc.
Review of attachment 234156 [details] [review]: Works for me, modulo losing g_debug() messages like you said (which could be construed to be a bug or a feature, depending...) If you care about getting the debug messages, I would suggest that the way to get them back would be to override the GLib default log handler and instead use one that: * sets priority prefixes like I mentioned above * respects the logic gdm normally uses for syslog, instead of G_MESSAGES_DEBUG and everything would be fine (assuming you also took my patch from Bug #692301, or something similar, to fix the logic that gdm normally uses for syslog).
So, Ray? Any further work you want here before this lands, or are you OK to land it and then we can iterate more afterwards?
I definitely want debug messages to work when debugging is enabled.
(In reply to comment #20) > I definitely want debug messages to work when debugging is enabled. I'll write a log handler like I suggested.
Created attachment 234626 [details] [review] 0001-log-When-using-systemd-just-log-to-stdout-stderr.patch Ok, this patch is based on top of smcv's patch from bug 692301 - I think it's almost there, but I can't figure out why journald isn't parsing the <7> prefix.
Review of attachment 234626 [details] [review]: Unofficial review from me: ::: common/gdm-log.c @@ +49,3 @@ switch (log_level & G_LOG_LEVEL_MASK) { case G_LOG_FLAG_FATAL: + return LOG_EMERG; As I noted on Bug #692301, I think this can never be reached. @@ +52,2 @@ case G_LOG_LEVEL_ERROR: + return LOG_ERR; As I noted on Bug #692301, this and CRITICAL should be the other way round: GLib's "critical warnings" are less serious than errors, whereas syslog's "critical errors" are more serious than errors. I would suggest something like this: case G_LOG_LEVEL_ERROR: /* fatal error - a critical error, in the syslog world */ return LOG_CRIT; case G_LOG_LEVEL_CRITICAL: /* critical warning - an error, in the syslog world */ return LOG_ERR; @@ +85,2 @@ + if (!message) + return; Why would this ever happen? If it does, wouldn't it be better to log "(null)" or something? @@ +102,3 @@ + if (is_sd_booted) { + fprintf (stdout, "%s\n", gstring->str); + fflush (stdout); Why not stderr? Since you're using printf anyway, why not drop the previous is_sd_booted check + prepend, and use this instead? if (is_sd_booted) { fprintf (stderr, "<%d>%s\n", priority, gstring->str); ...
(In reply to comment #22) > I think it's > almost there, but I can't figure out why journald isn't parsing the <7> prefix. Just <7>, or all severities? sd-daemon(7) says If a systemd service definition file is configured with StandardError=syslog or StandardError=kmsg these prefixes can be used to encode a log level in lines printed. so perhaps you need to set StandardError=syslog explicitly?
Created attachment 235193 [details] [review] slave: don't log directly to journald if we just let it inherit from the daemon's stderr, then journald will interpret the log priorities in its output.
Attachment 235193 [details] pushed as 22364a4 - slave: don't log directly to journald
(In reply to comment #25) > Created an attachment (id=235193) [details] [review] > slave: don't log directly to journald > > if we just let it inherit from the daemon's stderr, > then journald will interpret the log priorities in its output. Hm but with this patch then on e.g. Fedora gdm will start logging to journal instead of log files, right?