CoreOS 435: AgentReconciler task chain failed / Activation of org.freedesktop.systemd1 timed out

[carmstrong]

After letting my VM sit for a while, I started seeing fleet's journal filled with nothing but:

Sep 12 02:54:50 deis-1 fleetd[896]: INFO reconcile.go:267: AgentReconciler task chain failed: chain={deis-logger.service (LoadUnit, "unit scheduled here but not loaded"), (StartUnit, "unit currently loaded but desired state is launched")} err=task already in flight
Sep 12 02:54:50 deis-1 fleetd[896]: INFO reconcile.go:267: AgentReconciler task chain failed: chain={deis-logger-data.service (LoadUnit, "unit scheduled here but not loaded")} err=task already in flight
Sep 12 02:54:55 deis-1 fleetd[896]: INFO reconcile.go:267: AgentReconciler task chain failed: chain={deis-logger.service (StartUnit, "unit currently loaded but desired state is launched")} err=task already in flight
Sep 12 02:54:55 deis-1 fleetd[896]: INFO reconcile.go:267: AgentReconciler task chain failed: chain={deis-logger-data.service (LoadUnit, "unit scheduled here but not loaded")} err=task already in flight
Sep 12 02:55:00 deis-1 fleetd[896]: INFO reconcile.go:267: AgentReconciler task chain failed: chain={deis-logger-data.service (LoadUnit, "unit scheduled here but not loaded")} err=task already in flight
Sep 12 02:55:00 deis-1 fleetd[896]: INFO reconcile.go:267: AgentReconciler task chain failed: chain={deis-logger.service (StartUnit, "unit currently loaded but desired state is launched")} err=task already in flight
Sep 12 02:55:05 deis-1 fleetd[896]: INFO reconcile.go:267: AgentReconciler task chain failed: chain={deis-logger.service (StartUnit, "unit currently loaded but desired state is launched")} err=task already in flight
Sep 12 02:55:05 deis-1 fleetd[896]: INFO reconcile.go:267: AgentReconciler task chain failed: chain={deis-logger-data.service (LoadUnit, "unit scheduled here but not loaded")} err=task already in flight
Sep 12 02:55:10 deis-1 fleetd[896]: INFO reconcile.go:267: AgentReconciler task chain failed: chain={deis-logger-data.service (LoadUnit, "unit scheduled here but not loaded")} err=task already in flight
Sep 12 02:55:10 deis-1 fleetd[896]: INFO reconcile.go:267: AgentReconciler task chain failed: chain={deis-logger.service (StartUnit, "unit currently loaded but desired state is launched")} err=task already in flight
Sep 12 02:55:15 deis-1 fleetd[896]: INFO manager.go:222: Writing systemd unit deis-logger-data.service (324b)
Sep 12 02:55:15 deis-1 fleetd[896]: INFO reconcile.go:276: AgentReconciler task failed: type=LoadUnit job=deis-logger.service reason="unit scheduled here but not loaded" err=Activation of org.freedesktop.systemd1 timed out
Sep 12 02:55:40 deis-1 fleetd[896]: ERROR manager.go:113: Failed to start systemd unit deis-logger.service: Activation of org.freedesktop.systemd1 timed out
Sep 12 02:55:40 deis-1 fleetd[896]: INFO reconcile.go:276: AgentReconciler task failed: type=LoadUnit job=deis-logger-data.service reason="unit scheduled here but not loaded" err=Activation of org.freedesktop.systemd1 timed out
Sep 12 02:55:40 deis-1 fleetd[896]: INFO reconcile.go:274: AgentReconciler completed task: type=StartUnit job=deis-logger.service reason="unit currently loaded but desired state is launched"
Sep 12 02:56:05 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 02:56:30 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 02:56:55 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 02:57:20 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 02:57:45 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 02:58:10 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 02:58:35 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 02:59:00 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 02:59:25 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 02:59:50 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 03:00:15 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 03:00:40 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 03:01:05 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 03:01:30 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 03:01:55 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 03:02:20 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out
Sep 12 03:02:45 deis-1 fleetd[896]: ERROR generator.go:40: Failed fetching current unit states: Activation of org.freedesktop.systemd1 timed out

Seems like fleet has crashed the systemd bus?

core@deis-1 ~ $ systemctl status
Failed to read server status: Connection timed out

[carmstrong]

