Merge branch 'testing' of ssh://git.stormux.org:1101/storm/cthulhu into testing

docs/tentacle-diagnostics.md

@@ -0,0 +1,48 @@
+# Tentacle diagnostics
+
+With debug logging enabled, the reader records Tentacle activation, failure,
+disable, process exit and cleanup; failed requests; remote approval and lease
+opening; rejected remote operations; queue exhaustion; policy cancellation and
+lease revocation. Records identify the installed Tentacle and process session.
+Remote records also carry an epoch (connection generation). Revocation records
+include the last operation sequence and milliseconds remaining until expiry.
+A negative remaining duration indicates that the deadline has passed.
+
+`remote keyboard capture ended` describes keyboard cleanup, not necessarily the
+original disconnect. Look earlier for `tentacle remote revoked`, queue or policy
+records, and `tentacle child diagnostic`. An `expired` revocation is the reader's
+local heartbeat watchdog; it does not by itself prove internet failure. A child
+`network`, `timeout` or `closed` reason describes its relay transport; `peer`
+means membership/origin validation failed, and `protocol` means a message was
+rejected. These are observations, not proof of which remote machine or network
+component caused the problem. Child diagnostics are explicitly attributed claims.
+
+Remote's updated executable emits version 1 JSON lines on stderr. Older readers
+discard these. Both reader and Tentacle must be rebuilt to get relay diagnostics;
+rebuilding only the reader adds host diagnostics. This does not change stdout
+RPC or the protocol negotiation version.
+
+A record has `cthulhu_diagnostic: 1`, numeric `epoch` and `elapsed_ms`, and fixed
+`phase` and `reason` classifications. A failed reader call can include an
+`operation` from the remote RPC vocabulary. Epoch zero means a process-level
+record or call without an attached generation. Connection final elapsed time is
+measured from the start of the connection attempt; reader-call elapsed time is
+that call's duration. Other records use zero when duration is not measured.
+
+The host validates the vocabulary in `internal/tentacle/diagnostics.go`, rejects
+unknown fields and records over 1024 bytes, and retains the existing 64 KiB
+lifetime stderr budget. Partial final lines and ordinary stderr are discarded.
+Remote stops emitting after 48 KiB, with one final `diagnostics`/`limit` record,
+so repeated connection attempts cannot exhaust the host limit through these
+diagnostics alone. Restart the Tentacle to reset that budget.
+It never inserts arbitrary stderr into logs. Diagnostic records contain no
+channel keys, lease tokens, clipboard content or relay payloads. Existing speech
+and other debug logging can contain private content; redact logs before sharing.
+
+Focused automated checks cover streaming/chunk boundaries, oversized and invalid
+records, lease lifecycle logging and token omission, and remote error categories.
+For live validation, use a rebuilt reader and Remote executable, connect and
+exchange speech/keyboard input, return with F11, then disconnect. Confirm the log
+contains an opening/ready/closed sequence and a host lease revocation for the same
+session and epoch. If an unexpected drop recurs, preserve the entire debug log
+before restarting, including the records preceding keyboard cleanup.

internal/app/prompt_presentation_test.go

@@ -448,3 +448,63 @@ func TestTerminalTextChangeSuppressesPromptReplayButPreservesNavigation(t *testi
 	cancel()
 	<-completed
 }
