2026-07-29 15:26:40 +12:00
|
|
|
package logging
|
|
|
|
|
|
|
|
|
|
import (
|
|
|
|
|
"bytes"
|
|
|
|
|
"log/slog"
|
2026-08-12 09:57:56 +12:00
|
|
|
"path/filepath"
|
2026-07-29 15:26:40 +12:00
|
|
|
"strings"
|
|
|
|
|
"testing"
|
|
|
|
|
)
|
|
|
|
|
|
2026-08-06 22:33:56 +12:00
|
|
|
func TestConsoleLineLeadsWithTimeLevelAndMessage(t *testing.T) {
|
2026-07-29 15:26:40 +12:00
|
|
|
var output bytes.Buffer
|
2026-08-06 22:33:56 +12:00
|
|
|
New(&output, slog.LevelInfo).Info("gateway ready", "listen", ":8080")
|
|
|
|
|
|
|
|
|
|
line := strings.TrimRight(output.String(), "\n")
|
|
|
|
|
if strings.HasPrefix(line, "{") {
|
|
|
|
|
t.Fatalf("expected console output, got JSON: %s", line)
|
|
|
|
|
}
|
|
|
|
|
// The timestamp is a column, not a field: nothing labelled `time=` may appear in
|
|
|
|
|
// front of — or anywhere in — the readable part of the line.
|
|
|
|
|
if strings.Contains(line, "time=") || strings.Contains(line, "msg=") {
|
|
|
|
|
t.Fatalf("console line still carries slog's own keys: %s", line)
|
|
|
|
|
}
|
|
|
|
|
if !strings.Contains(line, "INFO") || !strings.Contains(line, "gateway ready") {
|
|
|
|
|
t.Fatalf("line is missing its level or message: %s", line)
|
|
|
|
|
}
|
|
|
|
|
if !strings.Contains(line, "listen=:8080") {
|
|
|
|
|
t.Fatalf("line is missing its fields: %s", line)
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
func TestConsoleLineOrdersIdentityFirstAndErrorLast(t *testing.T) {
|
|
|
|
|
var output bytes.Buffer
|
|
|
|
|
New(&output, slog.LevelInfo).Info("playback requested",
|
|
|
|
|
"error", "nope", "title", "Dune", "user", "matt", "component", "playback",
|
|
|
|
|
)
|
2026-07-29 15:26:40 +12:00
|
|
|
|
|
|
|
|
line := output.String()
|
2026-08-06 22:33:56 +12:00
|
|
|
order := []string{"component=playback", "user=matt", "title=Dune", "error=nope"}
|
|
|
|
|
previous := -1
|
|
|
|
|
for _, want := range order {
|
|
|
|
|
at := strings.Index(line, want)
|
|
|
|
|
if at < 0 {
|
|
|
|
|
t.Fatalf("output %q does not contain %q", line, want)
|
2026-07-29 15:26:40 +12:00
|
|
|
}
|
2026-08-06 22:33:56 +12:00
|
|
|
if at < previous {
|
|
|
|
|
t.Fatalf("field %q is out of order in %q", want, line)
|
|
|
|
|
}
|
|
|
|
|
previous = at
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
func TestConsoleQuotesOnlyAmbiguousValues(t *testing.T) {
|
|
|
|
|
var output bytes.Buffer
|
|
|
|
|
New(&output, slog.LevelInfo).Info("signed in", "device", "Living Room", "user", "matt")
|
|
|
|
|
|
|
|
|
|
line := output.String()
|
|
|
|
|
if !strings.Contains(line, `device="Living Room"`) {
|
|
|
|
|
t.Errorf("a value containing a space was not quoted: %s", line)
|
|
|
|
|
}
|
|
|
|
|
if !strings.Contains(line, `user=matt`) {
|
|
|
|
|
t.Errorf("an unambiguous value was quoted: %s", line)
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
2026-08-14 11:47:32 +12:00
|
|
|
func TestLoggingRedactsSensitiveAttributesAndURLs(t *testing.T) {
|
|
|
|
|
var output bytes.Buffer
|
|
|
|
|
logger, buffer := NewBuffered(&output, LevelTrace, 10, FormatConsole)
|
|
|
|
|
logger.Log(nil, LevelTrace, "diagnostic request",
|
|
|
|
|
"authorization", "Bearer private-token",
|
|
|
|
|
"url", "https://emby.example/stream?api_key=private-key&quality=720p",
|
|
|
|
|
)
|
|
|
|
|
|
|
|
|
|
line := output.String()
|
|
|
|
|
if strings.Contains(line, "private-token") || strings.Contains(line, "private-key") {
|
|
|
|
|
t.Fatalf("console leaked a secret: %s", line)
|
|
|
|
|
}
|
|
|
|
|
if !strings.Contains(line, "TRACE") {
|
|
|
|
|
t.Fatalf("console did not render TRACE: %s", line)
|
|
|
|
|
}
|
|
|
|
|
page := buffer.Events(0, 1)
|
|
|
|
|
if len(page.Events) != 1 || page.Events[0].Level != "TRACE" ||
|
|
|
|
|
page.Events[0].Attributes["authorization"] != "[redacted]" ||
|
|
|
|
|
strings.Contains(page.Events[0].Attributes["url"], "private-key") {
|
|
|
|
|
t.Fatalf("buffer leaked or mislabelled diagnostic event: %+v", page.Events)
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
2026-08-06 22:33:56 +12:00
|
|
|
func TestParseFormat(t *testing.T) {
|
|
|
|
|
tests := map[string]Format{
|
|
|
|
|
"": FormatConsole,
|
|
|
|
|
"console": FormatConsole,
|
|
|
|
|
"nonsense": FormatConsole,
|
|
|
|
|
"json": FormatJSON,
|
|
|
|
|
" LOGFMT": FormatLogfmt,
|
|
|
|
|
"text": FormatLogfmt,
|
|
|
|
|
}
|
|
|
|
|
for input, want := range tests {
|
|
|
|
|
if got := ParseFormat(input); got != want {
|
|
|
|
|
t.Errorf("ParseFormat(%q) = %v, want %v", input, got, want)
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
func TestSelectedFormatIsWhatGetsWritten(t *testing.T) {
|
|
|
|
|
var output bytes.Buffer
|
|
|
|
|
logger, _ := NewBuffered(&output, slog.LevelInfo, 0, FormatJSON)
|
|
|
|
|
logger.Info("gateway ready")
|
|
|
|
|
if !strings.HasPrefix(strings.TrimSpace(output.String()), "{") {
|
|
|
|
|
t.Fatalf("JSON format did not produce JSON: %s", output.String())
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
output.Reset()
|
|
|
|
|
logger, _ = NewBuffered(&output, slog.LevelInfo, 0, FormatLogfmt)
|
|
|
|
|
logger.Info("gateway ready")
|
|
|
|
|
if !strings.Contains(output.String(), `msg="gateway ready"`) {
|
|
|
|
|
t.Fatalf("logfmt format did not produce logfmt: %s", output.String())
|
2026-07-29 15:26:40 +12:00
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
func TestBufferedLoggerRetainsStructuredEventsWithCursorPagination(t *testing.T) {
|
|
|
|
|
var output bytes.Buffer
|
2026-08-06 22:33:56 +12:00
|
|
|
logger, buffer := NewBuffered(&output, slog.LevelDebug, 3, FormatConsole)
|
2026-07-29 15:26:40 +12:00
|
|
|
for i := 1; i <= 5; i++ {
|
|
|
|
|
logger.Info("request complete", "number", i)
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
first := buffer.Events(0, 2)
|
|
|
|
|
if first.Dropped != 2 || len(first.Events) != 2 || !first.HasMore {
|
|
|
|
|
t.Fatalf("unexpected first page: %+v", first)
|
|
|
|
|
}
|
|
|
|
|
if first.Events[0].Sequence != 3 || first.Events[0].Attributes["number"] != "3" {
|
|
|
|
|
t.Fatalf("oldest retained event was not delivered: %+v", first.Events[0])
|
|
|
|
|
}
|
|
|
|
|
second := buffer.Events(first.Next, 2)
|
|
|
|
|
if len(second.Events) != 1 || second.Events[0].Sequence != 5 || second.HasMore {
|
|
|
|
|
t.Fatalf("unexpected second page: %+v", second)
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
2026-08-12 09:57:56 +12:00
|
|
|
func TestPersistentBufferRestoresTheRetainedTail(t *testing.T) {
|
|
|
|
|
path := filepath.Join(t.TempDir(), "events.jsonl")
|
|
|
|
|
var output bytes.Buffer
|
|
|
|
|
logger, first, err := NewPersistentBuffered(&output, slog.LevelInfo, 3, FormatConsole, path)
|
|
|
|
|
if err != nil {
|
|
|
|
|
t.Fatal(err)
|
|
|
|
|
}
|
|
|
|
|
for i := 1; i <= 5; i++ {
|
|
|
|
|
logger.Info("request", "number", i)
|
|
|
|
|
}
|
|
|
|
|
if err := first.Close(); err != nil {
|
|
|
|
|
t.Fatal(err)
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
_, restored, err := NewPersistentBuffered(&output, slog.LevelInfo, 3, FormatConsole, path)
|
|
|
|
|
if err != nil {
|
|
|
|
|
t.Fatal(err)
|
|
|
|
|
}
|
|
|
|
|
defer restored.Close()
|
|
|
|
|
page := restored.Events(0, 10)
|
|
|
|
|
if len(page.Events) != 3 || page.Events[0].Attributes["number"] != "3" ||
|
|
|
|
|
page.Events[2].Attributes["number"] != "5" {
|
|
|
|
|
t.Fatalf("restored events = %+v", page.Events)
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
2026-07-29 15:26:40 +12:00
|
|
|
func TestParseLevel(t *testing.T) {
|
|
|
|
|
tests := map[string]slog.Level{
|
|
|
|
|
"": slog.LevelInfo,
|
2026-08-14 11:47:32 +12:00
|
|
|
"trace": LevelTrace,
|
2026-07-29 15:26:40 +12:00
|
|
|
"debug": slog.LevelDebug,
|
|
|
|
|
"WARNING": slog.LevelWarn,
|
|
|
|
|
"error": slog.LevelError,
|
|
|
|
|
"unknown": slog.LevelInfo,
|
|
|
|
|
}
|
|
|
|
|
for input, want := range tests {
|
|
|
|
|
if got := ParseLevel(input); got != want {
|
|
|
|
|
t.Errorf("ParseLevel(%q) = %v, want %v", input, got, want)
|
|
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
}
|
2026-08-02 22:10:19 +12:00
|
|
|
|
|
|
|
|
func TestParseCapacity(t *testing.T) {
|
|
|
|
|
if got := ParseCapacity("1000", 5); got != 1000 {
|
|
|
|
|
t.Fatalf("capacity = %d", got)
|
|
|
|
|
}
|
|
|
|
|
if got := ParseCapacity("-1", 5); got != 5 {
|
|
|
|
|
t.Fatalf("negative capacity = %d", got)
|
|
|
|
|
}
|
|
|
|
|
}
|