https://uberchromegw.corp.google.com/i/chromeos/builders/candy-release/builds/663

https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/90565051-chromeos-test/chromeos4-row8-rack3-host9/


The error reported in the waterfall corresponds to these lines in autoserv.DEBUG:


12/14 01:34:06.929 DEBUG|          ssh_host:0177| Running (ssh) 'rm -rf "/tmp/autoserv-ITdm4J"'
12/14 01:34:07.096 DEBUG|      abstract_ssh:0735| Nuking master_ssh_job.
12/14 01:34:08.102 DEBUG|      abstract_ssh:0741| Cleaning master_ssh_tempdir.
12/14 01:34:08.103 INFO |        server_job:0153| 	FAIL	autoupdate_EndToEndTest.npo_delta	autoupdate_EndToEndTest.npo_delta	timestamp=1481708048	localtime=Dec 14 01:34:08	Expected the updater to begin downloading (download_started) but received event type is different (rebooted_after_update). This could be an updater bug, crash or provisioning error; check the update_engine log (in sysinfo or on the DUT, also included in the test log). For a detailed log of update events, check the Omaha-devserver log (included in the test log).
12/14 01:34:08.104 INFO |        server_job:0153| END FAIL	autoupdate_EndToEndTest.npo_delta	autoupdate_EndToEndTest.npo_delta	timestamp=1481708048	localtime=Dec 14 01:34:08	


but sysinfo.tgz/.../update_engine.log reports this:


[1214/013006:INFO:libcurl_http_fetcher.cc(94)] Starting/Resuming transfer
[1214/013006:INFO:libcurl_http_fetcher.cc(106)] Using proxy: no
[1214/013006:INFO:libcurl_http_fetcher.cc(227)] Not setting http(s) curl options because we are running a dev/test image
[1214/013311:ERROR:libcurl_http_fetcher.cc(378)] Unable to get http response code.
[1214/013311:INFO:libcurl_http_fetcher.cc(397)] No HTTP response, retry 1
[1214/013321:INFO:libcurl_http_fetcher.cc(94)] Starting/Resuming transfer
[1214/013321:INFO:libcurl_http_fetcher.cc(106)] Using proxy: no
[1214/013321:INFO:libcurl_http_fetcher.cc(227)] Not setting http(s) curl options because we are running a dev/test image
[1214/013352:ERROR:libcurl_http_fetcher.cc(378)] Unable to get http response code.
[1214/013352:INFO:libcurl_http_fetcher.cc(410)] Transfer resulted in an error (0), 0 bytes downloaded
[1214/013352:INFO:libcurl_http_fetcher.cc(424)] No further proxies, indicating transfer complete
[1214/013352:INFO:omaha_request_action.cc(914)] Omaha request response: 
[1214/013352:ERROR:omaha_request_action.cc(926)] Omaha request network transfer failed.
[1214/013352:INFO:metrics.cc(142)] Sending 2 for metric UpdateEngine.Check.Result (enum)
[1214/013352:INFO:metrics.cc(155)] Sending 0 for metric UpdateEngine.Check.DownloadErrorCode (sparse)
[1214/013352:INFO:prefs.cc(41)] metrics-check-last-reporting-time not present in /var/lib/update_engine/prefs
[1214/013352:INFO:action_processor.cc(116)] ActionProcessor: finished OmahaRequestAction with code ErrorCode::kOmahaRequestHTTPResponseBase
[1214/013352:INFO:action_processor.cc(121)] ActionProcessor: Aborting processing due to failure.
[1214/013352:INFO:update_attempter.cc(903)] Processing Done.
[1214/013352:ERROR:update_attempter.cc(1327)] Update failed.
[1214/013352:INFO:utils.cc(874)] Converting error code 2000 to ErrorCode::kOmahaErrorInHTTPResponse
[1214/013352:INFO:payload_state.cc(247)] Updating payload state for error code: 37 (ErrorCode::kOmahaErrorInHTTPResponse)
[1214/013352:INFO:payload_state.cc(255)] Ignoring failures until we get a valid Omaha response.
[1214/013352:INFO:update_attempter.cc(1331)] Reporting the error event
[1214/013352:INFO:action_processor.cc(46)] ActionProcessor: starting OmahaRequestAction
[1214/013352:INFO:omaha_request_action.cc(654)] Posting an Omaha request to http://100.115.219.135:38353/update
[1214/013352:INFO:omaha_request_action.cc(655)] Request: <?xml version="1.0" encoding="UTF-8"?>
<request protocol="3.0" version="ChromeOSUpdateEngine-0.1.0.0" updaterversion="ChromeOSUpdateEngine-0.1.0.0" installsource="ondemandupdate" ismachine="1">
    <os version="Indy" platform="Chrome OS" sp="9085.0.0_x86_64"></os>
    <app appid="{BABC2E82-8F7D-26E5-EE66-4C60A2B41DBC}" version="9085.0.0" track="stable-channel" lang="en-US" board="candy" hardware_class="CANDY C2A-D4I-M6A-A3D" delta_okay="true" fw_version="" ec_version="" installdate="3633" >
        <event eventtype="3" eventresult="0" errorcode="805308368"></event>
    </app>
