Able to reproduce the issue on CrOS 10752.0.0/Chrome 69.0.3449.0(Canary)-Peppy

Deleted: recovery_logs.zip 45.9 KB

recovery_logs.zip 45.9 KB Download

sb-release inside the new rootfs:
CHROMEOS_AUSERVER=https://tools.google.com/service/update2
CHROMEOS_BOARD_APPID={E6710DFC-3EC0-42AE-8095-733FDEA6AF18}
CHROMEOS_CANARY_APPID={90F229CE-83E2-4FAF-8479-E368A34938B1}
CHROMEOS_DEVSERVER=
CHROMEOS_RELEASE_APPID={90F229CE-83E2-4FAF-8479-E368A34938B1}
CHROMEOS_RELEASE_BOARD=peppy-signed-mp-v3keys
CHROMEOS_RELEASE_BRANCH_NUMBER=0
CHROMEOS_RELEASE_BUILDER_PATH=peppy-release/R69-10752.0.0
CHROMEOS_RELEASE_BUILD_NUMBER=10752
CHROMEOS_RELEASE_BUILD_TYPE=Official Build
CHROMEOS_RELEASE_CHROME_MILESTONE=69
CHROMEOS_RELEASE_DESCRIPTION=10752.0.0 (Official Build) canary-channel peppy 
CHROMEOS_RELEASE_NAME=Chrome OS
CHROMEOS_RELEASE_PATCH_NUMBER=0
CHROMEOS_RELEASE_TRACK=canary-channel
CHROMEOS_RELEASE_VERSION=10752.0.0
DEVICETYPE=CHROMEBOOK
GOOGLE_RELEASE=10752.0.0

