afakhry@ can you look into this? I have one of these docks if you need to borrow it.

Could you file a feedback report is.rafique immediately after this happens? I understand you have to hard reboot the thing, but maybe there will be something in the logs from last boot. Please put this bug number in the feedback report : crbug.com/673040

Thanks.

Just to mention it, Ctrl+Shift+L doesn't put the system to sleep; it locks the screen and reduces the screen-dim/off (but not suspend, IIRC) delays.

Per the steps in the initial report, as long as there wasn't a 10+-minute gap between the Ctrl+Shift+L and disconnect/close-lid steps, it sounds like the dock was already disconnected when the system went to S3 and reconnected while it was suspended. I'd expect Chrome to reprobe displays on resume and see the external displays, which doesn't appear to be happening here.

After opening the lid, does disconnecting the dock bring things back? What about holding the brightness-up key on the builtin keyboard?

And yeah, please file a feedback report (immediately after rebooting and logging in, if that's the only way to get the system back) using Alt+Shift+i. The powerd log might be useful for seeing the sequence of events, and the kernel log might include USB problems.

We may get more complete logs if they're instead just downloaded from file:// URLs and then attached to this bug. After taking note of the time when the problem occurred, we'd want the corresponding logs (i.e. containing entries spanning the time of the problem) from the following locations, I think:

file:///var/log/power_manager (corresponding powerd.* file)
file:///var/log (corresponding messages* file)
file:///home/chronos/user/log (corresponding chrome_* file)

That's a displaylink dock, which is known to have suspend/resume issues right now.

Marcheu@ good catch. The original reporter said that the dock had three monitors attached, meaning that two of them will be using DL, and the third being on native DP Alt mode.

# sleep mode
[search][shift][l] doesn't put the system into proper sleep mode? My mistake, I thought it did (and the little red dot flashes as you would expect it to). I used to just write 'mem' to /sys/power/state before I discovered that key shortcut. In any case, all I'm trying to do there is put the machine to sleep without it going into "docked" mode (which is what would happen when you just closed the lid while connected to external displays - not great to hardcode that logic, IMHO).

# chromeos channel
Since filing this bug report, I've moved the machine off the dev channel and back onto the stable channel. However, the issue still persists. It doesn't always happen on stable (it would EVERY time on dev channel), but I've hit it twice yesterday already.

# logs
I'm attaching a tarball of all the logfiles you mentioned, covering yesterday.

# displays I'm using
To confirm, I'm using 4 displays as follows:
- 1 internal display
- 1 external display using DisplayPort
- 2 external displays using DisplayLink

Deleted: logs-for-bug-673040.tgz 257 KB

logs-for-bug-673040.tgz 257 KB Download

Thanks! The only point where I see the lid being closed in powerd's logs is here:

---

[1212/165202:INFO:daemon.cc(484)] Lid closed
[1212/165202:INFO:wakeup_controller.cc(166)] Inhibiting /sys/devices/pci0000:00/0000:00:15.1/i2c_designware.1/i2c-7/i2c-ELAN0000:00/input/input4
[1212/165202:INFO:wakeup_controller.cc(166)] Inhibiting /sys/devices/platform/i8042/serio0/input/input3
[1212/165202:INFO:wakeup_controller.cc(153)] Disabling wakeup for /sys/devices/pci0000:00/0000:00:15.1/i2c_designware.1/i2c-7/i2c-ELAN0000:00/input/input4 through /sys/devices/pci0000:00/0000:00:15.1/i2c_designware.1/i2c-7/i2c-ELAN0000:00
[1212/165202:INFO:wakeup_controller.cc(153)] Disabling wakeup for /sys/devices/platform/i8042/serio0/input/input3 through /sys/devices/platform/i8042/serio0
[1212/165202:INFO:state_controller.cc(846)] Turning panel off after entering docked mode
[1212/165202:INFO:display_power_setter.cc(80)] Asking Chrome to turn internal display off and external displays on
[1212/165202:ERROR:object_proxy.cc(582)] Failed to call method: org.chromium.LibCrosServiceInterface.SetDisplayPower: object_path= /org/chromium/LibCrosService: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.LibCrosService was not provided by any .service files
[1212/165202:INFO:internal_backlight_controller.cc(670)] Setting brightness to 0 (0%) over 0 ms
[1212/165202:INFO:state_controller.cc(889)] Ready to perform lid-closed action (no-op)
[1212/165210:INFO:daemon.cc(493)] Lid opened
[1212/165210:INFO:state_controller.cc(846)] Turning panel on after leaving docked mode
[1212/165210:INFO:display_power_setter.cc(80)] Asking Chrome to turn all displays on
[1212/165210:ERROR:object_proxy.cc(582)] Failed to call method: org.chromium.LibCrosServiceInterface.SetDisplayPower: object_path= /org/chromium/LibCrosService: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.LibCrosService was not provided by any .service files
[1212/165210:INFO:internal_backlight_controller.cc(670)] Setting brightness to 69 (63%) over 0 ms
[1212/165210:INFO:wakeup_controller.cc(166)] Un-inhibiting /sys/devices/pci0000:00/0000:00:15.1/i2c_designware.1/i2c-7/i2c-ELAN0000:00/input/input4
[1212/165210:INFO:wakeup_controller.cc(166)] Un-inhibiting /sys/devices/platform/i8042/serio0/input/input3
[1212/165210:INFO:wakeup_controller.cc(153)] Enabling wakeup for /sys/devices/pci0000:00/0000:00:15.1/i2c_designware.1/i2c-7/i2c-ELAN0000:00/input/input4 through /sys/devices/pci0000:00/0000:00:15.1/i2c_designware.1/i2c-7/i2c-ELAN0000:00
[1212/165210:INFO:wakeup_controller.cc(153)] Enabling wakeup for /sys/devices/platform/i8042/serio0/input/input3 through /sys/devices/platform/i8042/serio0
...
[1212/165250:INFO:daemon.cc(502)] Power button down
[1212/165250:INFO:main.cc(240)] Launching "sync"
<end of log>

---

All of those failed SetDisplayPower D-Bus calls make me think that Chrome isn't running. Indeed, there's a bunch of log spam suggesting that Chrome is exiting and restarting just before this, and it ends with Chrome exiting and not coming back:

[1212/061703:INFO:suspender.cc(466)] Starting suspend
[1212/061703:INFO:main.cc(259)] Running "/usr/bin/powerd_setuid_helper --action=suspend"
[1212/165111:INFO:daemon.cc(687)] powerd_suspend returned 0
[1212/165111:INFO:suspender.cc(424)] Finishing request 88080385 successfully
...
[1212/165111:INFO:suspend_delay_controller.cc(123)] Unregistering suspend delay 88080386 (chrome) due to D-Bus client :1.13 going away
[1212/165111:INFO:suspend_delay_controller.cc(123)] Unregistering dark suspend delay 88113154 (chrome) due to D-Bus client :1.13 going away
...
[1212/165114:INFO:suspend_delay_controller.cc(63)] Registering suspend delay 88080388 (chrome) of 5000 ms on behalf of :1.74
[1212/165114:INFO:suspend_delay_controller.cc(63)] Registering dark suspend delay 88113155 (chrome) of 5000 ms on behalf of :1.74
[1212/165114:INFO:daemon.cc(1062)] D-Bus org.chromium.LibCrosService ownership changed to :1.74
[1212/165114:INFO:display_power_setter.cc(80)] Asking Chrome to turn all displays on
[1212/165115:ERROR:object_proxy.cc(582)] Failed to call method: org.chromium.LibCrosServiceInterface.SetDisplayPower: object_path= /org/chromium/LibCrosService: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)
[1212/165115:INFO:suspend_delay_controller.cc(123)] Unregistering suspend delay 88080388 (chrome) due to D-Bus client :1.74 going away
[1212/165115:INFO:suspend_delay_controller.cc(123)] Unregistering dark suspend delay 88113155 (chrome) due to D-Bus client :1.74 going away
[1212/165115:INFO:suspend_delay_controller.cc(63)] Registering suspend delay 88080389 (chrome) of 5000 ms on behalf of :1.84
[1212/165115:INFO:suspend_delay_controller.cc(63)] Registering dark suspend delay 88113156 (chrome) of 5000 ms on behalf of :1.84
[1212/165115:INFO:daemon.cc(1062)] D-Bus org.chromium.LibCrosService ownership changed to :1.84
[1212/165115:INFO:display_power_setter.cc(80)] Asking Chrome to turn all displays on
[1212/165115:ERROR:object_proxy.cc(582)] Failed to call method: org.chromium.LibCrosServiceInterface.SetDisplayPower: object_path= /org/chromium/LibCrosService: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)
[1212/165115:INFO:suspend_delay_controller.cc(123)] Unregistering suspend delay 88080389 (chrome) due to D-Bus client :1.84 going away
[1212/165115:INFO:suspend_delay_controller.cc(123)] Unregistering dark suspend delay 88113156 (chrome) due to D-Bus client :1.84 going away
[1212/165116:INFO:suspend_delay_controller.cc(63)] Registering suspend delay 88080390 (chrome) of 5000 ms on behalf of :1.93
[1212/165116:INFO:suspend_delay_controller.cc(63)] Registering dark suspend delay 88113157 (chrome) of 5000 ms on behalf of :1.93
[1212/165116:INFO:daemon.cc(1062)] D-Bus org.chromium.LibCrosService ownership changed to :1.93
[1212/165116:INFO:display_power_setter.cc(80)] Asking Chrome to turn all displays on
[1212/165116:ERROR:object_proxy.cc(582)] Failed to call method: org.chromium.LibCrosServiceInterface.SetDisplayPower: object_path= /org/chromium/LibCrosService: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)
[1212/165116:INFO:suspend_delay_controller.cc(123)] Unregistering suspend delay 88080390 (chrome) due to D-Bus client :1.93 going away
[1212/165116:INFO:suspend_delay_controller.cc(123)] Unregistering dark suspend delay 88113157 (chrome) due to D-Bus client :1.93 going away
[1212/165116:INFO:daemon.cc(774)] On AC (USB_PD, 0.000A at 20.1V, max 3.0A at 20.0V) with battery at 100%, 3.898/3.898Ah at 0.000A, full
[1212/165116:INFO:suspend_delay_controller.cc(63)] Registering suspend delay 88080391 (chrome) of 5000 ms on behalf of :1.102
[1212/165116:INFO:suspend_delay_controller.cc(63)] Registering dark suspend delay 88113158 (chrome) of 5000 ms on behalf of :1.102
[1212/165116:INFO:daemon.cc(1062)] D-Bus org.chromium.LibCrosService ownership changed to :1.102
[1212/165116:INFO:display_power_setter.cc(80)] Asking Chrome to turn all displays on
[1212/165116:ERROR:object_proxy.cc(582)] Failed to call method: org.chromium.LibCrosServiceInterface.SetDisplayPower: object_path= /org/chromium/LibCrosService: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)
[1212/165116:INFO:suspend_delay_controller.cc(123)] Unregistering suspend delay 88080391 (chrome) due to D-Bus client :1.102 going away
[1212/165116:INFO:suspend_delay_controller.cc(123)] Unregistering dark suspend delay 88113158 (chrome) due to D-Bus client :1.102 going away

