diff --git a/docs/worker.md b/docs/worker.md index 2507cb2..0020316 100644 --- a/docs/worker.md +++ b/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 diff --git a/src/focus_guard.cpp b/src/focus_guard.cpp index 03f138b..e863c21 100644 --- a/src/focus_guard.cpp +++ b/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(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(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(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(event)->window; break; case XCB_CIRCULATE_REQUEST: window = reinterpret_cast(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 diff --git a/src/focus_guard.hpp b/src/focus_guard.hpp index 8303921..182522e 100644 --- a/src/focus_guard.hpp +++ b/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; diff --git a/src/paced_delivery.cpp b/src/paced_delivery.cpp index 6c4da8c..7ef93d3 100644 --- a/src/paced_delivery.cpp +++ b/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(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::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 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::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); diff --git a/src/paced_delivery.hpp b/src/paced_delivery.hpp index dc48f42..4431fbd 100644 --- a/src/paced_delivery.hpp +++ b/src/paced_delivery.hpp @@ -13,6 +13,8 @@ class PacedDelivery { public: using Clock = std::function; using Guard = std::function; + // Opt-in diagnostics: metadata only (sizes, offsets, reasons), never text. + using Trace = std::function; 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 release_idle_; Guard permitted_; + Trace trace_; std::unique_ptr task_; std::optional last_commit_; bool retained_ = false; diff --git a/src/runtime.cpp b/src/runtime.cpp index 4c14b6e..b1978fd 100644 --- a/src/runtime.cpp +++ b/src/runtime.cpp @@ -17,6 +17,7 @@ #include #include #include +#include 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::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 { @@ -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(); }, + paced.set_trace([&trace](const std::string& line) { trace(line); }); + Controller controller(audio, worker, acquire, [&trace] { return std::make_unique(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()) { diff --git a/src/worker.cpp b/src/worker.cpp index b7a3212..7624a42 100644 --- a/src/worker.cpp +++ b/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))) { diff --git a/src/worker.hpp b/src/worker.hpp index f70298b..ad7baeb 100644 --- a/src/worker.hpp +++ b/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),