See also: crosbug.com/p/53825

This issue can be triggered easily by using a magnet to very quickly trigger the lid sensor:

 (1) Log in to Chrome
 (2) Place magnet over lid sensor to trigger "lid close" event:
    (a) on elm: behind F1 "<-" key.
    (b) on oak: to the right of the "backspace" key.
 (3) Remove magnet to trigger "lid open" event

Here are some traces from evtest & powerd showing the case where the screen is black on a "quick magnet" test:

# evtest /dev/input/event5 &
# tail -F /var/log/power_manager/powerd.LATEST

Event: time 1465971633.463371, type 5 (EV_SW), code 0 (SW_LID), value 1
Event: time 1465971633.463371, -------------- SYN_REPORT ------------
Event: time 1465971633.638306, type 5 (EV_SW), code 0 (SW_LID), value 0
Event: time 1465971633.638306, -------------- SYN_REPORT ------------
[0615/062033:INFO:daemon.cc(533)] Lid closed
[0615/062033:INFO:wakeup_controller.cc(166)] Inhibiting /sys/devices/12d40000.spi/spi_master/spi2/spi2.0/cros-ec-keyb.3/input/input0
[0615/062033:INFO:wakeup_controller.cc(166)] Inhibiting /sys/devices/12e00000.hsi2c/i2c-8/8-004b/input/input4
[0615/062033:INFO:wakeup_controller.cc(153)] Disabling wakeup for /sys/devices/12d40000.spi/spi_master/spi2/spi2.0/cros-ec-keyb.3/input/input0 through /sys/devices/12d40000.spi/spi_master/spi2/spi2.0
[0615/062033:INFO:wakeup_controller.cc(153)] Disabling wakeup for /sys/devices/12e00000.hsi2c/i2c-8/8-004b/input/input4 through /sys/devices/12e00000.hsi2c/i2c-8/8-004b
[0615/062033:INFO:state_controller.cc(889)] Ready to perform lid-closed action (suspend)
[0615/062033:INFO:suspender.cc(397)] Starting request 61603870
[0615/062033:INFO:daemon.cc(613)] Reading wakeup count from /sys/power/wakeup_count
[0615/062033:INFO:daemon.cc(617)] Read wakeup count 0xb8814ff8
[0615/062033:INFO:internal_backlight_controller.cc(676)] Setting brightness to 0 (0%) over 0 ms
[0615/062033:INFO:internal_backlight_controller.cc(692)] Setting resume brightness to 1740 (80%)
[0615/062033:INFO:suspend_delay_controller.cc(139)] Announcing suspend request 61603870 with 2 pending delay(s) and 0 outstanding delay(s) from previous request
[0615/062033:INFO:suspend_delay_controller.cc(88)] Got notification that delay 61603841 (shill) is ready for suspend request 61603870 from :1.10
[0615/062033:INFO:daemon.cc(542)] Lid opened
[0615/062033:INFO:suspender.cc(359)] Aborting request in response to user activity
[0615/062033:INFO:suspender.cc(424)] Finishing request 61603870 unsuccessfully
[0615/062033:INFO:internal_backlight_controller.cc(676)] Setting brightness to 1740 (80%) over 0 ms
[0615/062033:INFO:wakeup_controller.cc(166)] Un-inhibiting /sys/devices/12d40000.spi/spi_master/spi2/spi2.0/cros-ec-keyb.3/input/input0
[0615/062033:INFO:wakeup_controller.cc(166)] Un-inhibiting /sys/devices/12e00000.hsi2c/i2c-8/8-004b/input/input4
[0615/062033:INFO:wakeup_controller.cc(153)] Enabling wakeup for /sys/devices/12d40000.spi/spi_master/spi2/spi2.0/cros-ec-keyb.3/input/input0 through /sys/devices/12d40000.spi/spi_master/spi2/spi2.0
[0615/062033:INFO:wakeup_controller.cc(153)] Enabling wakeup for /sys/devices/12e00000.hsi2c/i2c-8/8-004b/input/input4 through /sys/devices/12e00000.hsi2c/i2c-8/8-004b
[0615/062033:INFO:daemon.cc(806)] On AC (Mains) with battery at 44% (displayed as 43%), 1.901/4.341Ah at 2.649A, 0s until full (calculating)
[0615/062033:INFO:daemon.cc(1412)] Chrome is using normal display mode
[0615/062033:INFO:suspend_delay_controller.cc(88)] Got notification that delay 61603842 (chrome) is ready for suspend request 61603870 from :1.13
[0615/062033:WARNING:suspend_delay_controller.cc(104)] Ignoring readiness notification for suspend delay 61603842, which we weren't waiting for
[0615/062038:INFO:daemon.cc(806)] On AC (Mains) with battery at 44% (displayed as 43%), 1.905/4.341Ah at 2.817A, 49m7s until full



