moby / moby/swarmkit

Task restarts triggered multiple times

Open
#2,650 1 comment 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

kind/bug
Dominant language
Go
Stars
3.7k
Forks
676
Avg merge
4d 9h
Merged PRs (30d)
6

Description

Something looks wrong with SwarmKit restart monitoring of tasks; perhaps it's an odd use-case, or a misunderstanding on my side; perhaps there's a bug where monitoring is not stopped/removed (causing multiple monitors to run and overlap for a single service). No idea really, but I noticed this behavior, so thought it best to open an issue for this.

Here's to reproduce; create a service that runs a one-off command (stops immediately after the command has run), but set a long restart-delay on the service so that a new task is launched every XX seconds/minutes;

docker service create \
  --detach \
  --restart-delay=30s \
  --name cronnie \
  busybox date '+%Y-%m-%d %H:%M:%S doing my thing'

Check the service logs for that service:

docker service logs -f cronnie

cronnie.1.zi8k2zu530tb@linuxkit-025000000001    | 2018-05-28 08:39:41 doing my thing
cronnie.1.r9r9w06w0rrl@linuxkit-025000000001    | 2018-05-28 08:40:12 doing my thing
cronnie.1.xtlmhmo7xyzs@linuxkit-025000000001    | 2018-05-28 08:40:43 doing my thing
cronnie.1.s0hiu7b3vgkq@linuxkit-025000000001    | 2018-05-28 08:41:14 doing my thing
cronnie.1.j3s2gdrf4jmp@linuxkit-025000000001    | 2018-05-28 08:41:45 doing my thing
cronnie.1.pwqzxvj7fi6k@linuxkit-025000000001    | 2018-05-28 08:42:16 doing my thing
cronnie.1.6dkcg4tpiizu@linuxkit-025000000001    | 2018-05-28 08:42:18 doing my thing
cronnie.1.zk1wtq9d3plk@linuxkit-025000000001    | 2018-05-28 08:42:20 doing my thing
cronnie.1.501hrn5izt3r@linuxkit-025000000001    | 2018-05-28 08:42:21 doing my thing
cronnie.1.xu97hmdqzeqj@linuxkit-025000000001    | 2018-05-28 08:42:52 doing my thing
cronnie.1.zp9bkh7gbcr2@linuxkit-025000000001    | 2018-05-28 08:42:54 doing my thing
cronnie.1.9fwrg851qy22@linuxkit-025000000001    | 2018-05-28 08:42:56 doing my thing

Notice that the first couple of iterations are ok; 30..31 seconds in between

cronnie.1.zi8k2zu530tb@linuxkit-025000000001    | 2018-05-28 08:39:41 doing my thing
cronnie.1.r9r9w06w0rrl@linuxkit-025000000001    | 2018-05-28 08:40:12 doing my thing
cronnie.1.xtlmhmo7xyzs@linuxkit-025000000001    | 2018-05-28 08:40:43 doing my thing
cronnie.1.s0hiu7b3vgkq@linuxkit-025000000001    | 2018-05-28 08:41:14 doing my thing
cronnie.1.j3s2gdrf4jmp@linuxkit-025000000001    | 2018-05-28 08:41:45 doing my thing

After that, things seem to go wrong; four containers are spun up within 5 seconds:

cronnie.1.pwqzxvj7fi6k@linuxkit-025000000001    | 2018-05-28 08:42:16 doing my thing
cronnie.1.6dkcg4tpiizu@linuxkit-025000000001    | 2018-05-28 08:42:18 doing my thing
cronnie.1.zk1wtq9d3plk@linuxkit-025000000001    | 2018-05-28 08:42:20 doing my thing
cronnie.1.501hrn5izt3r@linuxkit-025000000001    | 2018-05-28 08:42:21 doing my thing

In a later instance even more:

