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:
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.
Thanks! Here's where I think the problem starts:
Ok, let's authenticate to dbus:
Jun 16 08:54:54 alan-hirsute- base-aiamcicscc iaelhaktpo systemd[1]: Bus bus-api-system: changing state AUTHENTICATING → HELLO base-aiamcicscc iaelhaktpo systemd[1]: Bus bus-api-system: changing state HELLO → RUNNING
...
Jun 16 08:54:54 alan-hirsute-
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-aiamcicscc iaelhaktpo 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 base-aiamcicscc iaelhaktpo 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
Jun 16 08:55:25 alan-hirsute-
And another timestamp jump, waiting for this timeout:
Jun 16 08:55:45 alan-hirsute- base-aiamcicscc iaelhaktpo dbus-daemon[711]: [system] Connection has not authenticated soon enough, closing it (auth_timeout= 30000ms, elapsed: 45129ms) base-aiamcicscc iaelhaktpo 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
Jun 16 08:55:45 alan-hirsute-
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-aiamcicscc iaelhaktpo 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 base-aiamcicscc iaelhaktpo systemd[1]: Reloading.
Jun 16 08:55:00 alan-hirsute-
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 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.
- Using the dbus 1.12.20-
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.