Notice that the line "Ignoring readiness notification for suspend delay 61603842, which we weren't waiting for".
I think this is the problem; powerd(?) is ignoring the notification that should be used to turn the display back on.

I think that the "Ignoring readiness notification for suspend delay ..." message is expected here. Processes like Chrome register suspend delays with powerd, which means that they want a chance to do last-minute cleanup and confirm that they're ready before powerd writes to /sys/power/state. This just means that Chrome's notification back to powerd that it was ready came in after the lid had already been opened and the suspend request cancelled in powerd. I don't think that there's any way to avoid this, as this all happens asynchronously.

Is there anything interesting in Chrome's logs? It should receive the SuspendImminent and SuspendDone D-Bus signals in-order, so even if Chrome turns the displays off after the request was cancelled in powerd, Chrome should still turn them back on when it sees SuspendDone.

Running Chrome with --vmodule=display_configurator=1 might provide some more information.

@#3 - I spent most of this evening tracing through chrome, and essentially what happens is:


==> /var/log/power_manager/powerd.LATEST <==
[0616/000832:VERBOSE1:input_watcher.cc(300)] Read 2 event(s) from /dev/input/event5
[0616/000832:VERBOSE1:input_watcher.cc(317)] Notifying observers about lid closed event
[0616/000832:INFO:daemon.cc(533)] Lid closed
[0616/000832:INFO:state_controller.cc(889)] Ready to perform lid-closed action (suspend)
[0616/000832:INFO:suspender.cc(397)] Starting request 1329266703
[0616/000832:INFO:suspend_delay_controller.cc(139)] Announcing suspend request 1329266703 with 2 pending delay(s) and 0 outstanding delay(s) from previous request

  ==> /var/log/ui/ui.LATEST <==
[26660:26660:0616/000832:ERROR:device_event_log_impl.cc(140)] [00:08:32.991] Power: power_manager_client.cc:548 Calling SuspendImminent() for observers.
[26660:26660:0616/000832:ERROR:power_event_observer.cc(83)] SuspendImminent
[26660:26660:0616/000832:ERROR:power_event_observer.cc(122)] StopRenderingRequests()
[26660:26660:0616/000832:ERROR:power_event_observer.cc(25)] StopRenderingRequests
[26660:26660:0616/000832:ERROR:power_event_observer.cc(126)] OnDisplayPowerChanging
[26660:26660:0616/000832:ERROR:power_event_observer.cc(128)] SuspendDisplays
[26660:26660:0616/000832:ERROR:device_event_log_impl.cc(140)] [00:08:32.996] Power: power_manager_client.cc:249 Adding suspend readiness callback #1 for suspend attempt 1329266703
[26660:26660:0616/000832:ERROR:device_event_log_impl.cc(140)] [00:08:32.997] Power: power_manager_client.cc:724 1 callbacks remain until announcing readiness of suspend delay 1329266694 for suspend attempt 1329266703
  => This is asynchronous, but will take a while, and 'block' sending the "Announcing readiness" message back to powerd...

  => Meanwhile, powerd gets the lid open event:
[0616/000832:INFO:suspend_delay_controller.cc(88)] Got notification that delay 1329266690 (shill) is ready for suspend request 1329266703 from :1.11
[0616/000833:VERBOSE1:input_watcher.cc(300)] Read 2 event(s) from /dev/input/event5
[0616/000833:VERBOSE1:input_watcher.cc(317)] Notifying observers about lid open event
[0616/000833:INFO:daemon.cc(542)] Lid opened
[0616/000833:INFO:suspender.cc(359)] Aborting request in response to user activity
[0616/000833:INFO:suspender.cc(424)] Finishing request 1329266703 unsuccessfully

