wlroots
wlroots copied to clipboard
Output hotplug fails on i915 (failed finding vcpi slots:-28)
I am using DisplayPort via a Dell dock to drive my external display. If the display is connected at startup, it works properly. Disconnecting the display also works fine. Reconnecting it, however, leaves it blank and yields the logspam at the end of sway.log.
I have reproduced this in rootston with the only difference being that the errno reported is "Permission denied".
Sway believes that the output is present again after reconnection: workspaces move back, and I can blindly navigate to the windows on them without issues. I have never managed to cause a crash in this state.
Switching VTs and back via the keyboard seems to "resolve" the issue.
wlroots has migrated to gitlab.freedesktop.org. This issue has been moved to:
https://gitlab.freedesktop.org/wlroots/wlroots/-/issues/1354
I had a really fun time "bisecting" to figure out when this broke and I narrowed it down to 5b13b8a12c55b3216b1b92a20474efc856be5d7b. This commit specifically calls out fixing #1230, so I'm a bit nervous about attempting a fix myself since I'm not familiar with this area.
EDIT: I think the difference in errno was a red herring caused by me running rootston at the same time as sway, additionally.
Hmm. This is the relevant part of the log:
2018-11-03 12:51:38 - [backend/drm/drm.c:861] Reallocating CRTCs
2018-11-03 12:51:38 - [backend/drm/drm.c:873] State before reallocation:
2018-11-03 12:51:38 - [backend/drm/drm.c:883] 'DP-3' crtc=-1 state=1 desired_enabled=1
2018-11-03 12:51:38 - [backend/drm/drm.c:883] 'DP-2' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:883] 'HDMI-A-3' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:883] 'HDMI-A-2' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:883] 'DP-1' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:883] 'HDMI-A-1' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:883] 'VGA-1' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:883] 'LVDS-1' crtc=0 state=3 desired_enabled=1
2018-11-03 12:51:38 - [backend/drm/drm.c:940] Assigning CRTC 2 to output -1 -> 0 'DP-3'
2018-11-03 12:51:38 - [backend/drm/drm.c:944] State after reallocation:
2018-11-03 12:51:38 - [backend/drm/drm.c:949] 'DP-3' crtc=2 state=1 desired_enabled=1
2018-11-03 12:51:38 - [backend/drm/drm.c:949] 'DP-2' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:949] 'HDMI-A-3' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:949] 'HDMI-A-2' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:949] 'DP-1' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:949] 'HDMI-A-1' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:949] 'VGA-1' crtc=-1 state=0 desired_enabled=0
2018-11-03 12:51:38 - [backend/drm/drm.c:949] 'LVDS-1' crtc=0 state=3 desired_enabled=1
2018-11-03 12:51:38 - [backend/drm/drm.c:433] Reallocating planes
2018-11-03 12:51:38 - [backend/drm/drm.c:478] Assigning plane -1 -> 51 (type 0) to CRTC 57
2018-11-03 12:51:38 - [backend/drm/drm.c:478] Assigning plane -1 -> 48 (type 1) to CRTC 57
2018-11-03 12:51:38 - [backend/drm/drm.c:478] Assigning plane -1 -> 54 (type 2) to CRTC 57
2018-11-03 12:51:38 - [backend/drm/drm.c:1214] Requesting modeset for 'DP-3'
2018-11-03 12:51:38 - [sway/sway/desktop/output.c:574] New output 0x555a88452110: DP-3
2018-11-03 12:51:38 - [sway/sway/tree/output.c:257] Matched wildcard output config for DP-3
2018-11-03 12:51:38 - [backend/drm/drm.c:510] Modesetting 'DP-3' with '2560x1440@59951 mHz'
2018-11-03 12:51:38 - [backend/drm/drm.c:357] Starting renderer on output 'DP-3'
2018-11-03 12:51:38 - [backend/drm/atomic.c:55] DP-3: Atomic commit failed (modeset): Invalid argument
Can you provide a log where you trigger this bug, and then switch VTs to "fix" it?
It seems the first time CRTC 47 is used. When disconnected it's successfully de-allocated. When re-connected it's using another CRTC (57), which should be fine but fails. Maybe we're not cleaning up the CRTC correctly.
One log, hot off the press: sway-switch-tty.log
Disconnect is at line 1229, reconnect at 1280, tty switch at 2061. There are a couple more errors mixed in after that, but it seems to get back to a normal state.
Actually, thinking about it more, perhaps the "permission denied" is a hint? Suppose that when rootston or sway is the only compositor running, whatever argument is triggering "invalid argument" is indeed just a nonsense value. However, when there is another compositor running, could it be passing a value that attempts to access a resource owned by the other compositor?
Actually, thinking about it more, perhaps the "permission denied" is a hint? Suppose that when rootston or sway is the only compositor running, whatever argument is triggering "invalid argument" is indeed just a nonsense value. However, when there is another compositor running, could it be passing a value that attempts to access a resource owned by the other compositor?
I also get "permission denied" issues pretty often. It happens when we try to do an atomic commit and our DRM session isn't active. We should fix it too (I think we have guards, maybe we are missing some) but it's not an issue related to this one.
In case it helps to track this down, I wanted to note that the behavior has changed just slightly in sway after swaywm/sway#3455: the swaybg_command now successfully executes on the external display when connected, instead of being left with a gray background and needing to reload the config to re-execute it. When unplugging the display, the internal display's swaybg_command would also fail to execute and need a reload, and that has been fixed as well. This seems to add weight to something CRTC-related being the root cause here.
I'm unsure if I'm seeing the same issue here or if my issue is different, but I too get the "invalid argument" error.
Relevant logs
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:904] Reallocating CRTCs
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:916] State before reallocation:
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:926] 'eDP-1' crtc=0 state=1 desired_enabled=1
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:926] 'DP-1' crtc=-1 state=0 desired_enabled=0
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:926] 'HDMI-A-1' crtc=-1 state=0 desired_enabled=0
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:926] 'DP-2' crtc=-1 state=0 desired_enabled=0
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:926] 'DP-3' crtc=-1 state=1 desired_enabled=1
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:926] 'DP-4' crtc=-1 state=1 desired_enabled=1
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:926] 'DP-5' crtc=-1 state=0 desired_enabled=0
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:983] Assigning CRTC 1 to output -1 -> 4 'DP-3'
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:983] Assigning CRTC 2 to output -1 -> 5 'DP-4'
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:987] State after reallocation:
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:992] 'eDP-1' crtc=0 state=1 desired_enabled=1
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:992] 'DP-1' crtc=-1 state=0 desired_enabled=0
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:992] 'HDMI-A-1' crtc=-1 state=0 desired_enabled=0
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:992] 'DP-2' crtc=-1 state=0 desired_enabled=0
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:992] 'DP-3' crtc=1 state=1 desired_enabled=1
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:992] 'DP-4' crtc=2 state=1 desired_enabled=1
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:992] 'DP-5' crtc=-1 state=0 desired_enabled=0
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:462] Reallocating planes
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:507] Assigning plane -1 -> 33 (type 0) to CRTC 41
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:507] Assigning plane -1 -> 47 (type 0) to CRTC 55
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:507] Assigning plane -1 -> 61 (type 0) to CRTC 69
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:507] Assigning plane -1 -> 28 (type 1) to CRTC 41
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:507] Assigning plane -1 -> 42 (type 1) to CRTC 55
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:507] Assigning plane -1 -> 56 (type 1) to CRTC 69
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:507] Assigning plane -1 -> 38 (type 2) to CRTC 41
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:507] Assigning plane -1 -> 52 (type 2) to CRTC 55
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:507] Assigning plane -1 -> 66 (type 2) to CRTC 69
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:1288] Requesting modeset for 'eDP-1'
2019-03-12 16:52:00 - [sway/desktop/output.c:612] New output 0x4314161a070: eDP-1
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:542] Modesetting 'eDP-1' with '2560x1440@59998 mHz'
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:374] Starting renderer on output 'eDP-1'
2019-03-12 16:52:00 - [GLES2] FS SIMD8 shader: 5 inst, 0 loops, 24 cycles, 0:0 spills:fills, Promoted 0 constants, compacted 80 to 48 bytes.
2019-03-12 16:52:00 - [GLES2] FS SIMD16 shader: 5 inst, 0 loops, 34 cycles, 0:0 spills:fills, Promoted 0 constants, compacted 80 to 48 bytes.
2019-03-12 16:52:00 - [GLES2] VS SIMD8 shader: 28 inst, 0 loops, 116 cycles, 0:0 spills:fills, Promoted 0 constants, compacted 448 to 336 bytes.
2019-03-12 16:52:00 - [GLES2] FS SIMD16 shader: 2 inst, 0 loops, 0 cycles, 0:0 spills:fills, Promoted 0 constants, compacted 32 to 32 bytes.
2019-03-12 16:52:00 - [sway/tree/workspace.c:290] Workspace: Generating new workspace name for output eDP-1
2019-03-12 16:52:00 - [sway/tree/workspace.c:227] Got valid workspace command for target: '1'
2019-03-12 16:52:00 - [sway/tree/workspace.c:280] Workspace: Found free name 1
2019-03-12 16:52:00 - [sway/tree/workspace.c:227] Got valid workspace command for target: '2'
2019-03-12 16:52:00 - [sway/tree/workspace.c:227] Got valid workspace command for target: '3'
2019-03-12 16:52:00 - [sway/tree/workspace.c:227] Got valid workspace command for target: '4'
2019-03-12 16:52:00 - [sway/tree/workspace.c:227] Got valid workspace command for target: '5'
2019-03-12 16:52:00 - [sway/tree/workspace.c:227] Got valid workspace command for target: '6'
2019-03-12 16:52:00 - [sway/tree/workspace.c:227] Got valid workspace command for target: '7'
2019-03-12 16:52:00 - [sway/tree/workspace.c:227] Got valid workspace command for target: '8'
2019-03-12 16:52:00 - [sway/tree/workspace.c:227] Got valid workspace command for target: '9'
2019-03-12 16:52:00 - [sway/tree/workspace.c:227] Got valid workspace command for target: '10'
2019-03-12 16:52:00 - [sway/tree/output.c:115] Creating default workspace 1
2019-03-12 16:52:00 - [sway/tree/workspace.c:79] Adding workspace 1 for output eDP-1
2019-03-12 16:52:00 - [sway/desktop/layer_shell.c:178] Usable area changed, rearranging output
2019-03-12 16:52:00 - [sway/tree/arrange.c:190] Usable area for ws: 2560x1440@0,0
2019-03-12 16:52:00 - [sway/tree/arrange.c:221] Arranging workspace '1' at 0.000000, 0.000000
2019-03-12 16:52:00 - [sway/tree/arrange.c:190] Usable area for ws: 2560x1440@0,0
2019-03-12 16:52:00 - [sway/tree/arrange.c:221] Arranging workspace '1' at 0.000000, 0.000000
2019-03-12 16:52:00 - [sway/desktop/transaction.c:413] Transaction 0x4314173c430 committing with 2 instructions
2019-03-12 16:52:00 - [sway/desktop/transaction.c:281] Applying transaction 0x4314173c430
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:1288] Requesting modeset for 'DP-3'
2019-03-12 16:52:00 - [sway/desktop/output.c:612] New output 0x431415ec4b0: DP-3
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:542] Modesetting 'DP-3' with '2560x1440@143856 mHz'
2019-03-12 16:52:00 - [wlroots-0.5.0/backend/drm/drm.c:374] Starting renderer on output 'DP-3'
2019-03-12 16:52:01 - [sway/tree/arrange.c:190] Usable area for ws: 2560x1440@0,0
2019-03-12 16:52:01 - [sway/tree/arrange.c:221] Arranging workspace '1' at 2560.000000, 0.000000
2019-03-12 16:52:01 - [sway/desktop/transaction.c:413] Transaction 0x4314173b750 committing with 1 instructions
2019-03-12 16:52:01 - [sway/desktop/transaction.c:281] Applying transaction 0x4314173b750
2019-03-12 16:52:01 - [sway/tree/workspace.c:290] Workspace: Generating new workspace name for output DP-3
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '1'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '2'
2019-03-12 16:52:01 - [sway/tree/workspace.c:280] Workspace: Found free name 2
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '3'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '4'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '5'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '6'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '7'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '8'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '9'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '10'
2019-03-12 16:52:01 - [sway/tree/output.c:115] Creating default workspace 2
2019-03-12 16:52:01 - [sway/tree/workspace.c:79] Adding workspace 2 for output DP-3
...omitted for brevity...
2019-03-12 16:52:01 - [sway/desktop/layer_shell.c:178] Usable area changed, rearranging output
2019-03-12 16:52:01 - [sway/tree/arrange.c:190] Usable area for ws: 2560x1440@0,0
2019-03-12 16:52:01 - [sway/tree/arrange.c:221] Arranging workspace '2' at 0.000000, 0.000000
2019-03-12 16:52:01 - [sway/tree/arrange.c:190] Usable area for ws: 2560x1440@0,0
2019-03-12 16:52:01 - [sway/tree/arrange.c:221] Arranging workspace '1' at 2560.000000, 0.000000
2019-03-12 16:52:01 - [sway/tree/arrange.c:190] Usable area for ws: 2560x1440@0,0
2019-03-12 16:52:01 - [sway/tree/arrange.c:221] Arranging workspace '2' at 0.000000, 0.000000
2019-03-12 16:52:01 - [sway/desktop/transaction.c:413] Transaction 0x4314175e910 committing with 3 instructions
2019-03-12 16:52:01 - [sway/desktop/transaction.c:281] Applying transaction 0x4314175e910
2019-03-12 16:52:01 - [wlroots-0.5.0/backend/drm/drm.c:1288] Requesting modeset for 'DP-4'
2019-03-12 16:52:01 - [sway/desktop/output.c:612] New output 0x431415ece10: DP-4
2019-03-12 16:52:01 - [wlroots-0.5.0/backend/drm/drm.c:542] Modesetting 'DP-4' with '3440x1440@59973 mHz'
2019-03-12 16:52:01 - [wlroots-0.5.0/backend/drm/drm.c:374] Starting renderer on output 'DP-4'
2019-03-12 16:52:01 - [wlroots-0.5.0/backend/drm/atomic.c:55] DP-4: Atomic commit failed (modeset): Invalid argument
2019-03-12 16:52:01 - [sway/tree/arrange.c:190] Usable area for ws: 2560x1440@0,0
2019-03-12 16:52:01 - [sway/tree/arrange.c:221] Arranging workspace '1' at 6000.000000, 0.000000
2019-03-12 16:52:01 - [sway/tree/arrange.c:190] Usable area for ws: 2560x1440@0,0
2019-03-12 16:52:01 - [sway/tree/arrange.c:221] Arranging workspace '2' at 3440.000000, 0.000000
2019-03-12 16:52:01 - [sway/desktop/transaction.c:413] Transaction 0x43141791330 committing with 2 instructions
2019-03-12 16:52:01 - [sway/desktop/transaction.c:281] Applying transaction 0x43141791330
2019-03-12 16:52:01 - [sway/tree/workspace.c:290] Workspace: Generating new workspace name for output DP-4
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '1'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '2'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '3'
2019-03-12 16:52:01 - [sway/tree/workspace.c:280] Workspace: Found free name 3
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '4'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '5'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '6'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '7'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '8'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '9'
2019-03-12 16:52:01 - [sway/tree/workspace.c:227] Got valid workspace command for target: '10'
2019-03-12 16:52:01 - [sway/tree/output.c:115] Creating default workspace 3
2019-03-12 16:52:01 - [sway/tree/workspace.c:79] Adding workspace 3 for output DP-4
2019-03-12 16:52:01 - [sway/desktop/layer_shell.c:178] Usable area changed, rearranging output
2019-03-12 16:52:01 - [sway/tree/arrange.c:190] Usable area for ws: 3440x1440@0,0
2019-03-12 16:52:01 - [sway/tree/arrange.c:221] Arranging workspace '3' at 0.000000, 0.000000
2019-03-12 16:52:01 - [sway/tree/arrange.c:190] Usable area for ws: 2560x1440@0,0
2019-03-12 16:52:01 - [sway/tree/arrange.c:221] Arranging workspace '1' at 6000.000000, 0.000000
2019-03-12 16:52:01 - [sway/tree/arrange.c:190] Usable area for ws: 2560x1440@0,0
2019-03-12 16:52:01 - [sway/tree/arrange.c:221] Arranging workspace '2' at 3440.000000, 0.000000
2019-03-12 16:52:01 - [sway/tree/arrange.c:190] Usable area for ws: 3440x1440@0,0
2019-03-12 16:52:01 - [sway/tree/arrange.c:221] Arranging workspace '3' at 0.000000, 0.000000
2019-03-12 16:52:01 - [sway/desktop/transaction.c:413] Transaction 0x43141791730 committing with 4 instructions
2019-03-12 16:52:01 - [sway/desktop/transaction.c:281] Applying transaction 0x43141791730
...omitted for brevity...
2019-03-12 16:52:01 - [wlroots-0.5.0/backend/drm/atomic.c:55] DP-4: Atomic commit failed (modeset): Invalid argument
2019-03-12 16:52:01 - [wlroots-0.5.0/backend/drm/atomic.c:62] DP-4: Atomic commit without new changes failed (modeset): Invalid argument
In the log above, DP-4
fails to initialize and does not receive signal. Cold boot, hotplug or otherwise, DP-4
fails with default configuration (no configured outputs).
Can you echo 0xFF | sudo tee /sys/module/drm/parameters/debug
, reproduce the bug, then echo 0x00 | sudo tee /sys/module/drm/parameters/debug
, and upload dmesg
?
Enabling DRM debug will produce very verbose output, so if you can reproduce as quick as possible between enabling debug and disabling it that would be better.
Sure, given the large-volume output, what should I be looking for to share here? Worst case I can always post the whole thing, but if I can pull out what would help that'd likely be easier on everyone.
Just post whatever you get between enabling logs and disabling them. Having too many logs is better than missing a critical piece of info.
Sure, I'll have that here in five minutes.
Hopefully this is enough, as my log buffer is not large: https://gist.github.com/Eriner/8d1a428cf792b8ca1976ac4cb7373c4c
I can reboot and try again with a larger buffer if that has truncated anything critical.
I should probably note that I had to pull the dock USB-C connection at the end to regain the tty after exiting sway.
This is the line where it's failing it seems: https://gist.github.com/Eriner/8d1a428cf792b8ca1976ac4cb7373c4c#file-dmesg-log-L186