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

Issue 861641 link

Starred by 6 users

Issue metadata

Status: Assigned
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

peppy M67 10575.58.0 unresponsive after resume ( screen black?) user induced SysRq

Project Member Reported by derat@chromium.org, Jul 9

Issue description

(forked from issue 859358)

http://feedback/#/Report/85540072740 contains a report of a peppy M67 10575.58.0 device not waking from sleep.

powerd.PREVIOUS ends with this:

...
[0709/001530:INFO:suspend_delay_controller.cc(223)] Notifying observers that suspend is ready
[0709/001530:INFO:suspender.cc(450)] Starting suspend
[0709/001530:INFO:main.cc(258)] Running "/usr/bin/powerd_setuid_helper --action=suspend  --suspend_wakeup_count_valid --suspend_wakeup_count=36425"
<bunch of garbage indicating a crash>

powerd.LATEST starts with this:

[0709/001728:INFO:main.cc(307)] vcsid 0.0.2-r2708-1067ee4893de6e42d8071e96d823d882a8f3da36
[0709/001728:INFO:main.cc(313)] System uptime: 3s
...

eventlog ends with this:

...
39 | 2018-07-09 00:15:35 | ACPI Enter | S3
40 | 2018-07-09 00:16:49 | EC Event | Lid Open
41 | 2018-07-09 00:16:49 | ACPI Wake | S3
42 | 2018-07-09 00:16:49 | Wake Source | PCI Express | 0
43 | 2018-07-09 00:17:22 | Kernel Event | Panic
44 | 2018-07-09 00:17:22 | System boot | 17
45 | 2018-07-09 00:17:22 | System Reset
46 | 2018-07-09 00:17:23 | Chrome OS Developer Mode

Here's the relevant part of syslog:

...
2018-07-08T23:29:55.557849-04:00 ERR cras_server[1259]: Unable to find the best channel map
2018-07-08T23:30:52.950572-04:00 ERR cras_server[1259]: Unable to find the best channel map
2018-07-08T23:39:41.845800-04:00 ERR cras_server[1259]: Unable to find the best channel map
2018-07-08T23:46:21.081951-04:00 ERR cras_server[1259]: pcm_avail returned frames larger than buf_size: HDA Intel PCH: ALC283 Analog:1,0: 16392 > 16384 for 1 times
2018-07-09T00:11:33.775191-04:00 INFO kernel: [ 3607.710024] tpm_tis tpm_tis: command 0x65 (size 20) returned code 0x0
2018-07-09T00:11:33.803097-04:00 INFO kernel: [ 3607.739996] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-07-09T00:11:33.839094-04:00 INFO kernel: [ 3607.776249] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-07-09T00:15:29.576437-04:00 ERR btdispatch[1539]: Failed to call method: org.bluez.Adapter1.PauseDiscovery: object_path= /org/bluez/hci0: org.bluez.Error.NotReady: Resource Not Ready
2018-07-09T00:15:30.787648-04:00 NOTICE powerd_suspend[10828]: Going to suspend-to-RAM state: args=--suspend_duration=-1 --nosuspend_to_idle --wakeup_count=36425
2018-07-09T00:15:30.878245-04:00 NOTICE powerd_suspend[10885]: Skipping disable BT HCI mode change event on non-Intel BT
2018-07-09T00:15:30.884275-04:00 NOTICE powerd_suspend[10888]: Available order 3 pages: 4393
2018-07-09T00:15:30.889522-04:00 NOTICE powerd_suspend[10891]: Finalizing suspend
<bunch of garbage from crash>
2018-07-09T00:17:27.657293-04:00 INFO kernel: [
   0.000000] Initializing cgroup subsys cpu
2018-07-09T00:17:27.657395-04:00 NOTICE kernel: [    0.000000] Linux version 3.8.11 (chrome-bot@cros-beefy246-c2) (gcc version 4.9.x 20150123
(prerelease) (4.9.2_cos_gg_4.9.2-r185-2cdcfd30c27f0d836cc477f2ae9f456287fd6b1b_4.9.2-r185) ) #1 SMP Fri Jun 22 18:18:57 PDT 2018
...