+
+// Replay YAD's stdin-fed menu sequence: initial unselected row, stale active
+// descendant for that row on Down, then the actual new selection.
+func TestListPromptInitialRowAndFirstArrow(t *testing.T) {
+	speech := &fakeSpeechQueue{spoken: make(chan string, 16), requests: make(chan speechRequest, 16)}
+	adapter := &fakeAdapter{events: make(chan atspi.Event, 16)}
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+	completed := make(chan struct{})
+	go func() {
+		processEvents(ctx, slog.New(slog.DiscardHandler), speech, adapter, 0)
+		close(completed)
+	}()
+	window := atspi.NewObjectID(":1.9", "/menu")
+	list := atspi.NewSnapshot("/menu/list", "", "tree table", "", "")
+	list.BusName = window.BusName
+	activation := atspi.NewEvent(atspi.WindowActivatedEvent, list)
+	activation.Window, activation.WindowTitle, activation.WindowMessage = window, "Action menu", "Please select an action"
+	adapter.events <- activation
+	cell := atspi.NewSnapshot("/menu/play", "Play", "table cell", "", "")
+	cell.BusName, cell.TablePath = window.BusName, list.Path
+	cell.GUITable, cell.TablePositionKnown = true, true
+	cell.TableRowText = "Play"
+	focus := atspi.NewEvent(atspi.FocusedStateEvent, cell)
+	focus.Window, focus.Detail1 = window, 1
+	adapter.events <- focus
+	expect := func(text string, appendSpeech bool) {
+		t.Helper()
+		select {
+		case request := <-speech.requests:
+			if request.Text != text || request.Append != appendSpeech {
+				t.Fatalf("got %q append=%v; want %q append=%v", request.Text, request.Append, text, appendSpeech)
+			}
+		case <-time.After(time.Second):
+			t.Fatalf("missing %q", text)
+		}
+	}
+	expect("Action menu, Please select an action", false)
+	expect("Play", true)
+	adapter.events <- focus // Duplicate container focus must not repeat Play.
+	adapter.events <- atspi.NewManagedDescendantEvent(atspi.ActiveDescendantEvent, list.Path, cell)
+	second := cell
+	second.Path, second.Name, second.TableRowText = "/menu/install", "Install", "Install"
+	second.TableRowIndex, second.Selected, second.Focused = 1, true, true
+	adapter.events <- atspi.NewManagedDescendantEvent(atspi.SelectionChangedEvent, list.Path, second)
+	expect("Install", false)
+	adapter.events <- atspi.NewManagedDescendantEvent(atspi.ActiveDescendantEvent, list.Path, second)
+	cell.Selected, cell.Focused = true, true
+	adapter.events <- atspi.NewManagedDescendantEvent(atspi.SelectionChangedEvent, list.Path, cell)
+	expect("Play", false)
+	cancel()
+	select {
+	case <-completed:
+	case <-time.After(time.Second):
+		t.Fatal("event loop did not stop")
+	}
+	if len(speech.requests) != 0 {
+		t.Fatal("unexpected duplicate menu speech")
+	}
+}

internal/app/tentacle_remote_capture.go