</request>

[1214/013352:INFO:libcurl_http_fetcher.cc(94)] Starting/Resuming transfer
[1214/013352:INFO:libcurl_http_fetcher.cc(106)] Using proxy: no
[1214/013352:INFO:libcurl_http_fetcher.cc(227)] Not setting http(s) curl options because we are running a dev/test image
[1214/013352:ERROR:libcurl_http_fetcher.cc(378)] Unable to get http response code.
[1214/013352:INFO:libcurl_http_fetcher.cc(410)] Transfer resulted in an error (0), 0 bytes downloaded
[1214/013352:INFO:libcurl_http_fetcher.cc(424)] No further proxies, indicating transfer complete
[1214/013352:INFO:omaha_request_action.cc(914)] Omaha request response: 
[1214/013352:INFO:action_processor.cc(116)] ActionProcessor: finished last action OmahaRequestAction with code ErrorCode::kSuccess
[1214/013352:INFO:update_attempter.cc(903)] Processing Done.
[1214/013352:INFO:update_attempter.cc(910)] Error event sent.


What is going on here?  The devserver chromeos4-devserver7 was pretty loaded at this time, with a lot of disk wait.

12:00:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
...
01:10:02 AM     all     74.22      0.00     12.86     10.40      0.00      2.51
01:15:02 AM     all     35.21      0.00      8.31     53.82      0.00      2.66
01:20:04 AM     all     35.70      0.06      8.05     52.91      0.00      3.28
01:25:01 AM     all     27.57      0.03      6.99     50.63      0.00     14.79
01:30:01 AM     all     47.16      0.00      8.26     39.29      0.00      5.29
01:35:03 AM     all     68.50      0.00     10.36     13.92      0.00      7.22
01:40:01 AM     all     75.55      0.00     11.21     12.70      0.00      0.55


12:00:01 AM       DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz     await     svctm     %util
...
01:10:02 AM  dev252-1     90.62    241.03    483.92      8.00     58.49    645.27      5.05     45.75
01:15:02 AM    dev8-0    420.02  78130.48  18096.02    229.10    203.96    490.71      2.38    100.00
01:15:02 AM  dev252-0    479.72  77985.22  17833.72    199.74    291.73    613.44      2.09    100.05
01:15:02 AM  dev252-1     33.82    115.84    154.70      8.00     28.03    802.67     27.92     94.42
01:20:04 AM    dev8-0    451.83  78934.07  22282.25    224.01    197.54    436.14      2.21    100.00
01:20:04 AM  dev252-0    500.83  78695.69  21935.44    200.93    228.69    454.28      2.00    100.04
01:20:04 AM  dev252-1     77.99    226.69    397.24      8.00     86.99   1120.32     12.82     99.99
01:25:01 AM    dev8-0    462.41  64789.79  44881.23    237.17    175.67    380.94      2.16    100.00
01:25:01 AM  dev252-0    507.05  64626.57  44663.61    215.54    204.76    404.37      1.97    100.06
01:25:01 AM  dev252-1     53.44    178.91    248.61      8.00     34.11    638.74     17.41     93.06
01:30:01 AM    dev8-0    425.79  79866.98  15544.87    224.08    122.02    288.60      2.35    100.01
01:30:01 AM  dev252-0    448.52  79569.52  15039.45    210.94    143.65    322.00      2.23    100.03
01:30:01 AM  dev252-1     63.91    277.08    234.17      8.00     33.33    520.76     15.65    100.00
01:35:03 AM    dev8-0    596.75  68050.25  14445.41    138.24     42.84     69.53      1.65     98.62
01:35:03 AM  dev252-0    633.09  67826.68  14639.50    130.26     54.17     82.89      1.56     98.47
01:35:03 AM  dev252-1     41.78    241.36     92.85      8.00      7.40    178.25     11.94     49.87
01:40:01 AM    dev8-0    523.43  65430.36  20222.41    163.64     85.66    166.18      1.89     98.72
01:40:01 AM  dev252-0    566.33  65325.25  19524.99    149.82    101.70    182.35      1.74     98.68
01:40:01 AM  dev252-1     60.57     77.17    407.42      8.00     38.76    639.80      6.28     38.04

so it's possible that it could not start serving the autoupdate.  The first two attempts ended with error 255, but the last attempt ended with no error, after transfering 0 bytes.  This may have caused the poor classification of this error.  I am suspecting a bug in update_engine.