Data race in agent logging

[cyli]

Saw this in CI, but couldn't spot what was causing it immediately. Looks like some kind of logging. @dperny suggests possibly the log entry being accessed in more than one place.

cd "$WORKDIR" && TMPDIR=/tmpfs make ci
🐳 fmt
🐳 bin/swarmd
🐳 bin/swarmctl
🐳 bin/swarm-bench
🐳 bin/swarm-rafttool
🐳 bin/protoc-gen-gogoswarm
🐳 ineffassign
🐳 misspell
🐳 protos
protoc -I.:/home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/gogo/protobuf:/home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor:/home/ubuntu/.go_workspace/src:/usr/local/include --include_imports --descriptor_set_out=/tmpfs/descriptors.pb-021291768 --gogoswarm_out=plugins=grpc+deepcopy+storeobject+raftproxy+authenticatedwrapper,import_path=github.com/docker/swarmkit/api,Mgogoproto/gogo.proto=github.com/gogo/protobuf/gogoproto,Mgoogle/protobuf/any.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/descriptor.proto=github.com/gogo/protobuf/protoc-gen-gogo/descriptor,Mgoogle/protobuf/duration.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/field_mask.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/timestamp.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/wrappers.proto=github.com/gogo/protobuf/types:/home/ubuntu/.go_workspace/src /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/ca.proto /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/control.proto /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/dispatcher.proto /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/health.proto /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/logbroker.proto /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/objects.proto /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/raft.proto /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/resource.proto /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/snapshot.proto /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/specs.proto /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/types.proto /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/api/watch.proto
protoc -I.:/home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/gogo/protobuf:/home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor:/home/ubuntu/.go_workspace/src:/usr/local/include --gogoswarm_out=plugins=grpc+deepcopy+storeobject+raftproxy+authenticatedwrapper,import_path=github.com/docker/swarmkit/protobuf/plugin,Mgogoproto/gogo.proto=github.com/gogo/protobuf/gogoproto,Mgoogle/protobuf/any.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/descriptor.proto=github.com/gogo/protobuf/protoc-gen-gogo/descriptor,Mgoogle/protobuf/duration.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/field_mask.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/timestamp.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/wrappers.proto=github.com/gogo/protobuf/types:/home/ubuntu/.go_workspace/src /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/protobuf/plugin/plugin.proto
protoc -I.:/home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/gogo/protobuf:/home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor:/home/ubuntu/.go_workspace/src:/usr/local/include --gogoswarm_out=plugins=grpc+deepcopy+storeobject+raftproxy+authenticatedwrapper,import_path=github.com/docker/swarmkit/protobuf/plugin/deepcopy/test,Mgogoproto/gogo.proto=github.com/gogo/protobuf/gogoproto,Mgoogle/protobuf/any.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/descriptor.proto=github.com/gogo/protobuf/protoc-gen-gogo/descriptor,Mgoogle/protobuf/duration.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/field_mask.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/timestamp.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/wrappers.proto=github.com/gogo/protobuf/types:/home/ubuntu/.go_workspace/src /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/protobuf/plugin/deepcopy/test/deepcopy.proto
protoc -I.:/home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/gogo/protobuf:/home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor:/home/ubuntu/.go_workspace/src:/usr/local/include --gogoswarm_out=plugins=grpc+deepcopy+storeobject+raftproxy+authenticatedwrapper,import_path=github.com/docker/swarmkit/protobuf/plugin/raftproxy/test,Mgogoproto/gogo.proto=github.com/gogo/protobuf/gogoproto,Mgoogle/protobuf/any.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/descriptor.proto=github.com/gogo/protobuf/protoc-gen-gogo/descriptor,Mgoogle/protobuf/duration.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/field_mask.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/timestamp.proto=github.com/gogo/protobuf/types,Mgoogle/protobuf/wrappers.proto=github.com/gogo/protobuf/types:/home/ubuntu/.go_workspace/src /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/protobuf/plugin/raftproxy/test/service.proto
protoc --decode google.protobuf.FileDescriptorSet -I/usr/local/include /usr/local/include/google/protobuf/descriptor.proto
🐳 generate
🐳 checkprotos
🐳 coverage
?   	github.com/docker/swarmkit	[no test files]
time="2018-03-28T21:19:18Z" level=warning msg="no certificate expiration specified, using default" cluster.id=ytbhivhicz7orlnk7fzvivq4x method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestAgentStartStop
time="2018-03-28T21:19:18Z" level=debug msg="Root CA set successfully" cluster.id=ytbhivhicz7orlnk7fzvivq4x method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestAgentStartStop
time="2018-03-28T21:19:18Z" level=debug msg="(*Agent).run" module=agent testHasExternalCA=false testname=TestAgentStartStop
time="2018-03-28T21:19:18Z" level=info msg="manager selected by agent for new session: { localhost:4949}" module=agent testHasExternalCA=false testname=TestAgentStartStop
time="2018-03-28T21:19:18Z" level=debug msg="(*Agent).run exited" module=agent testHasExternalCA=false testname=TestAgentStartStop
time="2018-03-28T21:19:18Z" level=info msg="waiting 0s before registering session" module=agent testHasExternalCA=false testname=TestAgentStartStop
time="2018-03-28T21:19:18Z" level=info msg="Failed to dial 127.0.0.1:56107: connection error: desc = \"transport: context canceled\"; please retry." module=grpc
time="2018-03-28T21:19:18Z" level=info msg="Failed to dial 127.0.0.1:56107: connection error: desc = \"transport: context canceled\"; please retry." module=grpc
time="2018-03-28T21:19:18Z" level=info msg="Failed to dial 127.0.0.1:56107: connection error: desc = \"transport: context canceled\"; please retry." module=grpc
time="2018-03-28T21:19:18Z" level=info msg="Failed to dial 127.0.0.1:56107: connection error: desc = \"transport: context canceled\"; please retry." module=grpc
time="2018-03-28T21:19:18Z" level=info msg="transport: http2Server.HandleStreams failed to receive the preface from client: read tcp 127.0.0.1:56107->127.0.0.1:51685: use of closed network connection" module=grpc
time="2018-03-28T21:19:18Z" level=info msg="grpc: Server.Serve failed to complete security handshake from \"127.0.0.1:51686\": EOF" module=grpc
time="2018-03-28T21:19:18Z" level=info msg="grpc: addrConn.resetTransport failed to create client transport: connection error: desc = \"transport: dial tcp 127.0.0.1:4949: getsockopt: connection refused\"; Reconnecting to {localhost:4949 <nil>}" module=grpc
time="2018-03-28T21:19:18Z" level=info msg="Failed to dial localhost:4949: grpc: the connection is closing; please retry." module=grpc
time="2018-03-28T21:19:19Z" level=warning msg="no certificate expiration specified, using default" cluster.id=h19z63fy3j3poo0rm9hi0ql0m method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug msg="Root CA set successfully" cluster.id=h19z63fy3j3poo0rm9hi0ql0m method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug msg="(*Agent).run" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:39285}" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=info msg="waiting 0s before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug localDispatcher=false method="(*session).watch" module=agent session.id=wpoq6lqg644xqag8blez2dsp0 testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug msg="agent: registered" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug msg="(*session).heartbeat" localDispatcher=false module=agent session.id=wpoq6lqg644xqag8blez2dsp0 testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=wpoq6lqg644xqag8blez2dsp0 testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug msg="(*session).listen" localDispatcher=false module=agent session.id=wpoq6lqg644xqag8blez2dsp0 testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=warning msg="manager does not support log subscriptions" localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=wpoq6lqg644xqag8blez2dsp0 testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug msg="sending heartbeat to manager { 127.0.0.1:39285} with timeout 500ms" localDispatcher=false method="(*session).heartbeat" module=agent session.id=wpoq6lqg644xqag8blez2dsp0 sessionID=wpoq6lqg644xqag8blez2dsp0 testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug msg="heartbeat successful to manager { 127.0.0.1:39285}, next heartbeat period: 5s" localDispatcher=false method="(*session).heartbeat" module=agent session.id=wpoq6lqg644xqag8blez2dsp0 sessionID=wpoq6lqg644xqag8blez2dsp0 testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug msg="(*Agent).run exited" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNetworkManagerChanges
time="2018-03-28T21:19:19Z" level=debug msg="non-dispatcher side closed session: wpoq6lqg644xqag8blez2dsp0"
time="2018-03-28T21:19:19Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:55240->127.0.0.1:52291: use of closed network connection" module=grpc
time="2018-03-28T21:19:19Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:55240->127.0.0.1:52289: use of closed network connection" module=grpc
time="2018-03-28T21:19:19Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:55240->127.0.0.1:52290: use of closed network connection" module=grpc
time="2018-03-28T21:19:19Z" level=warning msg="no certificate expiration specified, using default" cluster.id=l0f96i8ceww8ceb456ozf86gq method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=debug msg="Root CA set successfully" cluster.id=l0f96i8ceww8ceb456ozf86gq method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=debug msg="(*Agent).run" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:36676}" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=info msg="waiting 0s before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=debug localDispatcher=false method="(*session).watch" module=agent session.id=nl266q8lqvdw5pnjf7joiqnrf testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=debug localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=nl266q8lqvdw5pnjf7joiqnrf testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=debug msg="(*session).heartbeat" localDispatcher=false module=agent session.id=nl266q8lqvdw5pnjf7joiqnrf testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=debug msg="(*session).listen" localDispatcher=false module=agent session.id=nl266q8lqvdw5pnjf7joiqnrf testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=debug msg="agent: registered" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=debug msg="sending heartbeat to manager { 127.0.0.1:36676} with timeout 500ms" localDispatcher=false method="(*session).heartbeat" module=agent session.id=nl266q8lqvdw5pnjf7joiqnrf sessionID=nl266q8lqvdw5pnjf7joiqnrf testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=warning msg="manager does not support log subscriptions" localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=nl266q8lqvdw5pnjf7joiqnrf testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=debug msg="heartbeat successful to manager { 127.0.0.1:36676}, next heartbeat period: 5s" localDispatcher=false method="(*session).heartbeat" module=agent session.id=nl266q8lqvdw5pnjf7joiqnrf sessionID=nl266q8lqvdw5pnjf7joiqnrf testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=debug msg="(*Agent).run exited" localDispatcher=false module=agent testHasExternalCA=false testname=TestHandleSessionMessageNodeChanges
time="2018-03-28T21:19:19Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:36676->127.0.0.1:58878: use of closed network connection" module=grpc
time="2018-03-28T21:19:19Z" level=debug msg="non-dispatcher side closed session: nl266q8lqvdw5pnjf7joiqnrf"
time="2018-03-28T21:19:19Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:33175->127.0.0.1:45364: use of closed network connection" module=grpc
time="2018-03-28T21:19:19Z" level=warning msg="no certificate expiration specified, using default" cluster.id=cpv0a6iz0sl7o64bzihyjy8rg method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="Root CA set successfully" cluster.id=cpv0a6iz0sl7o64bzihyjy8rg method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="(*Agent).run" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:51376}" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=info msg="waiting 0s before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="(*session).heartbeat" localDispatcher=false module=agent session.id=y7d3a2zucjtnnmzdgyw5yykkw testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="agent: registered" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="(*session).listen" localDispatcher=false module=agent session.id=y7d3a2zucjtnnmzdgyw5yykkw testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=y7d3a2zucjtnnmzdgyw5yykkw testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug localDispatcher=false method="(*session).watch" module=agent session.id=y7d3a2zucjtnnmzdgyw5yykkw testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="sending heartbeat to manager { 127.0.0.1:51376} with timeout 500ms" localDispatcher=false method="(*session).heartbeat" module=agent session.id=y7d3a2zucjtnnmzdgyw5yykkw sessionID=y7d3a2zucjtnnmzdgyw5yykkw testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=warning msg="manager does not support log subscriptions" localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=y7d3a2zucjtnnmzdgyw5yykkw testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="heartbeat successful to manager { 127.0.0.1:51376}, next heartbeat period: 5s" localDispatcher=false method="(*session).heartbeat" module=agent session.id=y7d3a2zucjtnnmzdgyw5yykkw sessionID=y7d3a2zucjtnnmzdgyw5yykkw testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=info msg="agent: found node update" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="agent: rebuild session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:51376}" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=info msg="waiting 0s before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="non-dispatcher side closed session: y7d3a2zucjtnnmzdgyw5yykkw"
time="2018-03-28T21:19:19Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="(*session).listen" localDispatcher=false module=agent session.id=ouyii6i9offb7p8hx4ny506kh testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="agent: registered" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="(*session).heartbeat" localDispatcher=false module=agent session.id=ouyii6i9offb7p8hx4ny506kh testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug localDispatcher=false method="(*session).watch" module=agent session.id=ouyii6i9offb7p8hx4ny506kh testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=ouyii6i9offb7p8hx4ny506kh testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="sending heartbeat to manager { 127.0.0.1:51376} with timeout 500ms" localDispatcher=false method="(*session).heartbeat" module=agent session.id=ouyii6i9offb7p8hx4ny506kh sessionID=ouyii6i9offb7p8hx4ny506kh testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=warning msg="manager does not support log subscriptions" localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=ouyii6i9offb7p8hx4ny506kh testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:19Z" level=debug msg="heartbeat successful to manager { 127.0.0.1:51376}, next heartbeat period: 5s" localDispatcher=false method="(*session).heartbeat" module=agent session.id=ouyii6i9offb7p8hx4ny506kh sessionID=ouyii6i9offb7p8hx4ny506kh testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=info msg="agent: found node update" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=debug msg="agent: rebuild session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:51376}" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=info msg="waiting 0s before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=debug msg="non-dispatcher side closed session: ouyii6i9offb7p8hx4ny506kh"
time="2018-03-28T21:19:20Z" level=debug localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=0m98saytfzb6ngt1uzpgzrzaa testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=debug msg="(*session).listen" localDispatcher=false module=agent session.id=0m98saytfzb6ngt1uzpgzrzaa testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=debug msg="(*session).heartbeat" localDispatcher=false module=agent session.id=0m98saytfzb6ngt1uzpgzrzaa testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=debug msg="agent: registered" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=debug localDispatcher=false method="(*session).watch" module=agent session.id=0m98saytfzb6ngt1uzpgzrzaa testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=debug msg="sending heartbeat to manager { 127.0.0.1:51376} with timeout 500ms" localDispatcher=false method="(*session).heartbeat" module=agent session.id=0m98saytfzb6ngt1uzpgzrzaa sessionID=0m98saytfzb6ngt1uzpgzrzaa testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=warning msg="manager does not support log subscriptions" localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=0m98saytfzb6ngt1uzpgzrzaa testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:20Z" level=debug msg="heartbeat successful to manager { 127.0.0.1:51376}, next heartbeat period: 5s" localDispatcher=false method="(*session).heartbeat" module=agent session.id=0m98saytfzb6ngt1uzpgzrzaa sessionID=0m98saytfzb6ngt1uzpgzrzaa testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:21Z" level=debug msg="(*Agent).run exited" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionRestartedOnNodeDescriptionChange
time="2018-03-28T21:19:21Z" level=debug msg="non-dispatcher side closed session: 0m98saytfzb6ngt1uzpgzrzaa"
time="2018-03-28T21:19:21Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:59828->127.0.0.1:58405: use of closed network connection" module=grpc
time="2018-03-28T21:19:21Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:59828->127.0.0.1:58406: use of closed network connection" module=grpc
time="2018-03-28T21:19:21Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:59828->127.0.0.1:58403: use of closed network connection" module=grpc
time="2018-03-28T21:19:21Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:59828->127.0.0.1:58404: use of closed network connection" module=grpc
time="2018-03-28T21:19:21Z" level=warning msg="no certificate expiration specified, using default" cluster.id=whu4rsus6h4la35815jlbgqe8 method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="Root CA set successfully" cluster.id=whu4rsus6h4la35815jlbgqe8 method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="(*Agent).run" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:59128}" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=info msg="waiting 0s before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug localDispatcher=false method="(*session).watch" module=agent session.id=ymscug1ujbid863p0jep90791 testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="(*session).heartbeat" localDispatcher=false module=agent session.id=ymscug1ujbid863p0jep90791 testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="(*session).listen" localDispatcher=false module=agent session.id=ymscug1ujbid863p0jep90791 testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=ymscug1ujbid863p0jep90791 testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="agent: registered" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="sending heartbeat to manager { 127.0.0.1:59128} with timeout 500ms" localDispatcher=false method="(*session).heartbeat" module=agent session.id=ymscug1ujbid863p0jep90791 sessionID=ymscug1ujbid863p0jep90791 testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:59128->127.0.0.1:54523: use of closed network connection" module=grpc
time="2018-03-28T21:19:21Z" level=debug msg="non-dispatcher side closed session: ymscug1ujbid863p0jep90791"
time="2018-03-28T21:19:21Z" level=info msg="transport: http2Client.notifyError got notified that the client transport was broken EOF." module=grpc
time="2018-03-28T21:19:21Z" level=info msg="grpc: Server.handleStream failed to write status: stream error: code = Canceled desc = \"context canceled\"" module=grpc
time="2018-03-28T21:19:21Z" level=error msg="agent: session failed" backoff=100ms error="rpc error: code = Internal desc = transport is closing" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=error msg="heartbeat to manager { 127.0.0.1:59128} failed" error="rpc error: code = Internal desc = transport is closing" localDispatcher=false method="(*session).heartbeat" module=agent session.id=ymscug1ujbid863p0jep90791 sessionID=ymscug1ujbid863p0jep90791 testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="agent: rebuild session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=info msg="grpc: addrConn.resetTransport failed to create client transport: connection error: desc = \"transport: dial tcp 127.0.0.1:59128: getsockopt: connection refused\"; Reconnecting to {127.0.0.1:59128 <nil>}" module=grpc
time="2018-03-28T21:19:21Z" level=info msg="grpc: addrConn.transportMonitor exits due to: grpc: the connection is closing" module=grpc
time="2018-03-28T21:19:21Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:41931}" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=info msg="waiting 82.153551ms before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="non-dispatcher side closed session: 56bvajesib14kncn9be32xsys"
time="2018-03-28T21:19:21Z" level=error msg="agent: session failed" backoff=300ms error="rpc error: code = Unknown desc = terminate immediately" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="agent: rebuild session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:41931}" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=info msg="waiting 66.145821ms before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=error msg="agent: session failed" backoff=700ms error="session initiation timed out" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="agent: rebuild session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:41931}" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=info msg="waiting 35.010051ms before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="non-dispatcher side closed session: mo4uua8nl0np9ig86tkvhfcoi"
time="2018-03-28T21:19:21Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="(*session).heartbeat" localDispatcher=false module=agent session.id=alhhswmnj96xo1u7yeorpj3zr testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="agent: registered" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=alhhswmnj96xo1u7yeorpj3zr testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="(*session).listen" localDispatcher=false module=agent session.id=alhhswmnj96xo1u7yeorpj3zr testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug localDispatcher=false method="(*session).watch" module=agent session.id=alhhswmnj96xo1u7yeorpj3zr testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="sending heartbeat to manager { 127.0.0.1:41931} with timeout 500ms" localDispatcher=false method="(*session).heartbeat" module=agent session.id=alhhswmnj96xo1u7yeorpj3zr sessionID=alhhswmnj96xo1u7yeorpj3zr testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=warning msg="manager does not support log subscriptions" localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=alhhswmnj96xo1u7yeorpj3zr testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="heartbeat successful to manager { 127.0.0.1:41931}, next heartbeat period: 5s" localDispatcher=false method="(*session).heartbeat" module=agent session.id=alhhswmnj96xo1u7yeorpj3zr sessionID=alhhswmnj96xo1u7yeorpj3zr testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=debug msg="non-dispatcher side closed session: alhhswmnj96xo1u7yeorpj3zr"
time="2018-03-28T21:19:21Z" level=info msg="transport: http2Client.notifyError got notified that the client transport was broken EOF." module=grpc
time="2018-03-28T21:19:21Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:41931->127.0.0.1:48042: use of closed network connection" module=grpc
time="2018-03-28T21:19:21Z" level=debug msg="(*Agent).run exited" localDispatcher=false module=agent testHasExternalCA=false testname=TestSessionReconnectsIfDispatcherErrors
time="2018-03-28T21:19:21Z" level=info msg="grpc: addrConn.resetTransport failed to create client transport: connection error: desc = \"transport: dial tcp 127.0.0.1:41931: getsockopt: connection refused\"; Reconnecting to {127.0.0.1:41931 <nil>}" module=grpc
time="2018-03-28T21:19:21Z" level=info msg="grpc: addrConn.transportMonitor exits due to: grpc: the connection is closing" module=grpc
time="2018-03-28T21:19:21Z" level=warning msg="no certificate expiration specified, using default" cluster.id=r7v7xg5a6zbdfc8b1lzojbk00 method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=debug msg="Root CA set successfully" cluster.id=r7v7xg5a6zbdfc8b1lzojbk00 method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=debug msg="(*Agent).run" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:59991}" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=info msg="waiting 0s before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=debug msg="non-dispatcher side closed session: t9jucvypddiueku8bpmsaaqgy"
time="2018-03-28T21:19:21Z" level=error msg="agent: session failed" backoff=100ms error="rpc error: code = Unknown desc = I always error" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=debug msg="agent: rebuild session" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:59991}" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=info msg="waiting 87.113937ms before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=debug msg="non-dispatcher side closed session: cvk8ubq8zea7fisc1392h48lc"
time="2018-03-28T21:19:21Z" level=error msg="agent: session failed" backoff=300ms error="rpc error: code = Unknown desc = I always error" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=debug msg="agent: rebuild session" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:59991}" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=info msg="waiting 49.16732ms before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=debug msg="non-dispatcher side closed session: qwrbfoo4e9hqom9fhcad4xuim"
time="2018-03-28T21:19:21Z" level=error msg="agent: session failed" backoff=700ms error="rpc error: code = Unknown desc = I always error" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=error msg="agent: exiting" error="rpc error: code = Unknown desc = I always error" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:21Z" level=debug msg="(*Agent).run exited" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentExitsBasedOnSessionTracker
time="2018-03-28T21:19:22Z" level=warning msg="no certificate expiration specified, using default" cluster.id=r65vgisux9ccl49q9vy8jjge0 method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=debug msg="Root CA set successfully" cluster.id=r65vgisux9ccl49q9vy8jjge0 method="(*Server).UpdateRootCA" module=ca testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=debug msg="(*Agent).run" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=info msg="manager selected by agent for new session: { 127.0.0.1:55423}" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=info msg="waiting 0s before registering session" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=debug msg="(*session).start" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=debug localDispatcher=false method="(*session).watch" module=agent session.id=vnnvv93uanni3kwobetofju26 testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=debug localDispatcher=false method="(*session).logSubscriptions" module=agent session.id=vnnvv93uanni3kwobetofju26 testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=debug msg="(*session).listen" localDispatcher=false module=agent session.id=vnnvv93uanni3kwobetofju26 testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=debug msg="(*session).heartbeat" localDispatcher=false module=agent session.id=vnnvv93uanni3kwobetofju26 testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=debug msg="agent: registered" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=debug msg="sending heartbeat to manager { 127.0.0.1:55423} with timeout 500ms" localDispatcher=false method="(*session).heartbeat" module=agent session.id=vnnvv93uanni3kwobetofju26 sessionID=vnnvv93uanni3kwobetofju26 testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=debug msg="(*Agent).run exited" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=error msg="heartbeat to manager { 127.0.0.1:55423} failed" error="rpc error: code = Internal desc = transport is closing" localDispatcher=false method="(*session).heartbeat" module=agent session.id=vnnvv93uanni3kwobetofju26 sessionID=vnnvv93uanni3kwobetofju26 testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=debug msg="non-dispatcher side closed session: vnnvv93uanni3kwobetofju26"
==================
WARNING: DATA RACE
Read at 0x00c4202f27f8 by goroutine 144:
  reflect.typedmemmove()
      /usr/local/go/src/runtime/mbarrier.go:259 +0x0
  reflect.packEface()
      /usr/local/go/src/reflect/value.go:112 +0x10b
  reflect.valueInterface()
      /usr/local/go/src/reflect/value.go:961 +0x170
  reflect.Value.Interface()
      /usr/local/go/src/reflect/value.go:931 +0x51
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:692 +0x3994
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:846 +0x26da
  fmt.(*pp).printArg()
      /usr/local/go/src/fmt/print.go:682 +0x19e
  fmt.(*pp).doPrintf()
      /usr/local/go/src/fmt/print.go:996 +0x319
  fmt.Sprintf()
      /usr/local/go/src/fmt/print.go:196 +0x73
  github.com/docker/swarmkit/vendor/github.com/sirupsen/logrus.(*Entry).Errorf()
      /home/ubuntu/.go_workspace/src/github.com/docker/swarmkit/vendor/github.com/sirupsen/logrus/entry.go:205 +0xad
  github.com/docker/swarmkit/agent.(*worker).reportAllStatuses()
      github.com/docker/swarmkit/agent/_test/_obj_test/worker.go:495 +0x259
  github.com/docker/swarmkit/agent.(*worker).Report()
      github.com/docker/swarmkit/agent/_test/_obj_test/worker.go:482 +0xbb

