DEV Community: SACHIN INDWAR

Four Kubernetes node bugs I found by reading CI failures to the end

SACHIN INDWAR — Mon, 26 Oct 2026 18:30:00 +0000

Kubernetes' node tests fail a lot. Most of the time someone re-runs them, they go green, and everyone moves on.

Over the past week I picked four failures in SIG Node territory and refused to move on — I kept reading the logs until the timeline explained the failure. Three were CI flakes. The fourth was a second, separate bug hiding inside a reported kubelet 1.37 memory regression. In every case, the bug wasn't where the error message pointed.

Status, to be upfront: as of October 10, 2026, all four of my fixes are open pull requests, triaged or awaiting review, not merged. This post is about the investigations — which is the part I'd want to read anyway.

How I read a failing CI run

Every Kubernetes CI run on Prow keeps its artifacts: the build log, the JUnit results, the kubelet and containerd logs from the node, and for node tests, the VM's serial console. TestGrid shows the history, so you can tell a one-off from a pattern.

My loop for each flake:

Find the pattern in TestGrid. Which job, how often, and — most useful — which similar jobs don't fail.
Build a timeline across logs. Test log, kubelet log and serial console on one clock, to the second.
Explain the difference. If only one job fails, something about that job's environment is the clue.
Reproduce before fixing. Either in a unit test that fails on master, or on a machine set up like the CI node.

Bug 1: the image record that kept disappearing

PR: kubernetes/kubernetes#142801 · fixes #140942

The symptom

Tests for KubeletEnsureSecretPulledImages — the feature that makes the kubelet re-check credentials before reusing a private image — kept failing in one job, ci-kubernetes-node-swap-ubuntu-serial: 3 of the last 10 runs, 6 of 20 over a longer window. A test helper waits up to five seconds for the kubelet to write an ImagePulledRecord for an image, and the record never appeared.

This had already been through two issues. One was closed by a PR that only added debug logging. The working theory in the open issue was that the kubelet doesn't write a fresh record when an image is already cached from an earlier test.

The timeline

From the failing run (prow job 2080994746846679040):

The record was written. Then it was deleted one second later. The cached-image theory was wrong.

Why only this job

That job's image filesystem sat at about 85% for the whole run — exactly the kubelet's default high threshold for image garbage collection. Every kubelet restart in that job triggered a GC pass. Other jobs never got there.

The root cause

After a GC pass, the kubelet calls post-GC hooks with the list of images that "remain". The ImagePullManager's hook, PruneUnknownRecords, deletes every pulled-record for an image that isn't in that list.

The list was built inside freeSpace(), from the images it evaluated. But images in use by a running container, and pinned images, are filtered out before freeSpace() ever sees them. And freeSpace() stops early once it has freed enough bytes, so images after that point were never added either:

// imagesInEvictionOrder, simplified
for image, record := range im.imageRecords {
    if isImageUsed(image, imagesInUse) {
        continue          // in-use images never reach freeSpace()...
    }
    if record.pinned {
        continue          // ...and neither do pinned ones
    }
    images = append(images, evictionInfo{id: image, imageRecord: *record})
}

So the list of "remaining" images was really "the eviction candidates GC looked at and kept". The image the test pod was running wasn't on it, and its record got pruned.

It fails safe — a later pod just has to re-verify credentials — but it's wrong, and it's invisible: the deletions weren't logged.

The fix

Pass the hooks every image the GC manager still tracks, not just the candidates it evaluated:

// remainingImages returns the IDs of all images still known after a GC pass.
// This must include in-use and pinned images, not just the eviction candidates
// that survived: post-GC hooks treat anything missing from the list as gone.
func (im *realImageGCManager) remainingImages() []string {
    im.imageRecordsLock.Lock()
    defer im.imageRecordsLock.Unlock()

    // The same image can be tracked once per runtime handler.
    imageIDs := sets.New[string]()
    for imageKey := range im.imageRecords {
        imageIDs.Insert(getImageIDFromTuple(imageKey))
    }
    return sets.List(imageIDs)
}

Both GarbageCollect and DeleteUnusedImages now call im.runPostGCHooks(ctx, im.remainingImages(), freeTime), and pruned records are logged at V(4). The new TestPostGCHooksReceiveAllRemainingImages fails on master — the hook receives an empty list — and passes with the change.

Status (Oct 10, 2026): open, awaiting triage and review from SIG Node.

Bug 2: the swap test that hung nodes for hours

PR: kubernetes/kubernetes#142850 · related to #138226

The symptom

A swap e2e test, "should be able to use more than the node memory capacity", sometimes passed, sometimes failed, and sometimes produced a run that ended in exit status 255 with no JUnit results at all — the node had stopped responding.

The numbers didn't add up

The test allocates memory equal to the node's full capacity — 8 GiB on the CI node, which also has 1 GiB of swap. The system needs some of that RAM too, so part of the pod's allocation can't fit in memory and has to go to swap. In my reproduction below, when the pod was allowed to finish, about 761 MiB of it ended up in swap.

Under LimitedSwap, a container's swap limit is proportional to its memory request:

swap limit = (memory request ÷ node memory) × node swap

Request	Swap limit	Against ~761 MiB of overflow
30% (before)	~307 MiB	too small
90% (after)	~921 MiB	fits

So in every run, the pod hit its swap limit with memory still left to place. What happened next varied — which is why the test flaked instead of failing every time:

The OOM killer stepped in quickly. The run recovered, and sometimes the test passed.
It didn't. The kernel tried to reclaim memory elsewhere. On this image system.slice and user.slice can't swap, so it thrashed the page cache instead — and the node hung for hours. Those are the exit status 255 runs with no JUnit results.

The serial console of one failed run showed exactly this: the pod pinned at its swap limit, with roughly 700 MB of swap still free on the node.

Reproducing it

On a VM set up like the CI node (8 GiB RAM, 1 GiB swap, Ubuntu 24.04, the same slice swap settings): at 30% the pod hit its swap limit and was OOM-killed. At 90% it finished allocating with about 761 MiB in swap, with no OOM and no stalls.

