Samus sometimes wont wake from sleep with dock connected |
||||
Issue descriptionChrome Version: 64.0.3283.101 OS: 10176.54.0 beta-channel samus What steps will reproduce the problem? (1) Have a Pluggable dock connected to an external display, mouse, keyboard, network. (2) Leave for long enough for the device to fall asleep (3) Press a key on either internal or external keyboard to wake What is the expected result? Device wakes and is usable. What happens instead? Roll 1d10. 1-6: Wakes normally 7-8: Wakes and is usable but takes 30s+ to do so. 9: Will not wake until dock is unplugged and then suddenly reboots (see https://listnr.corp.google.com/report/84978084141) 0: Will not wake until dock is unpligged and then other weirdness happens (see https://listnr.corp.google.com/report/84969198527) This has happened enough now that I'm filing a bug for it rather than just feedback Not sure if this is an issue with USB or graphics. Adding components and CCs for people who might have ideas.
,
Jan 26 2018
End of eventlog from 84978084141: ... 194 | 2018-01-24 13:29:12 | ACPI Enter | S3 195 | 2018-01-24 13:30:30 | ACPI Wake | S3 196 | 2018-01-24 13:30:30 | Wake Source | GPIO | 27 197 | 2018-01-24 13:30:30 | EC Event | Lid Open 198 | 2018-01-24 13:35:54 | ACPI Enter | S3 199 | 2018-01-24 14:05:52 | ACPI Wake | S3 200 | 2018-01-24 14:05:52 | Wake Source | GPIO | 27 201 | 2018-01-24 14:05:52 | EC Event | Lid Open 202 | 2018-01-24 14:05:52 | EC Event | Battery Status Request 203 | 2018-01-24 17:04:42 | ACPI Enter | S3 204 | 2018-01-25 10:31:13 | ACPI Wake | S3 205 | 2018-01-25 10:31:13 | Wake Source | GPIO | 27 206 | 2018-01-25 10:31:13 | EC Event | Key Pressed and 84969198527: ... 178 | 2018-01-22 17:51:27 | ACPI Enter | S3 179 | 2018-01-23 09:18:25 | ACPI Wake | S3 180 | 2018-01-23 09:18:25 | Wake Source | GPIO | 27 181 | 2018-01-23 09:18:25 | EC Event | Key Pressed 182 | 2018-01-23 11:26:32 | System boot | 149 183 | 2018-01-23 11:26:32 | SUS Power Fail 184 | 2018-01-23 11:26:32 | Power Button Override 185 | 2018-01-23 11:26:32 | System Reset 186 | 2018-01-23 11:26:32 | Log area cleared | 1027 187 | 2018-01-23 11:26:32 | ACPI Wake | S5 188 | 2018-01-23 11:26:32 | Wake Source | Power Button | 0 189 | 2018-01-23 11:26:32 | EC Event | Power Button I don't know what's expected vs. not there.
,
Jan 26 2018
on 84978084141 ... the 'sudden reboot is a mystery AFAICT. Looking through syslog 2018-01-25T10:31:35.341525-08:00 NOTICE powerd_suspend[3360]: wake source: SMI_STS: MCSMI GPE0 PM1 #015#012PM1_STS: WAK #015#012GPE0_STS: GPIO27 #015 So it wakes ... and then remains up for quite a while (45min) ... last line of syslog presumably before feedback filed 2018-01-25T11:13:27.977895-08:00 DEBUG kernel: [105603.335020] SELinux: initialized (dev proc, type proc), uses genfs_contexts In any case there's definitely some USB unhappiness in that 45min timeframe, 2018-01-25T10:31:35.325611-08:00 ERR kernel: [103066.857609] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 30. 2018-01-25T10:31:35.325613-08:00 ERR kernel: [103067.010616] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 30. 2018-01-25T10:31:35.325929-08:00 ERR kernel: [103067.462516] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 32. 2018-01-25T10:31:35.325931-08:00 ERR kernel: [103067.539357] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 32. 2018-01-25T10:31:35.325945-08:00 ERR kernel: [103072.751535] hub 1-5.1:1.0: hub_port_status failed (err = -110) 2018-01-25T10:31:35.325946-08:00 ERR kernel: [103077.755572] hub 1-5.1:1.0: hub_port_status failed (err = -110) 2018-01-25T10:31:35.325947-08:00 ERR kernel: [103082.759614] hub 1-5.1:1.0: hub_port_status failed (err = -110) 2018-01-25T10:31:35.325949-08:00 ERR kernel: [103087.763668] hub 1-5.1:1.0: hub_port_status failed (err = -110) 2018-01-25T11:11:53.360895-08:00 ERR kernel: [105508.641500] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:11:54.360896-08:00 ERR kernel: [105509.642340] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:11:55.360913-08:00 ERR kernel: [105510.643117] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:11:56.360922-08:00 ERR kernel: [105511.643946] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:11:57.360887-08:00 ERR kernel: [105512.644751] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:11:57.360904-08:00 ERR kernel: [105512.644759] hub 1-5.1:1.0: Cannot enable port 3. Maybe the USB cable is bad? 2018-01-25T11:11:58.361920-08:00 ERR kernel: [105513.646595] hub 1-5.1:1.0: cannot disable port 3 (err = -110) 2018-01-25T11:11:59.361967-08:00 ERR kernel: [105514.647395] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:00.361884-08:00 ERR kernel: [105515.648146] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:01.361926-08:00 ERR kernel: [105516.649027] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:02.361890-08:00 ERR kernel: [105517.649766] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:03.361887-08:00 ERR kernel: [105518.650614] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:03.361899-08:00 ERR kernel: [105518.650622] hub 1-5.1:1.0: Cannot enable port 3. Maybe the USB cable is bad? 2018-01-25T11:12:04.361886-08:00 ERR kernel: [105519.651420] hub 1-5.1:1.0: cannot disable port 3 (err = -110) 2018-01-25T11:12:05.361947-08:00 ERR kernel: [105520.652410] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:06.361987-08:00 ERR kernel: [105521.653134] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:07.361920-08:00 ERR kernel: [105522.653864] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:08.361908-08:00 ERR kernel: [105523.654644] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:09.361990-08:00 ERR kernel: [105524.655612] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:09.362014-08:00 ERR kernel: [105524.655634] hub 1-5.1:1.0: Cannot enable port 3. Maybe the USB cable is bad? 2018-01-25T11:12:10.361943-08:00 ERR kernel: [105525.656371] hub 1-5.1:1.0: cannot disable port 3 (err = -110) 2018-01-25T11:12:11.361961-08:00 ERR kernel: [105526.657136] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:12.361971-08:00 ERR kernel: [105527.658031] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:13.361989-08:00 ERR kernel: [105528.658801] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:14.361992-08:00 ERR kernel: [105529.659612] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:15.361965-08:00 ERR kernel: [105530.660471] hub 1-5.1:1.0: cannot reset port 3 (err = -110) 2018-01-25T11:12:15.361989-08:00 ERR kernel: [105530.660495] hub 1-5.1:1.0: Cannot enable port 3. Maybe the USB cable is bad? 2018-01-25T11:12:16.361997-08:00 ERR kernel: [105531.661193] hub 1-5.1:1.0: cannot disable port 3 (err = -110) 2018-01-25T11:12:16.362022-08:00 ERR kernel: [105531.661247] hub 1-5.1:1.0: unable to enumerate USB device on port 3 2018-01-25T11:12:17.361923-08:00 ERR kernel: [105532.662073] hub 1-5.1:1.0: cannot disable port 3 (err = -110) 2018-01-25T11:12:59.101916-08:00 ERR kernel: [105574.436216] Bluetooth: hci0 setting interface failed (28) Not particularly familiar w/ 'ERR kernel: [103066.857609] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 30.' But the rest of the signature reminds me of a similar bug on Spring where bad or particularly long USB cable + an unpowered hub would do the same thing rendering that USB port useless till reboot. Might be worth filing feedback when 1-6 and 7-8 occur so we can contrast against the failure. I suspect its all USB likely related to VBUS supply being compromised depending upon how much power is sunk upon resume which then manifests in anything from normalcy in the case of 1-6 to USB devices stuggling to enumerate in 7-8 to just down right badness.
,
Jan 26 2018
Thanks for digging into it. I'll gather more reports with that dock connected. (It's currently packed for the move to 42 so it'll be next week.)
,
Jan 30 2018
,
Jan 31 2018
for 7-8 feedback, powerd.LATEST, [0129/164627:INFO:state_controller.cc(971)] Ready to perform idle action (suspend) after 30m30s [0129/164627:INFO:suspender.cc(383)] Starting request 88735746 [0129/164627:INFO:daemon.cc(595)] Reading wakeup count from /sys/power/wakeup_count [0129/164627:INFO:daemon.cc(599)] Read wakeup count 3878 [0129/164627:INFO:internal_backlight_controller.cc(693)] Setting resume brightness to 636 (80%) [0129/164627:INFO:suspend_delay_controller.cc(137)] Announcing suspend request 88735746 with 3 pending delay(s) and 0 outstanding delay(s) from previous request [0129/164627:INFO:suspend_delay_controller.cc(86)] Got notification that delay 88735745 (shill) is ready for suspend request 88735746 from :1.10 [0129/164628:INFO:suspend_delay_controller.cc(86)] Got notification that delay 88735749 (DisplayLinkSuspendHandle) is ready for suspend request 88735746 from :1.90 [0129/164647:WARNING:suspend_delay_controller.cc(205)] Timed out while waiting for suspend request 88735746 readiness confirmation for 1 delay(s): 88735748 (:1.55: chrome) [0129/164647:INFO:suspend_delay_controller.cc(223)] Notifying observers that suspend is ready [0129/164647:INFO:suspender.cc(458)] Starting suspend [0129/164647:INFO:main.cc(244)] Running "/usr/bin/powerd_setuid_helper --action=suspend --suspend_wakeup_count_valid --suspend_wakeup_count=3878" [0129/165450:INFO:daemon.cc(687)] powerd_suspend returned 0 [0129/165450:INFO:suspender.cc(414)] Finishing request 88735746 successfully [0129/165450:INFO:state_controller.cc(96)] Undimming screen [0129/165450:INFO:internal_backlight_controller.cc(693)] Setting resume brightness to 636 (80%) [0129/165450:INFO:state_controller.cc(96)] Turning screen on [0129/165450:INFO:internal_backlight_controller.cc(693)] Setting resume brightness to 636 (80%) [0129/165450:INFO:display_power_setter.cc(81)] Asking DisplayService to turn all displays on [0129/165454:INFO:internal_backlight_controller.cc(677)] Setting brightness to 636 (80%) over 0 ms Looks like ~4sec (165454 - 165450) to go from resume to userland request that brightness be restored. Didn't see any DRM related warn/errs that make me think display driver got lost. I do see, 2018-01-29 16:55:02.736 8 4400:4400: screen_locker.cc(346): Hiding the lock screen. 2018-01-29 16:55:03.106 8 4400:4400: screen_locker.cc(560): Deleting ScreenLocker 0x1f24ed5d05a0 2018-01-29 16:55:03.106 8 4400:4400: screen_locker.cc(573): Destroying ScreenLocker 0x1f24ed5d05a0 2018-01-29 16:55:03.106 8 4400:4400: screen_locker.cc(585): Emitting SCREEN_LOCK_STATE_CHANGED with state=0 2018-01-29 16:55:03.106 8 4400:4400: screen_locker.cc(590): Calling session manager's HandleLockScreenDismissed D-Bus method which would put resume ~12sec. Wonder if you're using BT smart unlock? I see a fair number of BT scans after initial resume .. wondering if there's some interaction there that delays things?
,
Feb 1 2018
Yes, I have smart unlock enabled. I'll try turning it off to see if things improve.
,
Feb 9 2018
Sorry for delays in responses here. I received a new Pixelbook and a new Belkin dock a few days ago, so I've been playing with them. I'll fire up the Samus and pluggable again soon and see if I can get more data.
,
Feb 16 2018
Feel free to assign this back to Benson or I once if it still fails upon retesting.
,
Feb 17 2018
Went back to test again and I now have bug 813261 making it difficult to quickly put things to sleep with the dock connected. :-/ I'll update as soon as I can get a sensible number of tries done. Thanks folks.
,
Feb 20 2018
Here's a long wake with smartlock disabled. Sorry it took a while to get. https://listnr.corp.google.com/report/85093414363 |
||||
►
Sign in to add a comment |
||||
Comment 1 by reillyg@chromium.org
, Jan 25 2018