snappy go does not always catch s-i dbus signal

Bug #1417456 reported by Michael Vogt
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Snappy
Invalid
Undecided
Unassigned
go-dbus
Fix Committed
Undecided
Unassigned

Bug Description

Sometime running the go version will give:

Data with https://wiki.ubuntu.com/DebuggingDBus enabled:
# ./snappy update
signal sender=org.freedesktop.DBus -> dest=(null destination) serial=25 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.8"
   string ""
   string ":1.8"
signal sender=org.freedesktop.DBus -> dest=(null destination) serial=26 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.9"
   string ""
   string ":1.9"
signal sender=org.freedesktop.DBus -> dest=(null destination) serial=9 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string "com.canonical.SystemImage"
   string ""
   string ":1.9"
signal sender=:1.0 -> dest=(null destination) serial=257 path=/org/freedesktop/systemd1/unit/ondemand_2eservice; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.systemd1.Service"
   array [
      dict entry(
         string "MainPID"
         variant uint32 0
      )
      dict entry(
         string "ControlPID"
         variant uint32 0
      )
      dict entry(
         string "StatusText"
         variant string ""
      )
      dict entry(
         string "StatusErrno"
         variant int32 0
      )
      dict entry(
         string "Result"
         variant string "success"
      )
      dict entry(
         string "ExecMainStartTimestamp"
         variant uint64 0
      )
      dict entry(
         string "ExecMainStartTimestampMonotonic"
         variant uint64 0
      )
      dict entry(
         string "ExecMainExitTimestamp"
         variant uint64 0
      )
      dict entry(
         string "ExecMainExitTimestampMonotonic"
         variant uint64 0
      )
      dict entry(
         string "ExecMainPID"
         variant uint32 0
      )
      dict entry(
         string "ExecMainCode"
         variant int32 0
      )
      dict entry(
         string "ExecMainStatus"
         variant int32 0
      )
   ]
   array [
      string "ExecStartPre"
      string "ExecStart"
      string "ExecStartPost"
      string "ExecReload"
      string "ExecStop"
      string "ExecStopPost"
   ]
signal sender=:1.0 -> dest=(null destination) serial=258 path=/org/freedesktop/systemd1/unit/ondemand_2eservice; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.systemd1.Unit"
   array [
      dict entry(
         string "ActiveState"
         variant string "active"
      )
      dict entry(
         string "SubState"
         variant string "exited"
      )
      dict entry(
         string "InactiveExitTimestamp"
         variant uint64 1422957865219669
      )
      dict entry(
         string "InactiveExitTimestampMonotonic"
         variant uint64 7946903
      )
      dict entry(
         string "ActiveEnterTimestamp"
         variant uint64 1422957865290019
      )
      dict entry(
         string "ActiveEnterTimestampMonotonic"
         variant uint64 8017252
      )
      dict entry(
         string "ActiveExitTimestamp"
         variant uint64 0
      )
      dict entry(
         string "ActiveExitTimestampMonotonic"
         variant uint64 0
      )
      dict entry(
         string "InactiveEnterTimestamp"
         variant uint64 0
      )
      dict entry(
         string "InactiveEnterTimestampMonotonic"
         variant uint64 0
      )
      dict entry(
         string "Job"
         variant struct {
               uint32 0
               object path "/"
            }
      )
      dict entry(
         string "ConditionResult"
         variant boolean true
      )
      dict entry(
         string "AssertResult"
         variant boolean true
      )
      dict entry(
         string "ConditionTimestamp"
         variant uint64 1422957865210174
      )
      dict entry(
         string "ConditionTimestampMonotonic"
         variant uint64 7937421
      )
      dict entry(
         string "AssertTimestamp"
         variant uint64 1422957865210189
      )
      dict entry(
         string "AssertTimestampMonotonic"
         variant uint64 7937422
      )
   ]
   array [
   ]