Set boot target to /dev/sda3: Partition 3, Slot A
SetImage
KERNEL_CONFIG: console= loglevel=7 init=/sbin/init cros_secure oops=panic panic=-1 root=/dev/dm-0 rootwait ro dm_verity.error_behavior=3 dm_verity.max_bios=-1 dm_verity.dev_wait=1 dm="1 vroot none ro 1,0 2539520 verity payload=PARTUUID=%U/PARTNROFF=1 hashtree=PARTUUID=%U/PARTNROFF=1 hashstart=2539520 alg=sha1 root_hexdigest=6b98ebe94f6a9273e985bbe1c84869e30f6227b3 salt=141219d0016dd514f88e1610ed49f0c3813165a92d3d953aee3f04c05af5116d" noinitrd vt.global_cursor_default=0 kern_guid=%U add_efi_memmap boot=local noresume noswap i915.modeset=1 tpm_tis.force=1 tpm_tis.interrupts=0 nmi_watchdog=panic,lapic iTCO_vendor_support.vendorsupport=3  
Setting up verity.
Finished after 12 seconds.
Clearing network driver boot cache: /var/lib/preload-network-drivers.
Syncing filesystems before changing boot order...
Finished after 0 seconds.
Updating Partition Table Attributes using CgptManager...
Updated kernel 2 with Successful = 1 and NumTriesLeft = 6
Checking /mnt/stateful_partition/unencrypted permission.
RemovePackFiles Failed
Touch(/mnt/stateful_partition/.install_completed) FAILED
Starting firmware updater (//usr/sbin/chromeos-firmwareupdate --mode=recovery)
Command: //usr/sbin/chromeos-firmwareupdate --mode=recovery
Starting Google_Peppy firmware updater v4 (recovery)...
 - Updater package: [RO:Google_Peppy.4389.89.0 RW:Google_Peppy.4389.117.0 / EC:peppy_v1.5.130-a1f12b7]
 - Current system:  [RO:Google_Peppy.4389.89.0 , ACT:Google_Peppy.4389.89.0 / EC:peppy_v1.5.133-9078375]
 - Write protection: Hardware: ON, Software: Main=off EC=off
recovery: update RO+RW
 * invoke: flashrom -p host --fast-verify -w bios.bin
recovery: update ec/RO+RW
 * invoke: flashrom -p ec --fast-verify -w ec.bin
 Execution failed (1): flashrom -p ec --fast-verify -w ec.bin
 Messages:
Calibrating delay loop... OK.
coreboot table found at 0x7bf7a000.
flashrom v0.9.9  : 2b62e3c : May 31 2018 19:26:07 UTC on Linux 3.8.11 (x86_64)
__cros_ec_command_dev(): Command 0x18 failed: -1, errno=74
__cros_ec_command_dev(): Command 0x18 failed: -1, errno=74
__cros_ec_command_dev(): Command 0x18 failed: -1, errno=74
No erasers found for this chip (ti:Unknown-10de)!
ERROR: Execution FAILED.
ERROR: Execution failed: ./updater4.sh (error code = 1)
Finished after 17 seconds.
Failed Command: //usr/sbin/chromeos-firmwareupdate --mode=recovery - Exit Code 1
Firmware update failed (error code: 1).
Rolling back update due to failure installing required firmware.
Successfully updated GPT with all settings to rollback.
PostInstall Failed



Would this be related to issue 849266, also started from same 10741.0.0 build?

I was able to flash todays ToT build 10751.0.0 on Veyron-Tiger 10751.0.0

Able to reproduce on Daisy with today's ToT build M69-10751.0.0, 69.0.3449.0

Probably related to https://chromium-review.googlesource.com/c/chromiumos/third_party/flashrom/+/1068270 ?

There are other flashrom issues as reported in issue 849266

seems a problem with my flashrom changes, let me take a look.

 Issue 849890  has been merged into this issue.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/flashrom/+/5503150db8d4650f22763be85d8f17d893068451

commit 5503150db8d4650f22763be85d8f17d893068451
Author: Vadim Bendebury <vbendeb@chromium.org>
Date: Wed Jun 06 04:28:48 2018

Revert "use action descriptor when programming flash chips"

This reverts commit 2b62e3c1c5d4c2e8801f3b4d2d146a561c9ad1b5.

Reason for revert: there are some use cases not properly tested,
let's revert the culprit patch and fix the failing cases.

BRANCH=none
BUG=b:79492818,  chromium:848709 ,  chromium:84926 
>
> TEST=more test suggestions welcome, tried the following (each time
>   confirming that DUT boots successfully in verified mode):
>
>   ======= re-write RO FWID area of a Scarlet device. ========
>
>   It is running locally built AP firmware image, after the test
>   RO_FWID matches the released image:
>
>   > ssh 100.127.30.93 crossystem | grep ro_fwid
>   ro_fwid                = Google_Scarlet.a251301adf      # Read-only firmware ID
>   > time  ./flashrom -p raiden_debug_spi:target=AP -w <path to>/released.scarlet.bin -i RO_FRID  --fast-verify
>
>   flashrom v0.9.9 chromium.googlesource.com/chromiumos/third_party/flashrom : 42321053 : May 21 2018 22:52:18 UTC on Linux 4.9.0-6-amd64 (x86_64)
>   Calibrating delay loop... OK.
>   sh: crossystem: command not found
>   Erasing and writing flash chip... Verifying flash... 0x3df000..0x3dffff VERIFIED.
>   SUCCESS
>
>   real    0m1.968s
>   user    0m0.820s
>   sys     0m0.084s
>   > ssh 100.127.30.93 crossystem | grep ro_fwid
>   ro_fwid                = Google_Scarlet.10388.12.0      # Read-only firmware ID
>
>   ====== Erased and programmed Scarlet AP flash ===========
>   > time ./flashrom   -p raiden_debug_spi:target=AP -E --do-not-diff
>   [...]
>   real    0m32.974s
>   user    0m0.888s
>   sys     0m0.040s
>   > time ./flashrom  -p raiden_debug_spi:target=AP  --do-not-diff  -w <path to>/scarlet.image.bin
>   [..]
>   No diff performed, considering the chip erased.
>   Erasing and writing flash chip... Verifying flash... 000000..0x7fffff VERIFIED.
>   SUCCESS
>
>   real    3m12.789s
>   user    0m5.860s
>   sys     0m19.728s
>
>   ====== Reprogrammed Scarlet AP flash without erasing it first ===========
>   > time ./flashrom  -p raiden_debug_spi:target=AP  -w <path to>/released.scarlet.bin
>   [..]
>   Erasing and writing flash chip... Verifying flash... 000000..0x7fffff VERIFIED.
>   SUCCESS
>
>   real    5m46.014s
>   user    0m17.040s
>   sys     0m33.056s
>
>   ==== reprogrammed it again using diff with previous image  ============
>   #### Failure to compare below is due to the firmware log being
>        written after flash was programmed, so the contents of the
>        flash did not match the file the flash was programmed with.
>        0x5d8000 is the offset of the firmare log into the flash, the
>        DUT boots and runs just fine.
>
>    > time ./flashrom  -p raiden_debug_spi:target=AP  --diff <path to>/scarlet.image.bin -w  <path to>/released.scarlet.bin
>    [...]
>    Erasing and writing flash chip... Verifying flash... 000000..0x7fffff \
>    VERIFY FAILED at 0x005d8000! Expected=0xff, Read=0x45, \
>    failed byte count from 0x00000000-0x007fffff: 0x37
>    Your flash chip is in an unknown state.
>    Get help on IRC at irc.freenode.net (channel #flashrom) or
>    mail flashrom@flashrom.org with FAILED: your board name in the subject line!
>    -------------------------------------------------------------------------------
>    DO NOT REBOOT OR POWEROFF!
>    FAILED
>
>    real    4m5.303s
>    user    0m13.672s
>    sys     0m23.656s
>
>   ==== reprogrammed it again using diff with previous image and --fast-verify  =======
>   #### Note that there is no failure to compare in this case as the
>        firmware log space is not different between two files and is not
>        being written
>   > time ./flashrom  -p raiden_debug_spi:target=AP  --diff <path to>/scarlet.image.bin -w  <path to>/released.scarlet.bin  --fast-verify
>   [..]
>   Erasing and writing flash chip... Verifying flash... 0x10000..0x10fff 0x78000..0x31afff \
>      0x381000..0x381fff 0x3df000..0x3dffff 0x440000..0x444fff 0x4e7000..0x4e7fff 0x530000..0x534fff \
>      0x5d7000..0x5d7fff 0x70000..0x77fff 000000..0xffff 0x20000..0x6ffff
>      0x400000..0x43ffff 0x4f0000..0x52ffff VERIFIED.
>   SUCCESS
>
>   real    3m4.700s
>   user    0m12.452s
>   sys     0m18.612s
>
> Change-Id: I68719fbe4c82ece35da650359a275e300954b15c
> Signed-off-by: Vadim Bendebury <vbendeb@chromium.org>
> Reviewed-on: https://chromium-review.googlesource.com/1068270
> Reviewed-by: Simon Glass <sjg@chromium.org>
> Reviewed-by: Martin Roth <martinroth@chromium.org>

Bug: b:79492818
Change-Id: I4159e7e2dc91f2f1cdad5faa2a6553bf8e6897c4
Reviewed-on: https://chromium-review.googlesource.com/1087507
Commit-Ready: Vadim Bendebury <vbendeb@chromium.org>
Tested-by: Vadim Bendebury <vbendeb@chromium.org>
Reviewed-by: Vadim Bendebury <vbendeb@chromium.org>
Reviewed-by: Martin Roth <martinroth@chromium.org>

[modify] https://crrev.com/5503150db8d4650f22763be85d8f17d893068451/flash.h
[modify] https://crrev.com/5503150db8d4650f22763be85d8f17d893068451/Makefile
[modify] https://crrev.com/5503150db8d4650f22763be85d8f17d893068451/layout.h
[modify] https://crrev.com/5503150db8d4650f22763be85d8f17d893068451/layout.c
[modify] https://crrev.com/5503150db8d4650f22763be85d8f17d893068451/cli_mfg.c
[modify] https://crrev.com/5503150db8d4650f22763be85d8f17d893068451/flashrom.c

the problem should be fixed now.

Issue 849266 has been merged into this issue.

Verified no issue installing M69.0.3451.0 10758.0.0 dev recovery image on Daisy, Kip, Reks and Paine.