shimv2 tests failing randomly

[chavafg]

Description of problem

Since the introduction of #490, the shimv2 started to fail randomly on all CI jobs.

08:47:57     container_stats_test.go:301: Fetch container stats for sandbox truncID and container truncID filter 
08:47:57     container_stats_test.go:318: Verify container stats for sandbox "04796b82a6d2c7c5159c3c581ae45a6b352e32ed0b2abf7847432988290383bc" and container "8c6b169c3c2237e1f93fee5738538fc5c24e4db0dc6a2cf2c501d3688ada58d6" filter
08:47:57     container_stats_test.go:318: Verify container stats for sandbox "04796b82a6d2c7c5159c3c581ae45a6b352e32ed0b2abf7847432988290383bc" and container "04f11f92a67646848edac381d9cf49ce3b692ec49985fea1e7c92208af2f78d9" filter
08:47:57     container_stats_test.go:318: Verify container stats for sandbox "04796b82a6d2c7c5159c3c581ae45a6b352e32ed0b2abf7847432988290383bc" and container "7bf6385af51459377d5f691f1dcafbae702b1f827927e9e29b0b4b432c479203" filter
08:47:57     assertions.go:237: 
                        
	Error Trace:	container_stats_test.go:274
08:47:57         
			container_stats_test.go:323
08:47:57         
	Error:		Received unexpected error rpc error: code = Unknown desc = failed to stop container "8c6b169c3c2237e1f93fee5738538fc5c24e4db0dc6a2cf2c501d3688ada58d6": container not running: unknown
08:47:57         
08:47:57     assertions.go:237: 
                        
	Error Trace:	container_stats_test.go:270
08:47:57         
			container_stats_test.go:323
08:47:57         
	Error:		Received unexpected error rpc error: code = Unknown desc = failed to set removing state for container "8c6b169c3c2237e1f93fee5738538fc5c24e4db0dc6a2cf2c501d3688ada58d6": container is still running, to stop first
08:47:57         
08:47:57 FAIL
08:47:57 ./hack/test-utils.sh: line 53: 107643 Terminated              keepalive "sudo PATH=${PATH} ${ROOT}/_output/containerd ${CONTAINERD_FLAGS}" ${RESTART_WAIT_PERIOD} &> ${report_dir}/containerd.log
08:47:57 make[1]: *** [Makefile:116: test-integration] Error 1
08:47:57 make[1]: Leaving directory '/tmp/jenkins/workspace/kata-containers-tests-fedora-PR/go/src/github.com/containerd/cri'
08:47:57 make: *** [Makefile:101: shimv2] Error 2

/cc @lifupan @bergwolf @sboeuf

[chavafg]

reproduced the issue locally using sudo -E PATH=$PATH make shimv2 from the tests repository, but the logs do not report any error:

=== RUN   TestContainerListStatsWithIdFilter
E0327 18:48:15.479191   19794 remote_runtime.go:233] StopContainer "71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf" from runtime service failed: rpc error: code = Unknown desc = failed to stop
container "71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf": container not running: unknown
E0327 18:48:15.480840   19794 remote_runtime.go:250] RemoveContainer "71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf" from runtime service failed: rpc error: code = Unknown desc = failed to set removing state for container "71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf": container is still running, to stop first
--- FAIL: TestContainerListStatsWithIdFilter (12.96s)
    container_stats_test.go:132: Create a pod config and run sandbox container
    container_stats_test.go:140: Create a container config and run containers in a pod
    container_stats_test.go:162: Fetch container stats for each container with Filter
    container_stats_test.go:181: Verify container stats for 8f92d5a7206718cc5c56866a91a575860d8094852f26f972aace4504a4d16313
    container_stats_test.go:181: Verify container stats for 71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf
    container_stats_test.go:181: Verify container stats for 6d5ef05e2929fcc32792bcd0c823b9bd480acf403704561a4a21b6508aa3224f
        Error Trace:    container_stats_test.go:158
                        container_stats_test.go:187
        Error:          Received unexpected error rpc error: code = Unknown desc = failed to stop container "71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf": container not running: unknown

        Error Trace:    container_stats_test.go:154
                        container_stats_test.go:187
        Error:          Received unexpected error rpc error: code = Unknown desc = failed to set removing state for container "71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf": container is still running, to stop first

FAIL
./hack/test-utils.sh: line 53: 19761 Terminated              keepalive "sudo PATH=${PATH} ${ROOT}/_output/containerd ${CONTAINERD_FLAGS}" ${RESTART_WAIT_PERIOD} &> ${report_dir}/containerd.log

Trying to look at the logs using container ID 71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf, I just see the following lines, but no error there

Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.45550722Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.StatsContainerRequest req="container_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.463082798Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.StatsContainerRequest req="container_id:\"6d5ef05e2929fcc32792bcd0c823b9bd480acf403704561a4a21b6508aa3224f\" " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.468630281Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.SignalProcessRequest req="container_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" exec_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" signal:15 " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.471511672Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.SignalProcessRequest req="container_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" exec_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" signal:9 " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.481846841Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.SignalProcessRequest req="container_id:\"8f92d5a7206718cc5c56866a91a575860d8094852f26f972aace4504a4d16313\" exec_id:\"8f92d5a7206718cc5c56866a91a575860d8094852f26f972aace4504a4d16313\" signal:15 " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.485443231Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.SignalProcessRequest req="container_id:\"8f92d5a7206718cc5c56866a91a575860d8094852f26f972aace4504a4d16313\" exec_id:\"8f92d5a7206718cc5c56866a91a575860d8094852f26f972aace4504a4d16313\" signal:9 " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.488186923Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.WaitProcessRequest req="container_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" exec_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.497608494Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.WaitProcessRequest req="container_id:\"8f92d5a7206718cc5c56866a91a575860d8094852f26f972aace4504a4d16313\" exec_id:\"8f92d5a7206718cc5c56866a91a575860d8094852f26f972aace4504a4d16313\" " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.516109739Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.SignalProcessRequest req="container_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" signal:9 " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.518888031Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.SignalProcessRequest req="container_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" signal:9 " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.521488323Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.WaitProcessRequest req="container_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" exec_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.523633617Z" level=debug msg="Setting container state from running to stopped" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb sandbox=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb source=virtcontainers subsystem=container
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.524002616Z" level=debug msg="sending request" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb name=grpc.RemoveContainerRequest req="container_id:\"71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf\" " source=virtcontainers subsystem=kata_agent
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.607497666Z" level=debug msg="Deleting files" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb backend=filesystem path=/var/lib/vc/sbs/a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb/71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf source=virtcontainers/store subsystem=store
Mar 27 18:48:15 k8s-block-dev kata[19857]: time="2019-03-27T18:48:15.607804465Z" level=debug msg="Deleting files" ID=a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb backend=filesystem path=/run/vc/sbs/a1de98f108c4acea60530ebf23032446da8f592fc6e0ca2b6a574f644f28e1eb/71bf10e0d2a6be0de0941944ef81e954806c4f6cc808ddff8f4e5a76cfc659cf source=virtcontainers/store subsystem=store

[sboeuf]

/cc @lifupan PTAL