Bug 97009 - dbus-daemon's _dbus_warn calls are rarely visible
Summary: dbus-daemon's _dbus_warn calls are rarely visible
Status: RESOLVED FIXED
Alias: None
Product: dbus
Classification: Unclassified
Component: core (show other bugs)
Version: git master
Hardware: Other All
: medium normal
Assignee: Simon McVittie
QA Contact: D-Bus Maintainers
URL:
Whiteboard: review?
Keywords: patch
Depends on:
Blocks:
 
Reported: 2016-07-20 17:18 UTC by Simon McVittie
Modified: 2016-09-30 19:06 UTC (History)
1 user (show)

See Also:
i915 platform:
i915 features:


Attachments
test-bus: don't write to the syslog (890 bytes, patch)
2016-07-20 17:18 UTC, Simon McVittie
Details | Splinter Review
sysdeps: move _dbus_system_log() into the shared library (9.77 KB, patch)
2016-07-20 17:19 UTC, Simon McVittie
Details | Splinter Review
_dbus_init_system_log: record a syslog tag (executable name) (4.37 KB, patch)
2016-07-20 17:20 UTC, Simon McVittie
Details | Splinter Review
_dbus_system_log: rename to _dbus_log (6.84 KB, patch)
2016-07-20 17:20 UTC, Simon McVittie
Details | Splinter Review
config-parser: remove unnecessary newline from _dbus_log() (1.07 KB, patch)
2016-07-20 17:21 UTC, Simon McVittie
Details | Splinter Review
_dbus_logv: configurably log to syslog and/or stderr (9.66 KB, patch)
2016-07-20 17:21 UTC, Simon McVittie
Details | Splinter Review
bus_context_log: remove special handling of !context->syslog (1.56 KB, patch)
2016-07-20 17:21 UTC, Simon McVittie
Details | Splinter Review
_dbus_warn, _dbus_warn_check_failed: unify with _dbus_logv (2.79 KB, patch)
2016-07-20 17:22 UTC, Simon McVittie
Details | Splinter Review
syslog test: extend assertions to cover new functionality (2.90 KB, patch)
2016-07-20 17:22 UTC, Simon McVittie
Details | Splinter Review
dbus-daemon: add --syslog, --nosyslog, --syslog-only (7.88 KB, patch)
2016-07-20 17:23 UTC, Simon McVittie
Details | Splinter Review
test-bus: don't write to the syslog (882 bytes, patch)
2016-07-21 10:15 UTC, Simon McVittie
Details | Splinter Review
sysdeps: move _dbus_system_log() into the shared library (9.76 KB, patch)
2016-07-21 10:15 UTC, Simon McVittie
Details | Splinter Review
_dbus_init_system_log: record a syslog tag (executable name) (5.10 KB, patch)
2016-07-21 10:16 UTC, Simon McVittie
Details | Splinter Review
_dbus_system_log: rename to _dbus_log (6.83 KB, patch)
2016-07-21 10:16 UTC, Simon McVittie
Details | Splinter Review
config-parser: remove unnecessary newline from _dbus_log() (1.06 KB, patch)
2016-07-21 10:16 UTC, Simon McVittie
Details | Splinter Review
_dbus_logv: configurably log to syslog and/or stderr (10.50 KB, patch)
2016-07-21 10:16 UTC, Simon McVittie
Details | Splinter Review
bus_context_log: remove special handling of !context->syslog (1.55 KB, patch)
2016-07-21 10:16 UTC, Simon McVittie
Details | Splinter Review
_dbus_warn, _dbus_warn_check_failed: unify with _dbus_logv (2.78 KB, patch)
2016-07-21 10:18 UTC, Simon McVittie
Details | Splinter Review
syslog test: extend assertions to cover new functionality (2.89 KB, patch)
2016-07-21 10:18 UTC, Simon McVittie
Details | Splinter Review
dbus-daemon: add --syslog, --nosyslog, --syslog-only (7.87 KB, patch)
2016-07-21 10:18 UTC, Simon McVittie
Details | Splinter Review
Only redirect child processes to systemd Journal if using syslog (8.86 KB, patch)
2016-07-21 10:18 UTC, Simon McVittie
Details | Splinter Review
dbus-launch: redirect dbus-daemon output to syslog (1.48 KB, patch)
2016-07-21 10:18 UTC, Simon McVittie
Details | Splinter Review
_dbus_change_to_daemon_user (audit code path): set DBusError correctly (1.13 KB, patch)
2016-07-21 10:19 UTC, Simon McVittie
Details | Splinter Review
internals: remove newline, pid from assertion failures (1.50 KB, patch)
2016-07-21 10:19 UTC, Simon McVittie
Details | Splinter Review
Remove trailing newlines from _dbus_assert_not_reached (7.38 KB, patch)
2016-07-21 10:19 UTC, Simon McVittie
Details | Splinter Review
Remove trailing newlines from _dbus_warn, _dbus_warn_check_failed (144.54 KB, patch)
2016-07-21 10:19 UTC, Simon McVittie
Details | Splinter Review
_dbus_logv: configurably log to syslog and/or stderr (12.63 KB, patch)
2016-08-12 16:23 UTC, Simon McVittie
Details | Splinter Review
bus_context_log: remove special handling of !context->syslog (1.67 KB, patch)
2016-08-12 16:25 UTC, Simon McVittie
Details | Splinter Review
_dbus_warn, _dbus_warn_check_failed: unify with _dbus_logv (2.79 KB, patch)
2016-08-12 16:27 UTC, Simon McVittie
Details | Splinter Review
syslog test: extend assertions to cover new functionality (2.98 KB, patch)
2016-08-12 16:28 UTC, Simon McVittie
Details | Splinter Review
dbus-daemon: add --syslog, --nosyslog, --syslog-only (7.84 KB, patch)
2016-08-12 16:29 UTC, Simon McVittie
Details | Splinter Review
Only redirect child processes to systemd Journal if using syslog (8.98 KB, patch)
2016-08-12 16:29 UTC, Simon McVittie
Details | Splinter Review
dbus-launch: redirect dbus-daemon output to syslog (1.49 KB, patch)
2016-08-12 16:30 UTC, Simon McVittie
Details | Splinter Review
internals: remove newline, pid from assertion failures (1.61 KB, patch)
2016-08-12 16:31 UTC, Simon McVittie
Details | Splinter Review
Remove trailing newlines from _dbus_warn, _dbus_warn_check_failed (144.55 KB, patch)
2016-08-12 16:33 UTC, Simon McVittie
Details | Splinter Review
Remove unmatched parenthesis (1.06 KB, patch)
2016-08-12 16:34 UTC, Simon McVittie
Details | Splinter Review
_dbus_logv: configurably log to syslog and/or stderr (12.63 KB, patch)
2016-08-12 17:02 UTC, Simon McVittie
Details | Splinter Review