Previous write at 0x00c4202f27f8 by goroutine 11:
  sync/atomic.AddInt32()
      /usr/local/go/src/runtime/race_amd64.s:269 +0xb
  sync.(*Mutex).Unlock()
      /usr/local/go/src/sync/mutex.go:182 +0x54
  github.com/docker/swarmkit/agent.(*statusReporter).run()
      github.com/docker/swarmkit/agent/_test/_obj_test/reporter.go:115 +0x680

Goroutine 144 (running) created at:
  github.com/docker/swarmkit/agent.(*Agent).run()
      github.com/docker/swarmkit/agent/_test/_obj_test/agent.go:370 +0x1acf

Goroutine 11 (finished) created at:
  github.com/docker/swarmkit/agent.newStatusReporter()
      github.com/docker/swarmkit/agent/_test/_obj_test/reporter.go:42 +0x1a7
  github.com/docker/swarmkit/agent.(*Agent).run()
      github.com/docker/swarmkit/agent/_test/_obj_test/agent.go:236 +0x644
==================
time="2018-03-28T21:19:22Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:46098->127.0.0.1:58363: use of closed network connection" module=grpc
time="2018-03-28T21:19:22Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:46098->127.0.0.1:58366: use of closed network connection" module=grpc
time="2018-03-28T21:19:22Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:46098->127.0.0.1:58364: use of closed network connection" module=grpc
time="2018-03-28T21:19:22Z" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:46098->127.0.0.1:58365: use of closed network connection" module=grpc
--- FAIL: TestAgentRegistersSessionsWithSessionTracker (0.06s)
	testing.go:699: race detected during execution of test
