Rich Gibbs

Four Silent Days, One Retracted Theory

homelab · honeypot · dionaea · monitoring · incident-response · docker

A Dionaea honeypot sensor silently stopped recording connections for four days while its Docker container continued reporting a healthy status; the gap was found through a stale database file timestamp rather than an alert. Diagnosis pointed to sustained SIP call volume exhausting per-call timer threads, but a second freeze the following day, under ordinary SIP volume, disproved that specific mechanism, leaving the root cause unknown. A four-signal heartbeat monitor (database freshness, container CPU, a second sensor's log freshness, and service status), tested by deliberately forcing and clearing an alert, now runs every 20 minutes and cuts detection time for this failure mode from four days to twenty minutes.

Dionaea stopped capturing at 13:36:53 UTC. Nobody noticed for four days, and when I finally did notice, the container had been reporting "Up 4 days" the entire time. Docker wasn't lying. The process existed, held its ports, never crashed, was never OOM-killed, never restarted. It just stopped doing anything useful, and every signal Docker had access to said that was fine.

The gap I'd already built

The thing that let it hide was the monitoring from the previous session. That change detector reports things it's never seen before — new hashes, new uploads, new payload URLs. It ran hourly for four straight days and stayed silent, because to that kind of check, a dead sensor and a quiet sensor produce the identical input: nothing new. Worse, the baseline it snapshotted that same evening was taken from the already-dead sensor, so that stretch of historical counts isn't a clean record either. The lesson I want to keep: a detector that only fires on new things appearing is structurally blind to things stopping. I need both directions, not one.

What actually surfaced it

Not an alert — a stale modify timestamp on the database file. Before trusting that, I checked the Docker mounts to rule out the boring explanation, that I was reading a stale host-side copy while the container wrote somewhere else. Same bind mounts, same paths inside and out. The database genuinely hadn't been written in four days.

The resource numbers were the strangest part: one CPU core pinned at 100.52%, memory flat at 107.1 MiB — no leak, no growth. Not crashed, not OOM-killed, exit code 0, by Docker's own account nothing was wrong. The thread state is what actually explained it: the main thread was Rsl — running, runnable — with an empty wchan and an empty kernel stack. Not blocked on disk, not blocked on network, not stuck in a futex. It was spinning in userspace. The worker threads were just idle. And the error log had exactly one thing in it: 711 identical "Cleanup" warnings stamped the same second, plus one near-twin with a slightly different path prefix — 712 lines, nothing before or after.

Wrong about the mechanism, and wrong about the IP

I read the actual cleanup function before blaming it, which was the right instinct: seven lines, iterating a fixed snapshot of a dict, deleting closed entries. It cannot loop forever — bounded by construction. It wasn't the cause, it was a symptom. Underneath it: every SIP call spins up its own repeating 60-second timer thread, uncapped. My working theory at the time was that sustained call volume created these faster than they got reclaimed until the single timer queue backed up, and 711 fires in one second was roughly 11.8 hours of scheduled work dumped into a single tick.

I also got the "who" wrong before I got the "what" wrong. The connection right before the freeze had a dramatic-looking SIP breakdown — thirty spoofed user-agents — and I built a theory around it. Then I checked the numbers: that source's 358 commands were cumulative across eight days and roughly two hundred sessions, about 1.8 commands per session. A metronome scanner, not a flood — it ranked 10th by volume and kept connecting harmlessly seven more times after the restart. The actual best-supported source was a different one entirely: 5,970 connections over the preceding 20 hours, sustained at 300–440 an hour, dipping overnight to around 180 and back above 400 by morning — one connection roughly every 12 seconds for 20 hours straight, the last one landing 20 seconds before the freeze. 16x larger by volume, and ranked first, not tenth. Daily SIP share backs this up independently: it climbed from 14% to 16% to 32% (a 6x jump day over day) to 67% of all traffic in the 13.6 hours before the freeze. This is the third time on this project I've pattern-matched on proximity to a timestamp instead of checking the volume first. Stop doing that by default.

Even the better theory came with its own asterisk, and I wrote that down at the time rather than pretending otherwise: proven — the database stopped, the container stayed up, the main thread was pinned, 711 fires happened in one second, the restart restored function, and the high-volume source was active and stopped right before the freeze. Not proven — whether a specific packet triggered it, whether timer-thread exhaustion was the real mechanism versus some other event-loop defect, whether the same volume would even reproduce it.

Good thing I hedged, because the day after I restarted it, Dionaea froze again — ordinary SIP volume this time, about 100 connections, no flood. PIDS stayed at 5 in both frozen states, which rules out thread accumulation outright. And both incidents logged roughly 712 Cleanup lines filling exactly 49,152 bytes — 12 × 4 KiB, a buffer size, not "11.8 hours of backlog" like I'd written. So the timer-exhaustion story, and the backlog-flush framing I built on top of it, are both wrong. I'm leaving the wrong reasoning in this note rather than cleaning it up, because the retraction is the more useful artifact than a tidy correct answer would have been. The failure signature, the recovery steps, and the heartbeat monitor below are all still accurate. The actual cause: unknown, for now.

Recovery, and building the thing that should have caught this

Evidence first, before touching anything — database, both logs, docker inspect output, stats, thread state — because a failed process state can't be recreated once you restart it. Then the restart itself: CPU and memory were back to idle, 0.01% and 34.3 MiB, within 12 seconds. A fast bounce-back isn't proof of function on its own, so I checked that FTP, HTTPS, MySQL, and the other emulated services actually answered, then watched for a real external SIP connection to show up in the database — it arrived six seconds before my own first manual test, from the open internet. That's the full path proven end to end, not just loopback.

The actual fix: a heartbeat script, separate from the change detector, watching four independent signals — database freshness (the comment I wrote says this alone would have caught it in about three hours), container CPU above 50% (would have caught it in 20 minutes), a second sensor's log freshness, and systemd status across all four services. It suppresses repeat alerts for a condition that hasn't changed and sends a clear notice once things recover. I didn't just write it and assume it worked — I forced a false stale-database condition by dropping the threshold to zero, confirmed the alert fired and delivered, restored the threshold, and confirmed a clean pass. Both the alert path and the suppression logic are tested, not assumed. It's on cron now, every 20 minutes, next to the existing hourly change detector. Detection time for this exact failure goes from four days to twenty minutes.

What I decided, and what's still open

Keep SIP capture running, monitor instead of auto-restarting, with auto-restart held in reserve rather than wired up now. One occurrence in three weeks didn't justify automating a restart on a condition I'd only seen once, and the data this sensor collects has been genuinely useful. If it recurs, auto-restart stops being optional.

The notification credentials for all of this read from the same shared local secrets file the existing notifier already uses — one secret, one place, worth remembering if these scripts ever get split across hosts.

Still open: verify the timer-exhaustion idea — now disproven as stated, but the underlying event-loop question isn't resolved — on a disposable instance, never the live sensor. The honeypot software itself dates to November 2020, and a newer release might behave differently, but I decided not to upgrade until this is actually understood. Four days of sensor data are simply gone and have to be excluded from any analysis spanning that window. The old baseline counts aren't clean either, for the same reason.

The parts of this worth keeping cold, independent of which theory survives: docker ps reporting a process exists is not the same as the process working. Thread state — Rsl, empty wchan, empty kernel stack — says "spinning in userspace" and rules out a whole category of causes in one command. The IP nearest the timestamp is not automatically the cause. A cumulative count across days is not a burst size; always bound a number by time before trusting it. Preserve state before repairing anything, because the failed process can't be recreated afterward. And verify recovery by function, not by status — "container up" had already been wrong for four days before I checked anything else.