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 new file mode 100644 index 0000000..1b09629 --- /dev/null +++ b/docs/plans-executions/2026-08-11-1838-gcp-http-wire-logging-v5.md @@ -0,0 +1,37 @@ +# Execution: GCP HTTP wire logging at V(5) + +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) + +## Steps 1–2 + +Went exactly as planned — the whole feature is ~10 lines of production code +because both halves already existed: the compute SDK logs full HTTP +request/response records at slog Debug to an injectable logger, and +`logr.ToSlogHandler` does the slog→logr bridging. The only real design +content is the level shift (`base.V(1)` + slog-Debug's +4 = V(5)) and the +startup warning line when V(5) is active (raw payloads include cloud-init +user-data, which the curated V(2) logging deliberately hides). + +Worth noting for future readers: + +- `option.WithLogger` **disables** `GOOGLE_SDK_GO_LOGGING_LEVEL` for this + client (documented SDK precedence) — `--zap-log-level` is now the only knob + for GCP wire logs. +- The V(5) check in `New` runs once at startup; that is sound because the zap + level is fixed by flags at process start. +- Added `TestWireLogger_infoLandsAtV1` beyond the plan's table — it pins the + shift arithmetic from the other side (slog Info → V(1)), so a future logr + mapping change would fail loudly. + +Verified with: + +```bash +go test -race ./internal/provider/gcp/ +go build ./... && go test ./... +``` diff --git a/internal/provider/gcp/gcp.go b/internal/provider/gcp/gcp.go index 0f43bd4..6071aab 100644 --- a/internal/provider/gcp/gcp.go +++ b/internal/provider/gcp/gcp.go @@ -9,6 +9,7 @@ package gcp import ( "context" "fmt" + "log/slog" "strings" "time" @@ -16,6 +17,7 @@ import ( "cloud.google.com/go/compute/apiv1/computepb" "github.com/go-logr/logr" "google.golang.org/api/iterator" + "google.golang.org/api/option" "google.golang.org/protobuf/proto" logf "sigs.k8s.io/controller-runtime/pkg/log" @@ -83,12 +85,28 @@ 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) { - client, err := compute.NewInstancesRESTClient(ctx) + 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") + } + client, err := compute.NewInstancesRESTClient(ctx, option.WithLogger(wireLogger(base))) 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 1452e87..1dd3a8b 100644 --- a/internal/provider/gcp/gcp_test.go +++ b/internal/provider/gcp/gcp_test.go @@ -397,6 +397,55 @@ func TestLogging_verbosityTiers(t *testing.T) { } } +func TestWireLogger_gatesAtV5(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + verbosity int + wantDebug bool + }{ + {name: "v5 shows wire records", verbosity: 5, wantDebug: true}, + {name: "v4 hides wire records", verbosity: 4, wantDebug: false}, + {name: "v2 hides wire records", verbosity: 2, wantDebug: false}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + lines := &[]string{} + base := funcr.New(func(prefix, args string) { + *lines = append(*lines, prefix+" "+args) + }, funcr.Options{Verbosity: tc.verbosity}) + + slogger := wireLogger(base) + slogger.Debug("api request", "rpcName", "Insert") + + joined := strings.Join(*lines, "\n") + if got := strings.Contains(joined, "api request"); got != tc.wantDebug { + t.Errorf("Debug record visible = %v, want %v; output:\n%s", got, tc.wantDebug, joined) + } + if tc.wantDebug && !strings.Contains(joined, "rpcName") { + t.Errorf("wire record lost its attrs:\n%s", joined) + } + }) + } +} + +func TestWireLogger_infoLandsAtV1(t *testing.T) { + t.Parallel() + lines := &[]string{} + base := funcr.New(func(prefix, args string) { + *lines = append(*lines, prefix+" "+args) + }, funcr.Options{Verbosity: 1}) + + wireLogger(base).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 TestLogging_apiErrorKeepsHTTPDetail(t *testing.T) { t.Parallel() ctx, lines := captureContext(1)