---

Here's what session_manager logged:

2016-12-12T16:51:11.860253-08:00 INFO session_manager[1474]: [INFO:child_exit_handler.cc(77)] Handling 1515 exit.
2016-12-12T16:51:11.860315-08:00 ERR session_manager[1474]: [ERROR:child_exit_handler.cc(85)]   Exited with signal 6
2016-12-12T16:51:11.860428-08:00 INFO session_manager[1474]: [INFO:session_manager_service.cc(296)] Exiting process is chrome.
...
2016-12-12T16:51:15.017532-08:00 INFO session_manager[1474]: [INFO:child_exit_handler.cc(77)] Handling 4885 exit.
2016-12-12T16:51:15.017547-08:00 ERR session_manager[1474]: [ERROR:child_exit_handler.cc(85)]   Exited with signal 4
2016-12-12T16:51:15.017551-08:00 INFO session_manager[1474]: [INFO:session_manager_service.cc(296)] Exiting process is chrome.
...
2016-12-12T16:51:15.597654-08:00 INFO session_manager[1474]: [INFO:child_exit_handler.cc(77)] Handling 6208 exit.
2016-12-12T16:51:15.597670-08:00 ERR session_manager[1474]: [ERROR:child_exit_handler.cc(85)]   Exited with signal 4
2016-12-12T16:51:15.597674-08:00 INFO session_manager[1474]: [INFO:session_manager_service.cc(296)] Exiting process is chrome.
...
2016-12-12T16:51:16.208533-08:00 INFO session_manager[1474]: [INFO:child_exit_handler.cc(77)] Handling 6260 exit.
2016-12-12T16:51:16.208548-08:00 ERR session_manager[1474]: [ERROR:child_exit_handler.cc(85)]   Exited with signal 4
2016-12-12T16:51:16.208551-08:00 INFO session_manager[1474]: [INFO:session_manager_service.cc(296)] Exiting process is chrome.
...
2016-12-12T16:51:16.818556-08:00 INFO session_manager[1474]: [INFO:child_exit_handler.cc(77)] Handling 6311 exit.
2016-12-12T16:51:16.818590-08:00 ERR session_manager[1474]: [ERROR:child_exit_handler.cc(85)]   Exited with signal 4
2016-12-12T16:51:16.818609-08:00 INFO session_manager[1474]: [INFO:session_manager_service.cc(296)] Exiting process is chrome.