=> Chrome process SuspendDone from powerd:
[26660:26660:0616/000833:ERROR:device_event_log_impl.cc(140)] [00:08:33.041] Power: power_manager_client.cc:578 Calling SuspendDone(0.052078s) for observers.
[26660:26660:0616/000833:ERROR:power_event_observer.cc(136)] ResumeDisplays
  => Here it "resumes displays"... but they haven't actually been suspended yet...

[26660:26660:0616/000833:ERROR:power_event_observer.cc(138)] NotifyRefreshClock
[26660:26660:0616/000833:ERROR:power_event_observer.cc(147)] ResumeRenderingRequests
[26660:26660:0616/000833:ERROR:power_event_observer.cc(36)] ResumeRenderingRequests
[26660:26660:0616/000833:ERROR:device_event_log_impl.cc(140)] [00:08:33.048] Power: power_manager_client.cc:404 Brightness changed to 81: user initiated 0
[26660:26660:0616/000833:ERROR:power_event_observer.cc(77)] BrightnessChanged(81, 0)
[26660:26754:0616/000833:ERROR:zygote_host_impl_linux.cc(162)] Failed to adjust OOM score of renderer with pid 27597: Permission denied

[26660:26660:0616/000833:ERROR:power_event_observer.cc(43)] OnSuspendDisplaysCompleted

  => Finally the original SuspendDisplay request completes (+1 second)
  => And Chrome can announce back to powerd that it is ready to suspend
[26660:26660:0616/000833:ERROR:device_event_log_impl.cc(140)] [00:08:33.734] Power: power_manager_client.cc:737 Announcing readiness of suspend delay 1329266694 for suspend attempt 1329266703

==> /var/log/power_manager/powerd.LATEST <==
[0616/000833:INFO:daemon.cc(1412)] Chrome is using normal display mode
[0616/000833:INFO:suspend_delay_controller.cc(88)] Got notification that delay 1329266694 (chrome) is ready for suspend request 1329266703 from :1.202
[0616/000833:WARNING:suspend_delay_controller.cc(104)] Ignoring readiness notification for suspend delay 1329266694, which we weren't waiting for


=> So the screen is still black b/c the SuspendDisplays() finished after ResumeDisplays(). [*]

[*] => I haven't looked into the details yet of why SuspendDisplays() takes so long and/or why SuspendDisplays() & ResumeDisplays() aren't synchronized.

Thanks for digging into the logs!

I'm not very familiar with this code anymore, but I suspect that DisplayConfigurator::ResumeDisplays() needs to be changed in the case when a config request is already in progress.

I can take a look at this later today since I've been working on this code lately.

I guess there are two ways to handle this well. One is to wait for Suspend Readiness to announce SuspendDone in powerd. The other is to do the synchronization in Chrome itself.

I partial to the first since Chrome might not be the only thing to run into this problem, and it effectively removes the problem for all Suspend Observers. If something takes too long to prepare for suspend, that can add latency, but nothing takes too long to suspend unless there's a bug. Interrupted suspends are also rare. We would also have to make sure that we didn't block emitting SuspendDone due to a pending DarkSuspendImminent call. Those can take longer, and we don't necessarily control to code running for Lucid Sleep v2 when it rolls out.

Fixing this only in Suspend/ResumeDisplays only fixes this for the display configurator. The same race condition can happen to other observers, so I think we should fix it once here.

@#7 - Yes, I tend to agree.

Having powerd's Suspender wait for all of pending SuspendDelayControllers to complete (reply, disconnect or time out) before doing Suspender::FinishRequest (ie sending SuspendDone) sounds like a good general solution to me.

I guess maybe add a new state like STATE_WAITING_FOR_SUSPEND_DELAYS_BEFORE_ABORT in HandleEvent between STATE_WAITING_FOR_SUSPEND_DELAYS and STATE_IDLE.

I disagree strongly. :-) Deferring SuspendDone seems like it'll lead to races and weird behavior. What happens if the user closes, opens, and recloses the lid quickly? Will powerd need to hold off on starting the new suspend request until it's received all of the readiness calls from the first request?

powerd's suspend code in suspender.cc is already very complicated (maybe overly so, although I don't see any obvious ways to simplify it). It seems cleaner to keep asynchronicity in the processes that are doing long-running operations. Doesn't DisplayConfigurator just need to check that display_suspended_ is still true when the original configuration request finishes and undo the suspend preparation if it isn't?

