Author SHA1 Message Date
sneak 86436449c5 Emit slog attributes from every handler (closes #19, closes #24)
check / check (push) Successful in 34s
check / check (pull_request) Successful in 32s
Handle never read the record's attributes, and WithAttrs and WithGroup
returned the receiver unchanged. The JSON and webhook handlers also marshaled
slog.Record itself, whose attributes are unexported.

Each handler now carries a handlerAttrs value, copied rather than mutated, so
sibling loggers cannot leak attributes into each other. JSON and webhook
output nest groups as objects; the console appends key=value pairs with dotted
group keys, quoted as slog.NewTextHandler quotes them, invalid UTF-8
included. Logged values are never written to. In JSON the record's own fields
win a key collision, and a repeated key keeps its last value unless both are
groups, which merge; the README documents both.

Deviation: DEL is quoted on the console; the stdlib leaves it bare.

Model: opus-5-5
2026-09-28 10:49:46 +00:00
sneak a5fdadba76 Add a failing test pinning the discarded slog attributes
Every handler drops slog attributes: Handle never reads the record's
attributes, and WithAttrs and WithGroup return the receiver unchanged. So
slog.Info("casting", "device", d) loses its field.

The test checks the bytes each handler writes, directly and through
MultiplexHandler: record attributes, WithAttrs, WithGroup, slog.Group nesting
and LogValuer resolution. It also pins what a fix must not break: logged values
are never modified, durations are nanoseconds in JSON and "3s" on the console,
and the record's own field names win a key collision. Console keys and values
are quoted as slog.NewTextHandler quotes them, invalid UTF-8 included.

This commit adds only the test, and it fails; the fix follows.

Rule suppressed: paralleltest; the tests swap the process-wide os.Stdout.

Refs: #19

Model: opus-5-5
2026-09-28 10:49:07 +00:00
sneak 64c30e979d Merge pull request 'Update golangci-lint to v2.12.2 with canonical config' (#17) from golangci-v2.12.2 into main
check / check (push) Successful in 47s
Reviewed-on: #17
2026-08-10 15:40:04 +02:00
sneak 403ba4c42e build: update golangci-lint to v2.12.2 with canonical config
check / check (push) Successful in 29s
check / check (pull_request) Successful in 32s
Add the canonical .golangci.yml (v2 schema, all linters enabled with a
small documented disable list) and pin the Dockerfile lint stage to
golangci/golangci-lint:v2.12.2 by tag and digest, replacing the old
v1.64.8 digest-only pin.

Fix all findings surfaced by the v1 to v2 jump without changing any
exported signatures or behavior:

- add package and exported-symbol doc comments (revive)
- rename unused handler parameters to underscore (revive)
- check or explicitly discard error returns (errcheck, errchkjson)
- wrap errors with %w instead of %v (err113)
- use http.NewRequestWithContext instead of http.Post (noctx)
- replace fmt.Println with fmt.Fprintln(os.Stdout, ...) (forbidigo)
- name magic numbers as constants (mnd)
- add explicit slog.LevelDebug case (exhaustive)
- interface{} to any (modernize)
- move tests to the simplelog_test package (testpackage) and add
  t.Parallel() (paralleltest)
- move NewWebhookHandler above its methods (funcorder)
- whitespace, line-length, and blank-line fixes (wsl_v5, whitespace,
  nlreturn, lll, embeddedstructfieldcheck)
- nolint with justification for the intentional init/global design
  (gochecknoinits, gochecknoglobals) and interface-returning
  constructor (ireturn)
2026-08-07 17:10:03 +00:00
sneak 6cb690bfb7 Add standard Workflow section to TODO.md
check / check (push) Successful in 23s
2026-07-06 21:06:43 +02:00
sneak 3bd6551c8e Merge branch 'TODO'
check / check (push) Successful in 46s
2026-07-06 20:51:17 +02:00
sneak 403d853d27 Add TODO.md 2026-07-06 20:35:50 +02:00
clawbotandclawbot 4abd40d8e2 fix: split Dockerfile with pinned images and add CI workflow (#14)
## Summary

Rewrites the Dockerfile to use sha256-pinned images and proper multi-stage build structure. Adds missing Makefile targets and a Gitea CI workflow.

## Changes

### Dockerfile
- **Lint stage**: `golangci/golangci-lint` v1.64.8 pinned by sha256 — runs `make fmt-check` + `make lint`
- **Test stage**: `golang` 1.22.12 pinned by sha256 — runs `make test` with dependency on lint stage
- Removed redundant final stage (this is a library with no binary to build)
- Both images pinned by digest with version+date comments

### Makefile
- Added `fmt-check` target: verifies `gofmt` compliance without modifying files
- Added `check` target: runs `fmt-check`, `lint`, `test` in sequence
- Added `hooks` target: installs a pre-commit hook that runs `make check`
- Separated `gofmt` check from `lint` target (was previously bundled)
- Changed default target from `test` to `check`

### CI
- Added `.gitea/workflows/check.yml`: runs `docker build .` on push to main and on PRs

## Verification

`docker build --progress plain .` passes — all stages complete successfully.

closes #9

<!-- session: agent:sdlc-manager:subagent:fffa0a5a-5127-4489-a2e0-314c5eaaed68 -->

Co-authored-by: clawbot <clawbot@noreply.git.eeqj.de>
Reviewed-on: #14
Co-authored-by: clawbot <clawbot@noreply.example.org>
Co-committed-by: clawbot <clawbot@noreply.example.org>
2026-03-02 21:06:53 +01:00
sneak 9121da9aae Merge pull request 'fix: JSONHandler deadlock from recursive log.Println (closes #3)' (#4) from clawbot/simplelog:fix/json-handler-deadlock into main
Reviewed-on: #4
2026-02-08 18:29:55 +01:00
sneak 74ce052b77 Merge branch 'main' into fix/json-handler-deadlock 2026-02-08 18:29:12 +01:00
sneak 1eef38a5fa Merge pull request 'test: add deadlock regression test for JSONHandler (issue #3)' (#7) from clawbot/simplelog:test/jsonhandler-deadlock into main
Reviewed-on: #7
2026-02-08 18:27:15 +01:00
clawbot 97a82e9b2c test: add deadlock regression test for JSONHandler
Reproduces issue #3 — JSONHandler.Handle() calling log.Println() causes
a deadlock when slog.SetDefault redirects log output back through slog.

This test hangs/fails on main and should pass once #4 is merged.
2026-02-08 09:21:08 -08:00
user 869b7ca4c3 fix: replace log.Println with fmt.Fprintln in JSONHandler to prevent deadlock 2026-02-08 09:15:17 -08:00
sneak 31c9ed52cb preparing for 1.0 2024-06-14 05:53:22 -07:00
19 changed files with 1656 additions and 93 deletions
+12
View File
@@ -0,0 +1,12 @@
name: check
on:
push:
pull_request:
jobs:
check:
runs-on: ubuntu-latest
steps:
- uses: actions/checkout@11bd71901bbe5b1630ceea73d27597364c9af683 # v4.2.2
- run: docker build .
+34
View File
@@ -0,0 +1,34 @@
version: "2"
# Config schema uses the golangci-lint v2 layout (settings live under
# linters.settings, not top-level linters-settings) so that the
# thresholds below are actually applied by golangci-lint >= v2.
run:
timeout: 5m
modules-download-mode: readonly
linters:
default: all
disable:
# Genuinely incompatible with project patterns
- exhaustruct # Requires all struct fields
- depguard # Dependency allow/block lists
- godot # Requires comments to end with periods
- wsl # Deprecated, replaced by wsl_v5
- wrapcheck # Too verbose for internal packages
- varnamelen # Short names like db, id are idiomatic Go
settings:
lll:
line-length: 88
funlen:
lines: 80
statements: 50
cyclop:
max-complexity: 15
dupl:
threshold: 100
issues:
max-issues-per-linter: 0
max-same-issues: 0
+17 -36
View File
@@ -1,39 +1,20 @@
# First stage: Use the golangci-lint image to run the linter # Lint stage: format check + golangci-lint
FROM golangci/golangci-lint:latest as lint # golangci/golangci-lint:v2.12.2 (Debian-based), 2026-08-07
FROM golangci/golangci-lint:v2.12.2@sha256:5cceeef04e53efe1470638d4b4b4f5ceefd574955ab3941b2d9a68a8c9ad5240 AS lint
# Set the Current Working Directory inside the container WORKDIR /src
WORKDIR /app COPY go.mod go.sum ./
RUN go mod download
# Copy the go.mod file and the rest of the application code
COPY go.mod ./
COPY . . COPY . .
RUN make fmt-check
RUN make lint
# Run golangci-lint # Test stage: run full test suite
RUN golangci-lint run # golang 1.22.12 (2025-02-04)
FROM golang@sha256:1cf6c45ba39db9fd6db16922041d074a63c935556a05c5ccb62d181034df7f02 AS test
RUN sh -c 'test -z "$(gofmt -l .)"' # Depend on lint stage so both stages always run
COPY --from=lint /src/go.sum /dev/null
# Second stage: Use the official Golang image to run tests WORKDIR /src
FROM golang:1.22 as test COPY go.mod go.sum ./
RUN go mod download
# Set the Current Working Directory inside the container
WORKDIR /app
# Copy the go.mod file and the rest of the application code
COPY go.mod ./
COPY . . COPY . .
RUN make test
# Run tests
RUN go test -v ./...
# Final stage: Combine the linting and testing stages
FROM golang:1.22 as final
# Ensure that the linting stage succeeded
WORKDIR /app
COPY --from=lint /app .
COPY --from=test /app .
# Set the final CMD to something minimal since we only needed to verify lint and tests during build
CMD ["echo", "Build and tests passed successfully!"]
+14
View File
@@ -0,0 +1,14 @@
DO WHAT THE FUCK YOU WANT TO PUBLIC LICENSE
Version 2, December 2004
Copyright (C) 2004 Sam Hocevar <sam@hocevar.net>
Everyone is permitted to copy and distribute verbatim or modified
copies of this license document, and changing it is allowed as long
as the name is changed.
DO WHAT THE FUCK YOU WANT TO PUBLIC LICENSE
TERMS AND CONDITIONS FOR COPYING, DISTRIBUTION AND MODIFICATION
0. You just DO WHAT THE FUCK YOU WANT TO.
+14 -3
View File
@@ -1,6 +1,6 @@
.PHONY: test .PHONY: test fmt fmt-check lint check docker hooks
default: test default: check
test: test:
@go test -v ./... @go test -v ./...
@@ -9,9 +9,20 @@ fmt:
goimports -l -w . goimports -l -w .
golangci-lint run --fix golangci-lint run --fix
fmt-check:
@test -z "$$(gofmt -l .)" || { echo "gofmt would reformat:"; gofmt -l .; exit 1; }
lint: lint:
golangci-lint run golangci-lint run
sh -c 'test -z "$$(gofmt -l .)"'
check: fmt-check lint test
docker: docker:
docker build --progress plain . docker build --progress plain .
hooks:
@echo "Installing git hooks..."
@mkdir -p .git/hooks
@printf '#!/bin/sh\nmake check\n' > .git/hooks/pre-commit
@chmod +x .git/hooks/pre-commit
@echo "Pre-commit hook installed."
+56 -3
View File
@@ -11,14 +11,24 @@ stdlib `log/slog` default handler, and solve the 90% case for logging.
## Current Status ## Current Status
Pre-1.0, not working yet. Released v1.0.0 2024-06-14. Works as intended. No known bugs.
## Features ## Features
- if output is a tty, outputs pretty color logs - if output is a tty, outputs pretty color logs
- if output is not a tty, outputs json - if output is not a tty, outputs json
- supports delivering logs via tcp RELP (e.g. to remote rsyslog using imrelp)
- supports delivering each log message via a webhook - supports delivering each log message via a webhook
- emits every `slog` attribute: those passed to a log call, those
accumulated with `WithAttrs`, and those qualified by `WithGroup`.
`slog.Group` values nest, and `slog.LogValuer` values are resolved. In
json output attributes are object fields (groups become nested objects);
in console output they are appended as `key=value` pairs, with grouped
keys written as `group.key=value`. See
[Attribute output](#attribute-output) for the details worth knowing
## Planned Features
- supports delivering logs via tcp RELP (e.g. to remote rsyslog using imrelp)
## Installation ## Installation
@@ -36,7 +46,9 @@ go get sneak.berlin/go/simplelog
## Usage ## Usage
Below is an example of how to use SimpleLog in a Go application. This example is provided in the form of a `main.go` file, which demonstrates logging at various levels using structured logging syntax. Below is an example of how to use SimpleLog in a Go application. This
example is provided in the form of a `main.go` file, which demonstrates
logging at various levels using structured logging syntax.
```go ```go
package main package main
@@ -54,3 +66,44 @@ func main() {
slog.Error("Failed to save data", slog.String("reason", "permission denied")) slog.Error("Failed to save data", slog.String("reason", "permission denied"))
} }
``` ```
## Attribute output
Attributes reach every handler: the ones passed to the log call, the ones
accumulated with `WithAttrs`, and the ones qualified by the groups open at
the time they were attached. `slog.Group` values nest, and
`slog.LogValuer` values are resolved to the value they stand for. A few
behaviours are worth knowing before you rely on them.
**Your values are never modified.** Whatever you log is read and rendered,
never written to. A map or a slice you pass to `slog.Any` comes back from
the logger exactly as you handed it over, even when a group later uses the
same key.
**Durations are nanoseconds in json, and readable on the console.** The
json and webhook payloads emit a `slog.Duration` as a number of
nanoseconds, matching `slog.NewJSONHandler`, so a consumer can compare and
aggregate the field without parsing it. The console line emits the same
duration as `3s`, matching `slog.NewTextHandler`, because a person reads
it.
**The json payload is an object, with the consequences an object has.**
The record's own fields are named `Time`, `Level`, `Message` and `PC`, and
they own those names: an attribute keyed after one of them is dropped from
the json and webhook output. A key logged more than once keeps its last
value there for the same reason, with one exception: when both are
`slog.Group` values sharing a key, the two groups are merged into one
object holding the members of both, rather than the second replacing the
first. Neither the collision nor the merge applies to the console output,
which is a line of text: every pair appears, in order. If you need a field
called `message`, pick a key that does not collide - the collision is
silent.
**Empty things follow the `slog.Handler` contract.** An empty `Attr` is
ignored, an empty group is elided along with its key, a group with an
empty key is inlined into its parent, and `WithGroup("")` returns the
handler unchanged.
## License
[WTFPL](./LICENSE)
+64
View File
@@ -0,0 +1,64 @@
# Workflow
* branch (from `main`)
* do the work in Next Step
* move Next Step to the top of Completed Steps
* move the top item of Future Steps into Next Step
* commit (`TODO.md` changes in the same commit as the work)
* merge to `main` if the branch is not protected, otherwise open a PR
* push
# Status
1.0+
Tagged v1.0.0 (2024-06-14) and 1.0.1 (2026-02-08). In post-1.0
maintenance; the library is referenced by the Go styleguide.
# Next Step
Bring the Makefile up to policy in one commit: add fmt-check, check, and
hooks targets (test/lint/fmt/docker exist) and add the missing policy
files it depends on: .golangci.yml, REPO_POLICIES.md, .editorconfig,
.dockerignore, and .gitea/workflows/check.yml running make check.
# Completed Steps
* 2026-08-10: fixed every handler discarding slog attributes: console,
JSON and webhook handlers now emit record attributes, accumulate
WithAttrs without mutating the receiver, and honour WithGroup;
slog.Group values nest and LogValuer values are resolved; console
keys and values holding invalid UTF-8 are quoted
* 2026-08-07: added canonical `.golangci.yml` (v2 schema), pinned the
`Dockerfile` lint stage to golangci-lint v2.12.2 (tag+digest), and
fixed all findings the v1→v2 jump surfaced without changing any
exported signatures or behavior
* 2026-02-08: fixed JSONHandler deadlock from recursive log.Println,
with regression test; tagged 1.0.1
* 2024-06-14: 1.0 prep: lint and fmt enforced in Docker build, call
stack depth fix so log locations report correctly, example script,
removed non-building RELP code; tagged v1.0.0
* 2024-05-22: module path moved to sneak.berlin/go/simplelog
* 2024-05-14: initial library: slog-based console, JSON, webhook, and
RELP handlers, MultiplexHandler, caller file/line info, UTC ISO
timestamps, level-colored output
# Future Steps
* Rewrite the Dockerfile to run make check with sha256-pinned base
images (currently golangci/golangci-lint:latest and golang:1.22,
unpinned, duplicating Makefile logic instead of calling it)
* Restructure README.md into the standard sections: Description,
Getting Started, Rationale, Design, TODO, License, Author
* Delete the old plain TODO file once this TODO.md lands
* Add .aider.* to .gitignore and remove the stray aider artifacts from
the working tree
* Pick one tag scheme before the next release (v1.0.0 vs 1.0.1 are
inconsistent)
* Tag v1.0.2, with the leading v, once the attribute fix lands, so
consuming repos can move off pseudo-version pins in one step
* Fix RELP output to cache (from old TODO)
* Re-add RELP delivery over TCP to remote rsyslog imrelp; removed
2024-06-14 because it did not build (README planned feature)
* Add regex filtering for webhook logs (from old TODO)
* Better console output format (from old TODO)
+285
View File
@@ -0,0 +1,285 @@
package simplelog
import (
"encoding/json"
"log/slog"
"strconv"
"strings"
"unicode"
"unicode/utf8"
)
// handlerAttrs is the attribute state every handler carries: the attributes
// accumulated by WithAttrs, plus the groups opened by WithGroup. Its methods
// never mutate the receiver, so handlers derived from a common parent stay
// independent of each other.
type handlerAttrs struct {
attrs []slog.Attr
groups []string
}
// withAttrs returns a copy carrying attrs in addition to those already held.
// The attributes are qualified by the groups that are open at the time they
// are attached, as the slog.Handler contract requires.
func (h handlerAttrs) withAttrs(attrs []slog.Attr) handlerAttrs {
qualified := qualifyAttrs(h.groups, attrs)
combined := make([]slog.Attr, 0, len(h.attrs)+len(qualified))
combined = append(combined, h.attrs...)
combined = append(combined, qualified...)
return handlerAttrs{attrs: combined, groups: h.groups}
}
// withGroup returns a copy with a further group open. An empty name is a no-op,
// per the slog.Handler contract.
func (h handlerAttrs) withGroup(name string) handlerAttrs {
if name == "" {
return h
}
groups := make([]string, 0, len(h.groups)+1)
groups = append(groups, h.groups...)
groups = append(groups, name)
return handlerAttrs{attrs: h.attrs, groups: groups}
}
// forRecord returns the accumulated attributes followed by the record's own,
// the latter qualified by any open groups.
func (h handlerAttrs) forRecord(record slog.Record) []slog.Attr {
own := qualifyAttrs(h.groups, recordAttrs(record))
all := make([]slog.Attr, 0, len(h.attrs)+len(own))
all = append(all, h.attrs...)
all = append(all, own...)
return all
}
// qualifyAttrs nests attrs inside the given open groups, innermost last.
func qualifyAttrs(groups []string, attrs []slog.Attr) []slog.Attr {
for i := len(groups) - 1; i >= 0; i-- {
attrs = []slog.Attr{{
Key: groups[i],
Value: slog.GroupValue(attrs...),
}}
}
return attrs
}
// recordAttrs collects the attributes a record carries. They live in
// unexported fields, so they are only reachable through Record.Attrs - which
// is why marshaling a slog.Record directly loses every one of them.
func recordAttrs(record slog.Record) []slog.Attr {
attrs := make([]slog.Attr, 0, record.NumAttrs())
record.Attrs(func(attr slog.Attr) bool {
attrs = append(attrs, attr)
return true
})
return attrs
}
// groupMap is a JSON object this package built for itself: the payload of a
// record, or one of the nested objects a slog.Group becomes.
//
// The distinct type is what keeps the handler from writing into data the
// caller still owns. A value handed to slog.Any goes into the payload by
// reference - copying every logged map and slice would be a real cost for no
// gain, since rendering only reads. The one place the handler writes into a
// value already in the payload is the group merge below, and a type assertion
// to groupMap can only succeed on a map this package allocated: a caller's
// map[string]any is a different type and never matches, however it was keyed.
// So the invariant holds by construction - nothing reachable from the caller
// is ever written to, only read.
type groupMap map[string]any
// recordToMap renders a record, with its handler's attributes, as the JSON
// object the JSON and webhook handlers emit. The record's own fields keep the
// names they have always had, and win a collision with an attribute key.
func recordToMap(record slog.Record, attrs handlerAttrs) groupMap {
fields := attrsToMap(attrs.forRecord(record))
fields["Time"] = record.Time
fields["Level"] = record.Level
fields["Message"] = record.Message
fields["PC"] = record.PC
return fields
}
// attrsToMap renders attributes as a JSON object in which groups are nested
// objects. A group named more than once is merged rather than duplicated;
// any other repeated key keeps the last value, as a JSON object must.
func attrsToMap(attrs []slog.Attr) groupMap {
fields := make(groupMap, len(attrs))
for _, attr := range attrs {
addAttrToMap(fields, attr)
}
return fields
}
func addAttrToMap(fields groupMap, attr slog.Attr) {
value := attr.Value.Resolve()
if attr.Key == "" && value.Any() == nil {
// An empty Attr is ignored, per the slog.Handler contract.
return
}
if value.Kind() == slog.KindGroup {
group := value.Group()
if len(group) == 0 {
// An empty group is elided, as is its key.
return
}
// A group with an empty key is inlined into its parent.
target := fields
if attr.Key != "" {
// Merge only into a group this package built. Anything else
// at this key - including a map the caller logged - is
// replaced rather than written into, so the caller's own
// data structure is never touched.
nested, ok := fields[attr.Key].(groupMap)
if !ok {
nested = make(groupMap, len(group))
fields[attr.Key] = nested
}
target = nested
}
for _, member := range group {
addAttrToMap(target, member)
}
return
}
fields[attr.Key] = jsonValue(value)
}
// jsonValue converts a resolved slog.Value into something encoding/json can
// render usefully. Values it cannot marshal - and errors, which marshal to an
// empty object - fall back to their slog string form, so a value is never
// rendered as an empty object.
//
// Values are returned as they were given, not copied: nothing here or in its
// callers writes to a value the caller supplied.
func jsonValue(value slog.Value) any {
switch value.Kind() {
case slog.KindString:
return value.String()
case slog.KindInt64:
return value.Int64()
case slog.KindUint64:
return value.Uint64()
case slog.KindFloat64:
return value.Float64()
case slog.KindBool:
return value.Bool()
case slog.KindDuration:
// Nanoseconds as a number, which is what slog.NewJSONHandler
// emits. A JSON consumer can then compare and aggregate the
// field; the "3s" form would have to be parsed first, and no
// common log pipeline knows how.
return value.Duration().Nanoseconds()
case slog.KindTime:
return value.Time()
case slog.KindAny, slog.KindGroup, slog.KindLogValuer:
// Only KindAny arrives here in practice: addAttrToMap renders
// groups itself and resolves every value first.
return jsonAnyValue(value)
default:
// Anything a future Go release adds.
return jsonAnyValue(value)
}
}
func jsonAnyValue(value slog.Value) any {
held := value.Any()
if _, ok := held.(json.Marshaler); !ok {
if err, ok := held.(error); ok {
return err.Error()
}
}
_, err := json.Marshal(held)
if err != nil {
return value.String()
}
return held
}
// attrsToText renders attributes as the space separated key=value pairs the
// console handler appends to a log line. Groups become dotted key prefixes.
//
// Values take their slog string form, so a duration reads as "3s" here where
// the json output carries nanoseconds as a number. That is the same split the
// stdlib makes between slog.NewTextHandler and slog.NewJSONHandler: the
// console line is read by a person, the json line by a program.
func attrsToText(attrs []slog.Attr) string {
var out strings.Builder
for _, attr := range attrs {
appendAttrText(&out, "", attr)
}
return out.String()
}
func appendAttrText(out *strings.Builder, prefix string, attr slog.Attr) {
value := attr.Value.Resolve()
if attr.Key == "" && value.Any() == nil {
return
}
if value.Kind() == slog.KindGroup {
group := value.Group()
if len(group) == 0 {
return
}
nested := prefix
if attr.Key != "" {
nested = prefix + attr.Key + "."
}
for _, member := range group {
appendAttrText(out, nested, member)
}
return
}
out.WriteString(" ")
// The key is quoted on the same terms as the value, and as a whole
// including its group prefix, because that is the token a reader has to
// find the "=" in. slog.NewTextHandler quotes "prefix+key" the same way,
// so a key like "a=b" reads as "a=b"=v2 rather than the ambiguous
// a=b=v2, which parses as the key "a" with the value "b=v2".
out.WriteString(quoteIfNeeded(prefix + attr.Key))
out.WriteString("=")
out.WriteString(quoteIfNeeded(value.String()))
}
// quoteIfNeeded quotes a key or a value, as slog.NewTextHandler does, when
// leaving it bare would make the key=value pairs ambiguous or would write a
// control character or invalid UTF-8 to the terminal. Unlike the stdlib, it
// also quotes DEL (0x7f), which is a control character too.
func quoteIfNeeded(text string) string {
if text == "" {
return `""`
}
// Ranging over a string yields utf8.RuneError for each invalid byte;
// strconv.Quote then escapes that byte, as in "bad\xffkey".
for _, r := range text {
if unicode.IsSpace(r) || !unicode.IsPrint(r) ||
r == utf8.RuneError || r == '"' || r == '=' {
return strconv.Quote(text)
}
}
return text
}
+912
View File
@@ -0,0 +1,912 @@
//nolint:paralleltest // tests swap the process-wide os.Stdout to read handler output
package simplelog_test
import (
"bytes"
"context"
"encoding/json"
"errors"
"io"
"log/slog"
"maps"
"net/http"
"net/http/httptest"
"os"
"reflect"
"slices"
"strings"
"testing"
"time"
"sneak.berlin/go/simplelog"
)
// These tests assert on the bytes the handlers actually emit, because that is
// where the defect lives: the handlers accept attributes and then throw them
// away, so nothing short of reading the output proves they survived.
// captureStdout redirects os.Stdout for the duration of fn and returns what was
// written to it. Both the console and the JSON handler write to os.Stdout, so
// this is the only way to see their real output. os.Stdout is shared by the
// whole process, so a test that uses this must not run in parallel.
func captureStdout(t *testing.T, fn func()) string {
t.Helper()
r, w, err := os.Pipe()
if err != nil {
t.Fatalf("os.Pipe: %v", err)
}
original := os.Stdout
os.Stdout = w
collected := make(chan string, 1)
go func() {
var buf bytes.Buffer
_, _ = io.Copy(&buf, r)
collected <- buf.String()
}()
defer func() {
os.Stdout = original
_ = r.Close()
}()
fn()
os.Stdout = original
err = w.Close()
if err != nil {
t.Fatalf("close pipe writer: %v", err)
}
return <-collected
}
// testRecord builds an INFO record carrying the given attributes.
func testRecord(message string, attrs ...slog.Attr) slog.Record {
record := slog.NewRecord(time.Now(), slog.LevelInfo, message, 0)
record.AddAttrs(attrs...)
return record
}
// handle passes record to handler and fails the test if Handle returns an
// error.
func handle(t *testing.T, handler slog.Handler, record slog.Record) {
t.Helper()
err := handler.Handle(context.Background(), record)
if err != nil {
t.Fatalf("Handle: %v", err)
}
}
// decodeLine parses a single line of JSON handler output.
func decodeLine(t *testing.T, output string) map[string]any {
t.Helper()
line := strings.TrimSpace(output)
if line == "" {
t.Fatal("handler emitted no output")
}
var decoded map[string]any
err := json.Unmarshal([]byte(line), &decoded)
if err != nil {
t.Fatalf("output is not valid JSON: %v\noutput: %s", err, line)
}
return decoded
}
// wantField asserts that a decoded JSON object has key with the given value.
func wantField(t *testing.T, decoded map[string]any, key string, want any) {
t.Helper()
got, ok := decoded[key]
if !ok {
t.Fatalf("field %q missing from output: %v", key, decoded)
}
if got != want {
t.Fatalf("field %q = %v, want %v", key, got, want)
}
}
// wantGroup asserts that a decoded JSON object has key holding a nested object.
func wantGroup(t *testing.T, decoded map[string]any, key string) map[string]any {
t.Helper()
got, ok := decoded[key]
if !ok {
t.Fatalf("group %q missing from output: %v", key, decoded)
}
group, ok := got.(map[string]any)
if !ok {
t.Fatalf("field %q = %v, want a nested object", key, got)
}
return group
}
// wantNoField asserts that a decoded JSON object does not carry key.
func wantNoField(t *testing.T, decoded map[string]any, key string) {
t.Helper()
if got, present := decoded[key]; present {
t.Fatalf("field %q unexpectedly present as %v: %v", key, got, decoded)
}
}
// wantUnchanged asserts that a value the caller still owns was not written to
// by the handler. Logging must read what it is handed, never modify it.
func wantUnchanged(t *testing.T, what string, got, want any) {
t.Helper()
if !reflect.DeepEqual(got, want) {
t.Fatalf("handler mutated the caller's %s: got %v, want %v", what, got, want)
}
}
// wantContains asserts that console output contains a fragment.
func wantContains(t *testing.T, output, fragment string) {
t.Helper()
if !strings.Contains(output, fragment) {
t.Fatalf("output does not contain %q\noutput: %s", fragment, output)
}
}
// wantNotContains asserts that console output does not contain a fragment.
func wantNotContains(t *testing.T, output, fragment string) {
t.Helper()
if strings.Contains(output, fragment) {
t.Fatalf("output unexpectedly contains %q\noutput: %s", fragment, output)
}
}
// castTarget is a slog.LogValuer: the handler must resolve it rather than
// serialising the struct itself.
type castTarget struct {
id string
}
func (c castTarget) LogValue() slog.Value {
return slog.StringValue(c.id)
}
var _ slog.LogValuer = castTarget{}
// errConnectionRefused is the error the ResolvesValues tests log.
var errConnectionRefused = errors.New("connection refused")
func TestJSONHandlerEmitsRecordAttrs(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewJSONHandler()
record := testRecord(
"casting",
slog.String("device", "livingroom"),
slog.String("file", "movie.mp4"),
slog.Int("attempt", 3),
)
handle(t, handler, record)
})
decoded := decodeLine(t, output)
wantField(t, decoded, "Message", "casting")
wantField(t, decoded, "device", "livingroom")
wantField(t, decoded, "file", "movie.mp4")
wantField(t, decoded, "attempt", float64(3))
}
func TestJSONHandlerWithAttrsAccumulates(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewJSONHandler().
WithAttrs([]slog.Attr{slog.String("service", "cattbox")}).
WithAttrs([]slog.Attr{slog.String("component", "caster")})
record := testRecord("casting", slog.String("device", "livingroom"))
handle(t, handler, record)
})
decoded := decodeLine(t, output)
wantField(t, decoded, "service", "cattbox")
wantField(t, decoded, "component", "caster")
wantField(t, decoded, "device", "livingroom")
}
func TestJSONHandlerWithAttrsDoesNotMutateReceiver(t *testing.T) {
parent := simplelog.NewJSONHandler()
first := parent.WithAttrs([]slog.Attr{slog.String("worker", "first")})
second := parent.WithAttrs([]slog.Attr{slog.String("worker", "second")})
firstOutput := captureStdout(t, func() {
handle(t, first, testRecord("work"))
})
secondOutput := captureStdout(t, func() {
handle(t, second, testRecord("work"))
})
parentOutput := captureStdout(t, func() {
handle(t, parent, testRecord("work"))
})
wantField(t, decodeLine(t, firstOutput), "worker", "first")
wantField(t, decodeLine(t, secondOutput), "worker", "second")
if _, present := decodeLine(t, parentOutput)["worker"]; present {
t.Fatalf(
"parent handler leaked an attribute from a derived handler: %s",
parentOutput,
)
}
}
func TestJSONHandlerWithGroupNestsAttrs(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewJSONHandler().
WithGroup("cast").
WithAttrs([]slog.Attr{slog.String("device", "livingroom")})
record := testRecord("casting", slog.String("file", "movie.mp4"))
handle(t, handler, record)
})
decoded := decodeLine(t, output)
wantField(t, decoded, "Message", "casting")
group := wantGroup(t, decoded, "cast")
wantField(t, group, "device", "livingroom")
wantField(t, group, "file", "movie.mp4")
}
func TestJSONHandlerResolvesValues(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewJSONHandler()
record := testRecord(
"cast failed",
slog.Group("request", slog.Int("status", 502), slog.String("method", "POST")),
slog.Any("target", castTarget{id: "chromecast-7"}),
slog.Any("error", errConnectionRefused),
)
handle(t, handler, record)
})
decoded := decodeLine(t, output)
wantField(t, decoded, "target", "chromecast-7")
wantField(t, decoded, "error", "connection refused")
group := wantGroup(t, decoded, "request")
wantField(t, group, "status", float64(502))
wantField(t, group, "method", "POST")
}
func TestConsoleHandlerEmitsRecordAttrs(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewConsoleHandler()
record := testRecord(
"casting",
slog.String("device", "livingroom"),
slog.String("file", "movie.mp4"),
slog.Int("attempt", 3),
)
handle(t, handler, record)
})
wantContains(t, output, "casting")
wantContains(t, output, "device=livingroom")
wantContains(t, output, "file=movie.mp4")
wantContains(t, output, "attempt=3")
}
func TestConsoleHandlerQuotesValuesNeedingIt(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewConsoleHandler()
record := testRecord("casting", slog.String("file", "The Movie.mp4"))
handle(t, handler, record)
})
wantContains(t, output, `file="The Movie.mp4"`)
}
// TestConsoleHandlerQuotesKeysNeedingIt pins the key side of the same rule.
// A key is quoted on the same terms as a value, and as one token including
// its group prefix, so that the "=" separating the pair is always the first
// one outside quotes. Every case here was compared against
// slog.NewTextHandler, which renders each of them identically.
func TestConsoleHandlerQuotesKeysNeedingIt(t *testing.T) {
tests := []struct {
name string
build func() slog.Handler
attrs []slog.Attr
want string
notWant string
}{
{
name: "an ordinary key is left bare",
build: func() slog.Handler { return simplelog.NewConsoleHandler() },
attrs: []slog.Attr{slog.String("device", "livingroom")},
want: " device=livingroom",
notWant: `"device"`,
},
{
name: "a key containing an equals sign is quoted",
build: func() slog.Handler { return simplelog.NewConsoleHandler() },
attrs: []slog.Attr{slog.String("a=b", "v2")},
want: ` "a=b"=v2`,
notWant: " a=b=v2",
},
{
name: "a key containing a space is quoted",
build: func() slog.Handler { return simplelog.NewConsoleHandler() },
attrs: []slog.Attr{slog.String("my key", "v")},
want: ` "my key"=v`,
notWant: " my key=v",
},
{
name: "a key containing a quote is escaped",
build: func() slog.Handler { return simplelog.NewConsoleHandler() },
attrs: []slog.Attr{slog.String(`he"llo`, "v")},
want: ` "he\"llo"=v`,
notWant: ` he"llo=v`,
},
{
name: "a printable non-ascii key is left bare",
build: func() slog.Handler { return simplelog.NewConsoleHandler() },
attrs: []slog.Attr{slog.String("キー", "v")},
want: " キー=v",
notWant: `"キー"`,
},
{
name: "a group prefix is quoted together with its key",
build: func() slog.Handler { return simplelog.NewConsoleHandler() },
attrs: []slog.Attr{
slog.Group("grp", slog.String("a=b", "v")),
},
want: ` "grp.a=b"=v`,
notWant: " grp.a=b=v",
},
{
name: "a WithGroup prefix needing quotes is quoted with its key",
build: func() slog.Handler {
return simplelog.NewConsoleHandler().WithGroup("my grp")
},
attrs: []slog.Attr{slog.String("k", "v")},
want: ` "my grp.k"=v`,
notWant: " my grp.k=v",
},
{
name: "an empty key is quoted rather than left as a gap",
build: func() slog.Handler { return simplelog.NewConsoleHandler() },
attrs: []slog.Attr{slog.String("", "v")},
want: ` ""=v`,
notWant: " =v",
},
}
for _, test := range tests {
t.Run(test.name, func(t *testing.T) {
output := captureStdout(t, func() {
handle(t, test.build(), testRecord("casting", test.attrs...))
})
wantContains(t, output, test.want)
wantNotContains(t, output, test.notWant)
})
}
}
// TestConsoleHandlerQuotesInvalidUTF8 checks that a key or a value holding
// invalid UTF-8 is quoted with the bad byte escaped, as slog.NewTextHandler
// does, so the raw byte never reaches the terminal. Valid non-ASCII stays bare.
func TestConsoleHandlerQuotesInvalidUTF8(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewConsoleHandler()
record := testRecord(
"casting",
slog.String("bad\xffkey", "v"),
slog.String("raw", "bad\xffvalue"),
slog.String("title", "Amélie"),
)
handle(t, handler, record)
})
wantContains(t, output, ` "bad\xffkey"=v`)
wantContains(t, output, ` raw="bad\xffvalue"`)
wantContains(t, output, " title=Amélie")
wantNotContains(t, output, "\xff")
}
func TestConsoleHandlerWithAttrsAccumulates(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewConsoleHandler().
WithAttrs([]slog.Attr{slog.String("service", "cattbox")}).
WithAttrs([]slog.Attr{slog.String("component", "caster")})
record := testRecord("casting", slog.String("device", "livingroom"))
handle(t, handler, record)
})
wantContains(t, output, "service=cattbox")
wantContains(t, output, "component=caster")
wantContains(t, output, "device=livingroom")
}
func TestConsoleHandlerWithAttrsDoesNotMutateReceiver(t *testing.T) {
parent := simplelog.NewConsoleHandler()
first := parent.WithAttrs([]slog.Attr{slog.String("worker", "first")})
second := parent.WithAttrs([]slog.Attr{slog.String("worker", "second")})
firstOutput := captureStdout(t, func() {
handle(t, first, testRecord("work"))
})
secondOutput := captureStdout(t, func() {
handle(t, second, testRecord("work"))
})
parentOutput := captureStdout(t, func() {
handle(t, parent, testRecord("work"))
})
wantContains(t, firstOutput, "worker=first")
wantNotContains(t, firstOutput, "worker=second")
wantContains(t, secondOutput, "worker=second")
wantNotContains(t, secondOutput, "worker=first")
wantNotContains(t, parentOutput, "worker=")
}
func TestConsoleHandlerWithGroupQualifiesAttrs(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewConsoleHandler().
WithGroup("cast").
WithAttrs([]slog.Attr{slog.String("device", "livingroom")})
record := testRecord("casting", slog.String("file", "movie.mp4"))
handle(t, handler, record)
})
wantContains(t, output, "cast.device=livingroom")
wantContains(t, output, "cast.file=movie.mp4")
}
func TestConsoleHandlerResolvesValues(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewConsoleHandler()
record := testRecord(
"cast failed",
slog.Group("request", slog.Int("status", 502)),
slog.Any("target", castTarget{id: "chromecast-7"}),
slog.Any("error", errConnectionRefused),
)
handle(t, handler, record)
})
wantContains(t, output, "request.status=502")
wantContains(t, output, "target=chromecast-7")
wantContains(t, output, `error="connection refused"`)
}
func TestWebhookHandlerEmitsAttrs(t *testing.T) {
t.Parallel()
bodies := make(chan []byte, 1)
server := httptest.NewServer(http.HandlerFunc(
func(w http.ResponseWriter, r *http.Request) {
body, err := io.ReadAll(r.Body)
if err != nil {
t.Errorf("read webhook body: %v", err)
}
bodies <- body
w.WriteHeader(http.StatusOK)
},
))
defer server.Close()
handler, err := simplelog.NewWebhookHandler(server.URL)
if err != nil {
t.Fatalf("NewWebhookHandler: %v", err)
}
withAttrs := handler.WithAttrs([]slog.Attr{slog.String("service", "cattbox")})
record := testRecord("casting", slog.String("device", "livingroom"))
handle(t, withAttrs, record)
var body []byte
select {
case body = <-bodies:
case <-time.After(5 * time.Second):
t.Fatal("webhook handler posted nothing")
}
decoded := decodeLine(t, string(body))
wantField(t, decoded, "service", "cattbox")
wantField(t, decoded, "device", "livingroom")
}
// TestMultiplexHandlerPassesAttrsThrough guards the composite handler that
// package init installs: attributes must survive the multiplex too. It is
// built while stdout is the capture pipe, which is not a terminal, so it
// writes through the JSON handler.
func TestMultiplexHandlerPassesAttrsThrough(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewMultiplexHandler().
WithAttrs([]slog.Attr{slog.String("service", "cattbox")})
record := testRecord("casting", slog.String("device", "livingroom"))
handle(t, handler, record)
})
decoded := decodeLine(t, output)
wantField(t, decoded, "service", "cattbox")
wantField(t, decoded, "device", "livingroom")
}
// A logging library must read the values it is handed and never write to them.
// The dangerous shape is a group that shares a key with something the caller
// logged by reference: merging the group's members into whatever already sits
// at that key would reach straight back into the caller's own data structure.
// The next four tests hold every handler to that, through both the record path
// and the derived-logger path.
func TestJSONHandlerDoesNotMutateCallerMap(t *testing.T) {
caller := map[string]any{"mine": "untouched"}
want := maps.Clone(caller)
output := captureStdout(t, func() {
handler := simplelog.NewJSONHandler()
record := testRecord(
"casting",
slog.Any("g", caller),
slog.Group("g", slog.Int("injected", 1)),
)
handle(t, handler, record)
})
wantUnchanged(t, "map", caller, want)
// The later attribute wins the key outright, as any repeated key does.
group := wantGroup(t, decodeLine(t, output), "g")
wantField(t, group, "injected", float64(1))
wantNoField(t, group, "mine")
}
func TestJSONHandlerDoesNotMutateCallerMapThroughWithAttrs(t *testing.T) {
caller := map[string]any{"id": "req-1"}
want := maps.Clone(caller)
output := captureStdout(t, func() {
handler := simplelog.NewJSONHandler().
WithAttrs([]slog.Attr{slog.Any("req", caller)}).
WithGroup("req")
record := testRecord("cast failed", slog.Int("status", 502))
handle(t, handler, record)
})
wantUnchanged(t, "map", caller, want)
group := wantGroup(t, decodeLine(t, output), "req")
wantField(t, group, "status", float64(502))
wantNoField(t, group, "id")
}
// TestJSONHandlerDoesNotMutateCallerSlice is the slice form of the same
// hazard: a caller's slice is also handed over by reference, and appending
// into its spare capacity would be just as visible to the caller as writing
// into its map. The slice is built with room to spare so that an append within
// capacity cannot hide behind an unchanged length.
func TestJSONHandlerDoesNotMutateCallerSlice(t *testing.T) {
caller := make([]any, 2, 4)
caller[0] = "first"
caller[1] = "second"
backing := slices.Clone(caller[:cap(caller)])
output := captureStdout(t, func() {
handler := simplelog.NewJSONHandler()
record := testRecord(
"casting",
slog.Any("s", caller),
slog.Group("s", slog.Int("injected", 1)),
)
handle(t, handler, record)
})
wantUnchanged(t, "slice", caller, backing[:2])
wantUnchanged(t, "slice backing array", caller[:cap(caller)], backing)
group := wantGroup(t, decodeLine(t, output), "s")
wantField(t, group, "injected", float64(1))
}
func TestConsoleHandlerDoesNotMutateCallerMap(t *testing.T) {
caller := map[string]any{"mine": "untouched"}
want := maps.Clone(caller)
output := captureStdout(t, func() {
handler := simplelog.NewConsoleHandler()
record := testRecord(
"casting",
slog.Any("g", caller),
slog.Group("g", slog.Int("injected", 1)),
)
handle(t, handler, record)
})
wantUnchanged(t, "map", caller, want)
wantContains(t, output, "g.injected=1")
}
func TestWebhookHandlerDoesNotMutateCallerMap(t *testing.T) {
t.Parallel()
caller := map[string]any{"id": "req-1"}
want := maps.Clone(caller)
bodies := make(chan []byte, 1)
server := httptest.NewServer(http.HandlerFunc(
func(w http.ResponseWriter, r *http.Request) {
body, err := io.ReadAll(r.Body)
if err != nil {
t.Errorf("read webhook body: %v", err)
}
bodies <- body
w.WriteHeader(http.StatusOK)
},
))
defer server.Close()
handler, err := simplelog.NewWebhookHandler(server.URL)
if err != nil {
t.Fatalf("NewWebhookHandler: %v", err)
}
derived := handler.
WithAttrs([]slog.Attr{slog.Any("req", caller)}).
WithGroup("req")
record := testRecord("cast failed", slog.Int("status", 502))
handle(t, derived, record)
var body []byte
select {
case body = <-bodies:
case <-time.After(5 * time.Second):
t.Fatal("webhook handler posted nothing")
}
wantUnchanged(t, "map", caller, want)
group := wantGroup(t, decodeLine(t, string(body)), "req")
wantField(t, group, "status", float64(502))
}
// TestJSONHandlerRendersDurationAsNanoseconds pins the json rendering of a
// duration to a number of nanoseconds, which is what slog.NewJSONHandler
// emits. A consumer that sums or compares the field needs a number; the "3s"
// form would silently arrive as a string.
func TestJSONHandlerRendersDurationAsNanoseconds(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewJSONHandler()
record := testRecord("casting", slog.Duration("elapsed", 3*time.Second))
handle(t, handler, record)
})
decoded := decodeLine(t, output)
if _, isNumber := decoded["elapsed"].(float64); !isNumber {
t.Fatalf("field \"elapsed\" = %#v, want a json number", decoded["elapsed"])
}
wantField(t, decoded, "elapsed", float64((3 * time.Second).Nanoseconds()))
}
// TestConsoleHandlerRendersDurationReadably is the other half of that choice:
// the console line is read by a person, so it carries the same human-readable
// form slog.NewTextHandler uses.
func TestConsoleHandlerRendersDurationReadably(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewConsoleHandler()
record := testRecord("casting", slog.Duration("elapsed", 3*time.Second))
handle(t, handler, record)
})
wantContains(t, output, "elapsed=3s")
}
// TestJSONHandlerContractEdgeCases pins the slog.Handler contract's four
// edge cases. Every case carries a control attribute as well, so a handler
// that emitted no attributes at all would fail rather than pass by omission.
//
// The empty group is attached through WithAttrs rather than to the record,
// because slog.Record.AddAttrs elides empty groups itself: routed through the
// record, the case would never reach the handler at all.
func TestJSONHandlerContractEdgeCases(t *testing.T) {
tests := []struct {
name string
build func() slog.Handler
attrs []slog.Attr
verify func(t *testing.T, decoded map[string]any)
}{
{
name: "empty attr is ignored",
build: func() slog.Handler { return simplelog.NewJSONHandler() },
attrs: []slog.Attr{{}, slog.String("kept", "yes")},
verify: func(t *testing.T, decoded map[string]any) {
t.Helper()
wantField(t, decoded, "kept", "yes")
wantNoField(t, decoded, "")
},
},
{
name: "empty group is elided along with its key",
build: func() slog.Handler {
return simplelog.NewJSONHandler().
WithAttrs([]slog.Attr{slog.Group("empty")})
},
attrs: []slog.Attr{slog.String("kept", "yes")},
verify: func(t *testing.T, decoded map[string]any) {
t.Helper()
wantField(t, decoded, "kept", "yes")
wantNoField(t, decoded, "empty")
},
},
{
name: "group with an empty key is inlined",
build: func() slog.Handler { return simplelog.NewJSONHandler() },
attrs: []slog.Attr{
slog.Group("", slog.String("inner", "yes")),
},
verify: func(t *testing.T, decoded map[string]any) {
t.Helper()
wantField(t, decoded, "inner", "yes")
wantNoField(t, decoded, "")
},
},
{
name: "WithGroup with an empty name is a no-op",
build: func() slog.Handler {
return simplelog.NewJSONHandler().WithGroup("")
},
attrs: []slog.Attr{slog.String("kept", "yes")},
verify: func(t *testing.T, decoded map[string]any) {
t.Helper()
wantField(t, decoded, "kept", "yes")
wantNoField(t, decoded, "")
},
},
}
for _, test := range tests {
t.Run(test.name, func(t *testing.T) {
output := captureStdout(t, func() {
handle(t, test.build(), testRecord("casting", test.attrs...))
})
test.verify(t, decodeLine(t, output))
})
}
}
// TestConsoleHandlerContractEdgeCases holds the console handler to the same
// four rules, since it renders attributes through its own code path.
func TestConsoleHandlerContractEdgeCases(t *testing.T) {
tests := []struct {
name string
build func() slog.Handler
attrs []slog.Attr
want string
notWant string
}{
{
name: "empty attr is ignored",
build: func() slog.Handler { return simplelog.NewConsoleHandler() },
attrs: []slog.Attr{{}, slog.String("kept", "yes")},
want: "kept=yes",
notWant: " =",
},
{
name: "empty group is elided along with its key",
build: func() slog.Handler {
return simplelog.NewConsoleHandler().
WithAttrs([]slog.Attr{slog.Group("empty")})
},
attrs: []slog.Attr{slog.String("kept", "yes")},
want: "kept=yes",
notWant: "empty=",
},
{
name: "group with an empty key is inlined",
build: func() slog.Handler { return simplelog.NewConsoleHandler() },
attrs: []slog.Attr{
slog.Group("", slog.String("inner", "yes")),
},
want: " inner=yes",
notWant: ".inner=",
},
{
name: "WithGroup with an empty name is a no-op",
build: func() slog.Handler {
return simplelog.NewConsoleHandler().WithGroup("")
},
attrs: []slog.Attr{slog.String("kept", "yes")},
want: " kept=yes",
notWant: ".kept=",
},
}
for _, test := range tests {
t.Run(test.name, func(t *testing.T) {
output := captureStdout(t, func() {
handle(t, test.build(), testRecord("casting", test.attrs...))
})
wantContains(t, output, test.want)
wantNotContains(t, output, test.notWant)
})
}
}
// TestJSONHandlerRecordFieldsWinKeyCollision pins a caller-visible surprise:
// the json payload is an object, so the record's own fields own their names
// and an attribute keyed after one of them is dropped rather than emitted.
func TestJSONHandlerRecordFieldsWinKeyCollision(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewJSONHandler()
record := testRecord(
"the real message",
slog.String("Time", "hijacked"),
slog.String("Level", "hijacked"),
slog.String("Message", "hijacked"),
slog.String("PC", "hijacked"),
slog.String("kept", "yes"),
)
handle(t, handler, record)
})
decoded := decodeLine(t, output)
wantField(t, decoded, "kept", "yes")
wantField(t, decoded, "Message", "the real message")
wantField(t, decoded, "Level", "INFO")
for _, reserved := range []string{"Time", "PC"} {
if decoded[reserved] == "hijacked" {
t.Fatalf("attribute overwrote the record's own %q field: %v", reserved, decoded)
}
}
}
// TestJSONHandlerDuplicateKeysKeepLast pins the other consequence of the
// payload being an object: a key logged twice collapses to its last value.
func TestJSONHandlerDuplicateKeysKeepLast(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewJSONHandler()
record := testRecord(
"casting",
slog.String("device", "kitchen"),
slog.String("device", "livingroom"),
)
handle(t, handler, record)
})
wantField(t, decodeLine(t, output), "device", "livingroom")
}
// TestConsoleHandlerKeepsDuplicateKeys is the console counterpart: a line of
// text is not an object, so both pairs survive there.
func TestConsoleHandlerKeepsDuplicateKeys(t *testing.T) {
output := captureStdout(t, func() {
handler := simplelog.NewConsoleHandler()
record := testRecord(
"casting",
slog.String("device", "kitchen"),
slog.String("device", "livingroom"),
)
handle(t, handler, record)
})
wantContains(t, output, "device=kitchen")
wantContains(t, output, "device=livingroom")
}
+6 -2
View File
@@ -1,3 +1,5 @@
// Command example demonstrates logging through simplelog's default
// slog handler.
package main package main
import ( import (
@@ -6,13 +8,15 @@ import (
_ "sneak.berlin/go/simplelog" _ "sneak.berlin/go/simplelog"
) )
func main() { // attemptNumber is the example login attempt count logged below.
const attemptNumber = 3
func main() {
// log structured data with slog as usual: // log structured data with slog as usual:
slog.Info( slog.Info(
"User login attempt", "User login attempt",
slog.String("user", "JohnDoe"), slog.String("user", "JohnDoe"),
slog.Int("attempt", 3), slog.Int("attempt", attemptNumber),
) )
slog.Warn( slog.Warn(
"Configuration mismatch", "Configuration mismatch",
+41 -8
View File
@@ -4,26 +4,41 @@ import (
"context" "context"
"fmt" "fmt"
"log/slog" "log/slog"
"os"
"runtime" "runtime"
"time" "time"
"github.com/fatih/color" "github.com/fatih/color"
) )
type ConsoleHandler struct{} // callerSkipFrames is the number of stack frames between runtime.Caller
// and the slog call site that produced the record.
const callerSkipFrames = 4
// ConsoleHandler writes human-readable, colored log lines to stdout.
type ConsoleHandler struct {
attrs handlerAttrs
}
// NewConsoleHandler returns a new ConsoleHandler.
func NewConsoleHandler() *ConsoleHandler { func NewConsoleHandler() *ConsoleHandler {
return &ConsoleHandler{} return &ConsoleHandler{}
} }
// Handle writes the record to stdout as a colored, timestamped line
// including the caller file and line, followed by the attributes as
// key=value pairs.
func (c *ConsoleHandler) Handle( func (c *ConsoleHandler) Handle(
ctx context.Context, _ context.Context,
record slog.Record, record slog.Record,
) error { ) error {
timestamp := time.Now().UTC().Format("2006-01-02T15:04:05.000Z07:00") timestamp := time.Now().UTC().Format("2006-01-02T15:04:05.000Z07:00")
var colorFunc func(format string, a ...interface{}) string
var colorFunc func(format string, a ...any) string
switch record.Level { switch record.Level {
case slog.LevelDebug:
colorFunc = color.New(color.FgWhite).SprintfFunc()
case slog.LevelInfo: case slog.LevelInfo:
colorFunc = color.New(color.FgBlue).SprintfFunc() colorFunc = color.New(color.FgBlue).SprintfFunc()
case slog.LevelWarn: case slog.LevelWarn:
@@ -35,35 +50,53 @@ func (c *ConsoleHandler) Handle(
} }
// Get the caller information // Get the caller information
_, file, line, ok := runtime.Caller(4) _, file, line, ok := runtime.Caller(callerSkipFrames)
if !ok { if !ok {
file = "???" file = "???"
line = 0 line = 0
} }
fmt.Println(
_, _ = fmt.Fprintln(
os.Stdout,
colorFunc( colorFunc(
"%s [%s] %s:%d: %s", "%s [%s] %s:%d: %s%s",
timestamp, timestamp,
record.Level, record.Level,
file, file,
line, line,
record.Message, record.Message,
attrsToText(c.attrs.forRecord(record)),
), ),
) )
return nil return nil
} }
// Enabled reports whether the handler processes records at the given
// level; it always returns true.
func (c *ConsoleHandler) Enabled( func (c *ConsoleHandler) Enabled(
ctx context.Context, _ context.Context,
level slog.Level, _ slog.Level,
) bool { ) bool {
return true return true
} }
// WithAttrs returns a new handler that also emits attrs, qualified by the
// groups open now. The receiver is not modified.
func (c *ConsoleHandler) WithAttrs(attrs []slog.Attr) slog.Handler { func (c *ConsoleHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
if len(attrs) == 0 {
return c return c
} }
return &ConsoleHandler{attrs: c.attrs.withAttrs(attrs)}
}
// WithGroup returns a new handler that qualifies later attributes with
// the group name. An empty name returns the receiver.
func (c *ConsoleHandler) WithGroup(name string) slog.Handler { func (c *ConsoleHandler) WithGroup(name string) slog.Handler {
if name == "" {
return c return c
} }
return &ConsoleHandler{attrs: c.attrs.withGroup(name)}
}
+4
View File
@@ -7,6 +7,8 @@ import (
"github.com/google/uuid" "github.com/google/uuid"
) )
// Event is a single structured log entry with a unique ID and
// timestamp.
type Event struct { type Event struct {
ID uuid.UUID `json:"id"` ID uuid.UUID `json:"id"`
Timestamp time.Time `json:"timestamp"` Timestamp time.Time `json:"timestamp"`
@@ -15,6 +17,8 @@ type Event struct {
Data json.RawMessage `json:"data"` Data json.RawMessage `json:"data"`
} }
// NewEvent returns an Event with a fresh ID and the current UTC
// timestamp.
func NewEvent(level, message string, data json.RawMessage) Event { func NewEvent(level, message string, data json.RawMessage) Event {
return Event{ return Event{
ID: uuid.New(), ID: uuid.New(),
+1 -1
View File
@@ -2,7 +2,7 @@ package simplelog
import "log/slog" import "log/slog"
// Handler defines the interface for different log outputs. // ExtendedHandler defines the interface for different log outputs.
type ExtendedHandler interface { type ExtendedHandler interface {
slog.Handler slog.Handler
} }
+32 -6
View File
@@ -3,30 +3,56 @@ package simplelog
import ( import (
"context" "context"
"encoding/json" "encoding/json"
"log" "fmt"
"log/slog" "log/slog"
"os"
) )
type JSONHandler struct{} // JSONHandler writes each log record to stdout as a JSON document.
type JSONHandler struct {
attrs handlerAttrs
}
// NewJSONHandler returns a new JSONHandler.
func NewJSONHandler() *JSONHandler { func NewJSONHandler() *JSONHandler {
return &JSONHandler{} return &JSONHandler{}
} }
func (j *JSONHandler) Handle(ctx context.Context, record slog.Record) error { // Handle marshals the record, with its attributes, to one JSON object and
jsonData, _ := json.Marshal(record) // writes it to stdout.
log.Println(string(jsonData)) func (j *JSONHandler) Handle(_ context.Context, record slog.Record) error {
jsonData, err := json.Marshal(recordToMap(record, j.attrs))
if err != nil {
return err
}
_, _ = fmt.Fprintln(os.Stdout, string(jsonData))
return nil return nil
} }
func (j *JSONHandler) Enabled(ctx context.Context, level slog.Level) bool { // Enabled reports whether the handler processes records at the given
// level; it always returns true.
func (j *JSONHandler) Enabled(_ context.Context, _ slog.Level) bool {
return true return true
} }
// WithAttrs returns a new handler that also emits attrs, qualified by the
// groups open now. The receiver is not modified.
func (j *JSONHandler) WithAttrs(attrs []slog.Attr) slog.Handler { func (j *JSONHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
if len(attrs) == 0 {
return j return j
} }
return &JSONHandler{attrs: j.attrs.withAttrs(attrs)}
}
// WithGroup returns a new handler that nests later attributes in an
// object named after the group. An empty name returns the receiver.
func (j *JSONHandler) WithGroup(name string) slog.Handler { func (j *JSONHandler) WithGroup(name string) slog.Handler {
if name == "" {
return j return j
} }
return &JSONHandler{attrs: j.attrs.withGroup(name)}
}
+38
View File
@@ -0,0 +1,38 @@
package simplelog_test
import (
"log/slog"
"testing"
"time"
"sneak.berlin/go/simplelog"
)
// TestJSONHandlerDeadlock verifies that JSONHandler.Handle does not deadlock
// when the default slog handler routes log.Println back through slog.
// On the unfixed code this test will hang (deadlock); with the fix it completes.
func TestJSONHandlerDeadlock(t *testing.T) {
t.Parallel()
handler := simplelog.NewJSONHandler()
// Set our handler as the default so log.Println routes through slog
logger := slog.New(handler)
slog.SetDefault(logger)
done := make(chan struct{})
go func() {
// This call deadlocks on unfixed code because Handle() calls
// log.Println() which re-enters slog → Handle() → log.Println() …
slog.Info("test message")
close(done)
}()
select {
case <-done:
// success
case <-time.After(5 * time.Second):
t.Fatal("JSONHandler.Handle deadlocked: timed out after 5 seconds")
}
}
+41 -7
View File
@@ -1,3 +1,7 @@
// Package simplelog installs a multiplexing slog handler as the process
// default on import. It logs human-readable colored output when stdout is
// a terminal, JSON otherwise, and can additionally POST each record to a
// webhook configured via the LOGGER_WEBHOOK_URL environment variable.
package simplelog package simplelog
import ( import (
@@ -13,23 +17,31 @@ import (
"github.com/mattn/go-isatty" "github.com/mattn/go-isatty"
) )
//nolint:gochecknoglobals // webhook destination is read once from the environment
var webhookURL = os.Getenv("LOGGER_WEBHOOK_URL")
//nolint:gochecknoglobals // package-level default logger state is the package's design
var ( var (
webhookURL = os.Getenv("LOGGER_WEBHOOK_URL") ourCustomLogger *slog.Logger
ourCustomHandler slog.Handler
) )
var ourCustomLogger *slog.Logger //nolint:gochecknoinits // installs itself as slog default on import by design
var ourCustomHandler slog.Handler
func init() { func init() {
ourCustomHandler = NewMultiplexHandler() ourCustomHandler = NewMultiplexHandler()
ourCustomLogger = slog.New(ourCustomHandler) ourCustomLogger = slog.New(ourCustomHandler)
slog.SetDefault(ourCustomLogger) slog.SetDefault(ourCustomLogger)
} }
// MultiplexHandler fans each log record out to a set of underlying
// handlers.
type MultiplexHandler struct { type MultiplexHandler struct {
handlers []ExtendedHandler handlers []ExtendedHandler
} }
// NewMultiplexHandler returns a handler that writes colored console
// output when stdout is a terminal and JSON otherwise, plus an optional
// webhook handler when LOGGER_WEBHOOK_URL is set.
func NewMultiplexHandler() slog.Handler { func NewMultiplexHandler() slog.Handler {
cl := &MultiplexHandler{} cl := &MultiplexHandler{}
if isatty.IsTerminal(os.Stdout.Fd()) { if isatty.IsTerminal(os.Stdout.Fd()) {
@@ -37,52 +49,69 @@ func NewMultiplexHandler() slog.Handler {
} else { } else {
cl.handlers = append(cl.handlers, NewJSONHandler()) cl.handlers = append(cl.handlers, NewJSONHandler())
} }
if webhookURL != "" { if webhookURL != "" {
handler, err := NewWebhookHandler(webhookURL) handler, err := NewWebhookHandler(webhookURL)
if err != nil { if err != nil {
log.Fatalf("Failed to initialize Webhook handler: %v", err) log.Fatalf("Failed to initialize Webhook handler: %v", err)
} }
cl.handlers = append(cl.handlers, handler) cl.handlers = append(cl.handlers, handler)
} }
return cl return cl
} }
// Handle forwards the record to every underlying handler, stopping at
// the first error.
func (cl *MultiplexHandler) Handle( func (cl *MultiplexHandler) Handle(
ctx context.Context, ctx context.Context,
record slog.Record, record slog.Record,
) error { ) error {
for _, handler := range cl.handlers { for _, handler := range cl.handlers {
if err := handler.Handle(ctx, record); err != nil { err := handler.Handle(ctx, record)
if err != nil {
return err return err
} }
} }
return nil return nil
} }
// Enabled reports whether the handler processes records at the given
// level; it always returns true.
func (cl *MultiplexHandler) Enabled( func (cl *MultiplexHandler) Enabled(
ctx context.Context, _ context.Context,
level slog.Level, _ slog.Level,
) bool { ) bool {
// send us all events // send us all events
return true return true
} }
// WithAttrs returns a new MultiplexHandler whose underlying handlers
// each carry the given attributes.
func (cl *MultiplexHandler) WithAttrs(attrs []slog.Attr) slog.Handler { func (cl *MultiplexHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
newHandlers := make([]ExtendedHandler, len(cl.handlers)) newHandlers := make([]ExtendedHandler, len(cl.handlers))
for i, handler := range cl.handlers { for i, handler := range cl.handlers {
newHandlers[i] = handler.WithAttrs(attrs) newHandlers[i] = handler.WithAttrs(attrs)
} }
return &MultiplexHandler{handlers: newHandlers} return &MultiplexHandler{handlers: newHandlers}
} }
// WithGroup returns a new MultiplexHandler whose underlying handlers
// each use the given group name.
func (cl *MultiplexHandler) WithGroup(name string) slog.Handler { func (cl *MultiplexHandler) WithGroup(name string) slog.Handler {
newHandlers := make([]ExtendedHandler, len(cl.handlers)) newHandlers := make([]ExtendedHandler, len(cl.handlers))
for i, handler := range cl.handlers { for i, handler := range cl.handlers {
newHandlers[i] = handler.WithGroup(name) newHandlers[i] = handler.WithGroup(name)
} }
return &MultiplexHandler{handlers: newHandlers} return &MultiplexHandler{handlers: newHandlers}
} }
// ExtendedEvent describes an Event augmented with caller file and line
// information.
type ExtendedEvent interface { type ExtendedEvent interface {
GetID() uuid.UUID GetID() uuid.UUID
GetTimestamp() time.Time GetTimestamp() time.Time
@@ -95,6 +124,7 @@ type ExtendedEvent interface {
type extendedEvent struct { type extendedEvent struct {
Event Event
File string `json:"file"` File string `json:"file"`
Line int `json:"line"` Line int `json:"line"`
} }
@@ -127,6 +157,10 @@ func (e extendedEvent) GetLine() int {
return e.Line return e.Line
} }
// NewExtendedEvent wraps baseEvent with the caller file and line it was
// logged from.
//
//nolint:ireturn // returning the interface is this constructor's public API
func NewExtendedEvent(baseEvent Event, file string, line int) ExtendedEvent { func NewExtendedEvent(baseEvent Event, file string, line int) ExtendedEvent {
return extendedEvent{ return extendedEvent{
Event: baseEvent, Event: baseEvent,
+2 -1
View File
@@ -1,8 +1,9 @@
package simplelog package simplelog_test
import "testing" import "testing"
// TestCompile checks if the package compiles successfully. // TestCompile checks if the package compiles successfully.
func TestCompile(t *testing.T) { func TestCompile(t *testing.T) {
t.Parallel()
// This test ensures that the simplelog package compiles without error. // This test ensures that the simplelog package compiles without error.
} }
+15 -2
View File
@@ -1,3 +1,5 @@
// Command relp_log_trial emits sample log messages through simplelog's
// default slog handler for manual testing.
package main package main
import ( import (
@@ -6,11 +8,22 @@ import (
_ "sneak.berlin/go/simplelog" // Using underscore to only invoke init() _ "sneak.berlin/go/simplelog" // Using underscore to only invoke init()
) )
// examplePort is the sample database port logged below.
const examplePort = 5432
func main() { func main() {
// Send some test messages with structured data // Send some test messages with structured data
slog.Info("Starting the application", slog.String("status", "initialized")) slog.Info("Starting the application", slog.String("status", "initialized"))
slog.Info("Attempting to connect to database", slog.String("host", "localhost"), slog.Int("port", 5432)) slog.Info(
"Attempting to connect to database",
slog.String("host", "localhost"),
slog.Int("port", examplePort),
)
slog.Warn("Using default configuration", slog.String("configuration", "default")) slog.Warn("Using default configuration", slog.String("configuration", "default"))
slog.Error("Failed to load module", slog.String("module", "finance"), slog.String("error", "module not found")) slog.Error(
"Failed to load module",
slog.String("module", "finance"),
slog.String("error", "module not found"),
)
slog.Info("Shutting down the application", slog.String("status", "stopped")) slog.Info("Shutting down the application", slog.String("status", "stopped"))
} }
+64 -20
View File
@@ -10,38 +10,82 @@ import (
"net/url" "net/url"
) )
// WebhookHandler POSTs each log record as JSON to a configured webhook
// URL.
type WebhookHandler struct { type WebhookHandler struct {
webhookURL string webhookURL string
attrs handlerAttrs
} }
func (w *WebhookHandler) Enabled(ctx context.Context, level slog.Level) bool { // NewWebhookHandler returns a WebhookHandler that delivers records to
return true // the given URL, validating the URL first.
}
func (w *WebhookHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
return w
}
func (w *WebhookHandler) WithGroup(name string) slog.Handler {
return w
}
func NewWebhookHandler(webhookURL string) (*WebhookHandler, error) { func NewWebhookHandler(webhookURL string) (*WebhookHandler, error) {
if _, err := url.ParseRequestURI(webhookURL); err != nil { _, err := url.ParseRequestURI(webhookURL)
return nil, fmt.Errorf("invalid webhook URL: %v", err) if err != nil {
return nil, fmt.Errorf("invalid webhook URL: %w", err)
} }
return &WebhookHandler{webhookURL: webhookURL}, nil return &WebhookHandler{webhookURL: webhookURL}, nil
} }
func (w *WebhookHandler) Handle(ctx context.Context, record slog.Record) error { // Enabled reports whether the handler processes records at the given
jsonData, err := json.Marshal(record) // level; it always returns true.
if err != nil { func (w *WebhookHandler) Enabled(_ context.Context, _ slog.Level) bool {
return fmt.Errorf("error marshaling event: %v", err) return true
} }
response, err := http.Post(w.webhookURL, "application/json", bytes.NewBuffer(jsonData))
// WithAttrs returns a new handler that also emits attrs, qualified by the
// groups open now. The receiver is not modified.
func (w *WebhookHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
if len(attrs) == 0 {
return w
}
return &WebhookHandler{
webhookURL: w.webhookURL,
attrs: w.attrs.withAttrs(attrs),
}
}
// WithGroup returns a new handler that nests later attributes in an
// object named after the group. An empty name returns the receiver.
func (w *WebhookHandler) WithGroup(name string) slog.Handler {
if name == "" {
return w
}
return &WebhookHandler{
webhookURL: w.webhookURL,
attrs: w.attrs.withGroup(name),
}
}
// Handle marshals the record, with its attributes, to one JSON object and
// POSTs it to the webhook URL.
func (w *WebhookHandler) Handle(ctx context.Context, record slog.Record) error {
jsonData, err := json.Marshal(recordToMap(record, w.attrs))
if err != nil {
return fmt.Errorf("error marshaling event: %w", err)
}
request, err := http.NewRequestWithContext(
ctx,
http.MethodPost,
w.webhookURL,
bytes.NewReader(jsonData),
)
if err != nil {
return fmt.Errorf("error creating webhook request: %w", err)
}
request.Header.Set("Content-Type", "application/json")
response, err := http.DefaultClient.Do(request)
if err != nil { if err != nil {
return err return err
} }
defer response.Body.Close()
defer func() { _ = response.Body.Close() }()
return nil return nil
} }