The fix

Three changes, all test-only:

Request 90% of memory, so the pod's swap limit can hold the overflow.
Lower the memory.available hard-eviction threshold to 100 Mi for these tests. Under node-level pressure, swap only starts a few seconds before the default 250 Mi threshold would evict the pod — before the test can see any swap usage.
Delete the pod with DeleteSync, so it's gone before the kubelet restarts in AfterEach. Nothing kills the pod while the kubelet is down.

Status (Oct 10, 2026): open, triaged as important-longterm, with the swap tests' original author asked to review.

Bug 3: the 3.9 GB image that never finished pulling

PR: kubernetes/kubernetes#142802 · related to #141200

The symptom

The GPU sanity test (nvidia-smi plus a CUDA demo) timed out after 30 minutes with the pod stuck in ErrImagePull. Even passing runs spent up to 24 minutes pulling the image.

The containerd log

cancel pulling image docker.io/nvidia/cuda:12.5.0-devel-ubuntu22.04 because of no progress in 5m0s
stop pulling image ...: active requests=1, bytes read=3918316892
failed to extract layer (... sha256:496b16dd...) to overlayfs as "extract-...": context canceled

The image is about 3.9 GB, and its largest layer is about 2.5 GB. The log shows 3.9 GB had been read before the pull was cancelled during layer extraction. So the expensive part wasn't the network — it was unpacking the big layer, which reported no "progress" to containerd's five-minute watchdog. The cancelled pull didn't reuse what it had already fetched, so each kubelet retry started the download again. That's containerd/containerd#13909, with a proposed fix upstream.

The fix

Use a smaller image. On amd64, the test only needs nvidia-smi (which comes from the driver) and the cuda-demo-suite-12-5 apt package, whose binaries link the CUDA runtime statically. The ~90 MB nvidia/cuda:12.5.0-base-ubuntu22.04 image has the same CUDA apt repository, keyring and environment. Other architectures build samples with nvcc, so they keep the devel image, and the pod is pinned to the GPU node's architecture so the image always matches the script's uname -m branch.

I left arm64 alone because I couldn't test it on arm64 GPU nodes. It can still hit the containerd behavior.

Status (Oct 10, 2026): open, triaged as important-longterm, awaiting /ok-to-test and review.

Bug 4: a second bug inside the 1.37 kubelet memory regression

PR: google/cadvisor#3946 · issue kubernetes/kubernetes#142874

This one isn't a flake. A SIG Node contributor reported 20–30% higher kubelet memory in Kubernetes 1.37, traced to cAdvisor — the library the kubelet uses to collect container stats — and wrote the main fix. My part is a separate, smaller bug I found while reproducing it. To keep the credit straight:

	What it fixes	Author
google/cadvisor#3944	The reported cause: changing counters that stop housekeeping from ever backing off	the reporter
google/cadvisor#3946	A back-off reset bug that makes the interval oscillate even when stats are unchanged	me

The reported cause

cAdvisor polls each container's stats on a "housekeeping" interval. When stats haven't changed, it backs off — doubling the interval up to a maximum. When they change, it drops back to the baseline.

MemoryQoS, default-on in 1.37, sets memory.high on containers. The kernel then reclaims memory continuously, which keeps advancing counters in memory.stat. cAdvisor compared whole stats structs, so they never looked unchanged, and housekeeping never backed off. The reporter's fix, google/cadvisor#3944, excludes those counters from the comparison.

The second bug underneath

I reproduced the regression and confirmed #3944 fixes the counters. But while simulating it, I found the back-off had a bug of its own:

if stats[0].StatsEq(stats[1]) && (cd.housekeepingInterval < cd.maxHousekeepingInterval) {
    cd.housekeepingInterval *= 2
    // ... cap at max ...
} else if cd.housekeepingInterval != *HousekeepingInterval {
    // Lower interval back to the baseline.
    cd.housekeepingInterval = *HousekeepingInterval
}

Once the interval reaches the maximum, interval < max is false — so even with unchanged stats, execution falls into the else branch and resets to the baseline. Instead of staying backed off, the interval cycles: with cAdvisor's defaults, 1s → 2s → 4s → … → 1m → 1s; with the kubelet's settings, 10s → 15s → 10s → 15s.

The fix separates the two conditions, so only changed stats reset the interval:

if stats[0].StatsEq(stats[1]) {
    if cd.housekeepingInterval < cd.maxHousekeepingInterval {
        cd.housekeepingInterval *= 2
        // ... cap at max ...
    }
} else if cd.housekeepingInterval != *HousekeepingInterval {
    cd.housekeepingInterval = *HousekeepingInterval
}

The new TestNextHousekeepingIntervalDynamic steps through unchanged and changed samples. Run against the original code, it fails exactly where the sawtooth starts:

In my simulation of a 10-minute run with the kubelet's settings and MemoryQoS-style advancing counters, a container got 60 housekeeping ticks on the current code, 48 with #3944, and 41 with both fixes. Most of the improvement comes from #3944; mine removes the oscillation that remains. Neither patch alone gets the kubelet to back off as intended, and the simulation measures housekeeping ticks, not the production memory figure in the report.

Status (Oct 10, 2026): #3946 is open; the issue is assigned to me, and the reporter called the patch a good one.

What the four had in common

Each bug lived at an edge that normal runs never reach:

A list that silently meant "some of everything". "Remaining images" excluded in-use and pinned images, and nothing downstream knew.
A number that couldn't work. A swap limit smaller than the overflow it had to hold.
A timeout that measured the wrong thing. A "no progress" watchdog applied to an unpack that reports no progress — and the fetched data not reused.
An else branch that fired at the boundary. Correct below the maximum, wrong exactly at it.

And each one was explained by a difference: the one job at 85% disk, the one test whose request didn't match its allocation, the one image that was 40 times bigger than it needed to be, the one comparison that never settled.

Flakes aren't noise. They're bugs that only show up under one environment's conditions. The job that fails is telling you which conditions.

What the evidence does and doesn't establish

Evidence	Establishes	Does not establish
Prow timeline for bug 1	The record was written, then pruned by GC one second later, in that run	That every historical failure of these tests had this cause
`TestPostGCHooksReceiveAllRemainingImages`	The hook now receives in-use and pinned images	That the fix has been reviewed or accepted
VM reproduction for bug 2	30% fails and 90% holds on a CI-like machine	Behavior on every node image the swap tests run on
containerd log for bug 3	3.9 GB had been read before the pull was cancelled during layer extraction	That every layer had fully downloaded, or that the smaller image never hits the same timeout
cAdvisor test, failing on original and passing with the fix	The back-off reset bug exists and the change removes it	The production memory savings
60 / 48 / 41 tick simulation	The relative effect of #3944 and #3946 in my model	The 20–30% memory figure, which comes from the reporter's environment

Check each one yourself

Bug 1 — kubelet image GC. Check out the PR branch and run the new unit test. Without the fix, the hook receives an empty list:

go test ./pkg/kubelet/images/ -run TestPostGCHooksReceiveAllRemainingImages -v

Bug 2 — swap test. This is a node e2e test, so it needs a Linux node with swap enabled. The PR describes the VM I used (8 GiB RAM, 1 GiB swap, Ubuntu 24.04). From a Kubernetes checkout:

make test-e2e-node FOCUS="should be able to use more than the node memory capacity"

Bug 3 — GPU image. The full test needs a GPU node; in CI it's the pull-kubernetes-e2e-gce-device-plugin-gpu job. The size difference behind the fix is easy to see anywhere crictl runs:

crictl pull nvidia/cuda:12.5.0-devel-ubuntu22.04   # ~3.9 GB, ~2.5 GB largest layer
crictl pull nvidia/cuda:12.5.0-base-ubuntu22.04    # ~90 MB

The cancellation itself is containerd's image_pull_progress_timeout (five minutes by default) firing during extraction; containerd/containerd#13909 has the details.

Bug 4 — cAdvisor back-off.

git clone https://github.com/google/cadvisor && cd cadvisor/lib
# add TestNextHousekeepingIntervalDynamic from the PR, then:
go test ./manager/ -run TestNextHousekeepingIntervalDynamic -v

On the original code it fails at step 3; with the fix applied, it passes.

I'm Sachin, an SRE / platform engineer working on Kubernetes, observability and distributed systems — currently open to new roles. LinkedIn · GitHub

32 bytes verified, 40 didn't: parsing HTTP inside the eBPF verifier's budget

SACHIN INDWAR — Mon, 19 Oct 2026 18:30:00 +0000

My eBPF agent traces HTTPS traffic without touching the application: uprobes on OpenSSL's SSL_write/SSL_read and on Go's crypto/tls copy the plaintext out of the process before encryption, and the agent turns it into OpenTelemetry spans.

The kernel side copies a bounded prefix of each payload — 256 bytes — into a ring buffer, and all the HTTP parsing happens in userspace.

The obvious question is why. Parsing in the kernel would mean shipping less data and filtering earlier. "The verifier won't allow it" is the usual answer, but I wanted a number, not folklore. So I wrote the in-kernel parser five different ways and recorded exactly what the verifier said about each.

The answer turned out to be more interesting than "no".

Repo: sAchin-680/eBPF-observability-agent

The setup

Every attempt is a real uprobe program that reads up to 256 bytes of the buffer passed to SSL_write and tries to find Host: headers. None is ever attached — they exist to be loaded, and the interesting ones are the loads that fail.

Each program is loaded on its own with cilium/ebpf, because loading them together would stop at the first rejection and hide the rest. The test records the outcome, the time, and — new for this post — the verifier's own count of instructions it processed.

I originally ran this on kernel 6.8. For this post I re-ran everything on 6.18. Every accept/reject outcome was identical.

Attempt 1: scan until the data says stop

The natural way to find the end of a header block:

while (data[i] != '\0') {
    if (data[i] == '\n')
        lines++;
    i++;
}

Rejected:

invalid read from stack R3 off=0 size=1

What's interesting is how it fails. Since kernel 5.3 the verifier accepts bounded loops by simulating every iteration. It did exactly that here: it followed i all the way to the end of the 256-byte buffer and refused the read that walks off it. It isn't objecting to the loop. It found the overrun.

Attempt 2: bound it by the caller's length

for (int i = 0; i < num; i++) { ... }

Rejected the same way. The verifier's register state shows why:

R6_r=Pscalar(smin=umin=250, smax=umax=0x7fffffff, ...)
invalid read from stack R2 off=0 size=1

umax=0x7fffffff. The length comes from userspace, so the verifier knows nothing about it and has to assume two billion. A bound the verifier can't see is no bound at all.

Attempt 3: bound it by the buffer

for (int i = 0; i < BUF; i++) {
    if (data[i] == '\n')
        lines++;
}

Accepted. 22 instructions, and the verifier processed 6,389 instructions to prove it safe — walking all 256 iterations.

But it only counts line breaks. Real parsing needs per-line work.

Attempt 4: actually parse — and hit the wall

The smallest thing that resembles parsing headers: at each \r\n, check whether the line that just ended starts with Host:, then remember where the next line begins.

for (int i = 0; i + 1 < size; i++) {
    if (data[i] != '\r' || data[i + 1] != '\n')
        continue;
    if (line_start + 5 < size &&
        data[line_start] == 'H' && data[line_start + 1] == 'o' &&
        data[line_start + 2] == 's' && data[line_start + 3] == 't' &&
        data[line_start + 4] == ':')
        matches++;
    line_start = i + 2;
}

I compiled the identical code at different buffer sizes. Every version is 76 instructions — the compiler doesn't unroll it. The difference is entirely in how much work the verifier does:

Buffer	Outcome	Instructions processed by the verifier
32 bytes	accepted	158,806
40 bytes	rejected, `E2BIG`	over 1,000,000
48 bytes	rejected, `E2BIG`	over 1,000,000
56 bytes	rejected, `E2BIG`	over 1,000,000
64 bytes	rejected, `E2BIG`	over 1,000,000
256 bytes	rejected, `E2BIG`	over 1,000,000