signal sender=:1.0 -> dest=(null destination) serial=1 path=/org/freedesktop/systemd1/agent; interface=org.freedesktop.systemd1.Agent; member=Released
   string "/system.slice/ondemand.service"
signal sender=:1.9 -> dest=(null destination) serial=11 path=/Service; interface=com.canonical.SystemImage; member=UpdateAvailableStatus
   boolean false
   boolean false
   string ""
   int32 0
   string "2015-02-03 09:31:42"
   string ""
ERROR: timed out after 30 seconds waiting for system image server to respond
signal sender=org.freedesktop.DBus -> dest=(null destination) serial=27 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.8"
   string ":1.8"
   string ""

Without the extra debug:
$ snappy update
ERROR: timed out after 30 seconds waiting for system image server to respond

Upon further investigation it turns out that the system-image server does indeed responds as shown by dbus-monitor --system:
"""
$ sudo ./snappy update
signal sender=org.freedesktop.DBus -> dest=(null destination) serial=40 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.15"
   string ""
   string ":1.15"
signal sender=org.freedesktop.DBus -> dest=(null destination) serial=41 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.16"
   string ""
   string ":1.16"
signal sender=org.freedesktop.DBus -> dest=(null destination) serial=9 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string "com.canonical.SystemImage"
   string ""
   string ":1.16"
signal sender=:1.16 -> dest=(null destination) serial=11 path=/Service; interface=com.canonical.SystemImage; member=UpdateAvailableStatus
   boolean true
   boolean false
   string "266"
   int32 29293320
   string "2015-02-03 07:42:10"
   string ""
ERROR: timed out after 30 seconds waiting for system image server to respond
signal sender=org.freedesktop.DBus -> dest=(null destination) serial=42 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
ubuntu@localhost:~$ string ":1.15"
   string ":1.15"
   string ""
"""

So it seems that our go-dbus code (or the underlying library) does not always pick up the signal

Related branches

Michael Vogt (mvo)
description: updated
Revision history for this message
Michael Vogt (mvo) wrote :

Here is a minimal test program. When I run it on my snappy box I get (with dbus-moitor running).

I can usually reproduce this when I kill the daemon and it gets dbus-activated. Subsequent runs work as expected. I wonder if it could be that the signal filter is created when there is no system-image on the dbus (yet).

The output of dbus-monitor:
# ./lala
signal sender=org.freedesktop.DBus -> dest=(null destination) serial=37 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.13"
   string ""
   string ":1.13"
signal sender=org.freedesktop.DBus -> dest=(null destination) serial=38 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.14"
   string ""
   string ":1.14"
signal sender=org.freedesktop.DBus -> dest=(null destination) serial=6 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string "com.canonical.SystemImage"
   string ""
   string ":1.14"
signal sender=:1.14 -> dest=(null destination) serial=10 path=/Service; interface=com.canonical.SystemImage; member=UpdateAvailableStatus
   boolean true
   boolean false
   string "266"
   int32 29293320
   string "2015-02-03 07:42:10"
   string ""
panic: ERROR: timed out after 30 seconds waiting for system image server to respond

Revision history for this message
Michael Vogt (mvo) wrote :

I debugged this a bit and it turns out the problem is as follows:
- in signal.go Connection.WatchSignal() there is a callback that reacts on name owner changes
- when the owner changes rule.senderNameOwner is updated
- *however* the rule that is actually used is a copy because the signalWatch struct takes a copy and not a pointer
- so the update to the owner has no effect (in the place where it matters)

The attached patch fixes this by passing the pointer to signalWatch. I'm new to the code-base so I have no idea if that might cause issues with consumers of the library. The tests pass fine (once they are updated).

Michael Vogt (mvo)
Changed in snappy-ubuntu:
status: New → Invalid
Michael Vogt (mvo)
Changed in go-dbus:
status: New → Fix Committed
Michael Terry (mterry)
affects: snappy-ubuntu → snappy
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Bug attachments

Remote bug watches

Bug watches keep track of this bug in other bug trackers.