New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 872394 link

Starred by 6 users

Issue metadata

Status: Verified
Owner:
Last visit > 30 days ago
Closed: Aug 22
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug-Regression



Sign in to add a comment

AU Post-install failed with error "Failed to read VBNV from flash."

Project Member Reported by abod...@chromium.org, Aug 8

Issue description

<b>Chrome Version: <From about:version: Google Chrome x.x.x.x></b>
<b>Chrome OS Version: <From about:version: Platform x.x.x.x></b>
<b>Chrome OS Platform: <Make/model of computer running Chrome OS></b>
<b>Network info: <network, encryption type, router model (if known)></b>

Please specify Cr-* of the system to which this bug/feature applies (add
the label below).

Steps To Reproduce:
(1)AU from M69 to M70
(2)
(3)

Expected Result:

Actual Result:



Log info
***************************************************************************


CHROMEOS_AUSERVER=https://tools.google.com/service/update2
CHROMEOS_BOARD_APPID={F1C30EB2-8429-4A18-9321-93E224753A98}
CHROMEOS_CANARY_APPID={90F229CE-83E2-4FAF-8479-E368A34938B1}
CHROMEOS_DEVSERVER=
CHROMEOS_RELEASE_APPID={F1C30EB2-8429-4A18-9321-93E224753A98}
CHROMEOS_RELEASE_BOARD=scarlet-signed-mpkeys
CHROMEOS_RELEASE_BRANCH_NUMBER=18
CHROMEOS_RELEASE_BUILDER_PATH=scarlet-release/R69-10895.18.0
CHROMEOS_RELEASE_BUILD_NUMBER=10895
CHROMEOS_RELEASE_BUILD_TYPE=Official Build
CHROMEOS_RELEASE_CHROME_MILESTONE=69
CHROMEOS_RELEASE_DESCRIPTION=10895.18.0 (Official Build) dev-channel scarlet-unibuild (dru) 
CHROMEOS_RELEASE_MODELS=dru
CHROMEOS_RELEASE_NAME=Chrome OS
CHROMEOS_RELEASE_PATCH_NUMBER=0
CHROMEOS_RELEASE_TRACK=dev-channel
CHROMEOS_RELEASE_UNIBUILD=1
CHROMEOS_RELEASE_VERSION=10895.18.0
DEVICETYPE=CHROMEBOOK
GOOGLE_RELEASE=10895.18.0

[0808/112112:INFO:image_properties_chromeos.cc(163)] stateful lsb-release:
CHROMEOS_IS_POWERWASH_ALLOWED=false
CHROMEOS_RELEASE_TRACK=dev-channel