E2BIG ("argument list too long") is what the verifier returns when it exhausts its budget of one million processed instructions.

32 bytes uses 16% of the budget. 40 bytes exceeds it. A 25% bigger buffer costs more than six times the verification work. A Host header alone is often longer than 32 bytes, so this isn't a tuning problem — this shape of parser simply can't cover a real request.

Why it explodes

The verifier walks every iteration and every branch. Normally it keeps the cost down by pruning: when it reaches an instruction in a state equivalent to one it has already proven safe, it stops exploring.

line_start defeats that. It's used as a memory offset, so the verifier must track its exact value — and every path through the data sets it differently, depending on where the \r\n pairs fell. States that differ only in line_start can't be merged, so the number of live paths multiplies with each byte. Counting line breaks in attempt 3 has no such variable, which is why it stays cheap over 256 bytes.

An aside: asking for the log changed the answer

On the 6.8 machine, requesting the verifier's log for the 64-byte program changed the reported error from E2BIG to EINVAL, and verification went from 0.3 s to 5.7 s. Worse: the loader retries with a progressively bigger log buffer while the log is truncated, and no buffer was ever big enough. The test process reached 5.3 GB resident on a 5.9 GB machine and was OOM-killed.

Verification itself took 280 ms. Only the log was unbounded. The experiment now loads the size sweep with logging disabled and asks only for the verifier's statistics, which are a few lines long.

Attempt 5: the two features built for exactly this

My original conclusion was "in-kernel parsing is ruled out." That conclusion was only about the classic loop. Newer kernels have two features designed for loops the verifier can't afford to walk:

bpf_loop() (kernel 5.17): a helper that calls a callback N times. The verifier checks the callback once, with the index known only to be in [0, N).
Open-coded iterators (bpf_for, kernel 6.4): an ordinary-looking loop that the verifier checks by converging on a stable state, rather than by walking every iteration.

Here's the same parse with bpf_loop(), over the full 256 bytes:

static long parse_step(__u64 index, void *arg)
{
    struct parse_ctx *c = arg;
    __u64 i = index;
    __u64 ls;

    if (i >= BUF - 1)
        return 1;
    if (c->data[i] != '\r' || c->data[i + 1] != '\n')
        return 0;

    ls = c->line_start;
    if (ls < BUF - 5 &&
        c->data[ls] == 'H' && c->data[ls + 1] == 'o' &&
        c->data[ls + 2] == 's' && c->data[ls + 3] == 't' &&
        c->data[ls + 4] == ':')
        c->matches++;

    c->line_start = i + 2;
    return 0;
}

/* in the uprobe: */
bpf_loop(BUF - 1, parse_step, &c, 0);

First, the verifier and the compiler disagreed

My first versions of both were rejected instantly. Not because of the budget — because of how I'd written the bounds checks:

invalid unbounded variable-offset read from stack R5
invalid variable-offset read from stack R2 var_off=(0x0; 0x1ff) off=-256 size=1

Two classic mistakes:

if (i + 1 >= BUF) let the compiler test a copy of the index, so the register actually used as the offset was never bounded in the verifier's eyes. Testing i >= BUF - 1 directly bounds the register that's used.
if (line_start + 5 < BUF) looks like it proves line_start < 251. In 32-bit arithmetic it doesn't: the addition could wrap, so the verifier learns nothing about line_start from it. line_start < BUF - 5 says the same thing in a form it can use.

The agent's production capture code already follows the same rule — it masks the copy length with n &= (MAX_DATA - 1) rather than relying on an earlier if, because the mask states the bound in a form the verifier accepts on every path. Bounds have to be written for the verifier, not just for the reader.

Then: 256 bytes, a few hundred instructions

Version	Buffer	Outcome	Instructions processed
classic bounded loop	32 bytes	accepted	158,806
classic bounded loop	40 bytes	rejected	over 1,000,000
`bpf_loop()`	256 bytes	accepted	149
`bpf_for` iterator	256 bytes	accepted	351

Eight times the buffer of the largest classic loop that verifies, for 0.1–0.2% of the verification work.

Loading isn't the same as being right, so I also checked they compute the correct answer. Uprobe programs can't be test-run directly, so the identical parse is wrapped in a BPF_PROG_TYPE_SYSCALL program and run on real requests with BPF_PROG_TEST_RUN:

run_bpf_loop  one Host header      len= 50  matches=1 want=1  ok
run_bpf_loop  no Host header       len= 51  matches=0 want=0  ok
run_bpf_loop  two Host headers     len= 42  matches=2 want=2  ok
run_bpf_loop  Host past byte 200   len=224  matches=1 want=1  ok
run_bpf_for   one Host header      len= 50  matches=1 want=1  ok
run_bpf_for   no Host header       len= 51  matches=0 want=0  ok
run_bpf_for   two Host headers     len= 42  matches=2 want=2  ok
run_bpf_for   Host past byte 200   len=224  matches=1 want=1  ok

That last case — a Host header past byte 200 — is one the classic loop couldn't even be verified over.

So why does the agent still parse in userspace?

The verifier is no longer the deciding reason on a modern kernel. These are:

The kernel floor. The agent ships as one CO-RE binary, verified by checksum on kernels 5.15 and 6.8. bpf_loop() needs 5.17 and iterators need 6.4. Ubuntu 22.04 runs 5.15. Using either would mean dropping supported kernels or maintaining two kernel-side parsers.

Where the work runs. A uprobe handler runs synchronously in the traced application's own thread, before SSL_write continues. Copying 256 bytes and returning keeps the cost on the application's request path as small as possible. Parsing in userspace moves that work onto the agent's own threads.

What the kernel can see. A header block can be split across several SSL_write calls, and the kernel program sees one call at a time. Userspace sees the whole stream and can correlate requests with responses.

What I can test. The userspace parser is ordinary Go with ordinary unit tests. The kernel parser needs root, a specific kernel, and a test harness just to run.

The cost of this design is explicit: the captured prefix is 256 bytes, so headers beyond it are truncated — and truncation is reported on every event rather than hidden.

