diff --git a/docs/plans/2026-09-10-0805-kvm-libvirt-tracing.md b/docs/plans/2026-09-10-0805-kvm-libvirt-tracing.md new file mode 100644 index 0000000..2c48cf7 --- /dev/null +++ b/docs/plans/2026-09-10-0805-kvm-libvirt-tracing.md @@ -0,0 +1,186 @@ +# 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` +```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"="`, 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"="