Issue metadata
Sign in to add a comment
|
Panther is failing autoupdate_EndToEndTest_paygen_au_beta_delta_11151.59.0 test |
||||||||||||||||||||||
Issue description
Panther is failing autoupdate_EndToEndTest_paygen_au_beta_delta_11151.59.0 test
Sample failure:
Traceback (most recent call last):
File "/usr/local/autotest/client/common_lib/test.py", line 800, in _call_test_function
return func(*args, **dargs)
File "/usr/local/autotest/client/common_lib/test.py", line 464, in execute
postprocess_profiled_run, args, dargs)
File "/usr/local/autotest/client/common_lib/test.py", line 371, in _call_run_once
self.run_once(*args, **dargs)
File "/usr/local/autotest/server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py", line 381, in run_once
self.run_update_test(cros_device, test_conf)
File "/usr/local/autotest/server/site_tests/autoupdate_EndToEndTest/autoupdate_EndToEndTest.py", line 316, in run_update_test
'target_payload_uri'])
File "/usr/local/autotest/server/cros/update_engine/chromiumos_test_platform.py", line 147, in install_target_image
return self._install_version(target_payload_uri)
File "/usr/local/autotest/server/cros/update_engine/chromiumos_test_platform.py", line 53, in _install_version
clobber_stateful=clobber_stateful)
File "/usr/local/autotest/client/common_lib/cros/dev_server.py", line 2505, in auto_update
error_msg % (host_name, real_error))
DevServerException: CrOS auto-update failed for host chromeos4-row9-rack3-host14: 0) RootfsUpdateError: Failed to perform rootfs update: RootfsUpdateError('Update failed with unexpected update status: UPDATE_STATUS_IDLE',), 1) RootfsUpdateError: Failed to perform rootfs update: RootfsUpdateError('Update failed with unexpected update status: UPDATE_STATUS_IDLE',)
01/07 04:08:15.121 INFO | server_job:0217| END FAIL autoupdate_EndToEndTest.paygen_au_beta_delta autoupdate_EndToEndTest.paygen_au_beta_delta timestamp=1
stainless link:
https://stainless.corp.google.com/search?exclude_retried=false&first_date=2018-12-30&master_builder_name=&builder_name_number=&shard=&exclude_acts=true&builder_name=&master_builder_name_number=&owner=chromeos-test&retry=&exclude_cts=false&exclude_non_production=false&hostname=&board=panther&branch=&test=%5Eautoupdate_EndToEndTest_paygen_au_beta_delta_11151%5C.59%5C.0%24&suite=%5CQpaygen_au_beta%5CE&build=%5ER72%5C-11316%5C.66%5C.0%24&status=FAIL&status=ERROR&status=ABORT&reason=&waterfall=&exclude_not_run=false&last_date=2019-01-13&exclude_non_release=true&exclude_au=false&model=&view=list
,
Jan 10
+dhaddock who should own this bug?
,
Jan 10
Looking at both failures The first fails with this error in update_engine.log [0107/034330:WARNING:delta_performer.cc(548)] Ignoring metadata signature validation failures [0107/034330:INFO:delta_performer.cc(801)] Converting update information from old format. [0107/034330:INFO:delta_performer.cc(447)] PartitionInfo old root sha256: qfBMyDXZBkI8xrkXRjve12GHsNYdrLWeg5AnS6+q3GE= size: 1300234240 [0107/034330:INFO:delta_performer.cc(447)] PartitionInfo new root sha256: PWxPycryAzgd6Qg3ihmrA01HYDB0rJWwde1VYYz5iyI= size: 1300234240 [0107/034330:INFO:delta_performer.cc(447)] PartitionInfo old kernel sha256: r2T0NW+/LWUftfyMxtYRRNNmjfAEs2OgV4gR6UuxgeY= size: 16777216 [0107/034330:INFO:delta_performer.cc(447)] PartitionInfo new kernel sha256: /zX2j30uHkv5kASOvPQ8F+CZmZLFgNc/FYj7WhUUvyc= size: 16777216 [0107/034330:INFO:delta_performer.cc(381)] Opening /dev/sda5 partition without O_DSYNC [0107/034330:INFO:delta_performer.cc(125)] Caching writes. [0107/034330:INFO:delta_performer.cc(393)] Applying 8394 operations to partition "root" [0107/034331:INFO:delta_performer.cc(647)] Starting to apply update payload operations [0107/034339:INFO:delta_performer.cc(209)] Completed 1177/8406 operations (14%), 6635257/93884328 bytes downloaded (7%), overall progress 10% [0107/034349:INFO:delta_performer.cc(209)] Completed 2513/8406 operations (29%), 11271929/93884328 bytes downloaded (12%), overall progress 20% [0107/034350:ERROR:utils.cc(306)] rc >= 0 failed: Input/output error [0107/034350:ERROR:extent_reader.cc(82)] utils::PReadAll( fd_, bytes + bytes_read, bytes_to_read, cur_extent_->start_block() * block_size_ + cur_extent_bytes_read_, &out_bytes_read) failed. [0107/034350:ERROR:file_descriptor_utils.cc(56)] reader.Read(buf.data(), read_blocks * block_size) failed. [0107/034350:ERROR:delta_performer.cc(1036)] The hash of the source data on disk for this operation doesn't match the expected value. This could mean that the delta update payload was targeted for another version, or that the source partition was modified after it was installed, for example, by mounting a filesystem. [0107/034350:ERROR:delta_performer.cc(1041)] Expected: sha256|hex = 3CCCAA179FB9B71E7439376883E882041C1240382BFC9DD0481008F451CBA5AA [0107/034350:ERROR:delta_performer.cc(1044)] Calculated: sha256|hex = [0107/034350:ERROR:delta_performer.cc(1055)] Operation source (offset:size) in blocks: 274770:16,18384:48,6956:1,7077:32,7219:31,17024:128,7503:1,15140:44,7971:19,8214:32,8722:1,10899:32,16645:11,11359:32,11815:20,17152:64,18432:512,19456:969 [0107/034350:WARNING:mount_history.cc(66)] Device was remounted R/W 5 times. Last remount happened on 2018-12-11 10:13:42.000 UTC. [0107/034350:ERROR:delta_performer.cc(1334)] source_fd != nullptr failed. [0107/034350:ERROR:delta_performer.cc(297)] Failed to perform BROTLI_BSDIFF operation 2632, which is the operation 2632 in partition "root" [0107/034350:ERROR:download_action.cc(337)] Error ErrorCode::kDownloadStateInitializationError (20) in DeltaPerformer's Write method when processing the received payload -- Terminating processing [0107/034359:INFO:delta_performer.cc(313)] Discarding 17534 unused downloaded bytes [0107/034359:INFO:multi_range_http_fetcher.cc(173)] Received transfer terminated. [0107/034359:INFO:multi_range_http_fetcher.cc(125)] TransferEnded w/ code 206 [0107/034359:INFO:multi_range_http_fetcher.cc(127)] Terminating. [0107/034359:INFO:prefs.cc(122)] delta-update-failures not present in /var/lib/update_engine/prefs [0107/034359:INFO:action_processor.cc(116)] ActionProcessor: finished DownloadAction with code ErrorCode::kDownloadStateInitializationError [0107/034359:INFO:action_processor.cc(121)] ActionProcessor: Aborting processing due to failure. [0107/034359:INFO:update_attempter.cc(956)] Processing Done. [0107/034359:INFO:cpu_limiter.cc(71)] Setting cgroup cpu shares to 1024 [0107/034359:INFO:cpu_limiter.cc(79)] CPU shares = 1024 [0107/034359:ERROR:update_attempter.cc(1367)] Update failed. [0107/034359:INFO:payload_state.cc(257)] Updating payload state for error code: 20 (ErrorCode::kDownloadStateInitializationError)
,
Jan 10
The second failure was different. It actually finished downloading the payload then failed.
[0107/040155:INFO:delta_performer.cc(209)] Completed 4087/8406 operations (48%), 30047993/93884328 bytes downloaded (32%), overall progress 40%
[0107/040206:INFO:delta_performer.cc(209)] Completed 5548/8406 operations (66%), 32882425/93884328 bytes downloaded (35%), overall progress 50%
[0107/040213:INFO:delta_performer.cc(209)] Completed 6493/8406 operations (77%), 41320185/93884328 bytes downloaded (44%), overall progress 60%
[0107/040215:INFO:delta_performer.cc(209)] Completed 7085/8406 operations (84%), 52575993/93884328 bytes downloaded (56%), overall progress 70%
[0107/040215:INFO:delta_performer.cc(209)] Completed 7085/8406 operations (84%), 71368441/93884328 bytes downloaded (76%), overall progress 80%
[0107/040240:INFO:delta_performer.cc(209)] Completed 7902/8406 operations (94%), 82460409/93884328 bytes downloaded (87%), overall progress 90%
[0107/040254:INFO:delta_performer.cc(381)] Opening /dev/sda2 partition without O_DSYNC
[0107/040254:INFO:delta_performer.cc(125)] Caching writes.
[0107/040254:INFO:delta_performer.cc(393)] Applying 12 operations to partition "kernel"
[0107/040254:INFO:delta_performer.cc(209)] Completed 8406/8406 operations (100%), 93884328/93884328 bytes downloaded (100%), overall progress 100%
[0107/040254:INFO:multi_range_http_fetcher.cc(112)] Terminating transfer.
[0107/040254:INFO:multi_range_http_fetcher.cc(173)] Received transfer terminated.
[0107/040254:INFO:multi_range_http_fetcher.cc(125)] TransferEnded w/ code 206
[0107/040254:INFO:multi_range_http_fetcher.cc(159)] Done w/ all transfers
[0107/040254:INFO:delta_performer.cc(1680)] Verifying payload using public key: /usr/share/update_engine/update-payload-key.pub.pem
[0107/040254:WARNING:delta_performer.cc(1698)] Not verifying signed delta payload -- missing public key.
[0107/040254:INFO:payload_state.cc(158)] Payload downloaded successfully
[0107/040254:INFO:metrics_utils.cc(350)] Payload Attempt Number = 1
[0107/040254:INFO:payload_state.cc(454)] Not incrementing payload attempt number for delta payloads
[0107/040254:INFO:download_action.cc(401)] Collections of histograms for UpdateEngine.DownloadAction.
Histogram: UpdateEngine.DownloadAction.InstallOperation::REPLACE.Duration recorded 538 samples, average = 4.6
0 ------------------------------------------------------------------------O (499 = 92.8%)
10 --O (15 = 2.8%) {92.8%}
18 -O (10 = 1.9%) {95.5%}
32 -O (4 = 0.7%) {97.4%}
57 O (3 = 0.6%) {98.1%}
101 -O (5 = 0.9%) {98.7%}
179 O (1 = 0.2%) {99.6%}
317 O (1 = 0.2%) {99.8%}
561 ...
Histogram: UpdateEngine.DownloadAction.InstallOperation::SOURCE_BSDIFF.Duration recorded 4541 samples, average = 7.9
0 ------------------------------------------------------------------------O (4231 = 93.2%)
10 ---O (189 = 4.2%) {93.2%}
18 -O (66 = 1.5%) {97.3%}
32 O (26 = 0.6%) {98.8%}
57 O (9 = 0.2%) {99.4%}
101 O (11 = 0.2%) {99.6%}
179 O (3 = 0.1%) {99.8%}
317 O (4 = 0.1%) {99.9%}
561 O (0 = 0.0%) {100.0%}
993 O (1 = 0.0%) {100.0%}
1758 ...
5509 O (1 = 0.0%) {100.0%}
9752 ...
Histogram: UpdateEngine.DownloadAction.InstallOperation::SOURCE_COPY.Duration recorded 2456 samples, average = 15.3
0 ------------------------------------------------------------------------O (2170 = 88.4%)
10 ----O (125 = 5.1%) {88.4%}
18 -----O (154 = 6.3%) {93.4%}
32 O (5 = 0.2%) {99.7%}
57 ...
5509 O (1 = 0.0%) {99.9%}
9752 O (1 = 0.0%) {100.0%}
17262 ...
Histogram: UpdateEngine.DownloadAction.InstallOperation::ZERO_OR_DISCARD.Duration recorded 871 samples, average = 1.5
0 ------------------------------------------------------------------------O (830 = 95.3%)
10 -O (10 = 1.1%) {95.3%}
18 --O (23 = 2.6%) {96.4%}
32 -O (7 = 0.8%) {99.1%}
57 O (1 = 0.1%) {99.9%}
101 ...
[0107/040254:INFO:action_processor.cc(116)] ActionProcessor: finished DownloadAction with code ErrorCode::kSuccess
[0107/040254:INFO:action_processor.cc(143)] ActionProcessor: starting OmahaRequestAction
[0107/040254:INFO:omaha_request_action.cc(817)] Posting an Omaha request to http://127.0.0.1:51755/update/pregenerated
[0107/040254:INFO:omaha_request_action.cc(818)] 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="11151.59.0_x86_64"></os>
<app appid="{C0E4276B-35C7-023D-BB4A-42D642B91E65}" version="11151.59.0" track="stable-channel" lang="en-US" board="panther" hardware_class="PANTHER F5I-N22" delta_okay="true" fw_version="" ec_version="" installdate="4389" >
<event eventtype="14" eventresult="1"></event>
</app>
</request>
[0107/040254:ERROR:object_proxy.cc(580)] Failed to call method: org.chromium.NetworkProxyServiceInterface.ResolveProxy: object_path= /org/chromium/NetworkProxyService: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.NetworkProxyService was not provided by any .service files
[0107/040254:ERROR:http_proxy.cc(28)] org.chromium.NetworkProxyService D-Bus call to ResolveProxy failed
[0107/040254:INFO:libcurl_http_fetcher.cc(146)] Starting/Resuming transfer
[0107/040254:INFO:libcurl_http_fetcher.cc(165)] Using proxy: no
[0107/040254:INFO:libcurl_http_fetcher.cc(286)] Not setting http(s) curl options because we are running a dev/test image
[0107/040255:INFO:libcurl_http_fetcher.cc(433)] HTTP response code: 200
[0107/040255:INFO:libcurl_http_fetcher.cc(509)] Transfer completed (200), 253 bytes downloaded
[0107/040255:INFO:omaha_request_action.cc(1165)] Omaha request response: <?xml version="1.0" encoding="UTF-8"?>
<response protocol="3.0">
<daystart elapsed_seconds="14575"/>
<app appid="{C0E4276B-35C7-023D-BB4A-42D642B91E65}" status="ok">
<ping status="ok"/>
<event status="ok"/>
</app>
</response>
[0107/040255:INFO:omaha_request_action.cc(1849)] Rollback is not enabled for consumer devices.
[0107/040255:INFO:omaha_request_action.cc(1892)] Rollback is disabled. Setting kernel_max_rollforward to -2
[0107/040255:INFO:metrics_reporter_omaha.cc(609)] Sending 65537 for metric UpdateEngine.KernelKey.MinVersion
[0107/040255:INFO:metrics_reporter_omaha.cc(614)] Sending -2 for metric UpdateEngine.KernelKey.MaxRollforwardVersion
[0107/040255:INFO:metrics_reporter_omaha.cc(619)] Sending 1 for metric UpdateEngine.KernelKey.MaxRollforwardSetSuccess (bool)
[0107/040255:INFO:action_processor.cc(116)] ActionProcessor: finished OmahaRequestAction with code ErrorCode::kSuccess
[0107/040255:INFO:action_processor.cc(143)] ActionProcessor: starting FilesystemVerifierAction
[0107/040255:INFO:filesystem_verifier_action.cc(104)] Hashing partition 0 (root) on device /dev/sda3
[0107/040255:ERROR:file_stream.cc(463)] ReadNonBlocking(...): Domain=system, Code=EIO, Message=Input/output error
[0107/040255:ERROR:filesystem_verifier_action.cc(147)] Unable to schedule an asynchronous read from the stream.
[0107/040255:INFO:prefs.cc(122)] delta-update-failures not present in /var/lib/update_engine/prefs
[0107/040255:INFO:action_processor.cc(116)] ActionProcessor: finished FilesystemVerifierAction with code ErrorCode::kError
[0107/040255:INFO:action_processor.cc(121)] ActionProcessor: Aborting processing due to failure.
[0107/040255:INFO:update_attempter.cc(956)] Processing Done.
[0107/040255:INFO:cpu_limiter.cc(71)] Setting cgroup cpu shares to 1024
[0107/040255:INFO:cpu_limiter.cc(79)] CPU shares = 1024
[0107/040255:ERROR:update_attempter.cc(1367)] Update failed.
[0107/040255:INFO:payload_state.cc(257)] Updating payload state for error code: 47 (ErrorCode::kFilesystemVerifierError)
,
Jan 10
Interesting that both failures were on the same DUT: chromeos4-row9-rack3-host14 Could just be a DUT problem
,
Jan 10
+amin for a quick check aashutoshk@ did this test get rerun more than once?
,
Jan 10
both logs indicate IO errors so I think there is something wrong with that particular DUT as dhaddock@ mentioned in #6.
,
Jan 10
As per sheriff duties, I ran all the failing boards multiple times. IIRC, this run was triggered by cloning previous failed job when trying to isolate real failures.
,
Jan 10
I only see a single run for it in cautotest: https://screenshot.googleplex.com/UBqsybidB7r.png
,
Jan 10
That's interesting. I am not sure if it is infra issue or something related to my setup (normally I verify if suite command returns OK). I checked my bash history, and I see three runs ~10:40 am, ~ 1:30 pm & 2:30 pm https://screenshot.googleplex.com/zOymEAFfpwm.png
,
Jan 10
I will rerun the test again and check if it passes.
,
Jan 10
Just check in GE, and it is passing now. I guess we can close the issue. panther (payloads) (FSIs) Full 11316.66.0 mp-v2 Present 1 1 1 Delta (Serving) 11316.35.0 72.0.3626.30 11316.66.0 mp-v2 Present 1
,
Jan 10
Still failing for me: https://cros-goldeneye.corp.google.com/chromeos/console/qaRelease?releaseName=M72-BETA-CHROMEOS-1
,
Jan 10
Yes, My bad. I checked the Dev Release record of the same build.
,
Jan 10
The test is passing. I will clear the No-Go label for Panther. https://ubercautotest.corp.google.com/afe/#tab_id=view_job&object_id=275735068 https://tests.corp.google.com/target?id=030ff1c7-1738-412a-83c4-c79c51a98235&target=panther-release%2FR72-11316.66.0%2Fpaygen_au_beta%2Fautoupdate_EndToEndTest_paygen_au_beta_delta_11151.59.0&searchFor=
,
Jan 10
[Auto-generated comment by a script] We noticed that this issue is targeted for M-72; it appears the fix may have landed after branch point, meaning a merge might be required. The owner of this bug should confirm if a merge is required here. If so, add Merge-Request-72 label and indicate which commits/CLs are to be merged. Otherwise, remove Merge-TBD label. Thanks. |
|||||||||||||||||||||||
►
Sign in to add a comment |
|||||||||||||||||||||||
Comment 1 by dchan@google.com
, Jan 10Labels: -Pri-2 ReleaseBlock-Stable Pri-1