New issue
Advanced search Search tips

Issue 823840 link

Starred by 1 user
Status: Untriaged
Owner: ----
Cc:
sdantul...@chromium.org
mkarkada@chromium.org
ahass...@chromium.org
dhadd...@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: Bug-Regression



Sign in to add a comment

AU(M66 Dev -> M65 stable) failed with ERROR: New 'system' partition verification failed.

Project Member Reported by abod...@chromium.org, Mar 20 2018 
Steps:

Perform AU from AU(M66 Dev -> M65 stable) 
Device: Veyron-minnie

Results:
Failed filesystem verifier.

log info:
-------------------------------------------------------------
[0320/114155:INFO:delta_performer.cc(217)] Completed 780/823 operations (94%), 908391565/952664776 bytes downloaded (95%), overall progress 94%
[0320/114225:INFO:delta_performer.cc(217)] Completed 792/823 operations (96%), 923764981/952664776 bytes downloaded (96%), overall progress 96%
[0320/114255:INFO:delta_performer.cc(376)] Opening /dev/mmcblk0p4 partition without O_DSYNC
[0320/114255:INFO:delta_performer.cc(133)] Caching writes.
[0320/114255:INFO:delta_performer.cc(388)] Applying 9 operations to partition "boot"
[0320/114255:INFO:delta_performer.cc(217)] Completed 814/823 operations (98%), 947979885/952664776 bytes downloaded (99%), overall progress 98%
[0320/114300:INFO:delta_performer.cc(1666)] Skipping hash verification for signature operation 823
[0320/114300:INFO:delta_performer.cc(1469)] Extracted signature data of size 264 at 952617678
[0320/114300:INFO:delta_performer.cc(217)] Completed 823/823 operations (100%), 952664776/952664776 bytes downloaded (100%), overall progress 100%
[0320/114300:INFO:libcurl_http_fetcher.cc(433)] HTTP response code: 206
[0320/114300:INFO:libcurl_http_fetcher.cc(509)] Transfer completed (206), 952664776 bytes downloaded
[0320/114300:INFO:multi_range_http_fetcher.cc(167)] Received transfer complete.
[0320/114300:INFO:multi_range_http_fetcher.cc(124)] TransferEnded w/ code 206
[0320/114300:INFO:multi_range_http_fetcher.cc(158)] Done w/ all transfers
[0320/114301:INFO:delta_performer.cc(1729)] Verifying payload using public key: /usr/share/update_engine/update-payload-key.pub.pem
[0320/114301:INFO:payload_verifier.cc(93)] signature blob size = 264
[0320/114301:INFO:payload_verifier.cc(112)] Verified correct signature 1 out of 1 signatures.
[0320/114301:INFO:delta_performer.cc(1766)] Payload hash matches value in payload.
[0320/114301:INFO:payload_state.cc(149)] Payload downloaded successfully
[0320/114301:INFO:payload_state.cc(861)] Payload Attempt Number = 1
[0320/114301:INFO:payload_state.cc(442)] Incrementing the full payload attempt number
[0320/114301:INFO:payload_state.cc(869)] Full Payload Attempt Number = 1
[0320/114301:INFO:payload_state.cc(513)] Incrementing the backoff expiry time by 1d3h17m0s
[0320/114301:INFO:payload_state.cc(952)] Backoff Expiry Time = 3/21/2018 22:00:01 GMT
[0320/114301:INFO:download_action.cc(320)] Collections of histograms for UpdateEngine.DownloadAction.
Histogram: UpdateEngine.DownloadAction.InstallOperation::REPLACE.Duration recorded 114 samples, average = 331.1
0    ---O                                                                      (1 = 0.9%)
10   ---------------------------O                                              (10 = 8.8%) {0.9%}
18   -------------------------------------------O                              (16 = 14.0%) {9.6%}
32   -----------------------------------O                                      (13 = 11.4%) {23.7%}
57   -------------O                                                            (5 = 4.4%) {35.1%}
101  ----------------O                                                         (6 = 5.3%) {39.5%}
179  -----------------------------------O                                      (13 = 11.4%) {44.7%}
317  ------------------------------------------------------------------------O (27 = 23.7%) {56.1%}
561  ---------------------------------------------O                            (17 = 14.9%) {79.8%}
993  ----------------O                                                         (6 = 5.3%) {94.7%}
1758 ... 


[0320/114301:INFO:action_processor.cc(116)] ActionProcessor: finished DownloadAction with code ErrorCode::kSuccess
[0320/114301:INFO:action_processor.cc(143)] ActionProcessor: starting OmahaRequestAction
[0320/114301:INFO:omaha_request_action.cc(226)] Passing OS version as 0.0.0.0 as we are set to powerwash on downgrading to the version in the more stable channel
[0320/114301:INFO:omaha_request_action.cc(680)] Posting an Omaha request to https://tools.google.com/service/update2
[0320/114301:INFO:omaha_request_action.cc(681)] 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="10452.14.0_armv7l"></os>
    <app appid="{432FF9F1-4D2E-7E74-6F98-32E56E904BFB}" cohort="1:5:" cohortname="veyron-minnie_stable" version="0.0.0.0" from_version="10452.14.0" track="stable-channel" from_track="dev-channel" lang="en-US" board="veyron_minnie-signed-mp-v4keys" hardware_class="MINNIE CHEETS 1237" delta_okay="false" fw_version="" ec_version="" installdate="4088" >
        <event eventtype="14" eventresult="1"></event>
    </app>
