Closes out the review-fix campaign. The kvm2 provider was deployed in-cluster and validated against beelink -- the first time any of this code had run against real libvirt rather than the in-memory fake. config/manager/providers_config.yaml ships the kvm2-home entry enabled, since the operator is now running it for real. review/ carries the code review the four H-commits reference, so H1..H4 resolve to something rather than dangling: scope, the seven-chunk sweep, the escalations, the ten deep dives and the final report. .claude/agents carries the two reviewer definitions that produced them. What the validation did not prove is recorded next to what it did: H2's error paths need a body that fails part way through, and a healthy 433 MB download never finishes short, so the unverified libvirtd short-stream behaviour is still open. The kvm2 integration test has also still never been run. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
532 lines
31 KiB
Markdown
532 lines
31 KiB
Markdown
# Execution: fix the kvm2 code-review findings
|
|
Plan: [docs/plans/2026-09-17-1515-kvm2-review-fixes.md](../plans/2026-09-17-1515-kvm2-review-fixes.md)
|
|
|
|
- [x] Step 0 — Save plan into the repo
|
|
- [x] Step 1 — H1: a stalled write must not delay the teardown
|
|
- [x] Step 2 — H2: a source error must not reach go-libvirt's stream sender
|
|
- [x] Step 3 — H3: an unreadable address must not look like a missing one
|
|
- [x] Step 4 — H4: the base image cache must not be shared across provider entries
|
|
|
|
- [x] Step 5 — Validate H1-H4 in-cluster against beelink
|
|
- [x] Step 6 — Route klog into the structured logger
|
|
|
|
Remaining after those: the 48 mediums and lows in `review/REPORT.md`. Each gets its own
|
|
checklist line here when it is planned, so this list stays a record of decided work rather
|
|
than a wish.
|
|
|
|
## Step 0 — plan committed
|
|
|
|
Copied out of `~/.claude/plans/` and committed alone before touching code, as the repo's
|
|
plan rules require.
|
|
|
|
## Step 1 — H1: close the SSH client, and signal dead before killing
|
|
|
|
Two edits, both small, in the order the bug unfolds.
|
|
|
|
`sshSocket.Close` was `errors.Join(s.Conn.Close(), s.client.Close())`. Go evaluates those
|
|
arguments left to right, so the blocking close ran before the unblocking one. `s.Conn` is
|
|
the forwarded libvirt socket, and closing an SSH channel writes a close message under
|
|
`ch.writeMu`, which go-libvirt already holds while streaming a base image through the same
|
|
channel. Against a host that vanished without RST or FIN, that write blocks until the
|
|
kernel stops retransmitting — `tcp_retries2`, about 15 minutes. `s.client.Close()`, a bare
|
|
`net.Conn.Close()` on the TCP socket that takes no lock and unblocks the stalled writer
|
|
through netpoll, was never reached. It now closes the client only.
|
|
|
|
**Dropping the channel close rather than reordering it** was the judgment call. Reordering
|
|
works, but afterwards the channel close returns an error — `net.ErrClosed`, a
|
|
`*net.OpError`, the transport's sticky write error, or `io.EOF` once `mux.loop` has run
|
|
`ch.close()` — and `closeErr` is memoised, so a filter that missed a case would poison
|
|
every later `Close` and break `ssh_test.go:66,69`, which assert both closes return nil.
|
|
Nothing wants the polite channel-close message: `dialSSHSocket` builds the client solely
|
|
for this one channel, the `sshSocket` owns it exclusively, and `dialSSHSocket`'s own error
|
|
paths already tear down by closing the client.
|
|
|
|
`link.markDead` then compounded it by running `kill()` before `close(l.closed)`, and doing
|
|
both inside a `sync.Once`. Reordering alone would not have been enough: `sync.Once.Do`
|
|
blocks concurrent callers until the first body returns, so every other `markDead` — including
|
|
the one in `call`'s own ctx-cancel branch — queued behind the stalled kill. **Cancelling the
|
|
reconcile did not help.** The `once` field is gone; the mutex the struct already had now
|
|
guards the "close it exactly once" invariant, `reason` is set before the signal so a
|
|
released caller always reads a populated `deadReason()`, and `kill` runs outside the lock.
|
|
|
|
**A second route to the same pin, found while planning and fixed by the same edits.**
|
|
go-libvirt's `Disconnect` closes the `net.Conn` it was handed (`libvirt.go:331` →
|
|
`socket.go:164`) — and that conn *is* our `*sshSocket`. So `libvirtBackend.Close`'s
|
|
`Disconnect` goroutine entered `sshSocket.closeOnce` and hung there; the 5 s `closeBudget`
|
|
released `Close`, which called `markDead("closed")` → `kill()` → `sshSocket.Close()` →
|
|
blocked in the other goroutine's `sync.Once`. The budget did not protect it.
|
|
|
|
The precondition was verified in the pinned x/crypto v0.54.0 rather than assumed: the
|
|
flow-control park (`remoteWin.reserve`, `channel.go:268`) happens *outside* `writeMu`, and
|
|
only `writePacket` holds it across the TCP write. So a writer parked in SSH flow control
|
|
never blocks the close; a writer inside the TCP write always does. Since the channel window
|
|
is 2 MiB (`channelWindowSize = 64 * channelMaxPacket`), reproducing it by hand needs a
|
|
kernel send buffer that fills first — shrink `SO_SNDBUF` well under 2 MiB.
|
|
|
|
The older kvm provider does not have this bug: it closes `client` only
|
|
(`internal/provider/kvm/conn.go:429,456`) and never touches the forwarded channel. kvm2's
|
|
rewrite introduced it.
|
|
|
|
### Tests: planned four, shipped one
|
|
|
|
The first draft had three hermetic tests plus a `//go:build integration && linux`
|
|
stalled-write test with a TCP proxy and shrunken socket buffers. The user pushed back —
|
|
once the bug is fixed the connection closes properly, so what is left to test? — and they
|
|
were right about most of it. `TestDial_forwardsUnixSocket` already covers "Close tears the
|
|
connection down", and after the fix `Close` is a single call with no ordering to get wrong.
|
|
The stalled-write test was the worst of the four: ~150 lines of Linux-only,
|
|
buffer-autotuning-dependent scaffolding whose own false-green guard made it *skip* whenever
|
|
the kernel did not cooperate, to demonstrate a bug that reading x/crypto settles and that
|
|
the fix deletes the code path for.
|
|
|
|
What survived is `TestMarkDead_slowKillDoesNotBlockCallers`, because the `markDead` change
|
|
*adds* a guarantee that did not exist before and nothing else touches it —
|
|
`TestCall_killedByAnotherCallerFailsTransient` passes a nil kill, so it cannot see the
|
|
property. It is also the plausible regression: restoring the `sync.Once` looks like a
|
|
correctness improvement. The call's own `fn` signals when it is in flight, so the parked
|
|
caller is genuinely parked rather than refused by the dead check on the way in.
|
|
|
|
The step that actually validates a regression test is running it against the unfixed code.
|
|
`markDead` was reverted in place, the test run, and the fixed version restored from a copy:
|
|
|
|
```bash
|
|
cp internal/provider/kvm2/backend.go "$SCRATCH/backend.go.fixed"
|
|
# ... revert markDead to the sync.Once form and re-add the once field ...
|
|
go test -race -count=1 -run 'TestMarkDead_slowKillDoesNotBlockCallers' ./internal/provider/kvm2/
|
|
# --- FAIL: TestMarkDead_slowKillDoesNotBlockCallers (1.00s)
|
|
# backend_test.go:186: link not signalled dead while its kill is still running
|
|
cp "$SCRATCH/backend.go.fixed" internal/provider/kvm2/backend.go
|
|
```
|
|
|
|
It fails in a second with the right diagnostic rather than hanging the suite, because the
|
|
blocked kill is released by `t.Cleanup`.
|
|
|
|
```bash
|
|
go build ./... && go vet ./... && go test -race -count=1 ./internal/provider/kvm2/
|
|
```
|
|
|
|
### Worth noting
|
|
|
|
**An accepted risk, deliberately not covered by a test.** Nothing now stops someone
|
|
re-adding `s.Conn.Close()` to `sshSocket.Close` as tidiness; it would look harmless and
|
|
every test would still pass, because in a healthy test the channel close returns instantly.
|
|
The guard is the doc comment on `sshSocket`, which says outright that closing the channel
|
|
would queue behind a stalled transfer. That is in idiom for this package — `hosts.go:25-34`
|
|
and `create.go:151-153` carry the same kind of hard-won decision — but it is a comment, not
|
|
a test, and the failure it prevents is a 15-minute operator-wide stall.
|
|
|
|
**Left for later, on purpose.** `ReconciliationTimeout` in `SetupWithManager` does not exist
|
|
in this repo at all; adding a per-reconcile deadline would change the contract for every
|
|
provider, since `hosts.go` and `image.go` both cite "no caller deadline", so it needs its own
|
|
change and its own spec entry. `sshSocket.keepalive` still has no test (sweep finding S1.2).
|
|
|
|
**Docs.** `docs/kvm2-provider.md` said the adapter "kills the connection (socket and SSH
|
|
client)", which is no longer true and was the description that made the bug look correct.
|
|
It now states the order (mark dead, then kill) and why both steps are lock-free.
|
|
`docs/kvm2-provider-spec.md` entries 18 and 19 were checked and are not falsified.
|
|
|
|
**No CHANGELOG entry yet** — the repo's rule is to add one once the user confirms the change
|
|
works, so it lands with a later "validate and record" step, as in the kvm campaign.
|
|
|
|
## Step 2 — H2: a source error must not reach go-libvirt's stream sender
|
|
|
|
This one is a workaround, not a repair. The defect is upstream, and the entry says so in
|
|
three places (code comment, `docs/kvm2-provider.md` *Known gaps*, commit message) so nobody
|
|
later reads the wrapper as ours to delete.
|
|
|
|
`requestStream` in the pinned go-libvirt starts its stream sender on two **unbuffered**
|
|
channels and then, on the error path, returns without ever reading `outErr`. A non-EOF error
|
|
from the reader makes `SendStream` emit a StatusError packet and return, whereupon it parks on
|
|
`outErr <-` forever; libvirtd answers the StatusError with an error, so the main goroutine
|
|
parks on `abort <- true` forever. `StorageVolUpload` never returns. The 20-minute budget
|
|
rescues only the caller, and the socket kill does nothing at all here, because both ends are
|
|
blocked on channel sends rather than on I/O — which is what the comment at `backend.go:152`
|
|
got wrong. Every failed upload leaked two goroutines and 4 MiB against a 128Mi pod limit,
|
|
with the reconciler retrying on backoff.
|
|
|
|
Three changes.
|
|
|
|
`eofReader` sits at the go-libvirt seam in `backend.go`, not in `image.go`, so it also covers
|
|
the seed and marker uploads, and so it stays out of the file Step 4 rewrites. It converts any
|
|
source error to `io.EOF` — the one outcome that ends a stream the normal way — and keeps the
|
|
real error for `StorageVolUpload` to return afterwards. `countingReader` is untouched
|
|
underneath it and still sees the true error, so `uploadImage`'s existing length and digest
|
|
checks produce exactly the messages they did before.
|
|
|
|
The download now carries its own deadline, one minute inside the transfer budget.
|
|
`fetchImage` already bounded the whole fetch at 20 minutes, so the body's death and the
|
|
budget's socket kill were racing, and the socket usually won. With the body a minute ahead, a
|
|
stalled mirror ends through the reader and unwinds cleanly. This is the difference between a
|
|
slow mirror costing a Transient error and costing a permanent leak, and slow mirrors are the
|
|
realistic repeat offender.
|
|
|
|
`discardVolume` moved from `uploadImage` up into `fetchImage`'s upload-error branch, so the
|
|
dedicated connection is closed — and libvirtd has let go of the stream's fd — before the file
|
|
is unlinked. Moving it rather than adding a second `Close` is what keeps
|
|
`image_test.go`'s `closeCount() == 1` assertion true. `uploadImage` lost its `be` parameter
|
|
and its private logger in the process.
|
|
|
|
**What is left, deliberately.** A failure that originates in libvirtd mid-upload (ENOSPC, or
|
|
the volume deleted underneath) still leaks, because by then `SendStream` has already returned
|
|
and nothing we pass, cancel or close can reach it. Confirmed unfixable from this side. The
|
|
upstream fix is two characters and is quoted in *Known gaps* along with the `replace` escape
|
|
hatch, should it ever bite hard enough to be worth the maintenance.
|
|
|
|
**Unverified, ~85%.** That libvirtd answers a short-but-clean stream finish with OK rather
|
|
than an error. `virFDStreamWrite` enforces `length` only on writes past it and nothing
|
|
compares `offset` to `length` on the close path, which is also why `virsh vol-upload` of a
|
|
small file into a large volume works. If it answers with an error we land back in a deadlock
|
|
by a different door — but that is precisely today's behaviour, so the change cannot make
|
|
things worse. To settle it, on any box with a libvirtd (not beelink, which is read-only
|
|
here), against the pinned go-libvirt:
|
|
|
|
```sh
|
|
virsh -c qemu:///session pool-define-as probe dir --target ~/vmprobe
|
|
virsh -c qemu:///session pool-start probe
|
|
virsh -c qemu:///session vol-create-as probe short.raw 10M --format raw
|
|
# then a ~40-line main.go: StorageVolUpload(vol, r, 0, 10<<20, 0) where r
|
|
# yields 1 MiB then io.EOF; print the error, then runtime.NumGoroutine()
|
|
# and a goroutine profile after a two-second settle.
|
|
```
|
|
|
|
Expected: `err == nil` and the goroutine count back at baseline. The same program with a
|
|
reader that returns a non-EOF error should wedge against the *unpatched* seam, which also
|
|
confirms the diagnosis end to end.
|
|
|
|
The negative check that matters was run on the unit test instead — `eofReader.Read` was
|
|
changed back to returning the real error, and both new tests failed with
|
|
`io.Copy through eofReader = connection reset by peer, want nil`, then passed again once
|
|
restored.
|
|
|
|
```bash
|
|
go build ./... && go vet ./... && go test -race -count=1 ./internal/provider/kvm2/
|
|
```
|
|
|
|
### Worth noting
|
|
|
|
The `fetchImage` discard is still unfenced against a second provider entry that shares the
|
|
volume name — Step 4 (H4) is what closes that, by making the name per-entry. The deferred
|
|
atomic-publish work then lands exactly where this step put the discard.
|
|
|
|
**Deliberately not tested:** the abort protocol end to end. `libvirttest` reads a fixed
|
|
28-byte header per packet and implements no stream procedures, so pinning this hermetically
|
|
would mean a 150-250 line libvirt RPC server stub whose only assertion is about *upstream's*
|
|
goroutines. Same call as H1's: the test would cost more than it protects. The two tests that
|
|
did land pin the one property the seam actually needs.
|
|
|
|
## Step 3 — H3: an unreadable address must not look like a missing one
|
|
|
|
`address()` tried the guest agent then the host's ARP table and skipped any error that was
|
|
not a context error, returning `("", nil)` after both. An active domain with no IP maps to
|
|
`StateProvisioning`, the controller clears `status.IP` on that, and the health engine prunes
|
|
the proxy's counters and calls `ForgetProxy` in one tick once `EffectiveHost()` is empty.
|
|
|
|
The damaging trigger was not the guest. The libvirt connection is pooled per host, so when
|
|
another reconcile's cancel or budget overrun killed it, `call` returned
|
|
`"connection is closed"` — carrying no context sentinel, so the check did not recognise it —
|
|
and `Get` returned a *successful* instance in Provisioning with an empty IP. An unrelated
|
|
proxy's timeout dropped a healthy proxy out of rotation.
|
|
|
|
The fix rests on a discriminator the spec had already recorded without drawing the
|
|
conclusion: during a normal boot on beelink exactly one source fails. The agent errors
|
|
because it is not up yet, while ARP answers *without* error and with nothing, since the host
|
|
never sees the guest's traffic. So one source failing is "no address yet"; every source
|
|
failing, or a connection already dead, is `ErrTransient`.
|
|
|
|
The explicit `provider.ErrTransient` wrap on the joined error is load-bearing rather than
|
|
decoration. Without it `classify` picks the first libvirt code out of the join tree, and
|
|
`ErrInvalidArg`, `ErrAccessDenied` and `ErrNoSupport` are Permanent — an address read failing
|
|
would have latched a *running* proxy as Failed, a worse version of the harm being fixed.
|
|
|
|
`isDead(be)` is checked first in the error branch. It is not strictly needed, since a dead
|
|
link fails both sources and the count rule catches it anyway, but it fails on the first
|
|
source instead of the second, attributes the error better, and is the same predicate M15 will
|
|
want for `ListByTag`.
|
|
|
|
### Tests
|
|
|
|
`TestGet_addressErrorIsProvisioning` failed against the new rule, which is correct: it fails
|
|
*both* sources with `ErrAgentUnresponsive`, and code 86 is agent-specific — the ARP source
|
|
cannot produce it. Re-pointed as `TestGet_agentFailsAndARPEmptyIsProvisioning`, the beelink
|
|
boot it was really reaching for: agent errors, ARP returns no addresses and no error, result
|
|
is Provisioning. Nothing covered that before, and it is the case the new rule must not break.
|
|
|
|
`TestGet_everyAddressSourceFailingIsTransient` covers the other side, two subtests: both
|
|
sources erroring, and the pooled connection dying under the read. Against the unfixed code
|
|
both return a Provisioning instance instead of an error, which is exactly the bug:
|
|
|
|
```bash
|
|
# with isDead() and the every-source-failed arm removed from address():
|
|
go test -count=1 -run TestGet_everyAddressSourceFailingIsTransient ./internal/provider/kvm2/
|
|
# get_test.go:215: Get = &{... IP: State:Provisioning ...}, want no instance
|
|
```
|
|
|
|
`TestGet_arpFallbackWhenAgentFails` passes untouched — one source of two.
|
|
|
|
### Worth noting
|
|
|
|
**Half of H3 is deliberately still open, and it is the half that fires more often.** A guest
|
|
agent restarting inside a running VM still demotes it to Provisioning and clears its IP: the
|
|
agent errors, ARP answers empty, and that is indistinguishable from a VM still booting. The
|
|
discriminator is the *previous* IP, which the provider does not hold by design
|
|
(`TestGet_readsUIDAndCreatedAtFromBackend` pins "read back, not remembered") and the
|
|
controller already has. Follow-up finding, to be filed against
|
|
`internal/controller/proxy_controller.go:208-211`: on `StateProvisioning`, keep an existing
|
|
IP and `Provisioned` condition for a few polls rather than clearing on the first, or give the
|
|
health engine a grace period before pruning.
|
|
|
|
The one kvm2-local alternative was considered and rejected: the mark carries `createdAt`, so
|
|
`get` could treat "active, no address from any source, domain older than a provisioning
|
|
window" as an error. It uses state the provider genuinely has, but `createdAt` is creation
|
|
rather than boot, it fires on every genuinely stuck VM as a retry-forever error, and it
|
|
invents a provisioning deadline that belongs to the controller. A design change wearing a bug
|
|
fix's clothes.
|
|
|
|
**L6 not folded in.** A domain that vanishes between `DomainGetState` and the address read
|
|
now returns Transient rather than a fake Provisioning — better, and self-correcting on the
|
|
next poll. Returning NotFound one poll earlier is a two-line addition at the same spot, left
|
|
for when L6 comes up so this commit stays one idea.
|
|
|
|
## Step 4 — H4: the base image cache must not be shared across provider entries
|
|
|
|
`baseVolumeName` was `base-<key>.<format>` — byte-identical to what
|
|
`internal/provider/kvm/image.go` builds in the same pool, for URL images too (kvm takes
|
|
`hex(sum[:8])`, kvm2 takes `hex(sum[:])[:16]`, the same eight bytes), with a completely
|
|
separate lock table. The shipped config has a live `kvm-home` entry and a commented-out
|
|
`kvm2-home` entry on the same host, the same key `debian-13` and the same default pool, and
|
|
the comment invites the operator to enable it. Both integration tests use key `test-image`.
|
|
On beelink both live overlays back onto kvm's `base-debian-13.qcow2`.
|
|
|
|
Since `cachedImage` accepts any 64-hex marker when no `sha256` is configured and never
|
|
re-hashes the base, that meant: two entries pointing one key at different URLs silently share
|
|
a file; a concurrent cold fetch lets one entry delete the other's half-uploaded base and boot
|
|
a guest from the remains; and a `sha256` edit deletes the base in place under live overlays,
|
|
which libvirt permits without complaint.
|
|
|
|
The name now carries the provider entry: `base-<entry>-<key>.<format>`. `imageSource` gained
|
|
an `Entry` field and `resolveImage` takes the provider name, so the four production call
|
|
sites all follow from `imageSource.volumeName()`. That closes the cross-entry sharing
|
|
outright, kvm↔kvm2 and kvm2↔kvm2 alike, and it turns the existing per-`Provider` `imageLocks`
|
|
from a latent bug into a correct one — with names unique per entry, no two entries can
|
|
contend for a file, so a process-wide lock table is not needed.
|
|
|
|
**The entry name reaches a file name, so it now has to be a usable one.** Provider names are
|
|
validated for all types at once and only for being non-empty and unique
|
|
(`internal/provider/config.go`), so `New` checks its own against the existing `kvmIdentifier`
|
|
rule, exported as `provider.IsKVMIdentifier` rather than duplicated. A name with a slash
|
|
fails at startup instead of producing a volume nothing can address.
|
|
|
|
**One companion fix, because the naming alone does not stop it.** `cachedImage`'s
|
|
digest-mismatch branch deleted the marker and the base and refetched. It now returns
|
|
`ErrPermanent` naming both digests and telling the operator what to do. That branch was the
|
|
remaining path that unlinks a good file under running domains, and the contract already said
|
|
"add a new key instead" — the code was contradicting it. The no-marker and non-hex-marker
|
|
branches keep deleting, since there the base is genuine debris.
|
|
|
|
### What this does NOT fix
|
|
|
|
Stated plainly rather than left to look closed:
|
|
|
|
- **Editing `images.<key>.url` is still a silent no-op.** The cache is keyed by entry and
|
|
key, and nothing records the URL, so the new one is never fetched. Pre-existing, already
|
|
documented as "add a new key"; the eviction section now says it outright.
|
|
- **Cross-process fencing.** Two managers, or a manager plus a hand-run `virsh`, can still
|
|
meet on one name. E4 refuted the rollout and leader-handover triggers for the shipped
|
|
manifests, so this is narrow, and its fix is the deferred atomic publish — upload to a temp
|
|
name, verify, publish — which lands where H2 put the discard.
|
|
|
|
### Migration
|
|
|
|
Nothing to do. The `base-debian-13.qcow2` on beelink is kvm's, kvm keeps using it untouched,
|
|
and kvm2 downloads its own copy once per host when `kvm2-home` is enabled. No window in which
|
|
anything is replaced under a running guest. The pool needs room for both, which the
|
|
prerequisites now say.
|
|
|
|
### Tests
|
|
|
|
Mostly literals becoming helpers, plus a new `fx.baseName()` in `provider_test.go` for the
|
|
three fixtures that asserted `"base-debian-13.qcow2"` by hand. The log and span assertions in
|
|
`TestEnsureImage_downloadsAndWritesMarkerLast` keep asserting a full name rather than loosening
|
|
to a prefix, so they still pin that the key stays readable in operator-facing output.
|
|
|
|
One test changed behaviour rather than spelling: `TestEnsureImage_sha256ChangeRedownloads`
|
|
became `TestEnsureImage_sha256ChangeRefusesInsteadOfReplacing`, asserting Permanent, zero
|
|
server hits, zero deletes, and both volumes untouched. Two added:
|
|
`TestNew_rejectsUnsafeEntryName`, and a `TestVolumeNames` row for a second entry with the same
|
|
key.
|
|
|
|
Both negative checks were run:
|
|
|
|
```bash
|
|
# baseVolumeName reverted to base-<key>.<format>:
|
|
go test -count=1 -run TestVolumeNames ./internal/provider/kvm2/
|
|
# volume_test.go:135: got "base-debian-13.qcow2", want "base-kvm2-lab-debian-13.qcow2"
|
|
|
|
# the digest branch reverted to delete-and-refetch:
|
|
go test -count=1 -run TestEnsureImage_sha256ChangeRefuses ./internal/provider/kvm2/
|
|
# image_test.go:412: ensureImage() error = <nil>, want ErrPermanent telling the operator what to do
|
|
```
|
|
|
|
`go vet -tags=integration` was run too, since `kvm2_integration_test.go:484` builds the base
|
|
name and only compiles under that tag.
|
|
|
|
### Worth noting
|
|
|
|
**The integration test has still never run on beelink.** Step 11 is unchecked in
|
|
`docs/plans-executions/2026-09-16-1333-kvm2-provider.md`, every `base-*` on the host predates
|
|
kvm2, and both live domains carry the kvm v1 metadata namespace. After this change it is also
|
|
the first end-to-end exercise of the new name, and it will do a real cold download under
|
|
`base-kvm2-integration-test-image.qcow2` beside kvm's untouched `base-test-image.qcow2`.
|
|
|
|
**Docs touched beyond the obvious:** the eviction recipe named `base-debian-13.qcow2`, which
|
|
after this change is *kvm's* file — following it would have deleted the wrong provider's base.
|
|
It now greps for the prefix and deletes the marker first.
|
|
|
|
## Step 6 — Route klog into the structured logger
|
|
|
|
Not a review finding. Found while watching the Step 5 validation: some lines ignored the zap
|
|
encoder no matter what, so `kubectl logs | jq` could never work.
|
|
|
|
```
|
|
I0917 19:50:02.580097 1 leaderelection.go:258] "Attempting to acquire leader lease..." lock="..."
|
|
```
|
|
|
|
That is klog's own stderr writer, not ours. client-go's leader elector calls
|
|
`klog.FromContext(ctx)` (`leaderelection.go:257`), and controller-runtime hands the elector a
|
|
context with no logr in it — `mgr.Start` receives `ctrl.SetupSignalHandler()`, which carries no
|
|
logger (`pkg/manager/internal.go:461-473`). `FromContext` falls back to `Background()`, and with
|
|
no logger registered that is klog's text sink. Nothing in this repo imported or configured klog;
|
|
it was an indirect dependency that around 60 linked packages use, including
|
|
`client-go/tools/{leaderelection,cache,record}` and `client-go/transport`. controller-runtime
|
|
does not route it either — its only `klog.SetLogger` call is in its own test suite.
|
|
|
|
**`klog.SetLogger(logger)`, deliberately not `SetLoggerWithOptions(logger, ContextualLogger(true))`.**
|
|
The contextual form is what klog's docs recommend, because it skips a klogr round trip. It also
|
|
disables klog's verbosity gate ("Such a logger cannot rely on verbosity checking in klog",
|
|
`contextual.go:83-86`), handing the decision to zap — whose level under `Development: true` is
|
|
Debug, which enables V(1). client-go's V(1) chatter, suppressed today by klog's own `-v=0`,
|
|
would have started appearing. Plain `SetLogger` keeps klog's check in front and still redirects
|
|
what it does emit ("all log lines will be suppressed from the regular output, and redirected to
|
|
the logr implementation", `contextual.go:47-48`). Same fix to the format, no new volume — which
|
|
matters, because the complaint that started this was volume.
|
|
|
|
`k8s.io/klog/v2` moves from indirect to direct in `go.mod`. It was already in the module graph;
|
|
nothing new is downloaded.
|
|
|
|
**The other bypass.** The discovery API's `http.Server` set no `ErrorLog`, so `net/http`'s own
|
|
faults — a failed `Accept`, a panic escaping a handler — went to the stdlib logger on stderr.
|
|
It now drains into logr through `logr.ToSlogHandler`, the pattern
|
|
`internal/provider/gcp/wirelog.go:31-36` already uses. This server is plain HTTP with no TLS, so
|
|
`ErrorLog` carries real faults rather than handshake noise, and Error level is right.
|
|
|
|
**Deployment.** `--zap-encoder=json` and `--zap-time-encoding=rfc3339` on the manager.
|
|
Verified the flag beats the in-code default rather than assuming it: `addDefaults` fills
|
|
`NewEncoder` only `if o.NewEncoder == nil` (`zap.go:176-191`) and `BindFlags` sets it from the
|
|
flag. The time encoding is not optional — the JSON encoder defaults to epoch seconds.
|
|
Verbosity was left at debug on purpose; `--zap-log-level=info` drops the per-RPC lines.
|
|
|
|
`opts := zap.Options{Development: true}` stays. Flipping it would change the format for every
|
|
deployment of this operator, and the flags get the same result here without that reach.
|
|
|
|
### Tests
|
|
|
|
None. Three changes, all wiring: two struct fields and a manifest key. `cmd/main.go` has no test
|
|
coverage, and pinning `klog.SetLogger` means mutating process-global state that leaks into every
|
|
other test in the package. Verified by observation instead, which for this change is stronger
|
|
than a unit test would be.
|
|
|
|
### Verification
|
|
|
|
```bash
|
|
kubectl -n egress-proxies-operator-system logs deploy/... | grep -i leader
|
|
# {"level":"info","ts":"2026-09-17T20:10:00Z","msg":"Attempting to acquire leader lease...",
|
|
# "lock":"egress-proxies-operator-system/b47711d1.example.com"}
|
|
|
|
kubectl -n egress-proxies-operator-system logs deploy/... | jq -e -s 'length > 0'
|
|
# YES - every line is valid JSON
|
|
```
|
|
|
|
The `jq -s` check is the one that counts: it fails if *any* line is not JSON, which is exactly
|
|
the property being fixed. All four existing proxies stayed Ready across the rollout and all
|
|
three ProviderHealth entries stayed Ready.
|
|
|
|
### Worth noting
|
|
|
|
**The JSON encoder renders durations as float seconds**, so `"duration":"566.12µs"` became
|
|
`"duration":0.000336664`. Machine-friendlier, worse to read. Either format in the query —
|
|
`(.duration*1000000|round)` for µs — or pass an encoder config option in code, which
|
|
controller-runtime exposes (`zap.Options.EncoderConfigOptions`, `zap.go:140-144`):
|
|
|
|
```go
|
|
opts := zap.Options{
|
|
Development: true,
|
|
EncoderConfigOptions: []zap.EncoderConfigOption{
|
|
func(c *zapcore.EncoderConfig) { c.EncodeDuration = zapcore.StringDurationEncoder },
|
|
},
|
|
}
|
|
```
|
|
|
|
Left out of this step as scope the plan did not cover.
|
|
|
|
## Step 5 — Validation against beelink
|
|
|
|
First contact between the kvm2 provider and real libvirt. Everything before this ran against
|
|
an in-memory fake of the twenty libvirt calls the provider uses.
|
|
|
|
Run in the existing `kind-proxy-operator-demo` cluster rather than a fresh one, deliberately.
|
|
That cluster already owned two live `kvm-home` VMs on beelink, and orphan GC deletes any
|
|
instance whose UID is missing from *its own* cluster's live set after `gc-min-age`. A second
|
|
operator carrying the `kvm-home` entry would have destroyed both within ten minutes. Using the
|
|
existing cluster made its live set the thing that protected them — the isolation argument
|
|
pointed the opposite way from instinct.
|
|
|
|
Baseline recorded first (4 Ready proxies, 3 ProviderHealth entries, beelink's domains, volumes
|
|
and pool space), so "did we break something" stayed answerable.
|
|
|
|
The image tag had to change from the running `kvm-dev`. `make deploy` sets the image through
|
|
kustomize, so an identical tag leaves the Deployment spec untouched, no rollout happens, the
|
|
new process never starts, and the providers config — which is read once per process — is never
|
|
re-read. The ConfigMap carries no generator hash either, so nothing else would have forced it.
|
|
|
|
Results, in the order they were checked:
|
|
|
|
| Check | Outcome |
|
|
|---|---|
|
|
| `kvm2-home` ProviderHealth | `Ready 1/1`, `Reachable`, 189 ms — hostname, libvirt 11.6.0, pool running, 247.8 GiB free |
|
|
| First Create, cold cache | `base image cached`, 433,651,712 bytes in 8.3 s, digest verified |
|
|
| Volume naming (H4) | `base-kvm2-home-debian-13.qcow2` created **beside** kvm's untouched `base-debian-13.qcow2` |
|
|
| Second Proxy | no `fetching` line at all — cache hit under the new name |
|
|
| State reporting (H3) | `Running` held steady across every poll, no flapping to Provisioning |
|
|
| Squid | `Healthy=True` on a real CONNECT probe |
|
|
| Delete | domain and both per-VM volumes gone; base image survived |
|
|
| Existing infrastructure | all four pre-existing proxies stayed Ready across two rollouts |
|
|
|
|
The health check alone is worth calling out as a gate: it dials SSH, verifies the host key,
|
|
completes the libvirt handshake, runs four RPCs and tears down a dedicated connection — the
|
|
exact path H1 changed — without creating anything. Putting the stop gate there meant the
|
|
riskiest unknown was settled before a single byte was written to the hypervisor.
|
|
|
|
### What this run did NOT prove
|
|
|
|
**H2's error paths.** The unverified claim — that libvirtd answers a short stream finish with
|
|
OK rather than an error — only arises when a body *fails* part way through, and a healthy
|
|
433 MB download never finishes short. The 19-minute HTTP deadline never fired either. What was
|
|
proved is narrower: the wrapper does not break normal uploads. Settling the rest still needs
|
|
the scratch-pool probe in the Step 2 entry, and it would be easy to mistake this green run for
|
|
more than it is.
|
|
|
|
**The `kvm2` integration test still has not run.** `make test-integration-kvm2` remains
|
|
unexecuted; this was a cluster-level validation, not that suite.
|
|
|
|
### Worth noting
|
|
|
|
`config/manager/providers_config.yaml` now ships with the `kvm2-home` entry **enabled**, since
|
|
the operator is running it for real. `config/manager/kustomization.yaml` was left at its
|
|
committed tag: `make deploy` rewrites it to whatever local image was last deployed, which is
|
|
churn rather than work.
|
|
|
|
Two host-side leftovers were *not* touched, both pre-existing and unrelated to kvm2: five
|
|
orphan `proxy-*` volumes from earlier kvm runs, and the `base-test-image.qcow2` pair from the
|
|
kvm integration test. Every write to beelink in this step came from the operator itself; no
|
|
`virsh` write was issued by hand.
|