egress-proxies-operator/docs/plans/2026-09-10-0805-kvm-libvirt-tracing.md

Plan: Trace every libvirt call in the KVM provider

Created: 2026-09-10 08:05

Context

Step 7 of the KVM provider plan (live validation on beelink) has gone through three fixes found only on the real host, and the current failure (guest hangs at GRUB's "Booting" line) is being diagnosed blind: the provider logs at V(1)/V(2) but nothing shows them. The integration test never installs a logger, so controller-runtime prints "log.SetLogger(...) was never called" and swallows everything; and even with a logger, the provider only logs per operation (Create, Get…), not per libvirt RPC, so the sequence and timing of what was actually sent to the hypervisor is invisible.

Goal: one log line per libvirt call at debug level (--zap-log-level=debug, logr V(1) in this repo's scheme: V(1) = outcome per operation, V(2) = curated detail, V(5) = raw wire, per the GCP verbose-logging plans), with method, host, domain or volume, duration and the libvirt error code on failure; and those lines visible in make test-integration-kvm output.

Assumption: this lands on the current feat/kvm-provider branch, since it exists to finish that branch's validation, and the plan file plus execution log follow CLAUDE.md conventions (plan committed alone first, execution summary alongside each step). Say so if you want a separate branch instead.

Design

• Decorator, not call-site logging. New tracingAPI implements the 17-method libvirtAPI seam (internal/provider/kvm/conn.go:26-44), wrapping the real client. Every method logs one V(1) line after the inner call returns. Applied in hostPool.call, so every provider method, image.go's cache and the integration test's own p.hosts.call are traced with no per-site changes.
• Logger passed explicitly. call(ctx, log, host, fn) and get(ctx, log, host) gain a logr.Logger parameter, matching how this package already threads log into every helper. The five call sites (kvm.go:169, 322, 458, 530, kvm_integration_test.go:220) already hold the right logger with provider/host/name values. call does log = log.WithName("libvirt"), so trace lines are named kvm.libvirt.
• Wrap only when log.V(1).Enabled(). Zero cost at info level; the controller-runtime unfulfilled root sink reports disabled, so unit tests and conn_test.go's hostClient{api: nil} cases are unaffected.
• One line per RPC at every level. At V(2) the same line gains extra keys (xml, metadata, addresses, names) instead of a second line. Upload and download log offset/length/duration only, never bytes (the seed ISO carries cloud-init). Domain and volume XML contain no secrets, so V(2) is fine for them.
• Connection events traced too in the pool: dial with duration, dial failure, dead cached client redial, and both drop reasons (context cancelled, transport error). dialSSH/connectLibvirt/keepalive stay untouched: changing hostDialer's signature would ripple into every test dialer, and the pool already observes every event.
• Rendering. Handles by name only (domain, pool, volume), never UUID/Key. libvirt.DomainState and DomainInterfaceAddressesSource have stringers, pass them typed. Bitmask flags don't stringify, log as integers only when non-zero. libvirt.OptString → first element or "" under uri.
• awaitOrCancel. done runs inside fn's goroutine; on the normal path it logs before call returns. On cancel, the abandoned RPC logs one late line when the closed connection makes it fail: desirable in production, and in the integration test only reachable in an already-failing timeout run (testr panics on a log after the test ends; note that in the header, don't engineer around it).

Steps

Step 0 — Save plan

Copy this file to docs/plans/2026-09-10-0805-kvm-libvirt-tracing.md, commit alone.

Step 1 — errors.go: shared error fields

Factor libvirtErrorFields(err error) []any out of logAPIError (errors.go:62-72): returns libvirtCode (uint32), libvirtCodeName (libvirt.ErrorNumber(code), e.g. ErrNoDomain), libvirtMessage; nil for non-libvirt errors; works through %w wrapping via errors.As. logAPIError keeps its message and gains libvirtCodeName. Test TestLibvirtErrorFields (table: libvirt.Error, wrapped, plain error) in errors_test.go.

Step 2 — new trace.go

type tracingAPI struct { inner libvirtAPI; log logr.Logger }
type tracedCall struct { t *tracingAPI; method string; start time.Time; kv []any }
func (t *tracingAPI) begin(method string, kv ...any) *tracedCall
func (c *tracedCall) detail(kv ...any) *tracedCall // appended only if V(2) enabled
func (c *tracedCall) done(err error, kv ...any)    // one V(1) line

done emits log.V(1).Info("libvirt call", ...) with keys in order: method, begin args, result kv, duration (rounded to µs), then on error error plus libvirtErrorFields. Per-method keys:

method	V(1) args	V(1) results	V(2) extra
DomainLookupByName	domain
DomainDefineXML	xmlBytes	domain	xml
DomainCreate, DomainDestroy	domain
DomainUndefineFlags	domain, flags
DomainGetState	domain	state, reason
DomainGetMetadata	domain, type, uri	metadataBytes	metadata
DomainInterfaceAddresses	domain, source	interfaces (count)	addresses
ConnectListAllDomains		count	names
StoragePoolLookupByName, StoragePoolRefresh	pool
StorageVolLookupByName	pool, volume
StorageVolGetPath	pool, volume	path
StorageVolCreateXML	pool, xmlBytes	volume	xml
StorageVolUpload, StorageVolDownload	pool, volume, offset, length		(never content)
StorageVolDelete	pool, volume

Return values pass through untouched.

Step 3 — conn.go: pool logging and wrapping

• get(ctx, log, host): dead cached client → "libvirt connection lost, redialing"; time the dial; "libvirt host connected" with address, duration; failure → "libvirt host dial failed" with address, duration, error.
• call(ctx, log, host, fn): log = log.WithName("libvirt"); wrap when log.V(1).Enabled(); abort closure logs "libvirt connection dropped" reason="context cancelled" before drop; transport-error branch logs the same message with reason="transport error". Update call's doc comment.

Step 4 — call sites

kvm.go Create/Get/Delete pass log, ListByTag passes hlog; kvm_integration_test.go:220 passes p.logger(ctx).WithValues("host", host.Name); conn_test.go (12 p.call( sites) gets var discard = logr.Discard().

Step 5 — integration test output

• integrationLogger(t): KVM_TEST_LOG_LEVEL (default 1, strconv.Atoi, t.Fatalf on garbage) → testr.NewWithOptions(t, testr.Options{LogTimestamp: true, Verbosity: n}) (github.com/go-logr/logr/testr, present in logr v1.4.3, no go.mod change); logf.SetLogger(log) once so nothing falls back to the unfulfilled root.
• TestKVM_lifecycle: ctx = logr.NewContext(ctx, log) after WithTimeout; the cleanup ctx gets the same logger.
• Header comment: document KVM_TEST_LOG_LEVEL (1 = one line per RPC, 2 adds XML/metadata/addresses, 0 = only t.Log) and the late-line-after-timeout caveat.

Step 6 — unit tests

• kvm_test.go: captureContext(verbosity) like gcp_test.go:277-286 but with a mutex around the slice; TestLogging_verbosityTiers (mirror gcp_test.go:322-399): V0 → no lines; V1 → "msg"="libvirt call", "method"="DomainDefineXML", "method"="StorageVolUpload", "msg"="libvirt host connected", provider/host/name values, "libvirtCodeName"="ErrNoDomain" from the first lookup, no "xml"=; V2 → "xml"="<domain and "metadata"=; a cloud-init sentinel absent at every tier.
• trace_test.go: TestTracingAPI_logsEveryMethod (table of 17 calls over a readyHost() fake, exactly one line each, plus reflect.TypeOf((*libvirtAPI)(nil)).Elem().NumMethod() == len(cases) so a new interface method without tracing fails); TestTracingAPI_passesResultsThrough; TestTracingAPI_errorFields (libvirt error → code/name/message; io.EOF → "error"="EOF", no code); TestTracingAPI_detailOnlyAtV2; TestTracingAPI_uploadLogsSizeNotContent.
• conn_test.go: fakeDialer gains an api field; TestHostPool_call_tracesAtV1 (V1 → connected + method lines; V0 → no lines and fn receives the bare *fakeAPI); TestHostPool_call_logsDropReason (transport error, cancel).

Step 7 — docs, execution log, CHANGELOG

• docs/kvm-provider.md: ## Logging section before "Known gaps": --zap-log-level=debug = one libvirt call line per RPC plus connect/drop lines; --zap-log-level=2 adds XML, metadata, addresses; cloud-init never logged; no V(5) wire tier because go-libvirt exposes no hook. Mention KVM_TEST_LOG_LEVEL in its Testing paragraph.
• docs/testing.md: KVM_TEST_LOG_LEVEL in the optional vars; -v now shows every RPC; extend the kvm_test.go table row.
• docs/plans-executions/2026-09-10-0805-kvm-libvirt-tracing.md with the checklist and per-step entries; also a short cross-reference line in the KVM provider execution log's Step 7 section.
• CHANGELOG.md entry once the user confirms the live run shows the trace.

Verification

go build ./... && go vet ./... && go vet -tags=integration ./internal/provider/kvm/
go test -race -count=1 ./internal/provider/kvm/
go test -short ./...

Live, with the usual env: make test-integration-kvm. Expect, interleaved with t.Log lines and attributed to trace.go:<line>, lines like

kvm.libvirt: "level"=1 "msg"="libvirt call" "provider"="kvm-integration" "host"="kvm-test" "name"="proxy-…" "method"="DomainLookupByName" "domain"="proxy-…" "duration"="2.1ms" "error"="…" "libvirtCode"=42 "libvirtCodeName"="ErrNoDomain" "libvirtMessage"="…"

plus one libvirt host connected line with duration, a StorageVolUpload line whose duration is the seed upload, and no "log.SetLogger(...) was never called" text. KVM_TEST_LOG_LEVEL=2 shows "xml"="<domain and "addresses"=; KVM_TEST_LOG_LEVEL=0 shows only t.Log output. No line at any level contains #cloud-config.

Critical files

• internal/provider/kvm/conn.go, trace.go (new), trace_test.go (new)
• internal/provider/kvm/errors.go, errors_test.go
• internal/provider/kvm/kvm.go, kvm_test.go, conn_test.go
• internal/provider/kvm/kvm_integration_test.go
• docs/kvm-provider.md, docs/testing.md