diff --git a/cmd/main.go b/cmd/main.go index 4994cdc..8598c90 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -92,6 +92,7 @@ func main() { var gcAllowNamespaced bool var leaseCooldown, maxLeaseTTL time.Duration var showVersion bool + var gcpWireFullPayloads bool 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.") @@ -130,6 +131,8 @@ func main() { "Maximum lease TTL a client may request.") flag.BoolVar(&showVersion, "version", false, "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{ Development: true, @@ -160,7 +163,9 @@ func main() { } providers, err := registry.Build(ctx, cfg, map[string]registry.Constructor{ "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 { setupLog.Error(err, "Failed to build providers") diff --git a/docs/plans-executions/2026-08-11-1838-gcp-http-wire-logging-v5.md b/docs/plans-executions/2026-08-11-1838-gcp-http-wire-logging-v5.md index 1b09629..87ea496 100644 --- a/docs/plans-executions/2026-08-11-1838-gcp-http-wire-logging-v5.md +++ b/docs/plans-executions/2026-08-11-1838-gcp-http-wire-logging-v5.md @@ -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 2 — Tests (`TestWireLogger_gatesAtV5`, `TestWireLogger_infoLandsAtV1`) -- [ ] Step 3 — Live verification at `--zap-log-level=5` (user, on cluster) -- [ ] Step 4 — CHANGELOG entry (after live confirmation; batch with the two - earlier pending entries: GCP V-logging, version stamp) +- [x] Step 3 — Live verification at `--zap-log-level=5` (user, on cluster) +- [x] Step 3b — Post-verification fix: drop auth records, elide huge fields +- [ ] Step 4 — CHANGELOG entry (after live confirmation of 3b; batch with the + two earlier pending entries: GCP V-logging, version stamp) ## Steps 1–2 @@ -35,3 +36,28 @@ Verified with: go test -race ./internal/provider/gcp/ 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. diff --git a/internal/provider/gcp/gcp.go b/internal/provider/gcp/gcp.go index 6071aab..a951f0b 100644 --- a/internal/provider/gcp/gcp.go +++ b/internal/provider/gcp/gcp.go @@ -9,7 +9,6 @@ package gcp import ( "context" "fmt" - "log/slog" "strings" "time" @@ -85,28 +84,27 @@ type Provider struct { 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 // identity in-cluster, gcloud ADC locally — no key-file plumbing). // Deliberately untested: it dials real Google endpoints; everything below // 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) { + 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") if base.V(5).Enabled() { 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 { return nil, fmt.Errorf("creating GCP instances client: %w", err) } diff --git a/internal/provider/gcp/gcp_test.go b/internal/provider/gcp/gcp_test.go index 1dd3a8b..60e526e 100644 --- a/internal/provider/gcp/gcp_test.go +++ b/internal/provider/gcp/gcp_test.go @@ -3,6 +3,7 @@ package gcp import ( "context" "errors" + "log/slog" "strings" "testing" "time" @@ -418,7 +419,7 @@ func TestWireLogger_gatesAtV5(t *testing.T) { *lines = append(*lines, prefix+" "+args) }, funcr.Options{Verbosity: tc.verbosity}) - slogger := wireLogger(base) + slogger := wireLogger(base, WireLogOptions{}) slogger.Debug("api request", "rpcName", "Insert") joined := strings.Join(*lines, "\n") @@ -439,13 +440,84 @@ func TestWireLogger_infoLandsAtV1(t *testing.T) { *lines = append(*lines, prefix+" "+args) }, funcr.Options{Verbosity: 1}) - wireLogger(base).Info("hello") + wireLogger(base, WireLogOptions{}).Info("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) } } +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) { t.Parallel() ctx, lines := captureContext(1) diff --git a/internal/provider/gcp/wirelog.go b/internal/provider/gcp/wirelog.go new file mode 100644 index 0000000..d93423b --- /dev/null +++ b/internal/provider/gcp/wirelog.go @@ -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) +}