Forceprobing DRM connections causes sway to lose monitor information/modeset when turning off dpms

[LaserEyess]

Please fill out the following:

• Sway Version:

  • sway version 1.5-a56098a2 (Nov 11 2020, branch 'master')

• Debug Log:
  Log capture of sway when this behavior was exhibited. Should be around the 58 minute mark.
  https://0x0.st/invm.log

• Configuration File:
  have not figured out a minimally reproducible config (yet).
  https://0x0.st/invB.txt

Swayidle config:

timeout 300 'swaylock -f -c 000000'
timeout 315 'swaymsg "output * dpms off"' resume 'swaymsg "output * dpms on"'
timeout 15 'if pgrep swaylock; then swaymsg "output * dpms off"; fi' resume 'if pgrep swaylock; then swaymsg "output * dpms on"; fi'
before-sleep 'swaylock -f -c 000000'

Run with swayidle -w

• Stack Trace:
  N/A

• Description:
  This bug appears to be caused by turning off dpms and then forceprobing connections on turning dpms back on. I can fix this bug by reverting 8bc5a92.

[Emantor]

00:58:06.093 [INFO] [backend/drm/drm.c:1351] 'DP-2' connected
00:58:06.093 [DEBUG] [backend/drm/drm.c:1352] Current CRTC: -1
00:58:06.093 [INFO] [backend/drm/drm.c:1357] Physical size: 600x340
00:58:06.093 [INFO] [backend/drm/drm.c:1375] Detected modes:
00:58:06.093 [INFO] [backend/drm/drm.c:1397]   640x480@59940 
00:58:06.094 [INFO] [backend/drm/drm.c:1397]   640x480@59940 
00:58:06.094 [DEBUG] [backend/drm/drm.c:1088] Reallocating CRTCs
00:58:06.094 [DEBUG] [backend/drm/drm.c:1099] State before reallocation:
00:58:06.094 [DEBUG] [backend/drm/drm.c:1105]   'DP-1' crtc=-1 state=0 desired_enabled=1
00:58:06.094 [DEBUG] [backend/drm/drm.c:1105]   'DP-2' crtc=-1 state=1 desired_enabled=1
00:58:06.094 [DEBUG] [backend/drm/drm.c:1105]   'DP-3' crtc=2 state=3 desired_enabled=1
00:58:06.095 [DEBUG] [backend/drm/drm.c:1105]   'HDMI-A-1' crtc=-1 state=0 desired_enabled=0
00:58:06.095 [DEBUG] [backend/drm/drm.c:1157] State after reallocation:
00:58:06.095 [DEBUG] [backend/drm/drm.c:1164]   'DP-1' crtc=-1 state=0 desired_enabled=1
00:58:06.095 [DEBUG] [backend/drm/drm.c:1164]   'DP-2' crtc=5 state=1 desired_enabled=1
00:58:06.095 [DEBUG] [backend/drm/drm.c:1164]   'DP-3' crtc=2 state=3 desired_enabled=1
00:58:06.095 [DEBUG] [backend/drm/drm.c:1164]   'HDMI-A-1' crtc=-1 state=0 desired_enabled=0
00:58:06.095 [INFO] [backend/drm/drm.c:1463] Requesting modeset for 'DP-2'
00:58:06.095 [sway/desktop/output.c:910] New output 0x55bb40ba8e60: DP-2
00:58:06.095 [sway/config/output.c:348] Turning on output DP-2
00:58:06.095 [sway/config/output.c:352] Set DP-2 mode to 2560x1440 (144.000000 Hz)
00:58:06.095 [sway/config/output.c:262] Configured mode for DP-2 not available
00:58:06.095 [sway/config/output.c:263] Picking preferred mode instead
00:58:06.095 [sway/config/output.c:368] Set DP-2 transform to 1
00:58:06.095 [sway/config/output.c:379] Auto-detected output scale: 1.000000
00:58:06.095 [sway/config/output.c:387] Set DP-2 adaptive sync to 1
00:58:06.095 [sway/config/output.c:409] Committing output DP-2
00:58:06.095 [INFO] [backend/drm/drm.c:811] Modesetting 'DP-2' with '640x480@59940mHz'
00:58:06.095 [DEBUG] [backend/drm/drm.c:693] Initializing renderer on connector 'DP-2'
00:58:06.509 [sway/config/output.c:455] Set DP-2 position to 2560, -500

Here the kernel reports only 640x480 as a avialable resolution for the monitor. This seems fishy, since the initial modeset reports all modes correctly. You can try obtaining drm debug logs to see why the kernel reports only two resolutions. wlroots iterates on the drm_connector here AFAICS, so we can only work with the modes the kernel gives to us.

[LaserEyess]

This might take a while, I'm afraid. This issue is sometimes hard to reproduce. I imagine the caution about "sifting through hundreds of thousands of drm log lines" will come true, but nevertheless I'll try.

[emersion]

A drm_info log after the bug occurs could also confirm that it's a kernel bug.

[LaserEyess]

I had previously done that on IRC and the kernel properly reported all of the correct modeettings. I will attempt to do the same thing again once the bug occurs.

[LaserEyess]

Just had it happen again, of course my debugging logging was turned off for some reason, and I turned off drm debugging because it bloated up my drivers. But I'm sitting here right now with sway having disabled one of my monitors becuase it doesn't detect it, yet the kernel (via drm_info) sees it just fine.

swaymsg -t get_outputs https://0x0.st/inU-.txt
drm_infohttps://0x0.st/inUH.txt

DP-1 should be the same as Connector 0 based on how they're plugged into my GPU.

[Emantor]

Just had it happen again, of course my debugging logging was turned off for some reason, and I turned off drm debugging because it bloated up my drivers. But I'm sitting here right now with sway having disabled one of my monitors becuase it doesn't detect it, yet the kernel (via drm_info) sees it just fine.

swaymsg -t get_outputs https://0x0.st/inU-.txt
drm_infohttps://0x0.st/inUH.txt

DP-1 should be the same as Connector 0 based on how they're plugged into my GPU.

Thanks for the info, this confirms that it is our bug. This is also a wlroots problem, so should be moved there.

[emersion]

https://gitlab.freedesktop.org/drm/amd/-/issues/1368

[LaserEyess]

After around 60 hours on 5.4.77 I have not seen this bug once. I am concluding this is a kernel bug, but I'll update with more information once I am able to get some better kernel logs on what is happening.

However, debugging this is still difficult so I have a couple questions:

1. Is there some IPC event I can hook into for sway that can give me information exactly on when sway/wlroots loses the monitor?
2. Is there any way to get sway logs to use absolute timestamps?

I need to be able to exactly pinpoint when this bug occurs so I don't have to sift through GB of dmesg logs.

[LaserEyess]

Fairly certain I was wrong about LTS fixing this, I think it simply made it harder to find. But from some very rough, inconclusive bisecting I believe this is still present in wlroots and specifically caused by 8bc5a92. Or rather it was "fixed" by 713c166 and is now back. I'm going to use wlroots with 713c166 put back in to see if I can try to trigger the bug.

See new amdgpu upstream bug: https://gitlab.freedesktop.org/drm/amd/-/issues/1376

[LaserEyess]

This may still be a kernel bug but testing with 8bc5a92 reverted pretty conclusively causes this bug to go away.