http://feedback/#/Report/85076975785

Looks like the kernel suspended and resumed immediately? Seems like it may be similar to http://g/chromeos-discuss/ivOBoAWMneA (link instead of samus).

----

[0216/164124:INFO:daemon.cc(1224)] Got RequestSuspend message from :1.55
[0216/164124:INFO:suspender.cc(383)] Starting request 93519874
[0216/164124:INFO:daemon.cc(601)] Reading wakeup count from /sys/power/wakeup_count
[0216/164124:INFO:daemon.cc(605)] Read wakeup count 4
[0216/164124:INFO:internal_backlight_controller.cc(677)] Setting brightness to 0 (0%) over 0 ms
[0216/164124:INFO:internal_backlight_controller.cc(693)] Setting resume brightness to 636 (80%)
[0216/164124:INFO:suspend_delay_controller.cc(137)] Announcing suspend request 93519874 with 3 pending delay(s) and 0 outstanding delay(s) from previous request
[0216/164124:INFO:suspend_delay_controller.cc(86)] Got notification that delay 93519875 (shill) is ready for suspend request 93519874 from :1.44
[0216/164125:INFO:daemon.cc(1443)] 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=6m30s 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)
[0216/164125:INFO:state_controller.cc(855)] Updated settings: dim=1m screen_off=1m10s lock=1m20s idle_warn=0s idle=30m30s (suspend) lid_closed=no-op use_audio=1 use_video=1
[0216/164125:INFO:suspend_delay_controller.cc(86)] Got notification that delay 93519874 (DisplayLinkSuspendHandle) is ready for suspend request 93519874 from :1.37
[0216/164126:INFO:daemon.cc(1425)] Chrome is using presentation display mode
[0216/164126:INFO:suspend_delay_controller.cc(86)] Got notification that delay 93519876 (chrome) is ready for suspend request 93519874 from :1.55
[0216/164126:INFO:suspend_delay_controller.cc(223)] Notifying observers that suspend is ready
[0216/164126:INFO:suspender.cc(456)] Starting suspend
[0216/164126:INFO:main.cc(244)] Running "/usr/bin/powerd_setuid_helper --action=suspend  --suspend_wakeup_count_valid --suspend_wakeup_count=4"
[0216/164130:INFO:daemon.cc(693)] powerd_suspend returned 0
[0216/164130:INFO:suspender.cc(414)] Finishing request 93519874 successfully

----

