TestUpdaterRollback test failures in CI

[cyli]

I've been seeing this test failure more often in CI:

time="2018-03-14T22:31:27Z" level=error msg="update failed" error="task 68j7zmft3c0krlt6zv1h5zb31 was already shut down when reached by updater" task.id=g4bhodvfo543x1xe3fwp28k4t 
--- FAIL: TestUpdaterRollback (4.47s)
    --- FAIL: TestUpdaterRollback/pause/monitor_set/spec_version_unset (1.60s)
	Error Trace:	testutils.go:26
			update_test.go:287
			update_test.go:19
	Error:		no task creation
    		

FAIL

[cyli]

Also seeing:

--- FAIL: TestUpdaterRollback (4.44s)
    --- FAIL: TestUpdaterRollback/pause/monitor_set/spec_version_set (1.60s)
	Error Trace:	testutils.go:26
			update_test.go:287
			update_test.go:20
	Error:		no task creation
    		

FAIL
coverage: 86.5% of statements
FAIL	github.com/docker/swarmkit/manager/orchestrator/replicated	7.765s

[cyli]

These aren't new, but I had saved additional failures from a while ago as something to look into:

https://circleci.com/gh/docker/swarmkit/7887:

time="2017-08-17T06:01:50Z" level=error msg="update failed" error="task g3ktlgigd8v6pzzzysieyjl6u was already shut down when reached by updater" task.id=lm1qzx2e9fz8lik7ghgj0shmf 
time="2017-08-17T06:01:51Z" level=error msg="update failed" error="task zr1jjr4bjcgqrk7vf3f5120he was already shut down when reached by updater" task.id=o3igf120bdt2e5t9zl8uhyuq6 
--- FAIL: TestUpdaterRollback (4.00s)
    --- FAIL: TestUpdaterRollback/continue/spec_version_unset (1.67s)
	Error Trace:	update_test.go:281
			update_test.go:24
	Error:		Not equal: "image2" (expected)
    			        != "image1" (actual)
    		

https://circleci.com/gh/docker/swarmkit/7875

--- FAIL: TestUpdaterRollback (4.42s)
    --- FAIL: TestUpdaterRollback/pause/monitor_set/spec_version_unset (1.59s)
	Error Trace:	testutils.go:26
			update_test.go:287
			update_test.go:19
	Error:		no task creation
    		

FAIL
coverage: 86.7% of statements
FAIL	github.com/docker/swarmkit/manager/orchestrator/replicated	6.996s

[olljanat]

@thaJeztah @cyli #2762 is merged and this should not happen anymore.

[thaJeztah]

closing; per the above; thanks!

[olljanat]

@thaJeztah FYI this one still happened on #2738 so probably it need to be re-opened.

EDIT: Difference before and after #2762 is that earlier this error happened after ~1,5 second and now after ~2,5 second.

Maybe we should follow this for a while and see if timeout value should be even higher?

[thaJeztah]

Let me reopen

ping @dperny @anshulpundir FYI ^^ the above may indicate that there's a regression in performance?

[olljanat]

Some more log from recent CI build on master

ok  	github.com/docker/swarmkit/manager/orchestrator/replicated	6.338s	coverage: 85.1% of statements
--- FAIL: TestUpdaterRollback (5.41s)
    --- FAIL: TestUpdaterRollback/pause/monitor_set/spec_version_unset (2.59s)
	Error Trace:	testutils.go:26
			update_test.go:285
			update_test.go:19
	Error:		no task creation
            

FAIL
coverage: 85.1% of statements
FAIL	github.com/docker/swarmkit/manager/orchestrator/replicated	7.331s
make: *** [coverage] Error 1
Exited with code 2

[olljanat]

I find out that this can be easily replicated with command:
go test -v -race -count 100 -run TestUpdaterRollback github.com/docker/swarmkit/manager/orchestrator/replicated

Interesting detail is that if I remove -race switch tests will pass just fine.