docs/kvm-provider.md

@@ -194,10 +194,11 @@ The provider logs through controller-runtime's logger, named `kvm`, with
 - `--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`),
+  `rpc` (the libvirt API function, e.g. `virDomainLookupByName`), the
-  curated results (`state`, `path`, `interfaces`), `duration`, and on
+  identifiers it was given (`domain`, `pool`, `volume`), curated results
-  failure `error` plus `libvirtCode`, `libvirtCodeName` and
+  (`state`, `path`, `interfaces`), `duration`, and on failure `error`
-  `libvirtMessage`. Connection events (`libvirt host connected`, dial
+  plus `libvirtError` (the code name, e.g. `ErrNoDomain`) and
+  `libvirtCode`. 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

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

@@ -55,3 +55,46 @@ 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.

docs/testing.md

@@ -120,11 +120,13 @@ verified — the log says so), `KVM_TEST_IMAGE_SHA256`, `KVM_TEST_POOL`
 `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
+logging the `-v` output shows: at `1` every libvirt RPC is one compact
-`libvirt call` line with method, identifiers, duration and error code,
+line (`HH:MM:SS.mmm libvirt virDomainLookupByName domain=... duration=...
-interleaved with the test's own `t.Log` lines; `2` adds the domain and
+error=... libvirtError=ErrNoDomain`), interleaved with the test's own
-volume XML, metadata and addresses; `0` leaves only `t.Log`. See the
+`t.Log` lines; `2` adds the domain and volume XML, metadata and
-Logging section of [kvm-provider.md](kvm-provider.md#logging).
+addresses; `0` leaves only `t.Log`. The per-run constants (provider,
+host, domain name) are left off each line. 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_test.go

@@ -586,7 +586,7 @@ func TestHostPool_call_tracesAtV1(t *testing.T) {
 		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 "} {
+	for _, want := range []string{`"msg"="libvirt host connected"`, `"address"="nas1:22"`, `"rpc"="virStoragePoolLookupByName"`, `"pool"="default"`, "libvirt "} {
 		if !strings.Contains(joined, want) {
 			t.Errorf("output missing %s:\n%s", want, joined)
 		}

internal/provider/kvm/errors.go

@@ -68,16 +68,13 @@ func logAPIError(log logr.Logger, op string, err error) {
 }
 
 // libvirtErrorFields renders a daemon-reported error as log key/values:
-// the numeric code, its constant name (ErrNoDomain, ...) and the daemon's
+// its constant name (ErrNoDomain, ...) and numeric code. The daemon's
-// message. Nil for transport and other non-libvirt errors.
+// message is already the error text. 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{
+	return []any{"libvirtError", libvirt.ErrorNumber(lerr.Code).String(), "libvirtCode", lerr.Code}
-		"libvirtCode", lerr.Code,
-		"libvirtCodeName", libvirt.ErrorNumber(lerr.Code).String(),
-		"libvirtMessage", lerr.Message,
-	}
 }

internal/provider/kvm/errors_test.go

@@ -76,8 +76,8 @@ func TestLibvirtErrorFields(t *testing.T) {
 		err  error
 		want []any
 	}{
-		{"libvirt error", lvErr(libvirt.ErrNoDomain), []any{"libvirtCode", uint32(42), "libvirtCodeName", "ErrNoDomain", "libvirtMessage", "ErrNoDomain"}},
+		{"libvirt error", lvErr(libvirt.ErrNoDomain), []any{"libvirtError", "ErrNoDomain", "libvirtCode", uint32(42)}},
-		{"wrapped libvirt error", fmt.Errorf("looking up: %w", lvErr(libvirt.ErrNoDomain)), []any{"libvirtCode", uint32(42), "libvirtCodeName", "ErrNoDomain", "libvirtMessage", "ErrNoDomain"}},
+		{"wrapped libvirt error", fmt.Errorf("looking up: %w", lvErr(libvirt.ErrNoDomain)), []any{"libvirtError", "ErrNoDomain", "libvirtCode", uint32(42)}},
 		{"transport error", io.EOF, nil},
 		{"cancelled", context.Canceled, nil},
 	}

internal/provider/kvm/image.go

@@ -101,7 +101,7 @@ func (c *imageCache) ensure(ctx context.Context, log logr.Logger, api libvirtAPI
 		return "", err
 	}
 	if ready {
-		log.V(1).Info("base image already cached", "host", hostName, "volume", src.volumeName())
+		log.V(1).Info("base image already cached", "volume", src.volumeName())
 		return api.StorageVolGetPath(base)
 	}
 	if err := deleteIfExists(api, pool, src.markerName()); err != nil {
@@ -170,7 +170,7 @@ func (c *imageCache) fetch(ctx context.Context, log logr.Logger, api libvirtAPI,
 	}
 
 	log.Info("fetching base image into host pool",
-		"host", hostName, "pool", pool.Name, "volume", src.volumeName(),
+		"pool", pool.Name, "volume", src.volumeName(),
 		"url", src.URL, "bytes", resp.ContentLength)
 	start := time.Now()
 
@@ -212,7 +212,7 @@ func (c *imageCache) fetch(ctx context.Context, log logr.Logger, api libvirtAPI,
 		return libvirt.StorageVol{}, fmt.Errorf("writing image marker: %w", err)
 	}
 	log.Info("base image cached",
-		"host", hostName, "volume", src.volumeName(), "sha256", digest,
+		"volume", src.volumeName(), "sha256", digest,
 		"bytes", resp.ContentLength, "duration", time.Since(start).Round(time.Second))
 	return base, nil
 }

internal/provider/kvm/kvm_integration_test.go

@@ -29,10 +29,13 @@ package kvm
 //	                       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
+// Provider logs are printed through t.Log in a compact form: time, logger
-// output. A run that hits its timeout may log one more line from the RPC
+// name, then the libvirt API function (or the message) and its fields.
-// the pool abandoned, after the test has ended; that is a symptom of the
+// The provider/host/name values that are the same on every line of a run
-// timeout, not a bug in the tracer.
+// are dropped; the first t.Log line of the run states them. 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"
@@ -43,12 +46,12 @@ import (
 	"net"
 	"os"
 	"strconv"
+	"strings"
 	"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"
 
@@ -127,11 +130,80 @@ func loadIntegrationEnv(t *testing.T) integrationEnv {
 // 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})
+	log := logr.New(&compactSink{t: t, verbosity: verbosity})
 	logf.SetLogger(log)
 	return log
 }
 
+// compactSink is a logr sink for test output: one line per record as
+// "HH:MM:SS.mmm name headline k=v ...", where the headline is the rpc
+// field when present (the libvirt API function) and the message
+// otherwise. Keys that are constant for the whole run are omitted.
+type compactSink struct {
+	t         *testing.T
+	verbosity int
+	name      string
+	values    []any
+}
+
+var compactOmit = map[string]bool{"provider": true, "host": true, "name": true}
+
+func (s *compactSink) Init(logr.RuntimeInfo) {}
+
+func (s *compactSink) Enabled(level int) bool { return level <= s.verbosity }
+
+// GetCallStackHelper lets logr mark its frames as helpers, so t.Log
+// attributes each line to the provider code that logged it.
+func (s *compactSink) GetCallStackHelper() func() { return s.t.Helper }
+
+func (s *compactSink) Info(_ int, msg string, kv ...any) {
+	s.t.Helper()
+	s.t.Log(s.format(msg, kv))
+}
+
+func (s *compactSink) Error(err error, msg string, kv ...any) {
+	s.t.Helper()
+	s.t.Log(s.format(msg, append(kv, "error", err)))
+}
+
+func (s *compactSink) WithValues(kv ...any) logr.LogSink {
+	c := *s
+	c.values = append(append([]any(nil), s.values...), kv...)
+	return &c
+}
+
+func (s *compactSink) WithName(name string) logr.LogSink {
+	c := *s
+	if c.name != "" {
+		name = c.name + "/" + name
+	}
+	c.name = name
+	return &c
+}
+
+func (s *compactSink) format(msg string, kv []any) string {
+	all := append(append([]any(nil), s.values...), kv...)
+	headline := msg
+	var b strings.Builder
+	for i := 0; i+1 < len(all); i += 2 {
+		key := fmt.Sprint(all[i])
+		if key == "rpc" {
+			headline = fmt.Sprint(all[i+1])
+			continue
+		}
+		if compactOmit[key] {
+			continue
+		}
+		val := fmt.Sprint(all[i+1])
+		if strings.ContainsAny(val, " \t\"=") {
+			val = strconv.Quote(val)
+		}
+		b.WriteString(" " + key + "=" + val)
+	}
+	name := s.name[strings.LastIndex(s.name, "/")+1:]
+	return fmt.Sprintf("%s %s %s%s", time.Now().Format("15:04:05.000"), name, headline, b.String())
+}
+
 func randomUID(t *testing.T) string {
 	t.Helper()
 	var b [16]byte

internal/provider/kvm/kvm_test.go

@@ -925,15 +925,15 @@ func TestLogging_verbosityTiers(t *testing.T) {
 			wantLines: []string{
 				`kvm/libvirt "level"=1 "msg"="libvirt host connected"`,
 				`"msg"="libvirt call"`,
-				`"method"="DomainLookupByName"`,
+				`"rpc"="virDomainLookupByName"`,
-				`"libvirtCodeName"="ErrNoDomain"`,
+				`"libvirtError"="ErrNoDomain"`,
-				`"method"="StorageVolUpload"`,
+				`"rpc"="virStorageVolUpload"`,
-				`"method"="DomainDefineXML"`,
+				`"rpc"="virDomainDefineXML"`,
-				`"method"="DomainCreate"`,
+				`"rpc"="virDomainCreate"`,
-				`"method"="DomainInterfaceAddresses"`,
+				`"rpc"="virDomainInterfaceAddresses"`,
-				`"method"="ConnectListAllDomains"`,
+				`"rpc"="virConnectListAllDomains"`,
-				`"method"="DomainUndefineFlags"`,
+				`"rpc"="virDomainUndefineFlags"`,
-				`"method"="StorageVolDelete"`,
+				`"rpc"="virStorageVolDelete"`,
 				`"provider"="kvm-home"`,
 				`"host"="nas1"`,
 				`"name"="` + testName + `"`,

internal/provider/kvm/trace.go

@@ -10,10 +10,11 @@ import (
 )
 
 // tracingAPI wraps a libvirtAPI and logs one V(1) line per call after it
-// returns: method, the identifiers it was given, curated results, duration,
+// returns: the libvirt API function (rpc=virDomainLookupByName, ...), the
-// and the libvirt error fields on failure. At V(2) the same line also
+// identifiers it was given, curated results, duration, and on failure the
-// carries XML bodies, metadata and address lists. Upload and download
+// error with libvirt's code name. At V(2) the same line also carries XML
-// bodies are never logged: the seed ISO carries cloud-init.
+// 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
@@ -26,8 +27,11 @@ type tracedCall struct {
 	kv     []any
 }
 
+// begin names the call by its libvirt API function: go-libvirt's method
+// names are the remote procedure names, which are the public vir* API
+// names without the prefix.
 func (t *tracingAPI) begin(method string, kv ...any) *tracedCall {
-	return &tracedCall{t: t, method: method, start: time.Now(), kv: kv}
+	return &tracedCall{t: t, method: "vir" + method, start: time.Now(), kv: kv}
 }
 
 // detail adds key/values that are only worth the bytes at V(2).
@@ -40,7 +44,7 @@ func (c *tracedCall) detail(kv ...any) *tracedCall {
 
 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, "rpc", c.method)
 	fields = append(fields, c.kv...)
 	fields = append(fields, kv...)
 	fields = append(fields, "duration", time.Since(c.start).Round(time.Microsecond))

internal/provider/kvm/trace_test.go

@@ -119,7 +119,7 @@ func TestTracingAPI_logsEveryMethod(t *testing.T) {
 			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"=`} {
+			for _, want := range []string{`"msg"="libvirt call"`, `"rpc"="vir` + tc.method + `"`, `"duration"=`} {
 				if !strings.Contains(lines[0], want) {
 					t.Errorf("line missing %s:\n%s", want, lines[0])
 				}
@@ -176,13 +176,13 @@ func TestTracingAPI_errorFields(t *testing.T) {
 		{
 			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`},
+			want:   []string{`"error"="Domain not found`, `"libvirtError"="ErrNoDomain"`, `"libvirtCode"=42`},
 		},
 		{
 			name:    "transport error has no libvirt fields",
 			inject:  io.EOF,
 			want:    []string{`"error"="EOF"`},
-			notWant: []string{`"libvirtCode"`},
+			notWant: []string{`"libvirtError"`, `"libvirtCode"`},
 		},
 	}
 	for _, tc := range tests {