fleetctl start hanging after submitting template unit

[MacTynow]

Some of my units can't load when I run fleetctl start unit.service. The command just hangs. If I print the debug log I get this output :

2015/05/27 15:17:12 INFO client.go:366: etcd: sending HTTP request GET      http://127.0.0.1:4001/v2/keys/_coreos.com/fleet/job/datacubes.service? consistent=true&recursive=true&sorted=false
2015/05/27 15:17:12 INFO client.go:373: etcd: recv response from GET http://127.0.0.1:4001/v2/keys/_coreos.com/fleet/job/datacubes.service?consistent=true&recursive=true&sorted=false: 200 OK
2015/05/27 15:17:12 INFO client.go:366: etcd: sending HTTP request GET http://127.0.0.1:4001/v2/keys/_coreos.com/fleet/unit/05ce25aa7bd72ab4d25a07dd47e2277a90598482?consistent=true&recursive=true&sorted=false
2015/05/27 15:17:12 INFO client.go:373: etcd: recv response from GET http://127.0.0.1:4001/v2/keys/_coreos.com/fleet/unit/05ce25aa7bd72ab4d25a07dd47e2277a90598482?consistent=true&recursive=true&sorted=false: 200 OK
2015/05/27 15:17:12 INFO client.go:366: etcd: sending HTTP request GET http://127.0.0.1:4001/v2/keys/_coreos.com/fleet/job/datacubes.service?consistent=true&recursive=true&sorted=false
2015/05/27 15:17:12 INFO client.go:373: etcd: recv response from GET http://127.0.0.1:4001/v2/keys/_coreos.com/fleet/job/datacubes.service?consistent=true&recursive=true&sorted=false: 200 OK
2015/05/27 15:17:12 INFO client.go:366: etcd: sending HTTP request GET http://127.0.0.1:4001/v2/keys/_coreos.com/fleet/states/datacubes.service/380f48b973a14f758804af723f3 50c7e?consistent=true&recursive=false&sorted=false
2015/05/27 15:17:12 INFO client.go:373: etcd: recv response from GET http://127.0.0.1:4001/v2/keys/_coreos.com/fleet/states/datacubes.service/380f48b973a14f758804af723f350c7e?consistent=true&recursive=false&sorted=false: 404 Not Found

As you can see the last line is the problem, causing an infinite loop. Here is my unit file :

[Unit]
Description=Datacubes
After=nginx-proxy.service
Requires=docker.service

[Service]
ExecStart=/home/core/scripts/service.sh datacubes start
ExecStop=/home/core/scripts/service.sh datacubes stop
Restart=on-failure
RestartSec=60
User=core

The unit still appears as launched

UNIT            HASH    DSTATE      STATE       TARGET
datacubes.service   18120e2 launched    inactive    380f48b9.../10.0.1.99

Weirdly, my global units work.

I am running on CoreOS 647.0.0.

Note that this happens on every new cluster I setup. I destroyed and recreated 3 clusters and had the same issue on all of them.

[MacTynow]

Could this be linked to the fact that I ran fleetctl load unit@.service instead of submit?

[MacTynow]

This seems to be the case. Running load on a template seems to break the cluster, journalctl is spammed by those messages :

May 27 16:09:18 ip-10-0-1-133.ec2.internal fleetd[604]: ERROR generator.go:67: Failed fetching current unit states: Unit name datacubes@.service is not valid.
May 27 16:09:19 ip-10-0-1-133.ec2.internal fleetd[604]: ERROR generator.go:67: Failed fetching current unit states: Unit name datacubes@.service is not valid.
May 27 16:09:20 ip-10-0-1-133.ec2.internal fleetd[604]: ERROR generator.go:67: Failed fetching current unit states: Unit name datacubes@.service is not valid.
May 27 16:09:21 ip-10-0-1-133.ec2.internal fleetd[604]: ERROR generator.go:67: Failed fetching current unit states: Unit name datacubes@.service is not valid.
May 27 16:09:22 ip-10-0-1-133.ec2.internal fleetd[604]: ERROR generator.go:67: Failed fetching current unit states: Unit name datacubes@.service is not valid.
May 27 16:09:22 ip-10-0-1-133.ec2.internal systemd[1]: Starting Generate /run/coreos/motd...
May 27 16:09:22 ip-10-0-1-133.ec2.internal fleetd[604]: ERROR reconcile.go:81: Unable to determine agent's current state: failed fetching unit states from UnitManager: Unit name datacubes@.service is not valid.

