8000
Skip to content

Add/use container.Exec() to integration - #36326

Merged
thaJeztah merged 3 commits into
moby:masterfrom
kolyshkin:integration-exec
Feb 20, 2018
Merged

Add/use container.Exec() to integration#36326
thaJeztah merged 3 commits into
moby:masterfrom
kolyshkin:integration-exec

Conversation

@kolyshkin
@kolyshkin kolyshkin commented Feb 15, 2018
Copy link
Copy Markdown
Contributor

Some test cases might need an ability to execute a command inside a container (in order to analyse its output and/or exit code). It is a bit complicated operation to do so using engine API. The function provided aims to hide this complexity, making exec almost as simple as 'docker exec'.

Currently, there are two integration test cases that re-implement this functionality (with some mistakes and leaks along the way) -- let's convert those to use the newly added container.Exec().

Comment thread integration/internal/exec/exec.go Outdated
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There are some lint errors because of naming.

I think we can put this into integration/internal/container so that calling it Exec is fine.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure, will do

Comment thread integration/internal/exec/exec.go Outdated
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This doesn't check if the container is running, just that it exists. Is this necessary or will execCreate handle this check for us?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wrote it in November so frankly I don't remember :) but it looks like this is indeed a check that container exists, and I think it can be dropped.

@kolyshkin
Copy link
Copy Markdown
Contributor Author

@dnephin please see updated commits

@kolyshkin kolyshkin changed the title [WIP] Add/use integration/internal/exec package [WIP] Add/use container.Exec() to integration Feb 15, 2018
@thaJeztah
Copy link
Copy Markdown
Member

Linting error;

integration/internal/container/exec.go:24:1:warning: comment on exported method ExecResult.Stderr should be of the form "Stderr ..." (golint)
23:52:42 Build step 'Execute shell' marked build as failure

Comment thread integration/internal/container/exec.go Outdated
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually; perhaps this type doesn’t have to be exported

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I tried it and it the (way too strict IMO) linter gives:

15:55:50 integration/internal/container/exec.go:37:80:warning: exported func Exec returns unexported type container.execResult, which can be annoying to use (golint)

so I had to revert it back to they way it was

@kolyshkin
kolyshkin commented Feb 16, 2018
Copy link
Copy Markdown
Contributor Author

Note that in test cases I deliberately skip the check for res.ExitCode() == 0, as in case of non-zero exit code we'll definitely have something in res.Stderr() (which is checked).

Scratch that; it's easier to do the check than to think/explain whether it should be done or not.

@dnephin
dnephin commented Feb 16, 2018
Copy link
Copy Markdown
Member

integration/internal/container/exec.go:42:80:warning: exported func Exec returns unexported type container.execResult, which can be annoying to use (golint)

I think it does need to be exported

Comment thread integration/internal/container/exec.go Outdated
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm worried that this is really high level and will end up with other similar implementations to get at the lower level details.
I'm wondering if this can take an ExecConfig and return a hijack response (or some suitable wrapper)?

I think the main issue is that it wasn't clear that ExecAttach and ExecStart are really just calling the same endpoint and this is very different from the container API.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The whole point was make it easy to use for the common case. A lower-level functions can definitely be added, too, in case there will be a need for those (so far I haven't seen it, but it might change).

I think the main issue is that it wasn't clear that ExecAttach and ExecStart are really just calling the same endpoint

There were other issues, too, the one I remember is not closing something that should be closing.

When a test case is being developed, one should concentrate on the test case itself, not the intricacies of how to correctly execute a simple command inside a container and get the result.

@kolyshkin
Copy link
Copy Markdown
Contributor Author

integration/internal/container/exec.go:42:80 exported func Exec returns unexported type >?
container.execResult, which can be annoying to use (golint)

I think it does need to be exported

Apparently. Patch set updated.

Weird, the semantics I used is a classical example of how to implement read-only access to a class member in C++.

@thaJeztah
Copy link
Copy Markdown
Member

Weird, the semantics I used is a classical example of how to implement read-only access to a class member in C++.

Hm, yes, I recall I ran into the same issue at some point. Perhaps the linter is too strict there, idk.

Apparently. Patch set updated.

Did you forgot to push? Looks like Janky is still failing on that issue

Some test cases might need an ability to execute a command inside a
container (in order to analyse its output and/or exit code). It is a bit
complicated operation to do so using engine API. The function provided
aims to hide this complexity, making exec almost as simple as 'docker
exec'.

NOTE that the exec is synchronous, and command's stdin is closed.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
An implementation of exec in TestUpdateCPUQUota had a few issues,
including resource leaking and calling both ContainerExecAttach and
ContainerExecRun. The last one makes the test flaky:

	update_linux_test.go:136: expected cgroup value 20000, got: Error: Exec
	command f923baf709525f6b38f6511126addc5d9bb88fb477eeca1c22440551090fa2bb
	is already running

Fix by using the integration/internal/exec package.

While at it, use require/assert to further improve code readability.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
1. Use integration/internal/exec, removing the getContainerSysFSValue().

2. Avoid repeating magic numbers, use a variable for those.