@#9 - We already have races and weird behavior.  

"What happens if the user closes, opens, and recloses the lid quickly? Will powerd need to hold off on starting the new suspend request until it's received all of the readiness calls from the first request?"

Yes.

From another feedback report: https://feedback.corp.google.com/#/Report/16551879976

tl;dr: another way of triggering this issue:
device wakes up from suspend, and powerd determines that "Lid still closed after resuming", and decides to suspend again...  just before a "lid open" arrives.


// Below is a "combined Logs" output from the Android debug tool, processing logs in feedback report.
// Note that powerd & chrome logs only have 'whole second' timestamps, so the exact timing is not accurately displayed relative to other logs with sub-second accuracy (eg kernel).

// User closes lid to enter suspend:

2016-08-15 11:56:33.000 6 daemon.cc(533):  Lid closed
2016-08-15 11:56:33.000 6 wakeup_controller.cc(166):  Inhibiting /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0/1100a000.spi:ec@0:keyboard-controller/input/input0
2016-08-15 11:56:33.000 6 wakeup_controller.cc(166):  Inhibiting /sys/devices/soc/11010000.i2c/i2c-6/6-0010/input/input2
2016-08-15 11:56:33.000 6 wakeup_controller.cc(166):  Inhibiting /sys/devices/soc/11011000.i2c/i2c-7/7-0015/input/input1
2016-08-15 11:56:33.000 6 wakeup_controller.cc(153):  Disabling wakeup for /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0/1100a000.spi:ec@0:keyboard-controller/input/input0 through /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0
2016-08-15 11:56:33.000 6 wakeup_controller.cc(153):  Disabling wakeup for /sys/devices/soc/11011000.i2c/i2c-7/7-0015/input/input1 through /sys/devices/soc/11011000.i2c/i2c-7/7-0015
2016-08-15 11:56:33.000 6 state_controller.cc(889):  Ready to perform lid-closed action (suspend)
2016-08-15 11:56:33.000 6 suspender.cc(397):  Starting request 61865992
2016-08-15 11:56:33.000 6 daemon.cc(613):  Reading wakeup count from /sys/power/wakeup_count
2016-08-15 11:56:33.000 6 daemon.cc(617):  Read wakeup count 0xf80bb410
2016-08-15 11:56:33.000 6 internal_backlight_controller.cc(676):  Setting brightness to 0 (0%) over 0 ms
2016-08-15 11:56:33.000 6 internal_backlight_controller.cc(692):  Setting resume brightness to 13 (81.25%)
2016-08-15 11:56:33.000 6 suspend_delay_controller.cc(139):  Announcing suspend request 61865992 with 2 pending delay(s) and 0 outstanding delay(s) from previous request
2016-08-15 11:56:33.000 6 dark_resume.cc(161):  Not in dark resume with battery at 95.0111% and line power off
2016-08-15 11:56:33.000 6 dark_resume.cc(170):  Updated shutdown threshold to 95.0111%
2016-08-15 11:56:33.000 6 daemon.cc(806):  On battery at 95% (displayed as 98%), 4.266/4.490Ah at 0.346A, 10h56m39s until empty (10h29m until shutdown)
2016-08-15 11:56:33.000 6 suspend_delay_controller.cc(88):  Got notification that delay 61865985 (shill) is ready for suspend request 61865992 from :1.10
2016-08-15 11:56:33.000 6 daemon.cc(1412):  Chrome is using normal display mode
2016-08-15 11:56:33.000 6 daemon.cc(1430):  Received updated external policy: ac_dim=30s ac_screen_off=40s ac_lock=50s ac_idle_warn=0s ac_idle=30m battery_dim=30s battery_screen_off=40s battery_lock=50s battery_idle_warn=0s battery_idle=10m ac_idle=suspend battery_idle=suspend lid_closed=suspend use_audio=1 use_video=1 presentation_factor=2.0 user_activity_factor=2.0 wait_for_initial_user_activity=0 force_nonzero_brightness_for_user_activity=1 (Prefs)
2016-08-15 11:56:33.000 6 state_controller.cc(751):  Updated settings: dim=1m screen_off=1m10s lock=1m20s idle_warn=0s idle=10m30s (suspend) lid_closed=suspend use_audio=1 use_video=1
2016-08-15 11:56:33.000 6 state_controller.cc(89):  Dimming screen after 2m19s
2016-08-15 11:56:33.000 6 internal_backlight_controller.cc(692):  Setting resume brightness to 13 (81.25%)
2016-08-15 11:56:33.000 6 state_controller.cc(89):  Turning screen off after 2m19s
2016-08-15 11:56:33.000 6 internal_backlight_controller.cc(692):  Setting resume brightness to 13 (81.25%)
2016-08-15 11:56:33.000 6 state_controller.cc(89):  Locking screen after 2m19s
2016-08-15 11:56:33.000 3 1:1     : PlatformKeyboardEvent.cpp(84): Not implemented reached in static bool blink<IPv6: 1>PlatformKeyboardEvent<IPv6: 5>urrentCapsLockState()
2016-08-15 11:56:34.000 8 1229:1229: gaia_screen_handler.cc(389): OnPortalDetectionCompleted Online
2016-08-15 11:56:34.000 8 1229:1229: lock_state_controller.cc(571): PostLockAnimationFinished
2016-08-15 11:56:34.000 6 suspend_delay_controller.cc(88):  Got notification that delay 61865986 (chrome) is ready for suspend request 61865992 from :1.11
2016-08-15 11:56:34.000 6 suspend_delay_controller.cc(224):  Notifying observers that suspend is ready
2016-08-15 11:56:34.000 6 suspender.cc(466):  Starting suspend
2016-08-15 11:56:34.000 6 util.cc(48):  Running "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa7"
2016-08-15 11:56:34.000 6 util.cc(48):  Running "/usr/bin/powerd_setuid_helper --action=suspend  --suspend_wakeup_count_valid --suspend_wakeup_count=9586"