cronnie.1.yn1cxubdemjg@linuxkit-025000000001    | 2018-05-28 08:49:00 doing my thing
cronnie.1.6hcpm7x9k62q@linuxkit-025000000001    | 2018-05-28 08:49:02 doing my thing
cronnie.1.trxi9sqiierx@linuxkit-025000000001    | 2018-05-28 08:49:04 doing my thing
cronnie.1.rok05vhagbxz@linuxkit-025000000001    | 2018-05-28 08:49:06 doing my thing
cronnie.1.ttlxll1rxl6l@linuxkit-025000000001    | 2018-05-28 08:49:07 doing my thing
cronnie.1.u94s83zjsseb@linuxkit-025000000001    | 2018-05-28 08:49:09 doing my thing
cronnie.1.pv8knvs6w16z@linuxkit-025000000001    | 2018-05-28 08:49:14 doing my thing
cronnie.1.r2r0ersjqvbb@linuxkit-025000000001    | 2018-05-28 08:49:16 doing my thing
cronnie.1.7d2o31r2tlvz@linuxkit-025000000001    | 2018-05-28 08:49:17 doing my thing

...

cronnie.1.levcprbazm86@linuxkit-025000000001    | 2018-05-28 08:51:59 doing my thing
cronnie.1.hpigc7iqeq8a@linuxkit-025000000001    | 2018-05-28 08:52:01 doing my thing
cronnie.1.ofwpicd9070a@linuxkit-025000000001    | 2018-05-28 08:52:03 doing my thing
cronnie.1.ymytyoxbi0pn@linuxkit-025000000001    | 2018-05-28 08:52:05 doing my thing
cronnie.1.36sjtaaohqri@linuxkit-025000000001    | 2018-05-28 08:52:06 doing my thing

Here are service logs a bit later (triggered twice this time):

cronnie.1.qbjp5py9blzj@linuxkit-025000000001    | 2018-05-28 09:12:49 doing my thing
cronnie.1.i2mun1v9hmh2@linuxkit-025000000001    | 2018-05-28 09:12:51 doing my thing

I captured docker events for that time:

2018-05-28T11:12:49.489553706+02:00 network connect 4896a2da9d4943f7e5447ba63ae3c9aa7f4e7f042e341697df709299accfc391 (container=9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103, name=bridge, type=bridge)
2018-05-28T11:12:49.805818922+02:00 container start 9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103 (com.docker.swarm.node.id=oifk2p0hd4tvlb62uf76womx0, com.docker.swarm.service.id=yhi2eiwq17kqzk3airtpmdg55, com.docker.swarm.service.name=cronnie, com.docker.swarm.task=, com.docker.swarm.task.id=qbjp5py9blzjryo60dc28g5y5, com.docker.swarm.task.name=cronnie.1.qbjp5py9blzjryo60dc28g5y5, image=busybox:latest@sha256:141c253bc4c3fd0a201d32dc1f493bcf3fff003b6df416dea4f41046e0f37d47, name=cronnie.1.qbjp5py9blzjryo60dc28g5y5)
2018-05-28T11:12:49.952215678+02:00 container die 9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103 (com.docker.swarm.node.id=oifk2p0hd4tvlb62uf76womx0, com.docker.swarm.service.id=yhi2eiwq17kqzk3airtpmdg55, com.docker.swarm.service.name=cronnie, com.docker.swarm.task=, com.docker.swarm.task.id=qbjp5py9blzjryo60dc28g5y5, com.docker.swarm.task.name=cronnie.1.qbjp5py9blzjryo60dc28g5y5, exitCode=0, image=busybox:latest@sha256:141c253bc4c3fd0a201d32dc1f493bcf3fff003b6df416dea4f41046e0f37d47, name=cronnie.1.qbjp5py9blzjryo60dc28g5y5)
2018-05-28T11:12:50.250284594+02:00 network disconnect 4896a2da9d4943f7e5447ba63ae3c9aa7f4e7f042e341697df709299accfc391 (container=9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103, name=bridge, type=bridge)
2018-05-28T11:12:50.671286196+02:00 container create 84ddbc59eb27e86be964f060120a793d93e532bbf9e478dae1e7d583e10a858f (com.docker.swarm.node.id=oifk2p0hd4tvlb62uf76womx0, com.docker.swarm.service.id=yhi2eiwq17kqzk3airtpmdg55, com.docker.swarm.service.name=cronnie, com.docker.swarm.task=, com.docker.swarm.task.id=5u4p0kozmfa8y9i888zrknycn, com.docker.swarm.task.name=cronnie.1.5u4p0kozmfa8y9i888zrknycn, image=busybox:latest@sha256:141c253bc4c3fd0a201d32dc1f493bcf3fff003b6df416dea4f41046e0f37d47, name=cronnie.1.5u4p0kozmfa8y9i888zrknycn)
2018-05-28T11:12:51.139066821+02:00 container destroy 84ddbc59eb27e86be964f060120a793d93e532bbf9e478dae1e7d583e10a858f (com.docker.swarm.node.id=oifk2p0hd4tvlb62uf76womx0, com.docker.swarm.service.id=yhi2eiwq17kqzk3airtpmdg55, com.docker.swarm.service.name=cronnie, com.docker.swarm.task=, com.docker.swarm.task.id=5u4p0kozmfa8y9i888zrknycn, com.docker.swarm.task.name=cronnie.1.5u4p0kozmfa8y9i888zrknycn, image=busybox:latest@sha256:141c253bc4c3fd0a201d32dc1f493bcf3fff003b6df416dea4f41046e0f37d47, name=cronnie.1.5u4p0kozmfa8y9i888zrknycn)
2018-05-28T11:12:51.273531115+02:00 container create 8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7 (com.docker.swarm.node.id=oifk2p0hd4tvlb62uf76womx0, com.docker.swarm.service.id=yhi2eiwq17kqzk3airtpmdg55, com.docker.swarm.service.name=cronnie, com.docker.swarm.task=, com.docker.swarm.task.id=i2mun1v9hmh22lbvfbcywp8e5, com.docker.swarm.task.name=cronnie.1.i2mun1v9hmh22lbvfbcywp8e5, image=busybox:latest@sha256:141c253bc4c3fd0a201d32dc1f493bcf3fff003b6df416dea4f41046e0f37d47, name=cronnie.1.i2mun1v9hmh22lbvfbcywp8e5)
2018-05-28T11:12:51.288427306+02:00 network connect 4896a2da9d4943f7e5447ba63ae3c9aa7f4e7f042e341697df709299accfc391 (container=8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7, name=bridge, type=bridge)
2018-05-28T11:12:51.689201666+02:00 container destroy 9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103 (com.docker.swarm.node.id=oifk2p0hd4tvlb62uf76womx0, com.docker.swarm.service.id=yhi2eiwq17kqzk3airtpmdg55, com.docker.swarm.service.name=cronnie, com.docker.swarm.task=, com.docker.swarm.task.id=qbjp5py9blzjryo60dc28g5y5, com.docker.swarm.task.name=cronnie.1.qbjp5py9blzjryo60dc28g5y5, image=busybox:latest@sha256:141c253bc4c3fd0a201d32dc1f493bcf3fff003b6df416dea4f41046e0f37d47, name=cronnie.1.qbjp5py9blzjryo60dc28g5y5)
2018-05-28T11:12:51.698961418+02:00 container start 8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7 (com.docker.swarm.node.id=oifk2p0hd4tvlb62uf76womx0, com.docker.swarm.service.id=yhi2eiwq17kqzk3airtpmdg55, com.docker.swarm.service.name=cronnie, com.docker.swarm.task=, com.docker.swarm.task.id=i2mun1v9hmh22lbvfbcywp8e5, com.docker.swarm.task.name=cronnie.1.i2mun1v9hmh22lbvfbcywp8e5, image=busybox:latest@sha256:141c253bc4c3fd0a201d32dc1f493bcf3fff003b6df416dea4f41046e0f37d47, name=cronnie.1.i2mun1v9hmh22lbvfbcywp8e5)
2018-05-28T11:12:51.827981329+02:00 container die 8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7 (com.docker.swarm.node.id=oifk2p0hd4tvlb62uf76womx0, com.docker.swarm.service.id=yhi2eiwq17kqzk3airtpmdg55, com.docker.swarm.service.name=cronnie, com.docker.swarm.task=, com.docker.swarm.task.id=i2mun1v9hmh22lbvfbcywp8e5, com.docker.swarm.task.name=cronnie.1.i2mun1v9hmh22lbvfbcywp8e5, exitCode=0, image=busybox:latest@sha256:141c253bc4c3fd0a201d32dc1f493bcf3fff003b6df416dea4f41046e0f37d47, name=cronnie.1.i2mun1v9hmh22lbvfbcywp8e5)
2018-05-28T11:12:52.111789949+02:00 network disconnect 4896a2da9d4943f7e5447ba63ae3c9aa7f4e7f042e341697df709299accfc391 (container=8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7, name=bridge, type=bridge)
2018-05-28T11:12:52.633675188+02:00 container create 7795755caef130c711209e39e89a67e32d9ca802a9716367c27a1a113c94dc31 (com.docker.swarm.node.id=oifk2p0hd4tvlb62uf76womx0, com.docker.swarm.service.id=yhi2eiwq17kqzk3airtpmdg55, com.docker.swarm.service.name=cronnie, com.docker.swarm.task=, com.docker.swarm.task.id=qs70pueu1tmsirwhvv0gq1141, com.docker.swarm.task.name=cronnie.1.qs70pueu1tmsirwhvv0gq1141, image=busybox:latest@sha256:141c253bc4c3fd0a201d32dc1f493bcf3fff003b6df416dea4f41046e0f37d47, name=cronnie.1.qs70pueu1tmsirwhvv0gq1141)
2018-05-28T11:12:53.016635542+02:00 container destroy 8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7 (com.docker.swarm.node.id=oifk2p0hd4tvlb62uf76womx0, com.docker.swarm.service.id=yhi2eiwq17kqzk3airtpmdg55, com.docker.swarm.service.name=cronnie, com.docker.swarm.task=, com.docker.swarm.task.id=i2mun1v9hmh22lbvfbcywp8e5, com.docker.swarm.task.name=cronnie.1.i2mun1v9hmh22lbvfbcywp8e5, image=busybox:latest@sha256:141c253bc4c3fd0a201d32dc1f493bcf3fff003b6df416dea4f41046e0f37d47, name=cronnie.1.i2mun1v9hmh22lbvfbcywp8e5)

