Wire logging: drop auth token-exchange records, elide huge payload fields
The option.WithLogger logger also reaches cloud.google.com/go/auth, which logged its token exchange at Debug — JWT assertion and bearer token included. wireLogger now allowlists only the compute client's api request/response records at Debug (fail-closed for future SDK additions); Warn/Error pass through. String fields over 1KiB (e.g. Shielded-VM UEFI dbx blobs) are elided recursively by default; the new --gcp-wire-log-full-payloads flag restores verbatim payloads. Co-Authored-By: Claude <noreply@anthropic.com>
This commit is contained in:
@@ -92,6 +92,7 @@ func main() {
|
|||||||
var gcAllowNamespaced bool
|
var gcAllowNamespaced bool
|
||||||
var leaseCooldown, maxLeaseTTL time.Duration
|
var leaseCooldown, maxLeaseTTL time.Duration
|
||||||
var showVersion bool
|
var showVersion bool
|
||||||
|
var gcpWireFullPayloads bool
|
||||||
|
|
||||||
flag.StringVar(&metricsAddr, "metrics-bind-address", "0", "The address the metrics endpoint binds to. "+
|
flag.StringVar(&metricsAddr, "metrics-bind-address", "0", "The address the metrics endpoint binds to. "+
|
||||||
"Use :8443 for HTTPS or :8080 for HTTP, or leave as 0 to disable the metrics service.")
|
"Use :8443 for HTTPS or :8080 for HTTP, or leave as 0 to disable the metrics service.")
|
||||||
@@ -130,6 +131,8 @@ func main() {
|
|||||||
"Maximum lease TTL a client may request.")
|
"Maximum lease TTL a client may request.")
|
||||||
flag.BoolVar(&showVersion, "version", false,
|
flag.BoolVar(&showVersion, "version", false,
|
||||||
"Print the commit the binary was built from and exit.")
|
"Print the commit the binary was built from and exit.")
|
||||||
|
flag.BoolVar(&gcpWireFullPayloads, "gcp-wire-log-full-payloads", false,
|
||||||
|
"Log GCP V(5) wire payloads verbatim instead of eliding fields larger than 1KiB.")
|
||||||
|
|
||||||
opts := zap.Options{
|
opts := zap.Options{
|
||||||
Development: true,
|
Development: true,
|
||||||
@@ -160,7 +163,9 @@ func main() {
|
|||||||
}
|
}
|
||||||
providers, err := registry.Build(ctx, cfg, map[string]registry.Constructor{
|
providers, err := registry.Build(ctx, cfg, map[string]registry.Constructor{
|
||||||
"kubernetes": kubernetes.New,
|
"kubernetes": kubernetes.New,
|
||||||
"gcp": gcp.New,
|
"gcp": func(ctx context.Context, pc provider.ProviderConfig) (provider.Provider, error) {
|
||||||
|
return gcp.NewWithWireOptions(ctx, pc, gcp.WireLogOptions{FullPayloads: gcpWireFullPayloads})
|
||||||
|
},
|
||||||
})
|
})
|
||||||
if err != nil {
|
if err != nil {
|
||||||
setupLog.Error(err, "Failed to build providers")
|
setupLog.Error(err, "Failed to build providers")
|
||||||
|
|||||||
@@ -4,9 +4,10 @@ Plan: `docs/plans/2026-08-11-1838-gcp-http-wire-logging-v5.md`
|
|||||||
|
|
||||||
- [x] Step 1 — `wireLogger` + `option.WithLogger` wiring in `internal/provider/gcp/gcp.go`
|
- [x] Step 1 — `wireLogger` + `option.WithLogger` wiring in `internal/provider/gcp/gcp.go`
|
||||||
- [x] Step 2 — Tests (`TestWireLogger_gatesAtV5`, `TestWireLogger_infoLandsAtV1`)
|
- [x] Step 2 — Tests (`TestWireLogger_gatesAtV5`, `TestWireLogger_infoLandsAtV1`)
|
||||||
- [ ] Step 3 — Live verification at `--zap-log-level=5` (user, on cluster)
|
- [x] Step 3 — Live verification at `--zap-log-level=5` (user, on cluster)
|
||||||
- [ ] Step 4 — CHANGELOG entry (after live confirmation; batch with the two
|
- [x] Step 3b — Post-verification fix: drop auth records, elide huge fields
|
||||||
earlier pending entries: GCP V-logging, version stamp)
|
- [ ] Step 4 — CHANGELOG entry (after live confirmation of 3b; batch with the
|
||||||
|
two earlier pending entries: GCP V-logging, version stamp)
|
||||||
|
|
||||||
## Steps 1–2
|
## Steps 1–2
|
||||||
|
|
||||||
@@ -35,3 +36,28 @@ Verified with:
|
|||||||
go test -race ./internal/provider/gcp/
|
go test -race ./internal/provider/gcp/
|
||||||
go build ./... && go test ./...
|
go build ./... && go test ./...
|
||||||
```
|
```
|
||||||
|
|
||||||
|
## Step 3b — what live verification exposed, and the fix
|
||||||
|
|
||||||
|
Live V(5) output revealed two problems the plan missed:
|
||||||
|
|
||||||
|
1. **Security: the injected logger propagates into `cloud.google.com/go/auth`**,
|
||||||
|
which logs its own token exchange (`auth.go:571/576`) — signed JWT
|
||||||
|
assertion in the request, full bearer access token in the response. The
|
||||||
|
plan's "auth token is safe" analysis only covered the compute client's
|
||||||
|
request headers, not the auth library's own records. Fix: `wireLogger`
|
||||||
|
now wraps the handler in a filter that drops every Debug record except
|
||||||
|
the compute client's `"api request"`/`"api response"` (allowlist, so
|
||||||
|
future SDK additions fail closed); Warn/Error still pass through.
|
||||||
|
2. **Readability: GCP responses embed multi-KB blobs** (Shielded-VM UEFI
|
||||||
|
dbx databases) that swamp the line. Fix: string fields >1KiB are elided
|
||||||
|
to `[elided N bytes]` by default, recursively through payload
|
||||||
|
maps/arrays. Opt-out via new manager flag
|
||||||
|
`--gcp-wire-log-full-payloads` (threaded through a constructor closure
|
||||||
|
in `cmd/main.go` → `gcp.NewWithWireOptions`; the `registry.Constructor`
|
||||||
|
signature stays unchanged). Chosen by the user: elision on by default,
|
||||||
|
verbatim available on demand. Auth records are dropped in both modes.
|
||||||
|
|
||||||
|
The filter/elision logic lives in `internal/provider/gcp/wirelog.go` with
|
||||||
|
tests covering: auth-record drop (both modes), elision marker + small-field
|
||||||
|
preservation, verbatim mode, and the original V(5) gating.
|
||||||
|
|||||||
@@ -9,7 +9,6 @@ package gcp
|
|||||||
import (
|
import (
|
||||||
"context"
|
"context"
|
||||||
"fmt"
|
"fmt"
|
||||||
"log/slog"
|
|
||||||
"strings"
|
"strings"
|
||||||
"time"
|
"time"
|
||||||
|
|
||||||
@@ -85,28 +84,27 @@ type Provider struct {
|
|||||||
api instancesAPI
|
api instancesAPI
|
||||||
}
|
}
|
||||||
|
|
||||||
// wireLogger returns the slog logger handed to the SDK: its Debug-level
|
|
||||||
// "api request"/"api response" records (slog Debug = +4 on the logr
|
|
||||||
// scale) land at V(5) on top of the base's V(1) shift.
|
|
||||||
func wireLogger(base logr.Logger) *slog.Logger {
|
|
||||||
return slog.New(logr.ToSlogHandler(base.V(1)))
|
|
||||||
}
|
|
||||||
|
|
||||||
// New builds a Provider using Application Default Credentials (workload
|
// New builds a Provider using Application Default Credentials (workload
|
||||||
// identity in-cluster, gcloud ADC locally — no key-file plumbing).
|
// identity in-cluster, gcloud ADC locally — no key-file plumbing).
|
||||||
// Deliberately untested: it dials real Google endpoints; everything below
|
// Deliberately untested: it dials real Google endpoints; everything below
|
||||||
// it is exercised through newWithAPI.
|
// it is exercised through newWithAPI.
|
||||||
//
|
|
||||||
// The injected wire logger surfaces the SDK's raw HTTP request/response
|
|
||||||
// records at V(5); note option.WithLogger overrides the SDK's own
|
|
||||||
// GOOGLE_SDK_GO_LOGGING_LEVEL env var, so --zap-log-level is the only knob.
|
|
||||||
func New(ctx context.Context, pc provider.ProviderConfig) (provider.Provider, error) {
|
func New(ctx context.Context, pc provider.ProviderConfig) (provider.Provider, error) {
|
||||||
|
return NewWithWireOptions(ctx, pc, WireLogOptions{})
|
||||||
|
}
|
||||||
|
|
||||||
|
// NewWithWireOptions is New with explicit control over the V(5) wire
|
||||||
|
// logging; the injected wire logger surfaces the SDK's HTTP
|
||||||
|
// request/response records at V(5). Note option.WithLogger overrides the
|
||||||
|
// SDK's own GOOGLE_SDK_GO_LOGGING_LEVEL env var, so --zap-log-level is
|
||||||
|
// the only knob.
|
||||||
|
func NewWithWireOptions(ctx context.Context, pc provider.ProviderConfig, opts WireLogOptions) (provider.Provider, error) {
|
||||||
base := logf.Log.WithName("gcp").WithName("http")
|
base := logf.Log.WithName("gcp").WithName("http")
|
||||||
if base.V(5).Enabled() {
|
if base.V(5).Enabled() {
|
||||||
logf.Log.WithName("gcp").Info(
|
logf.Log.WithName("gcp").Info(
|
||||||
"GCP HTTP wire logging active — request payloads include cloud-init user-data")
|
"GCP HTTP wire logging active — request payloads include cloud-init user-data",
|
||||||
|
"fullPayloads", opts.FullPayloads)
|
||||||
}
|
}
|
||||||
client, err := compute.NewInstancesRESTClient(ctx, option.WithLogger(wireLogger(base)))
|
client, err := compute.NewInstancesRESTClient(ctx, option.WithLogger(wireLogger(base, opts)))
|
||||||
if err != nil {
|
if err != nil {
|
||||||
return nil, fmt.Errorf("creating GCP instances client: %w", err)
|
return nil, fmt.Errorf("creating GCP instances client: %w", err)
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -3,6 +3,7 @@ package gcp
|
|||||||
import (
|
import (
|
||||||
"context"
|
"context"
|
||||||
"errors"
|
"errors"
|
||||||
|
"log/slog"
|
||||||
"strings"
|
"strings"
|
||||||
"testing"
|
"testing"
|
||||||
"time"
|
"time"
|
||||||
@@ -418,7 +419,7 @@ func TestWireLogger_gatesAtV5(t *testing.T) {
|
|||||||
*lines = append(*lines, prefix+" "+args)
|
*lines = append(*lines, prefix+" "+args)
|
||||||
}, funcr.Options{Verbosity: tc.verbosity})
|
}, funcr.Options{Verbosity: tc.verbosity})
|
||||||
|
|
||||||
slogger := wireLogger(base)
|
slogger := wireLogger(base, WireLogOptions{})
|
||||||
slogger.Debug("api request", "rpcName", "Insert")
|
slogger.Debug("api request", "rpcName", "Insert")
|
||||||
|
|
||||||
joined := strings.Join(*lines, "\n")
|
joined := strings.Join(*lines, "\n")
|
||||||
@@ -439,13 +440,84 @@ func TestWireLogger_infoLandsAtV1(t *testing.T) {
|
|||||||
*lines = append(*lines, prefix+" "+args)
|
*lines = append(*lines, prefix+" "+args)
|
||||||
}, funcr.Options{Verbosity: 1})
|
}, funcr.Options{Verbosity: 1})
|
||||||
|
|
||||||
wireLogger(base).Info("hello")
|
wireLogger(base, WireLogOptions{}).Info("hello")
|
||||||
|
|
||||||
if joined := strings.Join(*lines, "\n"); !strings.Contains(joined, "hello") {
|
if joined := strings.Join(*lines, "\n"); !strings.Contains(joined, "hello") {
|
||||||
t.Errorf("slog Info should land at V(1) and be visible at verbosity 1; output:\n%s", joined)
|
t.Errorf("slog Info should land at V(1) and be visible at verbosity 1; output:\n%s", joined)
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
func captureWireLogger(verbosity int, opts WireLogOptions) (*slog.Logger, *[]string) {
|
||||||
|
lines := &[]string{}
|
||||||
|
base := funcr.New(func(prefix, args string) {
|
||||||
|
*lines = append(*lines, prefix+" "+args)
|
||||||
|
}, funcr.Options{Verbosity: verbosity})
|
||||||
|
return wireLogger(base, opts), lines
|
||||||
|
}
|
||||||
|
|
||||||
|
func TestWireLogger_dropsNonAPIDebugRecords(t *testing.T) {
|
||||||
|
t.Parallel()
|
||||||
|
slogger, lines := captureWireLogger(9, WireLogOptions{})
|
||||||
|
|
||||||
|
const secret = "assertion=eyJhbGciOiJSUzI1NiJ9.SECRET"
|
||||||
|
slogger.Debug("2LO token request", "request", map[string]any{"payload": secret})
|
||||||
|
slogger.Debug("2LO token response", "response", map[string]any{"payload": "ya29.SECRET-TOKEN"})
|
||||||
|
|
||||||
|
if len(*lines) != 0 {
|
||||||
|
t.Errorf("auth token-exchange records must be dropped; got:\n%s", strings.Join(*lines, "\n"))
|
||||||
|
}
|
||||||
|
|
||||||
|
slogger.Warn("credential refresh failed")
|
||||||
|
if joined := strings.Join(*lines, "\n"); !strings.Contains(joined, "credential refresh failed") {
|
||||||
|
t.Errorf("non-debug SDK records should pass through; output:\n%s", joined)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
func TestWireLogger_elidesLargeFields(t *testing.T) {
|
||||||
|
t.Parallel()
|
||||||
|
slogger, lines := captureWireLogger(9, WireLogOptions{})
|
||||||
|
|
||||||
|
huge := strings.Repeat("x", 4096)
|
||||||
|
slogger.Debug("api response", "response", map[string]any{
|
||||||
|
"status": "200",
|
||||||
|
"payload": map[string]any{
|
||||||
|
"name": "proxy-abc",
|
||||||
|
"disks": []any{map[string]any{"content": huge}},
|
||||||
|
},
|
||||||
|
})
|
||||||
|
|
||||||
|
joined := strings.Join(*lines, "\n")
|
||||||
|
if strings.Contains(joined, huge[:64]) {
|
||||||
|
t.Errorf("large field not elided:\n%.500s", joined)
|
||||||
|
}
|
||||||
|
if !strings.Contains(joined, "[elided 4096 bytes]") {
|
||||||
|
t.Errorf("elision marker missing:\n%s", joined)
|
||||||
|
}
|
||||||
|
for _, keep := range []string{"proxy-abc", "200", "api response"} {
|
||||||
|
if !strings.Contains(joined, keep) {
|
||||||
|
t.Errorf("small field %q lost during elision:\n%s", keep, joined)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
func TestWireLogger_fullPayloadsDisablesElision(t *testing.T) {
|
||||||
|
t.Parallel()
|
||||||
|
slogger, lines := captureWireLogger(9, WireLogOptions{FullPayloads: true})
|
||||||
|
|
||||||
|
huge := strings.Repeat("y", 4096)
|
||||||
|
slogger.Debug("api response", "response", map[string]any{"payload": huge})
|
||||||
|
|
||||||
|
joined := strings.Join(*lines, "\n")
|
||||||
|
if !strings.Contains(joined, huge) {
|
||||||
|
t.Errorf("FullPayloads should keep fields verbatim:\n%.200s", joined)
|
||||||
|
}
|
||||||
|
|
||||||
|
slogger.Debug("2LO token response", "response", "ya29.SECRET")
|
||||||
|
if joined := strings.Join(*lines, "\n"); strings.Contains(joined, "ya29.SECRET") {
|
||||||
|
t.Error("auth records must be dropped even with FullPayloads")
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
func TestLogging_apiErrorKeepsHTTPDetail(t *testing.T) {
|
func TestLogging_apiErrorKeepsHTTPDetail(t *testing.T) {
|
||||||
t.Parallel()
|
t.Parallel()
|
||||||
ctx, lines := captureContext(1)
|
ctx, lines := captureContext(1)
|
||||||
|
|||||||
117
internal/provider/gcp/wirelog.go
Normal file
117
internal/provider/gcp/wirelog.go
Normal file
@@ -0,0 +1,117 @@
|
|||||||
|
package gcp
|
||||||
|
|
||||||
|
import (
|
||||||
|
"context"
|
||||||
|
"fmt"
|
||||||
|
"log/slog"
|
||||||
|
|
||||||
|
"github.com/go-logr/logr"
|
||||||
|
)
|
||||||
|
|
||||||
|
// wireLogMaxFieldBytes is the elision threshold for string fields in wire
|
||||||
|
// payloads: GCP responses embed multi-KB blobs (Shielded-VM UEFI dbx
|
||||||
|
// databases, licenses) that swamp the log line without diagnostic value.
|
||||||
|
const wireLogMaxFieldBytes = 1024
|
||||||
|
|
||||||
|
// WireLogOptions controls the V(5) HTTP wire logging of the GCP SDK.
|
||||||
|
type WireLogOptions struct {
|
||||||
|
// FullPayloads disables field elision and logs payloads verbatim.
|
||||||
|
FullPayloads bool
|
||||||
|
}
|
||||||
|
|
||||||
|
// wireLogger returns the slog logger handed to the SDK: its Debug-level
|
||||||
|
// "api request"/"api response" records (slog Debug = +4 on the logr
|
||||||
|
// scale) land at V(5) on top of the base's V(1) shift.
|
||||||
|
//
|
||||||
|
// Debug records other than the compute client's api request/response are
|
||||||
|
// dropped entirely: the same logger propagates into the auth library,
|
||||||
|
// whose token-exchange records contain the signed JWT assertion and the
|
||||||
|
// bearer access token. Warnings and errors pass through.
|
||||||
|
func wireLogger(base logr.Logger, opts WireLogOptions) *slog.Logger {
|
||||||
|
return slog.New(&wireFilterHandler{
|
||||||
|
inner: logr.ToSlogHandler(base.V(1)),
|
||||||
|
fullPayloads: opts.FullPayloads,
|
||||||
|
})
|
||||||
|
}
|
||||||
|
|
||||||
|
type wireFilterHandler struct {
|
||||||
|
inner slog.Handler
|
||||||
|
fullPayloads bool
|
||||||
|
}
|
||||||
|
|
||||||
|
func (h *wireFilterHandler) Enabled(ctx context.Context, level slog.Level) bool {
|
||||||
|
return h.inner.Enabled(ctx, level)
|
||||||
|
}
|
||||||
|
|
||||||
|
func (h *wireFilterHandler) Handle(ctx context.Context, rec slog.Record) error {
|
||||||
|
if rec.Level <= slog.LevelDebug && rec.Message != "api request" && rec.Message != "api response" {
|
||||||
|
return nil
|
||||||
|
}
|
||||||
|
if h.fullPayloads {
|
||||||
|
return h.inner.Handle(ctx, rec)
|
||||||
|
}
|
||||||
|
elided := slog.NewRecord(rec.Time, rec.Level, rec.Message, rec.PC)
|
||||||
|
rec.Attrs(func(a slog.Attr) bool {
|
||||||
|
elided.AddAttrs(slog.Attr{Key: a.Key, Value: elideValue(a.Value)})
|
||||||
|
return true
|
||||||
|
})
|
||||||
|
return h.inner.Handle(ctx, elided)
|
||||||
|
}
|
||||||
|
|
||||||
|
func (h *wireFilterHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
|
||||||
|
return &wireFilterHandler{inner: h.inner.WithAttrs(attrs), fullPayloads: h.fullPayloads}
|
||||||
|
}
|
||||||
|
|
||||||
|
func (h *wireFilterHandler) WithGroup(name string) slog.Handler {
|
||||||
|
return &wireFilterHandler{inner: h.inner.WithGroup(name), fullPayloads: h.fullPayloads}
|
||||||
|
}
|
||||||
|
|
||||||
|
func elideValue(v slog.Value) slog.Value {
|
||||||
|
v = v.Resolve()
|
||||||
|
switch v.Kind() {
|
||||||
|
case slog.KindString:
|
||||||
|
if s := v.String(); len(s) > wireLogMaxFieldBytes {
|
||||||
|
return slog.StringValue(elisionMarker(len(s)))
|
||||||
|
}
|
||||||
|
return v
|
||||||
|
case slog.KindGroup:
|
||||||
|
attrs := v.Group()
|
||||||
|
out := make([]slog.Attr, 0, len(attrs))
|
||||||
|
for _, a := range attrs {
|
||||||
|
out = append(out, slog.Attr{Key: a.Key, Value: elideValue(a.Value)})
|
||||||
|
}
|
||||||
|
return slog.GroupValue(out...)
|
||||||
|
case slog.KindAny:
|
||||||
|
return slog.AnyValue(elideAny(v.Any()))
|
||||||
|
default:
|
||||||
|
return v
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
func elideAny(v any) any {
|
||||||
|
switch t := v.(type) {
|
||||||
|
case string:
|
||||||
|
if len(t) > wireLogMaxFieldBytes {
|
||||||
|
return elisionMarker(len(t))
|
||||||
|
}
|
||||||
|
return t
|
||||||
|
case map[string]any:
|
||||||
|
out := make(map[string]any, len(t))
|
||||||
|
for k, val := range t {
|
||||||
|
out[k] = elideAny(val)
|
||||||
|
}
|
||||||
|
return out
|
||||||
|
case []any:
|
||||||
|
out := make([]any, len(t))
|
||||||
|
for i, val := range t {
|
||||||
|
out[i] = elideAny(val)
|
||||||
|
}
|
||||||
|
return out
|
||||||
|
default:
|
||||||
|
return v
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
func elisionMarker(size int) string {
|
||||||
|
return fmt.Sprintf("[elided %d bytes]", size)
|
||||||
|
}
|
||||||
Reference in New Issue
Block a user