[scole-scea]

Oh, yeah. Trying to run a template often causes stuff to hang.

[scole-scea]

In fact I wonder if the real bug here is that fleetctl doesn't error out when you try to run/load a template. Once you do it once, you learn not to do it, but I suspect there are plenty of people new to fleet who make this mistake. (And if you write a bash script wrong it's easy to get an unexpected hang. E.g., if id is the empty string fleetctl load service@$id.service hangs.)

[MacTynow]

I think that the fact that it doesn't error, still tries to load it and then prevents you from starting any other units in the cluster, is quite problematic.

[EtienneBruines]

I experience similar issues. I've experimented a bit with the filename / templating, and with the complexity of the .service file, and brought it down to this. It had functioned before; so I feel like the things I'm providing now point to the conclusion that these things are unrelated.

2015/06/18 18:59:19 DEBUG http.go:28: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json
2015/06/18 18:59:19 DEBUG http.go:31: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json 200 OK
2015/06/18 18:59:19 DEBUG fleetctl.go:610: Found Unit(skydns.service) in Registry, no need to recreate it
2015/06/18 18:59:19 DEBUG fleetctl.go:494: Unit(skydns.service) found in local filesystem
2015/06/18 18:59:19 DEBUG http.go:28: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json
2015/06/18 18:59:19 DEBUG http.go:31: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json 200 OK
2015/06/18 18:59:19 DEBUG fleetctl.go:720: Setting Unit(skydns.service) target state to loaded
2015/06/18 18:59:19 DEBUG http.go:28: HTTP PUT http://domain-sock/fleet/v1/units/skydns.service?alt=json
2015/06/18 18:59:19 DEBUG http.go:31: HTTP PUT http://domain-sock/fleet/v1/units/skydns.service?alt=json 204 No Content
2015/06/18 18:59:19 DEBUG http.go:28: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json
2015/06/18 18:59:19 DEBUG http.go:31: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json 200 OK
2015/06/18 18:59:19 DEBUG http.go:28: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json
2015/06/18 18:59:19 DEBUG http.go:31: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json 200 OK
2015/06/18 18:59:20 DEBUG http.go:28: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json
2015/06/18 18:59:20 DEBUG http.go:31: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json 200 OK
2015/06/18 18:59:20 DEBUG http.go:28: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json
2015/06/18 18:59:20 DEBUG http.go:31: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json 200 OK
2015/06/18 18:59:21 DEBUG http.go:28: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json
2015/06/18 18:59:21 DEBUG http.go:31: HTTP GET http://domain-sock/fleet/v1/units/skydns.service?alt=json 200 OK

I can reproduce it here by saving this file called skydns.service in my current working directory:

[Unit]
Description=SkyDNS Service

[Service]
TimeoutStartSec=0
KillMode=none
EnvironmentFile=/etc/environment
ExecStart=echo "Success"

Then, I run:

$ fleetctl submit skydns.service
$ fleetctl --debug load skydns.service

to produce the log file at the top.

fleetd version 0.10.1
fleetctl version 0.10.1

• Using the current master (June 17th), does not help either.
• I get the message regardless of the machine I use inside the fleet.

[jalev]

I too experience errors when loading a template without any data after the @ sign.

I'm using Fleet v0.9.2 (CoreOS Stable 647.2.0)

We have a unit called smoker@.service. This unit is intended to launch multiple instances of the smoker service.

When running fleetctl load smoker@.service, you will immediately get the following logs from Fleet:

Jun 16 12:56:43 core-01-01 fleetd[595]: ERROR generator.go:67: Failed fetching current unit states: Unit name smoker@.service is not valid.
Jun 16 12:56:44 core-01-01 fleetd[595]: ERROR generator.go:67: Failed fetching current unit states: Unit name smoker@.service is not valid.
Jun 16 12:56:45 core-01-01 fleetd[595]: ERROR generator.go:67: Failed fetching current unit states: Unit name smoker@.service is not valid.
Jun 16 12:56:46 core-01-01 fleetd[595]: ERROR generator.go:67: Failed fetching current unit states: Unit name smoker@.service is not valid.
Jun 16 12:56:47 core-01-01 fleetd[595]: ERROR generator.go:67: Failed fetching current unit states: Unit name smoker@.service is not valid.
Jun 16 12:56:47 core-01-01 fleetd[595]: ERROR reconcile.go:81: Unable to determine agent's current state: failed fetching unit states from UnitManager: Unit name smoker@.service is not valid.