// System is now suspended
    
// System resumes for an "unknown" reason :-( ... unfortunately, the syslog just says :

2016-08-15 12:12:34.161 6 kernel  :  [15285.163603] PM: resume of devices complete after 140.984 msecs
2016-08-15 12:12:34.161 7 kernel  :  [15285.165945] PM: Finishing wakeup.
2016-08-15 12:12:34.161 4 kernel  :  [15285.165965] Restarting tasks ... done.
2016-08-15 12:12:34.162 5 powerd_suspend[681]:  wake source: unknown
2016-08-15 12:12:34.167 5 powerd_suspend[689]:  Resume finished

2016-08-15 12:12:34.000 8 1229:1229: display_configurator.cc(869): SetDisplayPower: power_state=ALL_ON flags=0, configure timer=Stopped
2016-08-15 12:12:34.000 6 1229:1229: screenlock_bridge.cc(146): Focused user changed to {"email":"<email: 1>","gaia_id":"100220305255006791649"}
2016-08-15 12:12:34.000 8 1229:1229: update_display_configuration_task.cc(64): OnDisplaysUpdated: new_display_state=SINGLE new_power_state=ALL_ON flags=0 force_configure=0 display_count=1
2016-08-15 12:12:34.000 8 1229:1229: display_configurator.cc(217): EnterState: display=SINGLE power=ALL_ON
2016-08-15 12:12:34.000 3 1229:1229: device_event_log_impl.cc(140): [12:12:34.327] Network: network_state_handler.cc:618 DefaultNetworkPropertyUpdated: Google-A.Error = "out-of-range"
2016-08-15 12:12:34.000 3 1229:1229: device_event_log_impl.cc(140): [12:12:34.329] Network: network_state_handler.cc:921 Default network in unexpected state: Google-A (/service/4)State: failure
2016-08-15 12:12:34.000 8 1229:1229: gaia_screen_handler.cc(389): OnPortalDetectionCompleted Offline
2016-08-15 12:12:34.000 3 1229:1229: device_event_log_impl.cc(140): [12:12:34.335] Network: network_state_handler.cc:618 NetworkPropertyUpdated: Google-A.Error = "Unknown"
2016-08-15 12:12:34.000 8 1229:1229: display_configurator.cc(869): SetDisplayPower: power_state=ALL_OFF flags=0, configure timer=Stopped
2016-08-15 12:12:34.000 8 1229:1229: display_configurator.cc(1021): OnConfigured: success=1 new_display_state=SINGLE new_power_state=ALL_ON
2016-08-15 12:12:34.000 8 1229:1229: display_manager.cc(545): OnNativeDisplaysChanged(1):DisplayInfo[13761487533244416] native bounds=0,0 1920x1080, size=1920x1080, scale=1.250000, overscan=0,0,0,0, rotation=0, ui-scale=1.000000, touchscreen=yes, input_devices=[3]
2016-08-15 12:12:34.000 8 1229:1229: display_configurator.cc(869): SetDisplayPower: power_state=ALL_OFF flags=0, configure timer=Stopped
2016-08-15 12:12:34.000 8 1229:1229: display_configurator.cc(869): SetDisplayPower: power_state=ALL_ON flags=0, configure timer=Stopped
2016-08-15 12:12:34.000 8 1229:1229: display_color_manager_chromeos.cc(218): No ICC file found with product id: 30e42c05 for display id: 13761487533244416
2016-08-15 12:12:34.000 8 1229:1229: update_display_configuration_task.cc(64): OnDisplaysUpdated: new_display_state=SINGLE new_power_state=ALL_OFF flags=0 force_configure=0 display_count=1
2016-08-15 12:12:34.000 8 1229:1229: display_configurator.cc(217): EnterState: display=SINGLE power=ALL_OFF
2016-08-15 12:12:34.000 8 1229:1229: display_configurator.cc(1021): OnConfigured: success=1 new_display_state=SINGLE new_power_state=ALL_OFF
2016-08-15 12:12:34.000 8 1229:1229: display_manager.cc(517): OnNativeDisplaysChanged(0): # of current displays=1
2016-08-15 12:12:34.000 8 1229:1229: display_color_manager_chromeos.cc(218): No ICC file found with product id: 30e42c05 for display id: 13761487533244416
2016-08-15 12:12:34.000 4 1732:1766: screen_manager.cc(100): Display controller (crtc=30) already present.
2016-08-15 12:12:34.000 8 1732:1766: drm_display.cc(102): DRM configuring: device=/sys/devices/soc/14000000.clock-controller/drm/card2 crtc=30 connector=23 origin=0,0 size=1920x1080
2016-08-15 12:12:34.000 4 1732:1766: screen_manager.cc(100): Display controller (crtc=30) already present.
2016-08-15 12:12:34.000 8 1732:1766: drm_display.cc(102): DRM configuring: device=/sys/devices/soc/14000000.clock-controller/drm/card2 crtc=30 connector=23 origin=0,0 size=0x0
2016-08-15 12:12:34.000 6 daemon.cc(714):  powerd_suspend returned 0
2016-08-15 12:12:34.000 6 util.cc(36):  Launching "/usr/bin/powerd_setuid_helper --action=mosys_eventlog --mosys_eventlog_code=0xa8"
2016-08-15 12:12:34.000 6 suspender.cc(424):  Finishing request 61865992 successfully