I also see this in the feedback report:

[ 3879.792346] SysRq : Cros dump and crash
[ 3879.792377]   task                        PC stack   pid father
[ 3879.792409] powerd          D 0000011fbfa30407     0 11189      1 0x00000000
[ 3879.792457]  ffff88006a01bce0 0000000000000086 ffff88005ae01e00 ffff88006a01bfd8
[ 3879.792501]  ffff88006a01bfd8 00000000000122c0 ffff880055d3d280 000000010036a260
[ 3879.792541]  ffff88006a01bd10 ffff88006a01bfd8 ffffffff965afa40 ffffffff965b0078
[ 3879.792578] Call Trace:
[ 3879.792601]  [<ffffffff96155fff>] schedule+0x53/0x55
[ 3879.792621]  [<ffffffff9615357d>] schedule_timeout+0x3bc/0x51c
[ 3879.792644]  [<ffffffff95d08bff>] ? ftrace_raw_output_timer_class+0xa7/0xa7
[ 3879.792666]  [<ffffffff961536fb>] schedule_timeout_uninterruptible+0x1e/0x20
[ 3879.792687]  [<ffffffff961536fb>] ? schedule_timeout_uninterruptible+0x1e/0x20
[ 3879.792709]  [<ffffffff95d08f15>] msleep+0x51/0x5b
[ 3879.792731]  [<ffffffffc022a4b7>] isl29018_read_sensor_input+0x60/0xbf [isl29018]
[ 3879.792755]  [<ffffffffc022a627>] isl29018_read_lux+0x3b/0xf9 [isl29018]
[ 3879.792777]  [<ffffffffc022a786>] isl29018_read_raw+0xa1/0x15a [isl29018]
[ 3879.792802]  [<ffffffffc0213291>] iio_read_channel_info+0x47/0x15b [industrialio]
[ 3879.792825]  [<ffffffff95f77911>] dev_attr_show+0x28/0x4c
[ 3879.792845]  [<ffffffff95c5d7f1>] sysfs_read_file+0xd0/0x13e
[ 3879.792865]  [<ffffffff95c40ac9>] sys_pread64+0x186/0x21b
[ 3879.792887]  [<ffffffff96157968>] system_call_fastpath+0x16/0x1b
[ 3879.792905] chrome          D 0000010f0c08e4e1     0  1035    806 0x00000002
[ 3879.792947]  ffff88006a19fa80 0000000000000046 ffff8801000ad280 ffff88006a19ffd8
[ 3879.792984]  ffff88006a19ffd8 00000000000122c0 ffff88006d968780 7fffffffffffffff
[ 3879.793020]  7fffffffffffffff ffff88006a19fbf8 ffff88006d968780 0000000000000002
[ 3879.793057] Call Trace:
[ 3879.793072]  [<ffffffff96155fff>] schedule+0x53/0x55
[ 3879.793090]  [<ffffffff9615320c>] schedule_timeout+0x4b/0x51c
[ 3879.793113]  [<ffffffff95c1f8bd>] ? find_get_pages_tag+0xf3/0x156
[ 3879.793134]  [<ffffffff96155eb5>] wait_for_common+0x15c/0x191
[ 3879.793153]  [<ffffffff96155eb5>] ? wait_for_common+0x15c/0x191
[ 3879.793173]  [<ffffffff95c0b3bf>] ? wake_up_state+0x10/0x10
[ 3879.793194]  [<ffffffff95c1cbfd>] ? __call_rcu.constprop.37+0x3c5/0x3c5
[ 3879.793215]  [<ffffffff96155faa>] wait_for_completion+0x1d/0x1f
[ 3879.793237]  [<ffffffff95d15cd5>] wait_rcu_gp+0x6e/0x8e
[ 3879.793257]  [<ffffffff95d15c53>] ? ftrace_raw_output_rcu_utilization+0xa7/0xa7
[ 3879.793281]  [<ffffffff95d4f882>] synchronize_sched+0x41/0x43
[ 3879.793300]  [<ffffffff95d4f882>] ? synchronize_sched+0x41/0x43
[ 3879.793321]  [<ffffffff9600a16d>] evdev_release+0x8b/0xe7
[ 3879.793340]  [<ffffffff9600a0e2>] ? evdev_open+0x1b5/0x1b5
[ 3879.793358]  [<ffffffff95c40eef>] __fput+0x105/0x1f1
[ 3879.793376]  [<ffffffff95c40fe9>] ____fput+0xe/0x10
[ 3879.793396]  [<ffffffff95c06c2a>] task_work_run+0x81/0x97
[ 3879.793417]  [<ffffffff95cff3e8>] do_exit+0x3b8/0x1080
[ 3879.793437]  [<ffffffff96156aa9>] ? _raw_spin_unlock_irq+0xe/0x11
[ 3879.793456]  [<ffffffff961559eb>] ? __schedule+0x5cb/0x8dc
[ 3879.793477]  [<ffffffff95d01080>] do_group_exit+0x42/0xb0
[ 3879.793498]  [<ffffffff95d0cfe2>] get_signal_to_deliver+0x554/0x573
[ 3879.793519]  [<ffffffff96156aa9>] ? _raw_spin_unlock_irq+0xe/0x11
[ 3879.793541]  [<ffffffff95cc959b>] do_signal+0x43/0x65f
[ 3879.793561]  [<ffffffff95c06f30>] ? remove_wait_queue+0x4d/0x52
[ 3879.793583]  [<ffffffff95d0135a>] ? sys_wait4+0xb0/0xd4
[ 3879.793601]  [<ffffffff95c00614>] do_notify_resume+0x29/0x5b
[ 3879.793622]  [<ffffffff96157b89>] int_signal+0x12/0x17
[ 3879.793650] kworker/u:24    D 0000011fbfe59a2e     0 10920      2 0x00000000
[ 3879.793689]  ffff880012653be0 0000000000000046 ffff8801000ac380 ffff880012653fd8
[ 3879.793725]  ffff880012653fd8 00000000000122c0 ffff88003f152d00 000000010036a298
[ 3879.793761]  ffff880012653c10 ffff880012653fd8 ffffffff965afa40 ffffffff965b03f8
[ 3879.793798] Call Trace:
[ 3879.793814]  [<ffffffff96155fff>] schedule+0x53/0x55
[ 3879.793832]  [<ffffffff9615357d>] schedule_timeout+0x3bc/0x51c
[ 3879.793852]  [<ffffffff95d08bff>] ? ftrace_raw_output_timer_class+0xa7/0xa7
[ 3879.793874]  [<ffffffff961536fb>] schedule_timeout_uninterruptible+0x1e/0x20
[ 3879.793895]  [<ffffffff961536fb>] ? schedule_timeout_uninterruptible+0x1e/0x20
[ 3879.793917]  [<ffffffff95d08f15>] msleep+0x51/0x5b
[ 3879.793937]  [<ffffffff96085648>] netdev_run_todo+0x169/0x25a
[ 3879.793957]  [<ffffffff95d4fa21>] ? synchronize_rcu_expedited+0xe/0x10
[ 3879.793980]  [<ffffffff9608de64>] rtnl_unlock+0xe/0x10
[ 3879.793999]  [<ffffffff96081d33>] default_device_exit_batch+0xb6/0xd9
[ 3879.794021]  [<ffffffff9607d67e>] ops_exit_list+0x2c/0x5b
[ 3879.794040]  [<ffffffff9607e0ef>] cleanup_net+0x105/0x1b5
[ 3879.794061]  [<ffffffff95c06241>] worker_thread+0x551/0x77e
[ 3879.794081]  [<ffffffff95c05cf0>] ? worker_set_flags+0xec/0xec
[ 3879.794103]  [<ffffffff95d18434>] kthread+0xc3/0xcb
[ 3879.794124]  [<ffffffff95d18371>] ? __kthread_parkme+0x6b/0x6b
[ 3879.794145]  [<ffffffff9615789c>] ret_from_fork+0x7c/0xb0
[ 3879.794165]  [<ffffffff95d18371>] ? __kthread_parkme+0x6b/0x6b
[ 3880.794212] Kernel panic - not syncing: ChromeOS X Key
[ 3880.794231] Pid: 0, comm: swapper/0 Tainted: G        WC   3.8.11 #1
[ 3880.794247] Call Trace:
[ 3880.794258]  <IRQ>  [<ffffffff961527b7>] panic+0xcf/0x1e2
[ 3880.794291]  [<ffffffff95ef68a0>] sysrq_handle_cros_xkey+0x189/0x192
[ 3880.794314]  [<ffffffff95ef6b2e>] __handle_sysrq+0x9d/0x135
[ 3880.794335]  [<ffffffff95ef6d12>] sysrq_filter+0x117/0x1a4
[ 3880.794355]  [<ffffffff95cad2a9>] input_event+0x422/0x893
[ 3880.794375]  [<ffffffff9600be57>] atkbd_interrupt+0x49c/0x5a7
[ 3880.794396]  [<ffffffff9600b9bb>] ? atkbd_set_extra+0x156/0x156
[ 3880.794418]  [<ffffffff96001a0a>] serio_interrupt+0x48/0x81
[ 3880.794439]  [<ffffffff9600307d>] i8042_interrupt+0x297/0x2a9
[ 3880.794459]  [<ffffffff95c1aa10>] handle_irq_event+0x8d/0x1c8
[ 3880.794480]  [<ffffffff95c1b1ed>] handle_edge_irq+0xaa/0xc3
[ 3880.794498]  [<ffffffff95c00782>] handle_irq+0x11c/0x124
[ 3880.794517]  [<ffffffff961591da>] do_IRQ+0x4a/0xa1
[ 3880.794536]  [<ffffffff96156ec0>] common_interrupt+0x80/0x80
[ 3880.794552]  <EOI>  [<ffffffff95cb2f37>] ? cpuidle_wrap_enter+0x44/0x77
[ 3880.794584]  [<ffffffff95cb2f7a>] cpuidle_enter_tk+0x10/0x12
[ 3880.794604]  [<ffffffff95cb2e14>] cpuidle_idle_call+0x14b/0x22a
[ 3880.794624]  [<ffffffff95c00e6f>] cpu_idle+0xc0/0x100
[ 3880.794644]  [<ffffffff96145f69>] rest_init+0x6d/0x6f
[ 3880.794662]  [<ffffffff964d5b36>] start_kernel+0x39f/0x3c0
[ 3880.794682]  [<ffffffff964d52ad>] x86_64_start_reservations+0xb1/0xb4
[ 3880.794703]  [<ffffffff964d538d>] x86_64_start_kernel+0xdd/0xe2
[ 3880.794752] Kernel Offset: 0x14c00000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[ 3880.797140] gsmi: Log Shutdown Reason 0x02
[ 3880.818387] ACPI MEMORY or I/O RESET_REG.
 
