$RodHat_
Rod's Tales

The bug was gone the moment I looked for it.

Published by

The bug was gone the moment I looked for it.
Photo: AI-generated — no human photographer / RodHat AI Cover

It started with a ticket that said “connection refused intermittently.” They always say “intermittently.” Six months of those tickets, filed by six different teams, closed automatically after 48 hours because the service was healthy by the time anyone looked.

The service was a small HTTP proxy written in C by someone who had since left the company. Not a vendor proxy. Their own. Written, apparently, during a month when the team thought writing a custom HTTP proxy was a reasonable engineering decision. It handled about two thousand requests per second, and something like one in every three thousand of those requests got a ECONNREFUSED.

Not 503. Not a timeout. An outright refused connection. The listen backlog was fine. The process was running. No OOM events. Port was open. You could connect manually from the same host and it worked perfectly.

The first thing I did was attach strace.

$ strace -p $(pgrep proxy) -e trace=network -c

The bug disappeared.

I mean this literally: I ran strace, waited ten minutes, watched the request rate in another terminal, detached strace. Thirty seconds later, first ECONNREFUSED. Every. Single. Time.

If you have been doing this long enough, you know what that is. A Heisenbug. Named after Heisenberg’s uncertainty principle, which most programmers have misunderstood, but the name stuck because it fits: observing the system changes what the system does.

strace works by intercepting every system call with ptrace. ptrace is not free. For a process making thousands of system calls per second, strace adds enough serialization overhead that timing windows change. If your bug lives inside a timing window, strace closes it. The bug goes away. The moment you detach, it comes back.

This is not a strace bug. This is what strace is: a useful tool with a specific gravity field that bends what happens underneath it.

I spent about three hours convincing myself that strace was telling me the truth, and that the truth was a race condition. The proxy used a fixed-size pool of connection slots, and it had this in the accept loop:

/* Check for available slot */
if (pool->available == 0) {
    close(client_fd);
    return;
}
pool->available--;

That is two distinct operations. Check. Decrement. Between those two operations, another thread can run. Thread A sees available == 1, decides to take it. Thread A gets preempted. Thread B sees available == 1, decides to take it. Thread A resumes, decrements to zero. Thread B resumes, decrements to -1. Now you have two threads that both think they have a slot, and the pool counter is wrong.

The slot count going negative was not actually a crash, because when both threads returned their slots the count climbed back toward zero and eventually one. The problem was the allocator returning NULL when the count went negative, the accept loop interpreting NULL as “no slots available,” and closing the connection. ECONNREFUSED. One in three thousand. Whenever two threads happened to both be in that check-then-decrement gap at the same time.

strace closed the gap. No more bug.

So now I knew what the bug was. I knew why strace hid it. The question was: can I confirm it without strace? Because I needed to prove this to the team that owned the proxy, and “I attached a debugger and the bug disappeared, therefore race condition” was not going to close a six-month-old ticket.

This is where bpftrace comes in, and this is the part where I will admit it is worth knowing.

bpftrace instruments the kernel via BPF programs that run in-kernel, with no ptrace, no syscall interception, and overhead measured in microseconds per event rather than the milliseconds strace adds per call. You can trace return values, timestamps, process IDs, stack traces, and latencies, and the process you are tracing has no idea you are there.

# Trace when the proxy closes a newly accepted connection within 1ms
bpftrace -e '
  kretprobe:sys_accept4 / pid == $1 && retval >= 0 / {
    @fds[retval] = nsecs;
  }
  kprobe:sys_close / pid == $1 && @fds[arg0] / {
    $age_us = (nsecs - @fds[arg0]) / 1000;
    if ($age_us < 1000) {
      printf("fast-close fd %d after %d us\n", arg0, $age_us);
    }
    delete(@fds[arg0]);
  }
' $(pgrep proxy)

That is the whole probe. It watches for file descriptors accepted and then closed within one millisecond, which is exactly what the race looked like from the kernel’s side: accept a connection, immediately close it, no data exchanged.

Within about ninety seconds of running that probe I had a stream of fast-close fd N after 47 us events. Not every three thousand requests, but consistent. Repeatable. Timestamped. The probe was not affecting the race. The race was happening exactly as before.

I sent the output to the team with the source code excerpt and the words “this is a check-then-act race on pool->available, the fix is an atomic decrement or a mutex around the check and the decrement, your choice.”

The fix took twenty minutes. The ticket had been open six months.


The lesson is not “use bpftrace instead of strace.” Both tools are right for different things. strace tells you exactly what system calls a process is making and what they return, which is what you want when you do not know what a process is doing at all. bpftrace tells you what is happening at kernel level across arbitrary events, with latency and frequency data, without touching the process.

When a bug disappears under your instrumentation, your instrumentation is part of the system. strace is not passive observation. It is an active participant in process execution, one that changes timing, changes scheduling, and therefore changes which races surface. bpftrace is the closest thing to passive observation Linux gives you for this class of problem, and it has been on the box for years. The bpftrace IO latency tip has more probe examples if you’re setting up tracing infrastructure for the first time.

The proxy had been written by someone who knew pthreads existed but had not thought hard about what sharing a counter between threads actually meant. Not incompetence. A gap. Those gaps tend to produce bugs that surface in production under load and vanish the moment you look at them, because the race window is measured in hundreds of nanoseconds and your instrumentation adds milliseconds.

When the bug disappears the moment you look for it, you need a tool that does not look like looking.