If the agent ever drops 5.15, an in-kernel pre-filter with bpf_loop() — say, only capture requests to certain hosts — becomes a reasonable option rather than an impossible one. That's a different conclusion from the one I started with.

What the evidence does and doesn't establish

Evidence	Establishes	Does not establish
Classic loop: 32 bytes accepted, 40+ rejected	This parser shape exceeds the 1M-instruction budget above 32 bytes, on 6.8 and 6.18	That every classic-loop parser hits the same wall at the same size
`bpf_loop` / `bpf_for` accepted at 256 bytes	These two loop forms verify cheaply for this parse on 6.18	Behavior on kernels I haven't tested between 5.17/6.4 and 6.18
Test-run results	The parse returns the right count for these inputs	That it handles every valid HTTP/1.1 request
Verifier statistics	How much work the verifier did for these programs on this kernel	Run-time cost of the programs once attached

What I'd take from this

Measure the constraint before designing around it. "The verifier won't allow it" was true for one loop shape on one kind of kernel, and false for another.
Watch the verifier's instruction count, not just pass/fail. 158,806 of 1,000,000 at 32 bytes was the warning that 40 bytes would fail.
Write bounds for the verifier. Check the register you index with, avoid sums that can wrap, and mask when you can.
Re-test old conclusions when the platform moves. I'd written "in-kernel parsing is ruled out" into the project's docs. On a 6.x kernel, that's no longer true.

Reproduce it

sudo go test ./test/verifier/ -v

The classic-loop experiment is in test/verifier/headers.bpf.c, and the write-up with the raw verifier output is in docs/verifier/. The bpf_loop/bpf_for versions, the statistics test and the test-run checks are in test/verifier/extra.bpf.c.

sAchin-680 / eBPF-observability-agent

Production-grade eBPF observability agent for zero-instrumentation HTTP/HTTPS tracing.

Zero-Instrumentation eBPF Observability Agent

Request-level tracing for HTTP and HTTPS services, with zero changes to the traced application.

This agent attaches to the kernel and to TLS library entry points using eBPF reconstructs HTTP request/response pairs from raw syscalls and decrypted-in-place buffers, and exports them as OpenTelemetry traces and metrics.

No SDK. No sidecar proxy. No configuration injected into the traced process One binary, once per node.

Architecture

        ┌──────────────┐  ┌──────────────┐  ┌──────────────┐
        │  Go service  │  │    Python    │  │   Node.js    │
        │ (crypto/tls) │  │  (OpenSSL)   │  │  (OpenSSL)   │
        └───────┬──────┘  └───────┬──────┘  └───────┬──────┘
                │                 │                 │
                └─────────────────┼─────────────────┘
                                  │  uprobes + tracepoints
                                  ▼
        ┌──────────────────────────────────────────────────┐
        │              eBPF programs (kernel)              │
        │  SSL_write/read · Go TLS write/read · socket tp  │
        └─────────────────────────┬────────────────────────┘
                                  │  BPF ring buffer
                                  ▼
        ┌──────────────────────────────────────────────────┐
        │               Userspace agent (Go)               │
        │       parse · correlate · build OTel spans       │
        └─────────────────────────┬────────────────────────┘
                                  │  OTLP
                                  ▼
               ┌──────────────────┴──────────────────┐
               ▼                                     ▼
        Tempo (traces)                     Prometheus (metrics)

…

View on GitHub

Next in this series: why benchmarking the agent against an idle machine made it look faster than running no agent at all — and the control arm that fixed it.

I'm Sachin, an SRE / platform engineer working on observability, eBPF and Kubernetes — currently open to new roles. LinkedIn · GitHub

Three Raft bugs that only existed once I added log compaction

SACHIN INDWAR — Tue, 13 Oct 2026 17:47:07 +0000

I implemented Raft from the paper in Go — leader election, log replication, snapshotting, joint-consensus membership changes — with a linearizable key/value store on top.

The difficult part wasn't implementing the happy path. It was finding the defects that only became reachable once log compaction removed the redundancy that had been hiding them.

Adding snapshotting exposed three real bugs. A deterministic simulator I had built beforehand caught the subtlest one and pinned it to a single seed — seed 188 — which then reproduced it exactly throughout the diagnosis. The other two were caught by a storage conformance suite and a restart test. This post walks through each one, from trigger to regression test, along with the false positive I refused to count.

Repo: sAchin-680/Distributed-KV-Store-with-Raft-Deterministic-Simulation-Testing

Why ordinary tests miss this class of bug

Raft's correctness depends on the interleaving — which message arrives first, which is lost, whose timer fires first. An integration test samples whatever interleaving the OS scheduler produces on a fast, healthy machine. The orderings where consensus breaks — say, a message from long ago arriving after the entries it refers to have been compacted away — almost never come up that way. And when one does, it's gone before you can look at it.

Deterministic simulation testing, the approach FoundationDB and TigerBeetle are known for, attacks both problems: run the whole cluster on one thread, draw every source of nondeterminism from one seeded random source, and a run becomes repeatable from its seed.

Determinism has to be designed in

In Go, that only works if you control time, network, disk — and the goroutine scheduler. The scheduler forces the architecture: if consensus logic is spread across goroutines talking over channels, no virtual clock will make it replayable.

So the Raft core is a pure, synchronous state machine — no clock, no goroutines, no channels, no I/O:

func (r *RawNode) Tick()
func (r *RawNode) Step(m Message) error
func (r *RawNode) Propose(cmd []byte) (Index, error)
func (r *RawNode) Messages() []Message
func (r *RawNode) Applied() []LogEntry

Everything nondeterministic sits behind an interface, and the simulator swaps it out:

Concern	Production	Simulation
Time	`time.Now` / timers	virtual clock
Network	gRPC	in-memory queue with fault injection
Disk	bbolt	in-memory map
Scheduling	one goroutine per node	one single-threaded event loop

A CI script fails the build if a clock, goroutine, channel, mutex or package-level math/rand call appears inside the core, because this property degrades silently.