And daemon logs;

time="2018-05-28T09:12:49.474615959Z" level=debug msg="(*worker).Update" len(assignments)=1 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:49.474698390Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:49.474719577Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:49.474751117Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=1 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:49.474836144Z" level=debug msg=assigned module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.desiredstate=RUNNING task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:49.475479326Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=RUNNING state.transition="READY->STARTING" task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:49.477600641Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:49.477936100Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:49.479253009Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/fe542ca2f835a50539f2c493fc62e281a966deaf7bba29f3d3a09776a0a94627/merged 0x2dc7ac0 0x2dc7ac0}"
time="2018-05-28T09:12:49.479568472Z" level=debug msg="Assigning addresses for endpoint cronnie.1.qbjp5py9blzjryo60dc28g5y5's interface on network bridge"
time="2018-05-28T09:12:49.479594013Z" level=debug msg="RequestAddress(LocalDefault/172.17.0.0/16, <nil>, map[])"
time="2018-05-28T09:12:49.479604530Z" level=debug msg="Received set for ordinal 0, start 0, end 65535, any true, release false, serial:false curr:7 \n"
time="2018-05-28T09:12:49.483822806Z" level=debug msg="Assigning addresses for endpoint cronnie.1.qbjp5py9blzjryo60dc28g5y5's interface on network bridge"
time="2018-05-28T09:12:49.488788061Z" level=debug msg="Programming external connectivity on endpoint cronnie.1.qbjp5py9blzjryo60dc28g5y5 (af10efd6d3e748296046ac44632a8e9dca2341622d6c6bd340f8af2fcea89fd9)"
time="2018-05-28T09:12:49.491843270Z" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103 module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/fe542ca2f835a50539f2c493fc62e281a966deaf7bba29f3d3a09776a0a94627/merged
time="2018-05-28T09:12:49Z"           level=debug msg="event published" module="containerd/containers" ns=moby topic="/containers/create" type=containerd.events.ContainerCreate 
time="2018-05-28T09:12:49Z"           level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103/shim.sock" debug=true module="containerd/tasks" pid=3568 
time="2018-05-28T09:12:49Z"           level=debug msg="registering ttrpc server" 
time="2018-05-28T09:12:49Z"           level=debug msg="serving api on unix socket" socket="[inherited from parent]" 
time="2018-05-28T09:12:49.524416015Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="READY->STARTING" task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:49.657768166Z" level=debug msg="sandbox set key processing took 122.303736ms for container 9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103"
time="2018-05-28T09:12:49Z"           level=debug msg="event published" module="containerd/tasks" ns=moby topic="/tasks/create" type=containerd.events.TaskCreate 
time="2018-05-28T09:12:49.775116584Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/create
time="2018-05-28T09:12:49Z"           level=debug msg="event published" module="containerd/tasks" ns=moby topic="/tasks/start" type=containerd.events.TaskStart 
time="2018-05-28T09:12:49.793492894Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/start
time="2018-05-28T09:12:49.806150337Z" level=debug msg="EnableService 9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103 START"
time="2018-05-28T09:12:49.806194936Z" level=debug msg="EnableService 9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103 DONE"
time="2018-05-28T09:12:49.806322279Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=RUNNING state.transition="STARTING->RUNNING" task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:49.806667782Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:49.806706858Z" level=debug msg="begin logs" container=cronnie.1.qbjp5py9blzjryo60dc28g5y5 method="(*Daemon).ContainerLogs" module=daemon
time="2018-05-28T09:12:49.807313251Z" level=debug msg="Calling GET /v1.37/containers/9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103/json"
time="2018-05-28T09:12:49.807404809Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:49.809926103Z" level=debug msg="Calling GET /v1.37/tasks/qbjp5py9blzjryo60dc28g5y5"
time="2018-05-28T09:12:49.820679987Z" level=debug msg="waiting on events" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:49.828773254Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="STARTING->RUNNING" task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:49Z"           level=debug msg="event published" module="containerd/events" ns=moby topic="/tasks/exit" type=containerd.events.TaskExit 
time="2018-05-28T09:12:49.903467104Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exit
time="2018-05-28T09:12:49Z"           level=info msg="shim reaped" id=9d124528387aee20e00adbf6df9974c9c363dd3ebee5c0ef24ecf6f5e97f4103 module="containerd/tasks" 
time="2018-05-28T09:12:49Z"           level=debug msg="event published" module="containerd/tasks" ns=moby topic="/tasks/delete" type=containerd.events.TaskDelete 
time="2018-05-28T09:12:49.952101075Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/delete
time="2018-05-28T09:12:49.952186127Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
time="2018-05-28T09:12:49.952410329Z" level=debug msg="end logs" container=cronnie.1.qbjp5py9blzjryo60dc28g5y5 method="(*Daemon).ContainerLogs" module=daemon
time="2018-05-28T09:12:49.952924728Z" level=debug msg="Revoking external connectivity on endpoint cronnie.1.qbjp5py9blzjryo60dc28g5y5 (af10efd6d3e748296046ac44632a8e9dca2341622d6c6bd340f8af2fcea89fd9)"
time="2018-05-28T09:12:49.953663460Z" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
time="2018-05-28T09:12:50.199851171Z" level=debug msg="Releasing addresses for endpoint cronnie.1.qbjp5py9blzjryo60dc28g5y5's interface on network bridge"
time="2018-05-28T09:12:50.199938091Z" level=debug msg="ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.6)"
time="2018-05-28T09:12:50.199973233Z" level=debug msg="Received set for ordinal 6, start 0, end 0, any false, release true, serial:false curr:7 \n"
time="2018-05-28T09:12:50Z"           level=debug msg="event published" module="containerd/containers" ns=moby topic="/containers/delete" type=containerd.events.ContainerDelete 
time="2018-05-28T09:12:50.357136329Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=RUNNING state.transition="RUNNING->COMPLETE" task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:50.357346709Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:50.357735773Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.358766714Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:50.359071168Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.412150229Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="RUNNING->COMPLETE" task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:50.467171942Z" level=debug msg="assigning to node oifk2p0hd4tvlb62uf76womx0" module=node node.id=oifk2p0hd4tvlb62uf76womx0 task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.571080836Z" level=debug msg="(*worker).Update" len(assignments)=2 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.571139769Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.571147790Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.571154091Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=2 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.571164919Z" level=debug msg=assigned module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.desiredstate=READY task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.571813015Z" level=debug msg="state changed" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.571859030Z" level=debug msg=assigned module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.desiredstate=SHUTDOWN task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:50.571911487Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.572048431Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.575001984Z" level=debug msg="waiting on events" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.575247327Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.575377286Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.575620209Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.576333067Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=READY state.transition="ACCEPTED->PREPARING" task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.576373712Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:50.576719425Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.577622673Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.578053278Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.617316285Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="ASSIGNED->PREPARING" task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.617409406Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="COMPLETE->COMPLETE" task.id=qbjp5py9blzjryo60dc28g5y5
time="2018-05-28T09:12:50.621770721Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/9f0881b3e36d65c0728538d20bc961b0172cfd62345248d089f17a9230ccbb7b/merged 0x2dc7ac0 0x2dc7ac0}"
time="2018-05-28T09:12:50.671397650Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=READY state.transition="PREPARING->READY" task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.671621565Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.672139314Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.672969071Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.673300572Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:50.719197779Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="PREPARING->READY" task.id=5u4p0kozmfa8y9i888zrknycn
time="2018-05-28T09:12:50.974411977Z" level=debug msg="Service yhi2eiwq17kqzk3airtpmdg55 was scaled up from 0 to 1 instances" module=node node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.026552125Z" level=debug msg="assigning to node oifk2p0hd4tvlb62uf76womx0" module=node node.id=oifk2p0hd4tvlb62uf76womx0 task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.130809281Z" level=debug msg="(*worker).Update" len(assignments)=2 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.130897637Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.130918968Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.130936208Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=1 len(updatedTasks)=1 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.130994954Z" level=debug msg=assigned module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.desiredstate=RUNNING task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.131564155Z" level=debug msg="state changed" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=RUNNING state.transition="ASSIGNED->ACCEPTED" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.131909553Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.131866359Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=RUNNING state.transition="ASSIGNED->ACCEPTED" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.134709562Z" level=debug msg="waiting on events" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.134919606Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.135009451Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.135428868Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.137258616Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=RUNNING state.transition="ACCEPTED->PREPARING" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.137534722Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.137947188Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.139333117Z" level=error msg="logs call failed" error="container not ready for logs: exec: controller closed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.202711964Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/9d632ed6bbb7d89fc6971e19623103d57d8ef1ed714496df598b6bd8c5f5c224/merged 0x2dc7ac0 0x2dc7ac0}"
time="2018-05-28T09:12:51.226648172Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="ASSIGNED->PREPARING" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.273747908Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=RUNNING state.transition="PREPARING->READY" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.273995917Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.274487710Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.275382765Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=RUNNING state.transition="READY->STARTING" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.275579554Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.275796346Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.276956466Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/9d632ed6bbb7d89fc6971e19623103d57d8ef1ed714496df598b6bd8c5f5c224/merged 0x2dc7ac0 0x2dc7ac0}"
time="2018-05-28T09:12:51.277228476Z" level=debug msg="Assigning addresses for endpoint cronnie.1.i2mun1v9hmh22lbvfbcywp8e5's interface on network bridge"
time="2018-05-28T09:12:51.277253570Z" level=debug msg="RequestAddress(LocalDefault/172.17.0.0/16, <nil>, map[])"
time="2018-05-28T09:12:51.277263680Z" level=debug msg="Received set for ordinal 0, start 0, end 65535, any true, release false, serial:false curr:7 \n"
time="2018-05-28T09:12:51.283779653Z" level=debug msg="Assigning addresses for endpoint cronnie.1.i2mun1v9hmh22lbvfbcywp8e5's interface on network bridge"
time="2018-05-28T09:12:51.287168645Z" level=debug msg="Programming external connectivity on endpoint cronnie.1.i2mun1v9hmh22lbvfbcywp8e5 (cbe2d36021167798c0883bcdb6aaf80d98640944988b885f026de31846638114)"
time="2018-05-28T09:12:51.290436945Z" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7 module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/9d632ed6bbb7d89fc6971e19623103d57d8ef1ed714496df598b6bd8c5f5c224/merged
time="2018-05-28T09:12:51Z"           level=debug msg="event published" module="containerd/containers" ns=moby topic="/containers/create" type=containerd.events.ContainerCreate 
time="2018-05-28T09:12:51Z"           level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7/shim.sock" debug=true module="containerd/tasks" pid=3694 
time="2018-05-28T09:12:51Z"           level=debug msg="registering ttrpc server" 
time="2018-05-28T09:12:51Z"           level=debug msg="serving api on unix socket" socket="[inherited from parent]" 
time="2018-05-28T09:12:51.328423956Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="PREPARING->STARTING" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.543887782Z" level=debug msg="sandbox set key processing took 212.523934ms for container 8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7"
time="2018-05-28T09:12:51Z"           level=debug msg="event published" module="containerd/tasks" ns=moby topic="/tasks/create" type=containerd.events.TaskCreate 
time="2018-05-28T09:12:51.675336962Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/create
time="2018-05-28T09:12:51.681499590Z" level=debug msg="(*worker).Update" len(assignments)=1 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.681525903Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.681533682Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.681539170Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=1 len(updatedTasks)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51Z"           level=debug msg="event published" module="containerd/tasks" ns=moby topic="/tasks/start" type=containerd.events.TaskStart 
time="2018-05-28T09:12:51.690568095Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/start
time="2018-05-28T09:12:51.699108770Z" level=debug msg="EnableService 8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7 START"
time="2018-05-28T09:12:51.699127344Z" level=debug msg="EnableService 8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7 DONE"
time="2018-05-28T09:12:51.699205018Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=RUNNING state.transition="STARTING->RUNNING" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.699351488Z" level=debug msg="begin logs" container=cronnie.1.i2mun1v9hmh22lbvfbcywp8e5 method="(*Daemon).ContainerLogs" module=daemon
time="2018-05-28T09:12:51.699546803Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.699841783Z" level=debug msg="Calling GET /v1.37/containers/8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7/json"
time="2018-05-28T09:12:51.700043826Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:51.701101823Z" level=debug msg="waiting on events" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51.701587759Z" level=debug msg="Calling GET /v1.37/tasks/i2mun1v9hmh22lbvfbcywp8e5"
time="2018-05-28T09:12:51.732094297Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="STARTING->RUNNING" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:51Z"           level=debug msg="event published" module="containerd/events" ns=moby topic="/tasks/exit" type=containerd.events.TaskExit 
time="2018-05-28T09:12:51.799891258Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exit
time="2018-05-28T09:12:51Z"           level=info msg="shim reaped" id=8bdcca90a383d12a365a24d503575195de0c194b102666a6e27e59122a086df7 module="containerd/tasks" 
time="2018-05-28T09:12:51Z"           level=debug msg="event published" module="containerd/tasks" ns=moby topic="/tasks/delete" type=containerd.events.TaskDelete 
time="2018-05-28T09:12:51.827938663Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/delete
time="2018-05-28T09:12:51.827965323Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
time="2018-05-28T09:12:51.828166695Z" level=debug msg="end logs" container=cronnie.1.i2mun1v9hmh22lbvfbcywp8e5 method="(*Daemon).ContainerLogs" module=daemon
time="2018-05-28T09:12:51.828498040Z" level=debug msg="Revoking external connectivity on endpoint cronnie.1.i2mun1v9hmh22lbvfbcywp8e5 (cbe2d36021167798c0883bcdb6aaf80d98640944988b885f026de31846638114)"
time="2018-05-28T09:12:51.829123667Z" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
time="2018-05-28T09:12:52.052374957Z" level=debug msg="Releasing addresses for endpoint cronnie.1.i2mun1v9hmh22lbvfbcywp8e5's interface on network bridge"
time="2018-05-28T09:12:52.052477212Z" level=debug msg="ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.6)"
time="2018-05-28T09:12:52.052502917Z" level=debug msg="Received set for ordinal 6, start 0, end 0, any false, release true, serial:false curr:7 \n"
time="2018-05-28T09:12:52Z"           level=debug msg="event published" module="containerd/containers" ns=moby topic="/containers/delete" type=containerd.events.ContainerDelete 
time="2018-05-28T09:12:52.245569186Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=RUNNING state.transition="RUNNING->COMPLETE" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:52.245751930Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:52.246182604Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.247126486Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:52.247489245Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.338338859Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="RUNNING->COMPLETE" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:52.395408590Z" level=debug msg="assigning to node oifk2p0hd4tvlb62uf76womx0" module=node node.id=oifk2p0hd4tvlb62uf76womx0 task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.498907815Z" level=debug msg="(*worker).Update" len(assignments)=2 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.498933254Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.498940677Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.498946416Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=2 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.498957333Z" level=debug msg=assigned module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.desiredstate=SHUTDOWN task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:52.499040133Z" level=debug msg=assigned module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.desiredstate=READY task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.499736650Z" level=debug msg="state changed" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.499897772Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.500003445Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.503861747Z" level=debug msg="waiting on events" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.504160598Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.504234448Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:52.504496924Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.506261822Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.506476456Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.508420792Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=READY state.transition="ACCEPTED->PREPARING" task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.508573680Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.508836653Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.544608604Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="ASSIGNED->PREPARING" task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.544694185Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="COMPLETE->COMPLETE" task.id=i2mun1v9hmh22lbvfbcywp8e5
time="2018-05-28T09:12:52.573671831Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/309e58f0ac87b181aaf9ab889f4a1abdef1438f056005308388928b6c4c5c00f/merged 0x2dc7ac0 0x2dc7ac0}"
time="2018-05-28T09:12:52.633876867Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=oifk2p0hd4tvlb62uf76womx0 service.id=yhi2eiwq17kqzk3airtpmdg55 state.desired=READY state.transition="PREPARING->READY" task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.634073589Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.634487048Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.635500551Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.635762141Z" level=debug msg="task status reported" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:52.648576063Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=oifk2p0hd4tvlb62uf76womx0 state.transition="PREPARING->READY" task.id=qs70pueu1tmsirwhvv0gq1141
time="2018-05-28T09:12:52.940520398Z" level=debug msg="sending heartbeat to manager { } with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 session.id=rv4a9nwp9gyte640fav99twhz sessionID=rv4a9nwp9gyte640fav99twhz
time="2018-05-28T09:12:52.940788936Z" level=debug msg="received heartbeat from worker {[swarm-manager] emg7r0j0ou50nqgt8egutjdhl oifk2p0hd4tvlb62uf76womx0 <nil> 192.168.65.3:2377}, expect next heartbeat in 5.376257422s" method="(*Dispatcher).Heartbeat"
time="2018-05-28T09:12:52.940930776Z" level=debug msg="heartbeat successful to manager { }, next heartbeat period: 5.376257422s" method="(*session).heartbeat" module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0 session.id=rv4a9nwp9gyte640fav99twhz sessionID=rv4a9nwp9gyte640fav99twhz
time="2018-05-28T09:12:53.009949869Z" level=debug msg="(*worker).Update" len(assignments)=1 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:53.009985675Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:53.009993732Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0
time="2018-05-28T09:12:53.009999713Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=1 len(updatedTasks)=0 module=node/agent node.id=oifk2p0hd4tvlb62uf76womx0