3. Fix order of arguments to assert.Equal (first "expected", then "actual").

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
@kolyshkin
Copy link
Copy Markdown
Contributor Author

powerpc CI stuck:

13:00:31 PASS: docker_cli_swarm_test.go:1989: DockerSwarmSuite.TestSwarmClusterEventsType	7.195s
14:26:20 Build timed out (after 180 minutes). Marking the build as failed.
14:26:20 Build timed out (after 180 minutes). Marking the build as aborted.

I think I've seen something like this before; looks like the next test case to be executed is TestSwarmClusterRotateUnlockKey

@kolyshkin
kolyshkin commented Feb 20, 2018
Copy link
Copy Markdown
Contributor Author

I could use some help with the above mentioned test case. There are three daemons

daemon port directory
d1 2477 df66446df32b0
d2 2478 dbcb75368785c
d3 2479 d9e20f969765e

The last query received by daemon (d2 in this case) was this:
time="2018-02-19T21:00:47.027852381Z" level=debug msg="Calling POST /v1.30/swarm/unlock"

This query sent here (judging by the logs, i == 10, d == d2):

cmd = d.Command("swarm", "unlock")

and then the whole rig got stuck, with lots of messages in d1 and d2 logs.

Here's the relevant part of d2 log (starting from the aforementioned line):

time="2018-02-19T21:00:47.027852381Z" level=debug msg="Calling POST /v1.30/swarm/unlock"
time="2018-02-19T21:00:47.027932957Z" level=debug msg="form data: {\"UnlockKey\":\"*****\"}"
time="2018-02-19T21:00:47.055194030Z" level=debug msg="loaded node credentials" module=node/tls node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager
time="2018-02-19T21:00:47.055692886Z" level=debug msg="(*Agent).run" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:47.064805289Z" level=info msg="manager selected by agent for new session: {01apyb2gdfsz8k2t32vlqhdx6 127.0.0.1:2477}" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:47.065083143Z" level=info msg="waiting 0s before registering session" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:47.065183343Z" level=debug msg="(*session).start" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:47.089396570Z" level=debug msg="next certificate renewal scheduled for 1401h47m12.910615795s from now" module=node/tls node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager time="2018-04-19 06:48:00.000000908 +0000 UTC m=+5046439.190627964"
time="2018-02-19T21:00:47.100037498Z" level=info msg="Listening for local connections" addr=/tmp/docker-execroot/dbcb75368785c/swarm/control.sock module=node node.id=wyj91bz77bv9fp96iawlrhyis proto=unix
time="2018-02-19T21:00:47.104297434Z" level=info msg="Listening for connections" addr="[::]:2478" module=node node.id=wyj91bz77bv9fp96iawlrhyis proto=tcp
time="2018-02-19T21:00:47.118770160Z" level=info msg="6304186a177a639c became follower at term 2" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:47.118836526Z" level=info msg="newRaft 6304186a177a639c [peers: [3272226729412871,6304186a177a639c,78bef282b4064307], term: 2, commit: 28, applied: 24, lastindex: 28, lastterm: 2]" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:47.118936744Z" level=debug msg="transport: add peer 78bef282b4064307 with address 127.0.0.1:2477"
time="2018-02-19T21:00:47.120490461Z" level=debug msg="transport: add peer 3272226729412871 with address 127.0.0.1:2479"
time="2018-02-19T21:00:50.089840997Z" level=info msg="6304186a177a639c is starting a new election at term 2" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:50.089921368Z" level=info msg="6304186a177a639c became candidate at term 3" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:50.089951901Z" level=info msg="6304186a177a639c received MsgVoteResp from 6304186a177a639c at term 3" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:50.089979041Z" level=info msg="6304186a177a639c [logterm: 2, index: 28] sent MsgVote request to 3272226729412871 at term 3" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:50.090006611Z" level=info msg="6304186a177a639c [logterm: 2, index: 28] sent MsgVote request to 78bef282b4064307 at term 3" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:50.090764120Z" level=error msg="error sending message to peer" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable"
time="2018-02-19T21:00:50.090813281Z" level=debug msg="failed to send message MsgVote" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable" peer_id=3272226729412871
time="2018-02-19T21:00:52.066097649Z" level=error msg="agent: session failed" backoff=100ms error="session initiation timed out" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:52.066217772Z" level=debug msg="agent: rebuild session" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:52.066311945Z" level=info msg="manager selected by agent for new session: { }" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:52.066374911Z" level=info msg="waiting 5.61078ms before registering session" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:52.072063769Z" level=debug msg="(*session).start" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:53.089808332Z" level=info msg="6304186a177a639c is starting a new election at term 3" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:53.089877117Z" level=info msg="6304186a177a639c became candidate at term 4" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:53.089900218Z" level=info msg="6304186a177a639c received MsgVoteResp from 6304186a177a639c at term 4" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:53.089925400Z" level=info msg="6304186a177a639c [logterm: 2, index: 28] sent MsgVote request to 3272226729412871 at term 4" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:53.089954666Z" level=info msg="6304186a177a639c [logterm: 2, index: 28] sent MsgVote request to 78bef282b4064307 at term 4" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:53.090587309Z" level=error msg="error sending message to peer" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable"
time="2018-02-19T21:00:53.090630315Z" level=debug msg="failed to send message MsgVote" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable" peer_id=3272226729412871
time="2018-02-19T21:00:53.092307630Z" level=info msg="6304186a177a639c received MsgVoteResp rejection from 78bef282b4064307 at term 4" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:53.092354597Z" level=info msg="6304186a177a639c [quorum:2] has received 1 MsgVoteResp votes and 1 vote rejections" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:56.089820724Z" level=info msg="6304186a177a639c is starting a new election at term 4" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:56.089875868Z" level=info msg="6304186a177a639c became candidate at term 5" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:56.089900095Z" level=info msg="6304186a177a639c received MsgVoteResp from 6304186a177a639c at term 5" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:56.089930812Z" level=info msg="6304186a177a639c [logterm: 2, index: 28] sent MsgVote request to 3272226729412871 at term 5" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:56.089962810Z" level=info msg="6304186a177a639c [logterm: 2, index: 28] sent MsgVote request to 78bef282b4064307 at term 5" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:56.090561481Z" level=error msg="error sending message to peer" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable"
time="2018-02-19T21:00:56.090610757Z" level=debug msg="failed to send message MsgVote" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable" peer_id=3272226729412871
time="2018-02-19T21:00:56.092349019Z" level=info msg="6304186a177a639c received MsgVoteResp rejection from 78bef282b4064307 at term 5" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:56.092397260Z" level=info msg="6304186a177a639c [quorum:2] has received 1 MsgVoteResp votes and 1 vote rejections" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:57.072239750Z" level=error msg="agent: session failed" backoff=300ms error="session initiation timed out" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:57.072302779Z" level=debug msg="agent: rebuild session" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:57.072342918Z" level=info msg="manager selected by agent for new session: { }" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:57.072401167Z" level=info msg="waiting 2.816349ms before registering session" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
time="2018-02-19T21:00:57.075283359Z" level=debug msg="(*session).start" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis

Here's th A3E2 e relevant part of d1 log (starting from the same time as d2's):

time="2018-02-19T21:00:47.101337659Z" level=debug msg="sending heartbeat to manager { } with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6 session.id=x86o55gw7lvw884cecupg6pc7 sessionID=x86o55gw7lvw884cecupg6pc7
time="2018-02-19T21:00:47.101657111Z" level=debug msg="received heartbeat from worker {[swarm-manager] 4z8z8y5l0kqapqge61ssuivpm 01apyb2gdfsz8k2t32vlqhdx6 <nil> 127.0.0.1:2477}, expect next heartbeat in 5.13105825s" method="(*Dispatcher).Heartbeat"
time="2018-02-19T21:00:47.101849781Z" level=debug msg="heartbeat successful to manager { }, next heartbeat period: 5.13105825s" method="(*session).heartbeat" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6 session.id=x86o55gw7lvw884cecupg6pc7 sessionID=x86o55gw7lvw884cecupg6pc7
time="2018-02-19T21:00:47.134450461Z" level=warning msg="78bef282b4064307 stepped down to follower since quorum is not active" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:47.134506323Z" level=info msg="78bef282b4064307 became follower at term 2" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:47.134530278Z" level=info msg="raft.node: 78bef282b4064307 lost leader 78bef282b4064307 at term 2" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:47.134606133Z" level=error msg="soft state changed, node no longer a leader, resetting and cancelling all waits" raft_id=78bef282b4064307
time="2018-02-19T21:00:47.134850175Z" level=error msg="agent: session failed" backoff=100ms error="rpc error: code = Canceled desc = context canceled" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:47.134930056Z" level=debug msg="agent: rebuild session" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:47.134976193Z" level=info msg="manager selected by agent for new session: { }" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:47.135038665Z" level=info msg="waiting 83.358449ms before registering session" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:47.135045498Z" level=info msg="dispatcher session dropped, marking node 01apyb2gdfsz8k2t32vlqhdx6 down" method="(*Dispatcher).Session" node.id=01apyb2gdfsz8k2t32vlqhdx6 node.session=x86o55gw7lvw884cecupg6pc7
time="2018-02-19T21:00:47.135087439Z" level=error msg="failed to remove node" error="rpc error: code = Aborted desc = dispatcher is stopped" method="(*Dispatcher).Session" node.id=01apyb2gdfsz8k2t32vlqhdx6 node.session=x86o55gw7lvw884cecupg6pc7
time="2018-02-19T21:00:47.135607333Z" level=error msg="failed to receive changes from store watch API" error="rpc error: code = Internal desc = transport is closing"
time="2018-02-19T21:00:47.218468272Z" level=debug msg="(*session).start" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:48.737476322Z" level=debug msg="heartbeat expiration for worker %s, setting worker status to NodeStatus_DOWN wyj91bz77bv9fp96iawlrhyis"
time="2018-02-19T21:00:48.737555748Z" level=error msg="failed deregistering node after heartbeat expiration" error="rpc error: code = Aborted desc = dispatcher is stopped"
time="2018-02-19T21:00:50.091363399Z" level=debug msg="member which sent vote request failed health check" error="failed to check health: rpc error: code = Unavailable desc = grpc: the connection is unavailable" from=6304186a177a639c method="(*Node).ProcessRaftMessage" raft_id=78bef282b4064307
time="2018-02-19T21:00:52.134473705Z" level=info msg="78bef282b4064307 is starting a new election at term 2" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:52.134526808Z" level=info msg="78bef282b4064307 became candidate at term 3" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:52.134663475Z" level=info msg="78bef282b4064307 received MsgVoteResp from 78bef282b4064307 at term 3" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:52.134702412Z" level=info msg="78bef282b4064307 [logterm: 2, index: 31] sent MsgVote request to 6304186a177a639c at term 3" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:52.134747653Z" level=info msg="78bef282b4064307 [logterm: 2, index: 31] sent MsgVote request to 3272226729412871 at term 3" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:52.135498855Z" level=error msg="error sending message to peer" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable"
time="2018-02-19T21:00:52.135543809Z" level=debug msg="failed to send message MsgVote" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable" peer_id=6304186a177a639c
time="2018-02-19T21:00:52.135563849Z" level=error msg="error sending message to peer" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable"
time="2018-02-19T21:00:52.135600247Z" level=debug msg="failed to send message MsgVote" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable" peer_id=3272226729412871
time="2018-02-19T21:00:52.218637120Z" level=error msg="agent: session failed" backoff=300ms error="session initiation timed out" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:52.218691160Z" level=debug msg="agent: rebuild session" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:52.218730225Z" level=info msg="manager selected by agent for new session: { }" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:52.218773756Z" level=info msg="waiting 44.452284ms before registering session" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:52.263303120Z" level=debug msg="(*session).start" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:53.091477761Z" level=info msg="78bef282b4064307 [term: 3] received a MsgVote message with higher term from 6304186a177a639c [term: 4]" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:53.091530836Z" level=info msg="78bef282b4064307 became follower at term 4" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:53.091576747Z" level=info msg="78bef282b4064307 [logterm: 2, index: 31, vote: 0] rejected MsgVote from 6304186a177a639c [logterm: 2, index: 28] at term 4" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:56.058792796Z" level=debug msg="heartbeat expiration for worker %s, setting worker status to NodeStatus_DOWN pkkdatjee6bw0fm0efeqkd5xu"
time="2018-02-19T21:00:56.058898160Z" level=error msg="failed deregistering node after heartbeat expiration" error="rpc error: code = Aborted desc = dispatcher is stopped"
time="2018-02-19T21:00:56.091592707Z" level=info msg="78bef282b4064307 [term: 4] received a MsgVote message with higher term from 6304186a177a639c [term: 5]" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:56.091653953Z" level=info msg="78bef282b4064307 became follower at term 5" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
time="2018-02-19T21:00:56.091692146Z" level=info msg="78bef282b4064307 [logterm: 2, index: 31, vote: 0] rejected MsgVote from 6304186a177a639c [logterm: 2, index: 28] at term 5" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6

