hyper::test::execvm() test failure

[bergwolf]

reported by Hykins at http://ci.hypercontainer.io:8080/job/hyperd-auto/249/console

test case:

148 hyper::test::execvm() {
149   echo "Pod execvm echo test"
150   id=$(sudo hyperctl run -d busybox /bin/sh | sed -ne "s/POD id is \(.*\)/\1/p")
151   echo "test pod ID is $id"
152   res=$(sudo hyperctl exec -m $id /sbin/busybox sh -c "echo aaa")
153   echo "should return aaa, actual: $res"
154   test $res == aaa
155   sudo hyperctl rm $id
156 }

exec succeeded.

04:00:34 I0317 04:00:33.958069    7148 json.go:316] ProcessAsyncEvent: %s{"container":"hyperstart","process":"hyperstart-exec-OlJNvDceBK","event":"finished","status":0}

but no result was returned.

should return aaa, actual: 

[gnawux]

Is this stable repeated or randomly occurred?

[bergwolf]

It is random. Only saw it once. May relate to vm shutdown timing.

[gnawux]

got a similar log: log-vm-exec-failed.txt

[gnawux]

I0403 02:45:17.335797   23544 vm.go:194] SB[vm-QBHwitcBNN] got shut down msg, acked here
I0403 02:45:17.335819   23544 vm.go:498] hyperstart-exec "hyperstart-exec-SXlePMVCXt" terminated at 2017-04-03 02:45:17.335755185 +0000 UTC with code 0
I0403 02:45:17.335887   23544 json.go:401] tty: read 4 bytes for stream 3
I0403 02:45:17.335944   23544 vm_states.go:106] Close tty 
I0403 02:45:17.336256   23544 vm_console.go:46] SB[vm-QBHwitcBNN] [CNL] hyper_handle_exec_exit exec exit pid 334, seq 3, container hyperstart
I0403 02:45:17.336266   23544 json.go:401] tty: read 0 bytes for stream 3
I0403 02:45:17.336273   23544 json.go:414] session 3 closed by peer, close pty
I0403 02:45:17.336303   23544 json.go:504] session 3 send eof to hyperstart

looks stream bytes have been received by hyperd, but not output to client.

[gnawux]

The issue is comes from here: https://github.com/hyperhq/runv/blame/master/hypervisor/vm_states.go#L129

The tty.Close() is called earlier than the out stream end.

[gnawux]

The exec vm is very simple:

func (p *XPod) ExecVM(cmd string, stdin io.ReadCloser, stdout, stderr io.WriteCloser) (int, error) {
	return p.sandbox.HyperstartExec(cmd, &hypervisor.TtyIO{
		Stdin:  stdin,
		Stdout: stdout,
		Stderr: stderr,
	})
}

right after the the process is end, it will return and this may interrupt the hijack stream even there are still data on their way.

[laijs]

it was auto closed when #581 was merged. Reopen it until it is confirmed fixed.