// Previous suspend/resume is now complete

// However... the lid is still closed!  So powerd decides to suspend again (request 61865993)...

2016-08-15 12:12:34.000 6 state_controller.cc(351):  Lid still closed after resuming from lid-close-triggered suspend; repeating lid-closed action
2016-08-15 12:12:34.000 6 state_controller.cc(889):  Ready to perform lid-closed action (suspend)
2016-08-15 12:12:34.000 6 suspender.cc(397):  Starting request 61865993
2016-08-15 12:12:34.000 6 daemon.cc(613):  Reading wakeup count from /sys/power/wakeup_count
2016-08-15 12:12:34.000 6 daemon.cc(617):  Read wakeup count 0xf80bb410
2016-08-15 12:12:34.000 6 internal_backlight_controller.cc(692):  Setting resume brightness to 13 (81.25%)
2016-08-15 12:12:34.000 6 suspend_delay_controller.cc(139):  Announcing suspend request 61865993 with 2 pending delay(s) and 0 outstanding delay(s) from previous request
2016-08-15 12:12:34.000 6 dark_resume.cc(161):  Not in dark resume with battery at 94.922% and line power on
2016-08-15 12:12:34.000 6 dark_resume.cc(170):  Updated shutdown threshold to 94.922%

// But wait! the lid suddenly opens!  So powerd does the lid open action even though there is an on-going suspend operation... 