@@ -72,6 +72,7 @@ func (runtime *tentacleRuntime) start_remote_capture(ctx context.Context, sessio
 			case <-ctx.Done():
 				return
 			case <-leaseDone:
+				runtime.logger.Debug("remote capture lease ended", "session", session.Identity(), "epoch", lease.Epoch)
 				leaseDone = nil
 				end()
 			case request := <-requests:
@@ -119,7 +120,7 @@ func (runtime *tentacleRuntime) start_remote_capture(ctx context.Context, sessio
 					continue
 				}
 				if event.Ended != "" {
-					runtime.logger.Debug("remote keyboard capture ended", "reason", event.Ended)
+					runtime.logger.Debug("remote keyboard capture ended", "reason", event.Ended, "session", session.Identity(), "epoch", lease.Epoch)
 					_ = session.PublishRemoteFocus(lease, tentaclewire.RemoteFocusLocal, event.Ended)
 					runtime.report("Keyboard returned to this computer.")
 					continue

internal/app/tentacles.go

@@ -433,6 +433,9 @@ func (runtime *tentacleRuntime) report(message string) {
 // makeManager runs on the lifecycle worker, never on input or GTK callbacks.
 func (runtime *tentacleRuntime) makeManager() (*tentacle.Manager, error) {
 	manager, err := runtime.make_manager()
+	if err == nil {
+		manager.SetLogger(runtime.logger)
+	}
 	if err == nil && runtime.remotePolicy != nil {
 		err = manager.UseRemotePolicy(runtime.remotePolicy)
 	}

internal/atspi/adapter_event_callback_native.go

@@ -50,7 +50,8 @@ func selectNativeEventTarget(event *C.AtspiEvent, eventType string) (*C.AtspiAcc
 			ownedTarget = true
 		}
 		// A table's first selected child is its active child only when the
-		// selection is unique. Multi-selection changes use their own events.
+		// selection is unique. An unselected single-column GTK list can
+		// present its initial row without changing selection.
 		targetRole := C.atspi_accessible_get_role(target, nil)
 		tableContainer := C.cthulhu_is_table_container(target) != 0
 		// GTK notebooks report container focus before the active tab when an
@@ -59,7 +60,7 @@ func selectNativeEventTarget(event *C.AtspiEvent, eventType string) (*C.AtspiAcc
 		if targetRole == C.ATSPI_ROLE_MENU || targetRole == C.ATSPI_ROLE_PAGE_TAB_LIST || tableContainer {
 			var child *C.AtspiAccessible
 			if tableContainer {
-				child = C.cthulhu_table_selected_child(target)
+				child = C.cthulhu_table_focus_child(target)
 			} else {
 				child = C.cthulhu_selected_child(target)
 			}

internal/atspi/adapter_events.c

@@ -219,6 +219,44 @@ AtspiAccessible *cthulhu_table_selected_child(AtspiAccessible *source) {
     return child;
 }
 
+// GTK lists populated through stdin can have no selected row at focus time.
+// Their first navigation starts at row zero. Present that initial row without
+// selecting it or moving the application's cursor. Selection-change queries
+// must continue to return only actual selections.
+AtspiAccessible *cthulhu_table_focus_child(AtspiAccessible *source) {
+    AtspiAccessible *child = cthulhu_table_selected_child(source);
+    if (child != NULL) return child;
+    gchar *toolkit = atspi_accessible_get_toolkit_name(source, NULL);
+    gboolean gtk = g_ascii_strcasecmp(toolkit != NULL ? toolkit : "", "gtk") == 0;
+    g_free(toolkit);
+    if (!gtk) return NULL;
+    AtspiStateSet *states = atspi_accessible_get_state_set(source);
+    gboolean initial = states != NULL &&
+        atspi_state_set_contains(states, ATSPI_STATE_FOCUSED) &&
+        !atspi_state_set_contains(states, ATSPI_STATE_MULTISELECTABLE);
+    if (states != NULL) g_object_unref(states);
+    if (!initial) return NULL;
+    AtspiTable *table = atspi_accessible_get_table_iface(source);
+    if (table == NULL) return NULL;
+    GError *error = NULL;
+    gint selected = atspi_table_get_n_selected_rows(table, &error);
+    if (error == NULL && selected == 0 && atspi_table_get_n_rows(table, NULL) > 0 &&
+        atspi_table_get_n_columns(table, NULL) == 1) {
+        child = atspi_table_get_accessible_at(table, 0, 0, NULL);
+        if (child != NULL) {
+            states = atspi_accessible_get_state_set(child);
+            gboolean showing = states != NULL &&
+                atspi_state_set_contains(states, ATSPI_STATE_SHOWING) &&
+                !atspi_state_set_contains(states, ATSPI_STATE_DEFUNCT);
+            if (states != NULL) g_object_unref(states);
+            if (!showing) { g_object_unref(child); child = NULL; }
+        }
+    }
+    g_clear_error(&error);
+    g_object_unref(table);
+    return child;
+}
+
 // Resolve the focused descendant at a window-activation boundary. Providers
 // such as Steam's Chromium UI can activate a frame without emitting a usable
 // object-focus event. Keep the synchronous callback work bounded so a broken

internal/atspi/adapter_native.h

@@ -127,6 +127,7 @@ cthulhu_live_properties cthulhu_capture_live_properties(AtspiAccessible *source)
 AtspiAccessible *cthulhu_event_active_descendant(AtspiEvent *event);
 AtspiAccessible *cthulhu_selected_child(AtspiAccessible *source);
 AtspiAccessible *cthulhu_table_selected_child(AtspiAccessible *source);
+AtspiAccessible *cthulhu_table_focus_child(AtspiAccessible *source);
 gboolean cthulhu_is_gtk_list_table(AtspiAccessible *source);
 gboolean cthulhu_is_table_container(AtspiAccessible *source);
 AtspiAccessible *cthulhu_returned_menu_item(AtspiAccessible *menu);

internal/atspi/alert_native_test.go

@@ -311,3 +311,90 @@ func TestNativeGTKRadioGroupName(t *testing.T) {
 		}
 	}
 }
+
+func TestNativeYADListInitialRow(t *testing.T) {
+	if os.Getenv("CTHULHU_NATIVE_YAD") != "1" {
+		t.Skip("requires private Xvfb/AT-SPI session")
+	}
+	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
+	defer cancel()
+	adapter := New()
+	if err := adapter.Start(ctx); err != nil {
+		t.Fatal(err)
+	}
+	defer func() {
+		stopCtx, stopCancel := context.WithTimeout(context.Background(), 3*time.Second)
+		defer stopCancel()
+		if err := adapter.Stop(stopCtx); err != nil {
+			t.Errorf("stop adapter: %v", err)
+		}
+	}()
+	command := exec.CommandContext(ctx, "yad", "--list", "--title=Initial menu probe",
+		"--text=Please select an action", "--column=Option", "--no-headers",
+		"--selectable-labels", "--search-column=1", "--height=400", "--width=600")
+	command.Stdin = strings.NewReader("Play\nInstall\n")
+	if err := command.Start(); err != nil {
+		t.Fatal(err)
+	}
+	defer func() {
+		_ = command.Process.Kill()
+		_ = command.Wait()
+	}()
+	var yadWindow string
+	for yadWindow == "" && ctx.Err() == nil {
+		output, err := exec.CommandContext(ctx, "xdotool", "search", "--onlyvisible", "--name", "^Initial menu probe$").Output()
+		if err == nil {
+			yadWindow = strings.TrimSpace(string(output))
+		}
+		if yadWindow == "" {
+			time.Sleep(20 * time.Millisecond)
+		}
+	}
+	if yadWindow == "" {
+		t.Fatal("YAD list window did not appear")
+	}
+	if output, err := exec.CommandContext(ctx, "xdotool", "windowfocus", strings.Split(yadWindow, "\n")[0]).CombinedOutput(); err != nil {
+		t.Fatalf("focus YAD list window: %v: %s", err, output)
+	}
+	stage := 0
+	for {
+		select {
+		case <-ctx.Done():
+			t.Fatalf("menu event missing at navigation stage %d", stage)
+		case event := <-adapter.Events():
+			if event.Source.ApplicationName != "yad" {
+				continue
+			}
+			if stage == 0 {
+				if (event.Type != FocusEvent && event.Type != FocusedStateEvent) || event.Source.Role != "table cell" || event.Source.Name != "Play" {
+					continue
+				}
+				if event.Source.Selected || !event.Source.GUITable || event.Source.TablePath == "" {
+					t.Fatalf("initial row must retain table ownership without selecting it: %#v", event.Source)
+				}
+			} else {
+				want := "Install"
+				if stage == 2 {
+					want = "Play"
+				}
+				if event.Type != SelectionChangedEvent || event.Source.Name != want {
+					continue
+				}
+				if !event.Source.Selected {
+					t.Fatalf("navigation did not select %s", want)
+				}
+				if stage == 2 {
+					return
+				}
+			}
+			key := "Down"
+			if stage == 1 {
+				key = "Up"
+			}
+			if output, err := exec.CommandContext(ctx, "xdotool", "key", key).CombinedOutput(); err != nil {
+				t.Fatalf("navigate: %v: %s", err, output)
+			}
+			stage++
+		}
+	}
+}

internal/tentacle/diagnostics.go

@@ -0,0 +1,112 @@
+// SPDX-License-Identifier: GPL-3.0-or-later
+
+package tentacle
+
+import (
+	"context"
+	"encoding/json"
+	"errors"
+	"log/slog"
+	"slices"
+)
+
+// SetLogger configures diagnostics for subsequently started sessions.
+func (manager *Manager) SetLogger(logger *slog.Logger) {
+	manager.mutex.Lock()
+	defer manager.mutex.Unlock()
+	manager.logger = logger
+}
+
+func (session *Session) log(message string, args ...any) {
+	if session.logger != nil {
+		fields := []any{"tentacle", session.spec.ID, "session", session.identity}
+		session.logger.Debug(message, append(fields, args...)...)
+	}
+}
+
+// Error strings can contain paths or extension-controlled text. Classify them
+// without copying that text into host diagnostics.
+func diagnosticError(err error) string {
+	if err == nil {
+		return "none"
+	}
+	for _, item := range []struct {
+		err  error
+		name string
+	}{
+		{context.DeadlineExceeded, "timeout"}, {context.Canceled, "cancelled"},
+		{ErrProtocol, "protocol"}, {ErrLimit, "limit"}, {ErrExited, "exited"},
+		{ErrDisabled, "disabled"}, {ErrPermission, "permission"}, {ErrBusy, "capacity"},
+		{ErrUnavailable, "unavailable"}, {ErrSupervision, "supervision"}, {ErrContainment, "containment"},
+	} {
+		if errors.Is(err, item.err) {
+			return item.name
+		}
+	}
+	var rpc *RPCError
+	if errors.As(err, &rpc) {
+		return "rpc"
+	}
+	return "other"
+}
+
+func diagnosticOperation(method string) string {
+	switch method {
+	case "remote.open", "remote.close", "remote.heartbeat", "remote.present", "remote.key", "remote.focus", "remote.braille":
+		return method
+	default:
+		return "other"
+	}
+}
+
+// Stderr remains untrusted. Only this bounded, versioned vocabulary is admitted;
+// ordinary stderr, credentials, server text and malformed records are discarded.
+// Fields are reported as child claims, never interpreted as host events.
+type childDiagnostic struct {
+	Operation string `json:"operation,omitempty"`
+	Version   int    `json:"cthulhu_diagnostic"`
+	Epoch     uint64 `json:"epoch"`
+	Phase     string `json:"phase"`
+	Reason    string `json:"reason"`
+	ElapsedMS int64  `json:"elapsed_ms"`
+}
+
+type diagnosticWriter struct {
+	session  *Session
+	line     []byte
+	overflow bool
+}
+
+func (writer *diagnosticWriter) Write(data []byte) (int, error) {
+	for _, b := range data {
+		if b == '\n' {
+			if !writer.overflow {
+				writer.record()
+			}
+			writer.line = writer.line[:0]
+			writer.overflow = false
+		} else if len(writer.line) < 1024 {
+			writer.line = append(writer.line, b)
+		} else {
+			writer.overflow = true
+		}
+	}
+	return len(data), nil
+}
+
+func (writer *diagnosticWriter) record() {
+	var d childDiagnostic
+	if decode_strict(json.RawMessage(writer.line), &d) != nil || d.Version != 1 || d.ElapsedMS < 0 {
+		return
+	}
+	if d.Operation != "" && diagnosticOperation(d.Operation) == "other" {
+		return
+	}
+	if !slices.Contains([]string{"diagnostics", "opening", "connecting", "waiting", "ready", "stopping", "closed", "failed", "relay-read", "relay-write", "relay-message", "reader-call", "keyboard", "event-stream"}, d.Phase) {
+		return
+	}
+	if !slices.Contains([]string{"none", "requested", "cancelled", "timeout", "closed", "network", "trust", "protocol", "limit", "peer", "lease", "keyboard", "state", "stale", "other"}, d.Reason) {
+		return
+	}
+	writer.session.log("tentacle child diagnostic", "epoch", d.Epoch, "phase", d.Phase, "operation", d.Operation, "reason", d.Reason, "elapsed_ms", d.ElapsedMS)
+}

internal/tentacle/diagnostics_test.go

@@ -0,0 +1,71 @@
+package tentacle
+
+import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"log/slog"
+	"strings"
+	"testing"
+
+	"git.stormux.org/storm/cthulhu/internal/tentaclewire"
+)
+
+func TestDiagnosticStreamBoundsAndPrivacy(t *testing.T) {
+	var output bytes.Buffer
+	session := &Session{logger: slog.New(slog.NewJSONHandler(&output, &slog.HandlerOptions{Level: slog.LevelDebug})), identity: "fixture"}
+	writer := &diagnosticWriter{session: session}
+	good := `{"cthulhu_diagnostic":1,"epoch":3,"phase":"relay-read","reason":"timeout","elapsed_ms":42}` + "\n"
+	for _, bad := range []string{
+		"private stderr\n", strings.Repeat("x", 2048) + "\n",
+		strings.Replace(good, `"timeout"`, `"private secret"`, 1),
+		strings.Replace(good, `"elapsed_ms":42`, `"elapsed_ms":42,"secret":"private"`, 1),
+	} {
+		_, _ = writer.Write([]byte(bad))
+	}
+	if output.Len() != 0 {
+		t.Fatalf("untrusted text admitted: %s", output.String())
+	}
+	for _, b := range []byte(good) {
+		_, _ = writer.Write([]byte{b})
+	}
+	if strings.Count(output.String(), "tentacle child diagnostic") != 1 || !strings.Contains(output.String(), `"epoch":3`) {
+		t.Fatal(output.String())
+	}
+}
+
+func TestRemoteLifecycleDiagnosticsOmitAuthorityTokens(t *testing.T) {
+	var output bytes.Buffer
+	manager := test_manager(t, DefaultLimits(), nil)
+	manager.SetLogger(slog.New(slog.NewJSONHandler(&output, &slog.HandlerOptions{Level: slog.LevelDebug})))
+	// Exercise the real lease lifecycle with a logger attached, without a child.
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+	session := &Session{manager: manager, logger: manager.logger, identity: "fixture", state: Active, ctx: ctx, outputContext: ctx,
+		spec: Spec{SessionEvents: true, RemoteGrants: []string{"remote-present"}}, outbound: make(chan outgoing, 16)}
+	action, err := session.AuthorizeRemote("controller", []string{"remote-present"})
+	if err != nil {
+		t.Fatal(err)
+	}
+	params := tentaclewire.RemoteOpen{Action: action.Action, Epoch: action.Epoch, Role: action.Role, Grants: action.Grants}
+	session.mutex.Lock()
+	raw, _ := json.Marshal(params)
+	value, failure := session.remote_call_locked("remote.open", raw)
+	session.mutex.Unlock()
+	if failure != nil {
+		t.Fatal(failure)
+	}
+	lease := value.(tentaclewire.RemoteLease)
+	session.RevokeRemote()
+	logs := output.String()
+	for _, want := range []string{"remote authorized", "remote lease opened", "remote revoked", `"reason":"local"`} {
+		if !strings.Contains(logs, want) {
+			t.Fatalf("missing %s: %s", want, logs)
+		}
+	}
+	for _, secret := range []string{action.Action, lease.Lease} {
+		if strings.Contains(logs, secret) {
+			t.Fatal("authority token logged")
+		}
+	}
+}

internal/tentacle/manager.go

@@ -8,6 +8,7 @@ import (
 	"crypto/rand"
 	"encoding/hex"
 	"errors"
+	"log/slog"
 	"os"
 	"path/filepath"
 	"strings"
@@ -53,6 +54,7 @@ type Stats struct {
 }
 
 type Manager struct {
+	logger            *slog.Logger // Copied into sessions under mutex.
 	mutex             sync.Mutex
 	limits            Limits
 	sessions          map[string]*Session
@@ -157,7 +159,7 @@ func (manager *Manager) Start(ctx context.Context, spec Spec) (*Session, error)
 	}
 	sessionContext, cancel := context.WithCancel(ctx)
 	outputContext, revokeOutput := context.WithCancel(sessionContext)
-	session := &Session{manager: manager, spec: spec, identity: hex.EncodeToString(identity[:]),
+	session := &Session{logger: manager.logger, manager: manager, spec: spec, identity: hex.EncodeToString(identity[:]),
 		outputContext: outputContext, revokeOutput: revokeOutput,
 		ctx: sessionContext, cancel: cancel, state: Starting, ready: make(chan struct{}), done: make(chan struct{}),
 		stop: make(chan struct{}), revoked: make(chan struct{}), outbound: make(chan outgoing, queueSize),

internal/tentacle/process.go

@@ -18,6 +18,7 @@ import (
 )
 
 func (session *Session) run() {
+	session.log("tentacle starting", "supervised", len(session.manager.supervisorProgram) != 0, "contained", session.manager.containment != nil)
 	var cleanupError error
 	starting := true
 	ready := func() {
@@ -39,6 +40,7 @@ func (session *Session) run() {
 		} else if session.state != Failed {
 			session.fail_locked(ErrExited)
 		}
+		session.log("tentacle stopped", "state", session.state, "cleanup_reason", diagnosticError(cleanupError))
 		session.mutex.Unlock()
 		session.callbacks.Wait()
 		// A retained status/session handle must not retain unsent argument text.
@@ -202,6 +204,7 @@ func (session *Session) run() {
 		} else {
 			<-exited
 		}
+		session.log("tentacle process reaped", "exit_code", command.ProcessState.ExitCode(), "success", command.ProcessState.Success())
 		workers.Wait()
 	}()
 
@@ -357,8 +360,9 @@ func (session *Session) read_replies(reader io.Reader) {
 }
 
 func (session *Session) drain_diagnostics(reader io.Reader) {
-	count, err := io.Copy(io.Discard, io.LimitReader(reader, MaxDiagnosticBytes+1))
+	count, err := io.Copy(&diagnosticWriter{session: session}, io.LimitReader(reader, MaxDiagnosticBytes+1))
 	if count > MaxDiagnosticBytes {
+		session.log("tentacle diagnostic budget exceeded", "bytes", count)
 		session.fail(ErrLimit)
 	} else if err != nil && session.ctx.Err() == nil {
 		session.fail(ErrExited)

internal/tentacle/protocol.go

@@ -20,7 +20,7 @@ const (
 	MaxReaderArgumentBytes = 48 * 1024
 	MaxArgumentBytes       = 16 * 1024
 	MaxCommands            = 32
-	MaxDiagnosticBytes     = 64 * 1024 // Lifetime budget; diagnostics are discarded.
+	MaxDiagnosticBytes     = 64 * 1024 // Lifetime stderr budget; only structured diagnostics are logged.
 )
 
 var (

internal/tentacle/remote.go

@@ -98,12 +98,14 @@ func (session *Session) authorize_remote_locked(role string, grants []string, pa
 	access := &remoteAccess{action: hex.EncodeToString(token[:]), epoch: session.remoteEpoch,
 		role: role, grants: slices.Clone(grants), ctx: ctx, cancel: cancel}
 	session.remote = access
+	session.log("tentacle remote authorized", "epoch", access.epoch, "role", access.role, "grants", access.grants)
 	// Parent cancellation invalidates delivery immediately. Retirement/event
 	// cleanup acquires the session lock afterwards and cannot retire a newer epoch.
 	access.stopPolicy = context.AfterFunc(parent, func() {
 		session.mutex.Lock()
 		defer session.mutex.Unlock()
 		if session.remote == access {
+			session.log("tentacle remote policy cancelled", "epoch", access.epoch)
 			session.revoke_remote_locked("local", true)
 		}
 	})
@@ -176,6 +178,7 @@ func (session *Session) revoke_remote_locked(reason string, notify bool) {
 	if access == nil {
 		return
 	}
+	session.log("tentacle remote revoked", "epoch", access.epoch, "reason", reason, "lease_open", access.lease != "", "sequence", access.sequence, "deadline_remaining_ms", time.Until(access.deadline).Milliseconds(), "context_cancelled", access.ctx.Err() != nil, "speech_items", access.speechItems, "key_items", access.keyItems)
 	session.remote = nil
 	access.cancel()
 	access.speechBatch = nil
@@ -281,6 +284,7 @@ func (session *Session) accept_child_request(frame []byte) error {
 	value, failure := session.remote_call_locked(message.Method, message.Params)
 	reply := map[string]any{"jsonrpc": "2.0", "id": message.ID}
 	if failure != nil {
+		session.log("tentacle session operation rejected", "operation", diagnosticOperation(message.Method), "code", failure.Code, "epoch", session.remoteEpoch)
 		reply["error"] = failure
 	} else {
 		reply["result"] = value
@@ -324,6 +328,7 @@ func (session *Session) remote_call_locked(method string, params json.RawMessage
 		}
 		access.lease, access.action, access.grants = hex.EncodeToString(token[:]), "", slices.Clone(request.Grants)
 		session.refresh_remote_locked(RemoteHeartbeatTimeout)
+		session.log("tentacle remote lease opened", "epoch", access.epoch, "role", access.role, "heartbeat_timeout_ms", RemoteHeartbeatTimeout.Milliseconds())
 		return tentaclewire.RemoteLease{Lease: access.lease, Epoch: access.epoch}, nil
 	case "remote.close", "remote.heartbeat":
 		var request tentaclewire.RemoteOperation

internal/tentacle/remote_braille.go

@@ -51,6 +51,7 @@ func (session *Session) remote_braille_locked(params json.RawMessage) (any, *RPC
 	case session.remoteBraille <- RemoteBrailleDelivery{Context: access.ctx, Lease: lease, Role: access.role, Sequence: request.Sequence, Braille: request.Braille}:
 		return struct{}{}, nil
 	default:
+		session.log("tentacle remote queue full", "queue", "braille", "epoch", access.epoch)
 		session.revoke_remote_locked("local", true)
 		return nil, &RPCError{Code: -32002, Message: "Remote Braille queue full"}
 	}

internal/tentacle/remote_capture.go

@@ -53,6 +53,7 @@ func (session *Session) remote_focus_locked(params json.RawMessage) (any, *RPCEr
 		return struct{}{}, nil
 	default:
 		// A lost "local" request must never leave capture active.
+		session.log("tentacle remote queue full", "queue", "focus", "epoch", access.epoch)
 		session.revoke_remote_locked("local", true)
 		return nil, &RPCError{Code: -32002, Message: "Remote focus queue full"}
 	}

internal/tentacle/remote_key.go

@@ -57,6 +57,7 @@ func (session *Session) remote_key_locked(params json.RawMessage) (any, *RPCErro
 	data, _ := json.Marshal(request)
 	bytes := len(data)
 	if access.keyItems == tentaclewire.RemoteKeyQueueSize || access.keyBytes+bytes > tentaclewire.RemoteKeyQueueBytes {
+		session.log("tentacle remote queue full", "queue", "keyboard", "epoch", access.epoch)
 		session.revoke_remote_locked("local", true)
 		return nil, &RPCError{Code: -32002, Message: "Remote keyboard queue full"}
 	}
@@ -79,6 +80,7 @@ func (session *Session) remote_key_locked(params json.RawMessage) (any, *RPCErro
 		return struct{}{}, nil
 	default:
 		// Losing a release must never leave the input lease active.
+		session.log("tentacle remote queue full", "queue", "keyboard", "epoch", access.epoch)
 		session.revoke_remote_locked("local", true)
 		return nil, &RPCError{Code: -32002, Message: "Remote keyboard queue full"}
 	}

internal/tentacle/remote_speech.go

@@ -115,6 +115,7 @@ func (session *Session) remote_present_locked(params json.RawMessage) (any, *RPC
 	}
 	data, _ := json.Marshal(request.Speech)
 	if access.speechItems == tentaclewire.RemoteSpeechQueueSize || access.speechBytes+len(data) > tentaclewire.RemoteSpeechQueueBytes {
+		session.log("tentacle remote queue full", "queue", "speech", "epoch", access.epoch)
 		session.revoke_remote_locked("local", true)
 		return nil, &RPCError{Code: -32002, Message: "Remote speech queue full"}
 	}
@@ -144,6 +145,7 @@ func (session *Session) remote_present_locked(params json.RawMessage) (any, *RPC
 		return struct{}{}, nil
 	default:
 		// A dropped cancel would let stale speech outlive the intended stream.
+		session.log("tentacle remote queue full", "queue", "speech", "epoch", access.epoch)
 		session.revoke_remote_locked("local", true)
 		return nil, &RPCError{Code: -32002, Message: "Remote speech queue full"}
 	}

internal/tentacle/session.go

@@ -7,6 +7,7 @@ import (
 	"context"
 	"encoding/json"
 	"errors"
+	"log/slog"
 	"strconv"
 	"sync"
 	"time"
@@ -48,6 +49,7 @@ type outgoing struct {
 }
 
 type Session struct {
+	logger        *slog.Logger
 	outputContext context.Context
 	revokeOutput  context.CancelFunc
 
@@ -136,6 +138,7 @@ func (session *Session) Activate() error {
 	}
 	session.bindings = resolve_bindings(session.spec.ID, session.commands, occupied)
 	session.state = Active
+	session.log("tentacle activated")
 	return nil
 }
 
@@ -251,6 +254,9 @@ func (session *Session) finish_locked(id string, value json.RawMessage, err erro
 		err = contextError
 		value = nil
 	}
+	if err != nil {
+		session.log("tentacle request failed", "request", id, "reason", diagnosticError(err))
+	}
 	call.cancel()
 	<-session.manager.pending
 	call.result <- Result{Session: session.identity, ID: id, Value: value, Err: err}
@@ -294,6 +300,7 @@ func (session *Session) fail_locked(err error) {
 	if session.state == Stopping || session.state == Stopped || session.state == Failed {
 		return
 	}
+	session.log("tentacle failed", "state", session.state, "reason", diagnosticError(err), "pending", len(session.pending), "queued_bytes", session.queuedBytes)
 	session.state, session.failure = Failed, err
 	close(session.revoked)
 	session.revokeOutput()
@@ -321,6 +328,7 @@ func (session *Session) Disable() {
 	if session.state == Stopping || session.state == Stopped || session.state == Failed {
 		return
 	}
+	session.log("tentacle disabling", "state", session.state, "pending", len(session.pending))
 	session.state = Stopping
 	close(session.revoked)
 	session.revokeOutput()

tests/native_alert.py

@@ -34,7 +34,7 @@ def inside():
             cwd=Path(__file__).resolve().parents[1], env=environment, check=True, timeout=25,
         )
         environment["CTHULHU_NATIVE_YAD"] = "1"
-        for name in ("TestNativeYADQuestionMessage", "TestNativeYADListMessage", "TestNativeYADPowerListMessage"):
+        for name in ("TestNativeYADQuestionMessage", "TestNativeYADListMessage", "TestNativeYADPowerListMessage", "TestNativeYADListInitialRow"):
             subprocess.run(
                 ["go", "test", "./internal/atspi", "-run", f"^{name}$", "-count=1", "-timeout=20s"],
                 cwd=Path(__file__).resolve().parents[1], env=environment, check=True, timeout=25,