335 lines
9.9 KiB
Go
335 lines
9.9 KiB
Go
// 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 <https://www.gnu.org/licenses/gpl-3.0.html>.
|
|
|
|
package logging
|
|
|
|
import (
|
|
"bytes"
|
|
"context"
|
|
"encoding/json"
|
|
"errors"
|
|
"fmt"
|
|
"io"
|
|
"log/slog"
|
|
"os"
|
|
"path/filepath"
|
|
"strings"
|
|
"sync"
|
|
"testing"
|
|
"time"
|
|
)
|
|
|
|
type controlledWriter struct {
|
|
mutex sync.Mutex
|
|
output bytes.Buffer
|
|
started chan struct{}
|
|
startOnce sync.Once
|
|
release chan struct{}
|
|
canceled chan struct{}
|
|
cancelOnce sync.Once
|
|
writeError error
|
|
autoRelease bool
|
|
closed bool
|
|
}
|
|
|
|
func newControlledWriter() *controlledWriter {
|
|
return &controlledWriter{
|
|
started: make(chan struct{}),
|
|
release: make(chan struct{}, 1),
|
|
canceled: make(chan struct{}),
|
|
}
|
|
}
|
|
|
|
func (writer *controlledWriter) Write(data []byte) (int, error) {
|
|
writer.startOnce.Do(func() { close(writer.started) })
|
|
select {
|
|
case <-writer.release:
|
|
case <-writer.canceled:
|
|
return 0, errors.New("diagnostics writer canceled")
|
|
}
|
|
if writer.autoRelease {
|
|
select {
|
|
case writer.release <- struct{}{}:
|
|
default:
|
|
}
|
|
}
|
|
writer.mutex.Lock()
|
|
defer writer.mutex.Unlock()
|
|
if writer.writeError != nil {
|
|
return 0, writer.writeError
|
|
}
|
|
return writer.output.Write(data)
|
|
}
|
|
|
|
func (writer *controlledWriter) Cancel() error {
|
|
writer.cancelOnce.Do(func() { close(writer.canceled) })
|
|
return nil
|
|
}
|
|
|
|
func (writer *controlledWriter) Close() error {
|
|
writer.mutex.Lock()
|
|
defer writer.mutex.Unlock()
|
|
writer.closed = true
|
|
return nil
|
|
}
|
|
|
|
func (writer *controlledWriter) releaseWrites(count int) {
|
|
for index := 0; index < count; index++ {
|
|
writer.release <- struct{}{}
|
|
}
|
|
}
|
|
|
|
func (writer *controlledWriter) lines() []string {
|
|
writer.mutex.Lock()
|
|
defer writer.mutex.Unlock()
|
|
return strings.Split(strings.TrimSpace(writer.output.String()), "\n")
|
|
}
|
|
|
|
func messageNames(t *testing.T, lines []string) []string {
|
|
t.Helper()
|
|
messages := make([]string, 0, len(lines))
|
|
for _, line := range lines {
|
|
if line == "" {
|
|
continue
|
|
}
|
|
var record map[string]any
|
|
if err := json.Unmarshal([]byte(line), &record); err != nil {
|
|
t.Fatalf("invalid diagnostics JSON %q: %v", line, err)
|
|
}
|
|
messages = append(messages, fmt.Sprint(record["message"]))
|
|
}
|
|
return messages
|
|
}
|
|
|
|
func TestAsyncLoggingDoesNotBlockOnBlockedWriter(t *testing.T) {
|
|
writer := newControlledWriter()
|
|
diagnostics := NewAsync(writer, AsyncOptions{Options: Options{Level: slog.LevelDebug}, Capacity: 4, StopTimeout: 100 * time.Millisecond, CancelGrace: 10 * time.Millisecond})
|
|
logger := diagnostics.Logger()
|
|
completed := make(chan struct{})
|
|
go func() {
|
|
logger.Debug("accessibility event")
|
|
close(completed)
|
|
}()
|
|
|
|
select {
|
|
case <-completed:
|
|
case <-time.After(time.Second):
|
|
t.Fatal("slog call blocked on diagnostics writer")
|
|
}
|
|
if diagnostics.Dropped() != 0 {
|
|
t.Fatalf("dropped messages = %d, want 0", diagnostics.Dropped())
|
|
}
|
|
writer.Cancel()
|
|
if err := diagnostics.Stop(context.Background()); err == nil || !strings.Contains(err.Error(), "diagnostics writer canceled") {
|
|
t.Fatalf("Stop error = %v, want canceled writer error", err)
|
|
}
|
|
}
|
|
|
|
func TestAsyncLoggingFlushesInOrder(t *testing.T) {
|
|
writer := newControlledWriter()
|
|
diagnostics := NewAsync(writer, AsyncOptions{Capacity: 8, StopTimeout: time.Second, CancelGrace: 10 * time.Millisecond})
|
|
logger := diagnostics.Logger()
|
|
for _, message := range []string{"first", "second", "third", "fourth"} {
|
|
logger.Info(message)
|
|
}
|
|
writer.releaseWrites(4)
|
|
|
|
if err := diagnostics.Stop(context.Background()); err != nil {
|
|
t.Fatalf("Stop: %v", err)
|
|
}
|
|
got := messageNames(t, writer.lines())
|
|
want := []string{"first", "second", "third", "fourth"}
|
|
if fmt.Sprint(got) != fmt.Sprint(want) {
|
|
t.Fatalf("messages = %v, want %v", got, want)
|
|
}
|
|
}
|
|
|
|
func TestAsyncLoggingSaturationKeepsCriticalMessagesAndReportsDrops(t *testing.T) {
|
|
writer := newControlledWriter()
|
|
writer.autoRelease = true
|
|
diagnostics := NewAsync(writer, AsyncOptions{Options: Options{Level: slog.LevelDebug}, Capacity: 2, StopTimeout: time.Second, CancelGrace: 10 * time.Millisecond})
|
|
logger := diagnostics.Logger()
|
|
logger.Debug("debug 1")
|
|
select {
|
|
case <-writer.started:
|
|
case <-time.After(time.Second):
|
|
t.Fatal("diagnostics writer did not start")
|
|
}
|
|
logger.Debug("debug 2")
|
|
logger.Debug("debug 3")
|
|
logger.Error("critical message")
|
|
writer.releaseWrites(1)
|
|
|
|
if err := diagnostics.Stop(context.Background()); err != nil {
|
|
t.Fatalf("Stop: %v", err)
|
|
}
|
|
messages := messageNames(t, writer.lines())
|
|
joined := strings.Join(messages, "\n")
|
|
if !strings.Contains(joined, "critical message") {
|
|
t.Fatalf("critical message was dropped: %q", joined)
|
|
}
|
|
if strings.Contains(joined, "debug 2") {
|
|
t.Fatalf("oldest queued debug message was retained: %q", joined)
|
|
}
|
|
if !strings.Contains(joined, "diagnostics queue overflow") {
|
|
t.Fatalf("overflow report missing: %q", joined)
|
|
}
|
|
if diagnostics.Dropped() == 0 {
|
|
t.Fatal("drop count was not observable")
|
|
}
|
|
}
|
|
|
|
func TestAsyncLoggingNoncriticalRecordCannotEvictCriticalRecords(t *testing.T) {
|
|
writer := newControlledWriter()
|
|
writer.autoRelease = true
|
|
diagnostics := NewAsync(writer, AsyncOptions{Options: Options{Level: slog.LevelDebug}, Capacity: 2, StopTimeout: time.Second, CancelGrace: 10 * time.Millisecond})
|
|
logger := diagnostics.Logger()
|
|
logger.Debug("active writer")
|
|
select {
|
|
case <-writer.started:
|
|
case <-time.After(time.Second):
|
|
t.Fatal("diagnostics writer did not start")
|
|
}
|
|
logger.Warn("warning 1")
|
|
logger.Error("error 2")
|
|
logger.Debug("discarded debug")
|
|
writer.releaseWrites(1)
|
|
|
|
if err := diagnostics.Stop(context.Background()); err != nil {
|
|
t.Fatalf("Stop: %v", err)
|
|
}
|
|
joined := strings.Join(messageNames(t, writer.lines()), "\n")
|
|
for _, message := range []string{"warning 1", "error 2", "diagnostics queue overflow"} {
|
|
if !strings.Contains(joined, message) {
|
|
t.Fatalf("%q missing from diagnostics: %q", message, joined)
|
|
}
|
|
}
|
|
if strings.Contains(joined, "discarded debug") {
|
|
t.Fatalf("noncritical record displaced a critical record: %q", joined)
|
|
}
|
|
}
|
|
|
|
type failingWriter struct{}
|
|
|
|
func (failingWriter) Write([]byte) (int, error) {
|
|
return 0, errors.New("write failed")
|
|
}
|
|
|
|
func (failingWriter) Cancel() error { return nil }
|
|
func (failingWriter) Close() error { return nil }
|
|
|
|
func TestAsyncStopReportsWriteFailure(t *testing.T) {
|
|
diagnostics := NewAsync(failingWriter{}, AsyncOptions{Capacity: 4, StopTimeout: time.Second, CancelGrace: 10 * time.Millisecond})
|
|
diagnostics.Logger().Error("critical message")
|
|
|
|
err := diagnostics.Stop(context.Background())
|
|
if err == nil || !strings.Contains(err.Error(), "write diagnostics: write failed") {
|
|
t.Fatalf("Stop error = %v, want write failure", err)
|
|
}
|
|
if err := diagnostics.Stop(context.Background()); err == nil || !strings.Contains(err.Error(), "write failed") {
|
|
t.Fatalf("repeated Stop error = %v, want preserved write failure", err)
|
|
}
|
|
}
|
|
|
|
type timeoutWriter struct {
|
|
release chan struct{}
|
|
}
|
|
|
|
func (writer *timeoutWriter) Write([]byte) (int, error) {
|
|
<-writer.release
|
|
return 0, nil
|
|
}
|
|
|
|
func (writer *timeoutWriter) Cancel() error { return nil }
|
|
func (writer *timeoutWriter) Close() error { return nil }
|
|
|
|
func TestAsyncStopTimeoutIsPreservedAndRepeatedStopJoins(t *testing.T) {
|
|
writer := &timeoutWriter{release: make(chan struct{})}
|
|
diagnostics := NewAsync(writer, AsyncOptions{Capacity: 4, StopTimeout: 40 * time.Millisecond, CancelGrace: 10 * time.Millisecond})
|
|
diagnostics.Logger().Info("blocked message")
|
|
|
|
ctx, cancel := context.WithTimeout(context.Background(), 80*time.Millisecond)
|
|
defer cancel()
|
|
firstError := diagnostics.Stop(ctx)
|
|
if !errors.Is(firstError, context.DeadlineExceeded) {
|
|
t.Fatalf("first Stop error = %v, want deadline exceeded", firstError)
|
|
}
|
|
|
|
writer.release <- struct{}{}
|
|
secondError := diagnostics.Stop(context.Background())
|
|
if !errors.Is(secondError, context.DeadlineExceeded) {
|
|
t.Fatalf("second Stop error = %v, want preserved deadline exceeded", secondError)
|
|
}
|
|
}
|
|
|
|
func TestAsyncRepeatedStopAfterSuccess(t *testing.T) {
|
|
var output bytes.Buffer
|
|
diagnostics := NewAsync(NewPassthroughWriter(&output), AsyncOptions{Capacity: 4, StopTimeout: time.Second, CancelGrace: 10 * time.Millisecond})
|
|
diagnostics.Logger().Info("message")
|
|
|
|
if err := diagnostics.Stop(context.Background()); err != nil {
|
|
t.Fatalf("first Stop: %v", err)
|
|
}
|
|
if err := diagnostics.Stop(context.Background()); err != nil {
|
|
t.Fatalf("second Stop: %v", err)
|
|
}
|
|
if !strings.Contains(output.String(), "message") {
|
|
t.Fatalf("flushed output = %q", output.String())
|
|
}
|
|
}
|
|
|
|
func TestOpenFileIsAppendOnlyOwnerRestrictedAndCancellable(t *testing.T) {
|
|
path := filepath.Join(t.TempDir(), "diagnostics.log")
|
|
writer, err := OpenFile(path, nil)
|
|
if err != nil {
|
|
t.Fatalf("OpenFile: %v", err)
|
|
}
|
|
if _, err := writer.Write([]byte("first\n")); err != nil {
|
|
t.Fatalf("Write: %v", err)
|
|
}
|
|
if err := writer.Close(); err != nil {
|
|
t.Fatalf("Close: %v", err)
|
|
}
|
|
|
|
info, err := os.Stat(path)
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if info.Mode().Perm() != 0o600 {
|
|
t.Fatalf("file mode = %o, want 0600", info.Mode().Perm())
|
|
}
|
|
writer, err = OpenFile(path, nil)
|
|
if err != nil {
|
|
t.Fatalf("reopen: %v", err)
|
|
}
|
|
if _, err := writer.Write([]byte("second\n")); err != nil {
|
|
t.Fatalf("append: %v", err)
|
|
}
|
|
if err := writer.Cancel(); err != nil {
|
|
t.Fatalf("Cancel: %v", err)
|
|
}
|
|
data, err := os.ReadFile(path)
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if string(data) != "first\nsecond\n" {
|
|
t.Fatalf("file contents = %q, want append-only data", string(data))
|
|
}
|
|
}
|
|
|
|
var _ io.Writer = (*controlledWriter)(nil)
|