2016-08-15 12:12:34.000 6 daemon.cc(542):  Lid opened
2016-08-15 12:12:34.000 6 state_controller.cc(96):  Undimming screen
2016-08-15 12:12:34.000 6 internal_backlight_controller.cc(692):  Setting resume brightness to 13 (81.25%)
2016-08-15 12:12:34.000 6 state_controller.cc(96):  Turning screen on
2016-08-15 12:12:34.000 6 internal_backlight_controller.cc(692):  Setting resume brightness to 13 (81.25%)
2016-08-15 12:12:34.000 6 wakeup_controller.cc(166):  Un-inhibiting /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0/1100a000.spi:ec@0:keyboard-controller/input/input0
2016-08-15 12:12:34.000 6 wakeup_controller.cc(166):  Un-inhibiting /sys/devices/soc/11010000.i2c/i2c-6/6-0010/input/input2
2016-08-15 12:12:34.000 6 wakeup_controller.cc(166):  Un-inhibiting /sys/devices/soc/11011000.i2c/i2c-7/7-0015/input/input1
2016-08-15 12:12:34.000 6 wakeup_controller.cc(153):  Enabling wakeup for /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0/1100a000.spi:ec@0:keyboard-controller/input/input0 through /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0
2016-08-15 12:12:34.000 6 wakeup_controller.cc(153):  Enabling wakeup for /sys/devices/soc/11011000.i2c/i2c-7/7-0015/input/input1 through /sys/devices/soc/11011000.i2c/i2c-7/7-0015

// Oh no! The lid suddenly closes again...
    
2016-08-15 12:12:34.000 6 daemon.cc(533):  Lid closed
2016-08-15 12:12:34.000 6 wakeup_controller.cc(166):  Inhibiting /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0/1100a000.spi:ec@0:keyboard-controller/input/input0
2016-08-15 12:12:34.000 6 wakeup_controller.cc(166):  Inhibiting /sys/devices/soc/11010000.i2c/i2c-6/6-0010/input/input2
2016-08-15 12:12:34.000 6 wakeup_controller.cc(166):  Inhibiting /sys/devices/soc/11011000.i2c/i2c-7/7-0015/input/input1
2016-08-15 12:12:34.000 6 wakeup_controller.cc(153):  Disabling wakeup for /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0/1100a000.spi:ec@0:keyboard-controller/input/input0 through /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0
2016-08-15 12:12:34.000 6 wakeup_controller.cc(153):  Disabling wakeup for /sys/devices/soc/11011000.i2c/i2c-7/7-0015/input/input1 through /sys/devices/soc/11011000.i2c/i2c-7/7-0015

//  ...so powerd decides to do *another* lid close action (suspend) even though there already is an on-going suspend operation... 
    
2016-08-15 12:12:34.000 6 state_controller.cc(889):  Ready to perform lid-closed action (suspend)
2016-08-15 12:12:34.000 6 display_power_setter.cc(72):  Asking Chrome to turn all displays off
2016-08-15 12:12:34.000 6 daemon.cc(806):  On AC (Mains, 0.000A at 15.4V) with battery at 95% (displayed as 98%), 4.262/4.490Ah at 0.497A, 0s until full (calculating)
2016-08-15 12:12:34.000 6 internal_backlight_controller.cc(692):  Setting resume brightness to 13 (81.25%)
2016-08-15 12:12:34.000 6 state_controller.cc(751):  Updated settings: dim=1m screen_off=1m10s lock=1m20s idle_warn=0s idle=30m30s (suspend) lid_closed=suspend use_audio=1 use_video=1

//  ...and then the lid opens again! So powerd aborts the first suspend request 61865993 (from the 'lid still closed after resume') 

