Unkillable units - possible systemd bug

[bcwaldon]

1. start up fleet on a single node
2. start 50 simple units - they should all be scheduled to the one node
3. sudo systemctl killl --signal SIGKILL fleet && sudo systemctl start --no-block fleet
4. unload all 50 units

At this point, I see log lines repeated every 5s for several of the units:

Sep 17 00:13:14 deis-1 fleetd[10287]: INFO reconcile.go:267: AgentReconciler task chain failed: chain={rugged-newsreel_v2.web.6-announce.service (UnloadUnit, "unit loaded but not scheduled here")} err=task already in flight

Looking at fleetctl list-units, I see the state for these problem units, but not the units that appeared to unload successfully.

Now for the interesting piece: I instrumented fleet to log the systemd job IDs whenever it does something. For this particular unit, I see that fleet called the StartUnit dbus method, which returned the job ID 929681. During all this commotion, I was also running dbus-monitor (sudo dbus-monitor --system "type=signal"). I see the JobNew signal for 929681, but no JobRemoved!

So this looks like fleet, go-systemd, and godbus are all doing the right thing. The lack of a JobRemoved event means that fleet is going to hang on the StartUnit call and block all other operations for a given unit.

The only hint I have is that fleet calls Reload a lot. Several times a second when its starting 50+ units all at once. Maybe jobs are getting dropped inside of systemd during the Reload? I seem to remember running into a problem like this in the past.

[philips]

@bcwaldon does the job show up in systemctl list-jobs? Otherwise we should file upstream on the mailing list.

[bcwaldon]

Ah, good question @philips. A small subset of the units that exhibit this behavior do appear in systemctl list-jobs.

[bacongobbler]

I can confirm that I hit this as well. fleet did call reload on systemd and somehow one of the containers were stranded. I had to restart fleet before it noticed that the job was destroyed. Logs follow in this gist: https://gist.github.com/bacongobbler/f415eaf79e39131d129b

this part in particular is where we first see this error occur. The unit that was unkillable was deis-controller@1: https://gist.github.com/bacongobbler/f415eaf79e39131d129b#file-gistfile1-txt-L138-L142

[bcwaldon]

@bacongobbler if you start running into this more regularly, please let me know. We need to come up with a reproducible test case and determine if this is systemd- or fleet-specific.

[bcwaldon]

For the time-being, you can un-gracefully restart fleet and clear out the blocked goroutines with system kill --signal SIGKILL fleet && systemctl start fleet

[bcwaldon]

@bacongobbler @gabrtv Since you two have encountered this so here, here's an update. We don't actually have to care about the completion of the systemd jobs in fleet at all, so once we figure out coreos/go-systemd#65, this problem no longer affects fleet. There is clearly an underlying systemd bug that we need to address, but it won't be such a PITA for us anymore.