Compare commits
2 Commits
5a7f0a30c3
...
ed59a4c384
| Author | SHA1 | Date | |
|---|---|---|---|
| ed59a4c384 | |||
| 4619c352c0 |
@@ -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 ./...
|
||||
```
|
||||
85
docs/plans/2026-08-11-1838-gcp-http-wire-logging-v5.md
Normal file
85
docs/plans/2026-08-11-1838-gcp-http-wire-logging-v5.md
Normal file
@@ -0,0 +1,85 @@
|
||||
# Plan: GCP HTTP wire logging at V(5)
|
||||
|
||||
**Created:** 2026-08-11 18:38
|
||||
|
||||
## Context
|
||||
|
||||
The GCP provider logs curated call summaries at V(1)/V(2), but when debugging
|
||||
against the real API the user wants ground truth: the actual HTTP requests and
|
||||
responses ("gory details") — visible at `--zap-log-level=5`, in the same log
|
||||
stream as everything else. The compute SDK already produces exactly this:
|
||||
`cloud.google.com/go/compute@v1.65.0/apiv1/helpers.go:60,70` logs
|
||||
`"api request"`/`"api response"` (method, URL, headers, full JSON payloads,
|
||||
lazily via `internallog.HTTPRequest/HTTPResponse`) to an injectable
|
||||
`*slog.Logger` at slog Debug level. We inject one bridged to the operator's
|
||||
zap sink, level-shifted so those Debug records surface only at V(5).
|
||||
|
||||
Level scheme after this change: V(1) call outcomes, V(2) curated detail,
|
||||
V(5) raw HTTP traffic. V(3)/V(4) reserved.
|
||||
|
||||
## Mechanism (verified in module sources)
|
||||
|
||||
- `option.WithLogger(*slog.Logger)` exists in `google.golang.org/api@v0.292.0`
|
||||
(option.go:529) and **takes precedence over `GOOGLE_SDK_GO_LOGGING_LEVEL`**
|
||||
— after this change, V(5) is the single knob for this client; document that.
|
||||
- `logr.ToSlogHandler` (go-logr/logr v1.4.3, already a direct dep) maps
|
||||
slog Debug → logr V(4), plus the base logger's V-bias. logr's own docs
|
||||
(sloghandler.go:180-184): `slog.New(ToSlogHandler(logrV2)).Debug()` ≈ V(6).
|
||||
So a base of `.V(1)` lands Debug at exactly V(5).
|
||||
- Gating is cheap: the slog handler's `Enabled()` consults the zap sink, so
|
||||
below level 5 the SDK's lazy `LogValuer`s are never evaluated.
|
||||
|
||||
## Implementation
|
||||
|
||||
**`internal/provider/gcp/gcp.go`** (only production file):
|
||||
|
||||
1. New pure function:
|
||||
```go
|
||||
// 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)))
|
||||
}
|
||||
```
|
||||
2. In `New` (gcp.go:96): pass it to the client —
|
||||
`compute.NewInstancesRESTClient(ctx, option.WithLogger(wireLogger(logf.Log.WithName("gcp").WithName("http"))))`.
|
||||
Base is the process-root `logf.Log` (client is built once at startup;
|
||||
`ctrl.SetLogger` runs before `registry.Build` in cmd/main.go, so it
|
||||
resolves to the real zap logger).
|
||||
3. One-time notice in `New`: if `logf.Log.V(5).Enabled()`, log at Info:
|
||||
`"GCP HTTP wire logging active — request payloads include cloud-init user-data"`
|
||||
(the secret-leak warning our curated V(2) logging exists to avoid; at V(5)
|
||||
the user has explicitly opted into raw payloads).
|
||||
4. New imports: `log/slog`, `google.golang.org/api/option` (module already in
|
||||
go.mod as a direct dep; `option` package is a first-time import in the repo).
|
||||
|
||||
**`internal/provider/gcp/gcp_test.go`**:
|
||||
|
||||
- `TestWireLogger_gatesAtV5`: table over funcr sink verbosities
|
||||
(`funcr.Options{Verbosity: N}`, pattern already used by `captureContext`):
|
||||
at 5 a `Debug("api request", ...)` through `wireLogger` emits (message and
|
||||
attrs present); at 4 it emits nothing; an `Info` record through the same
|
||||
logger lands at V(1) (sanity-check of the shift).
|
||||
- `New` itself stays untested by design (dials real Google endpoints —
|
||||
existing convention, gcp.go:86-87).
|
||||
|
||||
No changes to manifests, Makefile, other providers, or the reconciler.
|
||||
CHANGELOG entry after the user confirms it works (house convention) — this
|
||||
plus the two earlier pending entries (GCP V-logging, version stamp).
|
||||
|
||||
## Verification
|
||||
|
||||
```bash
|
||||
go test -race ./internal/provider/gcp/
|
||||
go build ./... && go test ./...
|
||||
```
|
||||
|
||||
Live (the real proof, needs the cluster):
|
||||
|
||||
```bash
|
||||
# rebuild + load image, set --zap-log-level=5, restart, then:
|
||||
kubectl -n egress-proxies-operator-system logs deploy/egress-proxies-operator-controller-manager -f \
|
||||
| grep -m2 'api request\|api response' # full URL/headers/payload visible
|
||||
# and at --zap-log-level=2: the same grep stays silent while V(2) lines still appear
|
||||
```
|
||||
@@ -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)
|
||||
}
|
||||
|
||||
@@ -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)
|
||||
|
||||
Reference in New Issue
Block a user