Perhaps someone can shed some light on this? I'm as stuck as these two daemons.

@kolyshkin
kolyshkin commented Feb 20, 2018
Copy link
Copy Markdown
Contributor Author

@cyli can you PTAL (not at the PR itself, but at the powerpc failure that I wrote about in a couple of previous comments)

@kolyshkin kolyshkin changed the title [WIP] Add/use container.Exec() to integration Add/use container.Exec() to integration Feb 20, 2018
@kolyshkin
Copy link
Copy Markdown
Contributor Author

Removed [WIP], I think it's ready for the prime time. The powerpc CI failure is defininitely unrelated.


body, err := getContainerSysFSValue(ctx, client, cID, "/sys/fs/cgroup/memory/memory.limit_in_bytes")
res, err := container.Exec(ctx, client, cID,
[]string{"cat", "/sys/fs/cgroup/memory/memory.limit_in_bytes"})
@boaz0 boaz0 Feb 20, 2018
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there a reason why the binary here is cat while in TestUpdateCPUQuota it is explicitly given as /bin/cat?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No particular reason; we expect that /bin entry is present in $PATH, so no need to use an absolute path. I general, I'd prefer relying on $PATH and not giving absolute paths -- it's a bit more portable that way.

assert.Equal(t, strconv.FormatInt(setMemorySwap, 10), strings.TrimSpace(res.Stdout()))
}

