[DO NOT MERGE] Swarm tests debug by kolyshkin · Pull Request #38080 · moby/moby

kolyshkin · 2018-10-25T06:23:04Z

Just playing with TestSwarmClusterRotateUnlockKey a bit

Since commit 17173ef checkSwarmLockedToUnlocked() no longer require its third argument, so remove it. Signed-off-by: Kir Kolyshkin <[email protected]>

1. Using MNT_FORCE flag does not make sense for nsfs. Using MNT_DETACH though might help. 2. When -check.vv is added to TESTFLAGS, there are a lot of messages like this one: > unmount of /tmp/dxr/d847fd103a4ba/netns failed: invalid argument and some like > unmount of /tmp/dxr/dd245af642d94/netns failed: no such file or directory The first one means directory is not a mount point, the second one means it's gone. Do ignore both of these. Signed-off-by: Kir Kolyshkin <[email protected]>

A timer is leaking on every daemon start and stop. Probably nothing major, but given the amount of daemon starts/stops during tests, it's better to be accurate about it. Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin · 2018-10-25T08:28:03Z

OK the failure in DockerSwarmSuite.TestSwarmClusterRotateUnlockKey

01:27:19.614 docker_cli_swarm_test.go:1454:
01:27:19.614 c.Assert(err, checker.IsNil, check.Commentf("%s", outs))
01:27:19.614 ... value *exec.ExitError = &exec.ExitError{ProcessState:(*os.ProcessState)(0xc00083d0e0), Stderr:[]uint8(nil)} ("exit status 1")
01:27:19.614 ... Error response from daemon: rpc error: code = Unknown desc = The swarm does not have a leader. It's possible that too few managers are online. Make sure more than half of the managers are online.

happens (occasionally) because d1 (which is a leader) losts both d2 and d3, and thus it loses quorum and steps itself down from the leader to a follower:

time="2018-10-25T03:51:55.478817549Z" level=warning msg="58bdb01f53b70120 stepped down to follower since quorum is not active" module=raft node.id=l3s9bcv95laiiflz2pya15gi3
time="2018-10-25T03:51:55.478849752Z" level=info msg="58bdb01f53b70120 became follower at term 2" module=raft node.id=l3s9bcv95laiiflz2pya15gi3
time="2018-10-25T03:51:55.478859001Z" level=info msg="raft.node: 58bdb01f53b70120 lost leader 58bdb01f53b70120 at term 2" module=raft node.id=l3s9bcv95laiiflz2pya15gi3
time="2018-10-25T03:51:55.478929983Z" level=error msg="soft state changed, node no longer a leader, resetting and cancelling all waits" raft_id=58bdb01f53b70120
time="2018-10-25T03:51:55.478964151Z" level=info msg="dispatcher stopping" method="(*Dispatcher).Stop" module=dispatcher node.id=l3s9bcv95laiiflz2pya15gi3

what exactly causes that is not yet clear to me...

kolyshkin · 2018-10-25T18:50:44Z

Found a possible cause. Testing a fix (which makes sense for other tests, too, and will be applied if proved usable).

kolyshkin · 2018-10-25T22:34:30Z