time="2018-03-28T21:19:22Z" level=error msg="failed reporting initial statuses to registered listener &{0xc4204c20c0 map[] {0 0} {{} 0xc4202f27f8 {1 1 0 <nil> <nil>} 842353551408} true}" error="database not open" localDispatcher=false module=agent testHasExternalCA=false testname=TestAgentRegistersSessionsWithSessionTracker
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=error msg="status reporter failed to report status to agent" error="status send failed"
time="2018-03-28T21:19:22Z" level=debug msg="state changed" module=taskmanager state.desired=ACCEPTED state.transition="NEW->ACCEPTED"
time="2018-03-28T21:19:22Z" level=debug msg="state changed" module=taskmanager state.desired=READY state.transition="ACCEPTED->PREPARING"
time="2018-03-28T21:19:22Z" level=debug msg="state changed" module=taskmanager state.desired=READY state.transition="PREPARING->READY"
time="2018-03-28T21:19:23Z" level=debug msg="state changed" module=taskmanager state.desired=RUNNING state.transition="READY->STARTING"
time="2018-03-28T21:19:23Z" level=debug msg="state changed" module=taskmanager state.desired=RUNNING state.transition="STARTING->RUNNING"
time="2018-03-28T21:19:23Z" level=debug msg="state changed" module=taskmanager state.desired=RUNNING state.transition="RUNNING->COMPLETE"
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Assign" len(assignments)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Assign" len(assignments)=6
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=1 len(updatedSecrets)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=1 len(updatedConfigs)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=1 len(updatedTasks)=1
time="2018-03-28T21:19:23Z" level=debug msg=assigned task.desiredstate=NEW task.id=task-1
time="2018-03-28T21:19:23Z" level=debug msg="state changed" service.id= state.desired=NEW state.transition="NEW->ACCEPTED" task.id=task-1
time="2018-03-28T21:19:23Z" level=info msg="status update received" service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:ACCEPTED,Message:accepted,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-1
time="2018-03-28T21:19:23Z" level=info msg="status update received" module=taskmanager service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:NEW,Message:,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Assign" len(assignments)=3
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=1
time="2018-03-28T21:19:23Z" level=debug msg=assigned task.desiredstate=NEW task.id=task-2
time="2018-03-28T21:19:23Z" level=debug msg="state changed" service.id= state.desired=NEW state.transition="NEW->ACCEPTED" task.id=task-2
time="2018-03-28T21:19:23Z" level=info msg="status update received" service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:ACCEPTED,Message:accepted,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-2
time="2018-03-28T21:19:23Z" level=info msg="status update received" module=taskmanager service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:NEW,Message:,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-2
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Assign" len(assignments)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Assign" len(assignments)=4
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=2
time="2018-03-28T21:19:23Z" level=debug msg=assigned task.desiredstate=NEW task.id=task-1
time="2018-03-28T21:19:23Z" level=debug msg="state changed" service.id= state.desired=NEW state.transition="NEW->ACCEPTED" task.id=task-1
time="2018-03-28T21:19:23Z" level=info msg="status update received" service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:ACCEPTED,Message:accepted,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-1
time="2018-03-28T21:19:23Z" level=debug msg=assigned task.desiredstate=NEW task.id=task-2
time="2018-03-28T21:19:23Z" level=debug msg="state changed" service.id= state.desired=NEW state.transition="NEW->ACCEPTED" task.id=task-2
time="2018-03-28T21:19:23Z" level=info msg="status update received" service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:ACCEPTED,Message:accepted,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-2
time="2018-03-28T21:19:23Z" level=info msg="status update received" module=taskmanager service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:NEW,Message:,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-1
time="2018-03-28T21:19:23Z" level=info msg="status update received" module=taskmanager service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:NEW,Message:,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-2
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Assign" len(assignments)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Assign" len(assignments)=3
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=1
time="2018-03-28T21:19:23Z" level=debug msg=assigned task.desiredstate=NEW task.id=task-1
time="2018-03-28T21:19:23Z" level=debug msg="state changed" service.id= state.desired=NEW state.transition="NEW->ACCEPTED" task.id=task-1
time="2018-03-28T21:19:23Z" level=info msg="status update received" service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:ACCEPTED,Message:accepted,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-1
time="2018-03-28T21:19:23Z" level=info msg="status update received" module=taskmanager service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:NEW,Message:,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Update" len(assignments)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Update" len(assignments)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=1
time="2018-03-28T21:19:23Z" level=debug msg=assigned task.desiredstate=NEW task.id=task-1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Update" len(assignments)=3
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=1
time="2018-03-28T21:19:23Z" level=debug msg=assigned task.desiredstate=NEW task.id=task-2
time="2018-03-28T21:19:23Z" level=debug msg="state changed" service.id= state.desired=NEW state.transition="NEW->ACCEPTED" task.id=task-2
time="2018-03-28T21:19:23Z" level=info msg="status update received" service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:ACCEPTED,Message:accepted,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-2
time="2018-03-28T21:19:23Z" level=info msg="status update received" module=taskmanager service.id= status="&TaskStatus{Timestamp:(timestamp: nil google_protobuf.Timestamp),State:NEW,Message:,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil google_protobuf.Timestamp),}" task.id=task-2
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Update" len(assignments)=5
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=1 len(updatedSecrets)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=1 len(updatedConfigs)=1
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=1 len(updatedTasks)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).Update" len(assignments)=6
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=2 len(updatedSecrets)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=2 len(updatedConfigs)=0
time="2018-03-28T21:19:23Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=2 len(updatedTasks)=0
FAIL
coverage: 63.4% of statements
FAIL	github.com/docker/swarmkit/agent	4.311s
make: *** [coverage] Error 1

cd "$WORKDIR" && TMPDIR=/tmpfs make ci returned exit code 2

[stevvooe]

@cyli Nice catch!

It looks like the problem is https://github.com/docker/swarmkit/blob/master/agent/worker.go#L438. using reporter there is not going to be threadsafe. To tell you the truth, since we don't implement Stringer on the reporter, the value isn't that useful.

If we capture a string at that point, I think the problem will go away.

[cyli]

@stevvooe Thanks for identifying that! Will put a string in instead.