...
2018-02-16T16:41:30.815878-08:00 INFO kernel: [  404.892209] calling  0000:00:02.0+ @ 9123, parent: pci0000:00, cb: pci_pm_suspend_noirq
2018-02-16T16:41:30.815879-08:00 INFO kernel: [  404.892222] call 0000:00:02.0+ returned 0 after 0 usecs
2018-02-16T16:41:30.815879-08:00 INFO kernel: [  404.892235] calling  0000:00:00.0+ @ 9123, parent: pci0000:00, cb: pci_pm_suspend_noirq
2018-02-16T16:41:30.815882-08:00 INFO kernel: [  404.892271] call 0000:00:00.0+ returned 0 after 22 usecs
2018-02-16T16:41:30.815883-08:00 INFO kernel: [  404.892322] PM: noirq suspend of devices complete after 22.289 msecs
2018-02-16T16:41:30.815884-08:00 INFO kernel: [  404.893338] ACPI: Preparing to enter system sleep state S3
2018-02-16T16:41:30.815884-08:00 INFO kernel: [  404.893435] PM: Saving platform NVS memory
2018-02-16T16:41:30.815885-08:00 NOTICE kernel: [  404.893445] Disabling non-boot CPUs ...
2018-02-16T16:41:30.815886-08:00 INFO kernel: [  404.896191] smpboot: CPU 1 is now offline
2018-02-16T16:41:30.815887-08:00 INFO kernel: [  404.898461] smpboot: CPU 2 is now offline
2018-02-16T16:41:30.815889-08:00 INFO kernel: [  404.900932] smpboot: CPU 3 is now offline
2018-02-16T16:41:30.815890-08:00 INFO kernel: [  404.903512] Disabling VMX on cpu 0
2018-02-16T16:41:30.815890-08:00 INFO kernel: [  404.903520] TSC at resume: 649927552
2018-02-16T16:41:30.815891-08:00 INFO kernel: [  404.903524] ACPI: Low-level resume complete
2018-02-16T16:41:30.815892-08:00 INFO kernel: [  404.903580] PM: Restoring platform NVS memory
2018-02-16T16:41:30.815893-08:00 INFO kernel: [  404.903931] Enabling non-boot CPUs ...
2018-02-16T16:41:30.815895-08:00 INFO kernel: [  404.903979] x86: Booting SMP configuration:
2018-02-16T16:41:30.815896-08:00 INFO kernel: [  404.903983] smpboot: Booting Node 0 Processor 1 APIC 0x1
2018-02-16T16:41:30.815896-08:00 INFO kernel: [  404.914390] Disabling VMX on cpu 1
2018-02-16T16:41:30.815897-08:00 INFO kernel: [  404.918357] Intel pstate controlling: cpu 1
2018-02-16T16:41:30.815898-08:00 INFO kernel: [  404.918419] CPU1 is up
2018-02-16T16:41:30.815899-08:00 INFO kernel: [  404.918441] smpboot: Booting Node 0 Processor 2 APIC 0x3
2018-02-16T16:41:30.815900-08:00 INFO kernel: [  404.928803] Disabling VMX on cpu 2
2018-02-16T16:41:30.815902-08:00 INFO kernel: [  404.932730] Intel pstate controlling: cpu 2
2018-02-16T16:41:30.815903-08:00 INFO kernel: [  404.932784] CPU2 is up
2018-02-16T16:41:30.815904-08:00 INFO kernel: [  404.932803] smpboot: Booting Node 0 Processor 3 APIC 0x2
2018-02-16T16:41:30.815905-08:00 INFO kernel: [  404.943265] Disabling VMX on cpu 3
2018-02-16T16:41:30.815906-08:00 INFO kernel: [  404.947217] Intel pstate controlling: cpu 3
2018-02-16T16:41:30.815906-08:00 INFO kernel: [  404.947271] CPU3 is up
2018-02-16T16:41:30.815909-08:00 INFO kernel: [  404.950855] ACPI: Waking up from system sleep state S3
2018-02-16T16:41:30.815909-08:00 INFO kernel: [  404.950952] calling  0000:00:00.0+ @ 9123, parent: pci0000:00, cb: pci_pm_resume_noirq
2018-02-16T16:41:30.815910-08:00 INFO kernel: [  404.950972] call 0000:00:00.0+ returned 0 after 12 usecs
2018-02-16T16:41:30.815911-08:00 INFO kernel: [  404.950978] calling  0000:00:02.0+ @ 9123, parent: pci0000:00, cb: pci_pm_resume_noirq
2018-02-16T16:41:30.815912-08:00 INFO kernel: [  404.961335] call 0000:00:02.0+ returned 0 after 10100 usecs
...
2018-02-16T16:41:30.816057-08:00 INFO kernel: [  405.007968] calling  wakeup_source.0+ @ 9123, parent: platform, cb: wakeup_find_source
2018-02-16T16:41:30.816058-08:00 INFO kernel: [  405.008116] wakeup_source wakeup_source.0: System wakeup source: i2c-ATML0000:01
2018-02-16T16:41:30.816059-08:00 INFO kernel: [  405.008134] call wakeup_source.0+ returned 0 after 145 usecs
...

If kernel wakeup_source is to be believed then its a spurious trackpad wake.

Looks like this feedback might have been with dock connected based on lsusb output.

Is reproducible w/o anything connected to the samus?  I'm wondering if there's some interference that your samus TP is particularly sensitive to via dock, PSU, USB that's forcing the immediate wake.

If in dev-mode you could experiment w/ disabling the wake source as well via

echo disabled > /sys/devices/pci0000:00/INT3432:00/i2c-0/i2c-ATML0000:01/power/wakeup
sleep 1
powerd_dbus_suspend # or search + shift + l
# try to wake via trackpad


I tested myself w/ same failing image (test) on samus both w/ dock (HP usb-c elite) and w/o and could not easily reproduce the failure.

I was able to simulate the failure behavior by placing palm across TP while requesting suspend (I used 'echo mem > /sys/power/state')

although I could NOT replicate it w/ 'search + shift + l'.

@Adlr, would there be any evidence of noise or palm rejection just before suspend attempt in touch_activity_log?

That particular feedback was with dock connected. I can try to repro without if that's useful.

Yes please.  Also try to avoid any casual contact with trackpad while hitting key sequence to rule out chance there could be corner case w/ palm rejection.

I was able to repro this morning without the dock. I think this is the correct report https://listnr.corp.google.com/report/85092760753 (Ignore description. I got interrupted several times while filing the report and typed the wrong description)

Interestingly, after the test my trackpad stopped working. It could click but my cursor refused to move. Reboot fixed that and since then I'm unable to repro this issue.

I wonder if I'm just seeing a failing trackpad. :-/

Looked around this point in the logfile,

2018-02-19T16:21:01.358907-08:00 INFO kernel: [26748.289998] wakeup_source wakeup_source.0: System wakeup source: i2c-ATML0000:01

But couldn't find anything obvious that led me to believe the trackpad went away.

I did find bug, crbug.com/543616, which mentioned similar trackpad stopped working failures but no logs to see if wake source was also TP as perhaps a source of the repro.

Given that the trackpad recovers after a reboot.  I suspect its something on suspend/resume path that renders it inoperable.  Probably need to get device in dev-mode in fail case to sort out further.  I'll try w/ device in #c2 when time presents itself.

Search feedback a bit but couldn't find any more artifacts around this spurious wake.  Going to dupe to the trackpad stopped working in case it provides additional context there.