Refresh rplog: Go 1.25.12, dep bump, hardening, tests, benchmarks + leaner logs

.github/workflows/go.yaml

@@ -7,14 +7,18 @@ jobs:
     runs-on: ubuntu-latest
     steps:
       - uses: actions/checkout@v4
-      - name: Setup Go 1.22
+      - name: Setup Go 1.25.12
         uses: actions/setup-go@v5
         with:
-          go-version: 1.22
+          go-version: 1.25.12
       # You can test your matrix by printing the current Go version
       - name: Display Go version
         run: go version
       - name: build all go packages
         run: go build ./...
-      - name: Run tests
-        run: go test -v --cover ./...
+      - name: go vet
+        run: go vet ./...
+      - name: Run tests (race + cover)
+        run: go test -race -v --cover ./...
+      - name: Run benchmarks
+        run: go test -run=^$ -bench=. -benchmem ./...

BENCHMARKS.md

@@ -0,0 +1,52 @@
+# Benchmarks & performance analysis
+
+Environment: linux/amd64, Go 1.25.12.
+Reproduce with:
+
+```sh
+go test -run=^$ -bench=. -benchmem -count=6 ./...
+```
+
+## Baseline (before optimization)
+
+| Benchmark | ns/op | B/op | allocs/op |
+|---|--:|--:|--:|
+| `trace/New` | ~528 | 128 | 4 |
+| `trace/newuuid` | ~238 | 64 | 2 |
+| `trace/FromHeaderOrNew/valid` | ~645 | 32 | 2 |
+| `trace/FromHeaderOrNew/invalid` | ~1231 | 264 | 8 |
+| `trace/FromHeaderOrNew/missing` | ~981 | 240 | 7 |
+| `trace/SaveToHeader` | ~635 | 136 | 8 |
+| `Handler.Handle/with_trace` | ~880 | 0 | 0 |
+| `Handler.Handle/no_trace` | ~303 | 0 | 0 |
+| `FullLogPath` | ~1385 | 48 | 1 |
+
+## Analysis
+
+- **UUID generation dominates** every ID-minting path. `newuuid` (crypto-random
+  UUIDv7 + `.String()`) is ~238ns / 2 allocs and is intrinsic to the `uuid`
+  library and to the security guarantee (unpredictable IDs). `New` is exactly
+  2× `newuuid` — nothing wasteful to remove. **Left unchanged on purpose.**
+- **`Handler.Handle` is already allocation-free** (0 allocs); the `slog` machinery
+  in `FullLogPath` accounts for the single 48 B allocation, which is out of our
+  control. No action.
+- **`FromHeaderOrNew` unconditionally parsed `X-Trace-Start`** even when the header
+  was absent — the common first-hop case. The failed `time.Parse("")` allocated a
+  `*ParseError` on every such request. This was the one clear, safe win.
+
+## Optimization applied
+
+Skip `time.Parse` when `X-Trace-Start` is empty (`trace/trace.go`,
+`FromHeaderOrNew`). Behavior is unchanged (missing/malformed → `now`; future →
+clamped + warned); only wasted work on the absent-header path is removed.
+
+`benchstat` (n=6), before → after:
+
+| Benchmark | ns/op | B/op | allocs/op |
+|---|--:|--:|--:|
+| `FromHeaderOrNew/valid` | −2.8% | ~0% | ~0% |
+| `FromHeaderOrNew/invalid` | −8.2% | 264→184 (−30%) | 8→7 |
+| `FromHeaderOrNew/missing` | −7.3% | 240→160 (−33%) | 7→6 |
+
+No further optimization was pursued: the remaining cost is crypto-random UUID
+generation, which is deliberately not traded away for speed.

GO_README.md

@@ -1,13 +1,153 @@
-# rplog (go)
-This document covers the Go implementation of rplog. For language-independent documentation, see the [overall package documentation](../README.md).
+# rplog (Go)
 
+This document covers the Go implementation of rplog. For the language-independent
+documentation, see the [overall package documentation](./README.md).
 