Note the trade-off in that table, because it matters later: the simulator runs the real consensus core, but not bbolt and not the node driver. It can only find bugs in the code it actually executes.

The four lines determinism depended on

The event loop is a priority queue ordered by virtual time, and simultaneous events are routine — every node's first tick is at t=0. Go's container/heap makes no promise about the order of equal elements, so without a tiebreaker the same seed could execute differently on different runs. Every event gets an insertion sequence number:

func (q *eventQueue) Less(i, j int) bool {
    if q.items[i].at != q.items[j].at {
        return q.items[i].at < q.items[j].at
    }
    return q.items[i].seq < q.items[j].seq
}

(The other trap is Go's randomized map iteration, which can't be caught statically. Every peer list in the core is a sorted slice, and a test runs each seed twice and compares a hash of the full event trace.)

What the simulator checks

Faults drawn from the seed: dropped, duplicated, delayed and reordered messages; partitions and heals; crashes and restarts. After every event: at most one leader per term, no committed entry ever changes, the commit index never decreases, applied never exceeds committed. At the end of a run: logs match pairwise, and no two nodes applied different commands at the same index.

A seed reproduces its run. Here's the same seed three times, recorded on a Linux box, not my laptop:

$ for i in 1 2 3; do simctl run --seed=2; done
seed 2: ok — 169359 events in 246.926ms (30000ms virtual) ... trace 26c664211d16bfc0
seed 2: ok — 169359 events in 254.286ms (30000ms virtual) ... trace 26c664211d16bfc0
seed 2: ok — 169359 events in 247.318ms (30000ms virtual) ... trace 26c664211d16bfc0

Only the wall-clock time changes. To be precise about how far that's been verified: the same trace hash appears in the repo's docs, recorded on my development machine with a different Go minor version. That's two machines and two toolchains for this seed, plus CI replaying failures — not a proof that every build on every platform agrees.

The full campaign, from a fresh run whose raw output is committed to the repo:

{{CAMPAIGN_OUTPUT}}

The three bugs

Bug 1: a late message mistaken for an attack on the committed log

How it was found: the simulator, seed 188.

Trigger. The leader sends an AppendEntries starting near the beginning of the log. The network delays it. Meanwhile the follower receives newer appends, commits past them, takes a snapshot and compacts the old entries away. Then the stale message finally arrives.

Root cause. The follower ran its normal conflict scan on the stale message. The scan compares each incoming entry's term with the term the follower holds at that index — but those indices had been compacted. An entry the follower simply no longer had was reported as conflicting, and the node refused the append as an attempt to overwrite its committed prefix.

Before compaction this code was correct: the old entries were still there, the scan verified them, and found no conflict.

Consequence. The follower raised a safety error on a perfectly legitimate, merely late, message. To check how rare the trigger is, I removed the fix and re-ran the campaign:

$ simctl fuzz --count=300 --max-failures=0      # fix removed
ran 300 seeds in 1m27.659s (3 seeds/sec, 364034 entries committed, 48795440 events)
1 failing seed(s):
  seed 188: sim: step append-req on node 1: raft: leader entry at index 1
            conflicts with committed index 57: raft: safety violation

One seed out of 300. It needs a log long enough to compact and a message delayed long enough to span the compaction. That seed reproduced it identically on every run, including after I fixed the wrong thing first and had to go back.

Fix. A guard before the scan (raft/replication.go):

if m.PrevLogIndex < r.log.committed {
    r.send(Message{
        Type: MsgAppendResp, To: m.From,
        Success: true, MatchIndex: r.log.committed, ReadID: m.ReadID,
    })
    return nil
}

Why ignoring the entries is safe. It looks alarming to return without processing the message, so here's the invariant:

Messages from older terms are rejected before this handler runs, so this one comes from the current leader.
Everything at or below the follower's commit index is committed. By Raft's Leader Completeness and Log Matching properties, the current leader's log agrees with ours at every one of those indices. There is nothing to verify and nothing to change.
The message may also carry entries above our commit index. We drop them — but the reply says MatchIndex: committed, not "everything you sent". We never acknowledge an entry we don't hold, so the leader can't count us toward committing it.
The leader only ever moves its record of our progress forward (if m.MatchIndex > pr.Match), so a low-but-true answer can't rewind it. It resends the later entries on the next round.

So the cost of the early return is at most one extra round trip, and it can't affect safety.

The same change also floors the leader's rejection backoff at the follower's confirmed match index. A delayed rejection could otherwise make the leader resend entries the follower had already committed. That wasn't the cause of seed 188, but it's the same family: a late message acting on a world that has moved on.

Regression tests. TestStaleAppendBelowCommitIndexIsAnswered builds the exact sequence — append 60 entries, commit 58, snapshot and compact, then deliver a stale append from index 1 — and asserts it's answered with success, MatchIndex 58, and an unchanged commit index. TestStaleRejectionCannotRewindBelowMatch covers the delayed rejection. Seed 188 runs in the campaign above.

Bug 2: the log grew forever behind a snapshot that claimed to shorten it

How it was found: the storage conformance suite, which runs the same tests against the in-memory store and bbolt. The simulator couldn't have found this one — it never runs bbolt.

Trigger. A leader takes a snapshot but deliberately keeps a tail of entries past the snapshot point, so a follower that's one entry behind can be repaired with entries instead of the whole state machine. Later it compacts up to an index below the snapshot boundary.

Root cause. The bbolt store used one field for two different things: the log floor (the oldest entry still answerable) and the snapshot boundary. They're equal right up until a leader keeps a tail. Once they diverged, Compact saw an index at or below its "floor", concluded it had already run, and returned.

The fix was to give them separate fields (storage/bolt.go):

// snapIndex and snapTerm describe the newest snapshot.
snapIndex raft.Index
snapTerm  raft.Term

// floorIndex and floorTerm describe the oldest entry still answerable:
// the last one discarded by compaction. Separate from the snapshot —
// the floor sits *below* the snapshot boundary when a tail is kept.
floorIndex raft.Index
floorTerm  raft.Term

Compact now short-circuits only when upto <= s.floorIndex.

