Skip to content
This repository has been archived by the owner on Jan 30, 2020. It is now read-only.

Handling of unit names with special characters incorrect #477

Closed
tclavier opened this issue May 18, 2014 · 13 comments
Closed

Handling of unit names with special characters incorrect #477

tclavier opened this issue May 18, 2014 · 13 comments
Labels
reviewed/needs more information

Comments

@tclavier
Copy link
Contributor

Given 3 services files with the same content :

[Unit] 
Description=Check this

[Service]
ExecStart=/bin/sh -c "while true; do sleep 45;done"

[Install]
WantedBy=local.target

named

  • d_db.service
  • d-db.service
  • d%db.service

When i start service with fleetctl i have 3 outputs :

  • Timed out waiting for job d_db.service to report state launched
  • Job d-db.service launched on fa051f34.../192.168.33.12
  • Unable to find Job(d%db.service)

And fleetctl list-units say :

UNIT            STATE           LOAD    ACTIVE  SUB     DESC            MACHINE
d%db.service    inactive        -       -       -       Check this      -
d-db.service    launched        loaded  active  running Check this      fa051f34.../192.168.33.12
d_db.service    inactive        -       -       -       Check this      -

It's with fleet v0.3.2, with HEAD fleetctl never return for d_db.service, but output of "fleetctl list-units" is the same.
@jonboulle
Copy link
Contributor

I can't repro with the d_db.service not starting, on both v0.3.2 and HEAD. How big is your cluster?

As for the other unit, it looks like we have a URL-encoding issue with the % sign causing it to lose track of the job:

etcdctl ls /_coreos.com/fleet/job/
/_coreos.com/fleet/job/d�.service
/_coreos.com/fleet/job/d-db.service
/_coreos.com/fleet/job/d_db.service

For now, could you choose a different character for your job name?

@jonboulle
Copy link
Contributor

I'll also note that systemd itself doesn't support this unit name:

core-01 system # cat d%db.service 
[Unit] 
Description=Check this

[Service]
ExecStart=/bin/sh -c "while true; do sleep 45;done"

[Install]
WantedBy=local.target
core-01 system # systemctl start d%db.service 
Failed to start d\x25db.service: Unit d\x25db.service failed to load: No such file or directory.
core-01 system # mv d%db.service d_db.service
core-01 system # systemctl start d_db.service 
core-01 system #

We should obviously fail more gracefully in this case (and prevent you from having submitted the job in the first place); I'll file another ticket for follow up.

@tclavier
Copy link
Contributor Author

Our cluster size is 3 nodes

We use a debian testing with:

$ systemctl --version
systemd 204
+PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ

$ etcd --version
etcd version 0.3.0+git

$ fleetctl -version
fleetctl version 0.3.2+git

$ uname -a
Linux hv-01 3.13-1-amd64 #1 SMP Debian 3.13.10-1 (2014-04-15) x86_64 GNU/Linux

starting a.service:

