Fleet units stuck after updating, with "No such file or directory."

[scole-scea]

I'd left a comment on coreos/bugs#8 about this, but @bcwaldon asked me to make a new issue here in fleet instead.

We've been seeing many services get stuck in an invalid/dead state, and when querying their status, see a "No such file or directory" error.

My testcase is here: https://github.com/scole-scea/coreos_service_bug, but the TL;DR version is that services linked by Wants= wind up in this state:

scole@scole-kobold:~/devops/issue8 (master)$ fleetctl status other-helper@2.service
● other-helper@2.service
   Loaded: not-found (Reason: No such file or directory)
   Active: inactive (dead) since Fri 2015-03-20 20:11:16 UTC; 2min 53s ago
 Main PID: 1593
   CGroup: /system.slice/system-other\x2dhelper.slice/other-helper@2.service
           ├─1593 /bin/bash -c while true; do sleep 120; done
           └─1743 sleep 120

Mar 20 20:10:31 ci8-host-a.c.ace-ripsaw-671.internal systemd[1]: Starting CoreOS/bugs/issues/8 helper service...
Mar 20 20:10:31 ci8-host-a.c.ace-ripsaw-671.internal systemd[1]: Started CoreOS/bugs/issues/8 helper service.
Mar 20 20:11:16 ci8-host-a.c.ace-ripsaw-671.internal systemd[1]: Stopping CoreOS/bugs/issues/8 helper service...
Mar 20 20:11:16 ci8-host-a.c.ace-ripsaw-671.internal systemd[1]: Stopped CoreOS/bugs/issues/8 helper service.
Mar 20 20:11:20 ci8-host-a.c.ace-ripsaw-671.internal systemd[1]: Cannot add dependency job for unit other-helper@2.service, ignoring: Unit other-helper@2.service failed to load: No such file or directory.
scole@scole-kobold:~/devops/issue8 (master)$ 

I'm about to begin testing with the workaround from https://gist.github.com/sukrit007/574bfb21fea7bdf1711f, which looks promising, in initial testing.

It's also highly likely, based on reading the comments and looking at the errors, that this is related to #1158.

[scole-scea]

I should add: CoreOS 607; fleet 0.9.1; systemd 218.

[bcwaldon]

@scole-scea Can you share the fleet.service logs?

[scole-scea]

Yeah, let me spin this up and grab them.

[scole-scea]

Ok, I stuck the fleet.service log in Gist. https://gist.github.com/scole-scea/98bc4b19ec208d590f07

[balboah]

I find the "no such file or directory" problem to be really common when booting up 10-ish services from scratch, even when removing the Wants. To fix this problem I need to stop, destroy, load and start the failed services manually (only destroy & start doesn't fix it).
(CoreOS stable)

[jalev]

+1

We have this behaviour as well @ SCEE when launching more than 2 services (we have >15). Our services differ from @scole-scea's by having 'Requires' instead of 'Wants'. We've can replicate this behaviour by stopping/destroying/starting via fleet frequently.

Here are my logs. The problem service being 'account_authentication', which fails at 13:20:58.

[scole-scea]

@sukrit007's gist was promising; I've enhanced it to handle global units, non-templated units (i.e. one-shot services), and units associated with timers (which need to get loaded but not started). It's still a hack, but seems to be an effective workaround. It'll get shaken down as time moves forward.

https://gist.github.com/scole-scea/177a367c51d0b93d51f6

[BugRoger]

I'm seeing the same problem. I think this is due to the systemd reload mechanism being buggy. See this log.

Mar 26 16:50:22 mo-b3052ddd7.iaas.mo.sap.corp fleetd[52878]: INFO manager.go:262: Writing systemd unit docker-registry@wdf_1.service (1117b)
Mar 26 16:50:22 mo-b3052ddd7.iaas.mo.sap.corp fleetd[52878]: INFO manager.go:198: Instructing systemd to reload units
Mar 26 16:50:22 mo-b3052ddd7.iaas.mo.sap.corp fleetd[52878]: INFO manager.go:262: Writing systemd unit registrator.service (684b)
Mar 26 16:50:22 mo-b3052ddd7.iaas.mo.sap.corp fleetd[52878]: INFO manager.go:134: Triggered systemd unit registrator.service start: job=1490227

Note the second line. Systemd reload is triggered before all services are written to disk. The start of the registrator.service here fails with:

Mar 26 16:50:22 mo-b3052ddd7.iaas.mo.sap.corp docker[52826]: registrator
Mar 26 16:50:22 mo-b3052ddd7.iaas.mo.sap.corp systemd[1]: registrator.service: main process exited, code=exited, status=2/INVALIDARGUMENT
Mar 26 16:50:22 mo-b3052ddd7.iaas.mo.sap.corp systemd[1]: Stopped Registrator.
Mar 26 16:50:22 mo-b3052ddd7.iaas.mo.sap.corp systemd[1]: Unit registrator.service entered failed state.
Mar 26 16:50:22 mo-b3052ddd7.iaas.mo.sap.corp systemd[1]: registrator.service failed.

And it is because systemd does not see the file systemctl status registrator:

● registrator.service
   Loaded: not-found (Reason: No such file or directory)
   Active: failed (Result: exit-code) since Thu 2015-03-26 16:55:28 UTC; 5min 6s ago
 Main PID: 17117 (code=exited, status=2)

The file is written to disk though. And a manual start can be triggered with:

mo-67b5ad85c ~ # systemctl daemon-reload
mo-67b5ad85c ~ # systemctl start registrator

[scole-scea]

I just (quickly) scanned the systemd bug list at bugs.freedesktop.org, and didn't spot anything matching this behavior. Hey, @bcwaldon, is there any easy way to tell if this issue is also present in the upstream systemd?

[bcwaldon]

@BugRoger The issue you've documented is likely due to something like #1158. I've got a fix in progress for that bug.

@scole-scea The issue you're seeing is likely to the buggy management of the daemon (i.e. daemon-reload'ing at the wrong point in time). The fix for #1158 will apply here, too.

[bcwaldon]

See #1168

[scole-scea]

I'm eager to verify. Crossing fingers.

[bcwaldon]

@scole-scea you can drop the binaries published at https://github.com/coreos/fleet/releases/tag/v0.9.2 onto your machines and modify fleet.service if you want to verify manually.