Consequence. No error, no failed assertion — just a log that never got shorter, behind a snapshot that said it had been compacted. In production, a disk-space leak you notice days later. Any test that doesn't specifically check "did the log actually get shorter?" passes straight through it.

Regression test. TestCompactBelowTheSnapshotBoundaryStillWorks: append 60 entries, save a snapshot at 60, compact to a lower index, and assert the entries below it are actually gone — against both storage implementations.

Bug 3: a restarted node came back with a fraction of its data — and reported healthy

How it was found: while making the simulator's model of a restarting node correct (more on that below). The real defect lives in the node driver, which the simulator doesn't run, so it's covered by a cluster test rather than a seed.

Trigger. A node that has taken a snapshot and compacted its log restarts.

Root cause. On startup, the node resumed applying entries from its persisted applied index — but never rebuilt its state machine from its own snapshot first. Without compaction this was invisible: the whole log was still there, so replay produced the right state anyway. Wrong code path, right outcome, for exactly as long as nothing was ever discarded.

Fix. Restore from the node's own snapshot before the run loop starts, so nothing can observe a half-built state machine (node/node.go):

func (n *Node) restoreFromDisk() error {
    _, snap, err := n.cfg.Storage.InitialState()
    if err != nil {
        return fmt.Errorf("node: reading initial state: %w", err)
    }
    if snap.IsEmpty() {
        return nil
    }
    // ... the state machine must support snapshots, or the node cannot recover
    if err := snapshotter.Restore(snap.Data, snap.LastIncludedIndex); err != nil {
        return fmt.Errorf("node: restoring snapshot at index %d: %w",
            snap.LastIncludedIndex, err)
    }
    return nil
}

Consequence. Once compaction existed, the discarded entries were gone. The node came back, answered requests, voted in elections — and held the wrong data.

Regression test. TestNodeRestoresFromItsOwnSnapshot runs a real cluster with a low snapshot threshold, writes 60 keys, restarts the leader, and asserts all 60 keys are still there.

The finding I didn't count

The first snapshot-enabled fuzz run reported eleven seeds with state machine divergence. That looked like eleven more bugs.

It wasn't. The simulator's own model restarted a node with an empty state machine — the same mistake as bug 3, but in the test harness — so two correct nodes legitimately had histories starting at different points. The checker compared them by list position and called it divergence.

I fixed it twice over: the simulated node now restores from its snapshot, and the checker compares by log index instead of position, which states the property that actually matters — no two nodes disagree about what's at index i — without caring where each history begins.

A failing run means something disagrees, not the code is wrong. Counting your tool's bugs as findings poisons every future result.

How I know the checker isn't just quiet

A campaign with zero violations looks exactly like a broken checker. So there's a negative control.

Raft assumes a node's term, vote and log survive a crash. --disk-loss=0.5 deliberately breaks that: a restarting node loses its persisted state half the time. That must break safety somewhere:

$ simctl fuzz --count=41 --disk-loss=0.5 --max-failures=0
ran 41 seeds in 10.686s (4 seeds/sec, 31781 entries committed, 5206831 events)
23 failing seed(s):
  seed 1: safety violation [committed-entries-never-change] ...
  seed 6: safety violation [state-machines-agree] ...
  ...

23 of 41 seeds fail: 15 because a committed entry was later replaced, 8 because two nodes applied different entries at the same index. Each run stops at its first violation, so these are the first properties broken. Any one of them reproduces exactly from its seed:

$ simctl run --seed=27 --disk-loss=0.5
safety violation [committed-entries-never-change] at t=26106ms (seed 27):
  committed index 119 changed: node 1 committed term 1 (8488d043) at t=2520ms,
  node 3 now has term 3 (c38200e5)

The unit tests get the same treatment: 22 seeded mutations, each a plausible mistake paired with the test that should catch it. That check found three tests that could not fail — one measured nothing at all, and two pre-vote tests passed whether or not the bug they were named after was present.

What the evidence does and doesn't establish

Evidence	Establishes	Does not establish
10,000 seeded runs, no violations	No checked property was violated in those executions, under the simulator's fault model	That this Raft is correct
Identical trace hashes	Repeatability for the tested seeds on the machines and toolchains tried	Agreement across every build and platform
22/22 seeded mutations caught	Those specific mistakes are detected by their tests	Complete mutation coverage
Disk-loss negative control	The checker detects at least this class of injected failure	Detection of every possible safety defect
Real-cluster chaos + linearizability checks	The recorded client histories satisfy the model	Correctness under all workloads and faults

The last row covers the simulator's blind spot. Because it replaces gRPC, bbolt and the Go scheduler, a separate rig runs a real cluster in containers with tc/netem packet loss and iptables partitions, records every client operation, and checks the history is linearizable with Porcupine. Those runs can't be replayed, but they exercise exactly what the simulator stubs out — which, as bugs 2 and 3 show, is where real defects also live.

The lesson

The biggest lesson wasn't that a simulator found a bug. It was that all three bugs had been hidden by the absence of a feature.

Before compaction, replaying the log masked a broken restart path. Before the log floor diverged from the snapshot boundary, a storage bug stayed dormant. Before a delayed message could cross a compaction boundary, the conflict check behaved correctly.

Adding the feature removed those safety nets. Because the core was deterministic, the subtlest failure became a reproducible sequence of events — seed 188 — rather than an intermittent symptom. And because the simulator can't see everything, the conformance suite and restart test caught what it couldn't.

That's why I now treat the testing architecture as part of the system design, not something added after implementation.

Reproduce it

make fuzz FUZZ_SEEDS=10000                     # the campaign
make replay SEED=2                             # one execution, with its trace
make mutation                                  # the 22 seeded mutations
bin/simctl fuzz --count=41 --disk-loss=0.5 --max-failures=0   # the negative control

sAchin-680 / Distributed-KV-Store-with-Raft-Deterministic-Simulation-Testing

A Raft consensus implementation in Go built from scratch using real HTTP communication between processes to demonstrate leader election, heartbeats, and distributed systems fundamentals.

Distributed KV Store with Raft + Deterministic Simulation Testing

A linearizable key/value store on hand-written Raft — verified by a deterministic simulator that replays any failure from a single integer.

Overview · System design · Verification · Performance · Operations · Getting started · Docs

Overview

Raft implemented from the paper — leader election, log replication, snapshotting and joint-consensus membership changes — with a linearizable key/value store on top.

The part that matters is what surrounds it. A deterministic simulation framework controls time and the network, injects partitions and crashes from a seeded random source, and reproduces any execution exactly. When a randomized run finds a safety violation it prints one number, and that number is enough for anyone to replay the identical failure, byte for byte, indefinitely.

Everything below was measured, not estimated.

Simulation campaign	10,000 seeds, 1.7 billion events, 83 simulated hours in under 4 minutes, 0

…

View on GitHub

Next in this series: why my alert for leader elections uses a threshold derived from cluster size, and how a rolling upgrade showed the old constant was in the worst possible place.

I'm Sachin, an SRE / platform engineer working on observability, Kubernetes and distributed systems — currently open to new roles. LinkedIn · GitHub

Tracing a 3x Memory Blow-Up in Grafana's Time Comparison

SACHIN INDWAR — Fri, 07 Aug 2026 15:15:46 +0000

While contributing to Grafana, I picked up a memory issue in the Time Comparison feature — a follow-up to earlier performance work I had done in the same area.

A comparison panel was consuming significantly more memory than expected. The interesting part: the extra memory wasn't coming from real data.

This post covers how I traced it to the root cause and fixed it.

Background

Time Comparison overlays an earlier period onto the current one — for example, this week vs. last week. The comparison data is fetched from the earlier window and shifted forward before rendering:

Query → DataFrame → Prepare frame → Shift → Render
                         │
                         └─ Gap filling

The important detail: gap filling ran before the comparison frame was shifted.

The Problem

I reproduced the issue with:

Parameter	Value
Series	500
Window	6h
Interval	20s
Compare offset	24h

A single-period panel contained roughly 540,000 points, so a comparison panel should be about 2× the baseline.

Instead, the compare frame contained 3,240,500 points — ~6× the baseline — and consumed 76.4 MB.

The question was: where did the extra points come from?

Investigation

I first verified the baseline to rule out the query returning unexpected data. It was correct.

Then I used a reproducible browser harness and a heap snapshot to inspect the extra memory. Most of it was null rows introduced during gap filling — not real samples, not copies.

Following the frame through the preparation pipeline revealed why. When gap filling ran, the compare frame still represented data 24 hours in the past, but the gap-filler was using the current time range as its reference:

   Compare frame                         Current range
   [===== 6h =====]                      [===== 6h =====]
          └───────────────  24h  ───────────────┘
                gap-filler reads this offset as one gap

At a 20-second interval, 24 hours is:

24 × 60 × 60 / 20 = 4,320 intervals

So up to 4,320 null positions per series were introduced purely because the frame hadn't been shifted yet. The frame was then shifted forward, leaving most of that padding outside the visible range — where nothing draws it.

Root Cause

The issue was the reference range gap filling used. It evaluated the compare frame against the current range instead of the range the frame actually represented:

Before                         After
──────                         ─────
Compare frame                  Compare frame
     ↓                              ↓
Gap-fill vs current range      Use frame's effective range
     ↓                              ↓
Shift by 24h                   Gap-fill
                                    ↓
                               Shift by 24h

The Fix

I changed the gap-filling logic to account for the compare frame's own offset when determining its effective time range. This means:

genuine gaps are still filled
non-comparison frames are unchanged
the unnecessary null padding is eliminated

Results

Scenario	Before	After
Compare points	3,240,500	1,081,000
Compare heap	76.4 MB	22.8 MB
12× dashboard heap	822.5 MB	225.0 MB

The compare frame went from roughly 6× to 2× the baseline — consistent with the actual amount of data being rendered. I also verified it in the browser: the reproduced panel dropped from 144.2 MB to 84.4 MB.

What I Learned

1. Performance bugs can be data-flow bugs. The problem wasn't an expensive algorithm — it was a correct operation running against the wrong state.

2. Profile before optimizing. The heap snapshot showed the extra memory was synthetic null data, which immediately narrowed the search.

3. Large-codebase bugs often live between components. This one emerged from the interaction between time comparison, frame preparation, gap filling, and time shifting — not from a single isolated function.

Closing

This reinforced a lesson I keep coming back to while contributing to large open source projects:

When debugging performance, follow the data — not just the allocations.

The fix is up as a pull request against Grafana:

TimeComparison: Stop padding compare frames across the compare offset #129934

sAchin-680 posted on Aug 03, 2026

Follow-up to the memory investigation in #129681.

Compare frames are gap-filled while still sitting in their own earlier window - the panel only shifts them onto the current range afterwards. Measuring them against the unshifted current range reads the whole compare offset as a gap, so each frame gets padded with a null row per interval across it. Those rows then travel forward with the shift and land outside the visible range, where nothing can see them.

The fix measures a compare frame against the window it actually covers. Genuine gaps inside a frame still fill, and non-compare frames are untouched.

Measured with @drew08t's benchmark from #129806 (500 series, 6h window, 20s interval, 24h offset):

Scenario	Prepared points	Heap
Compare — before	3,240,500	76.4 MB
Compare — after	1,081,000	22.8 MB
Dashboard 12x compare — before	38,886,000	822.5 MB
Dashboard 12x compare — after	12,972,000	225.0 MB

Compare now reports 2.00x the points of a single-period baseline instead of 6.00x — two periods of 500 series should cost exactly twice one period, and it now does.

Also confirmed in a browser on the four-panel harness, toggling the fix in one session: the compare panel goes from 144.2 MB to 84.4 MB, with compare frames back to their true 1080 points. It now sits alongside an equivalent 1000-series non-compare panel (81.7 MB), the remaining ~3 MB being genuine compare overhead.

Note the benchmark in #129806 is still a draft, so those numbers aren't reproducible from main until it lands.

Ref #125104

View on GitHub