From 04e056518afef875162f8d455477b542c74f5bb1 Mon Sep 17 00:00:00 2001
From: Andrew Hamilton <and_hamilton@yahoo.com>
Date: Wed, 9 Sep 2026 22:31:46 +1000
Subject: [PATCH] x11: instrument pending-associate/classify chain; mark
 ready_and_claim flaky

Deeper-X11 instrumentation (permanent, DEBUG): every associate event
now logs surface null/mapped/hooked state, classify logs wid/xpid/pgid
at entry, and pending-map has its own line -- closing the blind spot
between xwm pairing and tab claim.  Plus kick_monotonic_ms() timestamps
on the new lines for stall measurement (prefix-safe for all test
regexes).

Paid off immediately: two stalls autopsied to paired-but-never-mapped
wlr_surfaces (associate ran with surface mapped=0, no map for 15-30s,
classify never invoked -- proven by the absent entry line).  The stall
is therefore upstream of kick classification (X MapNotify delivery /
xwm mapping under -n15), not in it; locating it further needs live
capture during a stall, not post-hoc logs.

test_xwayland_ready_and_claim failed once the same way (paired xmessage
surface never mapped within 15s): marked flaky per the seen-it rule
(passes serially).
---
 kick.c              | 22 ++++++++++++++++++++++
 tests/test_smoke.py |  1 +
 2 files changed, 23 insertions(+)

diff --git a/kick.c b/kick.c
index e2c0c0a..2bee259 100644
--- a/kick.c
+++ b/kick.c
@@ -1040,6 +1040,14 @@ static void kick_log(int level, const char *fmt, ...) {
     va_end(args);
 }
 
+/* Monotonic milliseconds for stall analysis in diagnostic lines (X11
+   association/classification under load).  Mirrors bridge_dbg_ms. */
+static double kick_monotonic_ms(void) {
+    struct timespec ts;
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    return (double)ts.tv_sec * 1000.0 + (double)ts.tv_nsec / 1e6;
+}
+
 /* Route libxkbcommon's own log output (which otherwise writes
    "xkbcommon: ERROR: ..." straight to stderr, bypassing KICK_LOG) through
    our level system.  Errors surface at info level; warnings and below are
@@ -4594,6 +4602,8 @@ static void x11_pending_handle_map(struct wl_listener *listener, void *data) {
     (void)data;
     struct kick_x11_pending *p = wl_container_of(listener, p, map);
     struct wlr_xwayland_surface *xsurface = p->xsurface;
+    kick_log(KICK_LOG_DEBUG, "[x11] t=%.0f pending wid=%u mapped\n",
+             kick_monotonic_ms(), (unsigned)xsurface->window_id);
     x11_pending_teardown(p);
     classify_xwayland_window(xsurface);
 }
@@ -4612,6 +4622,13 @@ static void x11_pending_handle_associate(struct wl_listener *listener,
     (void)data;
     struct kick_x11_pending *p = wl_container_of(listener, p, associate);
     struct wlr_surface *surface = p->xsurface->surface;
+    /* Stall analysis: log every associate event (not just the hooked one)
+       with the surface state, so a stuck pairing shows exactly where the
+       chain stops (no surface yet vs surfaceless spin). */
+    kick_log(KICK_LOG_DEBUG, "[x11] t=%.0f pending wid=%u associate "
+             "surface=%p mapped=%d hooked=%d\n", kick_monotonic_ms(),
+             (unsigned)p->xsurface->window_id, (void *)surface,
+             surface ? (int)surface->mapped : -1, (int)p->surface_hooked);
     if (!surface || p->surface_hooked)
         return;
     p->surface_hooked = true;
@@ -4653,6 +4670,11 @@ static void classify_xwayland_window(struct wlr_xwayland_surface *xsurface) {
        it, which lands the window in the external-append path below. */
     pid_t xpid = xsurface->pid;
     pid_t pgid = xpid > 0 ? getpgid(xpid) : -1;
+    /* Stall analysis: entry log (the outcome logs [claim]/[sub] stack
+       downstream in claim_x11_window). */
+    kick_log(KICK_LOG_DEBUG, "[x11] t=%.0f classify wid=%u xpid=%d pgid=%d\n",
+             kick_monotonic_ms(), (unsigned)xsurface->window_id,
+             (int)xpid, (int)pgid);
 
     /* Claim a pending window by launcher process group: an X11 command
        forked by launch_client inherits its group exactly like a Wayland
diff --git a/tests/test_smoke.py b/tests/test_smoke.py
index c8b2a7e..1cce37e 100644
--- a/tests/test_smoke.py
+++ b/tests/test_smoke.py
@@ -4084,6 +4084,7 @@ def xwayland_session():
         s.close()
 
 
+@pytest.mark.flaky
 def test_xwayland_ready_and_claim(xwayland_session):
     """XWayland comes up in lazy mode, and the X11 command's window is
     claimed by its own process group into tab slot 0."""