Builder Windows Build 8922145182990558640

Results:

Success

Trigger Info:

Project	celab
Revision	8ab6d723213d3a557674970d62b48b42e425656e
Got Revision	8ab6d723213d3a557674970d62b48b42e425656e

Execution:

• Source: Task 42e2c3a5a6139b10
• Bot: win10-727f49a0-us-west1-b-v7lj
• Recipe: celab

Steps and Logfiles:

Show: Expanded Default Non-Green

1. ( 187 ms ) setup_build

   running recipe: "celab"
   • stdout
   • run_recipe
2. ( 151 ms ) init src_root if not exists
   • stdout
3. ( 12 secs ) bot_update

   [21GB/299GB used (7%)]
   • stdout
   • json.output
4. ( 261 ms ) gclient runhooks
   • stdout
5. ( 26 secs ) ensure_installed
   • stdout
   • json.output
6. ( 59 secs ) install deps
   • stdout
7. ( 44 secs ) build
   • stdout
8. ( 5 secs ) zip archive
   • stdout
9. ( 5 secs ) gsutil upload CELab binaries
   • stdout
   • CELab binaries
10. ( 0 ) recipe result
    • result

Build Properties:

Name	Value	Source
$recipe_engine/buildbucket	{"build": {"builder": {"bucket": "ci", "builder": "Windows", "project": "celab"}, "createTime": "2019-02-07T21:51:53.942376Z", "createdBy": "user:luci-scheduler@appspot.gserviceaccount.com", "id": "8922145182990558640", "infra": {"buildbucket": {"serviceConfigRevision": "ef156230f5cd7f8c23f689fa4dc7f92742cd904d"}, "recipe": {"cipdPackage": "infra/recipe_bundles/chromium.googlesource.com/chromium/tools/build", "name": "celab"}, "swarming": {"hostname": "chromium-swarm.appspot.com"}}, "input": {"gitilesCommit": {"host": "chromium.googlesource.com", "id": "8ab6d723213d3a557674970d62b48b42e425656e", "project": "enterprise/cel", "ref": "refs/heads/master"}}, "tags": [{"key": "builder", "value": "Windows"}, {"key": "buildset", "value": "commit/git/8ab6d723213d3a557674970d62b48b42e425656e"}, {"key": "buildset", "value": "commit/gitiles/chromium.googlesource.com/enterprise/cel/+/8ab6d723213d3a557674970d62b48b42e425656e"}, {"key": "scheduler_invocation_id", "value": "9087575245131094608"}, {"key": "scheduler_job_id", "value": "celab/Windows"}, {"key": "user_agent", "value": "luci-scheduler"}]}}	setup_build
$recipe_engine/path	{"cache_dir": "C:\\b\\s\\w\\ir\\cache", "temp_dir": "C:\\b\\s\\w\\ir\\tmp\\rt"}	setup_build
$recipe_engine/runtime	{"is_experimental": false, "is_luci": true}	setup_build
bot_id	"win10-727f49a0-us-west1-b-v7lj"	setup_build
branch	"refs/heads/master"	setup_build
buildbucket	{"build": {"bucket": "luci.celab.ci", "created_by": "user:luci-scheduler@appspot.gserviceaccount.com", "created_ts": 1549576313942376, "id": "8922145182990558640", "project": "celab", "tags": ["builder:Windows", "buildset:commit/git/8ab6d723213d3a557674970d62b48b42e425656e", "buildset:commit/gitiles/chromium.googlesource.com/enterprise/cel/+/8ab6d723213d3a557674970d62b48b42e425656e", "gitiles_ref:refs/heads/master", "scheduler_invocation_id:9087575245131094608", "scheduler_job_id:celab/Windows", "user_agent:luci-scheduler"]}, "hostname": "cr-buildbucket.appspot.com"}	setup_build
buildername	"Windows"	setup_build
path_config	"generic"	setup_build
recipe	"celab"	setup_build
repository	"https://chromium.googlesource.com/enterprise/cel.git"	setup_build
revision	"8ab6d723213d3a557674970d62b48b42e425656e"	setup_build
target_cpu	"x64"	setup_build
got_revision	"8ab6d723213d3a557674970d62b48b42e425656e"	bot_update

Blamelist:

1. Mathieu Binette (mbinetteohnoyoudont@google.com)

Timing:

Create	Thursday, 07-Feb-19 21:51:53 UTC
Start	Thursday, 07-Feb-19 21:52:07 UTC
End	Thursday, 07-Feb-19 21:55:33 UTC
Pending	13 secs
Execution	3 mins 25 secs

All Changes:

1. Fix RunCommand missing output lines bug

   Changed by	Mathieu Binette - mbinetteohnoyoudont@google.com
   Changed at	Thursday, 07-Feb-19 21:51:47 UTC
   Repository	https://chromium.googlesource.com/enterprise/cel
   Branch
   Revision	8ab6d723213d3a557674970d62b48b42e425656e

   Comments

   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>
   

   Changed files

   • go/gcp/run_command.go