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 ./...
+```

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) {

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
 }

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=<verbosity>.
+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)
+		}
+	}
+}