# Execution: Trace every libvirt call in the KVM provider

Plan: [2026-09-10-0805-kvm-libvirt-tracing.md](../plans/2026-09-10-0805-kvm-libvirt-tracing.md)

- [x] Step 0 — Save plan
- [x] Step 1 — `errors.go`: shared error fields
- [x] Step 2 — `trace.go`: the `tracingAPI` decorator
- [x] Step 3 — `conn.go`: pool logging and wrapping
- [x] Step 4 — Call sites
- [x] Step 5 — Integration test output
- [x] Step 6 — Unit tests
- [x] Step 7 — Docs, execution log, CHANGELOG

## Steps 1–6 — Tracer, pool logging, tests, integration wiring

Done as one commit on `feat/kvm-provider`; the plan's assumption that
this belongs on the KVM branch rather than its own feature branch was
accepted at plan approval.

The code follows the plan closely. Things that came out differently
or are worth knowing:

- **Logger names join with `/` in funcr, `.` in zap.** The trace lines
  are `kvm/libvirt` in the unit-test capture and in `testr` output, and
  `kvm.libvirt` under the operator's zap logger. The docs use the zap
  spelling; the unit test asserts the funcr one. First run of the tier
  test failed on exactly this.
- **Cancel is not reported as a transport error.** The original `call`
  dropped the connection twice on cancellation (once from the abort
  closure, once from the "not a libvirt error" branch, harmlessly, since
  drop is idempotent). With a log line on each drop that would have
  printed both `context cancelled` and `transport error` for one event,
  so the transport branch now skips `ctx.Err()`. Covered by
  `TestHostPool_call_logsDropReason`.
- **`ConnectListAllDomains` in the fake includes every defined domain**,
  so the trace test's fixture (one running managed domain plus one
  stopped domain for `DomainCreate` to start) lists two; the V(2)
  assertion checks for the `names` key rather than an exact list.
- **`libvirtErrorFields` also feeds `logAPIError`**, which therefore
  gains `libvirtCodeName` (e.g. `ErrNoDomain`) next to the numeric code.
- The seam-coverage guard (`reflect` count of `libvirtAPI` methods vs
  the test table) is the only thing standing between a future 18th RPC
  and a silently untraced call; keep it.

Verification run before committing:

```bash
go build ./... && go vet ./... && go vet -tags=integration ./internal/provider/kvm/
go test -short ./...
go test -race -count=1 -cover ./internal/provider/kvm/   # 90.2 %, up from 88.2
go test -tags=integration -count=1 -run TestKVM ./internal/provider/kvm/   # self-skips without env
```

Worth noting: the live run (`make test-integration-kvm` against beelink)
had not happened when this was written; it is what Step 7 of the KVM
provider plan is waiting on, and its output is the acceptance test for
this feature. Expected shape is in the plan's Verification section.

## Revision after the first live run — less noise, libvirt names

The first live run on beelink showed the trace working but hard to read:
`testr` printed `"ts"`, `"level"`, `"msg"` and the three per-run
constants on every line, the error text appeared twice (`error` and
`libvirtMessage`), `host` appeared twice on image-cache lines (the
logger already carried it), and `method=DomainLookupByName` was
go-libvirt's name rather than something to look up in libvirt's docs.
The user asked for "less verbose but more informative". Changes:

- The tracer's headline field is now `rpc=virDomainLookupByName`: the
  public libvirt API function, which go-libvirt's method names are
  exactly minus the `vir` prefix (they come from the same
  `remote_protocol.x`). Not gRPC, for the record: libvirt's own
  XDR-based RPC over the forwarded unix socket.
- Errors are one `error` field plus `libvirtError=ErrNoDomain` and
  `libvirtCode=42`; `libvirtMessage` is gone from both the tracer and
  `logAPIError`, since it is the error text.
- `image.go` no longer adds `host` to lines whose logger has it.
- The integration test replaces `testr` with a small `compactSink`
  (`logr.LogSink` plus `GetCallStackHelper`, so `t.Log` still
  attributes lines to `trace.go`): `HH:MM:SS.mmm libvirt
  virDomainCreate domain=… duration=… error=… libvirtError=…`. The
  `rpc` value becomes the headline, `provider`/`host`/`name` are
  dropped (the run's first `t.Log` line states them), and values with
  spaces are quoted. Production zap output is unchanged apart from the
  field renames; structured logs are meant to repeat context.

Previewed by driving the sink through the fake provider with an
injected `DomainCreate` failure (a throwaway integration-tagged test,
not committed):

```
trace.go:55: 09:04:33.165 libvirt virDomainLookupByName domain=proxy-abc123def456ghij duration=4µs error="Domain not found: …" libvirtError=ErrNoDomain libvirtCode=42
trace.go:55: 09:04:33.165 libvirt virStorageVolUpload pool=default volume=proxy-abc123def456ghij-seed.iso offset=0 length=0 duration=71µs
kvm.go:262:  09:04:33.165 kvm seed volume uploaded volume=proxy-abc123def456ghij-seed.iso bytes=45056
trace.go:55: 09:04:33.165 libvirt virDomainCreate domain=proxy-abc123def456ghij duration=0s error="internal error: process exited…" libvirtError=ErrResourceBusy libvirtCode=87
```

Worth noting: `length=0` on `virStorageVolUpload` is what the provider
passes (libvirt reads to EOF); the following `seed volume uploaded`
line has the byte count.

## Step 7 — Live run confirmed; CHANGELOG

The compact trace was accepted on the first passing live run
(2026-09-10, beelink): one line per RPC with the libvirt function name,
the provider's own lines between them, `Provisioning` polls readable at
a glance (`SrcArp interfaces=0`, `SrcAgent … ErrAgentUnresponsive`
until the agent came up at +20 s), and a full `ListByTag` sweep over 21
domains in 15 ms. CHANGELOG entry added under the KVM validation entry.