May 22 18:16:14 hv-01 fleet[794]: I0522 18:16:14.619685 00794 agent.go:257] MachineHeartbeat tick
May 22 18:16:14 hv-01 fleet[794]: I0522 18:16:14.621062 00794 state.go:84] Attempting to retrieve IP route info from netlink
May 22 18:16:14 hv-01 fleet[794]: I0522 18:16:14.622458 00794 state.go:102] Found default route with interface eth0
May 22 18:16:14 hv-01 fleet[794]: I0522 18:16:14.623539 00794 agent.go:283] HeartbeatJobs tick
May 22 18:16:14 hv-01 fleet[794]: I0522 18:16:14.626636 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=18, machines=http://127.0.0.1:4001
May 22 18:16:14 hv-01 fleet[794]: I0522 18:16:14.628467 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=17 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object
May 22 18:16:14 hv-01 fleet[794]: I0522 18:16:14.630440 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=18, machines=http://127.0.0.1:4001
May 22 18:16:14 hv-01 fleet[794]: I0522 18:16:14.630687 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=17 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object
May 22 18:16:29 hv-01 fleet[794]: I0522 18:16:29.611374 00794 agent.go:257] MachineHeartbeat tick
May 22 18:16:29 hv-01 fleet[794]: I0522 18:16:29.612921 00794 state.go:84] Attempting to retrieve IP route info from netlink
May 22 18:16:29 hv-01 fleet[794]: I0522 18:16:29.614263 00794 state.go:102] Found default route with interface eth0
May 22 18:16:29 hv-01 fleet[794]: I0522 18:16:29.615208 00794 agent.go:283] HeartbeatJobs tick
May 22 18:16:29 hv-01 fleet[794]: I0522 18:16:29.617074 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=19, machines=http://127.0.0.1:4001
May 22 18:16:29 hv-01 fleet[794]: I0522 18:16:29.617273 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=18 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object
May 22 18:16:29 hv-01 fleet[794]: I0522 18:16:29.617523 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=19, machines=http://127.0.0.1:4001
May 22 18:16:29 hv-01 fleet[794]: I0522 18:16:29.618420 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=18 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object
May 22 18:16:35 hv-01 puppet-agent[910]: Could not request certificate: getaddrinfo: Name or service not known
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.771300 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=20, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.772227 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=19 Key=/_coreos.com/fleet/unit/23f1ac81bdd52ee48baeb656dfcd3b0893769a40
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.772789 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=20, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.773110 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=19 Key=/_coreos.com/fleet/unit/23f1ac81bdd52ee48baeb656dfcd3b0893769a40
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.774900 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=21, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.775208 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=20 Key=/_coreos.com/fleet/job/a.service/object
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.776049 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=21, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.777371 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=20 Key=/_coreos.com/fleet/job/a.service/object
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.779340 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=22, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.781197 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=21 Key=/_coreos.com/fleet/job/a.service/target-state
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.782503 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=22, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.782582 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=21 Key=/_coreos.com/fleet/job/a.service/target-state
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.784435 00794 event.go:59] Translated response(ModifiedIndex=21) to event(Type=CommandLoadJob)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.784572 00794 bus.go:43] Dispatching CommandLoadJob to listeners
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.784626 00794 bus.go:46] Looking for event handler func HandleCommandLoadJob on listener engine
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.784848 00794 bus.go:49] Calling event handler for CommandLoadJob on listener engine
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.785978 00794 event.go:59] Translated response(ModifiedIndex=21) to event(Type=CommandLoadJob)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.786211 00794 bus.go:43] Dispatching CommandLoadJob to listeners
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.786282 00794 bus.go:46] Looking for event handler func HandleCommandLoadJob on listener agent
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.787403 00794 job.go:112] Got Unit for Job(a.service) from registry
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.788508 00794 event.go:29] CommandLoadJob(a.service): publishing JobOffer
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.789183 00794 engine.go:88] Attempting to lock Job(a.service)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.789473 00794 lock.go:23] Attempting to acquire mutex on job-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.790071 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=23, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.790361 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=22 Key=/_coreos.com/fleet/mutex/job-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.791428 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=23, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.791720 00794 lock.go:33] Successfully acquired mutex on job-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.791752 00794 engine.go:97] Claimed Job(a.service)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.791971 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=22 Key=/_coreos.com/fleet/mutex/job-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.794277 00794 job.go:112] Got Unit for Job(a.service) from registry
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.797035 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=24, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.797330 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=23 Key=/_coreos.com/fleet/offer/a.service/object
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.797866 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=24, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.798929 00794 engine.go:109] Published JobOffer(a.service)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.799205 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=23 Key=/_coreos.com/fleet/offer/a.service/object
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.800536 00794 job.go:112] Got Unit for Job(a.service) from registry
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.801465 00794 job.go:112] Got Unit for Job(a.service) from registry
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.803440 00794 event.go:59] Translated response(ModifiedIndex=23) to event(Type=EventJobOffered)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.803724 00794 event.go:52] Received response from etcd watcher: Action=compareAndDelete ModifiedIndex=24 Key=/_coreos.com/fleet/mutex/job-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.804736 00794 bus.go:43] Dispatching EventJobOffered to listeners
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.804969 00794 bus.go:46] Looking for event handler func HandleEventJobOffered on listener engine
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.805197 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=25, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.806155 00794 event.go:59] Translated response(ModifiedIndex=23) to event(Type=EventJobOffered)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.806391 00794 event.go:52] Received response from etcd watcher: Action=compareAndDelete ModifiedIndex=24 Key=/_coreos.com/fleet/mutex/job-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.806449 00794 bus.go:43] Dispatching EventJobOffered to listeners
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.806654 00794 bus.go:46] Looking for event handler func HandleEventJobOffered on listener agent
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.806909 00794 bus.go:49] Calling event handler for EventJobOffered on listener agent
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.807642 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=25, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.807963 00794 event.go:21] EventJobOffered(a.service): verifying ability to run Job
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.808194 00794 state.go:46] Attempting to lock AgentState
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.808410 00794 state.go:48] AgentState locked
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.808413 00794 agent.go:445] Job(a.service) has no requirements
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.808640 00794 agent.go:448] Job(a.service) has requirements: map[]
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.808866 00794 agent.go:451] Job(a.service) requires machine metadata: map[]
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.808878 00794 agent.go:472] Job(a.service) has no peers to worry about
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.808885 00794 event.go:41] EventJobOffered(a.service): passed all criteria, submitting JobBid
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.808889 00794 agent.go:382] Submitting JobBid for Job(a.service)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.810997 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=26, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.810997 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=25 Key=/_coreos.com/fleet/offer/a.service/bids/63ae89d854314b939fd8f0424317f3da
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.811012 00794 event.go:59] Translated response(ModifiedIndex=25) to event(Type=EventJobBidSubmitted)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.812279 00794 bus.go:43] Dispatching EventJobBidSubmitted to listeners
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.812300 00794 bus.go:46] Looking for event handler func HandleEventJobBidSubmitted on listener engine
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.812306 00794 bus.go:49] Calling event handler for EventJobBidSubmitted on listener engine
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.812315 00794 engine.go:116] Attempting to lock JobOffer(a.service)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.813003 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=26, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.813124 00794 state.go:52] Attempting to unlock AgentState
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.813130 00794 state.go:54] AgentState unlocked
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.813138 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=25 Key=/_coreos.com/fleet/offer/a.service/bids/63ae89d854314b939fd8f0424317f3da
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.813145 00794 event.go:59] Translated response(ModifiedIndex=25) to event(Type=EventJobBidSubmitted)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.813940 00794 bus.go:43] Dispatching EventJobBidSubmitted to listeners
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.813950 00794 bus.go:46] Looking for event handler func HandleEventJobBidSubmitted on listener agent
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.814028 00794 lock.go:23] Attempting to acquire mutex on offer-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.815282 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=27, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.815388 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=26 Key=/_coreos.com/fleet/mutex/offer-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.816138 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=27, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.816210 00794 lock.go:33] Successfully acquired mutex on offer-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.816218 00794 engine.go:125] Claimed JobOffer(a.service)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.816253 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=26 Key=/_coreos.com/fleet/mutex/offer-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.817639 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=28, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.817790 00794 event.go:52] Received response from etcd watcher: Action=delete ModifiedIndex=27 Key=/_coreos.com/fleet/offer/a.service/object
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.818537 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=28, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.818537 00794 event.go:52] Received response from etcd watcher: Action=delete ModifiedIndex=27 Key=/_coreos.com/fleet/offer/a.service/object
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.818981 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=29, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.819024 00794 event.go:52] Received response from etcd watcher: Action=delete ModifiedIndex=28 Key=/_coreos.com/fleet/offer/a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.820195 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=29, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.820296 00794 event.go:52] Received response from etcd watcher: Action=delete ModifiedIndex=28 Key=/_coreos.com/fleet/offer/a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.820866 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=30, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.820940 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=29 Key=/_coreos.com/fleet/job/a.service/target
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.820949 00794 event.go:59] Translated response(ModifiedIndex=29) to event(Type=EventJobScheduled)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822016 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=30, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822084 00794 bus.go:43] Dispatching EventJobScheduled to listeners
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822096 00794 bus.go:46] Looking for event handler func HandleEventJobScheduled on listener engine
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822117 00794 bus.go:49] Calling event handler for EventJobScheduled on listener engine
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822133 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=29 Key=/_coreos.com/fleet/job/a.service/target
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822143 00794 event.go:59] Translated response(ModifiedIndex=29) to event(Type=EventJobScheduled)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822376 00794 event.go:46] EventJobScheduled(a.service): updating cluster
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822389 00794 bus.go:43] Dispatching EventJobScheduled to listeners
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822396 00794 bus.go:46] Looking for event handler func HandleEventJobScheduled on listener agent
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822401 00794 bus.go:49] Calling event handler for EventJobScheduled on listener agent
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822408 00794 state.go:46] Attempting to lock AgentState
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822412 00794 state.go:48] AgentState locked
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822415 00794 event.go:52] EventJobScheduled(a.service): Dropping outstanding offers and bids
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822420 00794 event.go:64] EventJobScheduled(a.service): Job scheduled to this Agent
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822424 00794 agent.go:392] Fetching Job(a.service) from Registry
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.822765 00794 engine.go:139] Scheduled Job(a.service) to Machine(63ae89d854314b939fd8f0424317f3da)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.823029 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=31, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.823077 00794 event.go:52] Received response from etcd watcher: Action=compareAndDelete ModifiedIndex=30 Key=/_coreos.com/fleet/mutex/offer-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.823978 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=31, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.824099 00794 event.go:82] EventJobBidSubmitted(a.service): successfully scheduled Job to Machine(63ae89d854314b939fd8f0424317f3da)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.824177 00794 event.go:52] Received response from etcd watcher: Action=compareAndDelete ModifiedIndex=30 Key=/_coreos.com/fleet/mutex/offer-a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.824651 00794 job.go:112] Got Unit for Job(a.service) from registry
May 22 18:16:37 hv-01 systemd[1]: Starting Check this...
May 22 18:16:37 hv-01 systemd[1]: Started Check this.
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.826667 00794 agent.go:445] Job(a.service) has no requirements
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.826676 00794 agent.go:448] Job(a.service) has requirements: map[]
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.826683 00794 agent.go:451] Job(a.service) requires machine metadata: map[]
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.826689 00794 agent.go:472] Job(a.service) has no peers to worry about
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.826698 00794 event.go:84] EventJobScheduled(a.service): Loading Job
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.826703 00794 agent.go:290] Loading Job(a.service)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.826707 00794 manager.go:198] Writing systemd unit a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.830418 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=32, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.830496 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=31 Key=/_coreos.com/fleet/state/a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.831107 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=32, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.831176 00794 event.go:87] EventJobScheduled(a.service): Bidding for all possible peers of Job
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.831341 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=31 Key=/_coreos.com/fleet/state/a.service
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.832166 00794 event.go:95] EventJobScheduled(a.service): Starting Job
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.833353 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=33, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.833396 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=32 Key=/_coreos.com/fleet/job/a.service/job-state
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.833751 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=33, machines=http://127.0.0.1:4001
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.833751 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=32 Key=/_coreos.com/fleet/job/a.service/job-state
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.837885 00794 manager.go:142] Started systemd unit a.service(done)
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.837900 00794 state.go:52] Attempting to unlock AgentState
May 22 18:16:37 hv-01 fleet[794]: I0522 18:16:37.837904 00794 state.go:54] AgentState unlocked
May 22 18:16:38 hv-01 fleet[794]: I0522 18:16:38.166237 00794 event.go:25] Received event from dbus
May 22 18:16:38 hv-01 fleet[794]: I0522 18:16:38.166238 00794 event.go:29] Translated dbus event to event(Type=EventUnitStateUpdated)
May 22 18:16:38 hv-01 fleet[794]: I0522 18:16:38.166340 00794 bus.go:43] Dispatching EventUnitStateUpdated to listeners
May 22 18:16:38 hv-01 fleet[794]: I0522 18:16:38.166431 00794 bus.go:46] Looking for event handler func HandleEventUnitStateUpdated on listener agent
May 22 18:16:38 hv-01 fleet[794]: I0522 18:16:38.166519 00794 bus.go:49] Calling event handler for EventUnitStateUpdated on listener agent
May 22 18:16:38 hv-01 fleet[794]: I0522 18:16:38.166609 00794 event.go:163] EventUnitStateUpdated(a.service): pushing state (loadState=loaded, activeState=active, subState=running) to Registry
May 22 18:16:38 hv-01 fleet[794]: I0522 18:16:38.168118 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=34, machines=http://127.0.0.1:4001
May 22 18:16:38 hv-01 fleet[794]: I0522 18:16:38.168266 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=33 Key=/_coreos.com/fleet/state/a.service
May 22 18:16:38 hv-01 fleet[794]: I0522 18:16:38.169208 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=34, machines=http://127.0.0.1:4001
May 22 18:16:38 hv-01 fleet[794]: I0522 18:16:38.169405 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=33 Key=/_coreos.com/fleet/state/a.service
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.611351 00794 agent.go:257] MachineHeartbeat tick
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.613295 00794 state.go:84] Attempting to retrieve IP route info from netlink
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.615699 00794 state.go:102] Found default route with interface eth0
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.616058 00794 agent.go:283] HeartbeatJobs tick
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.621395 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=35, machines=http://127.0.0.1:4001
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.622006 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=35, machines=http://127.0.0.1:4001
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.623572 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=34 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.624293 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=35 Key=/_coreos.com/fleet/job/a.service/job-state
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.623869 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=34 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.625641 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=36, machines=http://127.0.0.1:4001
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.626024 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=36, machines=http://127.0.0.1:4001
May 22 18:16:44 hv-01 fleet[794]: I0522 18:16:44.626073 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=35 Key=/_coreos.com/fleet/job/a.service/job-state
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.611273 00794 agent.go:257] MachineHeartbeat tick
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.612726 00794 state.go:84] Attempting to retrieve IP route info from netlink
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.618366 00794 agent.go:283] HeartbeatJobs tick
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.620587 00794 state.go:102] Found default route with interface eth0
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.621189 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=37, machines=http://127.0.0.1:4001
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.622401 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=37, machines=http://127.0.0.1:4001
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.622800 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=36 Key=/_coreos.com/fleet/job/a.service/job-state
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.623060 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=36 Key=/_coreos.com/fleet/job/a.service/job-state
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.624131 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=38, machines=http://127.0.0.1:4001
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.624388 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=37 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.624599 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=38, machines=http://127.0.0.1:4001
May 22 18:16:59 hv-01 fleet[794]: I0522 18:16:59.625477 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=37 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object

