From b82a9ca9c394ead63ecd13677aa8214b14d84720 Mon Sep 17 00:00:00 2001 From: Stephen Hellings Date: Mon, 9 Mar 2026 13:08:59 -0400 Subject: [PATCH] fix: clear IPC socket timeout after handshake, add vblank recovery and render diagnostics MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three bugs addressed: 1. SO_RCVTIMEO(5s) on the IPC socket was never cleared after the HELLO handshake. When the web page becomes static (no paint events for >5s), the blocking read_exact in recv_message times out, the IPC reader thread exits, and the socket is closed — causing ECONNRESET on the Electron side and permanently stalling frame delivery. Fix: clear SO_RCVTIMEO to zero (infinite) immediately after successful HELLO exchange. 2. If a VBlank event is lost or delayed (e.g. during DRM master transitions), vblank_pending stays true and all subsequent render_frame calls bail out permanently. Fix: if vblank_pending has been stuck for >500ms, force-clear it with a warning so rendering can resume. making it impossible to diagnose the black screen from logs. Fix: add INFO-level logging for first render, first page flip, first texture import, swapchain exhaustion on first frame, and vblank recovery events. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- src/electron.rs | 12 +++++++ src/main.rs | 85 +++++++++++++++++++++++++++++++++++++++++++------ 2 files changed, 88 insertions(+), 9 deletions(-) diff --git a/src/electron.rs b/src/electron.rs index c709deb..cf7bb86 100644 --- a/src/electron.rs +++ b/src/electron.rs @@ -810,6 +810,18 @@ fn handle_connection( }); clients.lock().unwrap().insert(name.clone(), client.clone()); + // Clear the handshake-only SO_RCVTIMEO so the reader thread blocks + // indefinitely between messages. A static web page may produce no paint + // events for many seconds; a 5-second timeout would incorrectly kill the + // connection during these normal idle periods. + { + let borrowed = unsafe { std::os::fd::BorrowedFd::borrow_raw(fd) }; + let no_timeout = TimeVal::new(0, 0); + if let Err(e) = setsockopt(&borrowed, ReceiveTimeout, &no_timeout) { + warn!("Failed to clear SO_RCVTIMEO on IPC socket: {e}"); + } + } + // 2. Stream Messages (frames, syscalls, positions, etc.) let mut msg_count = 0u32; loop { diff --git a/src/main.rs b/src/main.rs index ea05674..9db8492 100644 --- a/src/main.rs +++ b/src/main.rs @@ -86,9 +86,13 @@ struct EventLoopData { session: smithay::backend::session::libseat::LibSeatSession, active: bool, vblank_pending: bool, + /// When vblank_pending was first set; used to detect stuck vblank state. + vblank_since: Option, consecutive_flip_failures: u32, /// DRI render node path for spawning Electron processes (e.g. `/dev/dri/renderD128`). electron_render_node: String, + /// Total successful page flips (for startup diagnostics). + total_flips: u64, } const MAX_CONSECUTIVE_FLIP_FAILURES: u32 = 5; @@ -307,14 +311,32 @@ fn main() -> Result<(), anyhow::Error> { /// Render a single frame - called by VBlank events fn render_frame(data: &mut EventLoopData) { - // Bail if session is paused (VT switched away) or a page flip is pending + // Bail if session is paused (VT switched away) if !data.active { trace!("Skipping render: session inactive"); return; } + + // Vblank-pending gate: skip if a page flip is outstanding. + // Safety net: if vblank_pending has been stuck for >500ms, the VBlank event + // was likely lost (e.g. during DRM master transitions). Force-clear so + // rendering can resume. if data.vblank_pending { - trace!("Skipping render: vblank pending"); - return; + if let Some(since) = data.vblank_since { + if since.elapsed() > Duration::from_millis(500) { + warn!( + "vblank_pending stuck for {:?} (total_flips={}), force-clearing", + since.elapsed(), + data.total_flips, + ); + data.vblank_pending = false; + data.vblank_since = None; + } else { + return; + } + } else { + return; + } } // Frame pacing: respect adaptive timing for input responsiveness @@ -330,8 +352,14 @@ fn render_frame(data: &mut EventLoopData) { data.last_render = std::time::Instant::now(); data.input_events_pending = false; - // First render: mark all windows damaged + // First render: mark all windows damaged and log diagnostic state if data.first_render { + info!( + "First render: output={}x{}, windows={}, bg={:?}", + data.width, data.height, + data.state.config.windows.len(), + data.bg, + ); for win_cfg in &data.state.config.windows { data.state.damaged_windows.insert(win_cfg.name.clone()); } @@ -341,7 +369,12 @@ fn render_frame(data: &mut EventLoopData) { // Acquire swapchain slot let slot = match data.swapchain.acquire() { Ok(Some(slot)) => slot, - Ok(None) => return, + Ok(None) => { + if data.total_flips == 0 { + warn!("Swapchain: no free slots on first frame"); + } + return; + } Err(e) => { warn!("Error acquiring swapchain slot: {e}"); return; @@ -508,7 +541,9 @@ fn render_frame(data: &mut EventLoopData) { })(); if !render_ok { - trace!("Rendering failed, skipping page flip"); + if data.total_flips == 0 { + warn!("Rendering failed on first frame, skipping page flip"); + } data.swapchain.submitted(&slot); data.state.damaged_windows.clear(); if context_lost { @@ -543,16 +578,24 @@ fn render_frame(data: &mut EventLoopData) { }), }; + let tex_count = data.gles_tex_cache.len(); + // Schedule page flip (or full modeset commit for the first frame). // smithay's DrmSurface tracks pending state (mode, connectors). When // commit_pending() is true (e.g. first frame after surface creation or // VT switch), we must use commit() which includes ALLOW_MODESET. // page_flip() only does a non-blocking flip without modesetting and will // fail with EINVAL if the CRTC doesn't have a mode set yet. - let result = if data.drm_surface.commit_pending() { - info!("Performing initial modeset commit"); + let commit_pending = data.drm_surface.commit_pending(); + let result = if commit_pending { + info!("Performing initial modeset commit (textures={})", tex_count); data.drm_surface.commit([plane_state.clone()], true) } else { + // On the very first page_flip (no prior flips), log at INFO level + // so we can confirm the rendering pipeline is working. + if data.total_flips == 0 { + info!("First page_flip (commit_pending=false, textures={})", tex_count); + } data.drm_surface.page_flip([plane_state.clone()], true) }; @@ -560,6 +603,11 @@ fn render_frame(data: &mut EventLoopData) { Ok(_) => { data.consecutive_flip_failures = 0; data.vblank_pending = true; + data.vblank_since = Some(Instant::now()); + data.total_flips += 1; + if data.total_flips == 1 { + info!("First successful page flip (commit_pending={})", commit_pending); + } } Err(e) => { data.consecutive_flip_failures = data.consecutive_flip_failures.saturating_add(1); @@ -589,6 +637,7 @@ fn render_frame(data: &mut EventLoopData) { ); write_flip_failure_report(&commit_report); data.vblank_pending = false; + data.vblank_since = None; if data.consecutive_flip_failures >= MAX_CONSECUTIVE_FLIP_FAILURES { let report = format!( "Exceeded consecutive DRM flip failures ({}). Last page_flip error: {e}; last commit error: {commit_err}. Exiting compositor.", @@ -604,6 +653,8 @@ fn render_frame(data: &mut EventLoopData) { } else { data.consecutive_flip_failures = 0; data.vblank_pending = true; + data.vblank_since = Some(Instant::now()); + data.total_flips += 1; } } } @@ -648,6 +699,7 @@ fn run_drm(config: Config) -> Result<(), anyhow::Error> { info!("Session paused (VT switched away). Pausing DRM device and halting rendering."); data.active = false; data.vblank_pending = false; + data.vblank_since = None; data.drm.pause(); } Event::ActivateSession => { @@ -656,10 +708,12 @@ fn run_drm(config: Config) -> Result<(), anyhow::Error> { error!("Failed to activate DRM device on session resume: {e}"); data.active = false; data.vblank_pending = false; + data.vblank_since = None; return; } data.active = true; data.vblank_pending = false; + data.vblank_since = None; if let Err(e) = data.display.flush_clients() { warn!("Failed to flush Wayland clients on activation: {e}"); } @@ -1121,9 +1175,11 @@ fn run_drm(config: Config) -> Result<(), anyhow::Error> { session, active: true, vblank_pending: false, + vblank_since: None, consecutive_flip_failures: 0, gles_tex_cache: std::collections::HashMap::new(), electron_render_node: electron_render_node, + total_flips: 0, }; let signal_for_handler = loop_signal.clone(); @@ -1140,6 +1196,7 @@ fn run_drm(config: Config) -> Result<(), anyhow::Error> { if !data.active { if let DrmEvent::VBlank(_) = event { data.vblank_pending = false; + data.vblank_since = None; } trace!("Ignoring DRM event while session is inactive"); return; @@ -1147,6 +1204,7 @@ fn run_drm(config: Config) -> Result<(), anyhow::Error> { if let DrmEvent::VBlank(_) = event { // The screen just refreshed! We are clear to render the next frame. data.vblank_pending = false; + data.vblank_since = None; render_frame(data); } }) @@ -1274,14 +1332,23 @@ fn run_drm(config: Config) -> Result<(), anyhow::Error> { // Import latest frames for (_name, frame) in latest_frames { let frame_name = frame.name.clone(); + let frame_dims = (frame.width, frame.height); if let Some(renderer_arc) = data.state.backend.renderer() { match renderer_arc.lock() { Ok(ref mut renderer) => { match import_electron_frame(renderer, frame) { Ok((tex, cached)) => { + let is_first = !data.gles_tex_cache.contains_key(&frame_name); data.state.damaged_windows.insert(frame_name.clone()); data.state.texture_cache.insert_dmabuf(cached); - data.gles_tex_cache.insert(frame_name, tex.texture); + data.gles_tex_cache.insert(frame_name.clone(), tex.texture); + if is_first { + info!( + "First DMABUF imported for '{}' ({}x{}, total_textures={})", + frame_name, frame_dims.0, frame_dims.1, + data.gles_tex_cache.len(), + ); + } } Err(e) => warn!("DMABUF import failed for '{}': {e:#}", frame_name), }