-## Usage:
-This package provides an ordinary [slog.Logger](https://pkg.go.dev/log/slog) accessible via the `Log()` function. The first call to any function in this package will initialize the logger with the metadata fields described in the [overall package documentation](../README.md).
+`rplog` wraps the standard library's [`log/slog`](https://pkg.go.dev/log/slog) to
+give every service a uniform, structured (JSON) logger that:
 
-Either use the provided `rplog.DebugContext`, `rplog.InfoContext`, `rplog.WarnContext`, and `rplog.ErrorContext` functions to log, or access the `slog.Logger` directly via the `rplog.Log()` function. Traces will automatically be added to the log if a `request_id` is present in the context.
+- stamps build & runtime **metadata** — service, env, VCS commit/tag/time,
+  hostname, instance ID, and language version — onto every record;
+- automatically attaches **trace/request IDs and elapsed timings** taken from the
+  request `context.Context`;
+- writes newline-delimited JSON to one or more `io.Writer`s (typically `os.Stderr`).
+
+## Installation
+
+```sh
+go get github.com/runpod/rplog
+```
+
+## Quick start
+
+Call `rplog.Init` once at startup, then log with the standard `slog` package:
+`Init` installs rplog's handler as the `slog` default via `slog.SetDefault`.
+
+```go
+package main
+
+import (
+	"context"
+	"log/slog"
+	"os"
+
+	"github.com/runpod/rplog"
+)
+
+func main() {
+	// Pass nil to fill the VCS metadata best-effort from the binary's build
+	// info, or supply your own *rplog.Metadata (see "Metadata" below).
+	rplog.Init(nil, os.Stderr)
+
+	slog.Info("starting up", slog.Int("port", 8080))
+	slog.ErrorContext(context.Background(), "boom", slog.String("reason", "example"))
+}
+```
+
+`Init` requires at least one writer and **panics** if none are given. Pass several
+writers to fan out — they are combined with `io.MultiWriter`.
+
+## Metadata
+
+`Init` takes an optional `*rplog.Metadata`:
+
+- pass `nil` to populate the VCS fields best-effort from `debug.ReadBuildInfo`; or
+- generate a fully-populated value at build time with the
+  [`buildmeta`](./cmd/README.md) tool and pass it in.
+
+Every record carries these fields (see the
+[overall docs](./README.md#overview-logs) for the cross-language contract):
+`service`, `env`, `vcs_name`, `vcs_commit`, `vcs_tag`, `vcs_time`, `hostname`,
+`instance_id`, `language_version`.
+
+## Log levels
+
+Levels follow `slog`: `DEBUG`, `INFO`, `WARN`, `ERROR`. The minimum level is read
+once at `Init` from `RUNPOD_LOG_LEVEL` (default `INFO`).
+
+## Tracing
+
+The [`trace`](./trace) subpackage propagates a `Trace` (`trace_id`, `request_id`,
+their source services, and start times) across service boundaries via HTTP
+headers. rplog's handler then automatically adds `trace_id`, `request_id`,
+`trace_elapsed_ms`, and `request_elapsed_ms` to any record logged with a context
+that carries a `Trace`.
+
+Server side — attach a trace to every inbound request:
 
 ```go
-Use the provided `DebugContext`, `InfoContext`, `WarnContext`, and `ErrorContext` functions to log, or access the `slog.Logger` directly.
+mux := http.NewServeMux()
+// ... register handlers ...
+http.ListenAndServe(":8080", trace.ServerMiddleware(mux))
+```
+
+Client side — forward the existing trace (or mint one) on outbound requests:
+
+```go
+http.DefaultClient.Transport = trace.ClientMiddleware(http.DefaultTransport)
+```
+
+Inside a handler, log with the request context so the trace fields appear:
+
+```go
+func handler(w http.ResponseWriter, r *http.Request) {
+	slog.InfoContext(r.Context(), "handling request")
+}
+```
+
+Incoming header values are validated and sanitized: IDs must be well-formed
+UUIDs (a fresh one is minted otherwise), and source names are stripped of
+control characters and length-capped, so untrusted callers cannot inject into or
+bloat your logs.
+
+## Environment variables
+
+| Variable | Description | Default |
+|----------|-------------|---------|
+| `RUNPOD_LOG_LEVEL` | Minimum log level (`DEBUG`/`INFO`/`WARN`/`ERROR`). | `INFO` |
+| `RUNPOD_SERVICE_NAME` | Service name used as the trace/request source. | `unknown` |
+
+The [`buildmeta`](./cmd/README.md) tool emits the remaining `RUNPOD_*` build
+variables for your deployment.
+
+## Design notes: per-line metadata
+
+`Init` keeps each record lean. Only `vcs_commit` — which uniquely identifies the
+build — is stamped on every line; the remaining VCS fields (`vcs_name`, which is
+essentially always `"git"`; `vcs_tag`; and `vcs_time`, derivable from the commit)
+are logged **once** in the `"rplog initialized"` startup record and can be joined
+back via `vcs_commit`. `AddSource` is off by default, since a source file/line
+block on every record is a large, mostly-redundant per-line cost.
+
+For a representative record this trims ~40% of the line (~195 bytes: ~130 from
+dropping the source block, ~65 from the VCS fields). Callers who want richer
+per-line context can build their own `slog.Handler` — see "Downstream usage".
+
+`Metadata.Fields()` still returns the **complete** metadata (all VCS fields +
+`instance_id`), so exporters that want the full set per event (e.g. Datadog tags)
+are unaffected by the per-line trim.
+
+## Downstream usage
+
+How RunPod services consume this package today (useful context if you change the
+logging schema):
+
+- **[`runpod/host`](https://github.com/runpod/host)** — the primary consumer. It
+  uses `rplog/trace` heavily (client/server middleware, `FromHeaderOrNew`) and
+  embeds `rplog.Metadata` in its logger config. It does **not** call `rplog.Init`;
+  instead it builds its own `slog` handler chain (level sampling, a Datadog tee,
+  its own `HandlerOptions`). The full VCS metadata reaches Datadog as **tags** via
+  `Metadata.Fields()`, while its JSON log lines carry a single `ver` field rather
+  than the individual `vcs_*` fields.
+- **`runpod/ai-api`** — does **not** use rplog; it has a home-grown logrus+slog
+  logger that stamps `service`, `env`, and `version` per line.
+
+Takeaway: both services log a single build/version identifier per line rather than
+the full VCS set, which is why `Init` now defaults to `vcs_commit`-only. Because
+`host` controls its own handler options, `Init`'s `AddSource` and per-line
+defaults affect only callers that use `Init` directly.
+
+## Benchmarks
 
-```go
+See [BENCHMARKS.md](./BENCHMARKS.md) for performance numbers and the optimization
+analysis.

README.md

@@ -7,7 +7,7 @@ rplog is runpod's logging and tracing package. It provides a uniform logging imp
 |----------|--------------|
 | Python | [./py](./py) |
 | JavaScript | [./js](./js) |
-| Go | [./go](./go) |
+| Go | [./GO_README.md](./GO_README.md) (package at the repo root) |
 
 
 The following documentation covers language-independent aspects of rplog. For language-specific documentation, see the README in the appropriate subdirectory.
@@ -44,7 +44,7 @@ Generally speaking, `WARN` is to be avoided. If you're logging a warning, you sh
 
 ### Populating your logs with metadata via the `buildmeta` tool
 
-We provide a command-line tool, [buildmeta](./go/cmd/README.md), to populate your logs with metadata. The [releases page](https://github.com/runpod/rplog/releases/) will contain pre-built binaries ready for use: pick the appropriate binary for your platform and put it in your `PATH`.
+We provide a command-line tool, [buildmeta](./cmd/README.md), to populate your logs with metadata. The [releases page](https://github.com/runpod/rplog/releases/) will contain pre-built binaries ready for use: pick the appropriate binary for your platform and put it in your `PATH`.
 
 | OS | ARCH | Binary | Notes |
 |----|------|--------| ------- |
@@ -53,7 +53,7 @@ We provide a command-line tool, [buildmeta](./go/cmd/README.md), to populate you
 | macOS | arm64 | buildmeta_arm64_darwin | newer apple silicon macs |
 | Windows (not WSL) | amd64 | buildmeta_amd64_windows.exe | you probably don't want this |
 
-See the [buildmeta README](./go/cmd/README.md) for information on how to populate your logs with metadata. In short, you should run `buildmeta` as part of your deployment process to inject the build-time metadata into your application, either by generating a `.py` or `.js` file at 'compile time', or by writing a JSON or environment file to disk that's read at runtime.
+See the [buildmeta README](./cmd/README.md) for information on how to populate your logs with metadata. In short, you should run `buildmeta` as part of your deployment process to inject the build-time metadata into your application, either by generating a `.py` or `.js` file at 'compile time', or by writing a JSON or environment file to disk that's read at runtime.
 
 ### Logs: Environment Variables
 

go.mod

@@ -1,8 +1,10 @@
 module github.com/runpod/rplog
 
-go 1.21.6
+go 1.25.12
 
 require (
 	github.com/google/uuid v1.6.0
-	gitlab.com/efronlicht/enve v1.0.2
+	gitlab.com/efronlicht/enve v1.2.2
 )
+
+require gitlab.com/efronlicht/unit v1.0.0 // indirect

go.sum

@@ -1,4 +1,6 @@
 github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0=
 github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
-gitlab.com/efronlicht/enve v1.0.2 h1:ryivgFrms/4s/sM/ooOeoxZVN/kuwrwxvSSpjoFxhYA=
-gitlab.com/efronlicht/enve v1.0.2/go.mod h1:wDL62C+Pe/M4f4F1ubLkKo1lJnYYWvXbl6yQSzS+8D8=
+gitlab.com/efronlicht/enve v1.2.2 h1:W36cdBlADEhGHBweKb43QkEFpxI/EMVUGrzzqUR16IE=
+gitlab.com/efronlicht/enve v1.2.2/go.mod h1:Yo1/Uc2XjRH0p2tKXJwtZGL61VANtjVUBAQK4k5SOmM=
+gitlab.com/efronlicht/unit v1.0.0 h1:2tCBZGuBy0Lyj3ssvseFdOICsPOd0zDKB0+XOVMfUV0=
+gitlab.com/efronlicht/unit v1.0.0/go.mod h1:TW/2N/y/LW6CC+23MuDDzeLDq4S4dktfpBYzgPn9/08=