docs/kvm-provider.md

@@ -186,6 +186,27 @@ replaces the VM).
 - `virsh domifaddr proxy-abc… --source arp` / `--source agent` shows what
   the operator sees when it looks for the IP.
 
+## Logging
+
+The provider logs through controller-runtime's logger, named `kvm`, with
+`provider`, `host` and `name` (the domain) on every line.
+
+- `--zap-log-level=debug` (logr V(1)): one line per provider operation
+  (`domain defined`, `KVM domain ensured running`, ...) **and one
+  `libvirt call` line per libvirt RPC**, named `kvm.libvirt`, with
+  `method`, the identifiers it was given (`domain`, `pool`, `volume`),
+  curated results (`state`, `path`, `interfaces`), `duration`, and on
+  failure `error` plus `libvirtCode`, `libvirtCodeName` and
+  `libvirtMessage`. Connection events (`libvirt host connected`, dial
+  failures, `libvirt connection dropped` with a reason) log at the same
+  level. A Create is about ten RPCs; a Get is four.
+- `--zap-log-level=2`: the same lines also carry the domain and volume
+  `xml`, the `metadata` element, the interface `addresses` and the
+  domain `names` from a listing.
+- Cloud-init is never logged at any level: the seed ISO upload reports
+  only `length` and `duration`. There is no raw wire tier like the GCP
+  provider's V(5); go-libvirt exposes no hook for it.
+
 ## Known gaps
 
 - **No quota or capacity detection.** libvirt reports an out-of-space
@@ -211,4 +232,6 @@ replaces the VM).
 
 Unit tests run over an in-memory fake of the libvirt API. The optional
 integration test against a real host is described in