This causes Fleet to behave in the following ways:

• You won't be able to delete the offending unit from Fleet's registry
• Any attempt to destroy via fleetctl won't be honoured
• You can continue submitting units to Fleet, but it will no longer keep track of them
• Fleet will no longer keep track of job states of all existing units.
• If Fleet is restarted, you won't be able to see units in fleetctl list-units as generator is looping on smoker@.service

The only way to fix this is to stop Fleet, remove the offending unit from the filesystem, and remove all references to the unit in etcd.

Steps to replicate:

1. Create test@.service with the following content:

[Unit]
Description=This is a test

[Service]
ExecStart=/usr/bin/docker run --name=%p-%i -i debian:latest echo "Hello World!"
ExecStop=/usr/bin/docker rm %p-%i

1. Load into fleet with fleetctl load test@.service
2. Watch fleet's journal (journalctl -u fleet -f)

[dlyubarskiy]

Experiencing the same exact issue with Fleet 0.10.2 (CoreOS 681.2.0 - Stable). Have not been able to find a work around so far.

[devurandom]

This does not only seem to affect templated units, but also units depending on templated units:

[Unit]
Description=Generate service-account key file

[Service]
ExecStartPre=-/usr/bin/mkdir -p /opt/share/kube
ExecStart=/bin/openssl genrsa -out /opt/share/kube/kube-serviceaccount.key 2048 2>/dev/null
RemainAfterExit=yes
Type=oneshot

[X-Fleet]
MachineOf=kube-apiserver@*.service

$ fleetctl --debug load generate-serviceaccount-key.service                                                                                                                                                                   
2015/07/02 12:24:51 DEBUG fleetctl.go:273: Defaulting to --driver=etcd as --endpoint appears to be etcd
2015/07/02 12:24:52 DEBUG client.go:367: etcd: sending HTTP request GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/machines?consistent=true&recursive=true&sorted=true
2015/07/02 12:24:52 DEBUG client.go:374: etcd: recv response from GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/machines?consistent=true&recursive=true&sorted=true: 200 OK
2015/07/02 12:24:52 DEBUG client.go:367: etcd: sending HTTP request GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service?consistent=true&recursive=true&sorted=false
2015/07/02 12:24:52 DEBUG client.go:374: etcd: recv response from GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service?consistent=true&recursive=true&sorted=false: 404 Not Found
2015/07/02 12:24:52 DEBUG fleetctl.go:489: Unit(generate-serviceaccount-key.service) found in local filesystem
2015/07/02 12:24:52 DEBUG client.go:367: etcd: sending HTTP request PUT http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/unit/5910e3addde9a7679cfca4068b1714efa8dab9d3?prevExist=false
2015/07/02 12:24:52 DEBUG client.go:374: etcd: recv response from PUT http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/unit/5910e3addde9a7679cfca4068b1714efa8dab9d3?prevExist=false: 412 Precondition Failed
2015/07/02 12:24:52 DEBUG client.go:367: etcd: sending HTTP request PUT http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service/object?prevExist=false
2015/07/02 12:24:52 DEBUG client.go:374: etcd: recv response from PUT http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service/object?prevExist=false: 201 Created
2015/07/02 12:24:52 DEBUG client.go:367: etcd: sending HTTP request PUT http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service/target-state
2015/07/02 12:24:52 DEBUG client.go:374: etcd: recv response from PUT http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service/target-state: 201 Created
2015/07/02 12:24:52 DEBUG fleetctl.go:578: Created Unit(generate-serviceaccount-key.service) in Registry
2015/07/02 12:24:52 DEBUG client.go:367: etcd: sending HTTP request GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service?consistent=true&recursive=true&sorted=false
2015/07/02 12:24:52 DEBUG client.go:374: etcd: recv response from GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service?consistent=true&recursive=true&sorted=false: 200 OK
2015/07/02 12:24:52 DEBUG client.go:367: etcd: sending HTTP request GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/unit/5910e3addde9a7679cfca4068b1714efa8dab9d3?consistent=true&recursive=true&sorted=false
2015/07/02 12:24:52 DEBUG client.go:374: etcd: recv response from GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/unit/5910e3addde9a7679cfca4068b1714efa8dab9d3?consistent=true&recursive=true&sorted=false: 200 OK
2015/07/02 12:24:52 DEBUG client.go:367: etcd: sending HTTP request GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service?consistent=true&recursive=true&sorted=false
2015/07/02 12:24:52 DEBUG client.go:374: etcd: recv response from GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service?consistent=true&recursive=true&sorted=false: 200 OK
2015/07/02 12:24:52 DEBUG fleetctl.go:715: Setting Unit(generate-serviceaccount-key.service) target state to loaded
2015/07/02 12:24:52 DEBUG client.go:367: etcd: sending HTTP request PUT http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service/target-state
2015/07/02 12:24:52 DEBUG client.go:374: etcd: recv response from PUT http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service/target-state: 200 OK
2015/07/02 12:24:52 DEBUG client.go:367: etcd: sending HTTP request GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service?consistent=true&recursive=true&sorted=false
2015/07/02 12:24:52 DEBUG client.go:374: etcd: recv response from GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/job/generate-serviceaccount-key.service?consistent=true&recursive=true&sorted=false: 200 OK
2015/07/02 12:24:52 DEBUG client.go:367: etcd: sending HTTP request GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/unit/5910e3addde9a7679cfca4068b1714efa8dab9d3?consistent=true&recursive=true&sorted=false
2015/07/02 12:24:52 DEBUG client.go:374: etcd: recv response from GET http://127.0.0.1:2379/v2/keys/_coreos.com/fleet/unit/5910e3addde9a7679cfca4068b1714efa8dab9d3?consistent=true&recursive=true&sorted=false: 200 OK
^C

