# 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"="<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

```bash
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`