Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

kvm2 test failures: unable to stop vm, current state "Running" #5723

Closed
medyagh opened this issue Oct 24, 2019 · 4 comments
Closed

kvm2 test failures: unable to stop vm, current state "Running" #5723

medyagh opened this issue Oct 24, 2019 · 4 comments
Labels
area/testing co/runtime/crio CRIO related issues kind/failing-test Categorizes issue or PR as related to a consistently or frequently failing test. kind/flake Categorizes issue or PR as related to a flaky test. lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. priority/important-longterm Important over the long term, but may not be staffed and/or may need multiple releases to complete.

Comments

@medyagh
Copy link
Member

medyagh commented Oct 24, 2019

On master I have been seeing lots and lots of fails on "TestStartStop/group/crio"

as seen in this PR : https://storage.googleapis.com/minikube-builds/logs/5721/KVM_Linux.txt

here is one from master:

09:20:01 --- FAIL: TestStartStop (923.84s)
09:20:01     --- FAIL: TestStartStop/group (130.00s)
09:20:01         --- FAIL: TestStartStop/group/crio (778.90s)
09:20:01             helpers.go:349: MaybeSlowParallel: Sleeping 40s to avoid start race ...
09:20:01             start_stop_delete_test.go:89: (dbg) Run:  out/minikube-linux-amd64 start -p crio-20191024T160659.448877654-27169 --alsologtostderr -v=3 --container-runtime=crio --disable-driver-mounts --extra-config=kubeadm.ignore-preflight-errors=SystemVerification --vm-driver=kvm2 
09:20:01             start_stop_delete_test.go:89: (dbg) Done: out/minikube-linux-amd64 start -p crio-20191024T160659.448877654-27169 --alsologtostderr -v=3 --container-runtime=crio --disable-driver-mounts --extra-config=kubeadm.ignore-preflight-errors=SystemVerification --vm-driver=kvm2 : (6m35.799116136s)
09:20:01             start_stop_delete_test.go:100: (dbg) Run:  kubectl --context crio-20191024T160659.448877654-27169 create -f testdata/busybox.yaml
09:20:01             start_stop_delete_test.go:100: (dbg) Done: kubectl --context crio-20191024T160659.448877654-27169 create -f testdata/busybox.yaml: (18.026871106s)
09:20:01             start_stop_delete_test.go:105: (dbg) waiting for pods with labels "integration-test=busybox" in namespace "default" ...
09:20:01             helpers.go:244: "busybox" [5de2f98f-d0a2-4d21-8a64-45a6ca5902ca] Pending
09:20:01             helpers.go:244: "busybox" [5de2f98f-d0a2-4d21-8a64-45a6ca5902ca] Pending / Ready:ContainersNotReady (containers with unready status: [busybox]) / ContainersReady:ContainersNotReady (containers with unready status: [busybox])
09:20:01             helpers.go:244: "busybox" [5de2f98f-d0a2-4d21-8a64-45a6ca5902ca] Running
09:20:01             start_stop_delete_test.go:105: (dbg) pods integration-test=busybox up and healthy within 47.633823056s
09:20:01             start_stop_delete_test.go:110: (dbg) Run:  out/minikube-linux-amd64 stop -p crio-20191024T160659.448877654-27169 --alsologtostderr -v=3
09:20:01             start_stop_delete_test.go:110: (dbg) Non-zero exit: out/minikube-linux-amd64 stop -p crio-20191024T160659.448877654-27169 --alsologtostderr -v=3: exit status 70 (3m18.625113131s)
09:20:01                 -- stdout --
09:20:01                 * Stopping "crio-20191024T160659.448877654-27169" in kvm2 ...
09:20:01                 * Stopping "crio-20191024T160659.448877654-27169" in kvm2 ...
09:20:01                 * Stopping "crio-20191024T160659.448877654-27169" in kvm2 ...
09:20:01                 
09:20:01                 -- /stdout --
09:20:01                 ** stderr ** 
09:20:01                 I1024 16:14:41.117587   31636 main.go:110] libmachine: Found binary path at /home/jenkins/workspace/KVM_Linux_integration/out/docker-machine-driver-kvm2
09:20:01                 I1024 16:14:41.117830   31636 main.go:110] libmachine: Launching plugin server for driver kvm2
09:20:01                 I1024 16:14:41.148669   31636 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:34063
09:20:01                 I1024 16:14:41.154210   31636 main.go:110] libmachine: () Calling .GetVersion
09:20:01                 I1024 16:14:41.158965   31636 main.go:110] libmachine: Using API Version  1
09:20:01                 I1024 16:14:41.159021   31636 main.go:110] libmachine: () Calling .SetConfigRaw
09:20:01                 I1024 16:14:41.159697   31636 main.go:110] libmachine: () Calling .GetMachineName
09:20:01                 I1024 16:14:41.160038   31636 main.go:110] libmachine: Stopping "crio-20191024T160659.448877654-27169"...
09:20:01                 I1024 16:14:41.160062   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Calling .GetState
09:20:01                 I1024 16:14:41.168052   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Calling .Stop
09:20:01                 I1024 16:14:41.226422   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 0/60
09:20:01                 I1024 16:14:42.232934   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 1/60
09:20:01                 I1024 16:14:43.239994   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 2/60
09:20:01                 I1024 16:14:44.245985   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 3/60
09:20:01                 I1024 16:14:45.251985   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 4/60
09:20:01                 I1024 16:14:46.257661   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 5/60
09:20:01                 I1024 16:14:47.263725   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 6/60
09:20:01                 I1024 16:14:48.269536   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 7/60
09:20:01                 I1024 16:14:49.275389   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 8/60
09:20:01                 I1024 16:14:50.280771   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 9/60
09:20:01                 I1024 16:14:51.286361   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 10/60
09:20:01                 I1024 16:14:52.292036   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 11/60
09:20:01                 I1024 16:14:53.297208   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 12/60
09:20:01                 I1024 16:14:54.302371   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 13/60
09:20:01                 I1024 16:14:55.307273   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 14/60
09:20:01                 I1024 16:14:56.312083   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 15/60
09:20:01                 I1024 16:14:57.317151   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 16/60
09:20:01                 I1024 16:14:58.324922   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 17/60
09:20:01                 I1024 16:15:00.017632   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 18/60
09:20:01                 I1024 16:15:01.026067   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 19/60
09:20:01                 I1024 16:15:02.027516   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 20/60
09:20:01                 I1024 16:15:03.039943   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 21/60
09:20:01                 I1024 16:15:04.045665   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 22/60
09:20:01                 I1024 16:15:05.051125   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 23/60
09:20:01                 I1024 16:15:06.056504   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 24/60
09:20:01                 I1024 16:15:07.061534   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 25/60
09:20:01                 I1024 16:15:08.066469   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 26/60
09:20:01                 I1024 16:15:09.072372   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 27/60
09:20:01                 I1024 16:15:10.077512   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 28/60
09:20:01                 I1024 16:15:11.083293   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 29/60
09:20:01                 I1024 16:15:12.088422   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 30/60
09:20:01                 I1024 16:15:13.093707   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 31/60
09:20:01                 I1024 16:15:14.098533   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 32/60
09:20:01                 I1024 16:15:15.103894   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 33/60
09:20:01                 I1024 16:15:16.108120   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 34/60
09:20:01                 I1024 16:15:17.112482   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 35/60
09:20:01                 I1024 16:15:18.117007   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 36/60
09:20:01                 I1024 16:15:19.122385   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 37/60
09:20:01                 I1024 16:15:20.127398   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 38/60
09:20:01                 I1024 16:15:21.131625   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 39/60
09:20:01                 I1024 16:15:22.135995   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 40/60
09:20:01                 I1024 16:15:23.140812   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 41/60
09:20:01                 I1024 16:15:24.145465   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 42/60
09:20:01                 I1024 16:15:25.150565   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 43/60
09:20:01                 I1024 16:15:26.156114   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 44/60
09:20:01                 I1024 16:15:27.161609   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 45/60
09:20:01                 I1024 16:15:28.167116   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 46/60
09:20:01                 I1024 16:15:29.173351   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 47/60
09:20:01                 I1024 16:15:30.179332   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 48/60
09:20:01                 I1024 16:15:31.184420   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 49/60
09:20:01                 I1024 16:15:32.190127   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 50/60
09:20:01                 I1024 16:15:33.195555   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 51/60
09:20:01                 I1024 16:15:34.200366   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 52/60
09:20:01                 I1024 16:15:35.205614   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 53/60
09:20:01                 I1024 16:15:36.212379   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 54/60
09:20:01                 I1024 16:15:37.219752   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 55/60
09:20:01                 I1024 16:15:38.224538   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 56/60
09:20:01                 I1024 16:15:39.231052   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 57/60
09:20:01                 I1024 16:15:40.238062   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 58/60
09:20:01                 I1024 16:15:41.243112   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 59/60
09:20:01                 I1024 16:15:47.768133   31636 main.go:110] libmachine: Found binary path at /home/jenkins/workspace/KVM_Linux_integration/out/docker-machine-driver-kvm2
09:20:01                 I1024 16:15:47.768223   31636 main.go:110] libmachine: Launching plugin server for driver kvm2
09:20:01                 I1024 16:15:47.808451   31636 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:42523
09:20:01                 I1024 16:15:47.809008   31636 main.go:110] libmachine: () Calling .GetVersion
09:20:01                 I1024 16:15:47.809727   31636 main.go:110] libmachine: Using API Version  1
09:20:01                 I1024 16:15:47.809761   31636 main.go:110] libmachine: () Calling .SetConfigRaw
09:20:01                 I1024 16:15:47.810361   31636 main.go:110] libmachine: () Calling .GetMachineName
09:20:01                 I1024 16:15:47.810782   31636 main.go:110] libmachine: Stopping "crio-20191024T160659.448877654-27169"...
09:20:01                 I1024 16:15:47.810812   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Calling .GetState
09:20:01                 I1024 16:15:47.815437   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Calling .Stop
09:20:01                 I1024 16:15:47.825932   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 0/60
09:20:01                 I1024 16:15:48.831004   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 1/60
09:20:01                 I1024 16:15:49.837269   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 2/60
09:20:01                 I1024 16:15:50.842688   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 3/60
09:20:01                 I1024 16:15:51.847767   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 4/60
09:20:01                 I1024 16:15:52.852931   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 5/60
09:20:01                 I1024 16:15:53.858379   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 6/60
09:20:01                 I1024 16:15:54.864298   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 7/60
09:20:01                 I1024 16:15:55.869841   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 8/60
09:20:01                 I1024 16:15:56.875822   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 9/60
09:20:01                 I1024 16:15:57.881088   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 10/60
09:20:01                 I1024 16:15:58.886859   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 11/60
09:20:01                 I1024 16:15:59.892402   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 12/60
09:20:01                 I1024 16:16:00.897787   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 13/60
09:20:01                 I1024 16:16:01.903985   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 14/60
09:20:01                 I1024 16:16:02.910336   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 15/60
09:20:01                 I1024 16:16:03.916379   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 16/60
09:20:01                 I1024 16:16:04.921951   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 17/60
09:20:01                 I1024 16:16:05.926799   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 18/60
09:20:01                 I1024 16:16:06.932878   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 19/60
09:20:01                 I1024 16:16:07.938394   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 20/60
09:20:01                 I1024 16:16:08.944100   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 21/60
09:20:01                 I1024 16:16:09.950130   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 22/60
09:20:01                 I1024 16:16:10.955988   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 23/60
09:20:01                 I1024 16:16:11.961390   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 24/60
09:20:01                 I1024 16:16:12.967643   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 25/60
09:20:01                 I1024 16:16:13.973577   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 26/60
09:20:01                 I1024 16:16:14.979291   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 27/60
09:20:01                 I1024 16:16:15.985532   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 28/60
09:20:01                 I1024 16:16:16.990477   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 29/60
09:20:01                 I1024 16:16:17.996154   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 30/60
09:20:01                 I1024 16:16:19.001423   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 31/60
09:20:01                 I1024 16:16:20.006748   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 32/60
09:20:01                 I1024 16:16:21.011952   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 33/60
09:20:01                 I1024 16:16:22.016643   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 34/60
09:20:01                 I1024 16:16:23.022399   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 35/60
09:20:01                 I1024 16:16:24.027482   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 36/60
09:20:01                 I1024 16:16:25.031949   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 37/60
09:20:01                 I1024 16:16:26.037044   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 38/60
09:20:01                 I1024 16:16:27.042631   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 39/60
09:20:01                 I1024 16:16:28.047972   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 40/60
09:20:01                 I1024 16:16:29.052688   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 41/60
09:20:01                 I1024 16:16:30.058332   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 42/60
09:20:01                 I1024 16:16:31.063969   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 43/60
09:20:01                 I1024 16:16:32.069934   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 44/60
09:20:01                 I1024 16:16:33.074890   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 45/60
09:20:01                 I1024 16:16:34.080184   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 46/60
09:20:01                 I1024 16:16:35.085237   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 47/60
09:20:01                 I1024 16:16:36.091281   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 48/60
09:20:01                 I1024 16:16:37.097368   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 49/60
09:20:01                 I1024 16:16:38.102877   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 50/60
09:20:01                 I1024 16:16:39.108552   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 51/60
09:20:01                 I1024 16:16:40.120069   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 52/60
09:20:01                 I1024 16:16:41.125812   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 53/60
09:20:01                 I1024 16:16:42.131024   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 54/60
09:20:01                 I1024 16:16:43.136347   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 55/60
09:20:01                 I1024 16:16:44.142158   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 56/60
09:20:01                 I1024 16:16:45.148096   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 57/60
09:20:01                 I1024 16:16:46.153903   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 58/60
09:20:01                 I1024 16:16:47.160350   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 59/60
09:20:01                 I1024 16:16:58.966245   31636 main.go:110] libmachine: Found binary path at /home/jenkins/workspace/KVM_Linux_integration/out/docker-machine-driver-kvm2
09:20:01                 I1024 16:16:58.966326   31636 main.go:110] libmachine: Launching plugin server for driver kvm2
09:20:01                 I1024 16:16:59.007142   31636 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:45279
09:20:01                 I1024 16:16:59.007745   31636 main.go:110] libmachine: () Calling .GetVersion
09:20:01                 I1024 16:16:59.008757   31636 main.go:110] libmachine: Using API Version  1
09:20:01                 I1024 16:16:59.008783   31636 main.go:110] libmachine: () Calling .SetConfigRaw
09:20:01                 I1024 16:16:59.009412   31636 main.go:110] libmachine: () Calling .GetMachineName
09:20:01                 I1024 16:16:59.009755   31636 main.go:110] libmachine: Stopping "crio-20191024T160659.448877654-27169"...
09:20:01                 I1024 16:16:59.009775   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Calling .GetState
09:20:01                 I1024 16:16:59.015338   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Calling .Stop
09:20:01                 I1024 16:16:59.029357   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 0/60
09:20:01                 I1024 16:17:00.035317   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 1/60
09:20:01                 I1024 16:17:01.041278   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 2/60
09:20:01                 I1024 16:17:02.046736   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 3/60
09:20:01                 I1024 16:17:03.053702   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 4/60
09:20:01                 I1024 16:17:04.059194   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 5/60
09:20:01                 I1024 16:17:05.066285   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 6/60
09:20:01                 I1024 16:17:06.072842   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 7/60
09:20:01                 I1024 16:17:07.084273   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 8/60
09:20:01                 I1024 16:17:08.097481   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 9/60
09:20:01                 I1024 16:17:09.108028   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 10/60
09:20:01                 I1024 16:17:10.118957   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 11/60
09:20:01                 I1024 16:17:11.140587   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 12/60
09:20:01                 I1024 16:17:12.151169   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 13/60
09:20:01                 I1024 16:17:13.161014   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 14/60
09:20:01                 I1024 16:17:14.172130   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 15/60
09:20:01                 I1024 16:17:15.185150   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 16/60
09:20:01                 I1024 16:17:16.196891   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 17/60
09:20:01                 I1024 16:17:17.208998   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 18/60
09:20:01                 I1024 16:17:18.219085   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 19/60
09:20:01                 I1024 16:17:19.229862   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 20/60
09:20:01                 I1024 16:17:20.238978   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 21/60
09:20:01                 I1024 16:17:21.247749   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 22/60
09:20:01                 I1024 16:17:22.257823   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 23/60
09:20:01                 I1024 16:17:23.268853   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 24/60
09:20:01                 I1024 16:17:24.278416   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 25/60
09:20:01                 I1024 16:17:25.287520   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 26/60
09:20:01                 I1024 16:17:26.296283   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 27/60
09:20:01                 I1024 16:17:27.307492   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 28/60
09:20:01                 I1024 16:17:28.317158   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 29/60
09:20:01                 I1024 16:17:29.326558   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 30/60
09:20:01                 I1024 16:17:30.332557   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 31/60
09:20:01                 I1024 16:17:31.342237   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 32/60
09:20:01                 I1024 16:17:32.347863   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 33/60
09:20:01                 I1024 16:17:33.356362   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 34/60
09:20:01                 I1024 16:17:34.367230   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 35/60
09:20:01                 I1024 16:17:35.375559   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 36/60
09:20:01                 I1024 16:17:36.385604   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 37/60
09:20:01                 I1024 16:17:37.397583   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 38/60
09:20:01                 I1024 16:17:38.405322   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 39/60
09:20:01                 I1024 16:17:39.413166   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 40/60
09:20:01                 I1024 16:17:40.419205   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 41/60
09:20:01                 I1024 16:17:41.425473   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 42/60
09:20:01                 I1024 16:17:42.432143   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 43/60
09:20:01                 I1024 16:17:43.438379   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 44/60
09:20:01                 I1024 16:17:44.444849   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 45/60
09:20:01                 I1024 16:17:45.452407   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 46/60
09:20:01                 I1024 16:17:46.458609   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 47/60
09:20:01                 I1024 16:17:47.464599   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 48/60
09:20:01                 I1024 16:17:48.470112   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 49/60
09:20:01                 I1024 16:17:49.475495   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 50/60
09:20:01                 I1024 16:17:50.481974   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 51/60
09:20:01                 I1024 16:17:51.489881   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 52/60
09:20:01                 I1024 16:17:52.495647   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 53/60
09:20:01                 I1024 16:17:53.502261   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 54/60
09:20:01                 I1024 16:17:54.508113   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 55/60
09:20:01                 I1024 16:17:55.515353   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 56/60
09:20:01                 I1024 16:17:56.522078   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 57/60
09:20:01                 I1024 16:17:57.529057   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 58/60
09:20:01                 I1024 16:17:58.535588   31636 main.go:110] libmachine: (crio-20191024T160659.448877654-27169) Waiting for machine to stop 59/60
09:20:01                 W1024 16:17:59.536894   31636 exit.go:101] Unable to stop VM: Temporary Error: Stop: crio-20191024T160659.448877654-27169: unable to stop vm, current state "Running"
09:20:01                 * 
09:20:01                 X Unable to stop VM: Temporary Error: Stop: crio-20191024T160659.448877654-27169: unable to stop vm, current state "Running"
09:20:01                 * 
09:20:01                 * Sorry that minikube crashed. If this was unexpected, we would love to hear from you:
09:20:01                   - https://github.com/kubernetes/minikube/issues/new/choose
09:20:01                 
09:20:01                 ** /stderr **
09:20:01             start_stop_delete_test.go:112: [out/minikube-linux-amd64 stop -p crio-20191024T160659.448877654-27169 --alsologtostderr -v=3] failed: exit status 70
09:20:01             start_stop_delete_test.go:115: (dbg) Run:  out/minikube-linux-amd64 status --format={{.Host}} -p crio-20191024T160659.448877654-27169
09:20:01             start_stop_delete_test.go:117: status = "Running"; want = "Stopped"
09:20:01             start_stop_delete_test.go:120: (dbg) Run:  out/minikube-linux-amd64 start -p crio-20191024T160659.448877654-27169 --alsologtostderr -v=3 --container-runtime=crio --disable-driver-mounts --extra-config=kubeadm.ignore-preflight-errors=SystemVerification --vm-driver=kvm2 
09:20:01             start_stop_delete_test.go:120: (dbg) Done: out/minikube-linux-amd64 start -p crio-20191024T160659.448877654-27169 --alsologtostderr -v=3 --container-runtime=crio --disable-driver-mounts --extra-config=kubeadm.ignore-preflight-errors=SystemVerification --vm-driver=kvm2 : (1m11.365115632s)
09:20:01             start_stop_delete_test.go:128: (dbg) waiting for pods with labels "integration-test=busybox" in namespace "default" ...
09:20:01             helpers.go:244: "busybox" [5de2f98f-d0a2-4d21-8a64-45a6ca5902ca] Running
09:20:01             start_stop_delete_test.go:128: (dbg) pods integration-test=busybox up and healthy within 5.035175809s
09:20:01             start_stop_delete_test.go:132: (dbg) Run:  out/minikube-linux-amd64 status --format={{.Host}} -p crio-20191024T160659.448877654-27169
09:20:01             start_stop_delete_test.go:138: (dbg) Run:  out/minikube-linux-amd64 delete -p crio-20191024T160659.448877654-27169
09:20:01             start_stop_delete_test.go:142: TestStartStop/group/crio failed, collecting logs ...
09:20:01             start_stop_delete_test.go:142: (dbg) Run:  out/minikube-linux-amd64 -p crio-20191024T160659.448877654-27169 logs -n 100
09:20:01             start_stop_delete_test.go:142: (dbg) Non-zero exit: out/minikube-linux-amd64 -p crio-20191024T160659.448877654-27169 logs -n 100: exit status 70 (157.329442ms)
09:20:01                 
09:20:01                 ** stderr ** 
09:20:01                 * 
09:20:01                 X Error getting config: stat /home/jenkins/minikube-integration/linux-amd64-kvm2-master-25048-5ba4a7d66ca47a57d3b06f75e21e8e11134df7f0/.minikube/profiles/crio-20191024T160659.448877654-27169/config.json: no such file or directory
09:20:01                 * 
09:20:01                 * Sorry that minikube crashed. If this was unexpected, we would love to hear from you:
09:20:01                   - https://github.com/kubernetes/minikube/issues/new/choose
09:20:01                 
09:20:01                 ** /stderr **
09:20:01             start_stop_delete_test.go:142: failed logs error: exit status 70
09:20:01             start_stop_delete_test.go:142: TestStartStop/group/crio logs: 
09:20:01             start_stop_delete_test.go:142: Sorry that TestStartStop/group/crio failed :(
09:20:01             helpers.go:165: (dbg) Run:  out/minikube-linux-amd64 delete -p crio-20191024T160659.448877654-27169
09:20:01 FAIL
09:20:02 >> out/e2e-linux-amd64 exited with 1 at Thu Oct 24 16:20:02 UTC 2019
09:20:02 
09:20:02 minikube: FAIL
09:20:02 >> Cleaning up after ourselves ...
09:20:02 >> /home/jenkins/minikube-integration/linux-amd64-kvm2-master-25048-5ba4a7d66ca47a57d3b06f75e21e8e11134df7f0 completed at Thu Oct 24 16:20:02 UTC 2019
09:20:02 Build step 'Execute shell' marked build as failure
09:20:09 [Google Cloud Storage Plugin] Uploading: KVM_Linux.txt
09:20:10 Finished: FAILURE
@medyagh medyagh added kind/failing-test Categorizes issue or PR as related to a consistently or frequently failing test. kind/flake Categorizes issue or PR as related to a flaky test. labels Oct 24, 2019
@medyagh medyagh changed the title Flake Test: TestStartStop/group/crio TestStartStop/group/crio: "unable to stop vm, current state "Running" Oct 24, 2019
@afbjorklund
Copy link
Collaborator

Does it only happen with the crio runtime ? Maybe we are missing a systemd service here...

In the repository there are three services: crio.service, crio-wipe.service, crio-shutdown.service

[Unit]
Description=Shutdown CRI-O containers before shutting down the system
Wants=crio.service
After=crio.service
Documentation=man:crio(8)

[Service]
Type=oneshot
ExecStart=/usr/bin/rm -f /var/lib/crio/crio.shutdown
ExecStop=/usr/bin/bash -c "/usr/bin/mkdir /var/lib/crio; /usr/bin/touch /var/lib/crio/crio.shutdown"
RemainAfterExit=yes

[Install]
WantedBy=multi-user.target

@afbjorklund afbjorklund added the co/runtime/crio CRIO related issues label Oct 26, 2019
@medyagh medyagh added the priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. label Nov 4, 2019
@medyagh
Copy link
Member Author

medyagh commented Nov 4, 2019

@afbjorklund it seems to be a recuring one for ciro test on kvm

here is another one on current Master:
https://storage.googleapis.com/minikube-builds/logs/5813/KVM_Linux.txt

@tstromberg tstromberg added priority/important-longterm Important over the long term, but may not be staffed and/or may need multiple releases to complete. and removed priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. labels Dec 9, 2019
@fejta-bot
Copy link

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

@k8s-ci-robot k8s-ci-robot added the lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. label Mar 8, 2020
@tstromberg tstromberg changed the title TestStartStop/group/crio: "unable to stop vm, current state "Running" kvm2 test failures: unable to stop vm, current state "Running Mar 26, 2020
@tstromberg tstromberg changed the title kvm2 test failures: unable to stop vm, current state "Running kvm2 test failures: unable to stop vm, current state "Running" Mar 26, 2020
@tstromberg
Copy link
Contributor

crio test appears to be stable now on KVM:

KVM_Linux         | 2020-04-13 | 100% | 9 of 9
KVM_Linux         | 2020-04-14 | 100% | 12 of 12
KVM_Linux         | 2020-04-15 | 100% | 10 of 10
KVM_Linux         | 2020-04-16 | 100% | 12 of 12
KVM_Linux         | 2020-04-17 | 100% | 1 of 1

error message appears to have slowed down in frequency, haven't seen in past week:

Frequency per day                                                                                                                                                                                
-----------------                                                                                                                                                                                
      1 2020-04-09
      1 2020-04-04
     14 2020-04-01
     14 2020-03-31
     13 2020-03-30
     16 2020-03-29
     14 2020-03-28
     15 2020-03-27
     31 2020-03-26

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/testing co/runtime/crio CRIO related issues kind/failing-test Categorizes issue or PR as related to a consistently or frequently failing test. kind/flake Categorizes issue or PR as related to a flaky test. lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. priority/important-longterm Important over the long term, but may not be staffed and/or may need multiple releases to complete.
Projects
None yet
Development

No branches or pull requests

6 participants