Skip to content

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

Open
daveseddon-runpod wants to merge 3 commits into
masterfrom
chore/go-1.25-tests-bench
Open

Refresh rplog: Go 1.25.12, dep bump, hardening, tests, benchmarks + leaner logs#2
daveseddon-runpod wants to merge 3 commits into
masterfrom
chore/go-1.25-tests-bench

Conversation

@daveseddon-runpod

Copy link
Copy Markdown

Summary

A refresh of the Go implementation: modernize the toolchain and dependencies, replace the near-absent test suite with rigorous table-driven + security + race tests, harden the untrusted-input paths, add benchmarks, and act on the benchmark analysis. Also trims redundant per-line metadata for a ~40% smaller log line.

Best reviewed commit-by-commit.

What changed

1. Toolchain & dependencies

  • go.mod: go 1.21.6 → 1.25.12; enve v1.0.2 → v1.2.2; go mod tidy (uuid was already latest).
  • CI: Go 1.25.12, added go vet, tests now run with -race, plus a benchmark step. Test bodies modernized to Go 1.25 idioms (b.Loop(), range-over-int, WaitGroup.Go, SplitSeq).

2. Security hardening (trace, log)

trace.FromHeaderOrNew ingests untrusted HTTP headers. It now:

  • validates X-Trace-ID/X-Request-ID as UUIDs (regenerating on garbage/oversized input), and
  • sanitizes X-Trace-Source/X-Request-Source (strips control/CRLF chars, caps length) — closing a log-injection and unbounded-input hole.

Handler.Handle clamps negative elapsed times to 0 (clock skew / hostile CtxWith). The security tests were confirmed to fail against the pre-hardening code and pass after — i.e. they catch real issues (CRLF echoed verbatim, hostile IDs passed through, 10 KB input accepted).

Valid-UUID traffic (what host generates itself) is unaffected — the changes are backward compatible for the normal path.

3. Tests

  • New trace/trace_test.go + expanded log_test.go: table-driven positive / negative / boundary / corner / security cases, plus concurrency tests under -race.
  • Coverage: trace 98.1%, rplog ~71%.

4. Benchmarks & optimization

  • Benchmarks for the trace + log hot paths (see BENCHMARKS.md).
  • FromHeaderOrNew no longer calls time.Parse on an absent X-Trace-Start (the common first-hop case), which was allocating a *ParseError every request: ~7–8% faster, ~30% fewer allocations on the missing/invalid paths.
  • UUID generation dominates the remaining cost and is deliberately left alone (it's the security guarantee).

5. Init refactor + doc fixes

  • Removed the goto FILLED pattern in Init, extracting metadataFromBuildInfo() (behavior unchanged).
  • Rewrote GO_README.md to describe the real API (Init + standard log/slog) — it previously documented Log()/DebugContext/… functions that don't exist — and fixed broken links in both READMEs.

⚠️ Behavior change: leaner per-line logs (opt-in to reuse)

Every record previously carried vcs_name, vcs_commit, vcs_tag, vcs_time and a full source file/line block. On a representative line that's ~475 bytes, ~195 of them (~40%) redundant on every record:

Removed from each line ~bytes
source block (AddSource:false) ~130
vcs_name (always "git"), vcs_tag, vcs_time ~65

Init now stamps vcs_commit only per line (it uniquely identifies the build); the other VCS fields are emitted once in a new structured "rplog initialized" startup record and join back via vcs_commit.

This is optional to adopt — anyone building their own slog.Handler keeps full control. Metadata.Fields() is unchanged (returns the complete set), so Datadog-style tag exporters keep every field.

Why we recommend it (downstream analysis): neither runpod/host nor runpod/ai-api actually emits the full vcs_* set per line today — host logs a single ver, ai-api a single version, and neither calls rplog.Init (host builds its own handler; ai-api doesn't use rplog). Logging that it's "git" on literally every line — along with a redundant timestamp and source block — is pure overhead. This aligns the library default with what real consumers already do. Full write-up in GO_README.md → "Downstream usage".

Verification

  • go build ./..., go vet ./... clean.
  • go test -race -cover ./... green (trace 98.1%).
  • buildmeta sanity-checked end to end.

randomizedcoder and others added 3 commits July 25, 2026 11:22
Toolchain & deps:
- go.mod 1.21.6 -> 1.25.12; enve v1.0.2 -> v1.2.2; go mod tidy
- CI: Go 1.25.12, add go vet, run tests with -race, add benchmark step

Security hardening:
- trace.FromHeaderOrNew validates untrusted X-Trace-ID/X-Request-ID as
  UUIDs (regenerate on garbage/oversized) and sanitizes X-*-Source
  (strip control/CRLF, cap length) -> closes log-injection / unbounded input
- Handler.Handle clamps negative elapsed times to 0 (clock skew / hostile ctx)

Tests:
- New trace/trace_test.go + expanded log_test.go: table-driven
  positive/negative/boundary/corner/security cases, race tests
- trace coverage 98.1%

Benchmarks & optimization:
- Benchmarks for trace + log hot paths
- FromHeaderOrNew skips time.Parse on absent X-Trace-Start:
  ~7-8% faster, ~30% fewer allocs on missing/invalid paths
- Analysis recorded in BENCHMARKS.md

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
- log.go: extract metadataFromBuildInfo() helper, removing the goto FILLED
  label; behavior is unchanged. Correct the Init godoc, which falsely claimed
  the package self-initializes with os.Stderr.
- GO_README.md: rewrite to describe the real API (Init + standard log/slog,
  Metadata, the trace middlewares). Removes references to non-existent
  Log()/DebugContext/InfoContext/... functions, fixes the ../README.md link
  and the broken code blocks.
- README.md: fix Go links (Go lives at the repo root, not ./go; buildmeta
  docs are ./cmd/README.md).

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Every log record previously carried vcs_name, vcs_commit, vcs_tag, vcs_time
plus a full source file/line block (AddSource:true). On a representative line
that is ~475 bytes; ~195 of them (~40%) are redundant on every record.

Changes to rplog.Init:
- Per-line VCS metadata reduced to vcs_commit only. vcs_name (~always "git"),
  vcs_tag, and vcs_time (derivable from the commit) are now emitted once in a
  new structured "rplog initialized" startup record and can be joined back via
  vcs_commit. (~65 bytes/line)
- AddSource now defaults to false: a source block on every record is a large,
  mostly-redundant cost. (~130 bytes/line)
- Replace the stray fmt.Println debug print with the structured startup record.

Metadata.Fields() is unchanged (returns the full set), so Datadog-style tag
exporters keep every field.

Rationale (see GO_README.md "Downstream usage"): neither runpod/host nor
runpod/ai-api emits the full vcs_* set per line today -- host logs a single
`ver`, ai-api a single `version`. This aligns the library default with real
consumers. The savings are opt-in for anyone building their own slog.Handler.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants