Add opt-in delivery-debug.log for paced text delivery

Advanced debugging now also records paced-delivery metadata (byte
offsets, lease/send errors, finish results and the exact focus-guard
check that failed) to an owner-private delivery-debug.log. No transcript
text is logged. Diagnoses later chunks being dropped after the first.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

docs/worker.md

@@ -112,6 +112,12 @@ is required to avoid competing rotation by multiple workers. Debug output never
 shares the framed protocol stdout. Direct worker CLI use with `--advanced-debug`
 writes to its caller's stderr; the native adapter supplies the private bounded sink.
 
+The same opt-in also writes `delivery-debug.log` (rotated to
+`delivery-debug.previous.log` when debugging is enabled, capped near 1 MiB) in
+that directory: paced-delivery metadata only — start/sent byte counts and
+offsets, lease/send errors, finish results and which focus-guard check failed.
+It never contains transcript text.
+
 Hardware-free tests run through CTest, including fake-child cancellation, short
 injected warmup/request deadlines, duplicate/stale replies, malformed frames,
 missing/hash-mismatched model files and symlink refusal. Default production

src/focus_guard.cpp

@@ -21,6 +21,7 @@ struct FocusGuard::Impl {
     bool attempted = false;
     bool armed = false;
     bool dead = false;
+    const char* reason = "none";
 
     ~Impl() { if (connection) xcb_disconnect(connection); }
 
@@ -80,10 +81,12 @@ struct FocusGuard::Impl {
 
     bool snapshot(xcb_window_t& current) {
         xcb_window_t active = XCB_WINDOW_NONE, gamescope = XCB_WINDOW_NONE, actual = XCB_WINDOW_NONE;
-        if (!property_window(active_atom, XCB_ATOM_WINDOW, active) ||
-            !property_window(gamescope_atom, XCB_ATOM_CARDINAL, gamescope) ||
-            !focus(actual) || active != gamescope || active != actual || !keys_up())
-            return false;
+        if (!property_window(active_atom, XCB_ATOM_WINDOW, active)) { reason = "no _NET_ACTIVE_WINDOW"; return false; }
+        if (!property_window(gamescope_atom, XCB_ATOM_CARDINAL, gamescope)) { reason = "no GAMESCOPE_FOCUSED_WINDOW"; return false; }
+        if (!focus(actual)) { reason = "no X input focus"; return false; }
+        if (active != gamescope) { reason = "active != gamescope focus"; return false; }
+        if (active != actual) { reason = "active != X input focus"; return false; }
+        if (!keys_up()) { reason = "key held"; return false; }
         current = active;
         return true;
     }
@@ -92,15 +95,17 @@ struct FocusGuard::Impl {
         while (xcb_generic_event_t* event = xcb_poll_for_event(connection)) {
             const uint8_t type = event->response_type & 0x7f;
             bool bad = type == 0; // asynchronous X error
+            if (bad) reason = "X error";
             if (type == XCB_PROPERTY_NOTIFY) {
                 const auto* e = reinterpret_cast<xcb_property_notify_event_t*>(event);
-                if (e->window == root && (e->atom == active_atom || e->atom == gamescope_atom)) bad = true;
+                if (e->window == root && e->atom == active_atom) { bad = true; reason = "_NET_ACTIVE_WINDOW changed"; }
+                if (e->window == root && e->atom == gamescope_atom) { bad = true; reason = "GAMESCOPE_FOCUSED_WINDOW changed"; }
             } else if (type == XCB_FOCUS_OUT) {
                 const auto* e = reinterpret_cast<xcb_focus_out_event_t*>(event);
-                if (e->event == target) bad = true;
+                if (e->event == target) { bad = true; reason = "FocusOut on target"; }
             } else if (type == XCB_DESTROY_NOTIFY) {
                 const auto* e = reinterpret_cast<xcb_destroy_notify_event_t*>(event);
-                if (e->window == target) bad = true;
+                if (e->window == target) { bad = true; reason = "target destroyed"; }
             } else if (type == XCB_CREATE_NOTIFY || type == XCB_UNMAP_NOTIFY ||
                        type == XCB_MAP_NOTIFY || type == XCB_MAP_REQUEST ||
                        type == XCB_REPARENT_NOTIFY || type == XCB_CONFIGURE_NOTIFY ||
@@ -122,18 +127,22 @@ struct FocusGuard::Impl {
                 case XCB_CIRCULATE_NOTIFY: window = reinterpret_cast<xcb_circulate_notify_event_t*>(event)->window; break;
                 case XCB_CIRCULATE_REQUEST: window = reinterpret_cast<xcb_circulate_request_event_t*>(event)->window; break;
                 }
-                if (window == target) bad = true;
+                if (window == target) { bad = true; reason = "structure event on target"; }
             }
             std::free(event);
             if (bad) return false;
         }
-        return !failed();
+        if (failed()) { reason = "X connection failed"; return false; }
+        return true;
     }
 
     bool check() {
-        if (!armed || failed() || !drain_events()) { dead = true; return false; }
+        if (!armed || dead) { reason = armed ? reason : "not armed"; dead = true; return false; }
+        if (failed() || !drain_events()) { dead = true; return false; }
         xcb_window_t current = XCB_WINDOW_NONE;
-        if (!snapshot(current) || current != target || !drain_events()) {
+        if (!snapshot(current)) { dead = true; return false; }
+        if (current != target) { reason = "focus moved to another window"; dead = true; return false; }
+        if (!drain_events()) {
             dead = true;
             return false;
         }
@@ -178,6 +187,7 @@ bool FocusGuard::arm() {
 }
 
 bool FocusGuard::valid() { return impl_->check(); }
+const char* FocusGuard::failure() const { return impl_->reason; }
 void FocusGuard::invalidate() { impl_->dead = true; impl_->armed = false; }
 
 } // namespace frameyap

src/focus_guard.hpp

@@ -18,6 +18,8 @@ public:
     bool arm();
     bool valid();
     void invalidate();
+    // Static label of the most recent failed check, for opt-in diagnostics.
+    const char* failure() const;
 
 private:
     struct Impl;

src/paced_delivery.cpp

@@ -9,6 +9,9 @@ PacedDelivery::PacedDelivery(DeliveryFactory acquire, Clock clock,
     : acquire_(std::move(acquire)), clock_(std::move(clock)),
       release_idle_(std::move(release_idle)), permitted_(std::move(permitted)) {}
 
+void PacedDelivery::trace(const std::string& line) const {
+    if (trace_) { try { trace_(line); } catch (...) {} }
+}
 bool PacedDelivery::valid_guard() const {
     try { return (!permitted_ || permitted_()) && task_->guard && task_->guard(); }
     catch (...) { return false; }
@@ -32,15 +35,25 @@ void PacedDelivery::start(std::string text, bool enter, Guard guard,
         candidate->first_lease = acquire_();
         if (!candidate->first_lease || (permitted_ && !permitted_()) || !candidate->guard())
             throw std::runtime_error("Input focus changed during acquisition");
+    } catch (const std::exception& e) {
+        trace(std::string("start rejected: ") + e.what());
+        std::fill(candidate->text.begin(), candidate->text.end(), '\0');
+        throw;
     } catch (...) {
+        trace("start rejected: unknown");
         std::fill(candidate->text.begin(), candidate->text.end(), '\0');
         throw;
     }
+    trace("start bytes=" + std::to_string(candidate->text.size()) +
+          " enter=" + (candidate->enter ? "1" : "0"));
     retained_ = true;
     task_ = std::move(candidate);
 }
 PacedDelivery::Outcome PacedDelivery::finish(DeliveryResult result, bool focus_lost) {
     Outcome out{result, task_->began, focus_lost};
+    trace("finish result=" + std::to_string(static_cast<int>(result)) + " began=" +
+          (task_->began ? "1" : "0") + " focus_lost=" + (focus_lost ? "1" : "0") +
+          " offset=" + std::to_string(task_->offset) + "/" + std::to_string(task_->text.size()));
     std::fill(task_->text.begin(), task_->text.end(), '\0');
     task_.reset();
     return out;
@@ -59,15 +72,25 @@ std::optional<PacedDelivery::Outcome> PacedDelivery::tick() {
     auto& task = *task_;
     // A focus loss before ANY send leaves the review unconsumed. After the
     // first possible send, the remainder is discarded, not retargeted/retried.
-    if (!valid_guard()) return finish(task.began ? DeliveryResult::TextUncertain : DeliveryResult::Ignored, true);
+    if (!valid_guard()) {
+        trace("guard failed before acquire");
+        return finish(task.began ? DeliveryResult::TextUncertain : DeliveryResult::Ignored, true);
+    }
     std::unique_ptr<DeliveryLease> lease = std::move(task.first_lease);
     if (!lease) {
         try { lease = acquire_(); }
-        catch (...) { return finish(task.began ? (task.offset == task.text.size() ?
+        catch (const std::exception& e) {
+            trace(std::string("acquire failed: ") + e.what());
+            return finish(task.began ? (task.offset == task.text.size() ?
+            DeliveryResult::TextQueuedEnterUnavailable : DeliveryResult::TextUncertain) : DeliveryResult::Ignored); }
+        catch (...) { trace("acquire failed: unknown"); return finish(task.began ? (task.offset == task.text.size() ?
             DeliveryResult::TextQueuedEnterUnavailable : DeliveryResult::TextUncertain) : DeliveryResult::Ignored); }
         if (!lease) return finish(task.began ? DeliveryResult::TextUncertain : DeliveryResult::Ignored);
     }
-    if (!valid_guard()) return finish(task.began ? DeliveryResult::TextUncertain : DeliveryResult::Ignored, true);
+    if (!valid_guard()) {
+        trace("guard failed after acquire");
+        return finish(task.began ? DeliveryResult::TextUncertain : DeliveryResult::Ignored, true);
+    }
     if (!task.began) {
         // A callback consumes review immediately before a possibly ambiguous send.
         try { if (task.on_first_send) task.on_first_send(); }
@@ -87,17 +110,25 @@ std::optional<PacedDelivery::Outcome> PacedDelivery::tick() {
         try {
             chunk = task.text.substr(task.offset, end - task.offset);
             lease->text(chunk);
+        } catch (const std::exception& e) {
+            trace("text send failed at offset=" + std::to_string(task.offset) + ": " + e.what());
+            last_commit_ = clock_();
+            std::fill(chunk.begin(), chunk.end(), '\0');
+            return finish(DeliveryResult::TextUncertain);
         } catch (...) {
+            trace("text send failed at offset=" + std::to_string(task.offset) + ": unknown");
             last_commit_ = clock_();
             std::fill(chunk.begin(), chunk.end(), '\0');
             return finish(DeliveryResult::TextUncertain);
         }
         last_commit_ = clock_();
+        trace("sent offset=" + std::to_string(task.offset) + " bytes=" + std::to_string(end - task.offset));
         std::fill(chunk.begin(), chunk.end(), '\0');
         task.offset = end;
         if (end == task.text.size() && !task.enter) return finish(DeliveryResult::TextQueued);
     } else {
-        try { lease->enter(); }
+        try { lease->enter(); trace("sent enter"); }
+        catch (const std::exception& e) { trace(std::string("enter failed: ") + e.what()); last_commit_ = clock_(); return finish(DeliveryResult::EnterUncertain); }
         catch (...) { last_commit_ = clock_(); return finish(DeliveryResult::EnterUncertain); }
         last_commit_ = clock_();
         return finish(DeliveryResult::EnterQueued);

src/paced_delivery.hpp

@@ -13,6 +13,8 @@ class PacedDelivery {
 public:
     using Clock = std::function<std::chrono::steady_clock::time_point()>;
     using Guard = std::function<bool()>;
+    // Opt-in diagnostics: metadata only (sizes, offsets, reasons), never text.
+    using Trace = std::function<void(const std::string&)>;
     struct Outcome {
         DeliveryResult result;
         bool began;       // first send may have reached the compositor
@@ -32,6 +34,7 @@ public:
     bool active() const { return bool(task_); }
     bool began() const { return task_ && task_->began; }
     void cancel(); // drops and scrubs the remaining literal; never sends Enter
+    void set_trace(Trace trace) { trace_ = std::move(trace); }
 private:
     struct Task {
         std::string text;
@@ -44,10 +47,12 @@ private:
     bool valid_guard() const;
     Outcome finish(DeliveryResult result, bool focus_lost = false);
     void release_if_idle();
+    void trace(const std::string& line) const;
     DeliveryFactory acquire_;
     Clock clock_;
     std::function<void()> release_idle_;
     Guard permitted_;
+    Trace trace_;
     std::unique_ptr<Task> task_;
     std::optional<std::chrono::steady_clock::time_point> last_commit_;
     bool retained_ = false;

src/runtime.cpp

@@ -17,6 +17,7 @@
 #include <memory>
 #include <stdexcept>
 #include <thread>
+#include <unistd.h>
 
 namespace frameyap {
 namespace {
@@ -64,12 +65,50 @@ private:
     Worker worker_;
     std::string backend_, model_, manifest_, root_;
 };
+// Opt-in (Advanced debug) native delivery diagnostics. Metadata only: never
+// transcript text. Owner-private file next to worker-debug.log.
+class DeliveryTrace {
+public:
+    ~DeliveryTrace() { set_enabled(false); }
+    void set_enabled(bool enabled) {
+        if (enabled == enabled_) return;
+        enabled_ = enabled;
+        if (fd_ >= 0) { ::close(fd_); fd_ = -1; }
+        if (enabled_) {
+            try { fd_ = open_private_debug_log("delivery-debug.log", "delivery-debug.previous.log"); }
+            catch (...) { fd_ = -1; }
+            written_ = 0;
+        }
+    }
+    void operator()(const std::string& line) {
+        if (fd_ < 0 || written_ > 1024 * 1024) return;
+        const auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
+            std::chrono::steady_clock::now() - start_).count();
+        const auto out = std::to_string(ms) + "ms " + line + "\n";
+        if (::write(fd_, out.data(), out.size()) > 0) written_ += out.size();
+    }
+private:
+    bool enabled_ = false;
+    int fd_ = -1;
+    size_t written_ = 0;
+    std::chrono::steady_clock::time_point start_ = std::chrono::steady_clock::now();
+};
 class NativeFocus final : public ControllerFocus {
 public:
-    bool arm() override { return guard_.arm(); }
-    bool valid() override { return guard_.valid(); }
+    explicit NativeFocus(DeliveryTrace& trace) : trace_(trace) {}
+    bool arm() override {
+        if (guard_.arm()) { trace_("focus armed"); return true; }
+        trace_(std::string("focus arm failed: ") + guard_.failure());
+        return false;
+    }
+    bool valid() override {
+        if (guard_.valid()) return true;
+        trace_(std::string("focus invalid: ") + guard_.failure());
+        return false;
+    }
 private:
     FocusGuard guard_;
+    DeliveryTrace& trace_;
 };
 } // namespace
 int run(const Options& options) {
@@ -85,6 +124,8 @@ int run(const Options& options) {
     auto old_term = std::signal(SIGTERM, signal_stop);
     struct Restore { decltype(old_int) a, b; ~Restore() { std::signal(SIGINT, a); std::signal(SIGTERM, b); } } restore{old_int, old_term};
     Overlay overlay(options.assets, options.font, options.mount);
+    DeliveryTrace trace;
+    trace.set_enabled(overlay.advanced_debug());
     NativeWorker worker(options);
     NativeAudio audio;
     const DeliveryFactory acquire = [&]() -> std::unique_ptr<DeliveryLease> {
@@ -94,7 +135,8 @@ int run(const Options& options) {
     };
     PacedDelivery paced(acquire, std::chrono::steady_clock::now,
                         [] { TextInput::release_idle(); }, [] { return !interrupted; });
-    Controller controller(audio, worker, acquire, [] { return std::make_unique<NativeFocus>(); },
+    paced.set_trace([&trace](const std::string& line) { trace(line); });
+    Controller controller(audio, worker, acquire, [&trace] { return std::make_unique<NativeFocus>(trace); },
                           overlay.quick_inputs(), overlay.auto_insert(), overlay.advanced_debug(),
                           overlay.close_mic_when_idle(), &paced);
     namespace fs = std::filesystem;
@@ -190,6 +232,7 @@ int run(const Options& options) {
                 "Selected model unavailable or being checked. Recording disabled until offline verification.");
         }
         bool debug_changed = overlay.advanced_debug() != previous_debug;
+        trace.set_enabled(overlay.advanced_debug());
         controller.settings(overlay.auto_insert(), overlay.advanced_debug(), overlay.close_mic_when_idle());
         // Debug consent and model actions cancel work before any stale input.
         if (debug_changed || !model_actions.empty()) {

src/worker.cpp

@@ -138,21 +138,6 @@ void check_log_target(int dir, const char* name) {
     ::close(fd);
     if (!valid) throw std::runtime_error("unsafe existing worker debug log");
 }
-int create_debug_log() {
-    int dir = state_directory();
-    try {
-        check_log_target(dir, "worker-debug.log");
-        check_log_target(dir, "worker-debug.previous.log");
-        if (::unlinkat(dir, "worker-debug.previous.log", 0) && errno != ENOENT)
-            throw std::runtime_error("cannot rotate worker debug log");
-        if (::renameat(dir, "worker-debug.log", dir, "worker-debug.previous.log") && errno != ENOENT)
-            throw std::runtime_error("cannot rotate worker debug log");
-        int fd = ::openat(dir, "worker-debug.log", O_WRONLY | O_CREAT | O_EXCL | O_NOFOLLOW | O_CLOEXEC, 0600);
-        if (fd < 0) throw std::runtime_error("cannot create private worker debug log");
-        ::close(dir);
-        return fd;
-    } catch (...) { ::close(dir); throw; }
-}
 void log_bytes(int fd, const unsigned char* data, size_t size) {
     while (size) {
         ssize_t n = ::write(fd, data, size);
@@ -194,6 +179,22 @@ void write_all(int fd, const unsigned char* data, size_t size) {
 }
 } // namespace
 
+int open_private_debug_log(const char* name, const char* previous) {
+    int dir = state_directory();
+    try {
+        check_log_target(dir, name);
+        check_log_target(dir, previous);
+        if (::unlinkat(dir, previous, 0) && errno != ENOENT)
+            throw std::runtime_error("cannot rotate debug log");
+        if (::renameat(dir, name, dir, previous) && errno != ENOENT)
+            throw std::runtime_error("cannot rotate debug log");
+        int fd = ::openat(dir, name, O_WRONLY | O_CREAT | O_EXCL | O_NOFOLLOW | O_CLOEXEC, 0600);
+        if (fd < 0) throw std::runtime_error("cannot create private debug log");
+        ::close(dir);
+        return fd;
+    } catch (...) { ::close(dir); throw; }
+}
+
 struct Worker::State {
     pid_t pid = -1;
     int to_child = -1, from_child = -1, debug_pipe = -1, debug_file = -1;
@@ -293,7 +294,7 @@ void Worker::start(const std::string& python, const std::string& script,
         if (!::mkdtemp(tmp.data())) throw std::runtime_error("cannot create private clip directory");
         state_->dir = tmp.data();
         ::chmod(state_->dir.c_str(), 0700);
-        if (advanced_debug) state_->debug_file = create_debug_log();
+        if (advanced_debug) state_->debug_file = open_private_debug_log("worker-debug.log", "worker-debug.previous.log");
         int in[2]{-1,-1}, out[2]{-1,-1}, debug[2]{-1,-1};
         if (::pipe2(in, O_CLOEXEC) || ::pipe2(out, O_CLOEXEC) ||
             (advanced_debug && ::pipe2(debug, O_CLOEXEC))) {

src/worker.hpp

@@ -15,6 +15,10 @@ struct WorkerReply {
     std::string error;
 };
 
+// Opens (rotating `previous`) an owner-private 0600 file in the FrameYap state
+// directory, or throws. Used only for opt-in advanced debugging.
+int open_private_debug_log(const char* name, const char* previous);
+
 class Worker {
 public:
     explicit Worker(std::chrono::milliseconds warmup_timeout = std::chrono::seconds(120),