Looks like we're running into a problem with this in our larger test suites. For our tests, we configure an execution timeout (usually ~1 hr) and an I/O timeout (usually ~20min). If the test doesn't print anything to stdout/stderr within the I/O timeout, we assume it's frozen/hung and will kill it.

Since some of our tests run longer than 20min, and since cros_run_vm_test doesn't print anything to stdout until the cmd has finished, these tests are always assumed to be frozen and get killed.

There's a couple work-arounds (eg: bumping the timeout, printing dots while cmd is running) but I think simply streaming the stdout would work best and be more usable. I can try to take a stab at that. Hopefully it won't be too involved.

Note that we're currently planning to move VM testing in to Skylab next to the rest of the hardware testing area. That should happen within the next quarter.

Ben, do you know how to stream output, or have any examples of where this is done? I'll probably need to add this capability to RunCommand which is pretty basic primitive for chromeos python scripts:
https://cs.corp.google.com/chromeos_public/chromite/lib/cros_build_lib.py?l=626

Ah alright. I was assuming/hoping the actual invocation of the ssh cmd was ultimately a subprocess.Popen() call. If that's the case, passing stdout=sys.stdout would make it inherit the caller's stdout, which is what I was going for.

Now I see that that the RunCommand method has a massive signature, with a lot of stdout/stderr related args:
https://cs.corp.google.com/chromeos_public/chromite/lib/cros_build_lib.py?l=427

yikes...

Ya, I tried stdout_to_pipe, and that doesn't work as expected, but I have something working now that I can hopefully clean up.

RunCommand by default does write directly to stdout.  it's only when it's set to capture the output it does.  i don't know which RunCommand you're looking at, but at a glance, many are invoked with log_output=True which means we'll capturing things by design.

we generally avoid subprocess in chromite because it has a lot of rough edges/subtle bugs, and the RunCommand behavior is what most people actually want.

fair point re subprocess; we comically have several forks of in an attempt to smooth over those rough edges
https://codesearch.chromium.org/chromium/tools/depot_tools/subprocess2.py
https://codesearch.chromium.org/chromium/infra/luci/client/utils/subprocess42.py

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/chromite/+/5f638a1091fb0af2c5edacac2f51a9aa009a88c0

commit 5f638a1091fb0af2c5edacac2f51a9aa009a88c0
Author: Achuith Bhandarkar <achuith@chromium.org>
Date: Wed May 16 12:08:28 2018

cros_build_lib: Support for stream_log.

This allows for streaming output, useful for commands that take many
minutes to complete.

BUG= chromium:829481 
TEST=cros_run_vm_test --cmd -- /usr/local/autotest/bin/vm_sanity.py

Change-Id: I9dbf88e2f7e4bcdd9b2d49b83c94ae5b389534dd
Reviewed-on: https://chromium-review.googlesource.com/1055889
Commit-Ready: Achuith Bhandarkar <achuith@chromium.org>
Tested-by: Achuith Bhandarkar <achuith@chromium.org>
Reviewed-by: Don Garrett <dgarrett@chromium.org>

[modify] https://crrev.com/5f638a1091fb0af2c5edacac2f51a9aa009a88c0/lib/cros_build_lib.py
[modify] https://crrev.com/5f638a1091fb0af2c5edacac2f51a9aa009a88c0/lib/cros_build_lib_unittest.py
[modify] https://crrev.com/5f638a1091fb0af2c5edacac2f51a9aa009a88c0/scripts/cros_run_vm_test.py

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/0027ded864851cd26051500250f728cb222d6c4b

commit 0027ded864851cd26051500250f728cb222d6c4b
Author: chromite-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com <chromite-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Date: Wed May 16 13:33:07 2018

Roll src/third_party/chromite/ 4dc1da47a..5f638a109 (1 commit)

https://chromium.googlesource.com/chromiumos/chromite.git/+log/4dc1da47ad18..5f638a1091fb

$ git log 4dc1da47a..5f638a109 --date=short --no-merges --format='%ad %ae %s'
2018-05-11 achuith cros_build_lib: Support for stream_log.