Description Simon McVittie 2016-07-20 17:18:08 UTC
If a dbus-daemon that was not started by systemd calls _dbus_warn() or _dbus_warn_check_failed(), it will typically go to /dev/null (and in particular, if started by dbus-launch, it *always* goes to /dev/null). This is rather annoying when trying to debug a mysterious failure like <https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=829557>.

If it does have a non-trivial stderr, it breaks Unix command-line best-practice by not identifying itself, and its messages aren't always \n-terminated either.

It has always been like this, and the fix is large and intrusive, so I think we should only fix this for 1.11
Comment 1 Simon McVittie 2016-07-20 17:18:32 UTC
Created attachment 125171 [details] [review]
test-bus: don't write to the syslog

We want to emulate the behaviour of the system bus, but we don't
really want to spam the system log with lots of test messages.
Comment 2 Simon McVittie 2016-07-20 17:19:00 UTC
Created attachment 125172 [details] [review]
sysdeps: move _dbus_system_log() into the shared  library

This is in preparation for optionally making _dbus_warn() use it.
dbus-daemon closes its stderr under some circumstances, including
when launched by dbus-launch, which makes failures in that
situation rather hard to debug.

_dbus_system_log() is the same on Unix and Windows, so move it
to dbus-sysdeps.c. _dbus_system_logv() remains platform-specific.
Comment 3 Simon McVittie 2016-07-20 17:20:16 UTC
Created attachment 125173 [details] [review]
_dbus_init_system_log: record a syslog tag (executable  name)

Instead of hard-coding "dbus", report what the executable really is.

---