$ fleetctl list-unit-files
UNIT                                    HASH    DSTATE  STATE           TARGET
generate-serviceaccount-key.service     5910e3a loaded  inactive        -

Note 1: The unit loaded successfully, as list-unit-files shows, so I aborted fleetctl load.
Note 2: kube-apiserver@*.service is not yet loaded into the cluster.

The cluster is running CoreOS 681.2.0 and the client is running Fleet 0.10.2 on Ubuntu 14.04.

[devurandom]

Now I submitted all units before loading or starting any:

$ fleetctl list-unit-files
UNIT                                    HASH    DSTATE          STATE           TARGET
generate-serviceaccount-key.service     5910e3a inactive        inactive        -
kube-apiserver@.service                 253ccef inactive        -               global
kube-controller-manager@.service        86d9d7f inactive        inactive        -
kube-kubelet@.service                   0199ceb inactive        -               global
kube-proxy@.service                     e905f6f inactive        -               global
kube-scheduler@.service                 995eb83 inactive        inactive        -
kuberegister@.service                   49739d5 inactive        inactive        -

Afterwards I could start the apiserver:

$ fleetctl start kube-apiserver@0.20.2
Triggered global unit kube-apiserver@0.20.2.service start

(Please note that loading global units worked already during my last try, when I tried to load the unit directly.)

The unit appears to running, but its dependency generate-serviceaccount-key.service is still inactive:

$ fleetctl list-unit-files
UNIT                                    HASH    DSTATE          STATE           TARGET
generate-serviceaccount-key.service     5910e3a inactive        inactive        -
kube-apiserver@.service                 253ccef inactive        -               global
kube-apiserver@0.20.2.service           253ccef launched        -               global
kube-controller-manager@.service        86d9d7f inactive        inactive        -
kube-kubelet@.service                   0199ceb inactive        -               global
kube-proxy@.service                     e905f6f inactive        -               global
kube-scheduler@.service                 995eb83 inactive        inactive        -
kuberegister@.service                   49739d5 inactive        inactive        -

kube-apiserver@.service is a global unit, depending on generate-serviceaccount-key.service (which is not global, s.a.):

[Unit]
Description=Kubernetes API Server
Documentation=https://github.com/GoogleCloudPlatform/kubernetes
Requires=etcd2.service generate-serviceaccount-key.service
After=etcd2.service generate-serviceaccount-key.service

[Service]
…

[X-Fleet]
Global=true
MachineMetadata=k8srole=master

At the end, there is still no actual unit running:

$ fleetctl list-units
UNIT    MACHINE ACTIVE  SUB

[bcwaldon]

It is a known issue that if you submit/start a template unit (i.e. foo@.service), the affected fleet agent will stop publishing state for its other units. Unfortunately, I can't seem to find that issue... It seems like a fix was started here: #1024.

We also know that the overall experience with template units is a little broken: #969