starting d_db.service:

May 22 18:20:42 hv-01 fleet[794]: I0522 18:20:42.500881 00794 agent.go:257] MachineHeartbeat tick
May 22 18:20:42 hv-01 fleet[794]: I0522 18:20:42.502233 00794 state.go:84] Attempting to retrieve IP route info from netlink
May 22 18:20:42 hv-01 fleet[794]: I0522 18:20:42.504164 00794 state.go:102] Found default route with interface eth0
May 22 18:20:42 hv-01 fleet[794]: I0522 18:20:42.505456 00794 agent.go:283] HeartbeatJobs tick
May 22 18:20:42 hv-01 fleet[794]: I0522 18:20:42.508931 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=5, machines=http://127.0.0.1:4001
May 22 18:20:42 hv-01 fleet[794]: I0522 18:20:42.510804 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=5, machines=http://127.0.0.1:4001
May 22 18:20:42 hv-01 fleet[794]: I0522 18:20:42.511477 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=4 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object
May 22 18:20:42 hv-01 fleet[794]: I0522 18:20:42.513258 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=4 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.841735 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=6, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.842832 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=5 Key=/_coreos.com/fleet/unit/23f1ac81bdd52ee48baeb656dfcd3b0893769a40
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.843800 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=6, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.845107 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=5 Key=/_coreos.com/fleet/unit/23f1ac81bdd52ee48baeb656dfcd3b0893769a40
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.849614 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=7, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.850633 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=6 Key=/_coreos.com/fleet/job/d_db.service/object
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.851157 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=7, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.851385 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=6 Key=/_coreos.com/fleet/job/d_db.service/object
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.851729 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=8, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.852730 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=7 Key=/_coreos.com/fleet/job/d_db.service/target-state
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.853415 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=8, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.853483 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=7 Key=/_coreos.com/fleet/job/d_db.service/target-state
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.855195 00794 event.go:59] Translated response(ModifiedIndex=7) to event(Type=CommandLoadJob)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.855443 00794 bus.go:43] Dispatching CommandLoadJob to listeners
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.856181 00794 bus.go:46] Looking for event handler func HandleCommandLoadJob on listener engine
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.856440 00794 bus.go:49] Calling event handler for CommandLoadJob on listener engine
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.856940 00794 event.go:59] Translated response(ModifiedIndex=7) to event(Type=CommandLoadJob)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.857644 00794 bus.go:43] Dispatching CommandLoadJob to listeners
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.857923 00794 bus.go:46] Looking for event handler func HandleCommandLoadJob on listener agent
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.858403 00794 job.go:112] Got Unit for Job(d_db.service) from registry
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.859870 00794 event.go:29] CommandLoadJob(d_db.service): publishing JobOffer
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.860140 00794 engine.go:88] Attempting to lock Job(d_db.service)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.860162 00794 lock.go:23] Attempting to acquire mutex on job-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.861595 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=9, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.861833 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=8 Key=/_coreos.com/fleet/mutex/job-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.862141 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=9, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.862232 00794 lock.go:33] Successfully acquired mutex on job-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.862241 00794 engine.go:97] Claimed Job(d_db.service)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.862286 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=8 Key=/_coreos.com/fleet/mutex/job-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.864943 00794 job.go:112] Got Unit for Job(d_db.service) from registry
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.866816 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=10, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.868074 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=9 Key=/_coreos.com/fleet/offer/d_db.service/object
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.868703 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=10, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.869016 00794 engine.go:109] Published JobOffer(d_db.service)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.869516 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=9 Key=/_coreos.com/fleet/offer/d_db.service/object
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.869921 00794 job.go:112] Got Unit for Job(d_db.service) from registry
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.872840 00794 job.go:112] Got Unit for Job(d_db.service) from registry
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.873631 00794 event.go:59] Translated response(ModifiedIndex=9) to event(Type=EventJobOffered)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.873965 00794 event.go:52] Received response from etcd watcher: Action=compareAndDelete ModifiedIndex=10 Key=/_coreos.com/fleet/mutex/job-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.874180 00794 bus.go:43] Dispatching EventJobOffered to listeners
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.874442 00794 bus.go:46] Looking for event handler func HandleEventJobOffered on listener engine
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.875111 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=11, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876262 00794 event.go:59] Translated response(ModifiedIndex=9) to event(Type=EventJobOffered)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876415 00794 event.go:52] Received response from etcd watcher: Action=compareAndDelete ModifiedIndex=10 Key=/_coreos.com/fleet/mutex/job-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876415 00794 bus.go:43] Dispatching EventJobOffered to listeners
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876415 00794 bus.go:46] Looking for event handler func HandleEventJobOffered on listener agent
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876415 00794 bus.go:49] Calling event handler for EventJobOffered on listener agent
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876415 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=11, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876415 00794 event.go:21] EventJobOffered(d_db.service): verifying ability to run Job
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876415 00794 state.go:46] Attempting to lock AgentState
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876416 00794 state.go:48] AgentState locked
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876416 00794 agent.go:445] Job(d_db.service) has no requirements
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876422 00794 agent.go:448] Job(d_db.service) has requirements: map[]
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876428 00794 agent.go:451] Job(d_db.service) requires machine metadata: map[]
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876435 00794 agent.go:472] Job(d_db.service) has no peers to worry about
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876440 00794 event.go:41] EventJobOffered(d_db.service): passed all criteria, submitting JobBid
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.876445 00794 agent.go:382] Submitting JobBid for Job(d_db.service)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.878826 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=12, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.878826 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=12, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.878826 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=11 Key=/_coreos.com/fleet/offer/d_db.service/bids/63ae89d854314b939fd8f0424317f3da
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.878827 00794 event.go:59] Translated response(ModifiedIndex=11) to event(Type=EventJobBidSubmitted)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.879219 00794 event.go:52] Received response from etcd watcher: Action=set ModifiedIndex=11 Key=/_coreos.com/fleet/offer/d_db.service/bids/63ae89d854314b939fd8f0424317f3da
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.879231 00794 event.go:59] Translated response(ModifiedIndex=11) to event(Type=EventJobBidSubmitted)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.879911 00794 bus.go:43] Dispatching EventJobBidSubmitted to listeners
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.879924 00794 bus.go:46] Looking for event handler func HandleEventJobBidSubmitted on listener engine
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.879979 00794 bus.go:49] Calling event handler for EventJobBidSubmitted on listener engine
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.879988 00794 bus.go:43] Dispatching EventJobBidSubmitted to listeners
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.879993 00794 bus.go:46] Looking for event handler func HandleEventJobBidSubmitted on listener agent
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.880001 00794 engine.go:116] Attempting to lock JobOffer(d_db.service)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.880655 00794 state.go:52] Attempting to unlock AgentState
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.880663 00794 state.go:54] AgentState unlocked
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.880739 00794 lock.go:23] Attempting to acquire mutex on offer-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.882287 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=13, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.882288 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=12 Key=/_coreos.com/fleet/mutex/offer-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.882393 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=13, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.882468 00794 lock.go:33] Successfully acquired mutex on offer-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.882477 00794 engine.go:125] Claimed JobOffer(d_db.service)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.882511 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=12 Key=/_coreos.com/fleet/mutex/offer-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.883578 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=14, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.883995 00794 event.go:52] Received response from etcd watcher: Action=delete ModifiedIndex=13 Key=/_coreos.com/fleet/offer/d_db.service/object
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.884838 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=14, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.884939 00794 event.go:52] Received response from etcd watcher: Action=delete ModifiedIndex=13 Key=/_coreos.com/fleet/offer/d_db.service/object
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.886569 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=15, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.886627 00794 event.go:52] Received response from etcd watcher: Action=delete ModifiedIndex=14 Key=/_coreos.com/fleet/offer/d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.886954 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=15, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.886999 00794 event.go:52] Received response from etcd watcher: Action=delete ModifiedIndex=14 Key=/_coreos.com/fleet/offer/d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.888839 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=16, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.888886 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=15 Key=/_coreos.com/fleet/job/d_db.service/target
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.888895 00794 event.go:59] Translated response(ModifiedIndex=15) to event(Type=EventJobScheduled)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.889695 00794 bus.go:43] Dispatching EventJobScheduled to listeners
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.889707 00794 bus.go:46] Looking for event handler func HandleEventJobScheduled on listener engine
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.889712 00794 bus.go:49] Calling event handler for EventJobScheduled on listener engine
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.889721 00794 event.go:46] EventJobScheduled(d_db.service): updating cluster
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.889784 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=16, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.889846 00794 engine.go:139] Scheduled Job(d_db.service) to Machine(63ae89d854314b939fd8f0424317f3da)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.889882 00794 event.go:52] Received response from etcd watcher: Action=create ModifiedIndex=15 Key=/_coreos.com/fleet/job/d_db.service/target
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.889889 00794 event.go:59] Translated response(ModifiedIndex=15) to event(Type=EventJobScheduled)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.890370 00794 bus.go:43] Dispatching EventJobScheduled to listeners
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.890381 00794 bus.go:46] Looking for event handler func HandleEventJobScheduled on listener agent
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.890386 00794 bus.go:49] Calling event handler for EventJobScheduled on listener agent
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.890396 00794 state.go:46] Attempting to lock AgentState
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.890401 00794 state.go:48] AgentState locked
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.890404 00794 event.go:52] EventJobScheduled(d_db.service): Dropping outstanding offers and bids
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.890410 00794 event.go:64] EventJobScheduled(d_db.service): Job scheduled to this Agent
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.890414 00794 agent.go:392] Fetching Job(d_db.service) from Registry
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.892061 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=17, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.892153 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=17, machines=http://127.0.0.1:4001
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.892226 00794 event.go:82] EventJobBidSubmitted(d_db.service): successfully scheduled Job to Machine(63ae89d854314b939fd8f0424317f3da)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.892238 00794 event.go:52] Received response from etcd watcher: Action=compareAndDelete ModifiedIndex=16 Key=/_coreos.com/fleet/mutex/offer-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.893153 00794 event.go:52] Received response from etcd watcher: Action=compareAndDelete ModifiedIndex=16 Key=/_coreos.com/fleet/mutex/offer-d_db.service
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.893386 00794 job.go:112] Got Unit for Job(d_db.service) from registry
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.895338 00794 agent.go:445] Job(d_db.service) has no requirements
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.895348 00794 agent.go:448] Job(d_db.service) has requirements: map[]
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.895354 00794 agent.go:451] Job(d_db.service) requires machine metadata: map[]
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.895360 00794 agent.go:472] Job(d_db.service) has no peers to worry about
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.895368 00794 event.go:84] EventJobScheduled(d_db.service): Loading Job
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.895373 00794 agent.go:290] Loading Job(d_db.service)
May 22 18:20:47 hv-01 fleet[794]: I0522 18:20:47.895379 00794 manager.go:198] Writing systemd unit d_db.service
May 22 18:20:48 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:20:49 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:20:50 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:20:52 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:20:53 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:20:54 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:20:55 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:20:57 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:20:57 hv-01 fleet[794]: I0522 18:20:57.500945 00794 agent.go:257] MachineHeartbeat tick
May 22 18:20:57 hv-01 fleet[794]: I0522 18:20:57.501076 00794 state.go:84] Attempting to retrieve IP route info from netlink
May 22 18:20:57 hv-01 fleet[794]: I0522 18:20:57.501646 00794 state.go:102] Found default route with interface eth0
May 22 18:20:57 hv-01 fleet[794]: I0522 18:20:57.501962 00794 agent.go:283] HeartbeatJobs tick
May 22 18:20:57 hv-01 fleet[794]: I0522 18:20:57.506145 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=18, machines=http://127.0.0.1:4001
May 22 18:20:57 hv-01 fleet[794]: I0522 18:20:57.506276 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=17 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object
May 22 18:20:57 hv-01 fleet[794]: I0522 18:20:57.506318 00794 event.go:73] Creating etcd watcher: key=/_coreos.com/fleet/, index=18, machines=http://127.0.0.1:4001
May 22 18:20:57 hv-01 fleet[794]: I0522 18:20:57.507263 00794 event.go:52] Received response from etcd watcher: Action=update ModifiedIndex=17 Key=/_coreos.com/fleet/machines/63ae89d854314b939fd8f0424317f3da/object
May 22 18:20:58 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:20:59 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:21:01 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:21:02 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:21:03 hv-01 systemd[1]: Looping too fast. Throttling execution a little.
May 22 18:21:05 hv-01 systemd[1]: Looping too fast. Throttling execution a little.

