Recently, I made a change to add a WaitUntilReady method for the HWTest stages and move the appropriate logic in there. As a side effect, the log output now differs and can be confusing.

Previously, the stdio of the HWTest stage would look like this:

@@@BUILD_STEP@HWTest [sanity]@@@
************************************************************
** Start Stage HWTest [sanity] - Mon, 29 Aug 2016 12:48:23 -0700 (PDT)
** 
** Stage that runs tests in the Autotest lab.
************************************************************
12:48:23: INFO: Waiting up to forever for payloads ...
12:53:02: INFO: RunCommand: /b/cbuild/internal_master/chromite/third_party/swarming.client/swarming.py run
[..snip..]


But now, it looks like this:

@@@BUILD_STEP@HWTest [sanity]@@@
************************************************************
** Start Stage HWTest [sanity] - Mon, 05 Sep 2016 20:49:08 -0700 (PDT)
** 
** Stage that runs tests in the Autotest lab.
************************************************************
20:49:08: INFO: RunCommand: /b/cbuild/internal_master/chromite/third_party/swarming.client/swarming.py run
[..snip..]
21:07:25: INFO: cidb query succeeded after 1 retries
21:07:25: INFO: Running cidb query on pid 12642, repr(query) starts with <sqlalchemy.sql.expression.Update object at 0x7f071605b810>
************************************************************
** Finished Stage HWTest [sanity] - Mon, 05 Sep 2016 21:07:25 -0700 (PDT)
************************************************************
21:07:25: INFO: Running cidb query on pid 11985, repr(query) starts with <sqlalchemy.sql.expression.Insert object at 0x7f0716048e50>
21:07:25: WARNING: <class 'sqlalchemy.exc.OperationalError'>((OperationalError) (2006, 'MySQL server has gone away') 'INSERT INTO `buildStageTable` (build_id, name, board, status) VALUES (%s, %s, %s, %s)' (1045094, 'HWTest [bvt-inline]', 'auron_yuna', 'planned'))
21:07:29: INFO: cidb query succeeded after 1 retries
21:07:29: INFO: Running cidb query on pid 11985, repr(query) starts with <sqlalchemy.sql.expression.Insert object at 0x7f0716050710>
21:07:29: INFO: Created cidb engine bot@173.194.81.53 for pid 18623
21:07:29: INFO: Running cidb query on pid 18623, repr(query) starts with <sqlalchemy.sql.expression.Update object at 0x7f07163627d0>
21:07:30: INFO: Waiting up to forever for payloads and test artifacts ...
21:07:30: INFO: Running cidb query on pid 18623, repr(query) starts with <sqlalchemy.sql.expression.Update object at 0x7f0716048950>


Basically, the info log message about "Waiting up to forever for payloads" is now printed after the end of the stage.

And actually, I think that log message belongs to the *next* stage because of the timestamps. The suite shouldn't have been created until after WaitUntilReady() returned True. Examining the steps stdio shows that.

21:02:36: INFO: cidb query succeeded after 1 retries
************************************************************
** Finished Stage Archive - Mon, 05 Sep 2016 21:02:36 -0700 (PDT)
************************************************************
20:41:27: INFO: Created cidb engine bot@173.194.81.53 for pid 11985
20:41:27: INFO: Running cidb query on pid 11985, repr(query) starts with <sqlalchemy.sql.expression.Insert object at 0x7f0714f29ed0>
20:41:27: INFO: Created cidb engine bot@173.194.81.53 for pid 12642
20:41:27: INFO: Running cidb query on pid 12642, repr(query) starts with <sqlalchemy.sql.expression.Update object at 0x7f07163627d0>
20:41:28: INFO: Waiting up to forever for payloads and test artifacts ...
20:49:03: INFO: Running cidb query on pid 12642, repr(query) starts with <sqlalchemy.sql.expression.Update object at 0x7f071603fa50>
20:49:03: WARNING: <class 'sqlalchemy.exc.OperationalError'>((OperationalError) (2006, 'MySQL server has gone away') 'UPDATE `buildStageTable` SET status=%s, start_time=CURRENT_TIMESTAMP WHERE `buildStageTable`.id = %s' ('inflight', 29046774L))
20:49:08: INFO: cidb query succeeded after 1 retries

@@@BUILD_STEP@HWTest [sanity]@@@
************************************************************
** Start Stage HWTest [sanity] - Mon, 05 Sep 2016 20:49:08 -0700 (PDT) 
[..snip..]