Comment 16 for bug 1759950

Finally found some evidence and it is surprising.

I added /usr/local/bin/xfce4-power-manager:

#!/bin/sh
exec /usr/bin/xfce4-power-manager --debug

and logged in as normal. Confirmed x-p-m is writing debug messages.

Closed the lid, it suspended, opened lid and tap key to resume as per usual.

There were no new messages from x-p-m but there are two very relevant from another sub-system with microsecond precision timestamps.

I captured the boot log with similar precision timestamps using:

$ journalctl -o short-iso-precision -b --since="12:53:03" --until="12:53:05"

and have interleaved the messages:

2019-06-18T12:53:04.275008+0100 Asus-F5-01 kernel: Enabling non-boot CPUs ...
2019-06-18T12:53:04.275090+0100 Asus-F5-01 kernel: x86: Booting SMP configuration:
2019-06-18T12:53:04.275182+0100 Asus-F5-01 kernel: smpboot: Booting Node 0 Processor 1 APIC 0x1
2019-06-18T12:53:04.275298+0100 Asus-F5-01 kernel: cache: parent cpu1 should not be sleeping
2019-06-18T12:53:04.275404+0100 Asus-F5-01 kernel: CPU1 is up
2019-06-18T12:53:04.275506+0100 Asus-F5-01 kernel: ACPI: Waking up from system sleep state S3
2019-06-18T12:53:04.275624+0100 Asus-F5-01 kernel: ahci 0000:00:12.0: set SATA to AHCI mode
2019-06-18T12:53:04.276343+0100 Asus-F5-01 kernel: ACPI: EC: interrupt unblocked
2019-06-18T12:53:04.276460+0100 Asus-F5-01 kernel: ACPI: EC: event unblocked

(xfsettingsd:3749): xfsettingsd-WARNING **: 12:53:04.328: Failed to configure CRTC 79.

(xfsettingsd:3749): xfsettingsd-CRITICAL **: 12:53:04.329: Failed to apply display settings

2019-06-18T12:53:04.681767+0100 Asus-F5-01 kernel: sd 0:0:0:0: [sda] Starting disk
2019-06-18T12:53:04.682889+0100 Asus-F5-01 kernel: [drm] radeon: 3 quad pipes, 1 z pipes initialized.
2019-06-18T12:53:04.683026+0100 Asus-F5-01 kernel: [drm] PCIE GART of 512M enabled (table at 0x0000000034880000).
2019-06-18T12:53:04.683142+0100 Asus-F5-01 kernel: radeon 0000:01:05.0: WB enabled
2019-06-18T12:53:04.683844+0100 Asus-F5-01 kernel: radeon 0000:01:05.0: fence driver on ring 0 use gpu addr 0x0000000080000000 and cpu addr 0x0000000090ce6220
2019-06-18T12:53:04.684456+0100 Asus-F5-01 kernel: [drm] radeon: ring at 0x0000000080001000
2019-06-18T12:53:04.684694+0100 Asus-F5-01 kernel: [drm] ring test succeeded in 2 usecs
2019-06-18T12:53:04.684795+0100 Asus-F5-01 kernel: [drm] ib test succeeded in 0 usecs
2019-06-18T12:53:04.684897+0100 Asus-F5-01 kernel: ata5.00: ACPI cmd ef/03:0c:00:00:00:a0 (SET FEATURES) filtered out
2019-06-18T12:53:04.684992+0100 Asus-F5-01 kernel: ata5.00: ACPI cmd ef/03:42:00:00:00:a0 (SET FEATURES) filtered out
2019-06-18T12:53:04.685081+0100 Asus-F5-01 kernel: ata5.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
2019-06-18T12:53:04.685174+0100 Asus-F5-01 kernel: OOM killer enabled.
2019-06-18T12:53:04.685269+0100 Asus-F5-01 kernel: Restarting tasks ... done.
2019-06-18T12:53:04.685367+0100 Asus-F5-01 kernel: video LNXVIDEO:00: Restoring backlight state
2019-06-18T12:53:04.685950+0100 Asus-F5-01 kernel: PM: suspend exit

What confuses me about this is that the timestamps of xfsettingsd appear to be before the kernel restarts tasks.

However, if these are accurate, it seems to show the display isn't re-enabled at that time, which might explain how the internal state of the user session gets confused and as a result thinks the DPMS state is still 'off'.