Bug 50199

(In reply to comment #0)
> May 22 08:50:19 ASUSP6Tv2 dbus-daemon[850]: process 850: arguments to
> dbus_message_set_reply_serial() were incorrect, assertion "reply_serial != 0"
> failed in file dbus-message.c line 1009.

In this case the "application using the D-Bus library" is the system dbus-daemon itself, so either way, it's the dbus package's fault.

This is a crash, and should be fixed, but we can't do that without more information (a stack trace from the crashing dbus-daemon would be very useful).

Has this been filed as a bug in the Fedora bug tracking system? Fedora developers should be able to advise you on how to obtain a stack trace or core dump from the system dbus-daemon (with luck, abrt might have already logged it for you), and whether their version of dbus has been modified.

From the other log messages, my first guess would be that this might be something to do with the integration between dbus-daemon and systemd for activation, which is a relatively recent feature.

(In reply to comment #1)
> (In reply to comment #0)
> > May 22 08:50:19 ASUSP6Tv2 dbus-daemon[850]: process 850: arguments to
> > dbus_message_set_reply_serial() were incorrect, assertion "reply_serial != 0"
> > failed in file dbus-message.c line 1009.
> 
> In this case the "application using the D-Bus library" is the system
> dbus-daemon itself, so either way, it's the dbus package's fault.
> 
> This is a crash, and should be fixed, but we can't do that without more
> information (a stack trace from the crashing dbus-daemon would be very useful).
> 
> Has this been filed as a bug in the Fedora bug tracking system? 

No because it does not look to be distro specific but a bug in dbus itself (i.e upstream).

> Fedora
> developers should be able to advise you on how to obtain a stack trace or core
> dump from the system dbus-daemon (with luck, abrt might have already logged it
> for you), and whether their version of dbus has been modified.

abrt did not catch anything, I could try to attach gdb to it pre login (via ssh) but apparently dbus runs multiple processes so I am not sure which one to attach to. So will attach to all of them and see what I can get ...

The only modification is the "bindir patch":

----
diff -up dbus-1.2.1/bus/messagebus.in.start-early dbus-1.2.1/bus/messagebus.in
--- dbus-1.2.1/bus/messagebus.in.start-early	2008-04-04 11:24:08.000000000 -0400
+++ dbus-1.2.1/bus/messagebus.in	2008-07-18 19:50:19.000000000 -0400
@@ -21,7 +21,7 @@
 ### END INIT INFO
 
 # Sanity checks.
-[ -x @EXPANDED_BINDIR@/dbus-daemon ] || exit 0
+[ -x /bin/dbus-daemon ] || exit 0
 
 # Source function library.
 . @EXPANDED_SYSCONFDIR@/rc.d/init.d/functions
-----

Which is not relevant here.

(In reply to comment #2)
> abrt did not catch anything, I could try to attach gdb to it pre login (via
> ssh) but apparently dbus runs multiple processes so I am not sure which one to
> attach to.

The crash you reported is in the system dbus-daemon, which is started by systemd or an init script, is already running before anyone logs in, and runs under a system uid (not your personal uid, and not gdm's either). Its command-line as visible in ps or /proc/$PID/cmdline will contain "--system" (all the other dbus-daemon instances should have been run with "--session" instead).

On Debian derivatives, it's the copy of dbus-daemon running as a user called "messagebus" (an older name for D-Bus). The name varies by distribution, so if it isn't called messagebus on Fedora, it might be dbus or something similar.

There should hopefully only be one dbus-daemon meeting that description (if not, that's a bug somewhere).

Created attachment 61951 [details]
backtrace

OK, got a backtrace, see attachment.

A quick hack like:

---
 dbus/dbus-message.c |    6 ++++++
 1 files changed, 6 insertions(+), 0 deletions(-)

diff --git a/dbus/dbus-message.c b/dbus/dbus-message.c
index 71bcee6..9f2a766 100644
--- a/dbus/dbus-message.c
+++ b/dbus/dbus-message.c
@@ -1422,6 +1422,12 @@ dbus_message_new_error (DBusMessage *reply_to,
 
   dbus_message_set_no_reply (message, TRUE);
 
+  if (dbus_message_get_serial (reply_to) == 0)
+    {
+      dbus_message_unref (message);
+      return NULL;
+    }
+
   if (!dbus_message_set_reply_serial (message,
                                       dbus_message_get_serial (reply_to)))
     {
-- 
1.7.7.6


Does not seem to fix it (it does not crash but it hangs).

I think there are at least two bugs here.

(1) System activation is timing out for some reason. This is likely to make things not work (the hangs you mentioned). On this Fedora version, am I right in thinking that process 1 is systemd, and it's running dbus-daemon with the --systemd-activation option? (If so, it's using systemd to provide system activation, rather than doing it itself as it does on sysvinit systems.)

(2) When system activation fails, dbus-daemon incorrectly tries to reply to a message that had serial number 0. That's wrong, because received messages are never meant to have serial number 0; so either that isn't really a received message (perhaps freed memory or a newly-allocated message?), or it's a received message that wasn't validated properly.

The crash is a symptom of (2); your patch works around it, but doesn't make system activation actually work (and something in your session login is probably waiting for system activation to succeed/fail, so in the absence of a reply, it'll wait forever).

May 22 08:50:19 ASUSP6Tv2 dbus[850]: [system] Failed to activate service
'org.freedesktop.systemd1': timed out

Is the operative failure here.  You'd need to debug why that's failing for you.  A systemd bug?  

May 22 08:50:19 ASUSP6Tv2 dbus[850]: [system] Failed to activate service
'org.freedesktop.ColorManager': timed out

Also implies that none of the systemd dbus activation integration is working at all.

Should we crash in this code path?  No, but your system isn't going to get far without system activation either, so...

So the systemd timeout thingy is caused by borked bus policy in colord. The activation signal didn't appear to get through.

What's left to fix though is that we don't attempt to reply with an error to a message that doesn't carry a message serial (because we generated it locally). It's probably just a matter of not generating any reply if the serial is 0.

(In reply to comment #8)
> So the systemd timeout thingy is caused by borked bus policy in colord. The
> activation signal didn't appear to get through.

If this is a known error in a particular system bus policy file? If so, please attach it here for reference. The o.fd.ColorManager policy in Debian unstable looks straightforward enough, but that's probably not the same version of colord as in Fedora? (currently colord 0.1.18-1 in Debian)

> What's left to fix though is that we don't attempt to reply with an error to a
> message that doesn't carry a message serial (because we generated it locally).

Is this the message being sent to systemd to request activation of colord, or what?

If dbus-daemon is sending a message - to anyone - it ought to have a nonzero serial number.

If the reply is suppressed (with the same practical effect as drago01's patch from Comment #5), will that leave dbus-daemon waiting forever for a message that will never arrive?

(In reply to comment #9)
> (In reply to comment #8)
> > So the systemd timeout thingy is caused by borked bus policy in colord. The
> > activation signal didn't appear to get through.
> 
> If this is a known error in a particular system bus policy file? If so, please
> attach it here for reference. The o.fd.ColorManager policy in Debian unstable
> looks straightforward enough, but that's probably not the same version of
> colord as in Fedora? (currently colord 0.1.18-1 in Debian)

Does not seem to be the (only?) case ... the only thing I can say is that colord-0.1.12 is fine while 0.1.18 and 0.1.21 trigger this.

I cannot reproduce this on a second system running F16 though.

I have nuked the colord config files to make sure it isn't any system specific configuration still nothing ...

I have no idea how / why this would kill dbus though.

OK the difference between the working and non working colord versions is:

The working ones (0.1.12 and 0.1.15) are activated via dbus, while the non working ones are activated via systemd (points dbus to a systemd service file).

I have a very similar problem here on a system running F17.
It started somewhen this week. It's pretty annoying, because I have to restart prefdm.service (gdm) about 3 times, before being able to log in.

Is there any news on this topic? Can I help somehow?

--------------------------------------------------------------------
Aug 18 16:05:00 kk-office dbus-daemon[938]: dbus[938]: [system] Failed to activate service 'org.freedesktop.RealtimeKit1': timed out
Aug 18 16:05:00 kk-office dbus-daemon[938]: dbus[938]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service'
Aug 18 16:05:00 kk-office dbus[938]: [system] Failed to activate service 'org.freedesktop.RealtimeKit1': timed out
Aug 18 16:05:00 kk-office dbus[938]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service'
Aug 18 16:05:00 kk-office dbus-daemon[938]: dbus[938]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Aug 18 16:05:00 kk-office dbus-daemon[938]: process 938: arguments to dbus_message_set_reply_serial() were incorrect, assertion "reply_serial != 0" failed in file dbus-message.c line 1009.
Aug 18 16:05:00 kk-office dbus-daemon[938]: This is normally a bug in some application using the D-Bus library.
Aug 18 16:05:00 kk-office dbus-daemon[938]: D-Bus not built with -rdynamic so unable to print a backtrace
Aug 18 16:05:00 kk-office dbus[938]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Aug 18 16:05:00 kk-office avahi-daemon[867]: Disconnected from D-Bus, exiting.
Aug 18 16:05:00 kk-office avahi-daemon[867]: Got SIGTERM, quitting.
------------------------------------------------------------------

This only seems to affect systemd activation, not traditional activation; retitling accordingly.

Created attachment 79841 [details] [review]
[Fix] dbus-daemon will crash due to message rejection


From: Chengwei Yang <chengwei.yang@intel.com>
Date: Sat, 25 May 2013 18:44:40 +0800

The issue goes in the below situation.

At system early boot up, systemd registers it's dbus service
"org.freedesktop.systemd1" in asynchronous manner since dbus-daemon
hasn't been activated. After dbus-daemon activated, the others may
access services registered to dbus and then dbus will try to activate
the acquired service if there is no owner of it, in addition, if the
owner of service is declaimed as a systemd bus activation service, dbus
will try to activate (in fact, just pending the request) systemd
(org.freedesktop.systemd1) if it's not around here. Otherwise, dbus just
create a new message (signal) and dispatch it to systemd.

The issues caused by the inconsistent way how dbus dispatch the
activation message to systemd1, if systemd is there, the message created
by dbus with connection is NULL, so no security checking in fact because
both systemd and dbus-daemon are running in 'root'. However, if the
orignal request sent by unprivileged process, the message created by
dbus will failed to pass security check due to the original connection
created by unprivileged process.

This some how isn't consistent in the two situations:
1. systemd is already here, the message created by dbus pass security check
2. systemd isn't here, the message created by dbus rejected

The worse situation is it will cause dbus-daemon coredumped later (time
out) because fail to pass assertion (reply_serial != 0), see below backtrace.

[... backtrace deleted ...]

[... more logs deleted ...]

Signed-off-by: Chengwei Yang <chengwei.yang@intel.com>

Comment on attachment 79841 [details] [review]
[Fix] dbus-daemon will crash due to message rejection

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

Your detailed analysis is welcome, but rather long as a commit message. Here is my attempt at something shorter, with even more analysis of why the crash happened. Please confirm whether this is correct and would be OK?

> Subject: when "activating" systemd, handle its special case better
>
> When dbus-daemon receives a request to activate a service before systemd
> has connected to it, it enqueues a fake request to "activate" systemd
> itself (as a way to get a BusPendingActivationEntry to track the
> process of waiting for systemd). When systemd later joins the bus,
> dbus-daemon sends the actual activation message; any future
> activation messages are sent directly to systemd.
>
> In the "pending" code path, the activation messages are currently
> dispatched as though they had been sent by the same process
> that sent the original activation request, which is wrong:
> the bus security policy probably doesn't allow that process
> to talk to systemd directly. They should be dispatched as though
> they had been sent by the dbus-daemon itself (connection == NULL),
> the same as in the non-pending code path.
>
> In the worst case, if the attempt to activate systemd
> timed out, the dbus-daemon would crash with a (fatal) warning,
> because in this special case, activation_message is a signal
> with no serial number, whereas the code to send an error
> reply is expecting a method call with a serial number.

It looks as though try_send_activation_failure() still doesn't handle the (entry->connection == NULL) case. As far as I can tell, it should probably be:

-    if (dbus_connection_get_is_connected (entry->connection))
+    if (entry->connection != NULL && dbus_connection_get_is_connected (entry->connection))

because if the connection is NULL, the message came from dbus-daemon itself (and is a signal, not a method call, so replying to it would be an error).

I think changing BusPendingActivationEntry.connection from "never NULL" to "NULL if adding a fake activation entry for systemd" deserves a comment, and the fact that the activation message is sometimes a signal (although not new) also deserves a comment. Something like this:

struct BusPendingActivationEntry
{
  /* Normally a method call, but if connection is NULL, this is a signal instead. */
  DBusMessage *activation_message;
  /* NULL if this activation entry is for the dbus-daemon itself,
   * waiting for systemd to start. In this case, auto_activation is always TRUE. */
  DBusConnection *connection;

  dbus_bool_t auto_activation;
};

(In reply to comment #15)
> Comment on attachment 79841 [details] [review] [review]
> [Fix] dbus-daemon will crash due to message rejection
> 
> Review of attachment 79841 [details] [review] [review]:
> -----------------------------------------------------------------
> 
> Your detailed analysis is welcome, but rather long as a commit message. Here
> is my attempt at something shorter, with even more analysis of why the crash
> happened. Please confirm whether this is correct and would be OK?

Sure.

> 
> > Subject: when "activating" systemd, handle its special case better
> >
> > When dbus-daemon receives a request to activate a service before systemd

words in <insert></insert> I'd like to add here.

a service <insert>which declaimed should be activated by systemd</insert> before systemd

> > has connected to it, it enqueues a fake request to "activate" systemd
> > itself (as a way to get a BusPendingActivationEntry to track the
> > process of waiting for systemd). When systemd later joins the bus,
> > dbus-daemon sends the actual activation message; any future
> > activation messages are sent directly to systemd.
> >
> > In the "pending" code path, the activation messages are currently
> > dispatched as though they had been sent by the same process
> > that sent the original activation request, which is wrong:
> > the bus security policy probably doesn't allow that process
> > to talk to systemd directly. They should be dispatched as though
> > they had been sent by the dbus-daemon itself (connection == NULL),
> > the same as in the non-pending code path.
> >
> > In the worst case, if the attempt to activate systemd
> > timed out, the dbus-daemon would crash with a (fatal) warning,
> > because in this special case, activation_message is a signal
> > with no serial number, whereas the code to send an error
> > reply is expecting a method call with a serial number.
> 
> It looks as though try_send_activation_failure() still doesn't handle the
> (entry->connection == NULL) case. As far as I can tell, it should probably
> be:
> 
> -    if (dbus_connection_get_is_connected (entry->connection))
> +    if (entry->connection != NULL && dbus_connection_get_is_connected
> (entry->connection))
> 
> because if the connection is NULL, the message came from dbus-daemon itself
> (and is a signal, not a method call, so replying to it would be an error).
> 
> I think changing BusPendingActivationEntry.connection from "never NULL" to
> "NULL if adding a fake activation entry for systemd" deserves a comment, and
> the fact that the activation message is sometimes a signal (although not
> new) also deserves a comment. Something like this:

totally agreed. I'll add these lines to the patch V2.

> 
> struct BusPendingActivationEntry
> {
>   /* Normally a method call, but if connection is NULL, this is a signal
> instead. */
>   DBusMessage *activation_message;
>   /* NULL if this activation entry is for the dbus-daemon itself,
>    * waiting for systemd to start. In this case, auto_activation is always
> TRUE. */
>   DBusConnection *connection;
> 
>   dbus_bool_t auto_activation;
> };

In D-Bus we normally track patches as attachments to bugs (preferably in git-format-patch format) rather than git-send-email to the mailing list, so that the patches don't get lost in maintainers' inboxes. I realise this is the opposite of some other projects, like the Linux kernel.

(In reply to comment #16)
> a service <insert>which declaimed should be activated by systemd</insert>
> before systemd

Yeah, I see your point - non-systemd services can't trigger this bug. The conventional programmer-English phrasing here would be something like "a service which declares that it should be activated...".

Or perhaps just replace "service" with "systemd service" in the text I suggested - that'd leave it looking like "... a request to activate a systemd service before systemd has ..." etc.? Fewer words, same meaning, perhaps a bit clearer.

> > I think changing BusPendingActivationEntry.connection from "never NULL" to
> > "NULL if adding a fake activation entry for systemd" deserves a comment
> 
> totally agreed. I'll add these lines to the patch V2.

Thanks, that bit looks fine in v2.

(In reply to comment #15)
> It looks as though try_send_activation_failure() still doesn't handle the
> (entry->connection == NULL) case. As far as I can tell, it should probably
> be:
> 
> -    if (dbus_connection_get_is_connected (entry->connection))
> +    if (entry->connection != NULL && dbus_connection_get_is_connected
> (entry->connection))
> 
> because if the connection is NULL, the message came from dbus-daemon itself
> (and is a signal, not a method call, so replying to it would be an error).

Your patch v2 doesn't fix this, I don't think?

> For more details, please refer to freedesktop bugzilla below.
> https://bugs.freedesktop.org/show_bug.cgi?id=50199

I usually just say "Bug: https://bugs.freedesktop.org/show_bug.cgi?id=50199" in the same style as Signed-off-by and Tested-by - we borrowed that convention from Debian's patch tagging guidelines, <http://dep.debian.net/deps/dep3/>.

(In reply to comment #17)
> In D-Bus we normally track patches as attachments to bugs (preferably in
> git-format-patch format) rather than git-send-email to the mailing list, so
> that the patches don't get lost in maintainers' inboxes. I realise this is
> the opposite of some other projects, like the Linux kernel.
> 
> (In reply to comment #16)
> > a service <insert>which declaimed should be activated by systemd</insert>
> > before systemd
> 
> Yeah, I see your point - non-systemd services can't trigger this bug. The
> conventional programmer-English phrasing here would be something like "a
> service which declares that it should be activated...".
> 
> Or perhaps just replace "service" with "systemd service" in the text I
> suggested - that'd leave it looking like "... a request to activate a
> systemd service before systemd has ..." etc.? Fewer words, same meaning,
> perhaps a bit clearer.

Thank you, will update.

> 
> > > I think changing BusPendingActivationEntry.connection from "never NULL" to
> > > "NULL if adding a fake activation entry for systemd" deserves a comment
> > 
> > totally agreed. I'll add these lines to the patch V2.
> 
> Thanks, that bit looks fine in v2.
> 
> (In reply to comment #15)
> > It looks as though try_send_activation_failure() still doesn't handle the
> > (entry->connection == NULL) case. As far as I can tell, it should probably
> > be:
> > 
> > -    if (dbus_connection_get_is_connected (entry->connection))
> > +    if (entry->connection != NULL && dbus_connection_get_is_connected
> > (entry->connection))
> > 
> > because if the connection is NULL, the message came from dbus-daemon itself
> > (and is a signal, not a method call, so replying to it would be an error).
> 
> Your patch v2 doesn't fix this, I don't think?

Yep, will append these lines to commit msg. I originally misunderstood since these lines only with a single '>' prefix but the others has two '>>'. :-)

> 
> > For more details, please refer to freedesktop bugzilla below.
> > https://bugs.freedesktop.org/show_bug.cgi?id=50199
> 
> I usually just say "Bug: https://bugs.freedesktop.org/show_bug.cgi?id=50199"
> in the same style as Signed-off-by and Tested-by - we borrowed that
> convention from Debian's patch tagging guidelines,
> <http://dep.debian.net/deps/dep3/>.

Sure, will align with the standard format.

Created attachment 79929 [details] [review]
When "activating" systemd, handle its special case better

patch v3 attached, addressed Simon's comments.

(In reply to comment #18)
> Yep, will append these lines to commit msg. I originally misunderstood since
> these lines only with a single '>' prefix but the others has two '>>'.

I think you've misunderstood; sorry, I should have marked the point in comment #15 at which I stopped talking about the commit message and started talking about the code. Everything after "... with a serial number." is a review comment on the actual code changes.

Comment #15 has three separate points:

* Improving the commit message. You fixed that in patch v2, with a minor adjustment to the first paragraph in patch v3.
* try_send_activation_failure() is still wrong. Not fixed yet.
* More comments in the struct. You fixed that in patch v2.

try_send_activation_failure() probably hasn't come up in your testing, because on a correctly-working system, systemd shouldn't fail to start :-)

Created attachment 79961 [details] [review]
patch v4

Thank you for your patience, I need improve my enligh skill continuously. :-).

Anyway, the v4 addressed the NULL connection in try_send_activation_failure() and deleted these lines from commit msg.

Comment on attachment 79961 [details] [review]
patch v4

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

Looks good, I'll apply it soon.

For the record, this was fixed in 1.6.12 and 1.7.4.