Unable to reproduce the issue on 9460.60.0/59.0.3071.91 - Pit

[Auto-generated comment by a script] We noticed that this issue is targeted for M-60; it appears the fix may have landed after branch point, meaning a merge might be required. Please confirm if a merge is required here - if so add Merge-Request-60 label, otherwise remove Merge-TBD label. Thanks.

Tested with version  9592.71.0, 60.0.3112.80 on Peach-Pit and the observation is:

1. Recovery starts with USB stick but after 3 mins or so the device turns to black screen (see screenshot: https://screenshot.googleplex.com/SYb7o26fSGj )

2. When unplug USB stick from the device after few minutes(about 6 mins after the device turns black) and hard reboot (F3 + Power), I see that the device is updated. 

Does this happen all the time?

Happened 2 out of 2 times

 Issue 743295  has been merged into this issue.

Do you have any logs/feedback from this device?

Reproducible in Chrome 60.0.3112.95/9592.78.0 - Pit.
"Recovery_logs" is missing on "USB Drive" (USB stick).

The attached log file is generated after rebooting the system. 

Deleted: debug-logs_20170807-150444.tgz 63.6 KB

debug-logs_20170807-150444.tgz 63.6 KB Download

I did not see anything definitive in the logs ... these are mostly empty, that said there seems to be a related kernel panic but not sure that is the root cause here

Sameer, anyone who can look into this issue in more detail?

Song, IS M59 recovery image working fine on same device?

9460.76.0/59.0.3071.135 recovery image works fine on the same device. 

Perhaps dianders can?

I ran 9592.78.0 recovery image (as per comment 12) on my pit.  Sure enough it crashed.  I did a warm reboot and collected the console ramoops.

[  271.770051] ------------[ cut here ]------------
[  271.770065] kernel BUG at /mnt/host/source/src/third_party/kernel/v3.8/drivers/mfd/cros_ec_spi.c:197!
[  271.770075] Internal error: Oops - BUG: 0 [#1] SMP ARM
[  271.770084] Modules linked in:
[  271.770097] CPU: 0    Not tainted  (3.8.11 #2)
[  271.770110] PC is at cros_ec_spi_receive_response+0x214/0x244
[  271.770119] LR is at cros_ec_spi_receive_response+0x1e8/0x244
[  271.770129] pc : [<c04173cc>]    lr : [<c04173a0>]    psr: 20000013
[  271.770129] sp : d5d4dc18  ip : 00000000  fp : d5d4dcac
[  271.770137] r10: ef37d218  r9 : 00000100  r8 : d5d4dc48
[  271.770145] r7 : ef383d1b  r6 : d5d4dc50  r5 : 00000101  r4 : ef376718
[  271.770153] r3 : 0000021b  r2 : 00000120  r1 : ffffffec  r0 : d5d4dc7c
[  271.770162] Flags: nzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
[  271.770170] Control: 10c5387d  Table: 4570006a  DAC: 00000015
[  271.770178] Process flashrom (pid: 2969, stack limit = 0xd5d4c240)
[  271.770186] Stack: (0xd5d4dc18 to 0xd5d4e000)
...
...
[  271.770473] Backtrace:
[  271.770489] [<c04173cc>] (cros_ec_spi_receive_response+0x214/0x244) from [<c04174fc>] (cros_ec_cmd_xfer_spi+0x100/0x2b0)
[  271.770501] [<c04174fc>] (cros_ec_cmd_xfer_spi+0x100/0x2b0) from [<c04169d8>] (cros_ec_cmd_xfer+0x48/0xfc)
[  271.770511] [<c04169d8>] (cros_ec_cmd_xfer+0x48/0xfc) from [<c0417aa8>] (ec_device_ioctl_xcmd+0xe0/0x198)
[  271.770522] [<c0417aa8>] (ec_device_ioctl_xcmd+0xe0/0x198) from [<c0417ba4>] (ec_device_ioctl+0x44/0x5c)
[  271.770535] [<c0417ba4>] (ec_device_ioctl+0x44/0x5c) from [<c020ce88>] (do_vfs_ioctl+0x4a0/0x5c4)
[  271.770547] [<c020ce88>] (do_vfs_ioctl+0x4a0/0x5c4) from [<c020d01c>] (sys_ioctl+0x70/0xa8)
[  271.770560] [<c020d01c>] (sys_ioctl+0x70/0xa8) from [<c0105fc0>] (ret_fast_syscall+0x0/0x30)
[  271.770571] Code: e1530002 e50b6060 e50b805c daffffc3 (e7f001f2) 
[  271.770581] ---[ end trace 62b8781f7bc66161 ]---

===

Full ramoops attached.  No idea why this would have shown up suddenly.  Bisecting to get the exact first revision that failed seems like it would be a sane first step...

Deleted: console-ramoops (7) 45.6 KB

console-ramoops (7) 45.6 KB View Download

9592.78.0 - I personally confirmed this is bad
9460.76.0 - reported above OK

Run a bisect:

9587.0.0 - bad
9523.0.0 - good
9555.0.0 - good
9571.0.0 - bad
9563.0.0 - good
9567.0.0 - good
9569.0.0 - bad
9568.0.0 - bad

...thus break is from 9567.0.0 to 9568.0.0...

https://crosland.corp.google.com/log/9567.0.0..9568.0.0


Given the crash my first instinct is:

src/third_party/flashrom:
  a36ff507	264034	38018926	Mon Mar 23 23:36:47 2015	gwendal@chromium.org	cros_ec: Add v2 flash support.
  c79d141c	506901	38018926	Tue May 16 18:47:16 2017	gwendal@chromium.org	cros_ec: Add latest cros_ec_commands


...I'll see if I can get a little more details...

Replicated crash with "chromeos-firmware-update --mode=recovery".  

---

OK, also replicated the crash with:

mkdir -p /tmp/foo
chromeos-firmwareupdate --sb_extract /tmp/foo/
flashrom -p ec --fast-verify -w /tmp/foo/ec.bin

---

OK, tried building flashrom at a36ff507c593ea1acddee9f832bb91f9383c2e58~ (AKA the change before the "Add v2 flash support." change) and the problem went away.  Then tried building with a36ff507c593ea1acddee9f832bb91f9383c2e58 and the problem came back.

So problem is caused by:

  a36ff507c593 cros_ec: Add v2 flash support.

Adding folks from the CL that broke things and assigning to Gwendal.  It's fairly clear that the CL is the root cause here since it massively changed the way decide how big our flash transfers are going to be.  ..and the failure is basically caused by userspace initiating too big of a transfer.

Ideally nothing that userspace does should cause the kernel to execute a BUG_ON (instead we should return an error code), but at least we don't seem to be clobbering any memory that I can tell.

The problem is the EC use SPI_MAX_REQUEST_SIZE (0x220 = 536) when responding to EC_CMD_GET_PROTOCOL_INFO, but the SPI bus is not able to handle request larger than 256 bytes. 

flashrom is using that number (536) as .max_data_[read|write] requesting 512 bytes of data.

What is happening in 3.8 does not support EC version 3 command interface, (introduced in 3.14), so it limits commands to ~256 bytes.

kernel is not indicating which version it is supporting

pit EC support both version 2 and 3, newer EC only supports version 3 (CL https://chromium-review.googlesource.com/291411) unless explicitly requested.

My thinking is to use 128 bytes if the EC supports version 2 (the kernel may use that protocol). On EC that's only support version 3, hope the kernel is also using version 3...

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

commit cf540ef8391df0c094546751e6e0aeb82c956eff
Author: Gwendal Grignou <gwendal@chromium.org>
Date: Fri Aug 11 17:35:53 2017

cros_ec: Limit commands to 128 bytes when v2 EC protocol is supported

When EC reports that both v2 and v3 protocol are supported, it may
indicates the kernel only support protocol v2.
In that case, the kernel may not support large commands and crash.

BUG= chromium:733407 
BRANCH=none
TEST=Use flashrom -p ec -V -r /tmp/ec.bin.
On pit, without the change, we try to send 512 long commands and fail at
kernel level.
With that changes:
On pit: uses 128 bytes commands.
On glimmer: uses 128 bytes as well (v2 and v3 supported, even if we run
kernel 4.4).
On cyan: uses 248 bytes commands (only v3 supported, in EC since
cl/291411).

Change-Id: I89b8b9d9171c6737895b278854a13151add8fe59
Signed-off-by: Gwendal Grignou <gwendal@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/611011
Commit-Ready: Douglas Anderson <dianders@chromium.org>
Reviewed-by: Hung-Te Lin <hungte@chromium.org>
Reviewed-by: Douglas Anderson <dianders@chromium.org>

[modify] https://crrev.com/cf540ef8391df0c094546751e6e0aeb82c956eff/cros_ec.c

This bug requires manual review: M61 has already been promoted to the beta branch, so this requires manual review
Please contact the milestone owner if you have questions.
Owners: amineer@(Android), cmasso@(iOS), ketakid@(ChromeOS), govind@(Desktop)

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

Approving merge to M61 Chrome OS.

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

commit 422668bd515ebd5feba885e2142dc9ec1ffd5f67
Author: Gwendal Grignou <gwendal@chromium.org>
Date: Fri Aug 11 19:16:06 2017

cros_ec: Limit commands to 128 bytes when v2 EC protocol is supported

When EC reports that both v2 and v3 protocol are supported, it may
indicates the kernel only support protocol v2.
In that case, the kernel may not support large commands and crash.

BUG= chromium:733407 
BRANCH=none
TEST=Use flashrom -p ec -V -r /tmp/ec.bin.
On pit, without the change, we try to send 512 long commands and fail at
kernel level.
With that changes:
On pit: uses 128 bytes commands.
On glimmer: uses 128 bytes as well (v2 and v3 supported, even if we run
kernel 4.4).
On cyan: uses 248 bytes commands (only v3 supported, in EC since
cl/291411).

Change-Id: I89b8b9d9171c6737895b278854a13151add8fe59
Signed-off-by: Gwendal Grignou <gwendal@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/611011
Commit-Ready: Douglas Anderson <dianders@chromium.org>
Reviewed-by: Hung-Te Lin <hungte@chromium.org>
Reviewed-by: Douglas Anderson <dianders@chromium.org>
(cherry picked from commit cf540ef8391df0c094546751e6e0aeb82c956eff)
Reviewed-on: https://chromium-review.googlesource.com/611489

[modify] https://crrev.com/422668bd515ebd5feba885e2142dc9ec1ffd5f67/cros_ec.c

let's get some soaking time and verification in ToT/M61 before merging to M60

Marking as fixed to get verification going 

This issue has been approved for a merge. Please merge the fix to any appropriate branches as soon as possible!

If all merges have been completed, please remove any remaining Merge-Approved labels from this issue.

Thanks for your time! To disable nags, add the Disable-Nags label.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

 songsuk@ could you confirm the fix in either ToT or M61?

Verified in Chrome 61.0.3163.47/CrOS 9765.29.0 - pit

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

commit c719fb7b1914e90dd8bfd4995a07939586c13b08
Author: Gwendal Grignou <gwendal@chromium.org>
Date: Tue Aug 15 17:29:10 2017

cros_ec: Limit commands to 128 bytes when v2 EC protocol is supported

When EC reports that both v2 and v3 protocol are supported, it may
indicates the kernel only support protocol v2.
In that case, the kernel may not support large commands and crash.

BUG= chromium:733407 
BRANCH=none
TEST=Use flashrom -p ec -V -r /tmp/ec.bin.
On pit, without the change, we try to send 512 long commands and fail at
kernel level.
With that changes:
On pit: uses 128 bytes commands.
On glimmer: uses 128 bytes as well (v2 and v3 supported, even if we run
kernel 4.4).
On cyan: uses 248 bytes commands (only v3 supported, in EC since
cl/291411).

Change-Id: I89b8b9d9171c6737895b278854a13151add8fe59
Signed-off-by: Gwendal Grignou <gwendal@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/611011
Commit-Ready: Douglas Anderson <dianders@chromium.org>
Reviewed-by: Hung-Te Lin <hungte@chromium.org>
Reviewed-by: Douglas Anderson <dianders@chromium.org>
(cherry picked from commit cf540ef8391df0c094546751e6e0aeb82c956eff)
Reviewed-on: https://chromium-review.googlesource.com/615190

[modify] https://crrev.com/c719fb7b1914e90dd8bfd4995a07939586c13b08/cros_ec.c

Tried M61.0.3163.47:9765.29.0 dev pit on two Pit devices and at the end of the installation, I encountered "An unexpected error has occurred. Please refer to ...".  Nevertheless, after removing the USB stick and manually rebooting the device, the system came up updated and ran fine.

@33: that's not good.  Can you provide logs?  Possibly the firmware update is failing still but it's just not crashing the kernel anymore?

Sorry, I retried M61.0.3163.47:9765.29.0 dev pit using a different USB stick and no error was encountered at the end of the recovery.  The USB stick I used earlier could be bad.  So, this issue is verified fixed.

Append the recovery log anyway for #35 (and #33 if you have them).
We want to be sure a firmware upgrade happen with the new USB stick.
It may be possible the write phase worked, but not verify and at the second recovery no flash operation happened.

Attached recovery logs of one that gave the same error this morning.

Deleted: recovery_logs.tar.gz 53.2 KB

recovery_logs.tar.gz 53.2 KB Download

Something is giving crazy disk errors:

[    5.252341] EXT4-fs (dm-0): couldn't mount as ext3 due to feature incompatibilities
[    5.253125] EXT4-fs (dm-0): mounting ext2 file system using the ext4 subsystem
[    5.257665] EXT4-fs (dm-0): mounted filesystem without journal. Opts: (null)
[    5.264784] EXT4-fs (sda1): couldn't mount as ext3 due to feature incompatibilities
[    5.265737] EXT4-fs (sda1): mounting ext2 file system using the ext4 subsystem
[    5.267805] EXT4-fs (sda1): mounted filesystem without journal. Opts: (null)
[   43.881237] tpm_i2c_infineon 9-0020: command 0x4000000a (size 12) returned code 0x0
[   43.936168] tpm_i2c_infineon 9-0020: command 0x5d (size 10) returned code 0x0
[   43.956182] tpm_i2c_infineon 9-0020: command 0x6f (size 10) returned code 0x0
[   43.976977] tpm_i2c_infineon 9-0020: command 0x72 (size 11) returned code 0x0
[   44.011346] tpm_i2c_infineon 9-0020: command 0xcc (size 101) returned code 0x0
[   44.031308] tpm_i2c_infineon 9-0020: command 0x4000000a (size 12) returned code 0x0
[   46.911607] EXT4-fs (loop0): mounted filesystem without journal. Opts: (null)
[   46.982164] EXT4-fs (loop1): mounting ext2 file system using the ext4 subsystem
[   46.983590] EXT4-fs (loop1): mounted filesystem without journal. Opts: (null)
[   47.620473]  mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 p10 p11 p12
[  137.139281] EXT4-fs (loop2): mounted filesystem with ordered data mode. Opts: (null)
[  137.176289] EXT4-fs error (device loop1): ext4_get_branch:169: inode #16: block 5408: comm cp: invalid block
[  137.189393] EXT4-fs error (device loop1): ext4_map_blocks:544: inode #16: block 5408: comm cp: lblock 64 mapped to illegal pblock (length 64)
[  137.189484] EXT4-fs error (device loop1): ext4_map_blocks:544: inode #16: block 5408: comm cp: lblock 64 mapped to illegal pblock (length 1)
[  137.189577] EXT4-fs error (device loop1): ext4_map_blocks:544: inode #16: block 5409: comm cp: lblock 65 mapped to illegal pblock (length 63)
[  137.189662] EXT4-fs error (device loop1): ext4_map_blocks:544: inode #16: block 5409: comm cp: lblock 65 mapped to illegal pblock (length 1)
[  137.189750] EXT4-fs error (device loop1): ext4_map_blocks:544: inode #16: block 5410: comm cp: lblock 66 mapped to illegal pblock (length 62)
[  137.189835] EXT4-fs error (device loop1): ext4_map_blocks:544: inode #16: block 5410: comm cp: lblock 66 mapped to illegal pblock (length 1)
[  137.189931] EXT4-fs error (device loop1): ext4_map_blocks:544: inode #16: block 5411: comm cp: lblock 67 mapped to illegal pblock (length 61)
[  137.190028] EXT4-fs error (device loop1): ext4_map_blocks:544: inode #16: block 5411: comm cp: lblock 67 mapped to illegal pblock (length 1)
[  137.190132] EXT4-fs error (device loop1): ext4_map_blocks:544: inode #16: block 5412: comm cp: lblock 68 mapped to illegal pblock (length 60)
[  137.190231] EXT4-fs error (device loop1): ext4_map_blocks:544: inode #16: block 5412: comm cp: lblock 68 mapped to illegal pblock (length 1)
[  137.190335] EXT4-fs error (device loop1): ext4_map_blocks:544: inode #16: block 5413: comm cp: lblock 69 mapped to illegal pblock (length 59)
...
...
...

I'm not 100% sure that the loop here corresponds to the USB device, but if changing USB devices fixed your problems then it seems sane that's the problem.  I'd be OK with closing this, but if someone wants to confirm further that the loop really truly was the USB device then they could.