@bcwaldon bcwaldon changed the title service name Handling of unit names with special characters incorrect May 26, 2014
@oalbiez
Copy link

oalbiez commented Jun 2, 2014

Please, we really need help on this issue.

@jonboulle
Copy link
Contributor

Could you please clarify what the issue is here exactly?

@oalbiez
Copy link

oalbiez commented Jun 2, 2014

As you could not reproduce our issue, we sent you logs of our problem plus informations about software versions.
The service 'a.service' starts without error. The same service called 'd_db.service' times out. Thomas has joined the logs for both cases.

We can starts theses services manually using systemd without problem.

Whih other information could be usefull for you ?

@bcwaldon
Copy link
Contributor

bcwaldon commented Jun 4, 2014

@jonboulle Looks like we might not be serializing dbus paths properly. I used the same unit provided by @tclavier and found this log line:

Jun 04 18:06:01 core-01 fleet[3355]: E0604 18:06:01.753853 03355 agent.go:274] Failed fetching state of Unit(d_db.service): Message did not receive a reply (timeout by message bus)

@jonboulle
Copy link
Contributor

Interesting - is this a bug in systemd? It causes it to completely hang on the machine it seems

core@core-02 ~ $ systemctl list-units
Failed to list units: Activation of org.freedesktop.systemd1 timed out

