Make CrosVM Tast class return command output reliably |
|||
Issue descriptionThe vm.StartCrosVM Tast test occasionally times out; see e.g. http://stainless/browse/chromeos-autotest-results/213887491-chromeos-test/ : 2018/07/03 08:58:22 Started test vm.StartCrosVM 2018/07/03 08:58:29 [08:58:28.297] Waiting for VM to boot 2018/07/03 08:58:30 [08:58:29.371] VM booted 2018/07/03 08:59:25 [08:59:24.752] Error at bundle.go:210: Test timed out I think that the hang is happening while CrosVM.RunCommand is being run. WaitPrompt isn't watching the context for expiration, so it'll block indefinitely if the expected output isn't received. I have ideas about how to fix that, but this code seems fragile: func (r *CrosVM) WaitPrompt(ctx context.Context) (bool, *bytes.Buffer, error) { var output bytes.Buffer tee := io.TeeReader(r.stdout, &output) matched, err := regexp.MatchReader("localhost.+#", bufio.NewReader(io.LimitReader(tee, 16384))) if err != nil { return false, nil, err } return matched, &output, nil } After we write a command to crosvm's stdin, we read its stdout until we see "localhost.+#". When I run the vm.StartCrosVM test, which executes "/bin/ls /" and checks its output, the following is returned: "/bin/ls /\r\nbin dev home lib64\t media opt root\tsbin tmp var\r\nboot etc lib\t lost+found mnt proc run\tsys usr\r\n\x1b[01;31mlocalhost\x1b[01;34m / #\x1b[" There are issues here around buffering: - the returned output should probably be a []byte instead of a bytes.Buffer - it shouldn't include the prompt (actually, it includes just a partial prompt now) - it shouldn't leave some indeterminate part of the prompt in r.stdout like it does currently). This will also return early if the "localhost.+#" pattern appears in the command's output, and it'll break if the prompt is changed, and it seems like the stream will be left in a weird state if a command fails. Does crosvm expose another command-running interface that could be used instead? For example, is there any way to run a one-off process that just executes a single command in the VM and passes through stdin, stdout, and stderr?
,
Jul 9
Okay, that probably explains all the timeouts that I've been seeing. :-) Is there a bug tracking getting serial output working on those devices? If it's not on the verge of happening, do you mind if I disable the test until it's expected to pass everywhere where it runs? If there aren't any plans to improve the way that output is returned, I'd like to change CrosVM's interface to make it clearer that callers are just going to get a stream of everything that gets written to the console. Any objections to me doing that?
,
Jul 9
We probably won't get serial working this week, it's OK to disable them for now. I can't see a way to improve the output situation, it was kind of my last resort... If you can make it more clear, that would be great. Thanks Dan, Dylan
,
Jul 11
,
Jul 11
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/platform/tast-tests/+/c554ba224aa5116add7c2d0ac310e5dc9d2e71fc commit c554ba224aa5116add7c2d0ac310e5dc9d2e71fc Author: Daniel Erat <derat@chromium.org> Date: Wed Jul 11 19:13:09 2018 tast-tests: Make vm.StartCrosVM honor test timeout. Update the vm.StartCrosVM local test to fail if its deadline is reached before it sees the expected output from the VM. Also move stdout-parsing and command-running code out of the CrosVM type and instead export Stdin and Stdout methods that hopefully make it clearer that raw output is being returned. BUG= chromium:860348 TEST=test passes on eve and fails when expected output is changed or crosvm command is manually killed mid-run Change-Id: I29be5f6954c4dc9e7eae90f3482c50986ba12f4d Reviewed-on: https://chromium-review.googlesource.com/1132551 Commit-Ready: Dan Erat <derat@chromium.org> Tested-by: Dan Erat <derat@chromium.org> Reviewed-by: Dylan Reid <dgreid@chromium.org> [modify] https://crrev.com/c554ba224aa5116add7c2d0ac310e5dc9d2e71fc/src/chromiumos/tast/local/bundles/cros/vm/start_crosvm.go [modify] https://crrev.com/c554ba224aa5116add7c2d0ac310e5dc9d2e71fc/src/chromiumos/tast/local/vm/cros_vm.go
,
Jul 11
,
Jul 13
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/platform/tast-tests/+/dfe0c23fa59e02494c0484c49f86bef281b44580 commit dfe0c23fa59e02494c0484c49f86bef281b44580 Author: Daniel Erat <derat@chromium.org> Date: Fri Jul 13 09:22:29 2018 tast-tests: Improve stdout reading in vm.StartCrosVM. Fix a subtle issue in the vm.StartCrosVM test where the completion of the crosvm command could conceivably race with reading its output. I don't think this could actually happen in practice since crosvm doesn't get stopped until after the test has finished reading its output. BUG= chromium:860348 TEST=test still passes on eve Change-Id: I3990e736b0dda8589f3859f8b8f34739e03be8df Reviewed-on: https://chromium-review.googlesource.com/1134445 Commit-Ready: Dan Erat <derat@chromium.org> Tested-by: Dan Erat <derat@chromium.org> Reviewed-by: Dylan Reid <dgreid@chromium.org> [modify] https://crrev.com/dfe0c23fa59e02494c0484c49f86bef281b44580/src/chromiumos/tast/local/bundles/cros/vm/start_crosvm.go |
|||
►
Sign in to add a comment |
|||
Comment 1 by dgreid@chromium.org
, Jul 9