commit 8ab6d723213d3a557674970d62b48b42e425656e
author Mathieu Binette <mbinette@google.com> Thu Feb 07 01:02:29 2019
committer Mathieu Binette <mbinette@google.com> Thu Feb 07 21:51:47 2019
tree 41bfb84e70902b93d205f56267ad15c93ab96a5d
parent aa9afbeac64c61a841f2401db4c897510bfb1af7

Fix RunCommand missing output lines bug

There's an intermittent bug where RunCommand returns incomplete output.
This can lead to flaky tests depending on if that missing output is critical.

ex: https://ci.chromium.org/p/celab/builders/luci.celab.ci/Linux/b8922309052533242736

^ This test was missing the <title> line for one of our `Invoke-WebRequest`.

Looking at the instance & StackDriver logs for that test, missing lines were
logged normally and in the right order. StackDriver timestamps also looked OK.

I tried to get a repro with this powershell command:
```
  for ($i = 0; $i -lt %s; $i++) {
    Write-Host "This is line #$i"
  }
```

Most of the time, this works fine. However, about 1/20 times, we see a gap.
In one of those instance, we got the following batches from StackDriver:
[3 seconds between reads]
- nofilter: []
- nofilter: []
- nofilter: [0-43]
- InsertId > 43: [45-<end>]

And we missed line #44.

This is confusing because the StackDriver APIs promise to [return logs sorted by (Time,InsertID)](https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry).

However, it does not promise in-order log visibility.

I already knew there was some weird buffering there, but adding more traces
showed this interesting scenario (3s between reads):
[3 seconds between reads]
- nofilter: []
- nofilter: []
- nofilter: [0-9]
- InsertId > 9: [11-<end>]
- InsertId > 9: [11-<end>]
- InsertId > 9: [10-<end>]

Where we would've missed out on 10 had we not waited for it.

Thankfully, gaps in our logs are easy to identify, so I added some code to wait
for expected InsertIds when we can.
I considered adding a time out, printing "[missing lines N-M]" and succeeding
the command when a line is 100% missing, but decided against it.
I've never seen such a case so far and I'd be interested in debugging that if
it happened. Clearly failing RunCommand in this case will make it easier to
find/fix this bug (if it exists) rather than silently succeed after N seconds.

Tested with the IISSitesTest on an infinite loop until I got a [8-<end>] fetch
which would've failed the test (like in the failed CI), but actually succeeded
after the 4th stackdriver refetch.

Change-Id: Id50ea1682d3e7cdbe664882b915d5c9b6c0e60d9
Reviewed-on: https://chromium-review.googlesource.com/c/1457306
Reviewed-by: Fei Ling <feiling@chromium.org>