Logging

Muzak logs through log/slog. The handler it installs picks its format by looking at where its output is going: the aligned console format on a terminal, one JSON object per record anywhere else.

14:32:07.482 INFO  [Server]        Starting Muzak application...
14:32:07.492 INFO  [Server]        Listening on :8080
14:32:10.114 INFO  [Request]       GET /items/  status=200  duration=412µs  bytes=181  request_id=0611f4b2
14:32:10.115 INFO  [UsersService]  user created  user_id=42  request_id=0611f4b2

Colour is used only when the output is a terminal and NO_COLOR is unset.

Reaching the logger

// The application's logger.
log := app.Logger()

// Inside a handler, the same logger with method, path and request_id on every
// record, which joins a line the handler writes to its access log line.
func ListItems(ctx *muzak.Context, _ muzak.Empty) (schemas.ItemListOut, error) {
    ctx.Logger().Info("listing items")
    // ...
}

Scopes

Give each subsystem its own scope so its lines line up in the console and can be filtered in production.

log := muzak.Scoped(app.Logger(), "UsersService")
log.Info("user created", "user_id", 42)

14:32:10.115 INFO  [UsersService]  user created  user_id=42

The scope is an ordinary attribute under muzak.ScopeKey, which the console handler lifts out of the attribute list and renders as the bracketed column after the level. Scoped returns the logger unchanged when it is nil, so it is safe to call on an application that has not been built yet.

The framework uses four scopes of its own, so its lines can be told apart from yours at a glance:

Configuring it

app := muzak.New(muzak.AppOptions{
    Title: "Awesome API",
    LoggerOptions: muzak.LoggerOptions{
        Level:  slog.LevelDebug,
        Format: muzak.LogFormatConsole,
    },
})

Formats

ShortRequestID never applies to JSON output, where the full identifier is always written.

Auto, in a container

A container's stdout is not a terminal, so a service run under Docker or Compose gets JSON even on a laptop. That is the right default for a production container and a surprise in front of docker compose logs. Name the format to read it there, and ask for colour separately, since Color follows its own terminal check:

environment:
  # Both, or the output is JSON with no colour. Production sets json.
  LOG_FORMAT: console
  LOG_COLOR: "true"

muzak.LoggerOptions{
    Format: muzak.LogFormatConsole,
    Color:  &colour, // *bool, so "unset" and "off" stay different things
}

Changing the level at runtime

var level slog.LevelVar

app := muzak.New(muzak.AppOptions{
    Title:         "Awesome API",
    LoggerOptions: muzak.LoggerOptions{Level: &level},
})

// Later, from a handler or a signal:
level.Set(slog.LevelDebug)

Bringing your own logger

app := muzak.New(muzak.AppOptions{
    Title:  "Awesome API",
    Logger: slog.New(myHandler),
})

AppOptions.Logger takes precedence, and LoggerOptions is then unused. To build Muzak's own handler outside an application, call muzak.NewLogger:

log := muzak.NewLogger(muzak.LoggerOptions{Format: muzak.LogFormatJSON})

The result is safe for concurrent use, redacts sensitive attributes, and performs no formatting work for records below its level.

Redaction

Credentials reach logs by accident far more often than by design, most often through an attribute carrying a whole header map. An attribute whose key contains one of these terms has its value replaced with muzak.RedactedPlaceholder, which is [redacted]:

authorization   cookie            password        passwd          secret
token           api-key           private-key     signature       credential
session         jwt               bearer          passphrase      pwd
dsn             connection-string access-key      signing-key     master-key
encryption-key  hmac              totp            otp-code        basic-auth
auth-header     x-auth

log.Info("calling upstream", "api_key", key)

14:32:10.115 INFO  [Upstream]      calling upstream  api_key=[redacted]

Both the key and each term are lower-cased with -, _, . and spaces removed before they are compared, and a key is redacted when its normalised form contains a term. So token catches access_token, X-CSRF-Token and github_token, password catches db_password, api-key catches X-Api-Key, and session catches session_id.

Matching by containment errs towards hiding on purpose: a key such as token_count is redacted too, because a count missing from a log costs far less than a credential written into one. A key that these now hide and that is not a secret can be kept by passing RedactKeys without the term, or renamed.

auth, pass, sig and otp are left out of the list because each sits inside a common word that is not a secret (author, passenger, design, hot_path). The terms that stand for them are the specific spellings above. A secret under a shorter name is added through RedactKeys.

A key names a group as well as a single value. A group whose key matches, whether it was built with slog.Group, produced by a slog.LogValuer or opened with WithGroup, has every value inside it redacted, in the JSON format and the console format alike.

The keys inside a map are matched too. When an attribute's value is an http.Header, url.Values, map[string][]string or map[string]string, each matching entry has its value replaced in a copy, leaving the caller's map untouched, so slog.Any("headers", r.Header) is written with Authorization and Cookie hidden and every other header intact. A struct, a pointer or another map is not looked inside; log the fields you need rather than a whole request or configuration value.

