{"action":"created","issue":{"url":"https://api.github.com/repos/coreos/rkt/issues/3091","repository_url":"https://api.github.com/repos/coreos/rkt","labels_url":"https://api.github.com/repos/coreos/rkt/issues/3091/labels{/name}","comments_url":"https://api.github.com/repos/coreos/rkt/issues/3091/comments","events_url":"https://api.github.com/repos/coreos/rkt/issues/3091/events","html_url":"https://github.com/coreos/rkt/issues/3091","id":171925713,"number":3091,"title":"TestRktStop on stage1-kvm often fails on SemaphoreCI","user":{"login":"lucab","id":98086,"avatar_url":"https://avatars.githubusercontent.com/u/98086?v=3","gravatar_id":"","url":"https://api.github.com/users/lucab","html_url":"https://github.com/lucab","followers_url":"https://api.github.com/users/lucab/followers","following_url":"https://api.github.com/users/lucab/following{/other_user}","gists_url":"https://api.github.com/users/lucab/gists{/gist_id}","starred_url":"https://api.github.com/users/lucab/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/lucab/subscriptions","organizations_url":"https://api.github.com/users/lucab/orgs","repos_url":"https://api.github.com/users/lucab/repos","events_url":"https://api.github.com/users/lucab/events{/privacy}","received_events_url":"https://api.github.com/users/lucab/received_events","type":"User","site_admin":false},"labels":[{"id":217486471,"url":"https://api.github.com/repos/coreos/rkt/labels/area/developer%20tooling","name":"area/developer tooling","color":"bfe5bf","default":false},{"id":151845917,"url":"https://api.github.com/repos/coreos/rkt/labels/component/stage1","name":"component/stage1","color":"0052cc","default":false},{"id":258834327,"url":"https://api.github.com/repos/coreos/rkt/labels/technology/kvm","name":"technology/kvm","color":"d4c5f9","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":3,"created_at":"2016-08-18T15:12:02Z","updated_at":"2016-12-02T12:27:47Z","closed_at":null,"body":"Recently we are seeing an increasing number of failure on SemaphoreCI, while testing stage1-kvm. They are failing on `TestRktStop`, as follows:\n\n```\n=== RUN   TestRktStop\n--- FAIL: TestRktStop (21.87s)\n    rkt_tests.go:115: Running command: /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 --insecure-options=image prepare /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/test-tmp/rkt-stop-test.aci\n    rkt_tests.go:115: Running command: /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 --insecure-options=image run-prepared --interactive b22e5d1a-2a14-44d5-add6-986757de1fbb\n    rkt_stop_test.go:92: Running test #0, /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 stop b22e5d1a-2a14-44d5-add6-986757de1fbb\n    rkt_tests.go:115: Running command: /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 stop b22e5d1a-2a14-44d5-add6-986757de1fbb\n    rkt_tests.go:115: Running command: /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 --insecure-options=image prepare /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/test-tmp/rkt-stop-test.aci\n    rkt_tests.go:115: Running command: /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 --insecure-options=image run-prepared --interactive ad47a77a-f0e7-4442-9bd1-f42afb50c009\n    rkt_stop_test.go:92: Running test #1, /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 stop --force ad47a77a-f0e7-4442-9bd1-f42afb50c009\n    rkt_tests.go:115: Running command: /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 stop --force ad47a77a-f0e7-4442-9bd1-f42afb50c009\n    rkt_tests.go:115: Running command: /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 --insecure-options=image prepare /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/test-tmp/rkt-stop-test.aci\n    rkt_tests.go:115: Running command: /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 --insecure-options=image run-prepared --interactive 0e3a3cb9-28c2-4832-872f-b321033252d6\n    rkt_stop_test.go:92: Running test #2, /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 stop --uuid-file=/tmp/rkt-TestRktStop-320355424/uuid-file630404159\n    rkt_tests.go:115: Running command: /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/tmp/functional/rkt --dir=/tmp/datadir-393981548 --local-config=/tmp/localdir-097164507 --system-config=/tmp/systemdir-476420222 --user-config=/tmp/userdir-881331141 stop --uuid-file=/tmp/rkt-TestRktStop-320355424/uuid-file630404159\n    rkt_stop_test.go:107: Expected pod \"0e3a3cb9-28c2-4832-872f-b321033252d6\" to be exited, but it is \"running\"\npanic: Failed to remove temporary data directory \"/tmp/datadir-393981548\": remove /tmp/datadir-393981548/pods/run/0e3a3cb9-28c2-4832-872f-b321033252d6/stage1/rootfs/sys: device or resource busy [recovered]\n    panic: Failed to remove temporary data directory \"/tmp/datadir-393981548\": remove /tmp/datadir-393981548/pods/run/0e3a3cb9-28c2-4832-872f-b321033252d6/stage1/rootfs/sys: device or resource busy\n\ngoroutine 418 [running]:\ntesting.tRunner.func1(0xc820396fc0)\n    /usr/local/go/src/testing/testing.go:450 +0x171\ngithub.com/coreos/rkt/tests/testutils.(*dirDesc).cleanup(0xc82020d640)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/tests/testutils/ctx.go:67 +0x27c\ngithub.com/coreos/rkt/tests/testutils.(*RktRunCtx).Cleanup(0xc82020d740)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/tests/testutils/ctx.go:179 +0x1be\nruntime.Goexit()\n    /usr/local/go/src/runtime/panic.go:320 +0xfb\ntesting.(*common).FailNow(0xc820396fc0)\n    /usr/local/go/src/testing/testing.go:336 +0x36\ntesting.(*common).Fatalf(0xc820396fc0, 0xc9e360, 0x2a, 0xc8203afe18, 0x2, 0x2)\n    /usr/local/go/src/testing/testing.go:379 +0x83\ngithub.com/coreos/rkt/tests.TestRktStop(0xc820396fc0)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/tests/rkt_stop_test.go:107 +0x1254\ntesting.tRunner(0xc820396fc0, 0x11734c8)\n    /usr/local/go/src/testing/testing.go:456 +0x98\ncreated by testing.RunTests\n    /usr/local/go/src/testing/testing.go:561 +0x86d\n\ngoroutine 1 [chan receive]:\ntesting.RunTests(0xd1e130, 0x1172c40, 0x60, 0x60, 0xbcfd01)\n    /usr/local/go/src/testing/testing.go:562 +0x8ad\ntesting.(*M).Run(0xc82003df08, 0xc820164686)\n    /usr/local/go/src/testing/testing.go:494 +0x70\nmain.main()\n    github.com/coreos/rkt/tests/_test/_testmain.go:276 +0x116\n\ngoroutine 17 [syscall, 31 minutes, locked to thread]:\nruntime.goexit()\n    /usr/local/go/src/runtime/asm_amd64.s:1721 +0x1\n\ngoroutine 156 [chan receive, 15 minutes]:\ngithub.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels.func2(0xc82002c860, 0xc8203bbe60, 0xc82002c868)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:177 +0x5e\ncreated by github.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:190 +0x127\n\ngoroutine 158 [chan receive, 15 minutes]:\ngithub.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels.func2(0xc82002c8d8, 0xc82057ec00, 0xc82002c8e0)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:177 +0x5e\ncreated by github.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:190 +0x127\n\ngoroutine 138 [chan receive, 15 minutes]:\ngithub.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels.func2(0xc820112188, 0xc820132db0, 0xc820112190)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:177 +0x5e\ncreated by github.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:190 +0x127\n\ngoroutine 170 [chan receive, 15 minutes]:\ngithub.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels.func2(0xc820106490, 0xc820550720, 0xc820106498)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:177 +0x5e\ncreated by github.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:190 +0x127\n\ngoroutine 168 [chan receive, 15 minutes]:\ngithub.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels.func2(0xc8201063e8, 0xc82038f6e0, 0xc8201063f0)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:177 +0x5e\ncreated by github.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:190 +0x127\n\ngoroutine 166 [chan receive, 15 minutes]:\ngithub.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels.func2(0xc820106360, 0xc82038e7b0, 0xc820106368)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:177 +0x5e\ncreated by github.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:190 +0x127\n\ngoroutine 160 [chan receive, 15 minutes]:\ngithub.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels.func2(0xc82002c960, 0xc82057fc50, 0xc82002c968)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:177 +0x5e\ncreated by github.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:190 +0x127\n\ngoroutine 140 [chan receive, 15 minutes]:\ngithub.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels.func2(0xc820112238, 0xc820133e30, 0xc820112240)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:177 +0x5e\ncreated by github.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).AsyncInteractChannels\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:190 +0x127\n\ngoroutine 354 [chan send]:\ngithub.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).expectTimeoutRegexFind.func2(0xdf8475800, 0xc8201109f0, 0xc788e0, 0x21, 0xc820224ed0, 0xc820015500)\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:239 +0x387\ncreated by github.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).expectTimeoutRegexFind\n    /home/runner/rkt/builds/build-rkt-kvm/build-rkt-1.13.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:240 +0x17c\nexit status 2\nFAIL    github.com/coreos/rkt/tests 1897.924s\n```\n\nOne such example is https://semaphoreci.com/coreos/rkt/branches/pull-request-3090/builds/1\n"},"comment":{"url":"https://api.github.com/repos/coreos/rkt/issues/comments/264443706","html_url":"https://github.com/coreos/rkt/issues/3091#issuecomment-264443706","issue_url":"https://api.github.com/repos/coreos/rkt/issues/3091","id":264443706,"user":{"login":"lucab","id":98086,"avatar_url":"https://avatars.githubusercontent.com/u/98086?v=3","gravatar_id":"","url":"https://api.github.com/users/lucab","html_url":"https://github.com/lucab","followers_url":"https://api.github.com/users/lucab/followers","following_url":"https://api.github.com/users/lucab/following{/other_user}","gists_url":"https://api.github.com/users/lucab/gists{/gist_id}","starred_url":"https://api.github.com/users/lucab/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/lucab/subscriptions","organizations_url":"https://api.github.com/users/lucab/orgs","repos_url":"https://api.github.com/users/lucab/repos","events_url":"https://api.github.com/users/lucab/events{/privacy}","received_events_url":"https://api.github.com/users/lucab/received_events","type":"User","site_admin":false},"created_at":"2016-12-02T12:27:47Z","updated_at":"2016-12-02T12:27:47Z","body":"@grahamwhaley semaphore logs get garbage collected after a while, but the full log is above. The main failure is:\r\n```\r\nrkt_stop_test.go:107: Expected pod \"0e3a3cb9-28c2-4832-872f-b321033252d6\" to be exited, but it is \"running\"\r\n```\r\n\r\nWhich means that the lvkm process on the host is still running for some reason (it holds a pod lock, thus the pod is still marked as running). My initial guess is that `systemctl halt` in the VM is failing, perhaps due to the thread limit above.\r\n\r\nHowever I also realized that the timeout for this test is not too high (5s), so I just raised it to 15s in https://github.com/coreos/rkt/pull/3434/commits/46e9c157d80261aef1eaea478f2277ab3b812042 to make sure it is not just a matter of bad timing."}}
{"actor":{"display_login":"lucab"}}