2016-08-15 12:12:34.000 6 daemon.cc(542):  Lid opened
2016-08-15 12:12:34.000 6 suspender.cc(359):  Aborting request in response to user activity
2016-08-15 12:12:34.000 6 suspender.cc(424):  Finishing request 61865993 unsuccessfully
2016-08-15 12:12:34.000 6 display_power_setter.cc(72):  Asking Chrome to turn all displays on
2016-08-15 12:12:34.000 6 internal_backlight_controller.cc(676):  Setting brightness to 13 (81.25%) over 0 ms
2016-08-15 12:12:34.000 6 wakeup_controller.cc(166):  Un-inhibiting /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0/1100a000.spi:ec@0:keyboard-controller/input/input0
2016-08-15 12:12:34.000 6 wakeup_controller.cc(166):  Un-inhibiting /sys/devices/soc/11010000.i2c/i2c-6/6-0010/input/input2
2016-08-15 12:12:34.000 6 wakeup_controller.cc(166):  Un-inhibiting /sys/devices/soc/11011000.i2c/i2c-7/7-0015/input/input1
2016-08-15 12:12:34.000 6 wakeup_controller.cc(153):  Enabling wakeup for /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0/1100a000.spi:ec@0:keyboard-controller/input/input0 through /sys/devices/soc/1100a000.spi/spi_master/spi32766/spi32766.0
2016-08-15 12:12:34.000 6 wakeup_controller.cc(153):  Enabling wakeup for /sys/devices/soc/11011000.i2c/i2c-7/7-0015/input/input1 through /sys/devices/soc/11011000.i2c/i2c-7/7-0015

// And, then we hit  http://crbug.com/620208  -
// The aborted suspend request causes Chrome to "resumes displays" before it finishes processing an ongoing "suspend displays" request.

2016-08-15 12:12:34.000 6 suspend_delay_controller.cc(88):  Got notification that delay 61865986 (chrome) is ready for suspend request 61865993 from :1.11
2016-08-15 12:12:34.000 4 suspend_delay_controller.cc(104):  Ignoring readiness notification for suspend delay 61865986, which we weren't waiting for
2016-08-15 12:12:34.000 6 daemon.cc(1412):  Chrome is using normal display mode
2016-08-15 12:12:34.000 6 daemon.cc(1412):  Chrome is using normal display mode
2016-08-15 12:12:35.000 6 suspend_delay_controller.cc(88):  Got notification that delay 61865985 (shill) is ready for suspend request 61865993 from :1.10
2016-08-15 12:12:35.000 4 suspend_delay_controller.cc(104):  Ignoring readiness notification for suspend delay 61865985, which we weren't waiting for

#11: Is the lid switch on that device buggy? The wakeup and brightness stuff while the switch is flapping is independent of suspend/resume -- powerd needs to handle the lid-closed-but-still-awake case for docked mode.

I'm in the process of looking at this now. I'm seeing what it'd take to handle it on the Chrome side at the moment, but I'm open to workarounds in powerd if they simplify the code instead of making it even more complicated (there's already too much trickiness around handling buggy lid switches on earlier hardware, in my opinion).

@derat - I was trying to test your new CL [0] today... but it turns out I could not reproduce this issue any more on ToT, nor even on R53.

[0] https://codereview.chromium.org/2296003002/

A bisect across cros versions showed that this was fixed in 8530.27.0 / 53.0.2785.25 [1].
[1] https://chromium.googlesource.com/chromium/src/+log/53.0.2785.24..53.0.2785.25?pretty=fuller&n=10000

Searching the diff for 'power' shows the following CL was cherry-picked to R53 by dnicoara, which probably fixed it:

commit	e3b52ec90617f1fc68328068c959e28f2ee23353	
author	Daniel Nicoara <dnicoara@chromium.org>	Thu Jul 21 15:23:19 2016
committer	Daniel Nicoara <dnicoara@chromium.org>	Thu Jul 21 15:26:25 2016
Fix queuing of display power state change requests

If a display power change request arrives before the previous one
finishes or if a previous power change request failed the state becomes
inconsistent and future requests are optimized out.

BUG= 627795 
TEST=New unittest in display_unittests and manually checked on Samus

Review-Url: https://codereview.chromium.org/2154743003
Cr-Commit-Position: refs/heads/master@{#405990}
(cherry picked from commit 760bfbf595eb8e4597c971b60c2da1c911481fbd)

Review URL: https://codereview.chromium.org/2172583003 .

Cr-Commit-Position: refs/branch-heads/2785@{#262}
Cr-Branched-From: 68623971be0cfc492a2cb0427d7f478e7b214c24-refs/heads/master@{#403382}

Great! I was actually a bit confused about why this was happening, since it looked to me like the ToT DisplayConfigurator might in fact be preempting the pending suspend call when resume came in, hence my confusion in the CL description. :-)