It looks like this tomfoolery started when the leader was somehow lost:

Sep 12 01:49:47 deis-1 fleetd[896]: INFO manager.go:146: Instructing systemd to reload units
Sep 12 01:49:47 deis-1 fleetd[896]: INFO manager.go:235: Removing systemd unit wooden-offering_v2.web.5.service
Sep 12 01:49:47 deis-1 fleetd[896]: INFO reconcile.go:274: AgentReconciler completed task: type=UnloadUnit job=wooden-offering_v2.web.4.service reason="unit loaded but not scheduled here"
Sep 12 01:49:47 deis-1 fleetd[896]: INFO manager.go:146: Instructing systemd to reload units
Sep 12 01:49:47 deis-1 fleetd[896]: INFO manager.go:235: Removing systemd unit wooden-offering_v2.web.2.service
Sep 12 01:49:47 deis-1 fleetd[896]: INFO reconcile.go:274: AgentReconciler completed task: type=UnloadUnit job=wooden-offering_v2.web.5.service reason="unit loaded but not scheduled here"
Sep 12 01:49:47 deis-1 fleetd[896]: INFO manager.go:146: Instructing systemd to reload units
Sep 12 01:49:47 deis-1 fleetd[896]: INFO reconcile.go:274: AgentReconciler completed task: type=UnloadUnit job=wooden-offering_v2.web.2.service reason="unit loaded but not scheduled here"
Sep 12 02:28:23 deis-1 fleetd[896]: ERROR engine.go:98: Engine leadership lost, renewal failed: 100: Key not found (/_coreos.com/fleet/lease/engine-leader) [35795]
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:109: Engine leadership acquired
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(deis-database.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: deis-database.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df, Reason: "
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(wooden-offering_v2.web.1-announce.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: wooden-offering_v2.web.1-announce.service, MachineID: dbf8e1fb32934e42afef0e6
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(deis-controller.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: deis-controller.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df, Reason:
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(deis-database-data.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: deis-database-data.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df, Reas
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(deis-logger.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: deis-logger.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df, Reason: "ta
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(wooden-offering_v2.web.1-log.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: wooden-offering_v2.web.1-log.service, MachineID: dbf8e1fb32934e42afef0e6c4faf
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(deis-builder.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: deis-builder.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df, Reason: "t
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(deis-logger-data.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: deis-logger-data.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df, Reason
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(deis-registry.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: deis-registry.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df, Reason: "
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(wooden-offering_v2.web.1.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: wooden-offering_v2.web.1.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(deis-builder-data.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: deis-builder-data.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df, Reaso
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(deis-cache.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: deis-cache.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df, Reason: "tar
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(deis-registry-data.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: deis-registry-data.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df, Reas
Sep 12 02:28:23 deis-1 fleetd[896]: INFO engine.go:146: Unscheduled Job(deis-router@1.service) from Machine(dbf8e1fb32934e42afef0e6c4faf17df)
Sep 12 02:28:23 deis-1 fleetd[896]: INFO reconciler.go:147: EngineReconciler completed task: {Type: UnscheduleUnit, JobName: deis-router@1.service, MachineID: dbf8e1fb32934e42afef0e6c4faf17df, Reason:

Truth be told this is a one-node machine which I know is not etcd-ideal, but we've never seen this issue on one-node before.

[bcwaldon]

@carmstrong The churn you experienced comes down to how presence is handled. Your etcd cluster experienced downtime longer than the TTL used for agent presence, and when etcd became available again, the TTLs timed out and lots of things got rescheduled. This is not nearly as terrible when you have a multinode cluster, but it is still an architectural problem we know needs to be solved.

As for the systemd-related errors, I don't think fleet had anything to do with that. Do you see any error logs elsewhere in the system related to dbus or systemd?

[carmstrong]

@bcwaldon I guess that's why I'm confused - there was no downtime to speak of. I was working on the machine the entire time, and hopped back on the VM to check things. It was running the Deis control plane just fine, then according to the logs, 10 minutes later it died. And this feels like a regression, because previous releases have never had this occur.

[bcwaldon]

@carmstrong Can you look at the etcd logs from the period of time that leadership was lost? It almost looks like there was a time jump that forced etcd to time out a large number of keys all at once. Did ntpd shift time forward?

[carmstrong]

@bcwaldon etcd log is entirely clean -- nothing but a snapshot occurring every 30 minutes.

$ journalctl -u etcd
-- Logs begin at Fri 2014-09-12 00:35:35 UTC, end at Fri 2014-09-12 18:13:53 UTC. --
Sep 12 00:35:44 deis-1 systemd[1]: Starting etcd...
Sep 12 00:35:44 deis-1 systemd[1]: Started etcd.
Sep 12 00:35:44 deis-1 etcd[889]: [etcd] Sep 12 00:35:44.491 INFO      | The path /var/lib/etcd/log is in btrfs
Sep 12 00:35:44 deis-1 etcd[889]: [etcd] Sep 12 00:35:44.492 INFO      | Set NOCOW to path /var/lib/etcd/log succeeded
Sep 12 00:35:44 deis-1 etcd[889]: [etcd] Sep 12 00:35:44.492 INFO      | dbf8e1fb32934e42afef0e6c4faf17df is starting a new cluster
Sep 12 00:35:44 deis-1 etcd[889]: [etcd] Sep 12 00:35:44.493 INFO      | etcd server [name dbf8e1fb32934e42afef0e6c4faf17df, listen on :4001, advertised url http://172.17.8.100:4001]
Sep 12 00:35:44 deis-1 etcd[889]: [etcd] Sep 12 00:35:44.493 INFO      | peer server [name dbf8e1fb32934e42afef0e6c4faf17df, listen on :7001, advertised url http://172.17.8.100:7001]
Sep 12 00:35:44 deis-1 etcd[889]: [etcd] Sep 12 00:35:44.493 INFO      | dbf8e1fb32934e42afef0e6c4faf17df starting in peer mode
Sep 12 00:35:44 deis-1 etcd[889]: [etcd] Sep 12 00:35:44.493 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: state changed from 'initialized' to 'follower'.
Sep 12 00:35:44 deis-1 etcd[889]: [etcd] Sep 12 00:35:44.494 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: state changed from 'follower' to 'leader'.
Sep 12 00:35:44 deis-1 etcd[889]: [etcd] Sep 12 00:35:44.494 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: leader changed from '' to 'dbf8e1fb32934e42afef0e6c4faf17df'.
Sep 12 01:07:05 deis-1 etcd[889]: [etcd] Sep 12 01:07:05.997 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10008 events at index 10008 completed
Sep 12 01:29:58 deis-1 etcd[889]: [etcd] Sep 12 01:29:58.545 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10019 events at index 20027 completed
Sep 12 01:43:53 deis-1 etcd[889]: [etcd] Sep 12 01:43:53.148 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10032 events at index 30059 completed
Sep 12 02:02:57 deis-1 etcd[889]: [etcd] Sep 12 02:02:57.341 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10003 events at index 40062 completed
Sep 12 02:32:15 deis-1 etcd[889]: [etcd] Sep 12 02:32:15.585 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10017 events at index 50079 completed
Sep 12 03:01:29 deis-1 etcd[889]: [etcd] Sep 12 03:01:29.682 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10009 events at index 60088 completed
Sep 12 03:30:31 deis-1 etcd[889]: [etcd] Sep 12 03:30:31.386 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10042 events at index 70130 completed
Sep 12 03:59:33 deis-1 etcd[889]: [etcd] Sep 12 03:59:33.249 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10032 events at index 80162 completed
Sep 12 04:28:34 deis-1 etcd[889]: [etcd] Sep 12 04:28:34.619 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10030 events at index 90192 completed
Sep 12 04:57:33 deis-1 etcd[889]: [etcd] Sep 12 04:57:33.486 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10002 events at index 100194 completed
Sep 12 05:26:32 deis-1 etcd[889]: [etcd] Sep 12 05:26:32.053 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10020 events at index 110214 completed
Sep 12 05:55:30 deis-1 etcd[889]: [etcd] Sep 12 05:55:30.274 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10021 events at index 120235 completed
Sep 12 06:24:28 deis-1 etcd[889]: [etcd] Sep 12 06:24:28.673 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10007 events at index 130242 completed
Sep 12 06:53:28 deis-1 etcd[889]: [etcd] Sep 12 06:53:28.186 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10001 events at index 140243 completed
Sep 12 07:22:23 deis-1 etcd[889]: [etcd] Sep 12 07:22:23.930 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10011 events at index 150254 completed
Sep 12 07:51:19 deis-1 etcd[889]: [etcd] Sep 12 07:51:19.141 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10007 events at index 160261 completed
-- Reboot --
Sep 12 17:59:31 deis-1 systemd[1]: Starting etcd...
Sep 12 17:59:31 deis-1 systemd[1]: Started etcd.
Sep 12 17:59:31 deis-1 etcd[568]: [etcd] Sep 12 17:59:31.604 INFO      | The path /var/lib/etcd/log is in btrfs
Sep 12 17:59:31 deis-1 etcd[568]: [etcd] Sep 12 17:59:31.604 WARNING   | Failed setting NOCOW: skip nonempty file
Sep 12 17:59:31 deis-1 etcd[568]: [etcd] Sep 12 17:59:31.604 INFO      | Peer URLs in log:  / dbf8e1fb32934e42afef0e6c4faf17df (http://172.17.8.100:7001)
Sep 12 17:59:31 deis-1 etcd[568]: [etcd] Sep 12 17:59:31.607 INFO      | etcd server [name dbf8e1fb32934e42afef0e6c4faf17df, listen on :4001, advertised url http://172.17.8.100:4001]
Sep 12 17:59:31 deis-1 etcd[568]: [etcd] Sep 12 17:59:31.607 INFO      | peer server [name dbf8e1fb32934e42afef0e6c4faf17df, listen on :7001, advertised url http://172.17.8.100:7001]
Sep 12 17:59:31 deis-1 etcd[568]: [etcd] Sep 12 17:59:31.607 INFO      | dbf8e1fb32934e42afef0e6c4faf17df starting in peer mode
Sep 12 17:59:31 deis-1 etcd[568]: [etcd] Sep 12 17:59:31.607 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: state changed from 'initialized' to 'follower'.
Sep 12 17:59:34 deis-1 etcd[568]: [etcd] Sep 12 17:59:34.608 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 160261 events at index 160261 completed
Sep 12 17:59:35 deis-1 etcd[568]: [etcd] Sep 12 17:59:35.586 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: state changed from 'follower' to 'candidate'.
Sep 12 17:59:35 deis-1 etcd[568]: [etcd] Sep 12 17:59:35.587 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: state changed from 'candidate' to 'leader'.
Sep 12 17:59:35 deis-1 etcd[568]: [etcd] Sep 12 17:59:35.587 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: leader changed from '' to 'dbf8e1fb32934e42afef0e6c4faf17df'.
Sep 12 18:07:54 deis-1 etcd[568]: [etcd] Sep 12 18:07:54.793 INFO      | dbf8e1fb32934e42afef0e6c4faf17df: snapshot of 10019 events at index 170280 completed

[jonboulle]

@carmstrong can you confirm that sudo systemctl status is fine?

[carmstrong]

@jonboulle Indeed it is now, but the VM has since been rebooted / resumed from hibernation. It did not work before.

[jonboulle]

@carmstrong ah, drats. To be clear, there's an important distinction between non-sudo and sudo; with the former, systemctl talks to systemd over dbus, but with the latter, it talks directly over a private socket. In the past we've seen issues with systemd's dbus connection hanging but being fine to access over the private socket, so I wanted to narrow down whether that was the case here.

[carmstrong]

@jonboulle Ah, gotcha. I can try to recreate today.

[jonboulle]

@carmstrong awesome, that'd be great. For the record, here's how we were triggering the issue previously - although we never figured out the underlying issue with dbus-daemon: coreos/go-systemd#49

Would be great to have another reproducible case.

[apatil]

@jonboulle I observed something like this last night on a three-machine etcd cluster. The journal showed messages like in the issue description, and the fleet service was in a failed state. sudo systemctl status was 'degraded', but regrettably I didn't write down any more information than that before rebooting the machine.

When I rebooted, the machine came back and added itself to fleet without problems. However, I now have a phantom unit in fleetctl list-units:

$ fleetctl list-units
UNIT                                                            MACHINE                         ACTIVE  SUB
...
development.db.1411372892385.0.service                    3c78127f.../10.0.155.9          active  running
...
$ fleetctl cat development.db.1411372892385.0.service
Unit development.db.1411372892385.0.service not found

Anything else I can check, or look for if it happens again?

[kelseyhightower]

@apatil More logs from the machine "running" the phantom unit will help greatly in troubleshooting this.