TestAppUserGroup panic: test timed out after 1h0m0s ((*ExpectSubprocess).Expect hangs)

[evverx]

Environment

./build-rkt-1.23.0+git/target/bin/rkt version
rkt Version: 1.23.0+git838818d
appc Version: 0.8.9
Go Version: go1.7.4
Go OS/Arch: linux/amd64
Features: -TPM +SDJOURNAL

Linux version 4.8.0-34-generic (buildd@lcy01-21) (gcc version 6.2.0 20161005 (Ubuntu 6.2.0-5ubuntu12) ) #36-Ubuntu SMP Wed Dec 21 17:24:18 UTC 2016

and

Linux version 4.9.5-200.fc25.x86_64 (mockbuild@bkernel02.phx2.fedoraproject.org) (gcc version 6.3.1 20161221 (Red Hat 6.3.1-1) (GCC) ) #1 SMP Fri Jan 20 12:24:16 UTC 2017

What did you do?

I'm trying to reproduce #3477

What did you expect to see?

#3477

What did you see instead?

=== RUN   TestAppUserGroup
panic: test timed out after 1h0m0s
...
goroutine 2853 [syscall]:
syscall.Syscall(0x0, 0x3, 0xc420140600, 0x52, 0x2d, 0x52, 0x0)
        /home/ubuntu/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.read(0x3, 0xc420140600, 0x52, 0x52, 0x2d, 0x0, 0x0)
        /home/ubuntu/go/src/syscall/zsyscall_linux_amd64.go:783 +0x55
syscall.Read(0x3, 0xc420140600, 0x52, 0x52, 0x2d, 0xc420030c00, 0x7fac59946000)
        /home/ubuntu/go/src/syscall/syscall_unix.go:161 +0x49
os.(*File).read(0xc42002e020, 0xc420140600, 0x52, 0x52, 0x55ebe93f049c, 0xc4201a4292, 0x6e)
        /home/ubuntu/go/src/os/file_unix.go:228 +0x4f
os.(*File).Read(0xc42002e020, 0xc420140600, 0x52, 0x52, 0x2d, 0x0, 0x0)
        /home/ubuntu/go/src/os/file.go:101 +0x59
github.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*buffer).Read(0xc42011c1e0, 0xc420140600, 0x52, 0x52, 0x7f, 0xc4201a4240, 0x52)
        /home/ubuntu/gopath/src/github.com/coreos/rkt/build-rkt-1.23.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:61 +0x86
github.com/coreos/rkt/vendor/github.com/coreos/gexpect.(*ExpectSubprocess).Expect(0xc420350090, 0x55ebe9a35770, 0x29, 0x55ebe9f43c58, 0x0)
        /home/ubuntu/gopath/src/github.com/coreos/rkt/build-rkt-1.23.0+git/gopath/src/github.com/coreos/rkt/vendor/github.com/coreos/gexpect/gexpect.go:320 +0x133
github.com/coreos/rkt/tests.expectCommon(0xc420350090, 0x55ebe9a35770, 0x29, 0x0, 0xc42004f828, 0xc42004f838)
        /home/ubuntu/gopath/src/github.com/coreos/rkt/build-rkt-1.23.0+git/gopath/src/github.com/coreos/rkt/tests/rkt_tests.go:62 +0x6a
github.com/coreos/rkt/tests.expectWithOutput(0xc420350090, 0x55ebe9a35770, 0x29, 0xc420350090, 0x0)
        /home/ubuntu/gopath/src/github.com/coreos/rkt/build-rkt-1.23.0+git/gopath/src/github.com/coreos/rkt/tests/rkt_tests.go:74 +0x48
github.com/coreos/rkt/tests.runRktAsUidGidAndCheckOutput(0xc4204792c0, 0xc42018c000, 0x20d, 0x55ebe9a35770, 0x29, 0x0, 0xfffe, 0x0)
        /home/ubuntu/gopath/src/github.com/coreos/rkt/build-rkt-1.23.0+git/gopath/src/github.com/coreos/rkt/tests/rkt_tests.go:367 +0x148
github.com/coreos/rkt/tests.runRktAsGidAndCheckOutput(0xc4204792c0, 0xc42018c000, 0x20d, 0x55ebe9a35770, 0x29, 0xc42018c000, 0x0)
        /home/ubuntu/gopath/src/github.com/coreos/rkt/build-rkt-1.23.0+git/gopath/src/github.com/coreos/rkt/tests/rkt_tests.go:343 +0x72
github.com/coreos/rkt/tests.runRktAndCheckOutput(0xc4204792c0, 0xc42018c000, 0x20d, 0x55ebe9a35770, 0x29, 0xc42018c000)
        /home/ubuntu/gopath/src/github.com/coreos/rkt/build-rkt-1.23.0+git/gopath/src/github.com/coreos/rkt/tests/rkt_tests.go:469 +0x65
github.com/coreos/rkt/tests.TestAppUserGroup.func1(0xc42004fbd8, 0xc42030bc01, 0xc42042af50, 0x70, 0xc4204792c0)
        /home/ubuntu/gopath/src/github.com/coreos/rkt/build-rkt-1.23.0+git/gopath/src/github.com/coreos/rkt/tests/rkt_run_user_group_test.go:121 +0x409
github.com/coreos/rkt/tests.TestAppUserGroup(0xc4204792c0)
        /home/ubuntu/gopath/src/github.com/coreos/rkt/build-rkt-1.23.0+git/gopath/src/github.com/coreos/rkt/tests/rkt_run_user_group_test.go:133 +0x3f7
testing.tRunner(0xc4204792c0, 0x55ebe9a80b00)
        /home/ubuntu/go/src/testing/testing.go:610 +0x81
created by testing.(*T).Run
        /home/ubuntu/go/src/testing/testing.go:646 +0x2ec

This looks like #3443

[lucab]

This looks like #3443

It is not exactly that (output draining and waiting seem to be fine there) but it is some other gexpect quirk. This test doesn't need any interactive/tty feature out of gexpect, so it can just be switched back to plain process spawning and output matching.