Comment 34 for bug 1871538

Revision history for this message
Iain Lane (laney) wrote :

Thanks! Here's where I think the problem starts:

Ok, let's authenticate to dbus:

Jun 16 08:54:54 alan-hirsute-base-aiamcicscciaelhaktpo systemd[1]: Bus bus-api-system: changing state AUTHENTICATING → HELLO
...
Jun 16 08:54:54 alan-hirsute-base-aiamcicscciaelhaktpo systemd[1]: Bus bus-api-system: changing state HELLO → RUNNING

Right, systemd thinks it's done it at least. You can see a whole bunch of messages being returned, the connection is working.

After a while (note this first timestamp jump; is that significant? looks to be waiting for udev to settle I think so maybe not; could be snapd related) we decide to do something with a Type=dbus unit:

Jun 16 08:55:25 alan-hirsute-base-aiamcicscciaelhaktpo systemd[1]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=AddMatch cookie=1511 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Jun 16 08:55:25 alan-hirsute-base-aiamcicscciaelhaktpo systemd[1]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetNameOwner cookie=1512 reply_cookie=0 signature=s error-name=n/a error-message=n/a

And another timestamp jump, waiting for this timeout:

Jun 16 08:55:45 alan-hirsute-base-aiamcicscciaelhaktpo dbus-daemon[711]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 45129ms)
Jun 16 08:55:45 alan-hirsute-base-aiamcicscciaelhaktpo systemd[1]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.4 path=n/a interface=n/a member=n/a cookie=42 reply_cookie=1512 signature=s error-name=n/a error-message=n/a

The dbus-daemon didn't think that the connection was authenticated.

The last message AFAICS received on the bus connection was:

Jun 16 08:55:00 alan-hirsute-base-aiamcicscciaelhaktpo systemd[1]: Got message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=Reload cookie=1 reply_cookie=0 signature=n/a error-name=n/a error-message=n/a
Jun 16 08:55:00 alan-hirsute-base-aiamcicscciaelhaktpo systemd[1]: Reloading.

No smoking gun yet, at least not to me. But interesting that the last thing which happened successfully was reloading. Can we have another go please, with these changes vs. an upstream clean image?

  - LogLevel=debug in /etc/systemd/system.conf
  - Using the dbus 1.12.20-2ubuntu1+ppa1 from ppa:ci-train-ppa-service/4587. This dbus is just the one from impish backported to hirsute with verbose debugging turned on.

And then attach the full `journalctl -b <the boot that failed>` which will probably be quite large. :-)

Maybe we'll get some information out of the dbus side to say what it thinks goes wrong with the connection.

** Please note ** The "connection has not authenticated" string does not appear in the earlier logs from Christian or Steve. It could be that there are two bugs here, with similar symptoms that systemd loses its connection to the system bus.