From 837e37422805ec69952903aec5caf805d8a1294c Mon Sep 17 00:00:00 2001 From: Jan Novak Date: Tue, 11 Aug 2026 17:48:34 +0200 Subject: [PATCH] Add V(1)/V(2) verbose logging to the GCP provider MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit One V(1) line per GCP API call (insert/get/delete/aggregatedList) with outcome and operation name, V(2) request/per-instance detail, and raw googleapi status+reasons logged before classify collapses them. Curated fields only — cloud-init user-data never reaches logs (test-enforced). Co-Authored-By: Claude --- ...08-11-1742-gcp-provider-verbose-logging.md | 42 +++++ internal/provider/gcp/errors.go | 20 ++ internal/provider/gcp/gcp.go | 63 ++++++- internal/provider/gcp/gcp_test.go | 172 ++++++++++++++++++ 4 files changed, 291 insertions(+), 6 deletions(-) create mode 100644 docs/plans-executions/2026-08-11-1742-gcp-provider-verbose-logging.md diff --git a/docs/plans-executions/2026-08-11-1742-gcp-provider-verbose-logging.md b/docs/plans-executions/2026-08-11-1742-gcp-provider-verbose-logging.md new file mode 100644 index 0000000..71e86dd --- /dev/null +++ b/docs/plans-executions/2026-08-11-1742-gcp-provider-verbose-logging.md @@ -0,0 +1,42 @@ +# Execution: Verbose (V-level) logging in the GCP provider + +Plan: `docs/plans/2026-08-11-1742-gcp-provider-verbose-logging.md` + +- [x] Step 0 — Save and commit the plan +- [x] Step 1 — V(1)/V(2) logging in `internal/provider/gcp` (gcp.go, errors.go) +- [x] Step 2 — Tests (verbosity tiers, error detail, cloud-init leak guard) +- [ ] Step 3 — CHANGELOG entry (after the user confirms it works live) + +## Step 1 — logging in the provider + +Went as planned: context-carried logger (`logf.FromContext(ctx).WithName("gcp")`), +V(1) one line per API call, V(2) request/list detail, opNames captured from the +`instancesAPI` seam instead of being discarded. `logAPIError` lives in +`errors.go` (next to `classify`, whose imports it shares) rather than `gcp.go` +as loosely implied by the plan — same package, so no behavioural difference. +These are the first `.V(n)` calls and the first logging import anywhere under +`internal/provider/`. + +Worth noting: the gopls `errorsastype` suggestion fired on the new +`errors.As` in `logAPIError` (Go's newer `errors.AsType`); kept `errors.As` +for consistency with the three existing uses in the same file. Same for the +`newexpr` (`proto.String` → `new`) suggestions — the codebase consistently +uses `proto.String`. + +## Step 2 — tests + +`funcr.New` as the capturing sink, injected via `logr.NewContext`, exactly the +seam the plan predicted. One deviation: instead of a single +`TestLogging_verbosity` table, it split into three tests — `_verbosityTiers` +(table over V=0/1/2, incl. the cloud-init sentinel leak assertion), +`_apiErrorKeepsHTTPDetail` (403 quotaExceeded keeps `httpStatus`/reason at +V(1)), and `_treatedAsSuccessPathsAreExplicit` (409-on-create / +404-on-delete each log their "treated as success" line) — the last two +exercise fake error wiring that didn't fit the tier table cleanly. + +Verified with: + +```bash +go test -race ./internal/provider/gcp/ +go test ./... +``` diff --git a/internal/provider/gcp/errors.go b/internal/provider/gcp/errors.go index 9fec05b..7607f99 100644 --- a/internal/provider/gcp/errors.go +++ b/internal/provider/gcp/errors.go @@ -5,6 +5,7 @@ import ( "net/http" "slices" + "github.com/go-logr/logr" "google.golang.org/api/googleapi" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/provider" @@ -41,6 +42,25 @@ func (p *Provider) wrapErr(op, id string, err error) error { return provider.Wrap(classify(err), op, p.name, id, err) } +// logAPIError records the raw googleapi error shape (HTTP status, reasons) +// at V(1) — classify collapses it onto the coarser provider taxonomy, so +// this line is the only place the original status survives. +func logAPIError(log logr.Logger, op string, err error) { + if !log.V(1).Enabled() { + return + } + kv := []any{"op", op, "error", err.Error()} + var gerr *googleapi.Error + if errors.As(err, &gerr) { + reasons := make([]string, 0, len(gerr.Errors)) + for _, item := range gerr.Errors { + reasons = append(reasons, item.Reason) + } + kv = append(kv, "httpStatus", gerr.Code, "reasons", reasons) + } + log.V(1).Info("GCP API call failed", kv...) +} + func hasReason(gerr *googleapi.Error, reasons ...string) bool { for _, item := range gerr.Errors { if slices.Contains(reasons, item.Reason) { diff --git a/internal/provider/gcp/gcp.go b/internal/provider/gcp/gcp.go index 19fc0e0..0f43bd4 100644 --- a/internal/provider/gcp/gcp.go +++ b/internal/provider/gcp/gcp.go @@ -14,8 +14,10 @@ import ( compute "cloud.google.com/go/compute/apiv1" "cloud.google.com/go/compute/apiv1/computepb" + "github.com/go-logr/logr" "google.golang.org/api/iterator" "google.golang.org/protobuf/proto" + logf "sigs.k8s.io/controller-runtime/pkg/log" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/provider" ) @@ -101,6 +103,12 @@ func newWithAPI(pc provider.ProviderConfig, api instancesAPI) *Provider { return &Provider{name: pc.Name, cfg: withDefaults(cfg), api: api} } +// logger derives the request-scoped logger from ctx, so provider lines +// inherit the reconcile context (which Proxy triggered the call). +func (p *Provider) logger(ctx context.Context) logr.Logger { + return logf.FromContext(ctx).WithName("gcp").WithValues("provider", p.name) +} + // Create submits the insert and returns immediately with the // zone-qualified providerID. A 409 alreadyExists is success — the // deterministic instance name means a repeat call after a crash found the @@ -113,8 +121,28 @@ func (p *Provider) Create(ctx context.Context, req provider.CreateRequest) (stri "gcp requires placement.zone, placement.machineType and placement.image (got zone=%q machineType=%q image=%q)", pl.Zone, pl.MachineType, pl.Image)) } + log := p.logger(ctx) id := formatProviderID(pl.Zone, req.Name) - if _, err := p.api.Insert(ctx, buildInsertRequest(p.cfg, req)); err != nil && !isAlreadyExists(err) { + insertReq := buildInsertRequest(p.cfg, req) + // Curated fields only: the request proto embeds the cloud-init + // user-data, which may be Secret-sourced and must never reach logs. + log.V(2).Info("GCP insert request built", + "zone", pl.Zone, "name", req.Name, + "network", p.cfg.Network, "networkTag", p.cfg.NetworkTag, + "diskSizeGb", p.cfg.DiskSizeGB, "port", req.Port, + "labels", insertReq.GetInstanceResource().GetLabels(), + "cloudInitBytes", len(req.CloudInit)) + opName, err := p.api.Insert(ctx, insertReq) + switch { + case err == nil: + log.V(1).Info("GCP instance insert submitted", + "zone", pl.Zone, "name", req.Name, + "machineType", pl.MachineType, "image", pl.Image, "opName", opName) + case isAlreadyExists(err): + log.V(1).Info("GCP instance already exists, insert treated as success", + "zone", pl.Zone, "name", req.Name) + default: + logAPIError(log, "create", err) return "", p.wrapErr("create", id, err) } return id, nil @@ -128,15 +156,21 @@ func (p *Provider) Get(ctx context.Context, providerID string) (*provider.Instan if err != nil { return nil, provider.Wrap(provider.ErrPermanent, "get", p.name, providerID, err) } + log := p.logger(ctx) inst, err := p.api.Get(ctx, &computepb.GetInstanceRequest{ Project: p.cfg.Project, Zone: zone, Instance: name, }) if err != nil { + logAPIError(log, "get", err) return nil, p.wrapErr("get", providerID, err) } - return toInstance(inst, zone), nil + out := toInstance(inst, zone) + log.V(1).Info("GCP instance fetched", + "zone", zone, "name", name, + "status", inst.GetStatus(), "state", out.State, "ip", out.IP) + return out, nil } // Delete submits the delete and returns; deleting an instance that is @@ -146,11 +180,21 @@ func (p *Provider) Delete(ctx context.Context, providerID string) error { if err != nil { return provider.Wrap(provider.ErrPermanent, "delete", p.name, providerID, err) } - if _, err := p.api.Delete(ctx, &computepb.DeleteInstanceRequest{ + log := p.logger(ctx) + opName, err := p.api.Delete(ctx, &computepb.DeleteInstanceRequest{ Project: p.cfg.Project, Zone: zone, Instance: name, - }); err != nil && !isNotFound(err) { + }) + switch { + case err == nil: + log.V(1).Info("GCP instance delete submitted", + "zone", zone, "name", name, "opName", opName) + case isNotFound(err): + log.V(1).Info("GCP instance already gone, delete treated as success", + "zone", zone, "name", name) + default: + logAPIError(log, "delete", err) return p.wrapErr("delete", providerID, err) } return nil @@ -160,17 +204,24 @@ func (p *Provider) Delete(ctx context.Context, providerID string) error { // ReturnPartialSuccess matters: without it one unreachable zone fails the // entire GC sweep. func (p *Provider) ListByTag(ctx context.Context) ([]provider.Instance, error) { + log := p.logger(ctx) + filter := fmt.Sprintf("labels.%s = %s", provider.LabelManaged, provider.LabelManagedYes) instances, err := p.api.AggregatedList(ctx, &computepb.AggregatedListInstancesRequest{ Project: p.cfg.Project, - Filter: proto.String(fmt.Sprintf("labels.%s = %s", provider.LabelManaged, provider.LabelManagedYes)), + Filter: proto.String(filter), ReturnPartialSuccess: proto.Bool(true), }) if err != nil { + logAPIError(log, "list", err) return nil, p.wrapErr("list", "", err) } + log.V(1).Info("GCP instances listed", "filter", filter, "count", len(instances)) out := make([]provider.Instance, 0, len(instances)) for _, inst := range instances { - out = append(out, *toInstance(inst, lastPathSegment(inst.GetZone()))) + conv := toInstance(inst, lastPathSegment(inst.GetZone())) + out = append(out, *conv) + log.V(2).Info("GCP listed instance", + "id", conv.ID, "state", conv.State, "uid", conv.UID, "createdAt", conv.CreatedAt) } return out, nil } diff --git a/internal/provider/gcp/gcp_test.go b/internal/provider/gcp/gcp_test.go index 79f44bc..1452e87 100644 --- a/internal/provider/gcp/gcp_test.go +++ b/internal/provider/gcp/gcp_test.go @@ -3,10 +3,13 @@ package gcp import ( "context" "errors" + "strings" "testing" "time" "cloud.google.com/go/compute/apiv1/computepb" + "github.com/go-logr/logr" + "github.com/go-logr/logr/funcr" "google.golang.org/protobuf/proto" "gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/provider" @@ -269,3 +272,172 @@ func TestParseProviderID_roundTrip(t *testing.T) { t.Errorf("round trip = %s/%s (%v), want europe-west1-b/proxy-abc", zone, name, err) } } + +// captureContext returns a ctx carrying a funcr logger that records every +// emitted line, capped at the given verbosity — the test stand-in for +// --zap-log-level=. +func captureContext(verbosity int) (context.Context, *[]string) { + lines := &[]string{} + log := funcr.New(func(prefix, args string) { + *lines = append(*lines, prefix+" "+args) + }, funcr.Options{Verbosity: verbosity}) + return logr.NewContext(context.Background(), log), lines +} + +func runningInstance() *computepb.Instance { + return &computepb.Instance{ + Name: proto.String("proxy-abc123def456ghij"), + Status: proto.String("RUNNING"), + Zone: proto.String("https://www.googleapis.com/compute/v1/projects/my-project/zones/europe-west1-b"), + CreationTimestamp: proto.String("2026-08-09T10:00:00+02:00"), + Labels: map[string]string{ + provider.LabelManaged: provider.LabelManagedYes, + provider.LabelUID: "uid-1", + }, + NetworkInterfaces: []*computepb.NetworkInterface{{ + AccessConfigs: []*computepb.AccessConfig{{NatIP: proto.String("34.1.2.3")}}, + }}, + } +} + +func runAllOps(t *testing.T, ctx context.Context, req provider.CreateRequest) { + t.Helper() + inst := runningInstance() + p := newTestProvider(&fakeAPI{getInst: inst, listInsts: []*computepb.Instance{inst}}) + if _, err := p.Create(ctx, req); err != nil { + t.Fatalf("Create: %v", err) + } + if _, err := p.Get(ctx, "zones/europe-west1-b/instances/proxy-abc123def456ghij"); err != nil { + t.Fatalf("Get: %v", err) + } + if err := p.Delete(ctx, "zones/europe-west1-b/instances/proxy-abc123def456ghij"); err != nil { + t.Fatalf("Delete: %v", err) + } + if _, err := p.ListByTag(ctx); err != nil { + t.Fatalf("ListByTag: %v", err) + } +} + +func TestLogging_verbosityTiers(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + verbosity int + wantLines []string + absentLines []string + }{ + { + name: "v0 stays silent", + verbosity: 0, + absentLines: []string{ + "GCP instance insert submitted", + "GCP instance fetched", + "GCP instance delete submitted", + "GCP instances listed", + }, + }, + { + name: "v1 logs one line per API call", + verbosity: 1, + wantLines: []string{ + `"msg"="GCP instance insert submitted"`, + `"opName"="op-insert"`, + `"msg"="GCP instance fetched"`, + `"status"="RUNNING"`, + `"msg"="GCP instance delete submitted"`, + `"opName"="op-delete"`, + `"msg"="GCP instances listed"`, + `"provider"="gcp-eu"`, + }, + absentLines: []string{ + "GCP insert request built", + "GCP listed instance", + }, + }, + { + name: "v2 adds request and per-instance detail", + verbosity: 2, + wantLines: []string{ + `"msg"="GCP insert request built"`, + `"cloudInitBytes"=`, + `"msg"="GCP listed instance"`, + }, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + ctx, lines := captureContext(tc.verbosity) + req := testCreateRequest() + const sentinel = "SENTINEL-cloud-init-must-never-be-logged" + req.CloudInit = sentinel + + runAllOps(t, ctx, req) + + joined := strings.Join(*lines, "\n") + if tc.verbosity == 0 && len(*lines) != 0 { + t.Errorf("verbosity 0 logged %d lines:\n%s", len(*lines), joined) + } + for _, want := range tc.wantLines { + if !strings.Contains(joined, want) { + t.Errorf("output missing %q:\n%s", want, joined) + } + } + for _, absent := range tc.absentLines { + if strings.Contains(joined, absent) { + t.Errorf("output unexpectedly contains %q:\n%s", absent, joined) + } + } + if strings.Contains(joined, sentinel) { + t.Errorf("cloud-init content leaked into logs:\n%s", joined) + } + }) + } +} + +func TestLogging_apiErrorKeepsHTTPDetail(t *testing.T) { + t.Parallel() + ctx, lines := captureContext(1) + p := newTestProvider(&fakeAPI{insertErr: gerr(403, "quotaExceeded")}) + + if _, err := p.Create(ctx, testCreateRequest()); err == nil { + t.Fatal("Create: want error") + } + + joined := strings.Join(*lines, "\n") + for _, want := range []string{ + `"msg"="GCP API call failed"`, + `"httpStatus"=403`, + `"quotaExceeded"`, + `"op"="create"`, + } { + if !strings.Contains(joined, want) { + t.Errorf("output missing %q:\n%s", want, joined) + } + } +} + +func TestLogging_treatedAsSuccessPathsAreExplicit(t *testing.T) { + t.Parallel() + ctx, lines := captureContext(1) + p := newTestProvider(&fakeAPI{insertErr: gerr(409), deleteErr: gerr(404)}) + + if _, err := p.Create(ctx, testCreateRequest()); err != nil { + t.Fatalf("Create with 409: %v", err) + } + if err := p.Delete(ctx, "zones/z/instances/gone"); err != nil { + t.Fatalf("Delete with 404: %v", err) + } + + joined := strings.Join(*lines, "\n") + for _, want := range []string{ + `"msg"="GCP instance already exists, insert treated as success"`, + `"msg"="GCP instance already gone, delete treated as success"`, + } { + if !strings.Contains(joined, want) { + t.Errorf("output missing %q:\n%s", want, joined) + } + } +}