[0808/112112:INFO:action_processor.cc(116)] ActionProcessor: finished FilesystemVerifierAction with code ErrorCode::kSuccess
[0808/112112:INFO:action_processor.cc(143)] ActionProcessor: starting PostinstallRunnerAction
[0808/112112:INFO:postinstall_runner_action.cc(172)] Performing postinst (postinst at /tmp/.org.chromium.Chromium.fSTt3v/postinst) installed on device /dev/mmcblk0p3 and mountable device /dev/mmcblk0p3
[0808/112112:INFO:postinstall_runner_action.cc(179)] Format file for new postinst is: data
[0808/112147:INFO:subprocess.cc(153)] Subprocess exited with si_status: 1
[0808/112147:INFO:subprocess.cc(157)] Subprocess output:
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
PostInstall Configured: (A, /dev/mmcblk0p3, /dev/mmcblk0p2, /dev/mmcblk0p12)

 Current Kernel Info: sysname(Linux) nodename(localhost) release(4.4.141-14525-g8b69542f88ea) version(#1 SMP PREEMPT Wed Aug 8 01:35:42 PDT 2018) machine(aarch64)

lsb-release inside the new rootfs:
CHROMEOS_ARC_ANDROID_SDK_VERSION=25
CHROMEOS_ARC_VERSION=4937945
CHROMEOS_AUSERVER=https://tools.google.com/service/update2
CHROMEOS_BOARD_APPID={F1C30EB2-8429-4A18-9321-93E224753A98}
CHROMEOS_CANARY_APPID={90F229CE-83E2-4FAF-8479-E368A34938B1}
CHROMEOS_DEVSERVER=
CHROMEOS_RELEASE_APPID={F1C30EB2-8429-4A18-9321-93E224753A98}
CHROMEOS_RELEASE_BOARD=scarlet-signed-mpkeys
CHROMEOS_RELEASE_BRANCH_NUMBER=0
CHROMEOS_RELEASE_BUILDER_PATH=scarlet-release/R70-10950.0.0
CHROMEOS_RELEASE_BUILD_NUMBER=10950
CHROMEOS_RELEASE_BUILD_TYPE=Official Build
CHROMEOS_RELEASE_CHROME_MILESTONE=70
CHROMEOS_RELEASE_DESCRIPTION=10950.0.0 (Official Build) dev-channel scarlet-unibuild (dru) 
CHROMEOS_RELEASE_MODELS=dru
CHROMEOS_RELEASE_NAME=Chrome OS
CHROMEOS_RELEASE_PATCH_NUMBER=0
CHROMEOS_RELEASE_TRACK=dev-channel
CHROMEOS_RELEASE_UNIBUILD=1
CHROMEOS_RELEASE_VERSION=10950.0.0
DEVICETYPE=CHROMEBOOK
GOOGLE_RELEASE=10950.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 3334144 verity payload=PARTUUID=%U/PARTNROFF=1 hashtree=PARTUUID=%U/PARTNROFF=1 hashstart=3334144 alg=sha1 root_hexdigest=6630ac8cce4c36467b50e27b0eab5bc1a9ce249e salt=ed08e59d1196c0ecbf3fe53bfc4fca469f94c0e2672f721f364d55b5f2fa5f05" noinitrd vt.global_cursor_default=0 kern_guid=%U  
Setting up verity.
Finished after 20 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 = 0 and NumTriesLeft = 6
Checking /mnt/stateful_partition/unencrypted permission.
Permission is ok.
Unlinked file /var/lib/ureadahead/opt.google.containers.android.rootfs.root.pack
Unlinked file /var/lib/ureadahead/pack
Starting firmware updater (//usr/sbin/chromeos-firmwareupdate --mode=autoupdate)
Command: //usr/sbin/chromeos-firmwareupdate --mode=autoupdate
Model is dru
Starting Google_Scarlet firmware updater v4 (autoupdate)...
 - Updater package: [RO:Google_Scarlet.10388.26.0 RW:Google_Scarlet.10388.56.0 / EC:scarlet_v1.1.7822-73ef6367c]
 - Current system:  [RO:Google_Scarlet.10388.26.0 , ACT:Google_Scarlet.10388.56.0 / EC:scarlet_v1.1.7866-91171747b]
 - Write protection: Hardware: ON, Software: Main=off
Detected new boards - updating firmware
 - import root_key from keyset/rootkey.dru: success
successfully saved new image to: models/dru/bios.bin
Firmware keys changed to set [dru].
 * invoke: flashrom -p host -r _current/models/dru/bios.bin
Firmware update available: Google_Scarlet.10388.56.0. 
 * invoke: flashrom -p host --fast-verify -w models/dru/bios.bin -i RW_SECTION_A
Child process did not exit normally.
Failed to read VBNV from flash.
mosys invocation was: ["nvram", "vboot", "read"]
Application error: Subcommand execution finished with error -1
waitpid() or mosys error
Parameter fw_try_next is read-only
ERROR: cannot SET crossystem property: fw_try_next=A
ERROR: Execution failed: ./updater4.sh (error code = 1)
Finished after 15 seconds.
Failed Command: //usr/sbin/chromeos-firmwareupdate --mode=autoupdate - 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

 
update_engine.20180808-110932.txt
46.4 KB View Download

Comment 1 Deleted

Labels: ReleaseBlock-Dev
Please fix x86 as well - also seeing the same thing on my Nocturne.
Could this be related to https://bugs.chromium.org/p/chromium/issues/detail?id=869971?

At least on Nocturne, my bisecting shows:
10948.0.0 - good
10952.0.0 - bad. 
good= chromeos-firmwareupdate succeeds.
bad= fails with "Failed to read VBNV from flash" error message.

Cannot find anything obvious here though: https://crosland.corp.google.com/log/10948.0.0..10952.0.0

Is it that my firmware changes from good to bad?

Comment 5 Deleted

Hi, Is this still a Dev blocker? If so, please update here with the plan to address this. Thanks.
Cc: jclinton@chromium.org samanthamiller@chromium.org
Owner: samanthamiller@chromium.org
@Geo: Yes it is. Multiple people have reported this on Eve, Scarlet, and Rajat saw it on Dragonegg where he's doing bring-up. 

As seen of dragonegg, the issues seems to be something with the minijail policy / permissions of mosys. Mosys cannot execute a particular flashrom command and the flashroom crashes generating a core. However if I run the same command manually, I can run the flashrom command fine:

localhost ~ # mosys nvram vboot read -vvvv
...
<snip>
...

Found command nvram (NVRAM information)
Subcommand vboot (Access VbNvContext on NVRAM)
Subcommand read (Read VbNvContext from NVRAM)
flashrom -p host -i RW_NVRAM:/tmp/flashrom_6viavc -r 
Child process did not exit normally.
Opened file lock "//run/lock/firmware_utility_lock"
Unable to read region "RW_NVRAM"
Failed to read VBNV from flash.
mosys invocation was: ["nvram", "vboot", "read", "-vvvv"]
Application error: Subcommand execution finished with error -1
localhost ~ #
localhost ~ #
localhost ~ # flashrom -p host -i RW_NVRAM:/tmp/flashrom_6viavc -r
flashrom v0.9.9 chromium.googlesource.com/chromiumos/third_party/flashrom : edf79f3 : Aug 08 2018 20:48:19 UTC on Linux 4.18.0-rc5 (x86_64)
Calibrating delay loop... OK.
coreboot table found at 0x4bb6c000.
WARNING: SPI Configuration Lockdown activated.
Reading flash... SUCCESS
localhost ~ # 


IN the /var/log/messages:




2018-08-11T01:01:09.672374+00:00 WARNING mosys[8251]: libminijail[8251]: allowing syscall: socket
2018-08-11T01:01:09.672438+00:00 WARNING mosys[8251]: libminijail[8251]: allowing syscall: connect
2018-08-11T01:01:09.672467+00:00 WARNING mosys[8251]: libminijail[8251]: allowing syscall: sendto
2018-08-11T01:01:09.672539+00:00 WARNING mosys[8251]: libminijail[8251]: allowing syscall: writev
2018-08-11T01:01:09.685813+00:00 WARNING mosys[8251]: libminijail[8251]: logging seccomp filter failures
2018-08-11T01:01:10.342413+00:00 INFO crash_reporter[8270]: libminijail[8270]: mount /dev/log -> /dev/log type ''
2018-08-11T01:01:10.372428+00:00 WARNING crash_reporter[8270]: Could not load the device policy file.
2018-08-11T01:01:10.373088+00:00 WARNING crash_reporter[8270]: [user] Received crash notification for flashrom[8252] sig 31, user 0 (developer build - not testing - always dumping)
2018-08-11T01:01:10.378675+00:00 INFO crash_reporter[8270]: State of crashed process [8252]: S (sleeping)
2018-08-11T01:01:10.385759+00:00 INFO metrics_daemon[2623]: [INFO:metrics_daemon.cc(427)] Got org.chromium.CrashReporter.UserCrash D-Bus signal
2018-08-11T01:01:10.418564+00:00 INFO crash_reporter[8270]: Stored minidump to /var/spool/crash/flashrom.20180810.180110.8252.dmp
2018-08-11T01:01:10.419803+00:00 INFO crash_reporter[8270]: Leaving core file at /var/spool/crash/flashrom.20180810.180110.8252.core due to developer image

(This is with latest mosys codes (sync'ed 5 minutes ago)
This bug seems hard to reproduce - on my eve, it alternately succeeds and fails: 

localhost ~ # cat /etc/lsb-release 
CHROMEOS_RELEASE_APPID={01906EA2-3EB2-41F1-8F62-F0B7120EFD2E}
CHROMEOS_BOARD_APPID={01906EA2-3EB2-41F1-8F62-F0B7120EFD2E}
CHROMEOS_CANARY_APPID={90F229CE-83E2-4FAF-8479-E368A34938B1}
DEVICETYPE=CHROMEBOOK
CHROMEOS_ARC_VERSION=4937945
CHROMEOS_ARC_ANDROID_SDK_VERSION=25
GOOGLE_RELEASE=10950.0.0
CHROMEOS_DEVSERVER=
CHROMEOS_RELEASE_BUILDER_PATH=eve-release/R70-10950.0.0
CHROMEOS_RELEASE_BUILD_NUMBER=10950
CHROMEOS_RELEASE_BRANCH_NUMBER=0
CHROMEOS_RELEASE_CHROME_MILESTONE=70
CHROMEOS_RELEASE_PATCH_NUMBER=0
CHROMEOS_RELEASE_TRACK=testimage-channel
CHROMEOS_RELEASE_DESCRIPTION=10950.0.0 (Official Build) dev-channel eve test
CHROMEOS_RELEASE_BUILD_TYPE=Official Build
CHROMEOS_RELEASE_NAME=Chrome OS
CHROMEOS_RELEASE_BOARD=eve
CHROMEOS_RELEASE_VERSION=10950.0.0
CHROMEOS_AUSERVER=https://tools.google.com/service/update2
localhost ~ # chromeos-firmwareupdate --mode autp^C
localhost ~ # mosys nvram vboot read
601700000102002d00010000000100d4
localhost ~ # chromeos-firmwareupdate --mode autoupdate
Starting Google_Eve firmware updater v4 (autoupdate)...
 - Updater package: [RO:Google_Eve.9584.107.0 RW:Google_Eve.9584.160.0 / EC:eve_v1.1.6585-859d2ea99]
 - Current system:  [RO:Google_Eve.9584.107.0 , ACT:Google_Eve.9584.160.0 / EC:eve_v1.1.6640-993636243]
 - Write protection: Hardware: ON, Software: Main=off
Read the current FLMSTR values...
flashrom v0.9.9  : a7a062b : Jul 31 2018 23:37:21 UTC on Linux 4.4.145-14671-gb5977f05bff4 (x86_64)
Calibrating delay loop... OK.
coreboot table found at 0x7aabe000.
WARNING: SPI Configuration Lockdown activated.
Reading flash... SUCCESS
No need to modify image file.
 * invoke: flashrom -p host -r _current/bios.bin
Firmware update available: Google_Eve.9584.160.0. 
 * invoke: flashrom -p host --fast-verify -w bios.bin -i RW_SECTION_A
Child process did not exit normally.
Failed to read VBNV from flash.
mosys invocation was: ["nvram", "vboot", "write", "601000000102002600010000000100cc"]
Application error: Subcommand execution finished with error -1
waitpid() or mosys error
Child process did not exit normally.
Failed to read VBNV from flash.
mosys invocation was: ["nvram", "vboot", "write", "601800000102002600010000000100f1"]
Application error: Subcommand execution finished with error -1
waitpid() or mosys error
On reboot EC update may occur.
Firmware update (autoupdate) completed.
localhost ~ # 

This is fairly easily and consistently reproduced on my Dragonegg.
Cc: rajatja@google.com
I'm having trouble reproducing this on eve. Is there a dragonegg I can ssh into to test this on? Otherwise, can someone send me the output of 'strace -ff' and the failing command? That will say what system call is needed.

OK, I verified that using 10969.0.0, it is not reproducible on dragonegg also. 
Status: Closed (was: Untriaged)
Sounds like this issue got fixed by something else, then. I'm marking it as closed. Let me know if that's not correct.
This is still an issue for the ELM platform (Acer R13). The firmware fails to upgrade.

update_engine.log
941 KB View Download
Echoing the above, still seeing this issue on ELM
Reports of ongoing issues need to include exact versions tested with.
Same as OP for me.
Cc: dchan@chromium.org
Status: Untriaged (was: Closed)
Still AU is failed on Kevin from 10895.18.0 => TOT(10971.0.0).
Attached log file.


CHROMEOS_RELEASE_TRACK=dev-channel
CHROMEOS_RELEASE_VERSION=10895.18.0
DEVICETYPE=CHROMEBOOK
GOOGLE_RELEASE=10895.18.0

[0815/110458:INFO:action_processor.cc(116)] ActionProcessor: finished FilesystemVerifierAction with code ErrorCode::kSuccess
[0815/110458:INFO:action_processor.cc(143)] ActionProcessor: starting PostinstallRunnerAction
[0815/110458:INFO:postinstall_runner_action.cc(172)] Performing postinst (postinst at /tmp/.org.chromium.Chromium.kcAMhf/postinst) installed on device /dev/mmcblk0p3 and mountable device /dev/mmcblk0p3
[0815/110458:INFO:postinstall_runner_action.cc(179)] Format file for new postinst is: data
[0815/110536:INFO:subprocess.cc(153)] Subprocess exited with si_status: 1
[0815/110536:INFO:subprocess.cc(157)] Subprocess output:
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
PostInstall Configured: (A, /dev/mmcblk0p3, /dev/mmcblk0p2, /dev/mmcblk0p12)

 Current Kernel Info: sysname(Linux) nodename(localhost) release(4.4.141-14525-g8b69542f88ea) version(#1 SMP PREEMPT Wed Aug 8 01:48:51 PDT 2018) machine(aarch64)

lsb-release inside the new rootfs:
CHROMEOS_ARC_ANDROID_SDK_VERSION=25
CHROMEOS_ARC_VERSION=4953369
CHROMEOS_AUSERVER=https://tools.google.com/service/update2
CHROMEOS_BOARD_APPID={92A7272A-834A-47A3-9112-E8FD55831660}
CHROMEOS_CANARY_APPID={90F229CE-83E2-4FAF-8479-E368A34938B1}
CHROMEOS_DEVSERVER=
CHROMEOS_RELEASE_APPID={92A7272A-834A-47A3-9112-E8FD55831660}
CHROMEOS_RELEASE_BOARD=kevin-signed-mpkeys
CHROMEOS_RELEASE_BRANCH_NUMBER=0
CHROMEOS_RELEASE_BUILDER_PATH=kevin-release/R70-10971.0.0
CHROMEOS_RELEASE_BUILD_NUMBER=10971
CHROMEOS_RELEASE_BUILD_TYPE=Official Build
CHROMEOS_RELEASE_CHROME_MILESTONE=70
CHROMEOS_RELEASE_DESCRIPTION=10971.0.0 (Official Build) dev-channel kevin 
CHROMEOS_RELEASE_NAME=Chrome OS
CHROMEOS_RELEASE_PATCH_NUMBER=0
CHROMEOS_RELEASE_TRACK=dev-channel
CHROMEOS_RELEASE_VERSION=10971.0.0
DEVICETYPE=CHROMEBOOK
GOOGLE_RELEASE=10971.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 3334144 verity payload=PARTUUID=%U/PARTNROFF=1 hashtree=PARTUUID=%U/PARTNROFF=1 hashstart=3334144 alg=sha1 root_hexdigest=ab33d77821ed6c9afb023125e1a1efd60fe4a4ff salt=8bd2d806acc86422bd158f773ad315349b6658cf70df82cb71211372201d0f8e" noinitrd vt.global_cursor_default=0 kern_guid=%U  
Setting up verity.
Finished after 24 seconds.
Clearing network driver boot cache: /var/lib/preload-network-drivers.
Syncing filesystems before changing boot order...
Finished after 2 seconds.
Updating Partition Table Attributes using CgptManager...
Updated kernel 2 with Successful = 0 and NumTriesLeft = 6
Checking /mnt/stateful_partition/unencrypted permission.
Permission is ok.
Starting firmware updater (//usr/sbin/chromeos-firmwareupdate --mode=autoupdate)
Command: //usr/sbin/chromeos-firmwareupdate --mode=autoupdate
Starting Google_Kevin firmware updater v4 (autoupdate)...
 - Updater package: [RO:Google_Kevin.8785.94.7 RW:Google_Kevin.8785.264.0 / EC:kevin_v1.10.184-459421c]
 - Current system:  [RO:Google_Kevin.8785.94.7 , ACT:Google_Kevin.8785.264.0 / EC:kevin_v1.10.234-d3eb899]
 - Write protection: Hardware: off, Software: Main=off
 * invoke: flashrom -p host -r _current/bios.bin
Firmware update available: Google_Kevin.8785.264.0. 
 * invoke: flashrom -p host --fast-verify -w bios.bin -i RW_SECTION_A
Child process did not exit normally.
Failed to read VBNV from flash.
mosys invocation was: ["nvram", "vboot", "read"]
Application error: Subcommand execution finished with error -1
waitpid() or mosys error
Parameter fw_try_next is read-only
ERROR: cannot SET crossystem property: fw_try_next=A
ERROR: Execution failed: ./updater4.sh (error code = 1)
Finished after 12 seconds.
Failed Command: //usr/sbin/chromeos-firmwareupdate --mode=autoupdate - 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
update_engine.20180815-103518.txt
117 KB View Download
crrev.com/c/1176112 should hopefully fix the issue.
Summary: [ARM] AU Post-install failed with error "Failed to read VBNV from flash." (was: [Scarlet] AU Post-install failed with error "Failed to read VBNV from flash.")
Failed many ARM devices(Hana, Scarlet and Kevin)
Cc: aaboagye@chromium.org
Hi, regarding comments #22 and #23, are we still seeing failures?
Status: Assigned (was: Untriaged)
The change went in last night, around midnight, so well after comments #22 and #23. I don't know if there are still failures that include that change.
Still AU is failed on HANA with CROS: 10974.0.0

log Info
********************************************************

DEVICETYPE=CHROMEBOOK
GOOGLE_RELEASE=10974.0.0

Set boot target to /dev/mmcblk0p5: Partition 5, Slot B
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 3334144 verity payload=PARTUUID=%U/PARTNROFF=1 hashtree=PARTUUID=%U/PARTNROFF=1 hashstart=3334144 alg=sha1 root_hexdigest=90db1a90b41ee01a528cdafa49908ad81fae1c9e salt=d57f78d1e0ea298c466db1982ceecab1adea0cd8df01e9527693441898d9b781" noinitrd vt.global_cursor_default=0 kern_guid=%U  
Setting up verity.
Finished after 39 seconds.
Clearing network driver boot cache: /var/lib/preload-network-drivers.
Syncing filesystems before changing boot order...
Finished after 1 seconds.
Updating Partition Table Attributes using CgptManager...
Updated kernel 4 with Successful = 0 and NumTriesLeft = 6
Checking /mnt/stateful_partition/unencrypted permission.
Permission is ok.
Unlinked file /var/lib/ureadahead/pack
Unlinked file /var/lib/ureadahead/opt.google.containers.android.rootfs.root.pack
Starting firmware updater (//usr/sbin/chromeos-firmwareupdate --mode=autoupdate)
Command: //usr/sbin/chromeos-firmwareupdate --mode=autoupdate
Starting Google_Hana firmware updater v4 (autoupdate)...
 - Updater package: [Google_Hana.8438.140.0 / EC:hana_v1.1.4818-e120dd6]
 - Current system:  [RO:Google_Hana.8438.140.0 , ACT:Google_Hana.8438.140.0 / EC:hana_v1.1.4818-e120dd6]
 - Write protection: Hardware: off, Software: Main=off
 - import root_key from keyset/rootkey.OEM1: success
successfully saved new image to: bios.bin
Firmware keys changed to set [OEM1].
 * invoke: flashrom -p host -r _current/bios.bin
Firmware update available: Google_Hana.8438.140.0. 
 * invoke: flashrom -p host --fast-verify -w bios.bin -i RW_SECTION_A
Child process did not exit normally.
Failed to read VBNV from flash.
mosys invocation was: ["nvram", "vboot", "read"]
Application error: Subcommand execution finished with error -1
waitpid() or mosys error
Parameter fw_try_next is read-only
ERROR: cannot SET crossystem property: fw_try_next=A
ERROR: Execution failed: ./updater4.sh (error code = 1)
Finished after 12 seconds.
Failed Command: //usr/sbin/chromeos-firmwareupdate --mode=autoupdate - 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
update_engine.20180816-135001.txt
48.4 KB View Download
Ok! crrev.com/c/1178966 should do it! I found a hana machine that I could lock and test on, so I can confirm that at least hana should work after this.
Quick question: why these changes are not needed in the x86 version of policy?
Good point. I'd thought that all the remaining issues were on arm, but eve is still failing sometimes. I've added these changes to the x86 policy as well. It'll take me a while to confirm that eve is fixed, but this looks promising.
EVE Auto updated successfully to 10974.0.0. 
Eve was working inconsistently. It appears with the above change, eve is now working consistently.
Just repro-ed this on my Nocturne with nvme on 10974.0.0: 

localhost ~ # cat /etc/lsb-release 
CHROMEOS_RELEASE_APPID={BD7F7139-CC18-49C1-A847-33F155CCBCA8}
CHROMEOS_BOARD_APPID={BD7F7139-CC18-49C1-A847-33F155CCBCA8}
CHROMEOS_CANARY_APPID={90F229CE-83E2-4FAF-8479-E368A34938B1}
DEVICETYPE=CHROMEBOOK
CHROMEOS_ARC_VERSION=4957600
CHROMEOS_ARC_ANDROID_SDK_VERSION=28
GOOGLE_RELEASE=10974.0.0
CHROMEOS_DEVSERVER=
CHROMEOS_RELEASE_BUILDER_PATH=nocturne-release/R70-10974.0.0
CHROMEOS_RELEASE_BUILD_NUMBER=10974
CHROMEOS_RELEASE_BRANCH_NUMBER=0
CHROMEOS_RELEASE_CHROME_MILESTONE=70
CHROMEOS_RELEASE_PATCH_NUMBER=0
CHROMEOS_RELEASE_TRACK=testimage-channel
CHROMEOS_RELEASE_DESCRIPTION=10974.0.0 (Official Build) dev-channel nocturne test
CHROMEOS_RELEASE_BUILD_TYPE=Official Build
CHROMEOS_RELEASE_NAME=Chrome OS
CHROMEOS_RELEASE_BOARD=nocturne
CHROMEOS_RELEASE_VERSION=10974.0.0
CHROMEOS_AUSERVER=https://tools.google.com/service/update2
localhost ~ # iw wlan0 link
Not connected.
localhost ~ # chromeos-firmwareupdate --mode autoupdate
Starting Google_Nocturne firmware updater v4 (autoupdate)...
 - Updater package: [Google_Nocturne.10968.0.0 / EC:nocturne_v1.1.9033-5419afaaf]
 - Current system:  [RO:Google_Nocturne.10968.0.0 , ACT:Google_Nocturne.10968.0.0 / EC:nocturne_v1.1.9033-5419afaaf]
 - Write protection: Hardware: ON, Software: Main=off
 * invoke: flashrom -p host -r _current/bios.bin
Firmware update available: Google_Nocturne.10968.0.0. 
 * invoke: flashrom -p host --fast-verify -w bios.bin -i RW_SECTION_B
Child process returned 127.
Failed to read VBNV from flash.
mosys invocation was: ["nvram", "vboot", "write", "601000000102000a00feff0000ffffd1"]
Application error: Subcommand execution finished with error -1
waitpid() or mosys error
Child process returned 127.
Failed to read VBNV from flash.
mosys invocation was: ["nvram", "vboot", "write", "601600000102000a00feff0000ffff81"]
Application error: Subcommand execution finished with error -1
waitpid() or mosys error
Firmware update (autoupdate) completed.

Summary: AU Post-install failed with error "Failed to read VBNV from flash." (was: [ARM] AU Post-install failed with error "Failed to read VBNV from flash.")
Removing ARM tag since #34 shows Intel is affected too

I suspect that an easier way to reproduce the problem may be running "mosys nvram vboot read" in a loop. 
Alright, I've tried a few cycles on my eve - i7+nvme. 
The first "chromeos-firmwareupdate" on reboot (warm - just reboot on command line 
OR cold -ectool reboot_ec cold - either one works) will fail with a mosys error. 
The subsequent ones pass. Photos attached since I didnt grab logs from the terminal. 

If you want to play around with the device, its up at 100.90.31.54
running 10973.0.0 

IMG_20180816_173458.jpg
5.1 MB View Download
IMG_20180816_173352.jpg
5.3 MB View Download
IMG_20180816_173420.jpg
5.5 MB View Download
ELM still fails. 
update_engine.log
230 KB View Download
The expected fix hasn't been able to pass through the CQ yet.
Cc: kmshelton@google.com
Seen this issue on Asuka device also.

Type of hardware  : asuka PVT SKU1 Asset# C106410
Chrome OS Version : 10971.0.0 (Official Build) dev-channel asuka test
BIOS Version      : Google_Asuka.7820.257.0 / Google_Asuka.7820.389.0
Application error: No commands given
EC Version        : asuka_v1.9.351-96e8819 / asuka_v1.9.405-b9e91f7
PD Version        : asuka_pd_v1.9.351-96e8819 / asuka_pd_v1.9.405-b9e91f7

CPU arch     : x86_64
CPU model    : Intel(R) Celeron(R) CPU 3855U @ 1.60GHz
CPU speed    : 1600.0000
Total Memory : 3938760 kB
Memory Type  : 1-44: Micron Technology | 00000000 | MT52L256M32D1PF107
MMC Model    : CJNB4R
MMC Firmware : 0x0700000000000000

VPD info:
  mlb_serial_number=CN02WRRVWSC006CH0P2TA00
  ppid=CN02WRRVWSC006CH0P2TA00
  region=us
  asset_tag=
  customization_id=DELL-ASUKA
  model_name=Dell Chromebook 13 3380
  serial_number=4910A40100016510004EWD00
  service_tag=4910A40100016510004EWD00
  wifi_mac=00:16:eb:4c:30:33
  rlz_brand_code=DEAH

localhost /usr/sbin # ./chromeos-firmwareupdate --mode=autoupdate
Starting Google_Asuka firmware updater v4 (autoupdate)...
 - Updater package: [Google_Asuka.7820.389.0 / EC:asuka_v1.9.405-b9e91f7 / PD:asuka_pd_v1.9.405-b9e91f7]
 - Current system:  [RO:Google_Asuka.7820.257.0 , ACT:Google_Asuka.7820.314.0 / EC:asuka_v1.9.384-71bdb18 / PD:asuka_pd_v1.9.384-71bdb18]
 - Write protection: Hardware: ON, Software: Main=ON
Firmware update available: Google_Asuka.7820.389.0. 
 * invoke: flashrom -p host -r _current/bios.bin
 * invoke: flashrom -p host --fast-verify -w bios.bin -i RW_SECTION_B
Child process returned 127.
Failed to read VBNV from flash.
mosys invocation was: ["nvram", "vboot", "write", "701000000000000a00000000000000e4"]
Application error: Subcommand execution finished with error -1
waitpid() or mosys error
Child process returned 127.
Failed to read VBNV from flash.
mosys invocation was: ["nvram", "vboot", "write", "701800000000000a00000000000000d9"]
Application error: Subcommand execution finished with error -1
waitpid() or mosys error
On reboot EC update may occur.
Firmware update (autoupdate) completed.

Issue is not reproducible with M69 build.

localhost /usr/sbin # ./chromeos-firmwareupdate --mode=autoupdate
Starting Google_Asuka firmware updater v4 (autoupdate)...
 - Updater package: [Google_Asuka.7820.389.0 / EC:asuka_v1.9.405-b9e91f7 / PD:asuka_pd_v1.9.405-b9e91f7]
 - Current system:  [RO:Google_Asuka.7820.257.0 , ACT:Google_Asuka.7820.314.0 / EC:asuka_v1.9.384-71bdb18 / PD:asuka_pd_v1.9.384-71bdb18]
 - Write protection: Hardware: ON, Software: Main=ON
Firmware update available: Google_Asuka.7820.389.0. 
 * invoke: flashrom -p host -r _current/bios.bin
 * invoke: flashrom -p host --fast-verify -w bios.bin -i RW_SECTION_A
On reboot EC update may occur.
Firmware update (autoupdate) completed.

From the command line, a manual update on ELM seems to complete as well, however, from within the OS update, the firmware updater fails.
Command line
=======================
localhost /usr/sbin # ./chromeos-firmwareupdate --mode=autoupdate
Starting Google_Elm firmware updater v4 (autoupdate)...
 - Updater package: [Google_Elm.8438.140.0 / EC:elm_v1.1.4818-e120dd6]
 - Current system:  [RO:Google_Elm.8438.19.0 , ACT:Google_Elm.8438.140.0 / EC:elm_v1.1.4818-e120dd6]
 - Write protection: Hardware: ON, Software: Main=ON
 * invoke: flashrom -p host -r _current/bios.bin
Firmware update available: Google_Elm.8438.140.0. 
 * invoke: flashrom -p host --fast-verify -w bios.bin -i RW_SECTION_A
Firmware update (autoupdate) completed.

SNIP from the update_engine.log
======================
Starting firmware updater (//usr/sbin/chromeos-firmwareupdate --mode=autoupdate)
Command: //usr/sbin/chromeos-firmwareupdate --mode=autoupdate
Starting Google_Elm firmware updater v4 (autoupdate)...
 - Updater package: [Google_Elm.8438.140.0 / EC:elm_v1.1.4818-e120dd6]
 - Current system:  [RO:Google_Elm.8438.19.0 , ACT:Google_Elm.8438.140.0 / EC:elm_v1.1.4818-e120dd6]
 - Write protection: Hardware: ON, Software: Main=ON
 * invoke: flashrom -p host -r _current/bios.bin
Firmware update available: Google_Elm.8438.140.0.
 * invoke: flashrom -p host --fast-verify -w bios.bin -i RW_SECTION_A
Child process did not exit normally.
Failed to read VBNV from flash.
mosys invocation was: ["nvram", "vboot", "read"]
Application error: Subcommand execution finished with error -1
waitpid() or mosys error
Parameter fw_try_next is read-only
ERROR: cannot SET crossystem property: fw_try_next=A
ERROR: Execution failed: ./updater4.sh (error code = 1)
Finished after 8 seconds.
Failed Command: //usr/sbin/chromeos-firmwareupdate --mode=autoupdate - 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
This has been broken since Aug 3rd.  issue 870816 
Project Member

Comment 44 by bugdroid1@chromium.org, Aug 21

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/mosys/+/1842e66725eef3596a7dc16da71392e54981b7b9

commit 1842e66725eef3596a7dc16da71392e54981b7b9
Author: Samantha Miller <samanthamiller@google.com>
Date: Tue Aug 21 15:56:43 2018

mosys: Add more system calls for firmwareupdate.

Several machines (elm, hana, scarlet, eve, ...) were failing
on chromeos-firmware update. With these system calls,
the command succeeds on hana.

BUG= chromium:872394 
TEST=built and ran on hana

Change-Id: Iab8c82a6c2f1fab0032b398db2f328815ab0c786
Reviewed-on: https://chromium-review.googlesource.com/1178966
Reviewed-by: Jason Clinton <jclinton@chromium.org>
Tested-by: Samantha Miller <samanthamiller@google.com>
Tested-by: Raul E Rangel <rrangel@chromium.org>
Commit-Queue: Justin TerAvest <teravest@chromium.org>

[modify] https://crrev.com/1842e66725eef3596a7dc16da71392e54981b7b9/seccomp/mosys-seccomp-arm.policy
[modify] https://crrev.com/1842e66725eef3596a7dc16da71392e54981b7b9/seccomp/mosys-seccomp-amd64.policy

For reference update for ELM 10987.0.0/70.0.3524.2 failed. Logs attached

update_engine.log
379 KB View Download
Doesn't look like the fix made it into that version. If you look at /usr/share/policy/mosys-seccomp.policy, you will notice that the changes in the fix aren't there. You would see statfs, prctl, and sigreturn listed in that file if the change were in that version.
Project Member

Comment 47 by bugdroid1@chromium.org, Aug 21

Labels: merge-merged-factory-nocturne-10984.B
The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/mosys/+/98710b8f724fa9e504e4133abd384f8da9cc7535

commit 98710b8f724fa9e504e4133abd384f8da9cc7535
Author: Samantha Miller <samanthamiller@google.com>
Date: Tue Aug 21 17:20:58 2018

mosys: Add more system calls for firmwareupdate.

Several machines (elm, hana, scarlet, eve, ...) were failing
on chromeos-firmware update. With these system calls,
the command succeeds on hana.

BUG= chromium:872394 
TEST=built and ran on hana

Change-Id: Iab8c82a6c2f1fab0032b398db2f328815ab0c786
Reviewed-on: https://chromium-review.googlesource.com/1178966
Reviewed-by: Jason Clinton <jclinton@chromium.org>
Tested-by: Samantha Miller <samanthamiller@google.com>
Tested-by: Raul E Rangel <rrangel@chromium.org>
Commit-Queue: Justin TerAvest <teravest@chromium.org>
(cherry picked from commit 1842e66725eef3596a7dc16da71392e54981b7b9)
Reviewed-on: https://chromium-review.googlesource.com/1183762
Reviewed-by: Aseda Aboagye <aaboagye@chromium.org>
Reviewed-by: Samantha Miller <samanthamiller@google.com>
Commit-Queue: Aseda Aboagye <aaboagye@chromium.org>
Tested-by: Aseda Aboagye <aaboagye@chromium.org>
Trybot-Ready: Aseda Aboagye <aaboagye@chromium.org>

[modify] https://crrev.com/98710b8f724fa9e504e4133abd384f8da9cc7535/seccomp/mosys-seccomp-arm.policy
[modify] https://crrev.com/98710b8f724fa9e504e4133abd384f8da9cc7535/seccomp/mosys-seccomp-amd64.policy

I am just making sure everyone is aware. 
The mosys policy file does not exist on my machine, at least on the current OS partition. 
localhost / # ls /usr/share/policy/mosys-seccomp.policy
ls: cannot access '/usr/share/policy/mosys-seccomp.policy': No such file or directory
Project Member

Comment 49 by bugdroid1@chromium.org, Aug 21

Labels: merge-merged-stabilize-10985.B
The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/mosys/+/62e313a278544e6ae3a30d5a2b5ce1cc4b24a956

commit 62e313a278544e6ae3a30d5a2b5ce1cc4b24a956
Author: Samantha Miller <samanthamiller@google.com>
Date: Tue Aug 21 22:54:11 2018

mosys: Add more system calls for firmwareupdate.

Several machines (elm, hana, scarlet, eve, ...) were failing
on chromeos-firmware update. With these system calls,
the command succeeds on hana.

BUG= chromium:872394 
TEST=built and ran on hana

Change-Id: Iab8c82a6c2f1fab0032b398db2f328815ab0c786
Reviewed-on: https://chromium-review.googlesource.com/1178966
Reviewed-by: Jason Clinton <jclinton@chromium.org>
Tested-by: Samantha Miller <samanthamiller@google.com>
Tested-by: Raul E Rangel <rrangel@chromium.org>
Commit-Queue: Justin TerAvest <teravest@chromium.org>
(cherry picked from commit 1842e66725eef3596a7dc16da71392e54981b7b9)
Reviewed-on: https://chromium-review.googlesource.com/1184212
Reviewed-by: Geo Hsu <geohsu@chromium.org>
Commit-Queue: Geo Hsu <geohsu@chromium.org>
Tested-by: Geo Hsu <geohsu@chromium.org>
Trybot-Ready: Geo Hsu <geohsu@chromium.org>

[modify] https://crrev.com/62e313a278544e6ae3a30d5a2b5ce1cc4b24a956/seccomp/mosys-seccomp-arm.policy
[modify] https://crrev.com/62e313a278544e6ae3a30d5a2b5ce1cc4b24a956/seccomp/mosys-seccomp-amd64.policy

Status: Fixed (was: Assigned)
This appears to be fixed on hana, elm, and eve. If not, please reopen.
Confirmed working on ELM
Samantha, can you please confirm that for x86, whjat is the earliest R70 goldeneye image that should have all the fixes?
Looks like 10988.0.0.
Status: Verified (was: Fixed)
Successfully AUed to CROS:10991.0.0/70.0.3524.2 on Hana. Thanks for fixing.


With 10991.0.0, I see the following messages in my /var/log/messages (logs attached). Are these introduced by any CLs from this bug, or is it a different issue?

localhost ~ # grep -i mosys /var/log/messages | tail -100
2018-08-23T10:48:06.619274-07:00 WARNING mosys[1923]: libminijail[1923]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:48:06.630971-07:00 WARNING mosys[1923]: libminijail[1923]: not locking any securebits
2018-08-23T10:48:06.631064-07:00 WARNING mosys[1923]: libminijail[1923]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:48:06.631139-07:00 WARNING mosys[1923]: libminijail[1923]: logging seccomp filter failures
2018-08-23T10:48:06.680198-07:00 WARNING mosys[1927]: libminijail[1927]: allowing syscall: socket
2018-08-23T10:48:06.680466-07:00 WARNING mosys[1927]: libminijail[1927]: allowing syscall: connect
2018-08-23T10:48:06.680656-07:00 WARNING mosys[1927]: libminijail[1927]: allowing syscall: sendto
2018-08-23T10:48:06.680755-07:00 WARNING mosys[1927]: libminijail[1927]: allowing syscall: writev
2018-08-23T10:48:06.681090-07:00 WARNING mosys[1927]: libminijail[1927]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:48:06.691467-07:00 WARNING mosys[1927]: libminijail[1927]: not locking any securebits
2018-08-23T10:48:06.691565-07:00 WARNING mosys[1927]: libminijail[1927]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:48:06.691636-07:00 WARNING mosys[1927]: libminijail[1927]: logging seccomp filter failures
2018-08-23T10:50:27.755638-07:00 WARNING mosys[718]: libminijail[718]: allowing syscall: socket
2018-08-23T10:50:27.755716-07:00 WARNING mosys[718]: libminijail[718]: allowing syscall: connect
2018-08-23T10:50:27.755745-07:00 WARNING mosys[718]: libminijail[718]: allowing syscall: sendto
2018-08-23T10:50:27.755769-07:00 WARNING mosys[718]: libminijail[718]: allowing syscall: writev
2018-08-23T10:50:27.756079-07:00 WARNING mosys[718]: libminijail[718]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:50:27.767850-07:00 WARNING mosys[718]: libminijail[718]: not locking any securebits
2018-08-23T10:50:27.767923-07:00 WARNING mosys[718]: libminijail[718]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:50:27.767990-07:00 WARNING mosys[718]: libminijail[718]: logging seccomp filter failures
2018-08-23T10:50:27.801377-07:00 WARNING mosys[731]: libminijail[731]: allowing syscall: socket
2018-08-23T10:50:27.801422-07:00 WARNING mosys[731]: libminijail[731]: allowing syscall: connect
2018-08-23T10:50:27.801441-07:00 WARNING mosys[731]: libminijail[731]: allowing syscall: sendto
2018-08-23T10:50:27.801459-07:00 WARNING mosys[731]: libminijail[731]: allowing syscall: writev
2018-08-23T10:50:27.801744-07:00 WARNING mosys[731]: libminijail[731]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:50:27.810822-07:00 WARNING mosys[731]: libminijail[731]: not locking any securebits
2018-08-23T10:50:27.810922-07:00 WARNING mosys[731]: libminijail[731]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:50:27.811049-07:00 WARNING mosys[731]: libminijail[731]: logging seccomp filter failures
2018-08-23T10:50:45.183174-07:00 WARNING mosys[1380]: libminijail[1380]: allowing syscall: socket
2018-08-23T10:50:45.184231-07:00 WARNING mosys[1380]: libminijail[1380]: allowing syscall: connect
2018-08-23T10:50:45.184581-07:00 WARNING mosys[1380]: libminijail[1380]: allowing syscall: sendto
2018-08-23T10:50:45.184802-07:00 WARNING mosys[1380]: libminijail[1380]: allowing syscall: writev
2018-08-23T10:50:45.185335-07:00 WARNING mosys[1380]: libminijail[1380]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:50:45.285449-07:00 WARNING mosys[1380]: libminijail[1380]: not locking any securebits
2018-08-23T10:50:45.286371-07:00 WARNING mosys[1380]: libminijail[1380]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:50:45.286768-07:00 WARNING mosys[1380]: libminijail[1380]: logging seccomp filter failures
2018-08-23T10:50:47.895485-07:00 WARNING mosys[1690]: libminijail[1690]: allowing syscall: socket
2018-08-23T10:50:47.895569-07:00 WARNING mosys[1690]: libminijail[1690]: allowing syscall: connect
2018-08-23T10:50:47.895599-07:00 WARNING mosys[1690]: libminijail[1690]: allowing syscall: sendto
2018-08-23T10:50:47.895628-07:00 WARNING mosys[1690]: libminijail[1690]: allowing syscall: writev
2018-08-23T10:50:47.895911-07:00 WARNING mosys[1690]: libminijail[1690]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:50:47.921933-07:00 WARNING mosys[1690]: libminijail[1690]: not locking any securebits
2018-08-23T10:50:47.922054-07:00 WARNING mosys[1690]: libminijail[1690]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:50:47.922127-07:00 WARNING mosys[1690]: libminijail[1690]: logging seccomp filter failures
2018-08-23T10:50:48.179470-07:00 WARNING mosys[1837]: libminijail[1837]: allowing syscall: socket
2018-08-23T10:50:48.180380-07:00 WARNING mosys[1837]: libminijail[1837]: allowing syscall: connect
2018-08-23T10:50:48.181196-07:00 WARNING mosys[1837]: libminijail[1837]: allowing syscall: sendto
2018-08-23T10:50:48.181908-07:00 WARNING mosys[1837]: libminijail[1837]: allowing syscall: writev
2018-08-23T10:50:48.187757-07:00 WARNING mosys[1837]: libminijail[1837]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:50:48.208103-07:00 WARNING mosys[1837]: libminijail[1837]: not locking any securebits
2018-08-23T10:50:48.208204-07:00 WARNING mosys[1837]: libminijail[1837]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:50:48.208277-07:00 WARNING mosys[1837]: libminijail[1837]: logging seccomp filter failures
2018-08-23T10:50:48.391452-07:00 WARNING mosys[1889]: libminijail[1889]: allowing syscall: socket
2018-08-23T10:50:48.391538-07:00 WARNING mosys[1889]: libminijail[1889]: allowing syscall: connect
2018-08-23T10:50:48.391568-07:00 WARNING mosys[1889]: libminijail[1889]: allowing syscall: sendto
2018-08-23T10:50:48.391595-07:00 WARNING mosys[1889]: libminijail[1889]: allowing syscall: writev
2018-08-23T10:50:48.391880-07:00 WARNING mosys[1889]: libminijail[1889]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:50:48.405025-07:00 WARNING mosys[1889]: libminijail[1889]: not locking any securebits
2018-08-23T10:50:48.405142-07:00 WARNING mosys[1889]: libminijail[1889]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:50:48.405222-07:00 WARNING mosys[1889]: libminijail[1889]: logging seccomp filter failures
2018-08-23T10:50:50.211313-07:00 WARNING mosys[1923]: libminijail[1923]: allowing syscall: socket
2018-08-23T10:50:50.211612-07:00 WARNING mosys[1923]: libminijail[1923]: allowing syscall: connect
2018-08-23T10:50:50.211724-07:00 WARNING mosys[1923]: libminijail[1923]: allowing syscall: sendto
2018-08-23T10:50:50.211809-07:00 WARNING mosys[1923]: libminijail[1923]: allowing syscall: writev
2018-08-23T10:50:50.212176-07:00 WARNING mosys[1923]: libminijail[1923]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:50:50.224863-07:00 WARNING mosys[1923]: libminijail[1923]: not locking any securebits
2018-08-23T10:50:50.224979-07:00 WARNING mosys[1923]: libminijail[1923]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:50:50.225053-07:00 WARNING mosys[1923]: libminijail[1923]: logging seccomp filter failures
2018-08-23T10:50:50.244812-07:00 WARNING mosys[1924]: libminijail[1924]: allowing syscall: socket
2018-08-23T10:50:50.244904-07:00 WARNING mosys[1924]: libminijail[1924]: allowing syscall: connect
2018-08-23T10:50:50.244969-07:00 WARNING mosys[1924]: libminijail[1924]: allowing syscall: sendto
2018-08-23T10:50:50.244996-07:00 WARNING mosys[1924]: libminijail[1924]: allowing syscall: writev
2018-08-23T10:50:50.245274-07:00 WARNING mosys[1924]: libminijail[1924]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:50:50.261979-07:00 WARNING mosys[1924]: libminijail[1924]: not locking any securebits
2018-08-23T10:50:50.262055-07:00 WARNING mosys[1924]: libminijail[1924]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:50:50.262129-07:00 WARNING mosys[1924]: libminijail[1924]: logging seccomp filter failures
2018-08-23T10:50:50.285445-07:00 WARNING mosys[1925]: libminijail[1925]: allowing syscall: socket
2018-08-23T10:50:50.285968-07:00 WARNING mosys[1925]: libminijail[1925]: allowing syscall: connect
2018-08-23T10:50:50.286209-07:00 WARNING mosys[1925]: libminijail[1925]: allowing syscall: sendto
2018-08-23T10:50:50.286394-07:00 WARNING mosys[1925]: libminijail[1925]: allowing syscall: writev
2018-08-23T10:50:50.286825-07:00 WARNING mosys[1925]: libminijail[1925]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:50:50.298935-07:00 WARNING mosys[1925]: libminijail[1925]: not locking any securebits
2018-08-23T10:50:50.299828-07:00 WARNING mosys[1925]: libminijail[1925]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:50:50.300235-07:00 WARNING mosys[1925]: libminijail[1925]: logging seccomp filter failures
2018-08-23T10:50:50.328604-07:00 WARNING mosys[1926]: libminijail[1926]: allowing syscall: socket
2018-08-23T10:50:50.328675-07:00 WARNING mosys[1926]: libminijail[1926]: allowing syscall: connect
2018-08-23T10:50:50.328702-07:00 WARNING mosys[1926]: libminijail[1926]: allowing syscall: sendto
2018-08-23T10:50:50.328727-07:00 WARNING mosys[1926]: libminijail[1926]: allowing syscall: writev
2018-08-23T10:50:50.329054-07:00 WARNING mosys[1926]: libminijail[1926]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:50:50.344149-07:00 WARNING mosys[1926]: libminijail[1926]: not locking any securebits
2018-08-23T10:50:50.344237-07:00 WARNING mosys[1926]: libminijail[1926]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:50:50.344310-07:00 WARNING mosys[1926]: libminijail[1926]: logging seccomp filter failures
2018-08-23T10:50:50.393122-07:00 WARNING mosys[1931]: libminijail[1931]: allowing syscall: socket
2018-08-23T10:50:50.393186-07:00 WARNING mosys[1931]: libminijail[1931]: allowing syscall: connect
2018-08-23T10:50:50.393215-07:00 WARNING mosys[1931]: libminijail[1931]: allowing syscall: sendto
2018-08-23T10:50:50.393241-07:00 WARNING mosys[1931]: libminijail[1931]: allowing syscall: writev
2018-08-23T10:50:50.393539-07:00 WARNING mosys[1931]: libminijail[1931]: compile_file: /usr/share/policy/mosys-seccomp.policy(37): nonexistent syscall 'sigreturn'
2018-08-23T10:50:50.403858-07:00 WARNING mosys[1931]: libminijail[1931]: not locking any securebits
2018-08-23T10:50:50.403967-07:00 WARNING mosys[1931]: libminijail[1931]: SECURE_NOROOT not set, not dropping bounding set
2018-08-23T10:50:50.404039-07:00 WARNING mosys[1931]: libminijail[1931]: logging seccomp filter failures

debug-logs_20180823-112504.tgz
694 KB Download
That's not really a problem. Most of that logging is coming from things being run verbosely and is perfectly normal. I think there's a bug to not log all of that all the time. The "nonexistent syscall sigreturn" means that sigreturn doesn't exist on that platform. We should probably remove that from whatever architecture doesn't need it so we don't spam things, but it won't cause problems. I only have 1.5 more days to my internship, so I don't really have time to deal with that stuff, but you can give Jason a bug about it.
OK, Thanks a lot, and All the best! :-)
Project Member

Comment 58 by bugdroid1@chromium.org, Aug 31

Labels: merge-merged-stabilize-nocturne-10986.B
The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/mosys/+/35044e6048ef36cd7500d878f96105d63c3b9bd7

commit 35044e6048ef36cd7500d878f96105d63c3b9bd7
Author: Samantha Miller <samanthamiller@google.com>
Date: Fri Aug 31 04:54:43 2018

mosys: Add more system calls for firmwareupdate.

Several machines (elm, hana, scarlet, eve, ...) were failing
on chromeos-firmware update. With these system calls,
the command succeeds on hana.

BUG= chromium:872394 
TEST=built and ran on hana

Change-Id: Iab8c82a6c2f1fab0032b398db2f328815ab0c786
Reviewed-on: https://chromium-review.googlesource.com/1178966
Reviewed-by: Jason Clinton <jclinton@chromium.org>
Tested-by: Samantha Miller <samanthamiller@google.com>
Tested-by: Raul E Rangel <rrangel@chromium.org>
Commit-Queue: Justin TerAvest <teravest@chromium.org>
(cherry picked from commit 1842e66725eef3596a7dc16da71392e54981b7b9)
Reviewed-on: https://chromium-review.googlesource.com/1183762
Reviewed-by: Aseda Aboagye <aaboagye@chromium.org>
Reviewed-by: Samantha Miller <samanthamiller@google.com>
Commit-Queue: Aseda Aboagye <aaboagye@chromium.org>
Tested-by: Aseda Aboagye <aaboagye@chromium.org>
Trybot-Ready: Aseda Aboagye <aaboagye@chromium.org>
(cherry picked from commit 98710b8f724fa9e504e4133abd384f8da9cc7535)
Reviewed-on: https://chromium-review.googlesource.com/1198389
Reviewed-by: Bob Moragues <moragues@chromium.org>
Commit-Queue: Bob Moragues <moragues@chromium.org>
Tested-by: Bob Moragues <moragues@chromium.org>

[modify] https://crrev.com/35044e6048ef36cd7500d878f96105d63c3b9bd7/seccomp/mosys-seccomp-arm.policy
[modify] https://crrev.com/35044e6048ef36cd7500d878f96105d63c3b9bd7/seccomp/mosys-seccomp-amd64.policy

Sign in to add a comment