@oalbiez
Copy link

oalbiez commented Jun 6, 2014

Yes, systemd hand after this bug. In my logs, systemd seems to be flooded by dbus requests:

Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice
Jun  2 20:45:38 hv-02 systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/d_db_2eservice

@zspencer
Copy link

I have a similar error that appears to occur only if my unit file names have _ in them.

fleetctl version 0.5.0 on my mac; 0.3.3 on core.

Jun 18 22:54:56 segmentation-01 sshd[3850]: Accepted publickey for core from 10.0.2.2 port 55994 ssh2: RSA dd:3b:b8:2e:85:04:06:e9:ab:ff:a8:0a:c0:04:6e:d6
Jun 18 22:54:56 segmentation-01 sshd[3850]: SSH: Server;Ltype: Kex;Remote: 10.0.2.2-55994;Enc: aes128-ctr;MAC: [email protected];Comp: none
Jun 18 22:55:10 segmentation-01 dbus[2922]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Jun 18 22:55:10 segmentation-01 dbus-daemon[2922]: dbus[2922]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Jun 18 22:55:10 segmentation-01 fleet[3017]: E0618 22:55:10.234653 03017 event.go:30] Received error from dbus: err=Activation of org.freedesktop.systemd1 timed out
Jun 18 22:55:12 segmentation-01 systemd[1]: Starting Generate /run/coreos/motd...
Jun 18 22:55:12 segmentation-01 systemd[1]: Started Generate /run/coreos/motd.

@jonboulle
Copy link
Contributor

What version of systemd? I've been really struggling to reproduce this in my own testing.

@oalbiez
Copy link

oalbiez commented Jun 20, 2014

We use debian testing :

$ systemctl --version
systemd 204
+PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ

fleet is the master on github.

as a workarround of this bug, we currently encode all our service names in hex string

@jonboulle jonboulle mentioned this issue Jun 25, 2014
Closed
@jonboulle
Copy link
Contributor

Apologies for the confusion and difficulties reproducing this issue. It should now finally be resolved on master and available in the next release!

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
reviewed/needs more information
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@zspencer @oalbiez @tclavier @bcwaldon @jonboulle