Better logging for browser.

This commit is contained in:
Storm Dragon committed 2026-10-16 20:16:22 -04:00
1 parent 423590e11a
commit ebb9ad48d0
15 files changed
+297 -10

No files matched your search

+16
View File
@@ -68,6 +68,22 @@ update immediately. Moving focus, navigating, changing tabs or windows, and
locking the session discard pending announcements. Live regions retain their
existing announcement behavior.
For browser bug reports, start Cthulhu with `--debug-file /tmp/cthulhu-browser.log`
and reproduce the affected navigation. The startup record includes the release
version, embedded Git revision and modified-build status, Go and AT-SPI versions,
and session information. Builds without Go VCS stamps report `unknown`; a
modified build identifies its base commit, not the exact uncommitted changes.
Display availability does not establish whether the browser uses native Wayland
or XWayland. Include the browser version and its actual display backend separately.
Navigation records include focus and document identities, the cursor before and
after focus synchronization and movement, recovery decisions, capture attempts,
errors and structural-navigation wrapping. For example, `preserved` retains the
saved position, `replaced-text-child` recovers a replacement under its surviving
parent, and `saved-object-missing` falls back to native focus. These records help
distinguish a cursor reset from an intentional wrap without extra native queries.
Review debug logs before sharing: they also contain spoken page text.
## Wine Access
Install the separate `wine-access` helper for Wine application accessibility.
+4 -1
View File
@@ -173,7 +173,10 @@ func run(ctx context.Context, arguments []string, stdout, stderr io.Writer) (res
}()
logger = diagnostics.Logger()
}
logger.Info("starting Cthulhu", "version", version.String(), "pid", os.Getpid())
logger.Info("starting Cthulhu", "version", version.String(), "pid", os.Getpid(),
"build", version.RuntimeIdentity(), "atspi_version", atspi.Version(),
"session_type", os.Getenv("XDG_SESSION_TYPE"), "session_desktop", os.Getenv("XDG_SESSION_DESKTOP"),
"x11_display_available", os.Getenv("DISPLAY") != "", "wayland_display_available", os.Getenv("WAYLAND_DISPLAY") != "")
settings, err := config.Load(*configPath)
if err != nil {
logger.Error("load configuration", "error", err)
+7
View File
@@ -166,6 +166,13 @@ func TestDebugFileCapturesStartupFailureAndAppends(t *testing.T) {
if record["source"] == nil {
t.Fatalf("debug-file did not enable sources: %s", line)
}
if record["message"] == "starting Cthulhu" {
build, ok := record["build"].(map[string]any)
if !ok || build["go_version"] == "" || build["vcs_revision"] == nil || build["vcs_modified"] == nil ||
record["version"] != version.String() || record["atspi_version"] == nil || record["session_type"] == nil {
t.Fatalf("startup identity missing: %s", line)
}
}
if record["level"] == "ERROR" {
message, ok := record["error"].(string)
if !ok || !strings.Contains(message, "connect to Speech Dispatcher") {
+4
View File
@@ -100,6 +100,10 @@ func TestNativeBrowserDynamicNavigation(t *testing.T) {
if result.DocumentPosition.Snapshot.ApplicationName != applicationName {
t.Fatalf("document target application = %q, want %q", result.DocumentPosition.Snapshot.ApplicationName, applicationName)
}
attempts := result.DocumentDiagnostics.Attempts
if len(attempts) == 0 || attempts[len(attempts)-1].After.Object != result.DocumentPosition.Object.ID() {
t.Fatalf("navigation diagnostics do not match the browser position: %+v", result.DocumentDiagnostics)
}
t.Logf("line=%q elapsed=%s capture=%s reason=%v", got, result.Elapsed, result.CaptureDuration, result.CaptureReason)
case <-ctx.Done():
t.Fatal(ctx.Err())
+54
View File
@@ -0,0 +1,54 @@
// Copyright (c) 2026 Storm Dragon
// Authors: Storm Dragon, Angus Kola
// SPDX-License-Identifier: GPL-3.0-or-later
package app
import (
"bytes"
"encoding/json"
"errors"
"log/slog"
"testing"
"git.stormux.org/storm/cthulhu/internal/atspi"
"git.stormux.org/storm/cthulhu/internal/presentation"
"git.stormux.org/storm/cthulhu/internal/review"
)
func TestDocumentDiagnosticsSeparateFailureFromWrapping(t *testing.T) {
for _, caret := range []bool{true, false} {
var output bytes.Buffer
logger := slog.New(slog.NewJSONHandler(&output, &slog.HandlerOptions{Level: slog.LevelDebug}))
queue := &autocompleteRequestQueue{requests: make(chan speechRequest, 4)}
result := review.Result{DocumentEpoch: 7, DocumentFocus: atspi.NewObjectID(":1.42", "/doc"),
DocumentWrapped: !caret, Moved: !caret, DocumentTarget: review.DocumentHeading,
DocumentDiagnostics: review.DocumentDiagnostics{CaptureAttempts: 2,
Attempts: []review.DocumentAttempt{{Recovery: "saved-object-missing", Stage: "move"}}}}
if caret {
result.Err = errors.New("accessible children require recapture")
presentDocumentCaretResult(logger, queue, result, presentation.DefaultOptions())
} else {
result.DocumentPosition.Snapshot = atspi.NewSnapshot("/heading", "Example", "heading", "", "")
presentDocumentResult(logger, queue, result, presentation.DefaultOptions())
}
var record struct {
Epoch uint64 `json:"document_epoch"`
Focus atspi.ObjectID `json:"focus"`
Error string `json:"error"`
Wrapped bool `json:"wrapped"`
Navigation review.DocumentDiagnostics `json:"navigation"`
}
if err := json.NewDecoder(&output).Decode(&record); err != nil {
t.Fatal(err)
}
if record.Epoch != 7 || record.Focus != result.DocumentFocus || record.Wrapped != !caret ||
record.Navigation.CaptureAttempts != 2 || len(record.Navigation.Attempts) != 1 ||
record.Navigation.Attempts[0].Recovery != "saved-object-missing" {
t.Fatalf("missing navigation diagnostics: %+v", record)
}
if caret && record.Error != result.Err.Error() {
t.Fatalf("failed command lost its error: %+v", record)
}
}
}
+8
View File
@@ -187,6 +187,10 @@ func documentCaretCommand(command input.Command) review.DocumentCaretCommand {
func presentDocumentCaretResult(logger *slog.Logger, speech speechEnqueuer, result review.Result, options presentation.Options) {
if logger.Enabled(context.Background(), slog.LevelDebug) {
logger.Debug("document caret navigation completed", "elapsed", result.Elapsed,
"error", result.Err, "document_epoch", result.DocumentEpoch,
"focus", result.DocumentFocus, "document", result.DocumentPosition.Document.ID(),
"application", result.DocumentPosition.Snapshot.ApplicationName, "role", result.DocumentPosition.Snapshot.Role,
"navigation", result.DocumentDiagnostics,
"capture_duration", result.CaptureDuration, "capture_reason", result.CaptureReason,
"moved", result.Moved, "command", result.DocumentCaretCommand.String(),
"bus", result.DocumentPosition.Object.ID().BusName,
@@ -313,6 +317,10 @@ func documentResultMatchesCurrent(result review.Result, current atspi.Snapshot)
func presentDocumentResult(logger *slog.Logger, speech speechEnqueuer, result review.Result, options presentation.Options) {
if logger.Enabled(context.Background(), slog.LevelDebug) {
logger.Debug("document navigation completed", "elapsed", result.Elapsed,
"error", result.Err, "document_epoch", result.DocumentEpoch,
"focus", result.DocumentFocus, "document", result.DocumentPosition.Document.ID(),
"application", result.DocumentPosition.Snapshot.ApplicationName, "role", result.DocumentPosition.Snapshot.Role,
"wrapped", result.DocumentWrapped, "navigation", result.DocumentDiagnostics,
"capture_duration", result.CaptureDuration, "capture_reason", result.CaptureReason,
"moved", result.Moved, "target", result.DocumentTarget,
"level", result.DocumentLevel, "backwards", result.DocumentBackwards,
+18 -3
View File
@@ -168,6 +168,13 @@ func (cursor *DocumentCursor) ActivationTarget() (atspi.ObjectReference, error)
}
func (cursor *DocumentCursor) SyncFocus(ctx context.Context, focus atspi.ObjectID) (DocumentPosition, error) {
position, _, err := cursor.sync_focus(ctx, focus)
return position, err
}
// The outcome explains whether focus synchronization retained the reading
// position, recovered a replacement text child, or fell back to native focus.
func (cursor *DocumentCursor) sync_focus(ctx context.Context, focus atspi.ObjectID) (DocumentPosition, string, error) {
cursor.mu.Lock()
defer cursor.mu.Unlock()
// Failed ownership resolution must never leave web navigation active for
@@ -175,22 +182,30 @@ func (cursor *DocumentCursor) SyncFocus(ctx context.Context, focus atspi.ObjectI
cursor.active = atspi.ObjectReference{}
ref, err := cursor.tree.Reference(focus)
if err != nil {
return DocumentPosition{}, err
return DocumentPosition{}, "focus-unresolved", err
}
doc, err := cursor.tree.Document(ctx, ref)
if err != nil {
return DocumentPosition{}, err
return DocumentPosition{}, "document-unresolved", err
}
place := documentPlace{document: doc.Context.TopLevel, object: ref, focus: ref}
recovery := "new-document"
for index, saved := range cursor.places {
if saved.document != place.document {
if saved.document.ID() == place.document.ID() {
recovery = "document-replaced"
}
continue
}
recovery = "focus-changed"
if saved.focus == ref || saved.object == ref {
recovery = "saved-object-missing"
if _, ok := documentObject(doc, saved.object); ok {
recovery = "preserved"
place = saved
place.focus = ref
} else if replacement, ok := replacement_text_node(doc, saved); ok {
recovery = "replaced-text-child"
place = saved
place.focus, place.object = ref, replacement.Reference
place.offset = min(saved.offset, max(0, replacement.Snapshot.CharacterCount-1))
@@ -204,7 +219,7 @@ func (cursor *DocumentCursor) SyncFocus(ctx context.Context, focus atspi.ObjectI
}
cursor.places = append(cursor.places, place)
cursor.active = place.document
return documentPosition(doc, place), nil
return documentPosition(doc, place), recovery, nil
}
// JumpToFragment follows a browser document load whose URI names an element.
+66
View File
@@ -0,0 +1,66 @@
// Copyright (c) 2026 Storm Dragon
// Authors: Storm Dragon, Angus Kola
// SPDX-License-Identifier: GPL-3.0-or-later
package review
import "git.stormux.org/storm/cthulhu/internal/atspi"
// DocumentDiagnostics records bounded metadata for one navigation command. It
// never reads native objects or retains accessible text for diagnostic purposes.
type DocumentDiagnostics struct {
Attempts []DocumentAttempt `json:"attempts"`
CaptureAttempts int `json:"capture_attempts"`
CursorRecreated bool `json:"cursor_recreated"`
FocusRecovered bool `json:"focus_recovered"`
}
type DocumentAttempt struct {
Focus atspi.ObjectID `json:"focus"`
Before DocumentState `json:"before"`
Synced DocumentState `json:"synced"`
After DocumentState `json:"after"`
Recovery string `json:"recovery"`
Stage string `json:"stage"`
Error string `json:"error,omitempty"`
}
type DocumentState struct {
Document atspi.ObjectID `json:"document"`
Object atspi.ObjectID `json:"object"`
Focus atspi.ObjectID `json:"focus"`
TextParent atspi.ObjectID `json:"text_parent"`
Offset int `json:"offset"`
Origin string `json:"origin"`
Active bool `json:"active"`
}
func (cursor *DocumentCursor) diagnostic_state() DocumentState {
if cursor == nil {
return DocumentState{}
}
cursor.mu.Lock()
defer cursor.mu.Unlock()
if len(cursor.places) == 0 {
return DocumentState{}
}
place := cursor.places[len(cursor.places)-1]
origin := "native"
switch place.origin {
case StructuralNavigation:
origin = "structural"
case CaretNavigation:
origin = "caret"
}
return DocumentState{Document: place.document.ID(), Object: place.object.ID(),
Focus: place.focus.ID(), TextParent: place.textParent.ID(), Offset: place.offset,
Origin: origin, Active: cursor.active == place.document}
}
func (result *Result) record_document_attempt(cursor *DocumentCursor, attempt DocumentAttempt, err error) {
attempt.After = cursor.diagnostic_state()
if err != nil {
attempt.Error = err.Error()
}
result.DocumentDiagnostics.Attempts = append(result.DocumentDiagnostics.Attempts, attempt)
}
+11 -1
View File
@@ -51,16 +51,26 @@ func TestDocumentCaretRecoversSingleReplacedTextChild(t *testing.T) {
if err := tree.Replace(webID("/doc"), nodes); err != nil {
t.Fatal(err)
}
position, err := cursor.SyncFocus(ctx, webID("/doc"))
position, recovery, err := cursor.sync_focus(ctx, webID("/doc"))
if err != nil {
t.Fatal(err)
}
if kind != "single text" {
wantRecovery := "saved-object-missing"
if kind == "replaced document" {
wantRecovery = "document-replaced"
}
if recovery != wantRecovery {
t.Fatalf("recovery = %q, want %q", recovery, wantRecovery)
}
if position.Object.ID() == webID("/new") {
t.Fatal("ambiguous or replaced context inherited the old caret")
}
return
}
if recovery != "replaced-text-child" {
t.Fatalf("replacement recovery = %q", recovery)
}
move, err = cursor.MoveCaret(ctx, reader, CaretNextCharacter)
if err != nil || move.Text != "u" || move.Position.Offset != 1 || move.Position.Object.ID() != webID("/new") {
t.Fatalf("Right after text replacement = %+v, %v", move, err)
+26 -4
View File
@@ -44,13 +44,19 @@ func (worker *Worker) moveDocument(ctx context.Context, cursor *DocumentCursor,
result.Err = ErrNoCurrent
return result, cursor
}
move := func() error {
move := func() (moveErr error) {
attempt := DocumentAttempt{Focus: result.DocumentFocus, Before: cursor.diagnostic_state(), Stage: "focus"}
defer func() { result.record_document_attempt(cursor, attempt, moveErr) }()
if cursor == nil {
attempt.Recovery = "no-cursor"
return ErrNoCurrent
}
if _, err := cursor.SyncFocus(ctx, result.DocumentFocus); err != nil {
_, recovery, err := cursor.sync_focus(ctx, result.DocumentFocus)
attempt.Recovery, attempt.Synced = recovery, cursor.diagnostic_state()
if err != nil {
return err
}
attempt.Stage = "move"
move, err := cursor.Move(ctx, target, level, backwards)
result.DocumentPosition = move.Position
result.Moved = move.Moved
@@ -64,6 +70,7 @@ func (worker *Worker) moveDocument(ctx context.Context, cursor *DocumentCursor,
// A bounded refresh plus one retry handles a second replacement without
// allowing a constantly mutating page to loop indefinitely.
result.CaptureReason = result.Err
result.DocumentDiagnostics.CaptureAttempts++
captureContext, cancel := context.WithTimeout(ctx, worker.captureTimeout)
captureStarted := time.Now()
tree, err := worker.capturer.CaptureDocument(captureContext, result.DocumentFocus)
@@ -79,6 +86,7 @@ func (worker *Worker) moveDocument(ctx context.Context, cursor *DocumentCursor,
}
recovered := worker.recoverCapturedDocumentFocus(cursor, tree, &result)
if cursor == nil || cursor.tree != tree {
result.DocumentDiagnostics.CursorRecreated = true
cursor, _ = NewDocumentCursor(tree)
}
if !recovered {
@@ -89,6 +97,7 @@ func (worker *Worker) moveDocument(ctx context.Context, cursor *DocumentCursor,
worker.CurrentDocumentResult(result) && worker.focus() == result.DocumentFocus {
// A second replacement can race the first capture. Retry once while
// the navigation has not moved, so the heading is not skipped.
result.DocumentDiagnostics.CaptureAttempts++
retryContext, retryCancel := context.WithTimeout(ctx, worker.captureTimeout)
retryStarted := time.Now()
tree, err = worker.capturer.CaptureDocument(retryContext, result.DocumentFocus)
@@ -96,6 +105,7 @@ func (worker *Worker) moveDocument(ctx context.Context, cursor *DocumentCursor,
retryCancel()
if err == nil && tree != nil && worker.CurrentDocumentResult(result) && worker.focus() == result.DocumentFocus {
if cursor == nil || cursor.tree != tree {
result.DocumentDiagnostics.CursorRecreated = true
cursor, _ = NewDocumentCursor(tree)
}
result.Err = move()
@@ -148,6 +158,7 @@ func (worker *Worker) placeDocumentWithRetry(ctx context.Context, cursor *Docume
// and placing its native caret. Retry only the same target after one fresh
// capture; repeating the navigation command could skip to another target.
oldPosition := result.DocumentPosition
result.DocumentDiagnostics.CaptureAttempts++
captureContext, cancel := context.WithTimeout(ctx, worker.captureTimeout)
tree, err := worker.capturer.CaptureDocument(captureContext, result.DocumentFocus)
cancel()
@@ -193,13 +204,19 @@ func (worker *Worker) moveDocumentCaret(ctx context.Context, cursor *DocumentCur
result.Err = errors.New("document caret reader unavailable")
return result, cursor
}
move := func() error {
move := func() (moveErr error) {
attempt := DocumentAttempt{Focus: result.DocumentFocus, Before: cursor.diagnostic_state(), Stage: "focus"}
defer func() { result.record_document_attempt(cursor, attempt, moveErr) }()
if cursor == nil {
attempt.Recovery = "no-cursor"
return ErrNoCurrent
}
if _, err := cursor.SyncFocus(ctx, result.DocumentFocus); err != nil {
_, recovery, err := cursor.sync_focus(ctx, result.DocumentFocus)
attempt.Recovery, attempt.Synced = recovery, cursor.diagnostic_state()
if err != nil {
return err
}
attempt.Stage = "move"
// A word move can cross whitespace and several objects. Bound the
// whole navigation, not just each individual native text request.
navigationContext, cancel := context.WithTimeout(ctx, worker.captureTimeout)
@@ -235,6 +252,7 @@ func (worker *Worker) moveDocumentCaret(ctx context.Context, cursor *DocumentCur
return worker.placeDocumentCaret(ctx, result), cursor
}
result.CaptureReason = result.Err
result.DocumentDiagnostics.CaptureAttempts++
captureContext, cancel := context.WithTimeout(ctx, worker.captureTimeout)
captureStarted := time.Now()
tree, err := worker.capturer.CaptureDocument(captureContext, result.DocumentFocus)
@@ -250,6 +268,7 @@ func (worker *Worker) moveDocumentCaret(ctx context.Context, cursor *DocumentCur
}
recovered := worker.recoverCapturedDocumentFocus(cursor, tree, &result)
if cursor == nil || cursor.tree != tree {
result.DocumentDiagnostics.CursorRecreated = true
cursor, _ = NewDocumentCursor(tree)
}
if !recovered {
@@ -262,6 +281,7 @@ func (worker *Worker) moveDocumentCaret(ctx context.Context, cursor *DocumentCur
}
// A dynamic page can replace the captured target between recapture and
// SyncFocus. Retry once only if the first attempt did not move the caret.
result.DocumentDiagnostics.CaptureAttempts++
retryContext, retryCancel := context.WithTimeout(ctx, worker.captureTimeout)
retryStarted := time.Now()
tree, err = worker.capturer.CaptureDocument(retryContext, result.DocumentFocus)
@@ -271,6 +291,7 @@ func (worker *Worker) moveDocumentCaret(ctx context.Context, cursor *DocumentCur
return result, cursor
}
if cursor == nil || cursor.tree != tree {
result.DocumentDiagnostics.CursorRecreated = true
cursor, _ = NewDocumentCursor(tree)
}
result.Err = move()
@@ -430,6 +451,7 @@ func (worker *Worker) recoverCapturedDocumentFocus(cursor *DocumentCursor, tree
return false
}
result.DocumentFocus = root.ID()
result.DocumentDiagnostics.FocusRecovered = true
return true
}
+10
View File
@@ -785,6 +785,16 @@ func TestWorkerDocumentRecapturePreservesPosition(t *testing.T) {
r.DocumentWrapped || r.DocumentPosition.Object.ID() != webID("/first") {
t.Fatalf("recapture lost place: %+v", r)
}
diagnostics := r.DocumentDiagnostics
if diagnostics.CaptureAttempts != 1 || diagnostics.CursorRecreated || len(diagnostics.Attempts) != 2 {
t.Fatalf("recapture diagnostics = %+v", diagnostics)
}
failed, recovered := diagnostics.Attempts[0], diagnostics.Attempts[1]
if failed.Stage != "focus" || failed.Recovery != "document-unresolved" || failed.Error == "" ||
recovered.Recovery != "preserved" || recovered.Error != "" || recovered.Before.Object != webID("/second") ||
recovered.Synced.Object != webID("/second") || recovered.After.Object != webID("/first") {
t.Fatalf("recapture lost diagnostic history: %+v", diagnostics)
}
}
func TestWorkerPlaceDocumentAcceptsSameDocumentFocusTransition(t *testing.T) {
+1
View File
@@ -57,6 +57,7 @@ type Result struct {
ReadAllProgress func(int)
ReadAllPosition bool
DocumentEpoch uint64
DocumentDiagnostics DocumentDiagnostics
Elapsed time.Duration
CaptureDuration time.Duration
CaptureReason error
+43
View File
@@ -0,0 +1,43 @@
// Copyright (c) 2026 Storm Dragon
// Authors: Storm Dragon, Angus Kola
// SPDX-License-Identifier: GPL-3.0-or-later
package version
import (
"runtime"
"runtime/debug"
)
// Identity describes the executable itself, without consulting a checkout that
// may have changed since it was built. Missing VCS stamps remain explicit.
type Identity struct {
GoVersion string `json:"go_version"`
Revision string `json:"vcs_revision"`
Time string `json:"vcs_time"`
Modified string `json:"vcs_modified"`
}
func RuntimeIdentity() Identity {
info, _ := debug.ReadBuildInfo()
return build_identity(info)
}
func build_identity(info *debug.BuildInfo) Identity {
identity := Identity{GoVersion: runtime.Version(), Revision: "unknown", Time: "unknown", Modified: "unknown"}
if info == nil {
return identity
}
identity.GoVersion = info.GoVersion
for _, setting := range info.Settings {
switch setting.Key {
case "vcs.revision":
identity.Revision = setting.Value
case "vcs.time":
identity.Time = setting.Value
case "vcs.modified":
identity.Modified = setting.Value
}
}
return identity
}
+28
View File
@@ -0,0 +1,28 @@
// Copyright (c) 2026 Storm Dragon
// Authors: Storm Dragon, Angus Kola
// SPDX-License-Identifier: GPL-3.0-or-later
package version
import (
"runtime/debug"
"testing"
)
func TestBuildIdentityUsesEmbeddedSettings(t *testing.T) {
info := &debug.BuildInfo{GoVersion: "go1.24.0", Settings: []debug.BuildSetting{
{Key: "vcs.revision", Value: "0123456789abcdef"},
{Key: "vcs.time", Value: "2026-10-16T12:00:00Z"},
{Key: "vcs.modified", Value: "true"},
}}
identity := build_identity(info)
if identity != (Identity{"go1.24.0", "0123456789abcdef", "2026-10-16T12:00:00Z", "true"}) {
t.Fatalf("embedded build identity = %+v", identity)
}
for _, info := range []*debug.BuildInfo{nil, {GoVersion: "go1.24.0"}} {
identity := build_identity(info)
if identity.GoVersion == "" || identity.Revision != "unknown" || identity.Time != "unknown" || identity.Modified != "unknown" {
t.Fatalf("unstamped build falsely identified: %+v", identity)
}
}
}
+1 -1
View File
@@ -21,7 +21,7 @@ import "strings"
const Name = "Cthulhu"
const Version = "2026.10.15"
const Version = "2026.10.16"
const Channel = "master"
var Build = Version