Replace the list with one of your own:

muzak.LoggerOptions{
    RedactKeys: append(muzak.DefaultRedactedKeys, "internal_user_id"),
}

Passing an empty, non-nil slice disables redaction entirely, which is only appropriate when nothing sensitive can reach the logger.

Redaction covers attribute values, not message text. log.Info("token is " + token) is still a leak, and no key-based rule can catch it.

The access log

One line per request, written by the middleware Muzak installs by default.

14:32:10.114 INFO  [Request]       GET /items/  status=200  duration=412µs  bytes=181  request_id=0611f4b2

app := muzak.New(muzak.AppOptions{
    Title: "Awesome API",
    AccessLogOptions: muzak.AccessLogOptions{
        Level:     slog.LevelInfo,
        SkipPaths: []string{"/healthz", "/metrics"},
    },
})

Successful responses use Level. Server errors are always logged at error level and client errors at warn level, so a quiet production level still surfaces failures.

When a route answered, the line also carries its template under route, such as /items/{item_id}, which is what muzak.RouteFromContext returns. A HEAD answered by a GET route is named after that GET route, in the line and in RouteFromContext, rather than carrying no route at all.

Only fixed, non-sensitive fields are recorded. Query strings, request bodies and headers are deliberately omitted, because each of them routinely carries credentials or personal data that should not be duplicated into a log store.

A request whose response had started when it failed, and so aborted the connection, carries aborted=true.

When the application traces requests, the access log line and every record written through ctx.Logger() also carry trace_id and span_id (muzak.TraceIDKey and muzak.SpanIDKey), so a log store can jump from a line to its trace and back. With tracing off the records are unchanged. See Observability.

DisableAccessLog removes the middleware entirely.

The probes AppOptions.Health serves are answered ahead of this middleware and of anything installed with App.Use, and write a line of their own at HealthOptions.AccessLogLevel, debug by default, so a platform probing every few seconds does not drown real traffic. DisableAccessLog and SkipPaths silence them as well. See Health Checks.

What a log line can hold

Every record is exactly one line, and no request can change that. The message carries the decoded request path, so %0a in a URL used to forge log lines, and an escape character drove the operator's terminal. In the console format, control characters, DEL, C1 controls, U+2028, U+2029, bidirectional controls and invalid UTF-8 are escaped. The JSON format escapes the same set (C1 controls, DEL and bidirectional controls included) as \uXXXX, which a JSON reader decodes to the same text, in messages, keys and values logged with slog.Any.

A path or a method is quoted at most 1 KiB long in the access, error and panic logs, and in the 404 and 405 messages. A recovered panic's value is rendered with fmt and cut to 4 KiB with a ...(truncated) marker; the panic attribute is a string in the JSON format for every kind of value. A malformed form body is not written to the error log at all, because its parse error quoted the bad part header whole.

Request identifiers

Every request is assigned one, echoed in the X-Request-Id response header, copied into the request_id member of an error body, and recorded under muzak.RequestIDKey on every log line the request produces.

// Inside a handler.
ctx.RequestID()

// In code that has only a context.Context, such as a repository or a client
// wrapper that wants to propagate the identifier downstream.
id, ok := muzak.RequestIDFromContext(ctx)

A client built with muzak.NewClient already does that downstream: its default Propagate, muzak.DefaultPropagate, copies the identifier into the X-Request-Id header of every request made with the handler's context, without replacing one the caller set. See HTTP Client.

The console handler shortens values under that key to their first eight characters, which keeps a development session narrow while JSON output keeps the identifier in full. Turn it off with ShortRequestID.

Identifiers are UUID version 7, which sort chronologically, so a log store's index on the field is a time index for free.

Logging from a goroutine that outlives the request

A Context is pooled and reused, so it must not be captured. Pass ctx.Context() instead and copy out whatever else you need first. The logger ctx.Logger() returns may be kept: it holds copies of the request's attributes and nothing of the Context, so the goroutine's lines still carry the request identifier of the request that started it.

func Enqueue(ctx *muzak.Context, in JobIn) (JobOut, error) {
    log := muzak.Scoped(ctx.Logger(), "Jobs")
    requestCtx := ctx.Context()
    id := in.ID

    go func() {
        if err := process(requestCtx, id); err != nil {
            log.Error("job failed", "job_id", id, "error", err.Error())
        }
    }()

    return JobOut{ID: id}, nil
}

For work the client should not wait for, ctx.AfterResponse runs a task on a bounded pool once the response is written, with a context that keeps the request's values, so RequestIDFromContext still answers, and that a shutdown drains. See Background Tasks.

Quiet logs in tests

app := muzak.New(muzak.AppOptions{
    Title:         "Awesome API",
    LoggerOptions: muzak.LoggerOptions{Format: muzak.LogFormatNone},
})

Where to go next

Error Handling covers what reaches the log when a request fails, and Testing covers exercising an application in-process.