The only API users right now are dbus-daemon and test-syslog, but dbus-daemon-launch-helper (Bug #85106) and dbus-launch could potentially use this too.
Comment 4 Simon McVittie 2016-07-20 17:20:38 UTC
Created attachment 125174 [details] [review]
_dbus_system_log: rename to _dbus_log

This is a step towards making it write to either stderr or syslog
or both, as configured globally.
Comment 5 Simon McVittie 2016-07-20 17:21:00 UTC
Created attachment 125175 [details] [review]
config-parser: remove unnecessary newline from  _dbus_log()

_dbus_log() already adds a newline.
Comment 6 Simon McVittie 2016-07-20 17:21:17 UTC
Created attachment 125176 [details] [review]
_dbus_logv: configurably log to syslog and/or stderr
Comment 7 Simon McVittie 2016-07-20 17:21:37 UTC
Created attachment 125177 [details] [review]
bus_context_log: remove special handling of  !context->syslog

_dbus_log() and _dbus_logv() are always the right functions to call now.
Comment 8 Simon McVittie 2016-07-20 17:22:01 UTC
Created attachment 125178 [details] [review]
_dbus_warn, _dbus_warn_check_failed: unify with  _dbus_logv

This means that dbus-daemon will log something like

    dbus-daemon[123]: Unable to add reload watch to main loop

to syslog and/or stderr according to its configuration, while other
libdbus users will print something like this to stderr:

    dbus[4567]: arguments to dbus_foo() were incorrect, assertion
    "connection != NULL" failed at file dbus-foo.c line 123.
    This is normally a bug in some application using the D-Bus library.

This slightly changes the meaning of the argument to _dbus_warn()
and _dbus_warn_check_failed. Previously, a trailing newline was
expected, and a missing newline would have resulted in incorrect
output. Now, a newline is supplied automatically by the
library (like g_warning()), and messages that end with a newline will
result in an unnecessary extra newline in output.

This extra newline is harmless, so I'm not going to change all the
callers immediately.
Comment 9 Simon McVittie 2016-07-20 17:22:19 UTC
Created attachment 125179 [details] [review]
syslog test: extend assertions to cover new  functionality
Comment 10 Simon McVittie 2016-07-20 17:23:21 UTC
Created attachment 125180 [details] [review]
dbus-daemon: add --syslog, --nosyslog, --syslog-only

Like --fork and --nofork, these override what the configuration says.

Use --syslog-only to force the systemd services to log to the Journal
(via syslog, which means we see the severity metadata) instead of
testing sd_booted() in the configuration implementation.

---

With hindsight I think this should always have been a command-line option, and never a config option, like --fork/--nofork.
Comment 11 Simon McVittie 2016-07-20 17:27:29 UTC
Other things that could potentially be done here:

* make dbus-launch run dbus-daemon --syslog-only (or --syslog if it didn't close stderr) so that the messages don't just go to /dev/null
* make dbus-launch use syslog itself, if useful
* Bug #85106

This is potentially also useful for Bug #85108 and Bug #86442.
Comment 12 Simon McVittie 2016-07-20 17:28:36 UTC
Comment on attachment 125173 [details] [review]
_dbus_init_system_log: record a syslog tag (executable  name)

Review of attachment 125173 [details] [review]:
-----------------------------------------------------------------

::: dbus/dbus-sysdeps-unix.c
@@ +4436,2 @@
>  void
> +_dbus_init_system_log (const char *tag,

I should probably write a doc-comment to clarify that the tag is not strdup()'d, and must be available for the entire lifetime of the process.
Comment 13 Simon McVittie 2016-07-20 17:31:50 UTC
(In reply to Simon McVittie from comment #8)
>     dbus[4567]: arguments to dbus_foo() were incorrect, assertion
>     "connection != NULL" failed at file dbus-foo.c line 123.
>     This is normally a bug in some application using the D-Bus library.

I've also wondered whether the default syslog tag should be "libdbus" or "process" as a way to indicate that this is probably a bug in (some other library in) process 4567, not "the D-Bus system".

Or it could even be NULL and have a special case for NULL that attempts to read /proc/self/comm (once) and use that, but then we get into thread-safety and "but what if OOM?" considerations, so I'd rather not do that.
Comment 14 Simon McVittie 2016-07-20 17:33:15 UTC
(In reply to Simon McVittie from comment #11)
> Other things that could potentially be done here:

* remove \n from all the _dbus_warn() calls
* remove process IDs, likewise
* optionally (?) include timestamps and thread IDs like we do for
  _dbus_verbose (but I think there's a serious risk of overcomplicating it,
  and I'm trying hard not to introduce new places where we have to check
  for OOM in this patchset)
Comment 15 Simon McVittie 2016-07-21 10:15:32 UTC
Created attachment 125190 [details] [review]
test-bus: don't write to the syslog

We want to emulate the behaviour of the system bus, but we don't
really want to spam the system log with lots of test messages.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 16 Simon McVittie 2016-07-21 10:15:47 UTC
Created attachment 125191 [details] [review]
sysdeps: move _dbus_system_log() into the shared library

This is in preparation for optionally making _dbus_warn() use it.
dbus-daemon closes its stderr under some circumstances, including
when launched by dbus-launch, which makes failures in that
situation rather hard to debug.

_dbus_system_log() is the same on Unix and Windows, so move it
to dbus-sysdeps.c. _dbus_system_logv() remains platform-specific.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 17 Simon McVittie 2016-07-21 10:16:12 UTC
Created attachment 125192 [details] [review]
_dbus_init_system_log: record a syslog tag (executable name)

Instead of hard-coding "dbus", report what the executable really is.

Signed-off-by: Simon McVittie <smcv@debian.org>

---

Add doc-comment indicating that the syslog tag must remain valid forever
Comment 18 Simon McVittie 2016-07-21 10:16:20 UTC
Created attachment 125193 [details] [review]
_dbus_system_log: rename to _dbus_log

This is a step towards making it write to either stderr or syslog
or both, as configured globally.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 19 Simon McVittie 2016-07-21 10:16:32 UTC
Created attachment 125194 [details] [review]
config-parser: remove unnecessary newline from _dbus_log()

_dbus_log() already adds a newline.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 20 Simon McVittie 2016-07-21 10:16:48 UTC
Created attachment 125195 [details] [review]
_dbus_logv: configurably log to syslog and/or stderr

Signed-off-by: Simon McVittie <smcv@debian.org>

---

Add doc-comment
Comment 21 Simon McVittie 2016-07-21 10:16:53 UTC
Created attachment 125196 [details] [review]
bus_context_log: remove special handling of !context->syslog

_dbus_log() and _dbus_logv() are always the right functions to call now.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 22 Simon McVittie 2016-07-21 10:18:08 UTC
Created attachment 125197 [details] [review]
_dbus_warn, _dbus_warn_check_failed: unify with _dbus_logv

This means that dbus-daemon will log something like

    dbus-daemon[123]: Unable to add reload watch to main loop

to syslog and/or stderr according to its configuration, while other
libdbus users will print something like this to stderr:

    dbus[4567]: arguments to dbus_foo() were incorrect, assertion
    "connection != NULL" failed at file dbus-foo.c line 123.
    This is normally a bug in some application using the D-Bus library.

This slightly changes the meaning of the argument to _dbus_warn()
and _dbus_warn_check_failed. Previously, a trailing newline was
expected, and a missing newline would have resulted in incorrect
output. Now, a newline is supplied automatically by the
library (like g_warning()), and messages that end with a newline will
result in an unnecessary extra newline in output.

This extra newline is harmless, so I'm not going to change all the
callers immediately.

Signed-off-by: Simon McVittie <smcv@debian.org>

---

Still the same: I haven't changed the default syslog tag to "libdbus"
or "process" as I wondered about.
Comment 23 Simon McVittie 2016-07-21 10:18:22 UTC
Created attachment 125198 [details] [review]
syslog test: extend assertions to cover new functionality

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 24 Simon McVittie 2016-07-21 10:18:31 UTC
Created attachment 125199 [details] [review]
dbus-daemon: add --syslog, --nosyslog, --syslog-only

Like --fork and --nofork, these override what the configuration says.

Use --syslog-only to force the systemd services to log to the Journal
(via syslog, which means we see the severity metadata) instead of
testing sd_booted() in the configuration implementation.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 25 Simon McVittie 2016-07-21 10:18:46 UTC
Created attachment 125200 [details] [review]
Only redirect child processes to systemd Journal if using syslog

In particular this means the test suite won't spam the Journal
any more.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 26 Simon McVittie 2016-07-21 10:18:55 UTC
Created attachment 125201 [details] [review]
dbus-launch: redirect dbus-daemon output to syslog

Otherwise, it won't go anywhere at all.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 27 Simon McVittie 2016-07-21 10:19:05 UTC
Created attachment 125202 [details] [review]
_dbus_change_to_daemon_user (audit code path): set DBusError correctly

The other error cases here all set the error instead of just warning.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 28 Simon McVittie 2016-07-21 10:19:17 UTC
Created attachment 125203 [details] [review]
internals: remove newline, pid from assertion failures

_dbus_warn() now calls _dbus_logv() which always logs the pid and
prints a newline anyway.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 29 Simon McVittie 2016-07-21 10:19:37 UTC
Created attachment 125204 [details] [review]
Remove trailing newlines from _dbus_assert_not_reached

This was never necessary: _dbus_assert_not_reached() always added one.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 30 Simon McVittie 2016-07-21 10:19:44 UTC
Created attachment 125205 [details] [review]
Remove trailing newlines from _dbus_warn, _dbus_warn_check_failed

They used to be needed, but are not needed any more, and we were
never completely consistent about including them in any case.

Signed-off-by: Simon McVittie <smcv@debian.org>
Comment 31 Ralf Habacker 2016-07-25 10:47:53 UTC
Comment on attachment 125175 [details] [review]
config-parser: remove unnecessary newline from  _dbus_log()

duplicated patch
Comment 32 Ralf Habacker 2016-07-25 10:48:14 UTC
Comment on attachment 125177 [details] [review]
bus_context_log: remove special handling of  !context->syslog

patch is superseeded
Comment 33 Ralf Habacker 2016-07-25 10:49:32 UTC
Comment on attachment 125172 [details] [review]
sysdeps: move _dbus_system_log() into the shared  library

superseeded
Comment 34 Ralf Habacker 2016-07-25 10:50:01 UTC
Comment on attachment 125173 [details] [review]
_dbus_init_system_log: record a syslog tag (executable  name)

superseeded
Comment 35 Ralf Habacker 2016-07-25 11:15:37 UTC
Comment on attachment 125190 [details] [review]
test-bus: don't write to the syslog

Review of attachment 125190 [details] [review]:
-----------------------------------------------------------------

looks good
Comment 36 Ralf Habacker 2016-07-25 11:29:35 UTC
Comment on attachment 125191 [details] [review]
sysdeps: move _dbus_system_log() into the shared library

Review of attachment 125191 [details] [review]:
-----------------------------------------------------------------

looks good
Comment 37 Ralf Habacker 2016-07-25 11:31:47 UTC
Comment on attachment 125192 [details] [review]
_dbus_init_system_log: record a syslog tag (executable name)

Review of attachment 125192 [details] [review]:
-----------------------------------------------------------------

looks good
Comment 38 Ralf Habacker 2016-07-25 12:50:17 UTC
Comment on attachment 125193 [details] [review]
_dbus_system_log: rename to _dbus_log

Review of attachment 125193 [details] [review]:
-----------------------------------------------------------------

looks good
Comment 39 Ralf Habacker 2016-07-25 13:25:42 UTC
Comment on attachment 125195 [details] [review]
_dbus_logv: configurably log to syslog and/or stderr

Review of attachment 125195 [details] [review]:
-----------------------------------------------------------------

::: dbus/dbus-sysdeps-unix.c
@@ +4483,4 @@
>  {
>    va_list tmp;
>  #ifdef HAVE_SYSLOG_H
> +  if (log_mode != DBUS_LOG_MODE_STDERR)

Not better to use == operator instead != which is easier to read ?

@@ +4508,5 @@
> +      vsyslog (flags, msg, tmp);
> +      va_end (tmp);
> +    }
> +
> +  if (log_mode != DBUS_LOG_MODE_SYSTEM_LOG_ONLY)

see above

::: dbus/dbus-sysdeps-win.c
@@ +3634,5 @@
>    _dbus_win_set_errno (saved_errno);
>  }
>  
> +static const char *log_tag = "dbus";
> +static DBusLogMode log_mode = DBUS_LOG_MODE_STDERR;

Previous implementation indicates that DBUS_LOG_MODE_SYSTEM_LOG_ONLY need to be used here.

@@ +3681,4 @@
>       case DBUS_SYSTEM_LOG_FATAL: s = "fatal"; break;
>     }
>  
> +  if (log_mode != DBUS_LOG_MODE_STDERR)

Not better to use log_mode == instead of != ?

::: dbus/dbus-sysdeps.h
@@ +556,5 @@
>                                     DBusError  *error);
>  
> +typedef enum {
> +  DBUS_LOG_MODE_STDERR,
> +  DBUS_LOG_MODE_SYSTEM_LOG,

Here should be a note that DBUS_LOG_MODE_SYSTEM_LOG is a combination of DBUS_LOG_MODE_STDERR and BUS_LOG_MODE_SYSTEM_LOG_ONLY.
Alternativly another term could be used to indicate that this mode dumps to system log *and* to stderr.
Comment 40 Ralf Habacker 2016-07-25 13:28:08 UTC
Comment on attachment 125196 [details] [review]
bus_context_log: remove special handling of !context->syslog

Review of attachment 125196 [details] [review]:
-----------------------------------------------------------------

looks good if the answer to the question below is: yes.

::: bus/bus.c
@@ -1426,5 @@
> -      fputs (msg, stderr);
> -      fputc ('\n', stderr);
> -
> -      if (severity == DBUS_SYSTEM_LOG_FATAL)
> -        _dbus_exit (1);

Does dbus_log has code to exit on DBUS_SYSTEM_LOG_FATAL severity ?
Comment 41 Ralf Habacker 2016-07-25 13:41:54 UTC
Comment on attachment 125197 [details] [review]
_dbus_warn, _dbus_warn_check_failed: unify with _dbus_logv

Review of attachment 125197 [details] [review]:
-----------------------------------------------------------------

::: dbus/dbus-internals.c
@@ -262,5 @@
>    
>    if (!warn_initted)
>      init_warnings ();
>  
> -  fprintf (stderr, "process %lu: ", _dbus_pid_for_log ());

Does _dbus_logv supports printing pid to system log, which seems to be the default on entries in the linux system log ? Application message starts always with <processname>[<pid>].

Otherwise this information will be lost with this patch.
Comment 42 Ralf Habacker 2016-07-25 14:19:46 UTC
Comment on attachment 125199 [details] [review]
dbus-daemon: add --syslog, --nosyslog, --syslog-only

Review of attachment 125199 [details] [review]:
-----------------------------------------------------------------

looks good
Comment 43 Ralf Habacker 2016-07-25 14:27:39 UTC
Comment on attachment 125200 [details] [review]
Only redirect child processes to systemd Journal if using syslog

Review of attachment 125200 [details] [review]:
-----------------------------------------------------------------

looks good
Comment 44 Simon McVittie 2016-07-25 15:53:16 UTC
(In reply to Ralf Habacker from comment #39)
> > +  if (log_mode != DBUS_LOG_MODE_STDERR)
> 
> Not better to use == operator instead != which is easier to read ?

IMO no, because it's a tristate. We want to log to syslog, unless the mode is the single mode out of the three that does not log to syslog.

> > +  if (log_mode != DBUS_LOG_MODE_SYSTEM_LOG_ONLY)

Similarly, here we want to log to stderr, unless the mode is the one mode out of the three that does not log to stderr.

> > +static const char *log_tag = "dbus";
> > +static DBusLogMode log_mode = DBUS_LOG_MODE_STDERR;
> 
> Previous implementation indicates that DBUS_LOG_MODE_SYSTEM_LOG_ONLY need to
> be used here.

The previous implementation was designed to only be used by dbus-daemon (or test-syslog), and only after _dbus_init_system_log() was called first. The new implementation is designed to be called without first calling _dbus_init_system_log(), in some cases. So we want the global defaults to be whatever is correct in the cases where _dbus_init_system_log() has not been called.

In particular, if you are using libdbus from some random application (for instance a KDE app that uses QtDBus), nothing will have called _dbus_init_system_log(), and I would expect _dbus_warn() calls in that process to go to stderr as they have traditionally done.

If you want a different default on Windows, we can have a different default on Windows, but I'm fairly sure that the default on Unix should be STDERR.

> Here should be a note that DBUS_LOG_MODE_SYSTEM_LOG is a combination of
> DBUS_LOG_MODE_STDERR and BUS_LOG_MODE_SYSTEM_LOG_ONLY.

That's reasonable. As background, one common way the system log is used on Unix is the way dbus-daemon has traditionally done it: write each message to syslog and stderr, in parallel. We used to do this via the non-standard LOG_PERROR option, or if that isn't supported, by calling vfprintf() in _dbus_system_logv().
Comment 45 Simon McVittie 2016-07-25 15:54:07 UTC
(In reply to Simon McVittie from comment #44)
> So we want the global defaults to be
> whatever is correct in the cases where _dbus_init_system_log() has not been
> called.

(because in the cases where _dbus_init_system_log() *has* been called, the default has been overridden and is irrelevant)
Comment 46 Simon McVittie 2016-07-25 16:00:32 UTC
(In reply to Ralf Habacker from comment #40)
> Does dbus_log has code to exit on DBUS_SYSTEM_LOG_FATAL severity ?

Yes. (Not directly, but it calls _dbus_logv() which does.)

(In reply to Ralf Habacker from comment #41)
> > -  fprintf (stderr, "process %lu: ", _dbus_pid_for_log ());
> 
> Does _dbus_logv supports printing pid to system log, which seems to be the
> default on entries in the linux system log ? Application message starts
> always with <processname>[<pid>].

tl;dr: yes it's correct.

_dbus_logv() has two code paths: syslog and stderr. LOG_MODE_SYSLOG uses both.

In the syslog code path, we get the pid logged automatically because we passed LOG_PID to openlog(), and we get the syslog tag (in practice "dbus-daemon") because we passed it to openlog(). If nobody has called _dbus_init_system_log(), which is where we call openlog(), then we are in LOG_MODE_STDERR so this code path is irrelevant.

In the stderr code path, we print the syslog tag and the pid directly. If nobody has called _dbus_init_system_log(), we use a default syslog tag.

If you run the tests on a Linux system, you'll see the results of test-syslog in syslog/the Journal, and also on its stderr. I haven't tried it on real Windows, but it works as expected in Wine, and by setting WINEDEBUG=+relay I was able to see it calling OutputDebugString() in only the expected cases.
Comment 47 Simon McVittie 2016-07-25 16:03:24 UTC
(In reply to Ralf Habacker from comment #41)
> Application message starts
> always with <processname>[<pid>].

Strictly speaking that's not the process name, it's the "syslog tag" or "ident", which is *conventionally* the process name but can be different (for instance as a way to distinguish between different roles, like the D-Bus system and session buses).

In dbus-daemon versions that don't have these patches, the syslog tag is "dbus"; one side-effect of these patches is to correct it to the more conventional "dbus-daemon".
Comment 48 Simon McVittie 2016-07-25 16:06:20 UTC
(In reply to Simon McVittie from comment #44)
> > Not better to use == operator instead != which is easier to read ?
> 
> IMO no, because it's a tristate. We want to log to syslog, unless the mode
> is the single mode out of the three that does not log to syslog.

One advantage of this approach is that it "fails safe". If someone uses an invalid value, or if we add a new DBUS_LOG_MODE_SOMETHING_ELSE but forget to update all references to the log mode, then we get the most conservative implementation - log to all (in this case both) destinations, so the log message is never silently suppressed.
Comment 49 Ralf Habacker 2016-07-25 20:12:53 UTC
Comment on attachment 125203 [details] [review]
internals: remove newline, pid from assertion failures

Review of attachment 125203 [details] [review]:
-----------------------------------------------------------------

looks good
Comment 50 Ralf Habacker 2016-07-25 20:13:44 UTC
Comment on attachment 125204 [details] [review]
Remove trailing newlines from _dbus_assert_not_reached

Review of attachment 125204 [details] [review]:
-----------------------------------------------------------------

looks good
Comment 51 Ralf Habacker 2016-07-25 20:45:18 UTC
Comment on attachment 125205 [details] [review]
Remove trailing newlines from _dbus_warn, _dbus_warn_check_failed

Review of attachment 125205 [details] [review]:
-----------------------------------------------------------------

looks good otherwise.

::: dbus/dbus-marshal-recursive-util.c
@@ +2648,4 @@
>  
>    if (!_DBUS_DOUBLES_BITWISE_EQUAL (v, expected))
>      {
> +      _dbus_warn ("Expected double %g got %g\n bits = 0x%" PRIx64 " vs.\n bits = 0x%" PRIx64 ")",

You did not change it but: the closing ')' indicates that there might be a opening '(' which is not included in the format string. Looks strange.
Comment 52 Ralf Habacker 2016-07-25 20:48:34 UTC
Comment on attachment 125202 [details] [review]
_dbus_change_to_daemon_user (audit code path): set DBusError correctly

Review of attachment 125202 [details] [review]:
-----------------------------------------------------------------

looks good.
Comment 53 Ralf Habacker 2016-07-25 21:03:13 UTC
Comment on attachment 125201 [details] [review]
dbus-launch: redirect dbus-daemon output to syslog

Review of attachment 125201 [details] [review]:
-----------------------------------------------------------------

looks good
Comment 54 Ralf Habacker 2016-07-25 21:30:56 UTC
Comment on attachment 125198 [details] [review]
syslog test: extend assertions to cover new functionality

Review of attachment 125198 [details] [review]:
-----------------------------------------------------------------

looks good
Comment 55 Ralf Habacker 2016-07-25 21:31:17 UTC
Comment on attachment 125194 [details] [review]
config-parser: remove unnecessary newline from _dbus_log()

Review of attachment 125194 [details] [review]:
-----------------------------------------------------------------

looks good
Comment 56 Ralf Habacker 2016-07-25 21:35:21 UTC
I did a review of all patches. Unfortunally splinter review does not have a mode to set any "review+" state for patches, which would make it easier to see what is still open in a big patch set. 

Also related splinter review board at https://bugs.freedesktop.org/page.cgi?id=splinter.html&bug=97009 is partially incomplete in showing published reviews.
Comment 57 Simon McVittie 2016-08-11 14:59:37 UTC
(In reply to Ralf Habacker from comment #39)
> Previous implementation indicates that DBUS_LOG_MODE_SYSTEM_LOG_ONLY need to
> be used here.

I think I've justified why I changed this, hopefully you agree.

> Here should be a note that DBUS_LOG_MODE_SYSTEM_LOG is a combination of
> DBUS_LOG_MODE_STDERR and BUS_LOG_MODE_SYSTEM_LOG_ONLY.
> Alternativly another term could be used to indicate that this mode dumps to
> system log *and* to stderr.

I've changed this to a bitfield DBusLogFlags containing

DBUS_LOG_FLAGS_STDERR
DBUS_LOG_FLAGS_SYSTEM_LOG

together with an assertion that at least one of them is enabled. I think that addresses your concerns about != vs. ==, too.
Comment 58 Simon McVittie 2016-08-12 16:20:57 UTC
Comment on attachment 125190 [details] [review]
test-bus: don't write to the syslog

Applied
Comment 59 Simon McVittie 2016-08-12 16:21:20 UTC
Comment on attachment 125191 [details] [review]
sysdeps: move _dbus_system_log() into the shared library

Applied (with a missing #include fixed - it was corrected in a later patch)
Comment 60 Simon McVittie 2016-08-12 16:21:34 UTC
Comment on attachment 125192 [details] [review]
_dbus_init_system_log: record a syslog tag (executable name)

Applied
Comment 61 Simon McVittie 2016-08-12 16:21:47 UTC
Comment on attachment 125193 [details] [review]
_dbus_system_log: rename to _dbus_log

Applied
Comment 62 Simon McVittie 2016-08-12 16:22:05 UTC
Comment on attachment 125194 [details] [review]
config-parser: remove unnecessary newline from _dbus_log()

Applied
Comment 63 Simon McVittie 2016-08-12 16:22:28 UTC
Comment on attachment 125204 [details] [review]
Remove trailing newlines from _dbus_assert_not_reached

Applied
Comment 64 Simon McVittie 2016-08-12 16:23:54 UTC
Created attachment 125741 [details] [review]
_dbus_logv: configurably log to syslog and/or stderr

This changes the behaviour of _dbus_logv() if _dbus_init_system_log() was
not called. Previously, _dbus_logv() would always log to syslog;
additionally, it would log to stderr, unless the process is dbus-daemon
and it was started by systemd. Now, it will log to stderr only,
unless _dbus_init_system_log() was called first.

This is the desired behaviour because when we hook up
_dbus_warn_check_failed() to _dbus_logv() in the next commit, we don't
want typical users of libdbus to start logging their check failures to
syslog - we only want the dbus-daemon to do that.

In practice this is not usually a behaviour change, because there was
only one situation in which we called _dbus_logv() without first calling
_dbus_init_system_log(), namely an error while parsing configuration
files. Initialize the system log "just in time" in that situation
to preserve existing behaviour.

---

* Changed to use flags instead of an enum
* Amended commit message to explain why the behaviour change.
* Fixed an unintended behaviour change in config-parser
Comment 65 Simon McVittie 2016-08-12 16:25:43 UTC
Created attachment 125742 [details] [review]
bus_context_log: remove special handling of  !context->syslog

_dbus_log() and _dbus_logv() are always the right functions to call now.

---

Already reviewed, but depends on Attachment #125741 [details]. I'm re-attaching it to get it in the right sequence.
Comment 66 Simon McVittie 2016-08-12 16:27:59 UTC
Created attachment 125743 [details] [review]
_dbus_warn, _dbus_warn_check_failed: unify with  _dbus_logv

This means that dbus-daemon will log something like

    dbus-daemon[123]: Unable to add reload watch to main loop

to syslog and/or stderr according to its configuration, while other
libdbus users will print something like this to stderr:

    dbus[4567]: arguments to dbus_foo() were incorrect, assertion
    "connection != NULL" failed at file dbus-foo.c line 123.
    This is normally a bug in some application using the D-Bus library.

This slightly changes the meaning of the argument to _dbus_warn()
and _dbus_warn_check_failed. Previously, a trailing newline was
expected, and a missing newline would have resulted in incorrect
output. Now, a newline is supplied automatically by the
library (like g_warning()), and messages that end with a newline will
result in an unnecessary extra newline in output.

This extra newline is harmless, so I'm not going to change all the
callers immediately.

---

I've lost track of whether you approved this one already.
Comment 67 Simon McVittie 2016-08-12 16:28:30 UTC
Created attachment 125744 [details] [review]
syslog test: extend assertions to cover new  functionality
Comment 68 Simon McVittie 2016-08-12 16:28:51 UTC
(In reply to Simon McVittie from comment #67)
> syslog test: extend assertions to cover new  functionality

Sorry, should have said:

---

Redone in terms of the new API with flags.
Comment 69 Simon McVittie 2016-08-12 16:29:34 UTC
Created attachment 125745 [details] [review]
dbus-daemon: add --syslog, --nosyslog, --syslog-only

Like --fork and --nofork, these override what the configuration says.

Use --syslog-only to force the systemd services to log to the Journal
(via syslog, which means we see the severity metadata) instead of
testing sd_booted() in the configuration implementation.

---

Redone in terms of the new API with flags.
Comment 70 Simon McVittie 2016-08-12 16:29:59 UTC
Created attachment 125746 [details] [review]
Only redirect child processes to systemd Journal if  using syslog

In particular this means the test suite won't spam the Journal
any more.

---

Already reviewed, but depends on Attachment #125741 [details]. I'm re-attaching it to get it in the right sequence.
Comment 71 Simon McVittie 2016-08-12 16:30:50 UTC
Created attachment 125747 [details] [review]
dbus-launch: redirect dbus-daemon output to syslog

Otherwise, it won't go anywhere at all.

---

Depends on Attachment #125745 [details]. I'm re-attaching it to get it in the right sequence.
Comment 72 Simon McVittie 2016-08-12 16:31:37 UTC
Created attachment 125748 [details] [review]
internals: remove newline, pid from assertion failures

_dbus_warn() now calls _dbus_logv() which always logs the pid and
prints a newline anyway.

---

Already reviewed, but depends on Attachment #125741 [details]. I'm re-attaching it to get it in the right sequence.
Comment 73 Simon McVittie 2016-08-12 16:33:16 UTC
Created attachment 125749 [details] [review]
Remove trailing newlines from _dbus_warn,  _dbus_warn_check_failed

They used to be needed, but are not needed any more, and we were
never completely consistent about including them in any case.

---

Already reviewed (with one minor criticism which I fixed in a separate patch), but depends on Attachment #125741 [details]. I'm re-attaching it to get it in the right sequence.
Comment 74 Simon McVittie 2016-08-12 16:34:06 UTC
Created attachment 125750 [details] [review]
Remove unmatched parenthesis

---

Fix for your criticism of (the previous version of) Attachment #125749 [details].
Comment 75 Simon McVittie 2016-08-12 17:00:36 UTC
Comment on attachment 125202 [details] [review]
_dbus_change_to_daemon_user (audit code path): set DBusError correctly

Applied
Comment 76 Simon McVittie 2016-08-12 17:02:37 UTC
Created attachment 125751 [details] [review]
_dbus_logv: configurably log to syslog and/or stderr

This changes the behaviour of _dbus_logv() if _dbus_init_system_log() was
not called. Previously, _dbus_logv() would always log to syslog;
additionally, it would log to stderr, unless the process is dbus-daemon
and it was started by systemd. Now, it will log to stderr only,
unless _dbus_init_system_log() was called first.

This is the desired behaviour because when we hook up
_dbus_warn_check_failed() to _dbus_logv() in the next commit, we don't
want typical users of libdbus to start logging their check failures to
syslog - we only want the dbus-daemon to do that.

In practice this is not usually a behaviour change, because there was
only one situation in which we called _dbus_logv() without first calling
_dbus_init_system_log(), namely an error while parsing configuration
files. Initialize the system log "just in time" in that situation
to preserve existing behaviour.

---

Fix a remaining instance of DBusLogMode in Windows code (should be DBusLogFlags), and a Windows process ID logged with %d where %lu was expected.

I'm not going to bother reattaching the rest of the series, but this one needs to come first.
Comment 77 Simon McVittie 2016-09-30 19:06:50 UTC
Merged to master for 1.11.6.


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.