Created with:
  roll-dep src/third_party/chromite
BUG= chromium:829481 


The AutoRoll server is located here: https://chromite-chromium-roll.skia.org

Documentation for the AutoRoller is here:
https://skia.googlesource.com/buildbot/+/master/autoroll/README.md

If the roll is causing failures, please contact the current sheriff, who should
be CC'd on the roll, and stop the roller if necessary.


TBR=chrome-os-gardeners@chromium.org

Change-Id: I8fe6389f7a40c78f33c032f752f75b819892d83e
Reviewed-on: https://chromium-review.googlesource.com/1061574
Commit-Queue: Chromite Chromium Autoroll <chromite-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Reviewed-by: Chromite Chromium Autoroll <chromite-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Cr-Commit-Position: refs/heads/master@{#559063}
[modify] https://crrev.com/0027ded864851cd26051500250f728cb222d6c4b/DEPS

Our longer-running tests are now getting their logs streamed and not getting I/O timed-out: https://chromium-swarm.appspot.com/user/task/3d825eda1bc6cc10.

Thanks Achuith!

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/chromite/+/8100779766e26dad90273664a621f2ec15c1b2c9

commit 8100779766e26dad90273664a621f2ec15c1b2c9
Author: Achuith Bhandarkar <achuith@chromium.org>
Date: Thu May 31 03:38:47 2018

cros_build_lib: Support for streaming output.

Replace stream_log implementation with implicit streaming output.

The previous approach combined stdout/stderr and logged line by line.
This approach allows the subprocess to use the parent's stdout/stderr streams,
and does this when stdout/stderr are not redirected (stderr may be
redirected to stdout)

We still need to use wait() instead of communicate(), since
communicate() buffers the output.

BUG= chromium:829481 
TEST=manual

Change-Id: I9270f9a27e454b7cedf525e4ee07cd3d606b9237
Reviewed-on: https://chromium-review.googlesource.com/1063329
Commit-Ready: Achuith Bhandarkar <achuith@chromium.org>
Tested-by: Achuith Bhandarkar <achuith@chromium.org>
Reviewed-by: Don Garrett <dgarrett@chromium.org>

[modify] https://crrev.com/8100779766e26dad90273664a621f2ec15c1b2c9/lib/cros_build_lib.py
[modify] https://crrev.com/8100779766e26dad90273664a621f2ec15c1b2c9/scripts/cros_vm.py
[modify] https://crrev.com/8100779766e26dad90273664a621f2ec15c1b2c9/lib/cros_build_lib_unittest.py
[modify] https://crrev.com/8100779766e26dad90273664a621f2ec15c1b2c9/scripts/cros_run_vm_test.py

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/ad1a7be150bfdce47f4967f32cd8130418102a29

commit ad1a7be150bfdce47f4967f32cd8130418102a29
Author: chromite-chromium-autoroll <chromite-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Date: Thu May 31 14:38:38 2018

Roll src/third_party/chromite a05ffcc..8100779 (2 commits)

https://chromium.googlesource.com/chromiumos/chromite.git/+log/a05ffcc..8100779


git log a05ffcc..8100779 --date=short --no-merges --format='%ad %ae %s'
2018-05-16 achuith@chromium.org cros_build_lib: Support for streaming output.
2018-05-30 xixuan@chromium.org upload_symbols: Fix api calls changed by swarming.client upgrade.

Created with:
  gclient setdep -r src/third_party/chromite@8100779

The AutoRoll server is located here: https://chromite-chromium-roll.skia.org

Documentation for the AutoRoller is here:
https://skia.googlesource.com/buildbot/+/master/autoroll/README.md

If the roll is causing failures, please contact the current sheriff, who should
be CC'd on the roll, and stop the roller if necessary.



BUG= chromium:829481 , chromium:808149 

TBR=chrome-os-gardeners@chromium.org

Change-Id: I500767e4f46b125265cf5dfcb9366b548520a7ef
Reviewed-on: https://chromium-review.googlesource.com/1080453
Reviewed-by: Chromite Chromium Autoroll <chromite-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Commit-Queue: Chromite Chromium Autoroll <chromite-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Cr-Commit-Position: refs/heads/master@{#563224}
[modify] https://crrev.com/ad1a7be150bfdce47f4967f32cd8130418102a29/DEPS

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/chromite/+/665a9b372e406de143ee2438869ef4443d63c4d6

commit 665a9b372e406de143ee2438869ef4443d63c4d6
Author: Achuith Bhandarkar <achuith@chromium.org>
Date: Sat Jun 02 00:44:45 2018

cros_run_vm_test: stream long running commands.

BUG= chromium:829481 
TEST=manual

Change-Id: I4683e8e2ac1f79866caf3313f2b48213376d6829
Reviewed-on: https://chromium-review.googlesource.com/1064708
Commit-Ready: Achuith Bhandarkar <achuith@chromium.org>
Tested-by: Achuith Bhandarkar <achuith@chromium.org>
Reviewed-by: Achuith Bhandarkar <achuith@chromium.org>

[modify] https://crrev.com/665a9b372e406de143ee2438869ef4443d63c4d6/scripts/cros_run_vm_test.py
[modify] https://crrev.com/665a9b372e406de143ee2438869ef4443d63c4d6/scripts/cros_vm.py

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/5e30abe6e3c20b2ee8eba0903eb2a0993cfa48ce

commit 5e30abe6e3c20b2ee8eba0903eb2a0993cfa48ce
Author: Chromite Chromium Autoroll <chromite-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Date: Sat Jun 02 02:10:40 2018

Roll src/third_party/chromite d606e64..c4db222 (6 commits)

https://chromium.googlesource.com/chromiumos/chromite.git/+log/d606e64..c4db222


git log d606e64..c4db222 --date=short --no-merges --format='%ad %ae %s'
2018-06-02 tbrindus@chromium.org deploy_chrome: add missing string format in NoChromiumSrcDir exception
2018-06-02 achuith@chromium.org cros_run_vm_test: stream long running commands.
2018-06-02 ayatane@chromium.org infra_stages: Build skylab-inventory
2018-06-02 dgarrett@google.com config_lib: Remove dead site specific code.
2018-06-02 dgarrett@google.com config_lib: Have tests use config_lib not cbuildbot_config.
2018-06-02 mortonm@chromium.org Adjust tester for shill group.


Created with:
  gclient setdep -r src/third_party/chromite@c4db222

The AutoRoll server is located here: https://chromite-chromium-roll.skia.org

Documentation for the AutoRoller is here:
https://skia.googlesource.com/buildbot/+/master/autoroll/README.md

If the roll is causing failures, please contact the current sheriff, who should
be CC'd on the roll, and stop the roller if necessary.



BUG= chromium:848437 , chromium:829481 ,chromium:845337, chromium:848020 , chromium:848020 ,chromium:649417
TBR=chrome-os-gardeners@chromium.org

Change-Id: If746ebf051296d3c05ede530501656a4339c8f10
Reviewed-on: https://chromium-review.googlesource.com/1083944
Reviewed-by: Chromite Chromium Autoroll <chromite-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Commit-Queue: Chromite Chromium Autoroll <chromite-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Cr-Commit-Position: refs/heads/master@{#563915}
[modify] https://crrev.com/5e30abe6e3c20b2ee8eba0903eb2a0993cfa48ce/DEPS

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/chromite/+/cc35c59154e32fa81b17303c007d46132b7a5da8

commit cc35c59154e32fa81b17303c007d46132b7a5da8
Author: Alec Thilenius <athilenius@google.com>
Date: Sat Jun 09 18:41:06 2018

Revert "cros_build_lib: Support for streaming output."

This reverts commit 8100779766e26dad90273664a621f2ec15c1b2c9.

Reason for revert: Suspected culprit for breaking the Chrome Informational Builders ( crbug.com/848811 )

Original change's description:
> cros_build_lib: Support for streaming output.
>
> Replace stream_log implementation with implicit streaming output.
>
> The previous approach combined stdout/stderr and logged line by line.
> This approach allows the subprocess to use the parent's stdout/stderr streams,
> and does this when stdout/stderr are not redirected (stderr may be
> redirected to stdout)
>
> We still need to use wait() instead of communicate(), since
> communicate() buffers the output.
>
> BUG= chromium:829481 
> TEST=manual
>
> Change-Id: I9270f9a27e454b7cedf525e4ee07cd3d606b9237
> Reviewed-on: https://chromium-review.googlesource.com/1063329
> Commit-Ready: Achuith Bhandarkar <achuith@chromium.org>
> Tested-by: Achuith Bhandarkar <achuith@chromium.org>
> Reviewed-by: Don Garrett <dgarrett@chromium.org>

Bug:  chromium:829481 
Change-Id: I74af87fe89f1c9729cdae937e948956ff3ed7785
Reviewed-on: https://chromium-review.googlesource.com/1091183
Commit-Ready: Jason Clinton <jclinton@chromium.org>
Tested-by: Alec Thilenius <athilenius@google.com>
Reviewed-by: Jason Clinton <jclinton@chromium.org>
Reviewed-by: Don Garrett <dgarrett@chromium.org>

[modify] https://crrev.com/cc35c59154e32fa81b17303c007d46132b7a5da8/lib/cros_build_lib.py
[modify] https://crrev.com/cc35c59154e32fa81b17303c007d46132b7a5da8/scripts/cros_vm.py
[modify] https://crrev.com/cc35c59154e32fa81b17303c007d46132b7a5da8/lib/cros_build_lib_unittest.py
[modify] https://crrev.com/cc35c59154e32fa81b17303c007d46132b7a5da8/scripts/cros_run_vm_test.py

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/chromite/+/bad755b5e1159f1a7775567f2f85ff7281e64187

commit bad755b5e1159f1a7775567f2f85ff7281e64187
Author: Achuith Bhandarkar <achuith@chromium.org>
Date: Sun Jun 10 22:09:28 2018

cros_run_vm_test: Fix breakage due to revert.

Revert of CL:1091183 broke cros_run_vm_test.

Use stream_log for stream_output.

BUG= chromium:829481 
TEST=manual

Change-Id: If562478245e8951ab42d2fbef4fe4a2ccc6a3fb9
Reviewed-on: https://chromium-review.googlesource.com/1094489
Commit-Ready: Achuith Bhandarkar <achuith@chromium.org>
Tested-by: Achuith Bhandarkar <achuith@chromium.org>
Reviewed-by: Achuith Bhandarkar <achuith@chromium.org>

[modify] https://crrev.com/bad755b5e1159f1a7775567f2f85ff7281e64187/scripts/cros_run_vm_test.py
[modify] https://crrev.com/bad755b5e1159f1a7775567f2f85ff7281e64187/scripts/cros_vm.py

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/chromite/+/668e9f0e56261b94021ccdb674afcdd5b0e1336a

commit 668e9f0e56261b94021ccdb674afcdd5b0e1336a
Author: Achuith Bhandarkar <achuith@chromium.org>
Date: Fri Jul 20 12:31:23 2018

cros_build_lib: Remove stream_log.

BUG= chromium:829481 
TEST=unittests
Change-Id: Iad32dcc6737a2f5cddc982a718b0d91cf3f7d726
Reviewed-on: https://chromium-review.googlesource.com/1144423
Commit-Ready: Achuith Bhandarkar <achuith@chromium.org>
Tested-by: Achuith Bhandarkar <achuith@chromium.org>
Reviewed-by: Don Garrett <dgarrett@chromium.org>

[modify] https://crrev.com/668e9f0e56261b94021ccdb674afcdd5b0e1336a/lib/cros_build_lib.py
[modify] https://crrev.com/668e9f0e56261b94021ccdb674afcdd5b0e1336a/lib/cros_build_lib_unittest.py