Does look like device wakes after not being asleep for too long (200ms). Perhaps screen stays black?

[ 3848.392525] ACPI: Preparing to enter system sleep state S3
...
[ 3848.650560] PM: resume of devices complete after 125.499 msecs
[ 3848.650822] Restarting tasks ... 
...
[ 3879.792346] SysRq : Cros dump and crash

So at the time that user forced the panic (+31sec since resume) there's not much in the log,

[ 3848.665674] video LNXVIDEO:00: Restoring backlight state
[ 3848.695792] cfg80211: Calling CRDA to update world regulatory domain
[ 3848.807633] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 3848.807987] ata1.00: configured for UDMA/100
[ 3848.812272] usb 1-3: new high-speed USB device number 5 using xhci_hcd
[ 3848.885639] cfg80211: World regulatory domain updated:
[ 3848.885653] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[ 3848.885667] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm)
[ 3848.885679] cfg80211:   (2457000 KHz - 2482000 KHz @ 20000 KHz), (N/A, 2000 mBm)
[ 3848.885691] cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm)
[ 3848.885703] cfg80211:   (5170000 KHz - 5250000 KHz @ 80000 KHz), (N/A, 2000 mBm)
[ 3848.885715] cfg80211:   (5250000 KHz - 5330000 KHz @ 80000 KHz), (N/A, 2000 mBm)
[ 3848.885726] cfg80211:   (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm)
[ 3848.885738] cfg80211:   (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm)
[ 3848.885750] cfg80211:   (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm)
[ 3848.885959] cfg80211: Calling CRDA for country: US
[ 3848.891651] usb 1-3: New USB device found, idVendor=1bcf, idProduct=2c67, bcdDevice= 0.01
[ 3848.891669] usb 1-3: New USB device strings: Mfr=1, Product=2, SerialNumber=5
[ 3848.891692] usb 1-3: Product: HD WebCam
[ 3848.891702] usb 1-3: Manufacturer: SunplusIT Inc
[ 3848.903659] cfg80211: Regulatory domain changed to country: US
[ 3848.903674] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[ 3848.903688] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 3000 mBm)
[ 3848.903700] cfg80211:   (5170000 KHz - 5250000 KHz @ 80000 KHz), (N/A, 1700 mBm)
[ 3848.903712] cfg80211:   (5250000 KHz - 5330000 KHz @ 80000 KHz), (N/A, 2300 mBm)
[ 3848.903724] cfg80211:   (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2300 mBm)
[ 3848.903736] cfg80211:   (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 3000 mBm)
[ 3848.903748] cfg80211:   (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 4000 mBm)
[ 3848.965220] uvcvideo: Found UVC 1.00 device HD WebCam (1bcf:2c67)
[ 3848.973936] usb 1-4: USB disconnect, device number 4
[ 3850.074499] [drm] Enabling RC6 states: RC6 on, RC6p off, RC6pp off
[ 3850.524390] usb 1-4: new full-speed USB device number 6 using xhci_hcd
[ 3850.537377] usb 1-4: string descriptor 0 malformed (err = -61), defaulting to 0x0409
[ 3850.539452] usb 1-4: New USB device found, idVendor=0489, idProduct=e056, bcdDevice= 0.01
[ 3850.539480] usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=6
[ 3850.589334] usb 1-4: USB disconnect, device number 6
[ 3850.872363] usb 1-4: new full-speed USB device number 7 using xhci_hcd
[ 3850.885055] usb 1-4: string descriptor 0 malformed (err = -61), defaulting to 0x0409
[ 3850.887392] usb 1-4: New USB device found, idVendor=0489, idProduct=e056, bcdDevice= 0.02
[ 3850.887419] usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=6
[ 3879.348315] SysRq : Cros dump and crash





