187 lines
10 KiB
Markdown
187 lines
10 KiB
Markdown
# 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`
|