There are also logs before 'SetImage failed':

Installing the stateful partition...
dm:dm bht[DEBUG] Setting block_count 416768
dm:dm bht[DEBUG] Setting depth to 3.
dm:dm bht[DEBUG] depth: 0 entries: 1
dm:dm bht[DEBUG] depth: 1 entries: 26
dm:dm bht[DEBUG] depth: 2 entries: 3256
[1003/162759:ERROR:chromeos_verity.cc(279)] Filesystem hash verification failed
[1003/162759:ERROR:chromeos_verity.cc(280)] Expected 7a61afd2e4ab6cb87f101b4997ae1f19dd28823e != actual 97bfc7d4643df8f85198ba26a657aece0b6cb500

abodeti@, Can you please confirm this with AU.

This failed on recovery on reef too. 

Deleted: recovery.log 224 KB

recovery.log 224 KB View Download

AU also failed on nocturne

CHROMEOS_RELEASE_NAME=Chrome OS
CHROMEOS_RELEASE_PATCH_NUMBER=0
CHROMEOS_RELEASE_TRACK=dev-channel
CHROMEOS_RELEASE_VERSION=11120.0.0
DEVICETYPE=CHROMEBOOK
GOOGLE_RELEASE=11120.0.0

[1003/101854:INFO:action_processor.cc(116)] ActionProcessor: finished FilesystemVerifierAction with code ErrorCode::kSuccess
[1003/101854:INFO:action_processor.cc(143)] ActionProcessor: starting PostinstallRunnerAction
[1003/101854:INFO:postinstall_runner_action.cc(172)] Performing postinst (postinst at /tmp/.org.chromium.Chromium.VMeFSf/postinst) installed on device /dev/mmcblk0p3 and mountable device /dev/mmcblk0p3
[1003/101854:INFO:postinstall_runner_action.cc(179)] Format file for new postinst is: data
[1003/101915:INFO:subprocess.cc(153)] Subprocess exited with si_status: 1
[1003/101915:INFO:subprocess.cc(157)] Subprocess output:
dm:dm bht[DEBUG] Setting block_count 588800
dm:dm bht[DEBUG] Setting depth to 3.
dm:dm bht[DEBUG] depth: 0 entries: 1
dm:dm bht[DEBUG] depth: 1 entries: 36
dm:dm bht[DEBUG] depth: 2 entries: 4600
[1003/101914:ERROR:chromeos_verity.cc(279)] Filesystem hash verification failed
[1003/101914:ERROR:chromeos_verity.cc(280)] Expected 8949fc7febde1ef50254d5ed58d8b87b8c0ade3d != actual c5f37b9361b7a3a652e05eb417a6e39baed42739
PostInstall Configured: (A, /dev/mmcblk0p3, /dev/mmcblk0p2, /dev/mmcblk0p12)

 Current Kernel Info: sysname(Linux) nodename(localhost) release(4.4.158-15290-gdcadfbc359fb) version(#1 SMP PREEMPT Tue Oct 2 04:42:04 PDT 2018) machine(x86_64)

lsb-release inside the new rootfs:
CHROMEOS_ARC_ANDROID_SDK_VERSION=28
CHROMEOS_ARC_VERSION=5042281
CHROMEOS_AUSERVER=https://tools.google.com/service/update2
CHROMEOS_BOARD_APPID={BD7F7139-CC18-49C1-A847-33F155CCBCA8}
CHROMEOS_CANARY_APPID={90F229CE-83E2-4FAF-8479-E368A34938B1}
CHROMEOS_DEVSERVER=
CHROMEOS_RELEASE_APPID={BD7F7139-CC18-49C1-A847-33F155CCBCA8}
CHROMEOS_RELEASE_BOARD=nocturne-signed-mpkeys
CHROMEOS_RELEASE_BRANCH_NUMBER=0
CHROMEOS_RELEASE_BUILDER_PATH=nocturne-release/R71-11123.0.0
CHROMEOS_RELEASE_BUILD_NUMBER=11123
CHROMEOS_RELEASE_BUILD_TYPE=Official Build
CHROMEOS_RELEASE_CHROME_MILESTONE=71
CHROMEOS_RELEASE_DESCRIPTION=11123.0.0 (Official Build) dev-channel nocturne 
CHROMEOS_RELEASE_KEYSET=mp
CHROMEOS_RELEASE_NAME=Chrome OS
CHROMEOS_RELEASE_PATCH_NUMBER=0
CHROMEOS_RELEASE_TRACK=dev-channel
CHROMEOS_RELEASE_VERSION=11123.0.0
DEVICETYPE=CHROMEBOOK
GOOGLE_RELEASE=11123.0.0

Set boot target to /dev/mmcblk0p3: 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 4710400 verity payload=PARTUUID=%U/PARTNROFF=1 hashtree=PARTUUID=%U/PARTNROFF=1 hashstart=4710400 alg=sha1 root_hexdigest=8949fc7febde1ef50254d5ed58d8b87b8c0ade3d" 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 disablevmx=off  
Setting up verity.
Finished after 19 seconds.
SetImage failed.
PostInstall Failed

[1003/101915:ERROR:postinstall_runner_action.cc(305)] Postinst command failed with code: 1
[1003/101915:ERROR:postinstall_runner_action.cc(355)] Postinstall action failed.
[1003/101915:INFO:action_processor.cc(116)] ActionProcessor: finished PostinstallRunnerAction with code ErrorCode::kPostinstallRunnerError
[1003/101915:INFO:action_processor.cc(121)] ActionProcessor: Aborting processing due to failure.
[1003/101915:INFO:update_attempter.cc(956)] Processing Done.
[1003/101915:INFO:cpu_limiter.cc(71)] Setting cgroup cpu shares to  1024
[1003/101915:INFO:cpu_limiter.cc(79)] CPU shares = 1024
[1003/101915:ERROR:update_attempter.cc(1367)] Update failed.
[1003/101915:INFO:payload_state.cc(257)] Updating payload state for error code: 5 (ErrorCode::kPostinstallRunnerError)
[1003/101915:INFO:metrics_reporter_omaha.cc(264)] Uploading 1 for metric UpdateEngine.Attempt.Number
[1003/101915:INFO:metrics_reporter_omaha.cc(272)] Uploading Full for metric UpdateEngine.Attempt.PayloadType
[1003/101915:INFO:metrics_reporter_omaha.cc(277)] Uploading 11m34.474264s for metric UpdateEngine.Attempt.DurationMinutes
[1003/101915:INFO:metrics_reporter_omaha.cc(286)] Uploading 11m34.474265s for metric UpdateEngine.Attempt.DurationUptimeMinutes
[1003/101915:INFO:metrics_reporter_omaha.cc(296)] Uploading 1150 for metric UpdateEngine.Attempt.PayloadSizeMiB
[1003/101915:INFO:metrics_reporter_omaha.cc(306)] Uploading 9 for metric UpdateEngine.Attempt.Result
[1003/101915:INFO:metrics_reporter_omaha.cc(323)] Sending 17h7m1.758596s for metric UpdateEngine.Attempt.TimeSinceLastAttemptMinutes
[1003/101915:INFO:metrics_reporter_omaha.cc(356)] Uploading 1150 for metric UpdateEngine.Attempt.PayloadBytesDownloadedMiB
[1003/101915:INFO:metrics_reporter_omaha.cc(366)] Uploading 1737 for metric UpdateEngine.Attempt.PayloadDownloadSpeedKBps
[1003/101915:INFO:metrics_reporter_omaha.cc(375)] Uploading 1 for metric UpdateEngine.Attempt.DownloadSource
[1003/101915:INFO:metrics_reporter_omaha.cc(387)] Uploading 2 for metric UpdateEngine.Attempt.ConnectionType
[1003/101915:INFO:payload_state.cc(364)] Not incrementing URL index or failure count for this error
[1003/101915:INFO:update_attempter.cc(1377)] Reporting the error event

Deleted: update_engine.20181003-100712.txt 46.1 KB

update_engine.20181003-100712.txt 46.1 KB View Download

 Issue 891759  has been merged into this issue.

Mike, was this an unintended consequence of your change?

https://chrome-internal.googlesource.com/chromeos/cros-signing/+/52038547b0024b1c35c6587669eb3379845a7869#

Tom, could https://chromium-review.googlesource.com/c/chromiumos/platform/ec/+/1257645 be related?

Kalin: Tom's EC change would not have impacted most boards.

Re #10, no, this change only affects the board Cheza and its EC firmware image.

The vboot change represents this delta:
* 16ceb962 - image_signing: drop support for <R16 recovery image signing (26 hours ago) <Mike Frysinger>
* b95aa03f - futility: updater: Revise verbosity and error messages (26 hours ago) <Hung-Te Lin>
* bbe5fda1 - futility: updater: Support reading main image from stdin (26 hours ago) <Hung-Te Lin>
* 6d211585 - futility: updater: Preserve SMMSTORE and add quirk 'eve_smm_store' (26 hours ago) <Hung-Te Lin>
* 04e441e5 - futility: updater: Add quirk 'daisy_snow_dual_model' for daisy_snow (30 hours ago) <Hung-Te Lin>
* 9997820d - futility: updater: Add default quirks (30 hours ago) <Hung-Te Lin>
* ff34fd79 - futility: updater: Refactor: move quirks to 'updater_quirks.c' (30 hours ago) <Hung-Te Lin>
* 2c7dfb4e - futility: updater: Refactor: localize temp files management (30 hours ago) <Hung-Te Lin>
* 01d778c1 - futility: updater: Refactor: move command line processing to cmd_update.c (30 hours ago) <Hung-Te Lin>
* cf6b7a9c - image_signing: workaround ecrw signing breakage (5 days ago) <Mike Frysinger>

Re #11, #12: ACK. Saw the hash verification related log and CONFIG_VBOOT_HASH change...

If this is failing how come most boards are passing paygen AU tests in https://cros-goldeneye.corp.google.com/chromeos/console/viewBuild?version=11123.0.0&channel=dev&type=release ?

the futility log probably isn't relevant as the binaries on the signers weren't rebuilt.  only the scripts get updated+used right away.

reverting the signer change is cheap, so i sent that here:
  https://chrome-internal-review.googlesource.com/690694

Able to reproduce the issue on 70.0.3538.41/11021.36.0 -pit,big.  "unexpected error " appears while installing the recovery image. 

Deleted: recovery_logs (2).zip 50.7 KB

recovery_logs (2).zip 50.7 KB Download

The following revision refers to this bug:
  https://chrome-internal.googlesource.com/chromeos/cros-signing/+/6fc6d82055fd46f7ef5b7ef63d3db6ad79c35092

commit 6fc6d82055fd46f7ef5b7ef63d3db6ad79c35092
Author: Mike Frysinger <vapier@google.com>
Date: Wed Oct 03 19:02:34 2018

Does the signer CL go into effect when it is pushed to the signer in some way (such that it may help the on going ToT/71 build)? Or will this revert not go into effect until the next 71 build?

Not that we can feasibly test the on going 71 build today, but it would be good to verify this does fix it today.

all the signers should pull the update in the next ~5min in which case all new signing requests will see the revert.  if that CL was the problem, then this should be fixed.

No longer observing this issue using R71-11125.0.0.

Both USB Recovery and AU completed successfully on Kevin & Nocturne

ok, i'll follow up on the original bug

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/vboot_reference/+/aad0cfff9dea75a405a2ebff48c87b03cce43051

commit aad0cfff9dea75a405a2ebff48c87b03cce43051
Author: Mike Frysinger <vapier@chromium.org>
Date: Sat Dec 15 10:18:44 2018

image_signing: fix breakage from dropping <R16 support

Commit 16ceb9625ed13b0da4ae6306f9187b672b9b382f dropped support for old
versions, but it also accidentally dropped the salt= setting which ended
up breaking newer recovery kernels.  Restore that line and drop an unused
var from the old code path.

BRANCH=None
BUG= chromium:891015 ,  chromium:891764 
TEST=running `./sign_official_build.sh verify` against the images in  crbug.com/891764  works again

Change-Id: I8ae619c9243f9c2638962ae439b9df5090d6c535
Reviewed-on: https://chromium-review.googlesource.com/1376831
Commit-Ready: Mike Frysinger <vapier@chromium.org>
Tested-by: Mike Frysinger <vapier@chromium.org>
Reviewed-by: David Riley <davidriley@chromium.org>

[modify] https://crrev.com/aad0cfff9dea75a405a2ebff48c87b03cce43051/scripts/image_signing/sign_official_build.sh