Labels: Hotlist-ConOps-CrOS
Summary: peppy M67 10575.58.0 unresponsive after resume ( screen black?) user induced SysRq (was: peppy doesn't wake from sleep)
Does appear SysRq crash got uploaded,

2018-07-09T00:17:39.003317-04:00 INFO crash_reporter[2270]: Found 0 kernel crashes in efi-pstore.
2018-07-09T00:17:39.042827-04:00 INFO crash_reporter[2270]: Received prior crash notification from kernel (signature kernel-ChromeOS X Key-EED63409) (handling)
2018-07-09T00:17:39.044153-04:00 INFO crash_reporter[2270]: Stored kcrash to /var/spool/crash/kernel.20180709.001739.0.kcrash

Not seeing an increase of SysRq reporting in general though,

https://crash.corp.google.com/browse?q=product_name%3D%27ChromeOS%27+AND+EXISTS+%28SELECT+1+FROM+UNNEST%28productdata%29+WHERE+Key%3D%27exec_name%27+AND+STRPOS%28Value%2C+%27kernel%27%29+%3E+0%29+AND+stable_signature%3D%27kernel-ChromeOS+X+Key-EED63409%27

So think we'll have to monitor this failure mechanism to see if its on the rise 
From https://crbug.com/859358#c17:

"Just sent feedback after the bug happened. I used Alt+Volup+X once which got it to show a picture again.

The report has 'crbug 859358' in the first line and is from this email."

http://feedback/#/Report/85561290741

Sign in to add a comment