The above was on Docker for Mac, single node swarm:

Client:
 Version:      18.05.0-ce
 API version:  1.37
 Go version:   go1.9.5
 Git commit:   f150324
 Built:        Wed May  9 22:12:05 2018
 OS/Arch:      darwin/amd64
 Experimental: true
 Orchestrator: swarm

Server:
 Engine:
  Version:      18.05.0-ce
  API version:  1.37 (minimum version 1.12)
  Go version:   go1.10.1
  Git commit:   f150324
  Built:        Wed May  9 22:20:16 2018
  OS/Arch:      linux/amd64
  Experimental: true

Containers: 13
 Running: 6
 Paused: 0
 Stopped: 7
Images: 222
Server Version: 18.05.0-ce
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host ipvlan macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: active
 NodeID: oifk2p0hd4tvlb62uf76womx0
 Is Manager: true
 ClusterID: emg7r0j0ou50nqgt8egutjdhl
 Managers: 1
 Nodes: 1
 Orchestration:
  Task History Retention Limit: 5
 Raft:
  Snapshot Interval: 10000
  Number of Old Snapshots to Retain: 0
  Heartbeat Tick: 1
  Election Tick: 3
 Dispatcher:
  Heartbeat Period: 5 seconds
 CA Configuration:
  Expiry Duration: 3 months
  Force Rotate: 0
 Autolock Managers: false
 Root Rotation In Progress: false
 Node Address: 192.168.65.3
 Manager Addresses:
  192.168.65.3:2377
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 773c489c9c1b21a6d78b5c538cd395416ec50f88
runc version: 4fc53a81fb7c994640722ac585fa9ca548971871
init version: 949e6fa
Security Options:
 seccomp
  Profile: default
Kernel Version: 4.9.87-linuxkit-aufs
Operating System: Docker for Mac
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 1.952GiB
Name: linuxkit-025000000001
ID: NJ6V:TJNN:ER5T:7OSU:KASD:IYGI:5GK5:3NLH:RYYS:G4QZ:6GEO:WGQ2
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 82
 Goroutines: 232
 System Time: 2018-05-28T09:34:05.456080399Z
 EventsListeners: 5
HTTP Proxy: gateway.docker.internal:3128
HTTPS Proxy: gateway.docker.internal:3129
Registry: https://index.docker.io/v1/
Labels:
Experimental: true
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Reproduce with the provided docker service create command using a long restart delay, then compare service logs, docker events, and daemon logs around the first duplicate restart. Trace the SwarmKit restart-monitoring path described in the issue and verify whether monitors remain active for completed tasks. Done means one replacement task is triggered per restart delay, without overlapping monitors or bursts of containers.

Written by the indexing model from the issue text.

Assessment

Tech stack
go
Domain
distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
38/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.