func TestUpdateCPUQUota(t *testing.T) {
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the function name should be TestUpdateCPUQuota and not TestUpdateCPUQUota

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, that looks like a typo, but that code wasn't touched in this PR; perhaps you can open a separate PR for that?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch; I'll fix.

@codecov
codecov Bot commented Feb 20, 2018
Copy link
Copy Markdown

Codecov Report

❗ No coverage uploaded for pull request base (master@733ed2d). Click here to learn what that means.
The diff coverage is n/a.

Impacted file tree graph

@@            Coverage Diff            @@
##             master   #36326   +/-   ##
=========================================
  Coverage          ?   34.31%           
=========================================
  Files             ?      611           
  Lines             ?    45491           
  Branches          ?        0           
=========================================
  Hits              ?    15611           
  Misses            ?    27867           
  Partials          ?     2013

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 733ed2d...0f9da07. Read the comment docs.

@vdemeester vdemeester left a comment
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM 🐯

@thaJeztah thaJeztah left a comment
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@thaJeztah
thaJeztah merged commit ee9abc2 into moby:master Feb 20, 2018
@cyli
cyli commented Feb 20, 2018
Copy link
Copy Markdown
Contributor

@kolyshkin Thanks for the logs - will have a look

@kolyshkin
Copy link
Copy Markdown
Contributor Author

@cyli thanks for taking a look! You can get the full logs from https://jenkins.dockerproject.org/job/Docker-PRs-powerpc/8563/, let me know if you need anything.

@cyli
cyli commented Feb 22, 2018
Copy link
Copy Markdown
Contributor

Still not sure what's wrong yet, but notes so far:

I think i == 0, d == d2. Basically:

  1. The test auto-locked the cluster. Relevant logs from d1:

    time="2018-02-19T21:00:35.500484935Z" level=debug msg="Calling POST /v1.30/swarm/update?rotateManagerToken=false&rotateManagerUnlockKey=false&rotateWorkerToken=false&version=10"
    time="2018-02-19T21:00:35.500684140Z" level=debug msg="form data: {\"CAConfig\":{\"NodeCertExpiry\":7776000000000000},\"Dispatcher\":{\"HeartbeatPeriod\":5000000000},\"EncryptionConfig\":{\"AutoLockManagers\":true},\"Labels\":{},\"Name\":\"default\",\"Orchestration\":{\"TaskHistoryRetentionLimit\":5},\"Raft\":{\"ElectionTick\":3,\"HeartbeatTick\":1,\"KeepOldSnapshots\":0,\"LogEntriesForSlowFollowers\":500,\"SnapshotInterval\":10000},\"TaskDefaults\":{}}"
    time="2018-02-19T21:00:35.509972684Z" level=debug msg="Calling GET /v1.30/swarm/unlockkey"
    time="2018-02-19T21:00:35.578913112Z" level=debug msg="Calling GET /_ping"
    time="2018-02-19T21:00:35.580007328Z" level=debug msg="Calling GET /_ping"
    time="2018-02-19T21:00:35.580689893Z" level=debug msg="Calling GET /v1.30/swarm/unlockkey"
    time="2018-02-19T21:00:35.607258393Z" level=debug msg="successfully rotated KEK" module=node node.id=01apyb2gdfsz8k2t32vlqhdx6 node.role=swarm-manager
    time="2018-02-19T21:00:35.608435170Z" level=debug msg="beginning raft DEK rotation - last indices written with the old key are (snapshot: 0, WAL: 25) - waiting for snapshot of index 25 to be written before rotation can be completed" raft_id=78bef282b4064307
    time="2018-02-19T21:00:35.608734916Z" level=debug msg="a snapshot at index 25 is needed in order to complete raft DEK rotation - a snapshot with index >= 25 can now be triggered" raft_id=78bef282b4064307
    time="2018-02-19T21:00:35.609616244Z" level=debug msg="node certificate updated" cert.cn=wyj91bz77bv9fp96iawlrhyis cert.role=MANAGER method=issueRenewCertificate
    time="2018-02-19T21:00:35.614476218Z" level=debug msg="a snapshot with index 25 is available, which completes the DEK rotation requiring a snapshot of at least index 25 - throwing away DEK and older snapshots encrypted with the old key" raft_id=78bef282b4064307
    time="2018-02-19T21:00:35.615457813Z" level=debug msg="started watching for certificate updates" method=NodeCertificateStatus node.id=wyj91bz77bv9fp96iawlrhyis status="{RENEW }"
    time="2018-02-19T21:00:35.618679853Z" level=debug msg="node certificate updated" cert.cn=pkkdatjee6bw0fm0efeqkd5xu cert.role=MANAGER method=issueRenewCertificate
    
  2. Then test rotated the swarm unlock key once on d1. Relevant logs from d1:

    time="2018-02-19T21:00:35.500484935Z" level=debug msg="Calling POST /v1.30/swarm/update?rotateManagerToken=false&rotateManagerUnlockKey=false&rotateWorkerToken=false&version=10"`
    

    Relevant logs from d2 showing that it processed that first lock (where it introduces a KEK as opposed to when it was just unencrypted) as well as when it picked up the rotation:

    time="2018-02-19T21:00:35.555632247Z" level=debug msg="successfully rotated KEK" module=node node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager
    time="2018-02-19T21:00:35.560402019Z" level=debug msg="beginning raft DEK rotation - last indices written with the old key are (snapshot: 0, WAL: 24) - waiting for snapshot of index 24 to be written before rotation can be completed" raft_id=6304186a177a639c
    time="2018-02-19T21:00:35.560455293Z" level=debug msg="a snapshot at index 24 is needed in order to complete raft DEK rotation - a snapshot with index >= 24 can now be triggered" raft_id=6304186a177a639c
    time="2018-02-19T21:00:35.575346816Z" level=debug msg="a snapshot with index 24 is available, which completes the DEK rotation requiring a snapshot of at least index 24 - throwing away DEK and older snapshots encrypted with the old key" raft_id=6304186a177a639c
    time="2018-02-19T21:00:35.647357899Z" level=info msg="Processing signal 'interrupt'"
    time="2018-02-19T21:00:35.649982334Z" level=debug msg="(*worker).Assign" len(assignments)=0 module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:35.650027639Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:35.650065930Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:35.650102051Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=0 module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:35.650920708Z" level=info msg="Stopping manager" module=node node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:35.651025495Z" level=info msg="shutting down certificate renewal routine" module=node/tls node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager
    time="2018-02-19T21:00:35.651124594Z" level=debug msg="(*Agent).run exited" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:35.658537458Z" level=error msg="failed to renew the certificate" error="context canceled" module=tls node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager
    time="2018-02-19T21:00:35.658576466Z" level=error msg="failed to download new TLS certificate after locking the cluster" error="context canceled" module=node node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager
    time="2018-02-19T21:00:35.739452202Z" level=debug msg="successfully rotated KEK" module=node node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager
    time="2018-02-19T21:00:35.739820389Z" level=debug msg="stop transport"
    time="2018-02-19T21:00:35.740122795Z" l
    48C8
    evel=info msg="Manager shut down" module=node node.id=wyj91bz77bv9fp96iawlrhyis
    

    Relevant logs from d3 showing the same:

    time="2018-02-19T21:00:35.558570948Z" level=debug msg="successfully rotated KEK" module=node node.id=pkkdatjee6bw0fm0efeqkd5xu node.role=swarm-manager
    time="2018-02-19T21:00:35.559919461Z" level=debug msg="beginning raft DEK rotation - last indices written with the old key are (snapshot: 0, WAL: 24) - waiting for snapshot of index 24 to be written before rotation can be completed" raft_id=3272226729412871
    time="2018-02-19T21:00:35.559978481Z" level=debug msg="a snapshot at index 24 is needed in order to complete raft DEK rotation - a snapshot with index >= 24 can now be triggered" raft_id=3272226729412871
    time="2018-02-19T21:00:35.562563579Z" level=debug msg="a snapshot with index 24 is available, which completes the DEK rotation requiring a snapshot of at least index 24 - throwing away DEK and older snapshots encrypted with the old key" raft_id=3272226729412871
    time="2018-02-19T21:00:35.727609713Z" level=debug msg="successfully rotated KEK" module=node node.id=pkkdatjee6bw0fm0efeqkd5xu node.role=swarm-manager
    time="2018-02-19T21:00:40.517065966Z" level=debug msg="sending heartbeat to manager { 0.0.0.0:2477} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=pkkdatjee6bw0fm0efeqkd5xu session.id=uc9gg7o4icm2t4i2qo3qa7zbn sessionID=uc9gg7o4icm2t4i2qo3qa7zbn
    time="2018-02-19T21:00:40.517718538Z" level=debug msg="heartbeat successful to manager { 0.0.0.0:2477}, next heartbeat period: 5.18041326s" method="(*session).heartbeat" module=node/agent node.id=pkkdatjee6bw0fm0efeqkd5xu session.id=uc9gg7o4icm2t4i2qo3qa7zbn sessionID=uc9gg7o4icm2t4i2qo3qa7zbn
    
  3. Then the test restarted d2 and d3. It tried to unlock d2 with the old key - that failed, as expected, and it then tried the new key, and it succeeded. The restart happened as d2 was finishing rotating the key, but the rotation succeeded since it correctly unlocked d2 with the new key, not the old key. These are the relevant logs from d2:

    ime="2018-02-19T21:00:35.650920708Z" level=info msg="Stopping manager" module=node node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:35.651025495Z" level=info msg="shutting down certificate renewal routine" module=node/tls node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager
    time="2018-02-19T21:00:35.651124594Z" level=debug msg="(*Agent).run exited" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:35.658537458Z" level=error msg="failed to renew the certificate" error="context canceled" module=tls node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager
    time="2018-02-19T21:00:35.658576466Z" level=error msg="failed to download new TLS certificate after locking the cluster" error="context canceled" module=node node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager
    time="2018-02-19T21:00:35.739452202Z" level=debug msg="successfully rotated KEK" module=node node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager
    time="2018-02-19T21:00:35.739820389Z" level=debug msg="stop transport"
    time="2018-02-19T21:00:35.740122795Z" level=info msg="Manager shut down" module=node node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:35.740314751Z" level=debug msg="cleanupServiceDiscovery for all networks"
    time="2018-02-19T21:00:35.740323798Z" level=debug msg="daemon configured with a 15 seconds minimum shutdown timeout"
    time="2018-02-19T21:00:35.740347346Z" level=debug msg="cleanupServiceBindings for "
    time="2018-02-19T21:00:35.740353524Z" level=debug msg="start clean shutdown of all containers with a 15 seconds timeout..."
    time="2018-02-19T21:00:35.740430630Z" level=debug msg="start clean shutdown of cluster resources..."
    [... more shutdown logs]
    time="2018-02-19T21:00:40.938540510Z" level=debug msg="/sbin/iptables, [--wait -t nat -D PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]"
    [... more startup logs]
    time="2018-02-19T21:00:41.132027927Z" level=info msg="Loading containers: done."
    time="2018-02-19T21:00:41.141168974Z" level=info msg="Docker daemon" commit=7982e12 graphdriver(s)=vfs version=dev
    time="2018-02-19T21:00:41.143086072Z" level=error msg="cluster exited with error: Swarm is encrypted and needs to be unlocked before it can be used. Please use \"docker swarm unlock\" to unlock it."
    time="2018-02-19T21:00:41.143139634Z" level=error msg="swarm component could not be started" error="Swarm is encrypted and needs to be unlocked before it can be used. Please use \"docker swarm unlock\" to unlock it."
    time="2018-02-19T21:00:41.143203541Z" level=info msg="Daemon has completed initialization"
    time="2018-02-19T21:00:41.143488296Z" level=debug msg="Registering routers"
    [... more startup logs]
    time="2018-02-19T21:00:46.919297703Z" level=debug msg="Calling GET /v1.30/nodes"
    time="2018-02-19T21:00:46.919341142Z" level=error msg="Error getting nodes: Swarm is encrypted and needs to be unlocked before it can be used. Please use \"docker swarm unlock\" to unlock it."
    time="2018-02-19T21:00:46.919378066Z" level=error msg="Handler for GET /v1.30/nodes returned error: Swarm is encrypted and needs to be unlocked before it can be used. Please use \"docker swarm unlock\" to unlock it."
    time="2018-02-19T21:00:46.941458620Z" level=debug msg="Calling GET /_ping"
    time="2018-02-19T21:00:46.942208615Z" level=debug msg="Calling GET /_ping"
    time="2018-02-19T21:00:46.942595428Z" level=debug msg="Calling GET /v1.30/info"
    time="2018-02-19T21:00:46.955514901Z" level=debug msg="Calling POST /v1.30/swarm/unlock"
    time="2018-02-19T21:00:46.955661963Z" level=debug msg="form data: {\"UnlockKey\":\"*****\"}"
    time="2018-02-19T21:00:46.974217804Z" level=error msg="cluster exited with error: Swarm is encrypted and needs to be unlocked before it can be used. Please use \"docker swarm unlock\" to unlock it."
    time="2018-02-19T21:00:46.974304369Z" level=error msg="Error unlocking swarm: swarm could not be unlocked: invalid key provided"
    time="2018-02-19T21:00:46.994817981Z" level=debug msg="Calling GET /_ping"
    time="2018-02-19T21:00:46.995566807Z" level=debug msg="Calling GET /_ping"
    time="2018-02-19T21:00:46.996009849Z" level=debug msg="Calling GET /v1.30/nodes"
    time="2018-02-19T21:00:46.996046105Z" level=error msg="Error getting nodes: Swarm is encrypted and needs to be unlocked before it can be used. Please use \"docker swarm unlock\" to unlock it."
    time="2018-02-19T21:00:46.996076051Z" level=error msg="Handler for GET /v1.30/nodes returned error: Swarm is encrypted and needs to be unlocked before it can be used. Please use \"docker swarm unlock\" to unlock it."
    time="2018-02-19T21:00:47.016412742Z" level=debug msg="Calling GET /_ping"
    time="2018-02-19T21:00:47.017198218Z" level=debug msg="Calling GET /_ping"
    time="2018-02-19T21:00:47.017544263Z" level=debug msg="Calling GET /v1.30/info"
    time="2018-02-19T21:00:47.027852381Z" level=debug msg="Calling POST /v1.30/swarm/unlock"
    time="2018-02-19T21:00:47.027932957Z" level=debug msg="form data: {\"UnlockKey\":\"*****\"}"
    time="2018-02-19T21:00:47.055194030Z" level=debug msg="loaded node credentials" module=node/tls node.id=wyj91bz77bv9fp96iawlrhyis node.role=swarm-manager
    
  4. After that, d2 successfully starts up and connects to d1 - d2's agent connects to d1's dispatcher:

    time="2018-02-19T21:00:47.100037498Z" level=info msg="Listening for local connections" addr=/tmp/docker-execroot/dbcb75368785c/swarm/control.sock module=node node.id=wyj91bz77bv9fp96iawlrhyis proto=unix
    time="2018-02-19T21:00:47.104297434Z" level=info msg="Listening for connections" addr="[::]:2478" module=node node.id=wyj91bz77bv9fp96iawlrhyis proto=tcp
    time="2018-02-19T21:00:47.118770160Z" level=info msg="6304186a177a639c became follower at term 2" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:47.118836526Z" level=info msg="newRaft 6304186a177a639c [peers: [3272226729412871,6304186a177a639c,78bef282b4064307], term: 2, commit: 28, applied: 24, lastindex: 28, lastterm: 2]" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:47.118936744Z" level=debug msg="transport: add peer 78bef282b4064307 with address 127.0.0.1:2477"
    time="2018-02-19T21:00:47.120490461Z" level=debug msg="transport: add peer 3272226729412871 with address 127.0.0.1:2479"
    time="2018-02-19T21:00:50.089840997Z" level=info msg="6304186a177a639c is starting a new election at term 2" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:50.089921368Z" level=info msg="6304186a177a639c became candidate at term 3" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:50.089951901Z" level=info msg="6304186a177a639c received MsgVoteResp from 6304186a177a639c at term 3" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:50.089979041Z" level=info msg="6304186a177a639c [logterm: 2, index: 28] sent MsgVote request to 3272226729412871 at term 3" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:50.090006611Z" level=info msg="6304186a177a639c [logterm: 2, index: 28] sent MsgVote request to 78bef282b4064307 at term 3" module=raft node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:50.090764120Z" level=error msg="error sending message to peer" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable"
    time="2018-02-19T21:00:50.090813281Z" level=debug msg="failed to send message MsgVote" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable" peer_id=3272226729412871
    time="2018-02-19T21:00:52.066097649Z" level=error msg="agent: session failed" backoff=100ms error="session initiation timed out" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:52.066217772Z" level=debug msg="agent: rebuild session" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
    time="2018-02-19T21:00:52.066311945Z" level=info msg="manager selected by agent for new session: { }" module=node/agent node.id=wyj91bz77bv9fp96iawlrhyis
    

    But at around that time, d1 steps down as leader because d2 and d3 are offline:

    time="2018-02-19T21:00:47.134450461Z" level=warning msg="78bef282b4064307 stepped down to follower since quorum is not active" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:00:47.134506323Z" level=info msg="78bef282b4064307 became follower at term 2" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:00:47.134530278Z" level=info msg="raft.node: 78bef282b4064307 lost leader 78bef282b4064307 at term 2" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:00:47.134606133Z" level=error msg="soft state changed, node no longer a leader, resetting and cancelling all waits" raft_id=78bef282b4064307
    time="2018-02-19T21:00:47.134850175Z" level=error msg="agent: session failed" backoff=100ms error="rpc error: code = Canceled desc = context canceled" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:00:47.134930056Z" level=debug msg="agent: rebuild session" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:00:47.134976193Z" level=info msg="manager selected by agent for new session: { }" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:00:47.135038665Z" level=info msg="waiting 83.358449ms before registering session" module=node/agent node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:00:47.135045498Z" level=info msg="dispatcher session dropped, marking node 01apyb2gdfsz8k2t32vlqhdx6 down" method="(*Dispatcher).Session" node.id=01apyb2gdfsz8k2t32vlqhdx6 node.session=x86o55gw7lvw884cecupg6pc7
    

    Eventually, about 15 seconds later, d1 is elected leader again:

    time="2018-02-19T21:01:02.136731216Z" level=info msg="78bef282b4064307 received MsgVoteResp from 6304186a177a639c at term 7" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:01:02.136772756Z" level=info msg="78bef282b4064307 [quorum:2] has received 2 MsgVoteResp votes and 0 vote rejections" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:01:02.136814729Z" level=info msg="78bef282b4064307 became leader at term 7" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:01:02.136845101Z" level=info msg="raft.node: 78bef282b4064307 elected leader 78bef282b4064307 at term 7" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:01:02.137192918Z" level=error msg="error sending message to peer" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable"
    time="2018-02-19T21:01:02.137240385Z" level=debug msg="failed to send message MsgApp" error="rpc error: code = Unavailable desc = grpc: the connection is unavailable" peer_id=3272226729412871
    time="2018-02-19T21:01:02.137300244Z" level=debug msg="78bef282b4064307 failed to send message to 3272226729412871 because it is unreachable [next = 32, match = 0, state = ProgressStateProbe, waiting = true, pendingSnapshot = 0]" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:01:02.137916531Z" level=debug msg="78bef282b4064307 received msgApp rejection(lastindex: 28) from 6304186a177a639c for index 31" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
    time="2018-02-19T21:01:02.137962471Z" level=debug msg="78bef282b4064307 decreased progress of 6304186a177a639c to [next = 29, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]" module=raft node.id=01apyb2gdfsz8k2t32vlqhdx6
    ```
    
    
  5. However, for some reason I think the dispatcher never gets started up again, or otherwise thinks it's stopped, because neither d1 nor d2's agent can connect to any dispatcher, so both nodes are probably marked as down, and so possibly this line failed?

Not sure why the dispatcher doesn't come back up, but would it be possible that it's related to moby/swarmkit#2495 @anshulpundir?

@kolyshkin
Copy link
Copy Markdown
Contributor Author

@cyli yes you're right about i == 0, I mistyped it in my earlier comment. You seem to be right about everything else (the whole picture looked the same to me as far as I remember).

@anshulpundir
anshulpundir commented Feb 22, 2018
Copy link
Copy Markdown
Contributor

moby/swarmkit#2495 has been reverted and another fix put in (but not brought into moby yet). We could possibly expect the loss of leadership or node shutdown to hang because of that change, so I suppose Manager.handleLeadershipEvents() could be hung. Can you look at the backtrace to see where the different stacks are ? @cyli

@cyli
cyli commented Feb 22, 2018
Copy link
Copy Markdown
Contributor

@anshulpundir Unfortunately this was in CI and the daemons I think are no longer running. I have not been able to replicate this manually (although I think I've seen it in some logs for other things a couple times), but will try.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

9 participants

0