-[testing.md](testing.md#the-kvm-integration-test-real-hypervisor).
+[testing.md](testing.md#the-kvm-integration-test-real-hypervisor); its
+`-v` output includes the `libvirt call` trace above, at the verbosity
+`KVM_TEST_LOG_LEVEL` selects (default 1).

docs/plans-executions/2026-09-04-1404-kvm-provider.md

@@ -462,3 +462,18 @@ lookup already selected the element by URI. The fake now strips the
 declaration when storing metadata, so the provider's Get and ListByTag
 tests parse the shape libvirt really returns, and a new
 `TestParseInstanceMetadata_libvirtBareForm` pins it.
+
+### Run 4: guest hangs at GRUB's "Booting" line
+
+Create and start passed; Get polled `Provisioning` with no IP while the
+VM sat at 100 % CPU after GRUB printed "Booting `Debian GNU/Linux`" and
+before the kernel wrote anything to the serial console. The domain XML
+matches a working VM on the same host (q35, BIOS, host-passthrough,
+virtio disk, SATA cdrom, br0), so the difference is the disk content:
+the cached image was downloaded without a checksum and never verified.
+Diagnosis was handed to the user (sha512 against Debian's published
+sums, `qemu-img check`, and a `virt-install --import` of the same image
+outside the operator). Because the provider's own logs were invisible in
+the test output, this run also produced a side plan:
+[2026-09-10-0805-kvm-libvirt-tracing](2026-09-10-0805-kvm-libvirt-tracing.md),
+which traces every libvirt RPC at V(1) and routes it into `-v` output.

docs/plans-executions/2026-09-10-0805-kvm-libvirt-tracing.md

@@ -0,0 +1,57 @@
+# 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
+- [ ] Step 7 — Docs, execution log, CHANGELOG (docs and this log done; CHANGELOG waits for the live run)
+
+## 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.

docs/testing.md

@@ -56,7 +56,8 @@ manual runs too.
 | `internal/provider/gcp` | `insert_test.go`, `errors_test.go`, `gcp_test.go` | field-by-field `buildInsertRequest`; HTTP-code classification table; zone-qualified IDs, 409-is-success, 9-row state mapping, ListByTag filter + `ReturnPartialSuccess` | pure builder needs **no fake**; the rest uses the flattened `instancesAPI` seam |
 | `internal/provider/kvm` | `domainxml_test.go`, `volume_test.go`, `seed_test.go`, `id_test.go`, `metadata_test.go` | pure builders: domain/volume XML unmarshalled back and checked field by field, seed ISO reopened with the same library, providerID round-trip, metadata in both namespace spellings | pure |
 | | `errors_test.go`, `conn_test.go` | libvirt-code classification table; connection pool (reuse, redial, drop on transport error, cancel releases a blocked RPC, one dial per host under concurrency); SSH dial, host-key policy, keepalive | fake dialer; a **real in-process `x/crypto/ssh` server** forwarding a unix socket |
-| | `image_test.go`, `kvm_test.go` | image cache (fresh fetch, ready, marker missing, checksum change/mismatch, 4xx/5xx, concurrent callers); Create resume after every partial step, leftover truncated seed, state/IP mapping, every Delete already-gone case, ListByTag across hosts / one down / unreadable domain | `httptest` image server + in-memory `fakeAPI` behind the `libvirtAPI` seam |
+| | `image_test.go`, `kvm_test.go` | image cache (fresh fetch, ready, marker missing, checksum change/mismatch, 4xx/5xx, concurrent callers); Create resume after every partial step, leftover truncated seed, state/IP mapping, every Delete already-gone case, ListByTag across hosts / one down / unreadable domain; logging tiers (V0 silent, V1 one line per RPC, V2 XML) with cloud-init never logged | `httptest` image server + in-memory `fakeAPI` behind the `libvirtAPI` seam |
+| | `trace_test.go`, `conn_test.go`, `errors_test.go` | every `libvirtAPI` method traced exactly once (guarded by reflection on the interface), results and errors pass through, libvirt error fields, detail keys only at V2, upload content never logged; pool connect/drop lines, no wrapping below V1 | `fakeAPI` + `funcr` capture |
 | | `kvm_integration_test.go` (`-tags=integration`) | one real VM: image fetch, Create, idempotent re-Create, Running with IP, ListByTag, Delete, pool state afterwards | a **real hypervisor** — see below |
 | `internal/health` | `probe_test.go` | probes through a **real CONNECT-capable proxy stub** to a real TLS server: tunnel success, refused CONNECT, wrong status, dead proxy, plain-http forward | `httptest` + hijacked bidirectional tunnel |
 | | `engine_test.go` | thresholds, first-verdict, latency suppression matrix, dropped-event retry, stale-probe UID guard, tick scheduling/seeding/pruning, `Start` end-to-end | fake `client.Reader` + injected `probeFn` |
@@ -116,8 +117,14 @@ make test-integration-kvm
 Optional: `KVM_TEST_KNOWN_HOSTS` (without it host keys are **not**
 verified — the log says so), `KVM_TEST_IMAGE_SHA256`, `KVM_TEST_POOL`
 (default `default`), `KVM_TEST_SOCKET`, `KVM_TEST_TIMEOUT` (default
-`20m`, must cover the first-time image download), and `KVM_TEST_KEEP`
-to leave the VM behind for `virsh console` when something goes wrong.
+`20m`, must cover the first-time image download), `KVM_TEST_KEEP`
+to leave the VM behind for `virsh console` when something goes wrong,
+and `KVM_TEST_LOG_LEVEL` (default `1`) for how much of the provider's
+logging the `-v` output shows: at `1` every libvirt RPC is one
+`libvirt call` line with method, identifiers, duration and error code,
+interleaved with the test's own `t.Log` lines; `2` adds the domain and
+volume XML, metadata and addresses; `0` leaves only `t.Log`. See the
+Logging section of [kvm-provider.md](kvm-provider.md#logging).
 
 What one run asserts, in order: `New` dials the host; `Create` returns a
 `hosts/<host>/domains/<name>` ID (downloading the image on a cold host —

internal/provider/kvm/conn.go

@@ -2,6 +2,7 @@ package kvm
 
 import (
 	"context"
+	"errors"
 	"fmt"
 	"io"
 	"net"
@@ -10,6 +11,7 @@ import (
 	"time"
 
 	libvirt "github.com/digitalocean/go-libvirt"
+	"github.com/go-logr/logr"
 	"golang.org/x/crypto/ssh"
 	"golang.org/x/crypto/ssh/knownhosts"
 
@@ -95,7 +97,7 @@ func (p *hostPool) entry(name string) *hostEntry {
 	return e
 }
 
-func (p *hostPool) get(ctx context.Context, host provider.KVMHost) (*hostClient, error) {
+func (p *hostPool) get(ctx context.Context, log logr.Logger, host provider.KVMHost) (*hostClient, error) {
 	e := p.entry(host.Name)
 	e.mu.Lock()
 	defer e.mu.Unlock()
@@ -103,13 +105,17 @@ func (p *hostPool) get(ctx context.Context, host provider.KVMHost) (*hostClient,
 		if e.client.alive() {
 			return e.client, nil
 		}
+		log.V(1).Info("libvirt connection lost, redialing", "address", host.Address)
 		e.client.close()
 		e.client = nil
 	}
+	start := time.Now()
 	c, err := p.dial(ctx, host)
 	if err != nil {
+		log.V(1).Info("libvirt host dial failed", "address", host.Address, "duration", time.Since(start).Round(time.Millisecond), "error", err.Error())
 		return nil, fmt.Errorf("connecting to host %s (%s): %w", host.Name, host.Address, err)
 	}
+	log.V(1).Info("libvirt host connected", "address", host.Address, "duration", time.Since(start).Round(time.Millisecond))
 	e.client = c
 	return c, nil
 }
@@ -131,14 +137,24 @@ func (p *hostPool) drop(host string, c *hostClient) {
 // is closed — which unblocks fn with an error — and ctx.Err() is returned.
 // A transport error (anything that is not a libvirt.Error) also drops the
 // cached connection so the next call redials instead of reusing a dead
-// link.
-func (p *hostPool) call(ctx context.Context, host provider.KVMHost, fn func(api libvirtAPI) error) error {
-	c, err := p.get(ctx, host)
+// link. When log has V(1) enabled, every RPC fn makes is traced through it
+// (see tracingAPI), as are connection events.
+func (p *hostPool) call(ctx context.Context, log logr.Logger, host provider.KVMHost, fn func(api libvirtAPI) error) error {
+	log = log.WithName("libvirt")
+	c, err := p.get(ctx, log, host)
 	if err != nil {
 		return err
 	}
-	err = awaitOrCancel(ctx, func() error { return fn(c.api) }, func() { p.drop(host.Name, c) })
-	if err != nil && !isLibvirtError(err) {
+	api := c.api
+	if log.V(1).Enabled() {
+		api = &tracingAPI{inner: c.api, log: log}
+	}
+	err = awaitOrCancel(ctx, func() error { return fn(api) }, func() {
+		log.V(1).Info("libvirt connection dropped", "reason", "context cancelled", "error", ctx.Err().Error())
+		p.drop(host.Name, c)
+	})
+	if err != nil && !isLibvirtError(err) && !errors.Is(err, ctx.Err()) {
+		log.V(1).Info("libvirt connection dropped", "reason", "transport error", "error", err.Error())
 		p.drop(host.Name, c)
 	}
 	return err

internal/provider/kvm/conn_test.go

@@ -18,6 +18,7 @@ import (
 	"time"
 
 	libvirt "github.com/digitalocean/go-libvirt"
+	"github.com/go-logr/logr"
 	"golang.org/x/crypto/ssh"
 	"golang.org/x/crypto/ssh/knownhosts"
 
@@ -43,6 +44,8 @@ type fakeDialer struct {
 	err     error
 	delay   time.Duration
 	clients []*fakeClient
+	// api is what the dialled client exposes; nil for pool-only tests.
+	api libvirtAPI
 }
 
 func (d *fakeDialer) dial(ctx context.Context, _ provider.KVMHost) (*hostClient, error) {
@@ -61,7 +64,7 @@ func (d *fakeDialer) dial(ctx context.Context, _ provider.KVMHost) (*hostClient,
 	}
 	fc := &fakeClient{done: make(chan struct{})}
 	d.clients = append(d.clients, fc)
-	return &hostClient{api: nil, done: fc.done, close: fc.close}, nil
+	return &hostClient{api: d.api, done: fc.done, close: fc.close}, nil
 }
 
 func (d *fakeDialer) dialCount() int {
@@ -72,6 +75,8 @@ func (d *fakeDialer) dialCount() int {
 
 var testHost = provider.KVMHost{Name: "nas1", Address: "nas1:22", User: "virt", Socket: defaultSocket, Pool: "default", Bridge: "br0"}
 
+var discard = logr.Discard()
+
 func noop(libvirtAPI) error { return nil }
 
 func TestHostPool_call_reusesConnection(t *testing.T) {
@@ -79,7 +84,7 @@ func TestHostPool_call_reusesConnection(t *testing.T) {
 	d := &fakeDialer{}
 	p := newHostPool(d.dial)
 	for range 3 {
-		if err := p.call(context.Background(), testHost, noop); err != nil {
+		if err := p.call(context.Background(), discard, testHost, noop); err != nil {
 			t.Fatalf("call() error = %v", err)
 		}
 	}
@@ -92,11 +97,11 @@ func TestHostPool_call_redialsAfterDisconnect(t *testing.T) {
 	t.Parallel()
 	d := &fakeDialer{}
 	p := newHostPool(d.dial)
-	if err := p.call(context.Background(), testHost, noop); err != nil {
+	if err := p.call(context.Background(), discard, testHost, noop); err != nil {
 		t.Fatalf("call() error = %v", err)
 	}
 	d.clients[0].close()
-	if err := p.call(context.Background(), testHost, noop); err != nil {
+	if err := p.call(context.Background(), discard, testHost, noop); err != nil {
 		t.Fatalf("second call() error = %v", err)
 	}
 	if d.dialCount() != 2 {
@@ -108,14 +113,14 @@ func TestHostPool_call_transportErrorDropsConnection(t *testing.T) {
 	t.Parallel()
 	d := &fakeDialer{}
 	p := newHostPool(d.dial)
-	err := p.call(context.Background(), testHost, func(libvirtAPI) error { return io.ErrUnexpectedEOF })
+	err := p.call(context.Background(), discard, testHost, func(libvirtAPI) error { return io.ErrUnexpectedEOF })
 	if !errors.Is(err, io.ErrUnexpectedEOF) {
 		t.Fatalf("call() error = %v, want the transport error passed through", err)
 	}
 	if !d.clients[0].closed.Load() {
 		t.Error("connection not closed after a transport error")
 	}
-	if err := p.call(context.Background(), testHost, noop); err != nil {
+	if err := p.call(context.Background(), discard, testHost, noop); err != nil {
 		t.Fatalf("call() after transport error = %v", err)
 	}
 	if d.dialCount() != 2 {
@@ -127,11 +132,11 @@ func TestHostPool_call_libvirtErrorKeepsConnection(t *testing.T) {
 	t.Parallel()
 	d := &fakeDialer{}
 	p := newHostPool(d.dial)
-	err := p.call(context.Background(), testHost, func(libvirtAPI) error { return lvErr(libvirt.ErrNoDomain) })
+	err := p.call(context.Background(), discard, testHost, func(libvirtAPI) error { return lvErr(libvirt.ErrNoDomain) })
 	if !hasCode(err, libvirt.ErrNoDomain) {
 		t.Fatalf("call() error = %v, want the libvirt error passed through", err)
 	}
-	if err := p.call(context.Background(), testHost, noop); err != nil {
+	if err := p.call(context.Background(), discard, testHost, noop); err != nil {
 		t.Fatalf("call() error = %v", err)
 	}
 	if d.dialCount() != 1 {
@@ -146,7 +151,7 @@ func TestHostPool_call_dialErrorPropagates(t *testing.T) {
 	t.Parallel()
 	d := &fakeDialer{err: errors.New("ssh: handshake failed")}
 	p := newHostPool(d.dial)
-	err := p.call(context.Background(), testHost, noop)
+	err := p.call(context.Background(), discard, testHost, noop)
 	if err == nil || !strings.Contains(err.Error(), "nas1") || !strings.Contains(err.Error(), "handshake failed") {
 		t.Errorf("call() error = %v, want the dial error naming the host", err)
 	}
@@ -162,7 +167,7 @@ func TestHostPool_call_cancelAbandonsBlockedCall(t *testing.T) {
 		time.Sleep(20 * time.Millisecond)
 		cancel()
 	}()
-	err := p.call(ctx, testHost, func(libvirtAPI) error {
+	err := p.call(ctx, discard, testHost, func(libvirtAPI) error {
 		// Simulates an RPC stuck on a hung hypervisor: it only returns once
 		// the pool closes the connection out from under it.
 		<-d.clients[0].done
@@ -177,7 +182,7 @@ func TestHostPool_call_cancelAbandonsBlockedCall(t *testing.T) {
 	case <-time.After(time.Second):
 		t.Fatal("blocked call was not released by closing the connection")
 	}
-	if err := p.call(context.Background(), testHost, noop); err != nil {
+	if err := p.call(context.Background(), discard, testHost, noop); err != nil {
 		t.Fatalf("call() after cancel = %v", err)
 	}
 	if d.dialCount() != 2 {
@@ -192,7 +197,7 @@ func TestHostPool_call_concurrentCallersShareOneDial(t *testing.T) {
 	var wg sync.WaitGroup
 	for range 8 {
 		wg.Go(func() {
-			if err := p.call(context.Background(), testHost, noop); err != nil {
+			if err := p.call(context.Background(), discard, testHost, noop); err != nil {
 				t.Errorf("call() error = %v", err)
 			}
 		})
@@ -210,7 +215,7 @@ func TestHostPool_call_hostsAreIndependent(t *testing.T) {
 	other := testHost
 	other.Name = "lab2"
 	for _, h := range []provider.KVMHost{testHost, other, testHost, other} {
-		if err := p.call(context.Background(), h, noop); err != nil {
+		if err := p.call(context.Background(), discard, h, noop); err != nil {
 			t.Fatalf("call(%s) error = %v", h.Name, err)
 		}
 	}
@@ -567,3 +572,83 @@ func TestKeepalive_keepsHealthyClientOpen(t *testing.T) {
 	}
 	conn.Close()
 }
+
+func TestHostPool_call_tracesAtV1(t *testing.T) {
+	t.Parallel()
+	d := &fakeDialer{api: readyHost()}
+	p := newHostPool(d.dial)
+	log, snapshot := captureLogger(1)
+	err := p.call(context.Background(), log, testHost, func(api libvirtAPI) error {
+		_, err := api.StoragePoolLookupByName("default")
+		return err
+	})
+	if err != nil {
+		t.Fatalf("call() error = %v", err)
+	}
+	joined := strings.Join(snapshot(), "\n")
+	for _, want := range []string{`"msg"="libvirt host connected"`, `"address"="nas1:22"`, `"method"="StoragePoolLookupByName"`, `"pool"="default"`, "libvirt "} {
+		if !strings.Contains(joined, want) {
+			t.Errorf("output missing %s:\n%s", want, joined)
+		}
+	}
+}
+
+func TestHostPool_call_noTracingBelowV1(t *testing.T) {
+	t.Parallel()
+	inner := readyHost()
+	d := &fakeDialer{api: inner}
+	p := newHostPool(d.dial)
+	log, snapshot := captureLogger(0)
+	err := p.call(context.Background(), log, testHost, func(api libvirtAPI) error {
+		if api != libvirtAPI(inner) {
+			t.Errorf("fn received %T, want the bare fake when V(1) is off", api)
+		}
+		return nil
+	})
+	if err != nil {
+		t.Fatalf("call() error = %v", err)
+	}
+	if lines := snapshot(); len(lines) != 0 {
+		t.Errorf("verbosity 0 logged %d lines:\n%s", len(lines), strings.Join(lines, "\n"))
+	}
+}
+
+func TestHostPool_call_logsDropReason(t *testing.T) {
+	t.Parallel()
+	t.Run("transport error", func(t *testing.T) {
+		t.Parallel()
+		d := &fakeDialer{}
+		p := newHostPool(d.dial)
+		log, snapshot := captureLogger(1)
+		_ = p.call(context.Background(), log, testHost, func(libvirtAPI) error { return io.ErrUnexpectedEOF })
+		joined := strings.Join(snapshot(), "\n")
+		if !strings.Contains(joined, `"msg"="libvirt connection dropped"`) || !strings.Contains(joined, `"reason"="transport error"`) {
+			t.Errorf("output missing the drop line:\n%s", joined)
+		}
+	})
+	t.Run("context cancelled", func(t *testing.T) {
+		t.Parallel()
+		d := &fakeDialer{}
+		p := newHostPool(d.dial)
+		log, snapshot := captureLogger(1)
+		ctx, cancel := context.WithCancel(context.Background())
+		cancel()
+		released := make(chan struct{})
+		err := p.call(ctx, log, testHost, func(libvirtAPI) error {
+			<-d.clients[0].done
+			close(released)
+			return io.EOF
+		})
+		if !errors.Is(err, context.Canceled) {
+			t.Fatalf("call() error = %v, want context.Canceled", err)
+		}
+		<-released
+		joined := strings.Join(snapshot(), "\n")
+		if !strings.Contains(joined, `"reason"="context cancelled"`) {
+			t.Errorf("output missing the cancel drop line:\n%s", joined)
+		}
+		if strings.Contains(joined, `"reason"="transport error"`) {
+			t.Errorf("cancel was also reported as a transport error:\n%s", joined)
+		}
+	})
+}

internal/provider/kvm/errors.go

@@ -63,10 +63,21 @@ func logAPIError(log logr.Logger, op string, err error) {
 	if !log.V(1).Enabled() {
 		return
 	}
-	kv := []any{"op", op, "error", err.Error()}
-	var lerr libvirt.Error
-	if errors.As(err, &lerr) {
-		kv = append(kv, "libvirtCode", lerr.Code, "libvirtMessage", lerr.Message)
-	}
+	kv := append([]any{"op", op, "error", err.Error()}, libvirtErrorFields(err)...)
 	log.V(1).Info("libvirt call failed", kv...)
 }
+
+// libvirtErrorFields renders a daemon-reported error as log key/values:
+// the numeric code, its constant name (ErrNoDomain, ...) and the daemon's
+// message. Nil for transport and other non-libvirt errors.
+func libvirtErrorFields(err error) []any {
+	var lerr libvirt.Error
+	if !errors.As(err, &lerr) {
+		return nil
+	}
+	return []any{
+		"libvirtCode", lerr.Code,
+		"libvirtCodeName", libvirt.ErrorNumber(lerr.Code).String(),
+		"libvirtMessage", lerr.Message,
+	}
+}

internal/provider/kvm/errors_test.go

@@ -5,6 +5,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"reflect"
 	"testing"
 
 	libvirt "github.com/digitalocean/go-libvirt"
@@ -67,3 +68,26 @@ func TestHasCode(t *testing.T) {
 		t.Error("io.EOF classified as a libvirt error")
 	}
 }
+
+func TestLibvirtErrorFields(t *testing.T) {
+	t.Parallel()
+	tests := []struct {
+		name string
+		err  error
+		want []any
+	}{
+		{"libvirt error", lvErr(libvirt.ErrNoDomain), []any{"libvirtCode", uint32(42), "libvirtCodeName", "ErrNoDomain", "libvirtMessage", "ErrNoDomain"}},
+		{"wrapped libvirt error", fmt.Errorf("looking up: %w", lvErr(libvirt.ErrNoDomain)), []any{"libvirtCode", uint32(42), "libvirtCodeName", "ErrNoDomain", "libvirtMessage", "ErrNoDomain"}},
+		{"transport error", io.EOF, nil},
+		{"cancelled", context.Canceled, nil},
+	}
+	for _, tc := range tests {
+		t.Run(tc.name, func(t *testing.T) {
+			t.Parallel()
+			got := libvirtErrorFields(tc.err)
+			if !reflect.DeepEqual(got, tc.want) {
+				t.Errorf("libvirtErrorFields() = %#v, want %#v", got, tc.want)
+			}
+		})
+	}
+}

internal/provider/kvm/kvm.go

@@ -166,7 +166,7 @@ func (p *Provider) Create(ctx context.Context, req provider.CreateRequest) (stri
 		"vcpus", mt.VCPUs, "memoryMiB", mt.MemoryMiB, "diskSizeGb", p.cfg.DiskSizeGB,
 		"image", src.volumeName(), "cloudInitBytes", len(req.CloudInit))
 
-	err = p.hosts.call(ctx, host, func(api libvirtAPI) error {
+	err = p.hosts.call(ctx, log, host, func(api libvirtAPI) error {
 		dom, err := api.DomainLookupByName(req.Name)
 		if err == nil {
 			log.V(1).Info("domain already defined")
@@ -319,7 +319,7 @@ func (p *Provider) Get(ctx context.Context, providerID string) (*provider.Instan
 	}
 	log := p.logger(ctx).WithValues("host", host.Name, "name", name)
 	var inst *provider.Instance
-	err = p.hosts.call(ctx, host, func(api libvirtAPI) error {
+	err = p.hosts.call(ctx, log, host, func(api libvirtAPI) error {
 		dom, err := api.DomainLookupByName(name)
 		if err != nil {
 			return fmt.Errorf("looking up domain: %w", err)
@@ -455,7 +455,7 @@ func (p *Provider) Delete(ctx context.Context, providerID string) error {
 		return p.wrapErr("delete", providerID, err)
 	}
 	log := p.logger(ctx).WithValues("host", host.Name, "name", name)
-	err = p.hosts.call(ctx, host, func(api libvirtAPI) error {
+	err = p.hosts.call(ctx, log, host, func(api libvirtAPI) error {
 		if err := p.removeDomain(log, api, name); err != nil {
 			return err
 		}
@@ -527,7 +527,7 @@ func (p *Provider) ListByTag(ctx context.Context) ([]provider.Instance, error) {
 	var out []provider.Instance
 	for _, host := range p.cfg.Hosts {
 		hlog := log.WithValues("host", host.Name)
-		err := p.hosts.call(ctx, host, func(api libvirtAPI) error {
+		err := p.hosts.call(ctx, hlog, host, func(api libvirtAPI) error {
 			doms, _, err := api.ConnectListAllDomains(1, 0)
 			if err != nil {
 				return fmt.Errorf("listing domains: %w", err)

internal/provider/kvm/kvm_integration_test.go

@@ -25,6 +25,14 @@ package kvm
 //	KVM_TEST_SOCKET        libvirt socket path on the host
 //	KVM_TEST_TIMEOUT       overall budget incl. the image download (default 20m)
 //	KVM_TEST_KEEP          set to anything to leave the VM behind for inspection
+//	KVM_TEST_LOG_LEVEL     provider log verbosity shown in -v output (default 1:
+//	                       one line per libvirt call; 2 adds XML, metadata and
+//	                       addresses; 0 leaves only the t.Log lines)
+//
+// Provider logs go through a testr logger, so they interleave with t.Log
+// output. A run that hits its timeout may log one more line from the RPC
+// the pool abandoned, after the test has ended; that is a symptom of the
+// timeout, not a bug in the tracer.
 
 import (
 	"context"
@@ -34,11 +42,15 @@ import (
 	"fmt"
 	"net"
 	"os"
+	"strconv"
 	"testing"
 	"time"
 
 	libvirt "github.com/digitalocean/go-libvirt"
+	"github.com/go-logr/logr"
+	"github.com/go-logr/logr/testr"
 	"k8s.io/apimachinery/pkg/types"
+	logf "sigs.k8s.io/controller-runtime/pkg/log"
 
 	"gitea.home.hrajfrisbee.cz/kacerr/egress-proxies-operator/internal/provider"
 )
@@ -50,9 +62,10 @@ const (
 )
 
 type integrationEnv struct {
-	cfg     provider.ProviderConfig
-	timeout time.Duration
-	keep    bool
+	cfg      provider.ProviderConfig
+	timeout  time.Duration
+	keep     bool
+	logLevel int
 }
 
 func loadIntegrationEnv(t *testing.T) integrationEnv {
@@ -97,7 +110,26 @@ func loadIntegrationEnv(t *testing.T) integrationEnv {
 		}
 		timeout = d
 	}
-	return integrationEnv{cfg: pc, timeout: timeout, keep: os.Getenv("KVM_TEST_KEEP") != ""}
+	logLevel := 1
+	if v := os.Getenv("KVM_TEST_LOG_LEVEL"); v != "" {
+		n, err := strconv.Atoi(v)
+		if err != nil {
+			t.Fatalf("KVM_TEST_LOG_LEVEL: %v", err)
+		}
+		logLevel = n
+	}
+	return integrationEnv{cfg: pc, timeout: timeout, keep: os.Getenv("KVM_TEST_KEEP") != "", logLevel: logLevel}
+}
+
+// integrationLogger routes provider logs into the test output at the
+// requested verbosity, and installs it as controller-runtime's root logger
+// so nothing falls back to the unfulfilled delegating sink (which would
+// print its "SetLogger was never called" warning and swallow the lines).
+func integrationLogger(t *testing.T, verbosity int) logr.Logger {
+	t.Helper()
+	log := testr.NewWithOptions(t, testr.Options{LogTimestamp: true, Verbosity: verbosity})
+	logf.SetLogger(log)
+	return log
 }
 
 func randomUID(t *testing.T) string {
@@ -114,7 +146,8 @@ func randomUID(t *testing.T) string {
 // stage depends on the state the previous one left on the hypervisor.
 func TestKVM_lifecycle(t *testing.T) {
 	env := loadIntegrationEnv(t)
-	ctx, cancel := context.WithTimeout(context.Background(), env.timeout)
+	log := integrationLogger(t, env.logLevel)
+	ctx, cancel := context.WithTimeout(logr.NewContext(context.Background(), log), env.timeout)
 	defer cancel()
 
 	prov, err := New(ctx, env.cfg)
@@ -143,7 +176,7 @@ func TestKVM_lifecycle(t *testing.T) {
 			t.Logf("KVM_TEST_KEEP set: leaving domain %s and its volumes on %s", req.Name, host.Address)
 			return
 		}
-		cctx, ccancel := context.WithTimeout(context.Background(), 2*time.Minute)
+		cctx, ccancel := context.WithTimeout(logr.NewContext(context.Background(), log), 2*time.Minute)
 		defer ccancel()
 		if err := p.Delete(cctx, formatProviderID(host.Name, req.Name)); err != nil {
 			t.Errorf("cleanup Delete: %v", err)
@@ -217,7 +250,7 @@ func TestKVM_lifecycle(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	err = p.hosts.call(ctx, host, func(api libvirtAPI) error {
+	err = p.hosts.call(ctx, p.logger(ctx).WithValues("host", host.Name), host, func(api libvirtAPI) error {
 		pool, err := api.StoragePoolLookupByName(host.Pool)
 		if err != nil {
 			return err

internal/provider/kvm/kvm_test.go

@@ -885,3 +885,96 @@ func TestNew_badKeyPathFailsFast(t *testing.T) {
 		t.Fatal("New succeeded with a missing key file")
 	}
 }
+
+// runAllOps drives one full lifecycle over a ready fake host so logging
+// tests see every provider method and every libvirt call.
+func runAllOps(t *testing.T, ctx context.Context, req provider.CreateRequest) {
+	t.Helper()
+	p := newTestProvider(hostFakes{"nas1": readyHost()}, "nas1")
+	id, err := p.Create(ctx, req)
+	if err != nil {
+		t.Fatalf("Create: %v", err)
+	}
+	if _, err := p.Get(ctx, id); err != nil {
+		t.Fatalf("Get: %v", err)
+	}
+	if _, err := p.ListByTag(ctx); err != nil {
+		t.Fatalf("ListByTag: %v", err)
+	}
+	if err := p.Delete(ctx, id); err != nil {
+		t.Fatalf("Delete: %v", err)
+	}
+}
+
+func TestLogging_verbosityTiers(t *testing.T) {
+	t.Parallel()
+	tests := []struct {
+		name        string
+		verbosity   int
+		wantLines   []string
+		absentLines []string
+	}{
+		{
+			name:        "v0 stays silent",
+			verbosity:   0,
+			absentLines: []string{"libvirt call", "KVM domain ensured running"},
+		},
+		{
+			name:      "v1 logs one line per libvirt call plus the operation outcomes",
+			verbosity: 1,
+			wantLines: []string{
+				`kvm/libvirt "level"=1 "msg"="libvirt host connected"`,
+				`"msg"="libvirt call"`,
+				`"method"="DomainLookupByName"`,
+				`"libvirtCodeName"="ErrNoDomain"`,
+				`"method"="StorageVolUpload"`,
+				`"method"="DomainDefineXML"`,
+				`"method"="DomainCreate"`,
+				`"method"="DomainInterfaceAddresses"`,
+				`"method"="ConnectListAllDomains"`,
+				`"method"="DomainUndefineFlags"`,
+				`"method"="StorageVolDelete"`,
+				`"provider"="kvm-home"`,
+				`"host"="nas1"`,
+				`"name"="` + testName + `"`,
+				`"msg"="KVM domain ensured running"`,
+			},
+			absentLines: []string{`"xml"=`, `"metadata"=`},
+		},
+		{
+			name:      "v2 adds xml, metadata and addresses on the same lines",
+			verbosity: 2,
+			wantLines: []string{`"xml"="<domain`, `"xml"="<volume`, `"metadata"="<instance`, `"names"=[`},
+		},
+	}
+	for _, tc := range tests {
+		t.Run(tc.name, func(t *testing.T) {
+			t.Parallel()
+			ctx, snapshot := captureContext(tc.verbosity)
+			req := testRequest()
+			const sentinel = "SENTINEL-cloud-init-must-never-be-logged"
+			req.CloudInit = "#cloud-config\n" + sentinel + "\n"
+
+			runAllOps(t, ctx, req)
+
+			lines := snapshot()
+			joined := strings.Join(lines, "\n")
+			if tc.verbosity == 0 && len(lines) != 0 {
+				t.Errorf("verbosity 0 logged %d lines:\n%s", len(lines), joined)
+			}
+			for _, want := range tc.wantLines {
+				if !strings.Contains(joined, want) {
+					t.Errorf("output missing %s:\n%s", want, joined)
+				}
+			}
+			for _, absent := range tc.absentLines {
+				if strings.Contains(joined, absent) {
+					t.Errorf("output unexpectedly contains %s:\n%s", absent, joined)
+				}
+			}
+			if strings.Contains(joined, sentinel) {
+				t.Errorf("cloud-init content leaked into logs:\n%s", joined)
+			}
+		})
+	}
+}

internal/provider/kvm/trace.go

@@ -0,0 +1,201 @@
+package kvm
+
+import (
+	"fmt"
+	"io"
+	"time"
+
+	libvirt "github.com/digitalocean/go-libvirt"
+	"github.com/go-logr/logr"
+)
+
+// tracingAPI wraps a libvirtAPI and logs one V(1) line per call after it
+// returns: method, the identifiers it was given, curated results, duration,
+// and the libvirt error fields on failure. At V(2) the same line also
+// carries XML bodies, metadata and address lists. Upload and download
+// bodies are never logged: the seed ISO carries cloud-init.
+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 {
+	return &tracedCall{t: t, method: method, start: time.Now(), kv: kv}
+}
+
+// detail adds key/values that are only worth the bytes at V(2).
+func (c *tracedCall) detail(kv ...any) *tracedCall {
+	if c.t.log.V(2).Enabled() {
+		c.kv = append(c.kv, kv...)
+	}
+	return c
+}
+
+func (c *tracedCall) done(err error, kv ...any) {
+	fields := make([]any, 0, 2+len(c.kv)+len(kv)+10)
+	fields = append(fields, "method", c.method)
+	fields = append(fields, c.kv...)
+	fields = append(fields, kv...)
+	fields = append(fields, "duration", time.Since(c.start).Round(time.Microsecond))
+	if err != nil {
+		fields = append(fields, "error", err.Error())
+		fields = append(fields, libvirtErrorFields(err)...)
+	}
+	c.t.log.V(1).Info("libvirt call", fields...)
+}
+
+// flagKV renders a flags value only when something is set; go-libvirt's
+// generated stringers do not know bitmask combinations.
+func flagKV(v int64) []any {
+	if v == 0 {
+		return nil
+	}
+	return []any{"flags", v}
+}
+
+func optString(s libvirt.OptString) string {
+	if len(s) == 0 {
+		return ""
+	}
+	return s[0]
+}
+
+func (t *tracingAPI) DomainLookupByName(name string) (libvirt.Domain, error) {
+	c := t.begin("DomainLookupByName", "domain", name)
+	d, err := t.inner.DomainLookupByName(name)
+	c.done(err)
+	return d, err
+}
+
+func (t *tracingAPI) DomainDefineXML(xml string) (libvirt.Domain, error) {
+	c := t.begin("DomainDefineXML", "xmlBytes", len(xml)).detail("xml", xml)
+	d, err := t.inner.DomainDefineXML(xml)
+	c.done(err, "domain", d.Name)
+	return d, err
+}
+
+func (t *tracingAPI) DomainCreate(d libvirt.Domain) error {
+	c := t.begin("DomainCreate", "domain", d.Name)
+	err := t.inner.DomainCreate(d)
+	c.done(err)
+	return err
+}
+
+func (t *tracingAPI) DomainDestroy(d libvirt.Domain) error {
+	c := t.begin("DomainDestroy", "domain", d.Name)
+	err := t.inner.DomainDestroy(d)
+	c.done(err)
+	return err
+}
+
+func (t *tracingAPI) DomainUndefineFlags(d libvirt.Domain, flags libvirt.DomainUndefineFlagsValues) error {
+	c := t.begin("DomainUndefineFlags", append([]any{"domain", d.Name}, flagKV(int64(flags))...)...)
+	err := t.inner.DomainUndefineFlags(d, flags)
+	c.done(err)
+	return err
+}
+
+func (t *tracingAPI) DomainGetState(d libvirt.Domain, flags uint32) (int32, int32, error) {
+	c := t.begin("DomainGetState", "domain", d.Name)
+	state, reason, err := t.inner.DomainGetState(d, flags)
+	c.done(err, "state", libvirt.DomainState(state), "reason", reason)
+	return state, reason, err
+}
+
+func (t *tracingAPI) DomainGetMetadata(d libvirt.Domain, typ int32, uri libvirt.OptString, flags libvirt.DomainModificationImpact) (string, error) {
+	c := t.begin("DomainGetMetadata", "domain", d.Name, "type", typ, "uri", optString(uri))
+	s, err := t.inner.DomainGetMetadata(d, typ, uri, flags)
+	c.detail("metadata", s).done(err, "metadataBytes", len(s))
+	return s, err
+}
+
+func (t *tracingAPI) DomainInterfaceAddresses(d libvirt.Domain, source uint32, flags uint32) ([]libvirt.DomainInterface, error) {
+	c := t.begin("DomainInterfaceAddresses", "domain", d.Name, "source", libvirt.DomainInterfaceAddressesSource(source))
+	ifaces, err := t.inner.DomainInterfaceAddresses(d, source, flags)
+	c.detail("addresses", formatAddresses(ifaces)).done(err, "interfaces", len(ifaces))
+	return ifaces, err
+}
+
+func formatAddresses(ifaces []libvirt.DomainInterface) []string {
+	var out []string
+	for _, iface := range ifaces {
+		for _, a := range iface.Addrs {
+			out = append(out, fmt.Sprintf("%s=%s/%d", iface.Name, a.Addr, a.Prefix))
+		}
+	}
+	return out
+}
+
+func (t *tracingAPI) ConnectListAllDomains(needResults int32, flags libvirt.ConnectListAllDomainsFlags) ([]libvirt.Domain, uint32, error) {
+	c := t.begin("ConnectListAllDomains", flagKV(int64(flags))...)
+	doms, n, err := t.inner.ConnectListAllDomains(needResults, flags)
+	names := make([]string, 0, len(doms))
+	for _, d := range doms {
+		names = append(names, d.Name)
+	}
+	c.detail("names", names).done(err, "count", len(doms))
+	return doms, n, err
+}
+
+func (t *tracingAPI) StoragePoolLookupByName(name string) (libvirt.StoragePool, error) {
+	c := t.begin("StoragePoolLookupByName", "pool", name)
+	pool, err := t.inner.StoragePoolLookupByName(name)
+	c.done(err)
+	return pool, err
+}
+
+func (t *tracingAPI) StoragePoolRefresh(pool libvirt.StoragePool, flags uint32) error {
+	c := t.begin("StoragePoolRefresh", "pool", pool.Name)
+	err := t.inner.StoragePoolRefresh(pool, flags)
+	c.done(err)
+	return err
+}
+
+func (t *tracingAPI) StorageVolLookupByName(pool libvirt.StoragePool, name string) (libvirt.StorageVol, error) {
+	c := t.begin("StorageVolLookupByName", "pool", pool.Name, "volume", name)
+	vol, err := t.inner.StorageVolLookupByName(pool, name)
+	c.done(err)
+	return vol, err
+}
+
+func (t *tracingAPI) StorageVolGetPath(vol libvirt.StorageVol) (string, error) {
+	c := t.begin("StorageVolGetPath", "pool", vol.Pool, "volume", vol.Name)
+	path, err := t.inner.StorageVolGetPath(vol)
+	c.done(err, "path", path)
+	return path, err
+}
+
+func (t *tracingAPI) StorageVolCreateXML(pool libvirt.StoragePool, xml string, flags libvirt.StorageVolCreateFlags) (libvirt.StorageVol, error) {
+	c := t.begin("StorageVolCreateXML", append([]any{"pool", pool.Name, "xmlBytes", len(xml)}, flagKV(int64(flags))...)...).detail("xml", xml)
+	vol, err := t.inner.StorageVolCreateXML(pool, xml, flags)
+	c.done(err, "volume", vol.Name)
+	return vol, err
+}
+
+func (t *tracingAPI) StorageVolUpload(vol libvirt.StorageVol, r io.Reader, offset, length uint64, flags libvirt.StorageVolUploadFlags) error {
+	c := t.begin("StorageVolUpload", append([]any{"pool", vol.Pool, "volume", vol.Name, "offset", offset, "length", length}, flagKV(int64(flags))...)...)
+	err := t.inner.StorageVolUpload(vol, r, offset, length, flags)
+	c.done(err)
+	return err
+}
+
+func (t *tracingAPI) StorageVolDownload(vol libvirt.StorageVol, w io.Writer, offset, length uint64, flags libvirt.StorageVolDownloadFlags) error {
+	c := t.begin("StorageVolDownload", append([]any{"pool", vol.Pool, "volume", vol.Name, "offset", offset, "length", length}, flagKV(int64(flags))...)...)
+	err := t.inner.StorageVolDownload(vol, w, offset, length, flags)
+	c.done(err)
+	return err
+}
+
+func (t *tracingAPI) StorageVolDelete(vol libvirt.StorageVol, flags libvirt.StorageVolDeleteFlags) error {
+	c := t.begin("StorageVolDelete", append([]any{"pool", vol.Pool, "volume", vol.Name}, flagKV(int64(flags))...)...)
+	err := t.inner.StorageVolDelete(vol, flags)
+	c.done(err)
+	return err
+}

internal/provider/kvm/trace_test.go

@@ -0,0 +1,300 @@
+package kvm
+
+import (
+	"bytes"
+	"context"
+	"errors"
+	"io"
+	"reflect"
+	"strings"
+	"sync"
+	"testing"
+
+	libvirt "github.com/digitalocean/go-libvirt"
+	"github.com/go-logr/logr"
+	"github.com/go-logr/logr/funcr"
+)
+
+// captureLogger returns a funcr logger capped at verbosity (the test
+// stand-in for --zap-log-level=<verbosity>) and a snapshot function for the
+// lines it recorded. The sink is mutex-guarded: a cancelled call logs from
+// the abandoned goroutine.
+func captureLogger(verbosity int) (logr.Logger, func() []string) {
+	var mu sync.Mutex
+	var lines []string
+	log := funcr.New(func(prefix, args string) {
+		mu.Lock()
+		defer mu.Unlock()
+		lines = append(lines, prefix+" "+args)
+	}, funcr.Options{Verbosity: verbosity})
+	return log, func() []string {
+		mu.Lock()
+		defer mu.Unlock()
+		return append([]string(nil), lines...)
+	}
+}
+
+func captureContext(verbosity int) (context.Context, func() []string) {
+	log, snapshot := captureLogger(verbosity)
+	return logr.NewContext(context.Background(), log), snapshot
+}
+
+const stoppedName = "proxy-stopped"
+
+// tracedHost is a fake with one managed running domain and its volumes, so
+// every method of the seam has something to act on.
+func tracedHost(t *testing.T) *fakeAPI {
+	t.Helper()
+	api := readyHost()
+	managedDomain(t, api, testName, testUID, true, map[uint32][]libvirt.DomainInterface{
+		uint32(libvirt.DomainInterfaceAddressesSrcArp): {{Name: "vnet0", Addrs: []libvirt.DomainIPAddr{ipv4("192.168.1.50")}}},
+	})
+	api.putDomain(&fakeDomain{name: stoppedName})
+	return api
+}
+
+func TestTracingAPI_logsEveryMethod(t *testing.T) {
+	t.Parallel()
+	pool := libvirt.StoragePool{Name: "default"}
+	dom := libvirt.Domain{Name: testName}
+	overlay := libvirt.StorageVol{Pool: "default", Name: overlayVolumeName(testName)}
+	cases := []struct {
+		method string
+		call   func(api libvirtAPI) error
+	}{
+		{"DomainLookupByName", func(api libvirtAPI) error { _, err := api.DomainLookupByName(testName); return err }},
+		{"DomainDefineXML", func(api libvirtAPI) error {
+			xml, err := buildDomainXML(testDomainParams())
+			if err != nil {
+				return err
+			}
+			_, err = api.DomainDefineXML(xml)
+			return err
+		}},
+		{"DomainCreate", func(api libvirtAPI) error { return api.DomainCreate(libvirt.Domain{Name: stoppedName}) }},
+		{"DomainDestroy", func(api libvirtAPI) error { return api.DomainDestroy(dom) }},
+		{"DomainUndefineFlags", func(api libvirtAPI) error { return api.DomainUndefineFlags(dom, undefineFlags) }},
+		{"DomainGetState", func(api libvirtAPI) error { _, _, err := api.DomainGetState(dom, 0); return err }},
+		{"DomainGetMetadata", func(api libvirtAPI) error {
+			_, err := api.DomainGetMetadata(dom, int32(libvirt.DomainMetadataElement), libvirt.OptString{metadataURI}, 0)
+			return err
+		}},
+		{"DomainInterfaceAddresses", func(api libvirtAPI) error {
+			_, err := api.DomainInterfaceAddresses(dom, uint32(libvirt.DomainInterfaceAddressesSrcArp), 0)
+			return err
+		}},
+		{"ConnectListAllDomains", func(api libvirtAPI) error { _, _, err := api.ConnectListAllDomains(1, 0); return err }},
+		{"StoragePoolLookupByName", func(api libvirtAPI) error { _, err := api.StoragePoolLookupByName("default"); return err }},
+		{"StoragePoolRefresh", func(api libvirtAPI) error { return api.StoragePoolRefresh(pool, 0) }},
+		{"StorageVolLookupByName", func(api libvirtAPI) error { _, err := api.StorageVolLookupByName(pool, overlay.Name); return err }},
+		{"StorageVolGetPath", func(api libvirtAPI) error { _, err := api.StorageVolGetPath(overlay); return err }},
+		{"StorageVolCreateXML", func(api libvirtAPI) error {
+			xml, err := buildVolumeXML(rawVolume("new.iso", 3))
+			if err != nil {
+				return err
+			}
+			_, err = api.StorageVolCreateXML(pool, xml, 0)
+			return err
+		}},
+		{"StorageVolUpload", func(api libvirtAPI) error {
+			return api.StorageVolUpload(overlay, strings.NewReader("abc"), 0, 3, 0)
+		}},
+		{"StorageVolDownload", func(api libvirtAPI) error {
+			return api.StorageVolDownload(overlay, io.Discard, 0, 0, 0)
+		}},
+		{"StorageVolDelete", func(api libvirtAPI) error { return api.StorageVolDelete(overlay, 0) }},
+	}
+	if n := reflect.TypeOf((*libvirtAPI)(nil)).Elem().NumMethod(); n != len(cases) {
+		t.Fatalf("libvirtAPI has %d methods, this test covers %d; trace the new one", n, len(cases))
+	}
+	for _, tc := range cases {
+		t.Run(tc.method, func(t *testing.T) {
+			t.Parallel()
+			log, snapshot := captureLogger(1)
+			api := &tracingAPI{inner: tracedHost(t), log: log}
+			if err := tc.call(api); err != nil {
+				t.Fatalf("%s: %v", tc.method, err)
+			}
+			lines := snapshot()
+			if len(lines) != 1 {
+				t.Fatalf("logged %d lines, want exactly 1:\n%s", len(lines), strings.Join(lines, "\n"))
+			}
+			for _, want := range []string{`"msg"="libvirt call"`, `"method"="` + tc.method + `"`, `"duration"=`} {
+				if !strings.Contains(lines[0], want) {
+					t.Errorf("line missing %s:\n%s", want, lines[0])
+				}
+			}
+			if strings.Contains(lines[0], `"error"=`) {
+				t.Errorf("successful call logged an error:\n%s", lines[0])
+			}
+		})
+	}
+}
+
+func TestTracingAPI_passesResultsThrough(t *testing.T) {
+	t.Parallel()
+	inner := tracedHost(t)
+	log, _ := captureLogger(1)
+	traced := &tracingAPI{inner: inner, log: log}
+	dom := libvirt.Domain{Name: testName}
+
+	wantState, wantReason, err := inner.DomainGetState(dom, 0)
+	if err != nil {
+		t.Fatal(err)
+	}
+	state, reason, err := traced.DomainGetState(dom, 0)
+	if err != nil || state != wantState || reason != wantReason {
+		t.Errorf("DomainGetState = %d/%d/%v, want %d/%d/nil", state, reason, err, wantState, wantReason)
+	}
+
+	overlay := libvirt.StorageVol{Pool: "default", Name: overlayVolumeName(testName)}
+	wantPath, _ := inner.StorageVolGetPath(overlay)
+	if path, err := traced.StorageVolGetPath(overlay); err != nil || path != wantPath {
+		t.Errorf("StorageVolGetPath = %q/%v, want %q", path, err, wantPath)
+	}
+
+	wantDoms, _, _ := inner.ConnectListAllDomains(1, 0)
+	doms, _, err := traced.ConnectListAllDomains(1, 0)
+	if err != nil || !reflect.DeepEqual(doms, wantDoms) {
+		t.Errorf("ConnectListAllDomains = %v/%v, want %v", doms, err, wantDoms)
+	}
+
+	inner.fail["DomainCreate"] = lvError(libvirt.ErrOperationInvalid, "already running")
+	if err := traced.DomainCreate(dom); !hasCode(err, libvirt.ErrOperationInvalid) {
+		t.Errorf("DomainCreate error = %v, want the injected libvirt error unchanged", err)
+	}
+}
+
+func TestTracingAPI_errorFields(t *testing.T) {
+	t.Parallel()
+	tests := []struct {
+		name    string
+		inject  error
+		want    []string
+		notWant []string
+	}{
+		{
+			name:   "libvirt error carries code, name and message",
+			inject: lvError(libvirt.ErrNoDomain, "Domain not found: no domain with matching name"),
+			want:   []string{`"error"=`, `"libvirtCode"=42`, `"libvirtCodeName"="ErrNoDomain"`, `"libvirtMessage"="Domain not found`},
+		},
+		{
+			name:    "transport error has no libvirt fields",
+			inject:  io.EOF,
+			want:    []string{`"error"="EOF"`},
+			notWant: []string{`"libvirtCode"`},
+		},
+	}
+	for _, tc := range tests {
+		t.Run(tc.name, func(t *testing.T) {
+			t.Parallel()
+			inner := tracedHost(t)
+			inner.fail["DomainLookupByName"] = tc.inject
+			log, snapshot := captureLogger(1)
+			api := &tracingAPI{inner: inner, log: log}
+			if _, err := api.DomainLookupByName(testName); !errors.Is(err, tc.inject) {
+				t.Fatalf("error = %v, want the injected one", err)
+			}
+			joined := strings.Join(snapshot(), "\n")
+			for _, want := range tc.want {
+				if !strings.Contains(joined, want) {
+					t.Errorf("output missing %s:\n%s", want, joined)
+				}
+			}
+			for _, absent := range tc.notWant {
+				if strings.Contains(joined, absent) {
+					t.Errorf("output unexpectedly contains %s:\n%s", absent, joined)
+				}
+			}
+		})
+	}
+}
+
+func TestTracingAPI_detailOnlyAtV2(t *testing.T) {
+	t.Parallel()
+	dom := libvirt.Domain{Name: testName}
+	calls := []struct {
+		method string
+		call   func(api libvirtAPI) error
+		always string
+		detail string
+	}{
+		{"DomainDefineXML", func(api libvirtAPI) error {
+			xml, err := buildDomainXML(testDomainParams())
+			if err != nil {
+				return err
+			}
+			_, err = api.DomainDefineXML(xml)
+			return err
+		}, `"xmlBytes"=`, `"xml"="<domain`},
+		{"StorageVolCreateXML", func(api libvirtAPI) error {
+			xml, err := buildVolumeXML(rawVolume("new.iso", 3))
+			if err != nil {
+				return err
+			}
+			_, err = api.StorageVolCreateXML(libvirt.StoragePool{Name: "default"}, xml, 0)
+			return err
+		}, `"xmlBytes"=`, `"xml"="<volume`},
+		{"DomainGetMetadata", func(api libvirtAPI) error {
+			_, err := api.DomainGetMetadata(dom, int32(libvirt.DomainMetadataElement), libvirt.OptString{metadataURI}, 0)
+			return err
+		}, `"metadataBytes"=`, `"metadata"="<instance`},
+		{"DomainInterfaceAddresses", func(api libvirtAPI) error {
+			_, err := api.DomainInterfaceAddresses(dom, uint32(libvirt.DomainInterfaceAddressesSrcArp), 0)
+			return err
+		}, `"interfaces"=1`, `"addresses"=["vnet0=192.168.1.50/24"]`},
+		{"ConnectListAllDomains", func(api libvirtAPI) error {
+			_, _, err := api.ConnectListAllDomains(1, 0)
+			return err
+		}, `"count"=2`, `"names"=[`},
+	}
+	for _, verbosity := range []int{1, 2} {
+		for _, tc := range calls {
+			t.Run(tc.method+"/v"+string(rune('0'+verbosity)), func(t *testing.T) {
+				t.Parallel()
+				log, snapshot := captureLogger(verbosity)
+				api := &tracingAPI{inner: tracedHost(t), log: log}
+				if err := tc.call(api); err != nil {
+					t.Fatal(err)
+				}
+				joined := strings.Join(snapshot(), "\n")
+				if !strings.Contains(joined, tc.always) {
+					t.Errorf("v%d output missing %s:\n%s", verbosity, tc.always, joined)
+				}
+				if has := strings.Contains(joined, tc.detail); has != (verbosity >= 2) {
+					t.Errorf("v%d output contains %s = %v, want %v:\n%s", verbosity, tc.detail, has, verbosity >= 2, joined)
+				}
+			})
+		}
+	}
+}
+
+func TestTracingAPI_uploadLogsSizeNotContent(t *testing.T) {
+	t.Parallel()
+	const sentinel = "SENTINEL-seed-content-must-never-be-logged"
+	log, snapshot := captureLogger(2)
+	api := &tracingAPI{inner: tracedHost(t), log: log}
+	vol := libvirt.StorageVol{Pool: "default", Name: seedVolumeName(testName)}
+	if err := api.StorageVolUpload(vol, bytes.NewReader([]byte(sentinel)), 0, uint64(len(sentinel)), 0); err != nil {
+		t.Fatal(err)
+	}
+	joined := strings.Join(snapshot(), "\n")
+	if !strings.Contains(joined, `"length"=42`) {
+		t.Errorf("upload line missing the length:\n%s", joined)
+	}
+	if strings.Contains(joined, sentinel) {
+		t.Errorf("upload content leaked into logs:\n%s", joined)
+	}
+}
+
+func TestTracingAPI_silentBelowV1(t *testing.T) {
+	t.Parallel()
+	log, snapshot := captureLogger(0)
+	api := &tracingAPI{inner: tracedHost(t), log: log}
+	if _, err := api.DomainLookupByName(testName); err != nil {
+		t.Fatal(err)
+	}
+	if lines := snapshot(); len(lines) != 0 {
+		t.Errorf("verbosity 0 logged %d lines:\n%s", len(lines), strings.Join(lines, "\n"))
+	}
+}