From b03cb8917d56d1bf5002577ac9d9a1aa467f7aa4 Mon Sep 17 00:00:00 2001 From: Hunter Jozwiak Date: Tue, 10 Nov 2026 21:13:41 -0500 Subject: [PATCH] Add optional DuckDB debug log database with typed schema New --debug-db flag writes the redacted debug record stream to a DuckDB database alongside or instead of the NDJSON --debug-file. Frequent type-stable attributes are promoted to typed columns; the complete record remains in attrs JSON. libduckdb is dlopen'ed at runtime (build tag duckdb, Arch optdepends) so the reader runs unchanged without it. v1 databases upgrade in place on append. --- .gitignore | 7 + AGENTS.md | 2 + README.md | 53 +- cmd/cthulhu/main.go | 60 +- cmd/cthulhu/main_duckdb_native_test.go | 78 +++ cmd/cthulhu/main_duckdb_unavailable_test.go | 56 ++ cmd/cthulhu/main_test.go | 19 +- .../Arch-Linux/cthulhu-git/PKGBUILD | 9 +- internal/logging/duckdb.go | 381 ++++++++++ internal/logging/duckdb_native.go | 648 ++++++++++++++++++ internal/logging/duckdb_native_test.go | 318 +++++++++ internal/logging/duckdb_test.go | 228 ++++++ internal/logging/duckdb_unavailable.go | 25 + internal/logging/duckdb_unavailable_test.go | 36 + 14 files changed, 1906 insertions(+), 14 deletions(-) create mode 100644 cmd/cthulhu/main_duckdb_native_test.go create mode 100644 cmd/cthulhu/main_duckdb_unavailable_test.go create mode 100644 internal/logging/duckdb.go create mode 100644 internal/logging/duckdb_native.go create mode 100644 internal/logging/duckdb_native_test.go create mode 100644 internal/logging/duckdb_test.go create mode 100644 internal/logging/duckdb_unavailable.go create mode 100644 internal/logging/duckdb_unavailable_test.go diff --git a/.gitignore b/.gitignore index 51f40cf..5633774 100644 --- a/.gitignore +++ b/.gitignore @@ -17,3 +17,10 @@ __pycache__/ /distro-packages/Arch-Linux/cthulhu-git/*/ /cmd/cthulhu/cthulhu + +# Local tooling output and debug artifacts (never fixtures) +/graphify-out/ +/*.log +*.duckdb +*.duckdb.wal +/test.db* diff --git a/AGENTS.md b/AGENTS.md index da69dfc..cfe0351 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -22,10 +22,12 @@ Use Go 1.24+ with CGO and development libraries listed by the Arch `PKGBUILD`. - `go build -o build/cthulhu ./cmd/cthulhu`: build the reader. - `go build -tags brlapi -o build/cthulhu-braille ./cmd/cthulhu-braille`: build the Braille helper. +- `go build -tags duckdb -o build/cthulhu ./cmd/cthulhu`: build the reader with `--debug-db` DuckDB debug-log support (needs duckdb headers at build time only; libduckdb is dlopen'ed at runtime and is an optional package dependency; test with `go test -tags duckdb ./internal/logging/ ./cmd/cthulhu/`). - `go build -o build/cthulhu-input-helper ./cmd/cthulhu-input-helper`: build the remote input helper; install it beside the reader for incoming keyboard control. - `go test ./... -count=1`: run default tests; native cases may skip. - `go test -tags brlapi ./... -count=1`: run packaging checks. - `go vet ./...`: check common Go errors. +- `golangci-lint run ./...`: run the configured lint gate (`.golangci.yml`, v2 schema; build tags brlapi/duckdb set there; keep the linter built with a Go at least as new as the project toolchain or it reports typecheck garbage). - `go run ./cmd/parityledger validate testdata/parity-ledger.csv`: validate parity records. - `./build/cthulhu --check-config`: validate settings; `./build/cthulhu` starts the reader. diff --git a/README.md b/README.md index e6e16dd..75df1d7 100644 --- a/README.md +++ b/README.md @@ -355,7 +355,58 @@ existing announcement behavior. Debug logging with `--debug-file PATH` replaces any existing log at that path. Add `--append` to preserve earlier sessions, for example `cthulhu --debug-file /tmp/cthulhu.log --append`. -`--append` requires `--debug-file`. A log can still grow during a long session. +`--append` requires `--debug-file` or `--debug-db`. A log can still grow during a long session. + +Builds compiled with `-tags duckdb` (needs the DuckDB headers at build time; +the packaged Arch build is one) also accept `--debug-db PATH`, which writes +the same redacted debug records to a DuckDB database instead of, or in +addition to, the NDJSON file. `libduckdb` is loaded only when the flag is +used, so it is an optional runtime dependency (an Arch `optdepends`); the +reader runs normally without it, and `--debug-db` reports that the `duckdb` +package must be installed: +`cthulhu --debug-db /tmp/cthulhu.duckdb`. Passing both flags writes both +sinks. Without `--append` an existing database at the path is replaced; with +`--append` each run adds a row to the `sessions` table (`session_id`, +`started_at`, `pid`) and its records to the `logs` table. `logs` has typed +columns `seq` (per-session record order), `session_id`, `ts` (timestamptz), +`level`, `message`, `source`, and `function`, plus typed columns for the +record attributes real logs show are frequent and type-stable (such as +`role`, `application`, `focused`, `snapshot_duration`, and `error`; run +`DESCRIBE logs` for the full list). Every field, promoted or not, is also +preserved in the `attrs` JSON column, so nested and rare attributes remain +available. Databases written by the first schema version gain the promoted +columns automatically on the next `--append` open. This makes agent and +script queries cheap SQL instead of a full scan of a large JSON file, for +example: + +```sh +duckdb -readonly /tmp/cthulhu.duckdb +``` + +```sql +SELECT seq, ts, message, error +FROM logs +WHERE level IN ('WARN', 'ERROR') + AND session_id = (SELECT session_id FROM sessions ORDER BY started_at DESC LIMIT 1) +ORDER BY seq; + +SELECT role, count(*), round(avg(snapshot_duration) / 1e6, 2) AS avg_snapshot_ms +FROM logs WHERE snapshot_duration IS NOT NULL GROUP BY role ORDER BY 2 DESC; + +SELECT message, count(*) FROM logs GROUP BY message ORDER BY 2 DESC LIMIT 20; +``` + +The database file and its write-ahead log are restricted to the owner +(`0600`), like the debug file, and need the same review before sharing: +records can contain spoken page text. Routine records are buffered briefly +(flushed at least once a second while records flow, and immediately for +warnings and errors), so a hard crash can lose the last few hundred routine +records from the database; the NDJSON file writes every record immediately. +While the reader is running it holds DuckDB's write lock, so inspect a copy +of the database and its `.wal` file, or query after the reader stops. +In builds without the `duckdb` tag, +`--debug-db` fails at startup with an explanation instead of silently +writing nothing. For browser bug reports, start Cthulhu with `--debug-file /tmp/cthulhu-browser.log` and reproduce the affected navigation. The startup record includes the release diff --git a/cmd/cthulhu/main.go b/cmd/cthulhu/main.go index a8fb3ee..f5bdfd2 100644 --- a/cmd/cthulhu/main.go +++ b/cmd/cthulhu/main.go @@ -27,6 +27,7 @@ import ( "os" "os/signal" "os/user" + "path/filepath" "syscall" "time" @@ -80,8 +81,9 @@ func run(ctx context.Context, arguments []string, stdout, stderr io.Writer) (res clipboardWatch := options.Bool("clipboard-watch", false, "run the internal clipboard change helper (private pipe protocol)") ocrCapture := options.Bool("ocr-capture", false, "run the internal OCR capture helper (private pipe protocol)") ocrConfirm := options.Bool("ocr-confirm", false, "run the internal OCR click confirmation helper") - appendLog := options.Bool("append", false, "preserve existing debug log contents (requires --debug-file)") + appendLog := options.Bool("append", false, "preserve existing debug log contents (requires --debug-file or --debug-db)") debugFile := options.String("debug-file", "", "enable debug logging only to this file, replacing existing contents") + debugDB := options.String("debug-db", "", "enable debug logging only to this DuckDB database, replacing existing contents") speechSocket := options.String( "speech-socket", "", @@ -127,8 +129,11 @@ func run(ctx context.Context, arguments []string, stdout, stderr io.Writer) (res if options.NArg() != 0 { return fmt.Errorf("unexpected argument %q", options.Arg(0)) } - if *appendLog && *debugFile == "" { - return errors.New("--append requires --debug-file") + if *appendLog && *debugFile == "" && *debugDB == "" { + return errors.New("--append requires --debug-file or --debug-db") + } + if *debugFile != "" && *debugDB != "" && sameDestination(*debugFile, *debugDB) { + return errors.New("--debug-file and --debug-db must be different files") } if *showVersion || *shortVersion { fmt.Fprintln(stdout, version.Details( @@ -181,12 +186,36 @@ func run(ctx context.Context, arguments []string, stdout, stderr io.Writer) (res } } logger := slog.New(slog.DiscardHandler) - if *debugFile != "" { - fileWriter, err := logging.OpenFile(*debugFile, nil, *appendLog) - if err != nil { - return fmt.Errorf("open debug log: %w", err) + if *debugFile != "" || *debugDB != "" { + // Open the database first: its routine failure modes (libduckdb not + // installed, foreign file) must not destroy an existing debug log + // by truncating it before the run even starts. + var databaseWriter, fileWriter logging.DiagnosticsWriter + if *debugDB != "" { + var err error + databaseWriter, err = logging.OpenDuckDB(*debugDB, *appendLog, os.Getpid()) + if err != nil { + return fmt.Errorf("open debug database: %w", err) + } } - diagnostics := logging.NewAsync(fileWriter, logging.AsyncOptions{ + if *debugFile != "" { + var err error + fileWriter, err = logging.OpenFile(*debugFile, nil, *appendLog) + if err != nil { + if databaseWriter != nil { + _ = databaseWriter.Close() + } + return fmt.Errorf("open debug log: %w", err) + } + } + sinks := make([]logging.DiagnosticsWriter, 0, 2) + if fileWriter != nil { + sinks = append(sinks, fileWriter) + } + if databaseWriter != nil { + sinks = append(sinks, databaseWriter) + } + diagnostics := logging.NewAsync(logging.NewMultiWriter(sinks...), logging.AsyncOptions{ Options: logging.Options{Level: slog.LevelDebug, AddSource: true}, }) defer func() { @@ -261,3 +290,18 @@ func run(ctx context.Context, arguments []string, stdout, stderr io.Writer) (res } return err } + +// sameDestination reports whether two sink paths name the same file, via +// cleaned absolute paths or, when both exist, file identity (symlink and +// ./ aliases). Sharing one file between the NDJSON and DuckDB sinks would +// corrupt both. +func sameDestination(a, b string) bool { + absA, errA := filepath.Abs(a) + absB, errB := filepath.Abs(b) + if errA == nil && errB == nil && absA == absB { + return true + } + infoA, errA := os.Stat(a) + infoB, errB := os.Stat(b) + return errA == nil && errB == nil && os.SameFile(infoA, infoB) +} diff --git a/cmd/cthulhu/main_duckdb_native_test.go b/cmd/cthulhu/main_duckdb_native_test.go new file mode 100644 index 0000000..3359ca3 --- /dev/null +++ b/cmd/cthulhu/main_duckdb_native_test.go @@ -0,0 +1,78 @@ +//go:build duckdb && cgo + +// Cthulhu screen reader. +// Copyright (c) 2026 Storm Dragon +// Authors: Storm Dragon, Angus Kola +// +// This program is free software: you can redistribute it and/or modify it +// under the terms of the GNU General Public License as published by the Free +// Software Foundation, either version 3 of the License, or (at your option) +// any later version. +// +// This program is distributed in the hope that it will be useful, but WITHOUT +// ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or +// FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for +// more details. +// +// You should have received a copy of the GNU General Public License along with +// this program. If not, see . + +package main + +import ( + "bytes" + "context" + "os" + "os/exec" + "path/filepath" + "strings" + "testing" +) + +// --debug-db and --debug-file together must both receive the session: the +// NDJSON file stays available for existing tooling while the database gets +// the same records in queryable form. +func TestDebugDBAndFileBothReceiveRecords(t *testing.T) { + directory := t.TempDir() + databasePath := filepath.Join(directory, "debug.duckdb") + logPath := filepath.Join(directory, "debug.log") + configPath := filepath.Join(directory, "absent.toml") + var stdout, stderr bytes.Buffer + if err := run(context.Background(), []string{ + "--check-config", "--config", configPath, + "--debug-file", logPath, "--debug-db", databasePath, + }, &stdout, &stderr); err != nil { + t.Fatal(err) + } + if stderr.Len() != 0 { + t.Fatalf("debug sinks wrote to terminal: %q", stderr.String()) + } + logData, err := os.ReadFile(logPath) + if err != nil { + t.Fatal(err) + } + if !strings.Contains(string(logData), `"starting Cthulhu"`) { + t.Fatalf("debug file missing startup record: %s", logData) + } + + cli, err := exec.LookPath("duckdb") + if err != nil { + t.Skip("duckdb CLI not installed; cannot verify database contents") + } + output, err := exec.Command(cli, "-readonly", "-noheader", "-list", databasePath, + "-c", "SELECT message || '|' || (attrs->>'$.pid' IS NOT NULL) FROM logs WHERE seq = 1").CombinedOutput() + if err != nil { + t.Fatalf("duckdb query: %v\n%s", err, output) + } + if got := strings.TrimSpace(string(output)); got != "starting Cthulhu|true" { + t.Fatalf("first database record = %q", got) + } +} + +func TestDebugDBOpenFailure(t *testing.T) { + var output bytes.Buffer + err := run(context.Background(), []string{"--debug-db", t.TempDir()}, &output, &output) + if err == nil || !strings.Contains(err.Error(), "open debug database") { + t.Fatalf("error = %v", err) + } +} diff --git a/cmd/cthulhu/main_duckdb_unavailable_test.go b/cmd/cthulhu/main_duckdb_unavailable_test.go new file mode 100644 index 0000000..5d86da0 --- /dev/null +++ b/cmd/cthulhu/main_duckdb_unavailable_test.go @@ -0,0 +1,56 @@ +//go:build !duckdb || !cgo + +// Cthulhu screen reader. +// Copyright (c) 2026 Storm Dragon +// Authors: Storm Dragon, Angus Kola +// +// This program is free software: you can redistribute it and/or modify it +// under the terms of the GNU General Public License as published by the Free +// Software Foundation, either version 3 of the License, or (at your option) +// any later version. +// +// This program is distributed in the hope that it will be useful, but WITHOUT +// ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or +// FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for +// more details. +// +// You should have received a copy of the GNU General Public License along with +// this program. If not, see . + +package main + +import ( + "bytes" + "context" + "errors" + "path/filepath" + "strings" + "testing" + + "git.stormux.org/storm/cthulhu/internal/logging" +) + +func TestDebugDBUnavailableWithoutBuildTag(t *testing.T) { + databasePath := filepath.Join(t.TempDir(), "debug.duckdb") + var output bytes.Buffer + err := run(context.Background(), []string{"--debug-db", databasePath}, &output, &output) + if !errors.Is(err, logging.ErrDuckDBUnavailable) { + t.Fatalf("error = %v, want ErrDuckDBUnavailable", err) + } + if !strings.Contains(err.Error(), "open debug database") { + t.Fatalf("error = %v, want open context", err) + } +} + +func TestAppendAcceptsDebugDBAsSink(t *testing.T) { + databasePath := filepath.Join(t.TempDir(), "debug.duckdb") + var output bytes.Buffer + err := run(context.Background(), []string{"--append", "--debug-db", databasePath}, &output, &output) + if err != nil && strings.Contains(err.Error(), "--append requires") { + t.Fatalf("--append rejected --debug-db as its sink: %v", err) + } + // In this build the run then fails opening the database instead. + if !errors.Is(err, logging.ErrDuckDBUnavailable) { + t.Fatalf("error = %v, want ErrDuckDBUnavailable", err) + } +} diff --git a/cmd/cthulhu/main_test.go b/cmd/cthulhu/main_test.go index cffabd0..1208382 100644 --- a/cmd/cthulhu/main_test.go +++ b/cmd/cthulhu/main_test.go @@ -301,14 +301,29 @@ func TestStandaloneDebugFlagRejected(t *testing.T) { } } -func TestAppendRequiresDebugFile(t *testing.T) { +func TestAppendRequiresDebugSink(t *testing.T) { var output bytes.Buffer err := run(context.Background(), []string{"--append"}, &output, &output) - if err == nil || err.Error() != "--append requires --debug-file" { + if err == nil || err.Error() != "--append requires --debug-file or --debug-db" { t.Fatalf("error = %v", err) } } +func TestDebugFileAndDBSameFileRejected(t *testing.T) { + shared := filepath.Join(t.TempDir(), "debug.out") + alias := filepath.Dir(shared) + string(filepath.Separator) + "." + string(filepath.Separator) + "debug.out" + for _, arguments := range [][]string{ + {"--debug-file", shared, "--debug-db", shared}, + {"--debug-file", shared, "--debug-db", alias}, + } { + var output bytes.Buffer + err := run(context.Background(), arguments, &output, &output) + if err == nil || !strings.Contains(err.Error(), "must be different files") { + t.Fatalf("arguments %v: error = %v", arguments, err) + } + } +} + func TestDebugFileStartsFresh(t *testing.T) { logPath := filepath.Join(t.TempDir(), "debug.log") configPath := filepath.Join(t.TempDir(), "absent.toml") diff --git a/distro-packages/Arch-Linux/cthulhu-git/PKGBUILD b/distro-packages/Arch-Linux/cthulhu-git/PKGBUILD index 96ecb28..cd914eb 100644 --- a/distro-packages/Arch-Linux/cthulhu-git/PKGBUILD +++ b/distro-packages/Arch-Linux/cthulhu-git/PKGBUILD @@ -5,7 +5,7 @@ pkgbase=cthulhu-git pkgname=cthulhu-git _pkgname=cthulhu pkgver=2026.10.31.r588.g9680b58 -pkgrel=2 +pkgrel=3 pkgdesc="Desktop-agnostic screen reader with speech, Braille, and Tentacle support" url="https://git.stormux.org/storm/cthulhu" arch=(x86_64 aarch64 armv7h) @@ -45,6 +45,7 @@ optdepends=( 'git: Discover and update Tentacle repositories' 'tesseract: OCR engine for text recognition' 'tesseract-data-eng: English OCR language data' + 'duckdb: DuckDB debug database logging with --debug-db' ) optdepends_x86_64=( # Wine accessibility helpers are supported on x86_64. @@ -54,6 +55,8 @@ makedepends=( git go pkgconf + # Headers only: libduckdb is dlopen'ed at runtime when --debug-db is used. + duckdb ) options=(!debug !lto) source=("${_pkgname}::git+https://git.stormux.org/storm/${_pkgname}.git#branch=master") @@ -82,7 +85,7 @@ build() { export GOCACHE="${GOCACHE:-${srcdir}/go-build}" export GOFLAGS="-buildmode=pie -trimpath -ldflags=-linkmode=external -mod=readonly -modcacherw" - go build -o build/cthulhu ./cmd/cthulhu + go build -tags duckdb -o build/cthulhu ./cmd/cthulhu go build -tags brlapi -o build/cthulhu-braille ./cmd/cthulhu-braille # Include the helper once incoming Remote keyboard support reaches master. if [[ -d cmd/cthulhu-input-helper ]]; then @@ -95,7 +98,7 @@ check() { export CGO_ENABLED=1 export GOPATH="${srcdir}/go" export GOCACHE="${GOCACHE:-${srcdir}/go-build}" - go test -tags brlapi ./... -count=1 + go test -tags 'brlapi duckdb' ./... -count=1 } package() { diff --git a/internal/logging/duckdb.go b/internal/logging/duckdb.go new file mode 100644 index 0000000..a095664 --- /dev/null +++ b/internal/logging/duckdb.go @@ -0,0 +1,381 @@ +// Cthulhu screen reader. +// Copyright (c) 2026 Storm Dragon +// Authors: Storm Dragon, Angus Kola +// +// This program is free software: you can redistribute it and/or modify it +// under the terms of the GNU General Public License as published by the Free +// Software Foundation, either version 3 of the License, or (at your option) +// any later version. +// +// This program is distributed in the hope that it will be useful, but WITHOUT +// ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or +// FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for +// more details. +// +// You should have received a copy of the GNU General Public License along with +// this program. If not, see . + +package logging + +import ( + "bytes" + "encoding/json" + "errors" + "fmt" + "io" + "strings" + "time" +) + +// ErrDuckDBUnavailable reports that DuckDB debug logging cannot be used in +// this build or on this system: either the build was compiled without +// -tags duckdb, or libduckdb could not be loaded at runtime. +var ErrDuckDBUnavailable = errors.New("duckdb debug logging unavailable (requires a -tags duckdb build and an installed libduckdb)") + +// Debug database schema. The fields Handler.format emits for every record +// become typed columns, and so do the record attributes listed in +// promotedAttrs: keys that real logs show are frequent, scalar, and +// type-stable, which makes them honest filter and aggregate dimensions for +// SQL (real types, column statistics, no JSON extraction). Everything else +// is preserved verbatim in the attrs JSON column, promoted keys included, +// because the full key set is open-ended (over 100 keys, nested objects +// and arrays, occasional type changes), so one column per key is not +// viable. Promoted columns follow attrs so a v1 database upgrades in +// place by appending them. +const ( + duckDBSchemaVersion = "2" + duckDBSchemaVersionV1 = "1" + + duckDBCreateMeta = `CREATE TABLE IF NOT EXISTS meta ( + key VARCHAR PRIMARY KEY, + value VARCHAR NOT NULL + )` + duckDBCreateSessions = `CREATE TABLE IF NOT EXISTS sessions ( + session_id VARCHAR PRIMARY KEY, + started_at TIMESTAMPTZ NOT NULL, + pid BIGINT NOT NULL + )` +) + +// Column order here is the appender order in duckdb_native.go. +var duckDBCreateLogs = buildLogsDDL() + +func buildLogsDDL() string { + var ddl strings.Builder + ddl.WriteString(`CREATE TABLE IF NOT EXISTS logs ( + seq BIGINT NOT NULL, + session_id VARCHAR NOT NULL, + ts TIMESTAMPTZ NOT NULL, + level VARCHAR NOT NULL, + message VARCHAR NOT NULL, + source VARCHAR, + function VARCHAR, + attrs JSON NOT NULL`) + for _, attr := range promotedAttrs { + fmt.Fprintf(&ddl, ",\n\t\t\"%s\" %s", attr.key, attr.sqlType()) + } + ddl.WriteString("\n\t)") + return ddl.String() +} + +type promotedKind int + +const ( + promotedText promotedKind = iota + promotedInt + promotedBool +) + +type promotedAttr struct { + key string + kind promotedKind +} + +func (attr promotedAttr) sqlType() string { + switch attr.kind { + case promotedInt: + return "BIGINT" + case promotedBool: + return "BOOLEAN" + default: + return "VARCHAR" + } +} + +// promotedAttrs was derived by profiling real debug sessions: every key +// here is scalar and single-typed (null aside) at meaningful frequency, or +// carries errors. Free-text payloads (utterance, speech_text) stay in +// attrs only; they are content, not dimensions. +var promotedAttrs = []promotedAttr{ + {key: "role", kind: promotedText}, + {key: "type", kind: promotedText}, + {key: "bus", kind: promotedText}, + {key: "source_path", kind: promotedText}, + {key: "application", kind: promotedText}, + {key: "window_path", kind: promotedText}, + {key: "native_type", kind: promotedText}, + {key: "origin_path", kind: promotedText}, + {key: "window_bus", kind: promotedText}, + {key: "focus_outside_document", kind: promotedText}, + {key: "radio_group_name", kind: promotedText}, + {key: "editable_root", kind: promotedText}, + {key: "read_only_combo", kind: promotedText}, + {key: "key", kind: promotedText}, + {key: "cause", kind: promotedText}, + {key: "reason", kind: promotedText}, + {key: "command", kind: promotedText}, + {key: "object_path", kind: promotedText}, + {key: "capture_reason", kind: promotedText}, + {key: "error", kind: promotedText}, + {key: "component", kind: promotedText}, + {key: "service", kind: promotedText}, + + {key: "window_recovered", kind: promotedBool}, + {key: "focused", kind: promotedBool}, + {key: "browser_tab", kind: promotedBool}, + {key: "selected", kind: promotedBool}, + {key: "checked", kind: promotedBool}, + {key: "prompt_message_present", kind: promotedBool}, + {key: "editable", kind: promotedBool}, + {key: "autocomplete", kind: promotedBool}, + {key: "autocomplete_popup", kind: promotedBool}, + {key: "native_caret_known", kind: promotedBool}, + {key: "input_repeat", kind: promotedBool}, + {key: "append", kind: promotedBool}, + {key: "interrupt_previous", kind: promotedBool}, + {key: "character", kind: promotedBool}, + {key: "custom_echo", kind: promotedBool}, + {key: "moved", kind: promotedBool}, + {key: "has_offset", kind: promotedBool}, + + {key: "snapshot_duration", kind: promotedInt}, + {key: "event_detail1", kind: promotedInt}, + {key: "native_caret_offset", kind: promotedInt}, + {key: "native_line_start", kind: promotedInt}, + {key: "character_count", kind: promotedInt}, + {key: "selection_start", kind: promotedInt}, + {key: "selection_end", kind: promotedInt}, + {key: "input_timestamp", kind: promotedInt}, + {key: "recent", kind: promotedInt}, + {key: "input_keycode", kind: promotedInt}, + {key: "read_all_index", kind: promotedInt}, + {key: "capture_duration", kind: promotedInt}, + {key: "speech_style", kind: promotedInt}, + {key: "unit", kind: promotedInt}, + {key: "offset", kind: promotedInt}, + {key: "elapsed", kind: promotedInt}, + {key: "duration", kind: promotedInt}, + {key: "stage_duration", kind: promotedInt}, + {key: "captured_nodes", kind: promotedInt}, + {key: "pending_nodes", kind: promotedInt}, + {key: "text_bytes", kind: promotedInt}, +} + +// promotedValue is one promotedAttrs entry decoded from a record. valid is +// false when the key is absent, JSON null, or holds a different type than +// the column; the value still survives in attrs in every case. +type promotedValue struct { + text string + integer int64 + boolean bool + valid bool +} + +func decodePromoted(kind promotedKind, raw json.RawMessage) promotedValue { + if string(raw) == "null" { + return promotedValue{} + } + switch kind { + case promotedText: + var value string + if json.Unmarshal(raw, &value) == nil { + return promotedValue{text: value, valid: true} + } + case promotedInt: + var value int64 + if json.Unmarshal(raw, &value) == nil { + return promotedValue{integer: value, valid: true} + } + case promotedBool: + var value bool + if json.Unmarshal(raw, &value) == nil { + return promotedValue{boolean: value, valid: true} + } + } + return promotedValue{} +} + +// parsedRecord is one formatted log line split into typed columns and the +// remaining attributes as JSON object text. +type parsedRecord struct { + timestamp time.Time + level string + message string + source string + function string + attrs string + promoted []promotedValue +} + +// parseLogRecord splits one NDJSON line produced by Handler.format. The +// formatter emits message, level, source and function first, then any +// record attributes, and time last of all. An attribute may reuse one of +// those names (for example an integer "level" attribute), so the leading +// fields are owned by their first occurrence and time by its last; +// superseded duplicates fall through to attrs. ok is false for lines that +// do not match the formatter's shape, in which case the caller stores the +// raw line instead of dropping it. +func parseLogRecord(line []byte) (record parsedRecord, ok bool) { + decoder := json.NewDecoder(bytes.NewReader(line)) + token, err := decoder.Token() + if err != nil { + return parsedRecord{}, false + } + if delim, isDelim := token.(json.Delim); !isDelim || delim != '{' { + return parsedRecord{}, false + } + attrs := map[string]json.RawMessage{} + seen := map[string]bool{} + var timeRaw json.RawMessage + for decoder.More() { + keyToken, err := decoder.Token() + if err != nil { + return parsedRecord{}, false + } + key, isString := keyToken.(string) + if !isString { + return parsedRecord{}, false + } + var raw json.RawMessage + if err := decoder.Decode(&raw); err != nil { + return parsedRecord{}, false + } + if key == "time" { + // The formatter's timestamp comes last; any earlier "time" + // attribute is demoted to attrs when the real one arrives. + if timeRaw != nil { + attrs["time"] = timeRaw + } + timeRaw = raw + continue + } + if isReservedLogKey(key) && !seen[key] { + seen[key] = true + if !record.setReserved(key, raw) { + return parsedRecord{}, false + } + continue + } + attrs[key] = raw + } + if _, err := decoder.Token(); err != nil { // closing brace + return parsedRecord{}, false + } + if _, err := decoder.Token(); err != io.EOF { // trailing newline only + return parsedRecord{}, false + } + if !seen["message"] || !seen["level"] || timeRaw == nil { + return parsedRecord{}, false + } + var timeText string + if err := json.Unmarshal(timeRaw, &timeText); err != nil { + return parsedRecord{}, false + } + parsedTime, err := time.Parse(time.RFC3339Nano, timeText) + if err != nil { + return parsedRecord{}, false + } + record.timestamp = parsedTime + if len(attrs) == 0 { + record.attrs = "{}" + } else { + encoded, err := json.Marshal(attrs) + if err != nil { + return parsedRecord{}, false + } + record.attrs = string(encoded) + } + record.promoted = make([]promotedValue, len(promotedAttrs)) + for i, attr := range promotedAttrs { + if raw, present := attrs[attr.key]; present { + record.promoted[i] = decodePromoted(attr.kind, raw) + } + } + return record, true +} + +func isReservedLogKey(key string) bool { + switch key { + case "message", "level", "source", "function": + return true + } + return false +} + +func (record *parsedRecord) setReserved(key string, raw json.RawMessage) bool { + var text string + if err := json.Unmarshal(raw, &text); err != nil { + return false + } + switch key { + case "message": + record.message = text + case "level": + record.level = text + case "source": + record.source = text + case "function": + record.function = text + } + return true +} + +// multiWriter fans each formatted record out to every sink, for example the +// NDJSON file and the DuckDB database at the same time. A failing sink does +// not starve the others; errors are joined and reported to the diagnostics +// loop, which records them like any other write error. +type multiWriter struct { + writers []DiagnosticsWriter +} + +func NewMultiWriter(writers ...DiagnosticsWriter) DiagnosticsWriter { + live := make([]DiagnosticsWriter, 0, len(writers)) + for _, writer := range writers { + if writer != nil { + live = append(live, writer) + } + } + switch len(live) { + case 0: + return NewPassthroughWriter(nil) + case 1: + return live[0] + } + return &multiWriter{writers: live} +} + +func (writer *multiWriter) Write(data []byte) (int, error) { + var joined error + for _, sink := range writer.writers { + if _, err := sink.Write(data); err != nil { + joined = errors.Join(joined, err) + } + } + return len(data), joined +} + +func (writer *multiWriter) Cancel() error { + var joined error + for _, sink := range writer.writers { + joined = errors.Join(joined, sink.Cancel()) + } + return joined +} + +func (writer *multiWriter) Close() error { + var joined error + for _, sink := range writer.writers { + joined = errors.Join(joined, sink.Close()) + } + return joined +} diff --git a/internal/logging/duckdb_native.go b/internal/logging/duckdb_native.go new file mode 100644 index 0000000..39c81b8 --- /dev/null +++ b/internal/logging/duckdb_native.go @@ -0,0 +1,648 @@ +//go:build duckdb && cgo + +// Cthulhu screen reader. +// Copyright (c) 2026 Storm Dragon +// Authors: Storm Dragon, Angus Kola +// +// This program is free software: you can redistribute it and/or modify it +// under the terms of the GNU General Public License as published by the Free +// Software Foundation, either version 3 of the License, or (at your option) +// any later version. +// +// This program is distributed in the hope that it will be useful, but WITHOUT +// ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or +// FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for +// more details. +// +// You should have received a copy of the GNU General Public License along with +// this program. If not, see . + +package logging + +/* +#cgo LDFLAGS: -ldl +#include +#include +#include +#include + +// libduckdb is an optional runtime dependency (an Arch optdepend): the +// reader must start and run on systems without it, so the library is +// dlopen'ed only when --debug-db is actually used instead of being linked. +// The header is still needed at build time; the pointers below take their +// types from it, so calls through them are checked against the installed +// header exactly like direct calls would be. + +#define CTH_DUCK_PTR(name) static __typeof__(&name) cth_p_##name +CTH_DUCK_PTR(duckdb_create_config); +CTH_DUCK_PTR(duckdb_set_config); +CTH_DUCK_PTR(duckdb_destroy_config); +CTH_DUCK_PTR(duckdb_open_ext); +CTH_DUCK_PTR(duckdb_free); +CTH_DUCK_PTR(duckdb_connect); +CTH_DUCK_PTR(duckdb_query); +CTH_DUCK_PTR(duckdb_result_error); +CTH_DUCK_PTR(duckdb_destroy_result); +CTH_DUCK_PTR(duckdb_row_count); +CTH_DUCK_PTR(duckdb_value_varchar); +CTH_DUCK_PTR(duckdb_appender_create); +CTH_DUCK_PTR(duckdb_appender_error); +CTH_DUCK_PTR(duckdb_appender_begin_row); +CTH_DUCK_PTR(duckdb_append_int64); +CTH_DUCK_PTR(duckdb_append_varchar_length); +CTH_DUCK_PTR(duckdb_create_timestamp_tz); +CTH_DUCK_PTR(duckdb_append_value); +CTH_DUCK_PTR(duckdb_destroy_value); +CTH_DUCK_PTR(duckdb_append_null); +CTH_DUCK_PTR(duckdb_append_bool); +CTH_DUCK_PTR(duckdb_appender_end_row); +CTH_DUCK_PTR(duckdb_appender_flush); +CTH_DUCK_PTR(duckdb_appender_close); +CTH_DUCK_PTR(duckdb_appender_destroy); +CTH_DUCK_PTR(duckdb_disconnect); +CTH_DUCK_PTR(duckdb_close); + +// cth_duckdb_load resolves every symbol the sink uses from the library at +// path. It returns NULL on success or a diagnostic string (dlerror output or +// a string literal; neither must be freed) on failure. +static const char *cth_duckdb_load(const char *path) { + void *handle = dlopen(path, RTLD_NOW | RTLD_LOCAL); + if (!handle) return dlerror(); +#define CTH_DUCK_SYM(name) do { \ + *(void **)(&cth_p_##name) = dlsym(handle, #name); \ + if (!cth_p_##name) return "missing symbol " #name; \ + } while (0) + CTH_DUCK_SYM(duckdb_create_config); + CTH_DUCK_SYM(duckdb_set_config); + CTH_DUCK_SYM(duckdb_destroy_config); + CTH_DUCK_SYM(duckdb_open_ext); + CTH_DUCK_SYM(duckdb_free); + CTH_DUCK_SYM(duckdb_connect); + CTH_DUCK_SYM(duckdb_query); + CTH_DUCK_SYM(duckdb_result_error); + CTH_DUCK_SYM(duckdb_destroy_result); + CTH_DUCK_SYM(duckdb_row_count); + CTH_DUCK_SYM(duckdb_value_varchar); + CTH_DUCK_SYM(duckdb_appender_create); + CTH_DUCK_SYM(duckdb_appender_error); + CTH_DUCK_SYM(duckdb_appender_begin_row); + CTH_DUCK_SYM(duckdb_append_int64); + CTH_DUCK_SYM(duckdb_append_varchar_length); + CTH_DUCK_SYM(duckdb_create_timestamp_tz); + CTH_DUCK_SYM(duckdb_append_value); + CTH_DUCK_SYM(duckdb_destroy_value); + CTH_DUCK_SYM(duckdb_append_null); + CTH_DUCK_SYM(duckdb_append_bool); + CTH_DUCK_SYM(duckdb_appender_end_row); + CTH_DUCK_SYM(duckdb_appender_flush); + CTH_DUCK_SYM(duckdb_appender_close); + CTH_DUCK_SYM(duckdb_appender_destroy); + CTH_DUCK_SYM(duckdb_disconnect); + CTH_DUCK_SYM(duckdb_close); +#undef CTH_DUCK_SYM + return NULL; +} + +static duckdb_state cth_duckdb_create_config(duckdb_config *out) { + return cth_p_duckdb_create_config(out); +} +static duckdb_state cth_duckdb_set_config(duckdb_config config, const char *name, const char *option) { + return cth_p_duckdb_set_config(config, name, option); +} +static void cth_duckdb_destroy_config(duckdb_config *config) { + cth_p_duckdb_destroy_config(config); +} +static duckdb_state cth_duckdb_open_ext(const char *path, duckdb_database *out, duckdb_config config, char **err) { + return cth_p_duckdb_open_ext(path, out, config, err); +} +static void cth_duckdb_free(void *pointer) { + cth_p_duckdb_free(pointer); +} +static duckdb_state cth_duckdb_connect(duckdb_database database, duckdb_connection *out) { + return cth_p_duckdb_connect(database, out); +} +static duckdb_state cth_duckdb_query(duckdb_connection connection, const char *query, duckdb_result *out) { + return cth_p_duckdb_query(connection, query, out); +} +static const char *cth_duckdb_result_error(duckdb_result *result) { + return cth_p_duckdb_result_error(result); +} +static void cth_duckdb_destroy_result(duckdb_result *result) { + cth_p_duckdb_destroy_result(result); +} +static idx_t cth_duckdb_row_count(duckdb_result *result) { + return cth_p_duckdb_row_count(result); +} +static char *cth_duckdb_value_varchar(duckdb_result *result, idx_t column, idx_t row) { + return cth_p_duckdb_value_varchar(result, column, row); +} +static duckdb_state cth_duckdb_appender_create(duckdb_connection connection, const char *schema, const char *table, duckdb_appender *out) { + return cth_p_duckdb_appender_create(connection, schema, table, out); +} +static const char *cth_duckdb_appender_error(duckdb_appender appender) { + return cth_p_duckdb_appender_error(appender); +} +static duckdb_state cth_duckdb_appender_begin_row(duckdb_appender appender) { + return cth_p_duckdb_appender_begin_row(appender); +} +static duckdb_state cth_duckdb_append_int64(duckdb_appender appender, int64_t value) { + return cth_p_duckdb_append_int64(appender, value); +} +static duckdb_state cth_duckdb_append_varchar_length(duckdb_appender appender, const char *text, idx_t length) { + return cth_p_duckdb_append_varchar_length(appender, text, length); +} +static duckdb_value cth_duckdb_create_timestamp_tz(duckdb_timestamp input) { + return cth_p_duckdb_create_timestamp_tz(input); +} +static duckdb_state cth_duckdb_append_value(duckdb_appender appender, duckdb_value value) { + return cth_p_duckdb_append_value(appender, value); +} +static void cth_duckdb_destroy_value(duckdb_value *value) { + cth_p_duckdb_destroy_value(value); +} +static duckdb_state cth_duckdb_append_null(duckdb_appender appender) { + return cth_p_duckdb_append_null(appender); +} +static duckdb_state cth_duckdb_append_bool(duckdb_appender appender, bool value) { + return cth_p_duckdb_append_bool(appender, value); +} +static duckdb_state cth_duckdb_appender_end_row(duckdb_appender appender) { + return cth_p_duckdb_appender_end_row(appender); +} +static duckdb_state cth_duckdb_appender_flush(duckdb_appender appender) { + return cth_p_duckdb_appender_flush(appender); +} +static duckdb_state cth_duckdb_appender_close(duckdb_appender appender) { + return cth_p_duckdb_appender_close(appender); +} +static void cth_duckdb_appender_destroy(duckdb_appender *appender) { + cth_p_duckdb_appender_destroy(appender); +} +static void cth_duckdb_disconnect(duckdb_connection *connection) { + cth_p_duckdb_disconnect(connection); +} +static void cth_duckdb_close(duckdb_database *database) { + cth_p_duckdb_close(database); +} +*/ +import "C" + +import ( + "crypto/rand" + "errors" + "fmt" + "io/fs" + "os" + "strings" + "sync" + "sync/atomic" + "time" + "unsafe" +) + +// This sink uses the system libduckdb C API directly instead of the duckdb-go +// driver: duckdb-go bundles its own engine build, which can write a storage +// format the system duckdb CLI (the tool agents query logs with) cannot +// read, and it inflates the binary by tens of megabytes plus dozens of +// module dependencies for a debug-only sink. The system library always +// matches the same system's CLI, and loading it with dlopen keeps it an +// optional runtime dependency: builds need the duckdb headers (hence the +// duckdb build tag, mirroring brlapi), but the resulting reader starts and +// runs normally on systems without libduckdb, and only --debug-db fails. + +// Rows are buffered in the appender only briefly: a flush happens at +// duckDBFlushRows, on the first record at least duckDBFlushInterval after +// the previous flush, and immediately for WARN and ERROR records so crash +// diagnostics reach the database. A hard crash can still lose the rows +// buffered since the last flush, unlike the file sink, which writes every +// record straight away; the database otherwise trails live activity by +// about a second, so it can be inspected (from a file copy, while the +// reader holds the write lock) during a session. +const ( + duckDBFlushRows = 512 + duckDBFlushInterval = time.Second +) + +var emptyDuckText = C.CString("") + +// Runtime packages install a versioned soname; the unversioned name is the +// development symlink (present in Arch's duckdb package, absent from some +// other distributions' runtime packages). +var duckLibraryCandidates = []string{"libduckdb.so.1", "libduckdb.so"} + +var ( + duckLoadOnce sync.Once + duckLoadErr error +) + +func loadDuckDBLibrary() error { + duckLoadOnce.Do(func() { + var failures []string + for _, candidate := range duckLibraryCandidates { + cname := C.CString(candidate) + message := C.cth_duckdb_load(cname) + C.free(unsafe.Pointer(cname)) + if message == nil { + return + } + failures = append(failures, candidate+": "+C.GoString(message)) + } + duckLoadErr = fmt.Errorf( + "%w: cannot load libduckdb (%s); install the duckdb package to use --debug-db", + ErrDuckDBUnavailable, strings.Join(failures, "; ")) + }) + return duckLoadErr +} + +type duckDBWriter struct { + path string + database C.duckdb_database + conn C.duckdb_connection + appender C.duckdb_appender + sessionID string + seq int64 + pending int + lastFlush time.Time + + mutex sync.Mutex + closeOnce sync.Once + closed bool + writeErr error + closeErr error + cancelled atomic.Bool +} + +// OpenDuckDB opens a DuckDB database at path as a diagnostics sink. Without +// appendExisting, any existing database at path is replaced, mirroring +// OpenFile. With it, existing sessions are kept and this run is recorded as +// a new session row. The sink receives the same redacted NDJSON records as +// the file sink, so redaction in Handler.format protects both. +func OpenDuckDB(path string, appendExisting bool, pid int) (DiagnosticsWriter, error) { + if path == "" || path == "." || path == ".." { + return nil, errors.New("invalid diagnostics database path") + } + // Load before touching the filesystem: without the library we must not + // delete an existing database we then cannot replace. + if err := loadDuckDBLibrary(); err != nil { + return nil, err + } + if info, err := os.Stat(path); err == nil && info.IsDir() { + return nil, fmt.Errorf("diagnostics database path is a directory: %s", path) + } + if !appendExisting { + for _, target := range []string{path, path + ".wal"} { + if err := os.Remove(target); err != nil && !errors.Is(err, fs.ErrNotExist) { + return nil, fmt.Errorf("replace diagnostics database: %w", err) + } + } + } + + sessionID, err := newSessionID() + if err != nil { + return nil, err + } + writer := &duckDBWriter{path: path, sessionID: sessionID} + if err := writer.open(pid); err != nil { + return nil, err + } + return writer, nil +} + +func (writer *duckDBWriter) open(pid int) (err error) { + // Every failure past a successful open must release the handles already + // acquired and leave the writer in the closed state. + defer func() { + if err != nil { + writer.closed = true + writer.teardown() + } + }() + + var config C.duckdb_config + if C.cth_duckdb_create_config(&config) == C.DuckDBError { + return errors.New("create duckdb config") + } + threads := C.CString("threads") + one := C.CString("1") + setState := C.cth_duckdb_set_config(config, threads, one) + C.free(unsafe.Pointer(threads)) + C.free(unsafe.Pointer(one)) + if setState == C.DuckDBError { + C.cth_duckdb_destroy_config(&config) + return errors.New("configure duckdb threads") + } + + cpath := C.CString(writer.path) + var openErr *C.char + state := C.cth_duckdb_open_ext(cpath, &writer.database, config, &openErr) + C.free(unsafe.Pointer(cpath)) + C.cth_duckdb_destroy_config(&config) + if state == C.DuckDBError { + message := C.GoString(openErr) + C.cth_duckdb_free(unsafe.Pointer(openErr)) + return fmt.Errorf("open diagnostics database: %s", message) + } + + // DuckDB creates the file with process umask permissions and rejects a + // pre-created empty file, so restrict it immediately: debug records can + // contain spoken text and the file sink creates its log at 0600. + if chmodErr := os.Chmod(writer.path, 0o600); chmodErr != nil { + return fmt.Errorf("restrict diagnostics database permissions: %w", chmodErr) + } + + if C.cth_duckdb_connect(writer.database, &writer.conn) == C.DuckDBError { + return errors.New("connect diagnostics database") + } + for _, statement := range []string{duckDBCreateMeta, duckDBCreateSessions, duckDBCreateLogs} { + if execErr := duckExec(writer.conn, statement); execErr != nil { + return execErr + } + } + version, found, queryErr := duckQueryVarchar(writer.conn, + "SELECT value FROM meta WHERE key = 'schema_version'") + if queryErr != nil { + return queryErr + } + if found && version == duckDBSchemaVersionV1 { + // v1 stored every attribute in attrs only. Append the promoted + // columns (existing rows read NULL there; nothing is lost because + // attrs is complete) and restamp the version. + for _, attr := range promotedAttrs { + statement := fmt.Sprintf("ALTER TABLE logs ADD COLUMN IF NOT EXISTS \"%s\" %s", attr.key, attr.sqlType()) + if execErr := duckExec(writer.conn, statement); execErr != nil { + return execErr + } + } + if execErr := duckExec(writer.conn, + "UPDATE meta SET value = '"+duckDBSchemaVersion+"' WHERE key = 'schema_version'"); execErr != nil { + return execErr + } + } else if found && version != duckDBSchemaVersion { + return fmt.Errorf("unsupported diagnostics database schema version %q (want %q); use a new file or omit --append", + version, duckDBSchemaVersion) + } + if !found { + for _, statement := range []string{ + "INSERT INTO meta VALUES ('format', 'cthulhu-debug-log') ON CONFLICT DO NOTHING", + "INSERT INTO meta VALUES ('schema_version', '" + duckDBSchemaVersion + "') ON CONFLICT DO NOTHING", + } { + if execErr := duckExec(writer.conn, statement); execErr != nil { + return execErr + } + } + } + // sessionID is generated by newSessionID from random bytes (hex and + // dashes only) and the timestamp is RFC3339, so both are safe SQL + // literal content. + insertSession := fmt.Sprintf( + "INSERT INTO sessions VALUES ('%s', TIMESTAMPTZ '%s', %d)", + writer.sessionID, time.Now().UTC().Format(time.RFC3339Nano), pid) + if execErr := duckExec(writer.conn, insertSession); execErr != nil { + return execErr + } + + table := C.CString("logs") + state = C.cth_duckdb_appender_create(writer.conn, nil, table, &writer.appender) + C.free(unsafe.Pointer(table)) + if state == C.DuckDBError { + return fmt.Errorf("create diagnostics appender: %s", duckAppenderError(writer.appender)) + } + writer.lastFlush = time.Now() + // Schema and session setup already wrote through the WAL; restrict it + // now rather than waiting for the first flush. + _ = os.Chmod(writer.path+".wal", 0o600) + return nil +} + +func (writer *duckDBWriter) Write(data []byte) (int, error) { + writer.mutex.Lock() + defer writer.mutex.Unlock() + if writer.closed || writer.cancelled.Load() { + return 0, fmt.Errorf("write diagnostics database: %w", fs.ErrClosed) + } + if writer.writeErr != nil { + return 0, writer.writeErr + } + record, ok := parseLogRecord(data) + if !ok { + // The formatter is the only producer, so this should not happen; + // keep the raw record rather than silently dropping it. + record = parsedRecord{ + timestamp: time.Now(), + level: "UNKNOWN", + message: strings.TrimRight(string(data), "\n"), + attrs: "{}", + } + } + if err := writer.appendRecord(record); err != nil { + writer.writeErr = err + return 0, err + } + writer.pending++ + if writer.pending >= duckDBFlushRows || record.level == "WARN" || record.level == "ERROR" || + time.Since(writer.lastFlush) >= duckDBFlushInterval { + if err := writer.flushLocked(); err != nil { + writer.writeErr = err + return 0, err + } + } + return len(data), nil +} + +// appendRecord appends one row in logs table column order. +func (writer *duckDBWriter) appendRecord(record parsedRecord) error { + writer.seq++ + app := writer.appender + if C.cth_duckdb_appender_begin_row(app) == C.DuckDBError { + return writer.appendError("begin row") + } + if C.cth_duckdb_append_int64(app, C.int64_t(writer.seq)) == C.DuckDBError { + return writer.appendError("append seq") + } + if duckAppendText(app, writer.sessionID) == C.DuckDBError { + return writer.appendError("append session_id") + } + timestamp := C.duckdb_timestamp{micros: C.int64_t(record.timestamp.UnixMicro())} + value := C.cth_duckdb_create_timestamp_tz(timestamp) + state := C.cth_duckdb_append_value(app, value) + C.cth_duckdb_destroy_value(&value) + if state == C.DuckDBError { + return writer.appendError("append ts") + } + for _, field := range []struct { + name string + text string + }{ + {"level", record.level}, + {"message", record.message}, + } { + if duckAppendText(app, field.text) == C.DuckDBError { + return writer.appendError("append " + field.name) + } + } + for _, field := range []struct { + name string + text string + }{ + {"source", record.source}, + {"function", record.function}, + } { + if field.text == "" { + if C.cth_duckdb_append_null(app) == C.DuckDBError { + return writer.appendError("append " + field.name) + } + continue + } + if duckAppendText(app, field.text) == C.DuckDBError { + return writer.appendError("append " + field.name) + } + } + if duckAppendText(app, record.attrs) == C.DuckDBError { + return writer.appendError("append attrs") + } + for i, attr := range promotedAttrs { + var value promotedValue + if i < len(record.promoted) { + value = record.promoted[i] + } + if !value.valid { + if C.cth_duckdb_append_null(app) == C.DuckDBError { + return writer.appendError("append " + attr.key) + } + continue + } + var state C.duckdb_state + switch attr.kind { + case promotedText: + state = duckAppendText(app, value.text) + case promotedInt: + state = C.cth_duckdb_append_int64(app, C.int64_t(value.integer)) + case promotedBool: + state = C.cth_duckdb_append_bool(app, C.bool(value.boolean)) + } + if state == C.DuckDBError { + return writer.appendError("append " + attr.key) + } + } + if C.cth_duckdb_appender_end_row(app) == C.DuckDBError { + return writer.appendError("end row") + } + return nil +} + +func (writer *duckDBWriter) appendError(step string) error { + return fmt.Errorf("write diagnostics database (%s): %s", step, duckAppenderError(writer.appender)) +} + +func (writer *duckDBWriter) flushLocked() error { + if C.cth_duckdb_appender_flush(writer.appender) == C.DuckDBError { + return fmt.Errorf("flush diagnostics database: %s", duckAppenderError(writer.appender)) + } + writer.pending = 0 + writer.lastFlush = time.Now() + // The write-ahead log holds recent records until checkpoint; restrict it + // too whenever it exists. Best effort: DuckDB may not have created it. + _ = os.Chmod(writer.path+".wal", 0o600) + return nil +} + +// Cancel flags the sink cancelled and returns immediately. Diagnostics.Stop +// calls Cancel synchronously while enforcing its deadline, so it must never +// wait for an in-flight appender call or run the closing flush/checkpoint; +// that teardown belongs to Close, which the diagnostics writer goroutine +// calls after its queue drains. This mirrors fileWriter, whose Cancel is a +// bare file close that never waits for an in-flight Write. +func (writer *duckDBWriter) Cancel() error { + writer.cancelled.Store(true) + return nil +} + +func (writer *duckDBWriter) Close() error { + writer.closeOnce.Do(func() { + writer.mutex.Lock() + defer writer.mutex.Unlock() + writer.closed = true + if writer.appender != nil && C.cth_duckdb_appender_close(writer.appender) == C.DuckDBError { + writer.closeErr = fmt.Errorf("close diagnostics appender: %s", + duckAppenderError(writer.appender)) + } + writer.teardown() + }) + return writer.closeErr +} + +// teardown releases any handles still held, in reverse acquisition order. +// Callers outside open must hold the mutex. +func (writer *duckDBWriter) teardown() { + if writer.appender != nil { + C.cth_duckdb_appender_destroy(&writer.appender) + } + if writer.conn != nil { + C.cth_duckdb_disconnect(&writer.conn) + } + if writer.database != nil { + C.cth_duckdb_close(&writer.database) + } +} + +func duckExec(conn C.duckdb_connection, sql string) error { + csql := C.CString(sql) + defer C.free(unsafe.Pointer(csql)) + var result C.duckdb_result + if C.cth_duckdb_query(conn, csql, &result) == C.DuckDBError { + message := C.GoString(C.cth_duckdb_result_error(&result)) + C.cth_duckdb_destroy_result(&result) + return fmt.Errorf("diagnostics database statement: %s", message) + } + C.cth_duckdb_destroy_result(&result) + return nil +} + +func duckQueryVarchar(conn C.duckdb_connection, sql string) (string, bool, error) { + csql := C.CString(sql) + defer C.free(unsafe.Pointer(csql)) + var result C.duckdb_result + if C.cth_duckdb_query(conn, csql, &result) == C.DuckDBError { + message := C.GoString(C.cth_duckdb_result_error(&result)) + C.cth_duckdb_destroy_result(&result) + return "", false, fmt.Errorf("diagnostics database query: %s", message) + } + defer C.cth_duckdb_destroy_result(&result) + if C.cth_duckdb_row_count(&result) == 0 { + return "", false, nil + } + text := C.cth_duckdb_value_varchar(&result, 0, 0) + value := C.GoString(text) + C.cth_duckdb_free(unsafe.Pointer(text)) + return value, true, nil +} + +func duckAppendText(app C.duckdb_appender, text string) C.duckdb_state { + if len(text) == 0 { + return C.cth_duckdb_append_varchar_length(app, emptyDuckText, 0) + } + // The length variant preserves embedded NUL bytes that JSON decoding can + // legitimately produce ("\u0000"); the NUL-terminated variant truncates. + state := C.cth_duckdb_append_varchar_length( + app, (*C.char)(unsafe.Pointer(unsafe.StringData(text))), C.idx_t(len(text))) + // StringData must stay live across the call above. + _ = text + return state +} + +func duckAppenderError(app C.duckdb_appender) string { + if app == nil { + return "unknown error" + } + return C.GoString(C.cth_duckdb_appender_error(app)) +} + +func newSessionID() (string, error) { + var raw [16]byte + if _, err := rand.Read(raw[:]); err != nil { + return "", fmt.Errorf("generate diagnostics session id: %w", err) + } + raw[6] = raw[6]&0x0f | 0x40 + raw[8] = raw[8]&0x3f | 0x80 + return fmt.Sprintf("%x-%x-%x-%x-%x", raw[0:4], raw[4:6], raw[6:8], raw[8:10], raw[10:16]), nil +} diff --git a/internal/logging/duckdb_native_test.go b/internal/logging/duckdb_native_test.go new file mode 100644 index 0000000..95681d2 --- /dev/null +++ b/internal/logging/duckdb_native_test.go @@ -0,0 +1,318 @@ +//go:build duckdb && cgo + +// Cthulhu screen reader. +// Copyright (c) 2026 Storm Dragon +// Authors: Storm Dragon, Angus Kola +// +// This program is free software: you can redistribute it and/or modify it +// under the terms of the GNU General Public License as published by the Free +// Software Foundation, either version 3 of the License, or (at your option) +// any later version. +// +// This program is distributed in the hope that it will be useful, but WITHOUT +// ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or +// FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for +// more details. +// +// You should have received a copy of the GNU General Public License along with +// this program. If not, see . + +package logging + +import ( + "errors" + "io/fs" + "os" + "os/exec" + "path/filepath" + "strings" + "testing" + "time" +) + +const ( + duckTestLineInfo = `{"message":"starting Cthulhu","level":"INFO","source":"/srv/cthulhu/cmd/cthulhu/main.go:201","function":"main.run","pid":42,"time":"2026-11-04T03:58:47.316096257-05:00"}` + "\n" + duckTestLineDup = `{"message":"document navigation completed","level":"DEBUG","source":"/srv/cthulhu/internal/app/document_review.go:319","function":"example.present","level":3,"role":"heading","time":"2026-11-04T04:01:02.5-05:00"}` + "\n" + duckTestLineErr = `{"message":"speech delivery failed","level":"ERROR","source":"/srv/cthulhu/internal/app/speech.go:9","function":"example.deliver","error":"socket closed","time":"2026-11-04T04:02:03-05:00"}` + "\n" +) + +func duckQuery(t *testing.T, path, query string) string { + t.Helper() + cli, err := exec.LookPath("duckdb") + if err != nil { + t.Skip("duckdb CLI not installed; cannot verify queryability") + } + output, err := exec.Command(cli, "-readonly", "-noheader", "-list", path, "-c", query).CombinedOutput() + if err != nil { + t.Fatalf("duckdb query %q: %v\n%s", query, err, output) + } + return strings.TrimSpace(string(output)) +} + +func TestDuckDBSinkStoresQueryableRecords(t *testing.T) { + path := filepath.Join(t.TempDir(), "debug.duckdb") + writer, err := OpenDuckDB(path, false, 4242) + if err != nil { + t.Fatal(err) + } + for _, line := range []string{duckTestLineInfo, duckTestLineDup, duckTestLineErr, "not a formatted record\n"} { + if _, err := writer.Write([]byte(line)); err != nil { + t.Fatalf("Write %q: %v", line, err) + } + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + if _, err := writer.Write([]byte(duckTestLineInfo)); !errors.Is(err, fs.ErrClosed) { + t.Fatalf("write after close error = %v, want fs.ErrClosed", err) + } + info, err := os.Stat(path) + if err != nil { + t.Fatal(err) + } + if info.Mode().Perm() != 0o600 { + t.Fatalf("database permissions = %o, want 600", info.Mode().Perm()) + } + + if got := duckQuery(t, path, "SELECT count(*) FROM logs"); got != "4" { + t.Fatalf("log rows = %s, want 4", got) + } + if got := duckQuery(t, path, + "SELECT level FROM logs WHERE message = 'document navigation completed'"); got != "DEBUG" { + t.Fatalf("typed level = %s, want DEBUG", got) + } + if got := duckQuery(t, path, + "SELECT attrs->>'$.level' FROM logs WHERE message = 'document navigation completed'"); got != "3" { + t.Fatalf("attrs level = %s, want 3", got) + } + if got := duckQuery(t, path, + "SELECT attrs->>'$.error' FROM logs WHERE level = 'ERROR'"); got != "socket closed" { + t.Fatalf("attrs error = %s", got) + } + // The unformatted line must be preserved, not dropped. + if got := duckQuery(t, path, "SELECT message FROM logs WHERE level = 'UNKNOWN'"); got != "not a formatted record" { + t.Fatalf("fallback message = %q", got) + } + if got := duckQuery(t, path, + "SELECT count(DISTINCT session_id) || '|' || min(seq) || '|' || max(seq) FROM logs"); got != "1|1|4" { + t.Fatalf("session/seq = %s, want 1|1|4", got) + } + if got := duckQuery(t, path, "SELECT pid FROM sessions"); got != "4242" { + t.Fatalf("session pid = %s", got) + } + if got := duckQuery(t, path, "SELECT value FROM meta WHERE key = 'schema_version'"); got != duckDBSchemaVersion { + t.Fatalf("schema_version = %s", got) + } + // Timestamps are real TIMESTAMPTZ values that support range filters. + if got := duckQuery(t, path, + "SELECT count(*) FROM logs WHERE level != 'UNKNOWN' AND ts >= TIMESTAMPTZ '2026-11-04 04:00:00-05:00'"); got != "2" { + t.Fatalf("range-filtered rows = %s, want 2", got) + } +} + +func TestDuckDBSinkAppendsSessionsAndReplaces(t *testing.T) { + path := filepath.Join(t.TempDir(), "debug.duckdb") + write := func(appendExisting bool, line string) { + t.Helper() + writer, err := OpenDuckDB(path, appendExisting, 7) + if err != nil { + t.Fatal(err) + } + if _, err := writer.Write([]byte(line)); err != nil { + t.Fatal(err) + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + } + + write(false, duckTestLineInfo) + write(true, duckTestLineErr) + if got := duckQuery(t, path, "SELECT count(*) || '|' || count(DISTINCT session_id) FROM logs"); got != "2|2" { + t.Fatalf("after append rows|sessions = %s, want 2|2", got) + } + // Each session restarts its own sequence. + if got := duckQuery(t, path, "SELECT count(*) FROM logs WHERE seq = 1"); got != "2" { + t.Fatalf("seq=1 rows = %s, want 2", got) + } + + write(false, duckTestLineDup) + if got := duckQuery(t, path, "SELECT count(*) || '|' || count(DISTINCT session_id) FROM logs"); got != "1|1" { + t.Fatalf("after replace rows|sessions = %s, want 1|1", got) + } +} + +func TestDuckDBSinkRejectsDirectoryAndForeignFile(t *testing.T) { + if _, err := OpenDuckDB(t.TempDir(), false, 1); err == nil { + t.Fatal("directory path accepted") + } + foreign := filepath.Join(t.TempDir(), "foreign.duckdb") + if err := os.WriteFile(foreign, []byte("not a duckdb database"), 0o600); err != nil { + t.Fatal(err) + } + if _, err := OpenDuckDB(foreign, true, 1); err == nil { + t.Fatal("foreign file accepted in append mode") + } + // Replace mode discards the foreign file, mirroring OpenFile truncation. + writer, err := OpenDuckDB(foreign, false, 1) + if err != nil { + t.Fatal(err) + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } +} + +// At idle record rates the row-count threshold alone would leave the +// database empty for minutes; a record arriving after the flush interval +// must flush everything buffered so far. +func TestDuckDBSinkFlushesAfterInterval(t *testing.T) { + path := filepath.Join(t.TempDir(), "debug.duckdb") + sink, err := OpenDuckDB(path, false, 7) + if err != nil { + t.Fatal(err) + } + writer := sink.(*duckDBWriter) + if wal, err := os.Stat(path + ".wal"); err == nil && wal.Mode().Perm() != 0o600 { + t.Fatalf("wal permissions at open = %o, want 600", wal.Mode().Perm()) + } + if _, err := writer.Write([]byte(duckTestLineInfo)); err != nil { + t.Fatal(err) + } + if writer.pending != 1 { + t.Fatalf("pending after one INFO record = %d, want 1 (buffered)", writer.pending) + } + writer.lastFlush = time.Now().Add(-2 * duckDBFlushInterval) + if _, err := writer.Write([]byte(duckTestLineDup)); err != nil { + t.Fatal(err) + } + if writer.pending != 0 { + t.Fatalf("pending after interval record = %d, want 0 (flushed)", writer.pending) + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + if got := duckQuery(t, path, "SELECT count(*) FROM logs"); got != "2" { + t.Fatalf("log rows = %s, want 2", got) + } +} + +func duckExecCLI(t *testing.T, path, statement string) { + t.Helper() + cli, err := exec.LookPath("duckdb") + if err != nil { + t.Skip("duckdb CLI not installed; cannot prepare fixture database") + } + if output, err := exec.Command(cli, path, "-c", statement).CombinedOutput(); err != nil { + t.Fatalf("duckdb exec %q: %v\n%s", statement, err, output) + } +} + +// Promoted attributes must land in typed columns (queryable without JSON +// extraction or casts) while remaining in attrs. +func TestDuckDBSinkPromotedColumns(t *testing.T) { + path := filepath.Join(t.TempDir(), "debug.duckdb") + writer, err := OpenDuckDB(path, false, 7) + if err != nil { + t.Fatal(err) + } + for _, line := range []string{duckTestLineInfo, duckTestLineDup, duckTestLineErr} { + if _, err := writer.Write([]byte(line)); err != nil { + t.Fatal(err) + } + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + if got := duckQuery(t, path, + "SELECT role FROM logs WHERE message = 'document navigation completed'"); got != "heading" { + t.Fatalf("promoted role = %s, want heading", got) + } + if got := duckQuery(t, path, + "SELECT error FROM logs WHERE level = 'ERROR'"); got != "socket closed" { + t.Fatalf("promoted error = %s, want socket closed", got) + } + if got := duckQuery(t, path, + "SELECT count(*) FROM logs WHERE role IS NULL"); got != "2" { + t.Fatalf("null-role rows = %s, want 2", got) + } + // Column types are honest SQL types, not text. + if got := duckQuery(t, path, + "SELECT data_type FROM information_schema.columns WHERE table_name = 'logs' AND column_name = 'snapshot_duration'"); got != "BIGINT" { + t.Fatalf("snapshot_duration type = %s, want BIGINT", got) + } + if got := duckQuery(t, path, + "SELECT data_type FROM information_schema.columns WHERE table_name = 'logs' AND column_name = 'focused'"); got != "BOOLEAN" { + t.Fatalf("focused type = %s, want BOOLEAN", got) + } +} + +// A v1 database (envelope columns and attrs only) must upgrade in place on +// append: existing rows keep their attrs and read NULL in the new columns. +func TestDuckDBSinkUpgradesV1Database(t *testing.T) { + path := filepath.Join(t.TempDir(), "debug.duckdb") + duckExecCLI(t, path, ` + CREATE TABLE meta (key VARCHAR PRIMARY KEY, value VARCHAR NOT NULL); + INSERT INTO meta VALUES ('format', 'cthulhu-debug-log'), ('schema_version', '1'); + CREATE TABLE sessions (session_id VARCHAR PRIMARY KEY, started_at TIMESTAMPTZ NOT NULL, pid BIGINT NOT NULL); + INSERT INTO sessions VALUES ('old-session', TIMESTAMPTZ '2026-11-04 03:58:47-05:00', 99); + CREATE TABLE logs (seq BIGINT NOT NULL, session_id VARCHAR NOT NULL, ts TIMESTAMPTZ NOT NULL, + level VARCHAR NOT NULL, message VARCHAR NOT NULL, source VARCHAR, function VARCHAR, attrs JSON NOT NULL); + INSERT INTO logs VALUES (1, 'old-session', TIMESTAMPTZ '2026-11-04 03:58:47-05:00', + 'DEBUG', 'document navigation completed', NULL, NULL, '{"role":"heading"}'); + `) + writer, err := OpenDuckDB(path, true, 7) + if err != nil { + t.Fatal(err) + } + if _, err := writer.Write([]byte(duckTestLineDup)); err != nil { + t.Fatal(err) + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + if got := duckQuery(t, path, "SELECT value FROM meta WHERE key = 'schema_version'"); got != duckDBSchemaVersion { + t.Fatalf("schema_version after upgrade = %s, want %s", got, duckDBSchemaVersion) + } + if got := duckQuery(t, path, + "SELECT role || '|' || (attrs->>'$.role') FROM logs WHERE session_id != 'old-session'"); got != "heading|heading" { + t.Fatalf("new row role column|attrs = %s", got) + } + if got := duckQuery(t, path, + "SELECT (role IS NULL) || '|' || (attrs->>'$.role') FROM logs WHERE session_id = 'old-session'"); got != "true|heading" { + t.Fatalf("old row role-null|attrs = %s, want true|heading", got) + } +} + +// Cancel is called synchronously by Diagnostics.Stop while it enforces its +// deadline, so it must only flag cancellation and return at once; records +// already appended are still flushed by the Close that follows. +func TestDuckDBSinkCancelIsNonBlocking(t *testing.T) { + path := filepath.Join(t.TempDir(), "debug.duckdb") + writer, err := OpenDuckDB(path, false, 7) + if err != nil { + t.Fatal(err) + } + if _, err := writer.Write([]byte(duckTestLineInfo)); err != nil { + t.Fatal(err) + } + done := make(chan error, 1) + go func() { done <- writer.Cancel() }() + select { + case err := <-done: + if err != nil { + t.Fatal(err) + } + case <-time.After(5 * time.Second): + t.Fatal("Cancel blocked") + } + if _, err := writer.Write([]byte(duckTestLineDup)); !errors.Is(err, fs.ErrClosed) { + t.Fatalf("write after cancel error = %v, want fs.ErrClosed", err) + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + if got := duckQuery(t, path, "SELECT count(*) FROM logs"); got != "1" { + t.Fatalf("log rows = %s, want 1 (pre-cancel record flushed by Close)", got) + } +} diff --git a/internal/logging/duckdb_test.go b/internal/logging/duckdb_test.go new file mode 100644 index 0000000..f1b580a --- /dev/null +++ b/internal/logging/duckdb_test.go @@ -0,0 +1,228 @@ +// Cthulhu screen reader. +// Copyright (c) 2026 Storm Dragon +// Authors: Storm Dragon, Angus Kola +// +// This program is free software: you can redistribute it and/or modify it +// under the terms of the GNU General Public License as published by the Free +// Software Foundation, either version 3 of the License, or (at your option) +// any later version. +// +// This program is distributed in the hope that it will be useful, but WITHOUT +// ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or +// FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for +// more details. +// +// You should have received a copy of the GNU General Public License along with +// this program. If not, see . + +package logging + +import ( + "encoding/json" + "errors" + "strings" + "testing" + "time" +) + +func TestParseLogRecordSplitsTypedColumnsAndAttrs(t *testing.T) { + line := []byte(`{"message":"starting Cthulhu","level":"INFO","source":"/srv/cthulhu/cmd/cthulhu/main.go:201","function":"main.run","pid":259626,"build":{"go_version":"go1.27"},"x11_display_available":true,"time":"2026-11-04T03:58:47.316096257-05:00"}` + "\n") + + record, ok := parseLogRecord(line) + if !ok { + t.Fatal("record did not parse") + } + if record.message != "starting Cthulhu" || record.level != "INFO" { + t.Fatalf("message/level = %q/%q", record.message, record.level) + } + if record.source != "/srv/cthulhu/cmd/cthulhu/main.go:201" || record.function != "main.run" { + t.Fatalf("source/function = %q/%q", record.source, record.function) + } + wantTime, err := time.Parse(time.RFC3339Nano, "2026-11-04T03:58:47.316096257-05:00") + if err != nil { + t.Fatal(err) + } + if !record.timestamp.Equal(wantTime) { + t.Fatalf("timestamp = %v, want %v", record.timestamp, wantTime) + } + var attrs map[string]json.RawMessage + if err := json.Unmarshal([]byte(record.attrs), &attrs); err != nil { + t.Fatalf("attrs is not a JSON object: %v (%s)", err, record.attrs) + } + if string(attrs["pid"]) != "259626" || string(attrs["build"]) != `{"go_version":"go1.27"}` || + string(attrs["x11_display_available"]) != "true" { + t.Fatalf("attrs = %s", record.attrs) + } + for _, reserved := range []string{"message", "level", "source", "function", "time"} { + if _, present := attrs[reserved]; present { + t.Fatalf("reserved key %q leaked into attrs: %s", reserved, record.attrs) + } + } +} + +// Some records carry an attribute that reuses a reserved name with a +// different type (an integer heading "level", for example). The formatter +// emits its own level first, so the typed column keeps the string level and +// the attribute lands in attrs. +func TestParseLogRecordDuplicateReservedAttrGoesToAttrs(t *testing.T) { + line := []byte(`{"message":"document navigation completed","level":"DEBUG","source":"/srv/cthulhu/internal/app/document_review.go:319","function":"example.present","level":3,"role":"heading","time":"2026-11-04T04:01:02.5-05:00"}` + "\n") + + record, ok := parseLogRecord(line) + if !ok { + t.Fatal("record did not parse") + } + if record.level != "DEBUG" { + t.Fatalf("level = %q, want DEBUG", record.level) + } + var attrs map[string]json.RawMessage + if err := json.Unmarshal([]byte(record.attrs), &attrs); err != nil { + t.Fatal(err) + } + if string(attrs["level"]) != "3" || string(attrs["role"]) != `"heading"` { + t.Fatalf("attrs = %s", record.attrs) + } +} + +func TestParseLogRecordRejectsMalformedLines(t *testing.T) { + for name, line := range map[string]string{ + "empty": "", + "not json": "starting Cthulhu\n", + "array": `[{"message":"m"}]` + "\n", + "missing time": `{"message":"m","level":"INFO"}` + "\n", + "missing message": `{"level":"INFO","time":"2026-11-04T03:58:47Z"}` + "\n", + "numeric level": `{"message":"m","level":1,"time":"2026-11-04T03:58:47Z"}` + "\n", + "bad time": `{"message":"m","level":"INFO","time":"not-a-time"}` + "\n", + "trailing garbage": `{"message":"m","level":"INFO","time":"2026-11-04T03:58:47Z"} extra` + "\n", + "unclosed": `{"message":"m","level":"INFO"` + "\n", + } { + if _, ok := parseLogRecord([]byte(line)); ok { + t.Errorf("%s: parsed unexpectedly", name) + } + } +} + +func promotedByKey(record parsedRecord, key string) promotedValue { + for i, attr := range promotedAttrs { + if attr.key == key && i < len(record.promoted) { + return record.promoted[i] + } + } + return promotedValue{} +} + +func TestParseLogRecordPromotesTypedAttrs(t *testing.T) { + line := []byte(`{"message":"received accessibility event","level":"DEBUG","source":"s:1","function":"f","role":"heading","snapshot_duration":12345,"focused":true,"error":null,"selection_start":"3","custom_thing":{"nested":1},"time":"2026-11-04T03:58:47Z"}` + "\n") + + record, ok := parseLogRecord(line) + if !ok { + t.Fatal("record did not parse") + } + if got := promotedByKey(record, "role"); !got.valid || got.text != "heading" { + t.Fatalf("role = %+v", got) + } + if got := promotedByKey(record, "snapshot_duration"); !got.valid || got.integer != 12345 { + t.Fatalf("snapshot_duration = %+v", got) + } + if got := promotedByKey(record, "focused"); !got.valid || !got.boolean { + t.Fatalf("focused = %+v", got) + } + // JSON null and wrong-typed values stay out of the typed columns but + // remain in attrs. + if got := promotedByKey(record, "error"); got.valid { + t.Fatalf("error = %+v, want invalid for null", got) + } + if got := promotedByKey(record, "selection_start"); got.valid { + t.Fatalf("selection_start = %+v, want invalid for string in int column", got) + } + if got := promotedByKey(record, "application"); got.valid { + t.Fatalf("application = %+v, want invalid when absent", got) + } + var attrs map[string]json.RawMessage + if err := json.Unmarshal([]byte(record.attrs), &attrs); err != nil { + t.Fatal(err) + } + if string(attrs["selection_start"]) != `"3"` || string(attrs["custom_thing"]) != `{"nested":1}` || + string(attrs["role"]) != `"heading"` { + t.Fatalf("attrs lost data: %s", record.attrs) + } +} + +// The formatter emits its timestamp last, after record attributes. An +// attribute also named "time" must land in attrs and never steal the ts +// column or sink the whole record to the fallback row. +func TestParseLogRecordTimeAttrDoesNotStealTimestamp(t *testing.T) { + for name, attr := range map[string]string{ + "numeric attr": `123`, + "rfc3339 attr": `"1999-01-01T00:00:00Z"`, + "garbage attr": `"not-a-time"`, + } { + line := []byte(`{"message":"m","level":"INFO","source":"s:1","function":"f","time":` + attr + + `,"role":"heading","time":"2026-11-04T03:58:47Z"}` + "\n") + record, ok := parseLogRecord(line) + if !ok { + t.Fatalf("%s: record did not parse", name) + } + want, err := time.Parse(time.RFC3339Nano, "2026-11-04T03:58:47Z") + if err != nil { + t.Fatal(err) + } + if !record.timestamp.Equal(want) { + t.Fatalf("%s: timestamp = %v, want %v", name, record.timestamp, want) + } + var attrs map[string]json.RawMessage + if err := json.Unmarshal([]byte(record.attrs), &attrs); err != nil { + t.Fatal(err) + } + if string(attrs["time"]) != attr { + t.Fatalf("%s: attrs time = %s, want %s", name, attrs["time"], attr) + } + if got := promotedByKey(record, "role"); !got.valid || got.text != "heading" { + t.Fatalf("%s: promoted role = %+v", name, got) + } + } +} + +type recordingSink struct { + writes [][]byte + writeErr error + cancels int + closes int +} + +func (sink *recordingSink) Write(data []byte) (int, error) { + sink.writes = append(sink.writes, append([]byte(nil), data...)) + return len(data), sink.writeErr +} + +func (sink *recordingSink) Cancel() error { sink.cancels++; return nil } +func (sink *recordingSink) Close() error { sink.closes++; return nil } + +func TestMultiWriterFansOutDespiteFailure(t *testing.T) { + failing := &recordingSink{writeErr: errors.New("sink failed")} + healthy := &recordingSink{} + writer := NewMultiWriter(failing, healthy) + + line := []byte("{\"message\":\"m\"}\n") + if _, err := writer.Write(line); err == nil || !strings.Contains(err.Error(), "sink failed") { + t.Fatalf("Write error = %v", err) + } + if len(failing.writes) != 1 || len(healthy.writes) != 1 { + t.Fatalf("writes = %d/%d, want both sinks served", len(failing.writes), len(healthy.writes)) + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + if failing.closes != 1 || healthy.closes != 1 { + t.Fatalf("closes = %d/%d", failing.closes, healthy.closes) + } +} + +func TestMultiWriterPassesThroughSingleSink(t *testing.T) { + sink := &recordingSink{} + if got := NewMultiWriter(sink); got != DiagnosticsWriter(sink) { + t.Fatalf("single sink wrapped: %T", got) + } + if got := NewMultiWriter(); got == nil { + t.Fatal("empty multi writer is nil") + } +} diff --git a/internal/logging/duckdb_unavailable.go b/internal/logging/duckdb_unavailable.go new file mode 100644 index 0000000..77a1a4a --- /dev/null +++ b/internal/logging/duckdb_unavailable.go @@ -0,0 +1,25 @@ +//go:build !duckdb || !cgo + +// Cthulhu screen reader. +// Copyright (c) 2026 Storm Dragon +// Authors: Storm Dragon, Angus Kola +// +// This program is free software: you can redistribute it and/or modify it +// under the terms of the GNU General Public License as published by the Free +// Software Foundation, either version 3 of the License, or (at your option) +// any later version. +// +// This program is distributed in the hope that it will be useful, but WITHOUT +// ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or +// FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for +// more details. +// +// You should have received a copy of the GNU General Public License along with +// this program. If not, see . + +package logging + +// OpenDuckDB is provided by duckdb_native.go in builds with -tags duckdb. +func OpenDuckDB(_ string, _ bool, _ int) (DiagnosticsWriter, error) { + return nil, ErrDuckDBUnavailable +} diff --git a/internal/logging/duckdb_unavailable_test.go b/internal/logging/duckdb_unavailable_test.go new file mode 100644 index 0000000..7407eaa --- /dev/null +++ b/internal/logging/duckdb_unavailable_test.go @@ -0,0 +1,36 @@ +//go:build !duckdb || !cgo + +// Cthulhu screen reader. +// Copyright (c) 2026 Storm Dragon +// Authors: Storm Dragon, Angus Kola +// +// This program is free software: you can redistribute it and/or modify it +// under the terms of the GNU General Public License as published by the Free +// Software Foundation, either version 3 of the License, or (at your option) +// any later version. +// +// This program is distributed in the hope that it will be useful, but WITHOUT +// ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or +// FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for +// more details. +// +// You should have received a copy of the GNU General Public License along with +// this program. If not, see . + +package logging + +import ( + "errors" + "path/filepath" + "testing" +) + +func TestOpenDuckDBUnavailableWithoutBuildTag(t *testing.T) { + writer, err := OpenDuckDB(filepath.Join(t.TempDir(), "debug.duckdb"), false, 1) + if writer != nil { + t.Fatalf("writer = %v, want nil", writer) + } + if !errors.Is(err, ErrDuckDBUnavailable) { + t.Fatalf("error = %v, want ErrDuckDBUnavailable", err) + } +}