[Feature] Built-in debug instrumentation for PTY data flow

[wblech]

[Feature] Built-in debug instrumentation for PTY data flow

Summary

Expose a built-in, opt-in debug logging facility inside wmux that captures every step of the PTY data flow on the daemon side, mirroring what consumers (e.g., Watchtower) are doing on the client side. Goal: when a downstream app sees lost characters, wrong cursor positions, or backpressure stalls, it can correlate its own logs with the daemon's logs in a single timeline and quickly localize the bug to "before wmux", "inside wmux", or "after wmux".

Motivation

wmux already implements non-trivial mechanics that can hide bugs from consumers:

• PTY readLoop with batching into a Buffer (HWM 4 MiB, 16ms ticker) — ADR-0006.
• Backpressure pause/resume on HWM — ADR-0006.
• Snapshot/replay flow — ADR-0026.
• Async emulator processing — ADR-0024.
• ED2 / scrollback handling in charmvt — ADR-0027.

When a consumer reports "characters got lost" or "cursor jumped", today the only options are:

• Read the consumer's logs, see a gap or drift, and guess whether the issue is upstream (kernel/PTY/daemon readLoop/Buffer) or downstream (consumer's emit/render).
• Hand-patch local copies of wmux with fmt.Printf to bisect the issue, then revert.

A first-class debug facility eliminates the patch-and-revert loop and makes wmux self-diagnosable in production without any code change in either project.

Proposed Solution

A new optional package pkg/debug (or internal/debug if you prefer not to expose it as a public surface) that:

1. Is opt-in via env var WMUX_DEBUG=1 (or WMUX_DEBUG_LEVEL=2|3). Default off, zero overhead.
2. Writes structured JSON Lines (slog.JSONHandler) to a rotating file:
   • macOS default: ~/Library/Logs/wmux/wmux-debug.log
   • Linux default: $XDG_STATE_HOME/wmux/wmux-debug.log (fallback ~/.local/state/wmux/)
   • Override: WMUX_DEBUG_PATH=/path/to/file.log
3. Uses lumberjack (or equivalent) for size-based rotation: 50 MB per file, keep last N files, configurable via env var.
4. Captures a canonical Event schema covering every stage of the data flow.

Event schema

type Stage string

const (
    StagePtyRead         Stage = "pty.read"          // raw read from PTY fd
    StageBufferAppend    Stage = "buffer.append"     // chunk added to Buffer
    StageBufferFlush     Stage = "buffer.flush"      // ticker/coalesce flush
    StageBufferPause     Stage = "buffer.pause"      // HWM hit, paused
    StageBufferResume    Stage = "buffer.resume"     // drained below HWM
    StageEmulatorIn      Stage = "emulator.in"       // sent to emulator (charmvt)
    StageEmulatorOut     Stage = "emulator.out"      // back from emulator
    StageFrameSend       Stage = "frame.send"        // pushed over unix socket
    StageClientRecv      Stage = "client.recv"       // client lib received frame
    StageSnapshotStart   Stage = "snapshot.start"
    StageSnapshotDone    Stage = "snapshot.done"
    StageReplaySend      Stage = "replay.send"
    StageResize          Stage = "resize"            // SIGWINCH
    StageAttach          Stage = "attach"
    StageDetach          Stage = "detach"
    StageSessionCreate   Stage = "session.create"
    StageSessionClose    Stage = "session.close"
)

type Event struct {
    SessionID string
    Stage     Stage
    Seq       int64                     // -1 if N/A
    ByteLen   int
    HeadHex   string                    // first 64 bytes hex (level >= 2)
    TailHex   string                    // last 64 bytes hex (level >= 2)
    FullHex   string                    // full hex (level == 3)
    Sha1      string                    // first 8 chars of sha1
    Extra     map[string]any            // buffer state, cols/rows, paused flag, etc.
}

Levels

Level	Captured
0 (default)	Disabled (no-op). Callsites compile to nothing — see "Build tag option" below.
1	Lifecycle only: session.create/close, attach/detach, resize, buffer.pause/resume, snapshot.start/done. No payload.
2	Level 1 + every chunk with ByteLen, Sha1, HeadHex, TailHex. Recommended for diagnosis.
3	Level 2 + FullHex (full payload of every chunk). Diagnostic-only, very large.

Public API

package debug

// Enabled reports whether debug logging is on (env var or build tag).
func Enabled() bool

// Level returns the configured level (0-3).
func Level() int

// Log emits a single event. No-op when Enabled() is false.
func Log(ev Event)

// Optional: callback hook so external consumers (e.g., Watchtower)
// can mirror events into THEIR own log file for unified timeline.
// Hook is invoked synchronously for every Log call.
func SetHook(hook func(Event))

Build tag option (zero-overhead in production)

In addition to env-var gating, support a wmux_debug build tag:

• Without the tag (default): Log is a stub func Log(Event) {} that the compiler eliminates entirely. Zero binary size, zero runtime cost.
• With -tags wmux_debug: full implementation compiled in; env var still controls activation at runtime.

This lets release builds ship with debug compiled out, while internal/dogfooding builds enable it.

Why this matters for downstream consumers

For example, Watchtower is currently building a parallel debug-logging system on its own side: backend-side captures of OnData callbacks, emit-to-frontend events, ack semaphores, frontend-side captures of xterm.write calls, etc. Without daemon-side instrumentation, half the picture is missing — gaps detected on the consumer side cannot be attributed to the daemon's Buffer flush, backpressure pause, or emulator step.

If wmux exposes (a) its own log file with the same schema and (b) a SetHook so consumers can route the daemon events into their own log file, downstream apps get a single unified timeline without forking wmux.

Acceptance Criteria

• WMUX_DEBUG=1 enables level 2 logging to default platform path.
• WMUX_DEBUG_LEVEL=3 enables level 3.
• WMUX_DEBUG_PATH=… overrides the file path.
• WMUX_DEBUG_MAX_SIZE_MB, WMUX_DEBUG_MAX_FILES knobs (defaults: 50, 7).
• Build without -tags wmux_debug produces a binary where debug.Log is dead-code-eliminated (verified via go build -gcflags='-m').
• All stages in the schema have at least one callsite.
• SetHook is invoked exactly once per event, before the slog write.
• No allocations on hot paths when Enabled() == false (verified via benchmark with -benchmem).
• Documentation: a section in docs/getting-started/ showing how to turn it on, what each stage means, and how to read the resulting JSON Lines.
• One ADR added under decisions/ documenting the design (env var + build tag + schema + lumberjack choice).

Out of Scope

• Distributed tracing / OpenTelemetry export. JSON Lines + grep is sufficient for the bug class this targets.
• Automatic log uploading. Local file only.
• Per-session log files. One file per process is enough — SessionID is in every event.

Notes / Open Questions

• Should SetHook accept a slice of hooks (multiple subscribers) or just one? Single hook is simpler; multiple is more flexible.
• Should Enabled() be atomic.Bool to allow runtime toggle, or static (env-var read once at init)? Static is simpler and matches typical use; atomic adds ~zero overhead but allows live toggling without restart — useful when a bug only reproduces after long uptime.
• For pkg vs internal placement: pkg/debug lets external code call SetHook from the client lib (which seems necessary for the hook story to work). I recommend pkg/debug.

---

Filed by a downstream consumer (Watchtower) currently building parallel debug instrumentation. Happy to contribute the implementation if the design is accepted.