---

I'm not sure what's causing the SIGILLs (I think that CHECK sometimes produces this now) and don't see logs corresponding to them, but this appears to be the initial SIGABRT:

[1515:4233:1212/061649:ERROR:freezer_cgroup_process_manager.cc(108)] Writing 4070 to /sys/fs/cgroup/freezer/chrome_renderers/to_be_frozen/cgroup.procs failed: No such file or directory
[1515:1515:1212/061649:VERBOSE1:update_display_configuration_task.cc(64)] OnDisplaysUpdated: new_display_state=MULTI_EXTENDED new_power_state=ALL_OFF flags=0 force_configure=0 display_count=4
[1515:1515:1212/061649:VERBOSE1:display_configurator.cc(217)] EnterState: display=MULTI_EXTENDED power=ALL_OFF
[1515:1515:1212/061650:VERBOSE1:display_configurator.cc(1029)] OnConfigured: success=1 new_display_state=MULTI_EXTENDED new_power_state=ALL_OFF
[1515:1515:1212/061650:VERBOSE1:display_manager.cc(532)] OnNativeDisplaysChanged(0): # of current displays=4
[1515:4233:1212/061650:ERROR:freezer_cgroup_process_manager.cc(108)] Writing FROZEN to /sys/fs/cgroup/freezer/chrome_renderers/to_be_frozen/freezer.state failed: No such file or directory
[1515:1515:1212/061650:VERBOSE1:display_color_manager_chromeos.cc(216)] No ICC file found with product id: 30e48c04 for display id: 13761487533244416
[1515:1515:1212/061650:VERBOSE1:display_color_manager_chromeos.cc(216)] No ICC file found with product id: 22647522 for display id: 9680988155546912
[1515:1515:1212/061650:VERBOSE1:display_color_manager_chromeos.cc(216)] No ICC file found with product id: 22647522 for display id: 9680988155546881
[1515:1515:1212/061650:VERBOSE1:display_color_manager_chromeos.cc(216)] No ICC file found with product id: 2264fd62 for display id: 9680978113643536
[1515:1515:1212/061657:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::ProcessInstance::RequestProcessList not available.
[1515:4233:1212/165111:ERROR:freezer_cgroup_process_manager.cc(108)] Writing THAWED to /sys/fs/cgroup/freezer/chrome_renderers/to_be_frozen/freezer.state failed: No such file or directory
[1515:1515:1212/165111:VERBOSE1:display_configurator.cc(877)] SetDisplayPower: power_state=ALL_ON flags=0, configure timer=Stopped
[1515:1515:1212/165111:VERBOSE1:arc_auth_service.cc(196)] Arc is not enabled.
[1515:1515:1212/165111:VERBOSE1:arc_auth_service.cc(196)] Arc is not enabled.
[1515:1515:1212/165111:FATAL:renderer_freezer.cc(139)] Unable to thaw renderers.

---

This seems like it might be  issue 661310 .

At the very least, should we avoid writing THAWED, or at least ignore failures when writing it, if writing FROZEN failed?

Re manually writing 'mem' to /sys/power/state, that bypasses the full suspend path, so Chrome won't be freezing and thawing renderers. That might explain why you don't see the problem when using that (assuming I understood your comment correctly).

Oh, and sorry, but I misread an earlier comment. Search+Shift+L (which I misread as Ctrl+Shift+L, the old "Lock Screen" accelerator) does in fact suspend the system immediately. It was added for  issue 357295 .

I have only two external displays at the moment, but I'm unable to test this as whenever I connect the second MIMO Magic Touch USB display either to the dock or directly to samus, a kernel panic occurs!

I can't find any useful info in the logs about the panic. I attached the DisplayLinkManager log.

So I ended up testing with one external display, in which case everything works as expected.

Google Chrome 57.0.2951.0 (Official Build) unknown (64-bit)
Platform 9085.0.0 (Official Build) dev-channel samus test

I'll try to get another external display and try again.

Deleted: DisplayLinkManager.log.txt 12.1 KB

DisplayLinkManager.log.txt 12.1 KB View Download

@9: if you have a report for the kernel panic with udl, please file a bug. These are usually easy to fix.

Where can I find that report?

/dev/pstore/console-ramoops

Reported  issue 674289 .

After  issue 674289  was fixed, I tried to repro again on 57.0.2952.0/9089.0.0 (samus), and still couldn't.

I have only two external displays + the internal display:
- DELL 2405FPW @ 1920x1200.
- MIMO Magic Touch USB Monitor @ 1024x600.
- Internal display @ 1280x850.

The only thing I noticed when I try the steps in the bug description is that the USB monitor sometimes takes a **long** time to be detected and turned on. Apparently an issue with the dock's USB hub? Eventually it gets connected (In a little less than a minute).

The errors that show up in 'messages' for the USB monitor are like [Attached file contains more]:

INFO kernel: [ 1028.009520] usb 1-5.4.1.1: new high-speed USB device number 90 using xhci_hcd
ERR kernel: [ 1044.022546] hub 1-5.4.1:1.0: cannot reset port 1 (err = -110)
ERR kernel: [ 1048.025760] hub 1-5.4.1:1.0: Cannot enable port 1.  Maybe the USB cable is bad?
ERR kernel: [ 1049.026546] hub 1-5.4.1:1.0: cannot disable port 1 (err = -110)
ERR kernel: [ 1050.027316] hub 1-5.4.1:1.0: cannot reset port 1 (err = -110)
ERR kernel: [ 1054.030680] hub 1-5.4.1:1.0: Cannot enable port 1.  Maybe the USB cable is bad?
ERR kernel: [ 1055.031359] hub 1-5.4.1:1.0: cannot disable port 1 (err = -110)
ERR kernel: [ 1056.032265] hub 1-5.4.1:1.0: cannot reset port 1 (err = -110)
ERR kernel: [ 1060.035521] hub 1-5.4.1:1.0: Cannot enable port 1.  Maybe the USB cable is bad?
ERR kernel: [ 1061.036314] hub 1-5.4.1:1.0: cannot disable port 1 (err = -110)
ERR kernel: [ 1062.037121] hub 1-5.4.1:1.0: cannot reset port 1 (err = -110)
ERR kernel: [ 1066.040334] hub 1-5.4.1:1.0: Cannot enable port 1.  Maybe the USB cable is bad?
ERR kernel: [ 1067.041160] hub 1-5.4.1:1.0: cannot disable port 1 (err = -110)
ERR kernel: [ 1067.041218] hub 1-5.4.1:1.0: unable to enumerate USB device on port 1
ERR kernel: [ 1068.041890] hub 1-5.4.1:1.0: cannot disable port 1 (err = -110)
ERR kernel: [ 1073.046004] hub 1-5.4.1:1.0: hub_port_status failed (err = -110)

Questions to is.rafique@gmail.com:
- Does this happen if you connect only two external displays instead of three?
- What happens if all displays remain off and you wait a little longer? Do they end up turning on after a while?
- Have you tried with different cables or links?

Deleted: Displays.png 566 KB

	Displays.png 566 KB View Download

Deleted: messages_usb.txt 14.5 KB

messages_usb.txt 14.5 KB View Download

Tried again with three external displays [configured as shown in the attached screenshot]:
- DELL 2405FPW @ 1920x1200 --> HDMI.
- MIMO Magic Touch USB Monitor @ 1024x600 --> USB.
- LG Chromebase @ 1920x1080 --> HDMI.
- Internal display @ 1280x850.

I still can't repro. 

[Attached screenshot].

Deleted: Displays_2.png 66.5 KB

	Displays_2.png 66.5 KB View Download

@14:
> - Does this happen if you connect only two external displays instead of three?

No idea.

> - What happens if all displays remain off and you wait a little longer? Do they end up turning on after a while?

Define "a little longer". When this bug hits, the entire system is unresponsive. No displays (internal or external), no reaction to keyboard input (I tried various key shortcuts). I did leave it on for a bit a couple of times, in the hope that something was hanging in the display server and might timeout eventually, but no luck (and didn't time it.)

It did look as if the usb sticks plugged into the dock were being accessed (being remounted after resume from sleep, I guess?).

- Have you tried with different cables or links?

No.

Just to reiterate. When I first got this dock, everything worked fine on the stable channel. By fine I mean:

- all 3 displays working
- put machine to sleep
- disconnect the dock (ostensibly to stop the machine charging for no reason)
- (later) reconnect the dock
- resume the machine
- all 3 displays working - WITH all windows in their old positions on the various displays

When I switched to the dev channel, thats the first time the buggy behaviour appeared. And it would happen EVERY time I tried the above.

When I switched back to the stable channel, this bug started happening again.

Now, when using chrome os, I disconnect the dock BEFORE going to sleep. Then resume from sleep, and THEN reconnect the dock.

This prevents this bug from happening, but has the disadvantage of having to manually move all the windows back to their previous locations. With the combo of lots of windows across lots of displays, and Aura's really primitive window management, this is a real pain in the backside.

https://bugs.chromium.org/p/chromium/issues/detail?id=620418

Re #17:
> > - Does this happen if you connect only two external displays instead of three?

> No idea.

Can you please give it a try and let me know?

So things were working fine when you were on stable, the buggy behavior started showing when you switched to dev, but when you switched back to stable the problem didn't go away?

Is the new-stable the same version as the old-stable? Do you have the version numbers?

I tried again doing the exact same steps you described and couldn't repro. There's not much we can do if we can't repro.

> So things were working fine when you were on stable, the buggy behavior started showing when you switched to dev, but when you switched back to stable the problem didn't go away?
> Is the new-stable the same version as the old-stable? Do you have the version numbers?

I didn't make a note of the stable version before I switched to the dev channel (to get the play store). I think the version (when I reverted back) was newer (my other chromebooks also got stable updates in the interim).

BTW, I had a quick look at some previous comments, and saw this in comment 7:

> The only point where I see the lid being closed in powerd's logs is here:

As explained in the initial bug report, I wasn't suspending the machine by closing the lid. I would first explicitly put the machine to sleep, and **THEN** close the lid (so surely there's no point in grep'ing for 'Lid closed' in my logs).

Not sure why you can't reproduce. It happened here multiple times, without fail.

Is this still happening?