diff --git a/docs/kvm-provider.md b/docs/kvm-provider.md index c79899e..b7aed5f 100644 --- a/docs/kvm-provider.md +++ b/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). diff --git a/docs/plans-executions/2026-09-04-1404-kvm-provider.md b/docs/plans-executions/2026-09-04-1404-kvm-provider.md index 18f61b3..ff9d7b1 100644 --- a/docs/plans-executions/2026-09-04-1404-kvm-provider.md +++ b/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. 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 new file mode 100644 index 0000000..3a4ac3c --- /dev/null +++ b/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. diff --git a/docs/testing.md b/docs/testing.md index 5ee1633..206a63c 100644 --- a/docs/testing.md +++ b/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//domains/` ID (downloading the image on a cold host — diff --git a/internal/provider/kvm/conn.go b/internal/provider/kvm/conn.go index b0034b0..4531532 100644 --- a/internal/provider/kvm/conn.go +++ b/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 diff --git a/internal/provider/kvm/conn_test.go b/internal/provider/kvm/conn_test.go index 732413b..d6105f1 100644 --- a/internal/provider/kvm/conn_test.go +++ b/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) + } + }) +} diff --git a/internal/provider/kvm/errors.go b/internal/provider/kvm/errors.go index 51bb20e..6896c01 100644 --- a/internal/provider/kvm/errors.go +++ b/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, + } +} diff --git a/internal/provider/kvm/errors_test.go b/internal/provider/kvm/errors_test.go index 1f00ad7..6ce0065 100644 --- a/internal/provider/kvm/errors_test.go +++ b/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) + } + }) + } +} diff --git a/internal/provider/kvm/kvm.go b/internal/provider/kvm/kvm.go index 6d94dc4..ed4613e 100644 --- a/internal/provider/kvm/kvm.go +++ b/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) diff --git a/internal/provider/kvm/kvm_integration_test.go b/internal/provider/kvm/kvm_integration_test.go index 1e1faf7..32bf5a7 100644 --- a/internal/provider/kvm/kvm_integration_test.go +++ b/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 diff --git a/internal/provider/kvm/kvm_test.go b/internal/provider/kvm/kvm_test.go index 087c371..60d50da 100644 --- a/internal/provider/kvm/kvm_test.go +++ b/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"=") 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"="= 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")) + } +}