</request>

[0320/114301:INFO:libcurl_http_fetcher.cc(146)] Starting/Resuming transfer
[0320/114301:INFO:libcurl_http_fetcher.cc(165)] Using proxy: no
[0320/114301:INFO:libcurl_http_fetcher.cc(308)] Setting up curl options for HTTPS
[0320/114301:INFO:libcurl_http_fetcher.cc(433)] HTTP response code: 200
[0320/114301:INFO:libcurl_http_fetcher.cc(509)] Transfer completed (200), 233 bytes downloaded
[0320/114301:INFO:omaha_request_action.cc(940)] Omaha request response: <?xml version="1.0" encoding="UTF-8"?><response protocol="3.0" server="prod"><daystart elapsed_days="4096" elapsed_seconds="42181"/><app appid="{432FF9F1-4D2E-7E74-6F98-32E56E904BFB}" status="ok"><event status="ok"/></app></response>
[0320/114301:INFO:action_processor.cc(116)] ActionProcessor: finished OmahaRequestAction with code ErrorCode::kSuccess
[0320/114301:INFO:action_processor.cc(143)] ActionProcessor: starting FilesystemVerifierAction
[0320/114301:INFO:filesystem_verifier_action.cc(111)] Hashing partition 0 (system) on device /dev/mmcblk0p5
[0320/114330:INFO:filesystem_verifier_action.cc(202)] Hash of system: vrkJV5N3hQKw4ooy9JUBzTIwoUKbUJeQLDPFcFklGxQ=
[0320/114330:ERROR:filesystem_verifier_action.cc(207)] New 'system' partition verification failed.
[0320/114330:INFO:prefs.cc(122)] delta-update-failures not present in /var/lib/update_engine/prefs
[0320/114330:INFO:action_processor.cc(116)] ActionProcessor: finished FilesystemVerifierAction with code ErrorCode::kNewRootfsVerificationError
[0320/114330:INFO:action_processor.cc(121)] ActionProcessor: Aborting processing due to failure.
[0320/114330:INFO:update_attempter.cc(873)] Processing Done.
[0320/114330:INFO:cpu_limiter.cc(71)] Setting cgroup cpu shares to  1024
[0320/114330:INFO:cpu_limiter.cc(79)] CPU shares = 1024
[0320/114330:ERROR:update_attempter.cc(1278)] Update failed.
[0320/114330:INFO:payload_state.cc(248)] Updating payload state for error code: 15 (ErrorCode::kNewRootfsVerificationError)
[0320/114330:INFO:metrics.cc(223)] Uploading 1 for metric UpdateEngine.Attempt.Number
[0320/114330:INFO:metrics.cc(231)] Uploading ForcedFull for metric UpdateEngine.Attempt.PayloadType
[0320/114330:INFO:metrics.cc(238)] Uploading 2m52.799995s for metric UpdateEngine.Attempt.DurationMinutes
[0320/114330:INFO:metrics.cc(247)] Uploading 2m52.799994s for metric UpdateEngine.Attempt.DurationUptimeMinutes
[0320/114330:INFO:metrics.cc(257)] Uploading 908 for metric UpdateEngine.Attempt.PayloadSizeMiB
[0320/114330:INFO:metrics.cc(267)] Uploading 80 for metric UpdateEngine.Attempt.PayloadBytesDownloadedMiB
[0320/114330:INFO:metrics.cc(277)] Uploading 487 for metric UpdateEngine.Attempt.PayloadDownloadSpeedKBps
[0320/114330:INFO:metrics.cc(286)] Uploading 1 for metric UpdateEngine.Attempt.DownloadSource
[0320/114330:INFO:metrics.cc(293)] Uploading 8 for metric UpdateEngine.Attempt.Result
[0320/114330:INFO:prefs.cc(122)] metrics-attempt-last-reporting-time not present in /var/lib/update_engine/prefs
[0320/114330:INFO:metrics.cc(352)] Uploading 2 for metric UpdateEngine.Attempt.ConnectionType
[0320/114330:INFO:payload_state.cc(352)] Not incrementing URL index or failure count for this error
[0320/114330:INFO:update_attempter.cc(1282)] Reporting the error event
update_engine.20180316-170545.txt
82.9 KB View Download
update_engine.20180320-114006.txt
31.0 KB View Download

Comment 1 by ahass...@chromium.org, Mar 21 2018 

I tried with the exact same source and target version on a veyron_minnie I have and cannot reproduce it. Could you reproduce the problem? Could it be your target partition is corrupted?

Comment 2 by abod...@chromium.org, Mar 21 2018 

Tried another device but not reprod.


actually in the middle of update process device got crashed and reboot. then again started AU.

Comment 3 by ahass...@chromium.org, Mar 21 2018 

The crash could be the cause of issue. Some data was written badly or it was missed. It would be nice if we can recreate a crash like this. reboot is not normally as harsh as a crash. Things can get persisted well in reboot. I'm guessing this was caused by a race condition between writing to the target partition and writing 'where was the last byte I wrote to partition' to preferences. The preference's write landed on the disk, but not the partition changes even they the order was correct. These disks are not this reliable and we can have these problems. But fortunately we have checks to catch these problems and retry on failure. So unless we can reliably reproduce this, I don't think this is a serious bug.
►

Sign in to add a comment