Out of 5 runs, got a TestAPISwarmLeaderElection failure on z (I haven't patched this test yet). Guess it makes sense to patch all the swarm tests.

kolyshkin · 2018-10-26T05:36:18Z

Patched all the tests, reset the counter, running repeated CI again.

Runs 1-5, no failures.

Run 6, failure on experimental in TestSwarmLockUnlockCluster:

00:25:37.850 START: docker_cli_swarm_test.go:1143: DockerSwarmSuite.TestSwarmLockUnlockCluster
00:25:37.850 START: check_test.go:320: DockerSwarmSuite.SetUpTest
00:25:37.851 PASS: check_test.go:320: DockerSwarmSuite.SetUpTest	0.000s
00:25:37.851 
00:25:37.851 [d67a16aac9c2d] waiting for daemon to start
00:25:38.353 [d67a16aac9c2d] daemon started
00:25:38.353 
00:25:39.153 [d598c4764df87] waiting for daemon to start
00:25:39.655 [d598c4764df87] daemon started
00:25:39.655 
00:25:40.440 [d53d8f36873f9] waiting for daemon to start
00:25:40.941 [d53d8f36873f9] daemon started
00:25:40.941 
00:25:46.731 [d598c4764df87] exiting daemon
00:25:46.731 [d598c4764df87] waiting for daemon to start
00:25:47.233 [d598c4764df87] daemon started
00:25:47.233 
00:25:56.355 [d598c4764df87] exiting daemon
00:25:56.698 [d67a16aac9c2d] exiting daemon
00:25:56.698 [d67a16aac9c2d] waiting for daemon to start
00:25:57.200 [d67a16aac9c2d] daemon started
00:25:57.200 
00:26:13.697 [d53d8f36873f9] exiting daemon
00:26:13.697 [d53d8f36873f9] waiting for daemon to start
00:26:14.200 [d53d8f36873f9] daemon started
00:26:14.200 
00:26:18.372 [d598c4764df87] waiting for daemon to start
00:26:18.874 [d598c4764df87] daemon started
00:26:18.874 
00:26:24.997 [d598c4764df87] exiting daemon
00:26:24.998 [d598c4764df87] waiting for daemon to start
00:26:25.499 [d598c4764df87] daemon started
00:26:25.499 
00:26:26.037 [d67a16aac9c2d] exiting daemon
00:26:26.038 [d67a16aac9c2d] waiting for daemon to start
00:26:46.129 [d67a16aac9c2d] daemon started
00:26:46.130 
00:26:46.240 docker_cli_swarm_test.go:1198:
00:26:46.246     checkSwarmLockedToUnlocked(c, d)
00:26:46.246 docker_cli_swarm_test.go:1017:
00:26:46.254     c.Assert(getNodeStatus(c, d), checker.Equals, swarm.LocalNodeStateActive)
00:26:46.255 ... obtained swarm.LocalNodeState = "pending"
00:26:46.255 ... expected swarm.LocalNodeState = "active"
00:26:46.255 
00:26:46.260 START: check_test.go:347: DockerSwarmSuite.TearDownTest
00:26:46.272 [d67a16aac9c2d] exiting daemon
00:26:46.276 [d598c4764df87] exiting daemon
00:26:51.285 [d53d8f36873f9] exiting daemon
00:26:51.289 PASS: check_test.go:347: DockerSwarmSuite.TearDownTest	5.028s
00:26:51.289 
00:26:51.289 FAIL: docker_cli_swarm_test.go:1143: DockerSwarmSuite.TestSwarmLockUnlockCluster
00:26:51.289

kolyshkin · 2018-10-27T00:02:36Z

Runs 7-9: no failures.

Run 10/60 [▓▓▓▓▓▓▓▓▓▓░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░]

Failure in TestAPISwarmLeaderElection on power:

00:20:07.222 
00:20:07.223 START: docker_api_swarm_test.go:296: DockerSwarmSuite.TestAPISwarmLeaderElection
00:20:07.223 START: check_test.go:320: DockerSwarmSuite.SetUpTest
00:20:07.223 PASS: check_test.go:320: DockerSwarmSuite.SetUpTest	0.000s
00:20:07.223 
00:20:07.292 [d88e13dd68846] waiting for daemon to start
00:20:07.727 [d88e13dd68846] daemon started
00:20:07.727 
00:20:08.300 [d29173e92c51e] waiting for daemon to start
00:20:08.803 [d29173e92c51e] daemon started
00:20:08.803 
00:20:10.963 [dbef89344f8cd] waiting for daemon to start
00:20:11.466 [dbef89344f8cd] daemon started
00:20:11.466 
00:20:12.854 [d88e13dd68846] exiting daemon
00:20:32.857 assertion failed: error is not nil: Error response from daemon: rpc error: code = DeadlineExceeded desc = context deadline exceeded
00:20:32.857 START: check_test.go:347: DockerSwarmSuite.TearDownTest
00:20:32.858 Daemon d88e13dd68846 is not started
00:20:34.028 [d29173e92c51e] exiting daemon
00:20:35.272 [dbef89344f8cd] exiting daemon
00:20:35.279 PASS: check_test.go:347: DockerSwarmSuite.TearDownTest	2.423s
00:20:35.280 
00:20:35.280 FAIL: docker_api_swarm_test.go:296: DockerSwarmSuite.TestAPISwarmLeaderElection
00:20:35.280

This is repeated 6 times in different tests, with slight minor variations. Let's factor it out, for clarity. While at it, simplify the code: instead of more complex parsing of "docker swarm init|update --autolock" output (1) and checking if the key is also present in "docker swarm unlock-key" output (2), get the key from (2) and check it is present in (1). Signed-off-by: Kir Kolyshkin <[email protected]>

.. Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin · 2018-10-29T22:31:42Z

Run 18/60 [▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░]

Failure on power, TestAPISwarmLeaderElection

00:11:55.420
00:11:55.420 START: docker_api_swarm_test.go:296: DockerSwarmSuite.TestAPISwarmLeaderElection
00:11:55.421 START: check_test.go:320: DockerSwarmSuite.SetUpTest
00:11:55.421 PASS: check_test.go:320: DockerSwarmSuite.SetUpTest 0.000s
00:11:55.421
00:11:55.489 [d38e3c8be7c55] waiting for daemon to start
00:11:55.925 [d38e3c8be7c55] daemon started
00:11:55.925
00:11:56.528 [d79776d753327] waiting for daemon to start
00:11:57.031 [d79776d753327] daemon started
00:11:57.032
00:11:59.193 [d3223dbf271f8] waiting for daemon to start
00:11:59.699 [d3223dbf271f8] daemon started
00:11:59.699
00:12:01.074 [d38e3c8be7c55] exiting daemon
00:12:21.076 assertion failed: error is not nil: Error response from daemon: rpc error: code = DeadlineExceeded desc = context deadline exceeded
00:12:21.077 START: check_test.go:347: DockerSwarmSuite.TearDownTest
00:12:21.077 Daemon d38e3c8be7c55 is not started
00:12:22.245 [d79776d753327] exiting daemon
00:12:28.418 [d3223dbf271f8] exiting daemon
00:12:28.423 PASS: check_test.go:347: DockerSwarmSuite.TearDownTest 7.347s
00:12:28.424
00:12:28.424 FAIL: docker_api_swarm_test.go:296: DockerSwarmSuite.TestAPISwarmLeaderElection
00:12:28.424

kolyshkin · 2018-10-30T04:51:58Z

Run 19/60 [▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░]

Two failures, one on power in TestAPISwarmLeaderElection:

00:19:42.491
00:19:42.491 START: docker_api_swarm_test.go:296: DockerSwarmSuite.TestAPISwarmLeaderElection
00:19:42.491 START: check_test.go:320: DockerSwarmSuite.SetUpTest
00:19:42.491 PASS: check_test.go:320: DockerSwarmSuite.SetUpTest 0.000s
00:19:42.491
00:19:42.493 [d724a4bdcf700] waiting for daemon to start
00:19:42.996 [d724a4bdcf700] daemon started
00:19:42.996
00:19:43.615 [dd109cf60cb89] waiting for daemon to start
00:19:44.118 [dd109cf60cb89] daemon started
00:19:44.118
00:19:45.293 [d82deaefcb384] waiting for daemon to start
00:19:45.795 [d82deaefcb384] daemon started
00:19:45.795
00:19:47.188 [d724a4bdcf700] exiting daemon
00:20:07.191 assertion failed: error is not nil: Error response from daemon: rpc error: code = DeadlineExceeded desc = context deadline exceeded
00:20:07.191 START: check_test.go:347: DockerSwarmSuite.TearDownTest
00:20:07.191 Daemon d724a4bdcf700 is not started
00:20:12.201 [dd109cf60cb89] exiting daemon
00:20:13.405 [d82deaefcb384] exiting daemon
00:20:13.412 PASS: check_test.go:347: DockerSwarmSuite.TearDownTest 6.221s
00:20:13.412
00:20:13.412 FAIL: docker_api_swarm_test.go:296: DockerSwarmSuite.TestAPISwarmLeaderElection
00:20:13.412

and a new failure on z, TestSwarmPublishAdd:

00:35:47.832
00:35:47.832 START: docker_cli_swarm_test.go:274: DockerSwarmSuite.TestSwarmPublishAdd
00:35:47.832 START: check_test.go:320: DockerSwarmSuite.SetUpTest
00:35:47.832 PASS: check_test.go:320: DockerSwarmSuite.SetUpTest 0.000s
00:35:47.832
00:35:47.834 [d3f9f547e33bb] waiting for daemon to start
00:35:48.346 [d3f9f547e33bb] daemon started
00:35:48.346
00:35:49.973 docker_cli_swarm_test.go:286:
00:35:49.981 c.Assert(err, checker.IsNil, check.Commentf("%s", out))
00:35:49.985 ... value *exec.ExitError = &exec.ExitError{ProcessState:(*os.ProcessState)(0xc000617da0), Stderr:[]uint8(nil)} ("exit status 1")
00:35:49.986 ... Error response from daemon: rpc error: code = Unknown desc = update out of sequence
00:35:49.986
00:35:49.986
00:35:49.986 START: check_test.go:347: DockerSwarmSuite.TearDownTest
00:35:51.903 [d3f9f547e33bb] exiting daemon
00:35:51.911 PASS: check_test.go:347: DockerSwarmSuite.TearDownTest 1.928s
00:35:51.911
00:35:51.911 FAIL: docker_cli_swarm_test.go:274: DockerSwarmSuite.TestSwarmPublishAdd
00:35:51.912

...... Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin · 2018-10-30T05:30:19Z

Some previous findings on TestAPISwarmLeaderElection are in #37833

kolyshkin · 2018-10-30T18:19:08Z

Run 20 -- no failures

Run 21/60 [▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░]

Failure on power in TestSwarmClusterRotateUnlockKey:

00:33:55.218
00:33:55.218 START: docker_cli_swarm_test.go:1316: DockerSwarmSuite.TestSwarmClusterRotateUnlockKey
00:33:55.218 START: check_test.go:320: DockerSwarmSuite.SetUpTest
00:33:55.218 PASS: check_test.go:320: DockerSwarmSuite.SetUpTest 0.000s
00:33:55.218
00:33:55.223 [db8afafbf2e95] waiting for daemon to start
00:33:55.726 [db8afafbf2e95] daemon started
00:33:55.726
00:33:56.313 [d178b2e905cdf] waiting for daemon to start
00:33:56.833 [d178b2e905cdf] daemon started
00:33:56.833
00:33:57.985 [db1bfab8e751e] waiting for daemon to start
00:33:58.488 [db1bfab8e751e] daemon started
00:33:58.488
00:34:04.759 [d178b2e905cdf] exiting daemon
00:34:04.761 [d178b2e905cdf] waiting for daemon to start
00:34:05.266 [d178b2e905cdf] daemon started
00:34:05.266
00:34:10.502 [db1bfab8e751e] exiting daemon
00:34:10.503 [db1bfab8e751e] waiting for daemon to start
00:34:11.006 [db1bfab8e751e] daemon started
00:34:11.006
00:34:36.221 docker_cli_swarm_test.go:1379:
00:34:36.235 c.Assert(err, checker.IsNil, check.Commentf("%s", outs))
00:34:36.236 ... value *exec.ExitError = &exec.ExitError{ProcessState:(*os.ProcessState)(0xc000627e60), Stderr:[]uint8(nil)} ("exit status 1")
00:34:36.236 ... Error response from daemon: rpc error: code = Unknown desc = The swarm does not have a leader. It's possible that too few managers are online. Make sure more than half of the managers are online.
00:34:36.236
00:34:36.236
00:34:36.237 START: check_test.go:347: DockerSwarmSuite.TearDownTest
00:34:36.590 [db8afafbf2e95] exiting daemon
00:34:41.603 [d178b2e905cdf] exiting daemon
00:34:41.612 [db1bfab8e751e] exiting daemon
00:34:41.618 PASS: check_test.go:347: DockerSwarmSuite.TearDownTest 5.382s
00:34:41.618
00:34:41.618 FAIL: docker_cli_swarm_test.go:1316: DockerSwarmSuite.TestSwarmClusterRotateUnlockKey
00:34:41.619

When starting docker daemons for swarm testing, we disable iptables and use lo for communication (in order to avoid network conflicts). The problem is, these options are lost on restart, that can lead to any sorts of network conflicts and thus connectivity issues between swarm nodes. Fix this. 29/60 [▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░] Failures so far: * TestSwarmLockUnlockCluster ▓▓ * TestAPISwarmLeaderElection ▓▓▓▓ * TestSwarmClusterRotateUnlockKey ▓▓▓ * TestSwarmPublishAdd ▓ Signed-off-by: Kir Kolyshkin <[email protected]>

vdemeester · 2019-01-10T10:44:13Z

@kolyshkin giving the "status" and the time without activity on this PR, I'm gonna close it 👼

kolyshkin · 2019-01-10T22:16:19Z

Right, thanks. The good part of it is already merged in #38127, the rest is just [futile] attempts to figure out what's going on with flaky swarm tests.

thaJeztah · 2019-01-11T00:09:16Z

Perhaps we could use testing.Verbose() to enable additional debugging on some tests (https://splice.com/blog/lesser-known-features-go-test/)

docker_cli_swarm_test.go: rm unused arg

40fd6cf

Since commit 17173ef checkSwarmLockedToUnlocked() no longer require its third argument, so remove it. Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin requested review from tianon and vdemeester as code owners October 25, 2018 06:23

GordonTheTurtle added the status/0-triage label Oct 25, 2018

kolyshkin added 2 commits October 25, 2018 01:17

internal/test/daemon: don't leak timers

88dc05b

A timer is leaking on every daemon start and stop. Probably nothing major, but given the amount of daemon starts/stops during tests, it's better to be accurate about it. Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin force-pushed the swarm-tests branch from 98e0388 to eadb71b Compare October 25, 2018 08:21

thaJeztah added area/testing area/swarm labels Oct 25, 2018

kolyshkin force-pushed the swarm-tests branch 3 times, most recently from 2310221 to 1b9ae46 Compare October 25, 2018 18:28

kolyshkin force-pushed the swarm-tests branch 4 times, most recently from 8dd6f99 to 1547db6 Compare October 25, 2018 21:48

kolyshkin force-pushed the swarm-tests branch 5 times, most recently from 72f830b to 7c3bf5b Compare October 26, 2018 03:39

kolyshkin force-pushed the swarm-tests branch 4 times, most recently from 706c6ad to 6f9b564 Compare October 26, 2018 19:46

kolyshkin added 2 commits October 29, 2018 14:03

debug: only run *Swarm* tests

d810c73

.. Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin force-pushed the swarm-tests branch 2 times, most recently from 3f55b07 to 8faac3e Compare October 29, 2018 22:09

kolyshkin force-pushed the swarm-tests branch from 8faac3e to 46f123a Compare October 29, 2018 22:59

kolyshkin force-pushed the swarm-tests branch from 46f123a to af4ec3e Compare October 30, 2018 05:00

TestAPISwarmLeaderElection: add some debug

d97d868

...... Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin force-pushed the swarm-tests branch 2 times, most recently from 4a5b90b to e9d385d Compare October 30, 2018 16:09

kolyshkin force-pushed the swarm-tests branch 7 times, most recently from b168e90 to 5643aed Compare November 2, 2018 00:40

kolyshkin force-pushed the swarm-tests branch from 5643aed to ede2d11 Compare November 2, 2018 01:27

GordonTheTurtle assigned tonistiigi Nov 9, 2018

derek bot added the invalid label Dec 22, 2018

olljanat mentioned this pull request Dec 24, 2018

Disabled Flaky tests on powerpc and z #38423

Merged

vdemeester closed this Jan 10, 2019

kolyshkin deleted the swarm-tests branch January 10, 2019 22:16

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[DO NOT MERGE] Swarm tests debug#38080

[DO NOT MERGE] Swarm tests debug#38080
kolyshkin wants to merge 7 commits intomoby:masterfrom
kolyshkin:swarm-tests

kolyshkin commented Oct 25, 2018

Uh oh!

kolyshkin commented Oct 25, 2018

Uh oh!

kolyshkin commented Oct 25, 2018

Uh oh!

kolyshkin commented Oct 25, 2018

Uh oh!

kolyshkin commented Oct 26, 2018 •

edited

Loading

Uh oh!

kolyshkin commented Oct 27, 2018

Uh oh!

kolyshkin commented Oct 29, 2018

Uh oh!

kolyshkin commented Oct 30, 2018 •

edited

Loading

Uh oh!

kolyshkin commented Oct 30, 2018

Uh oh!

kolyshkin commented Oct 30, 2018 •

edited

Loading

Uh oh!

vdemeester commented Jan 10, 2019

Uh oh!

kolyshkin commented Jan 10, 2019

Uh oh!

thaJeztah commented Jan 11, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

Conversation

kolyshkin commented Oct 25, 2018

Uh oh!

kolyshkin commented Oct 25, 2018

Uh oh!

kolyshkin commented Oct 25, 2018

Uh oh!

kolyshkin commented Oct 25, 2018

Uh oh!

kolyshkin commented Oct 26, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

kolyshkin commented Oct 27, 2018

Uh oh!

kolyshkin commented Oct 29, 2018

Uh oh!

kolyshkin commented Oct 30, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

kolyshkin commented Oct 30, 2018

Uh oh!

kolyshkin commented Oct 30, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vdemeester commented Jan 10, 2019

Uh oh!

kolyshkin commented Jan 10, 2019

Uh oh!

thaJeztah commented Jan 11, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

kolyshkin commented Oct 26, 2018 •

edited

Loading

kolyshkin commented Oct 30, 2018 •

edited

Loading

kolyshkin commented Oct 30, 2018 •

edited

Loading