diff --git a/docs/kvm-provider.md b/docs/kvm-provider.md index b7aed5f..d861acb 100644 --- a/docs/kvm-provider.md +++ b/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`), - curated results (`state`, `path`, `interfaces`), `duration`, and on - failure `error` plus `libvirtCode`, `libvirtCodeName` and - `libvirtMessage`. Connection events (`libvirt host connected`, dial + `rpc` (the libvirt API function, e.g. `virDomainLookupByName`), the + identifiers it was given (`domain`, `pool`, `volume`), curated results + (`state`, `path`, `interfaces`), `duration`, and on failure `error` + 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 diff --git a/docs/plans-executions/2026-09-10-0805-kvm-libvirt-tracing.md b/docs/plans-executions/2026-09-10-0805-kvm-libvirt-tracing.md index 3a4ac3c..f6f747c 100644 --- a/docs/plans-executions/2026-09-10-0805-kvm-libvirt-tracing.md +++ b/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. diff --git a/docs/testing.md b/docs/testing.md index 206a63c..c4d79d1 100644 --- a/docs/testing.md +++ b/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 -`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). +logging the `-v` output shows: at `1` every libvirt RPC is one compact +line (`HH:MM:SS.mmm libvirt virDomainLookupByName domain=... duration=... +error=... libvirtError=ErrNoDomain`), interleaved with the test's own +`t.Log` lines; `2` adds the domain and volume XML, metadata and +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//domains/` ID (downloading the image on a cold host — diff --git a/internal/provider/kvm/conn_test.go b/internal/provider/kvm/conn_test.go index d6105f1..452d66a 100644 --- a/internal/provider/kvm/conn_test.go +++ b/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) } diff --git a/internal/provider/kvm/errors.go b/internal/provider/kvm/errors.go index 6896c01..158449f 100644 --- a/internal/provider/kvm/errors.go +++ b/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 -// message. Nil for transport and other non-libvirt errors. +// its constant name (ErrNoDomain, ...) and numeric code. The daemon's +// 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{ - "libvirtCode", lerr.Code, - "libvirtCodeName", libvirt.ErrorNumber(lerr.Code).String(), - "libvirtMessage", lerr.Message, - } + return []any{"libvirtError", libvirt.ErrorNumber(lerr.Code).String(), "libvirtCode", lerr.Code} } diff --git a/internal/provider/kvm/errors_test.go b/internal/provider/kvm/errors_test.go index 6ce0065..b8ccd65 100644 --- a/internal/provider/kvm/errors_test.go +++ b/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"}}, - {"wrapped libvirt error", fmt.Errorf("looking up: %w", 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{"libvirtError", "ErrNoDomain", "libvirtCode", uint32(42)}}, {"transport error", io.EOF, nil}, {"cancelled", context.Canceled, nil}, } diff --git a/internal/provider/kvm/image.go b/internal/provider/kvm/image.go index ffdc0e1..a13645c 100644 --- a/internal/provider/kvm/image.go +++ b/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 } diff --git a/internal/provider/kvm/kvm_integration_test.go b/internal/provider/kvm/kvm_integration_test.go index 32bf5a7..6e9e157 100644 --- a/internal/provider/kvm/kvm_integration_test.go +++ b/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 -// 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. +// Provider logs are printed through t.Log in a compact form: time, logger +// name, then the libvirt API function (or the message) and its fields. +// The provider/host/name values that are the same on every line of a run +// 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 diff --git a/internal/provider/kvm/kvm_test.go b/internal/provider/kvm/kvm_test.go index 60d50da..c1f3603 100644 --- a/internal/provider/kvm/kvm_test.go +++ b/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"`, - `"libvirtCodeName"="ErrNoDomain"`, - `"method"="StorageVolUpload"`, - `"method"="DomainDefineXML"`, - `"method"="DomainCreate"`, - `"method"="DomainInterfaceAddresses"`, - `"method"="ConnectListAllDomains"`, - `"method"="DomainUndefineFlags"`, - `"method"="StorageVolDelete"`, + `"rpc"="virDomainLookupByName"`, + `"libvirtError"="ErrNoDomain"`, + `"rpc"="virStorageVolUpload"`, + `"rpc"="virDomainDefineXML"`, + `"rpc"="virDomainCreate"`, + `"rpc"="virDomainInterfaceAddresses"`, + `"rpc"="virConnectListAllDomains"`, + `"rpc"="virDomainUndefineFlags"`, + `"rpc"="virStorageVolDelete"`, `"provider"="kvm-home"`, `"host"="nas1"`, `"name"="` + testName + `"`, diff --git a/internal/provider/kvm/trace.go b/internal/provider/kvm/trace.go index 152f65b..c3d8e21 100644 --- a/internal/provider/kvm/trace.go +++ b/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, -// 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. +// returns: the libvirt API function (rpc=virDomainLookupByName, ...), the +// identifiers it was given, curated results, duration, and on failure the +// error with libvirt's code name. 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 @@ -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)) diff --git a/internal/provider/kvm/trace_test.go b/internal/provider/kvm/trace_test.go index 98e60a8..0a11a30 100644 --- a/internal/provider/kvm/trace_test.go +++ b/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 {