Files
felhom.eu/documentation/tests/campaign10-evidence-2026-07-31/RESOLVED-backup-target-pair-went-silent.md
T
admin 405a795e32 Campaign 10: RESOLVED — the backup_target_* silence was transient and self-recovered; SQLITE_BUSY drops are absorbed by retry
Both halves of the disposition were run and neither survived as a finding.

The I1/I1-pair violations cluster at cycles 31-33 and nowhere else across 39
cycles; c34-c39 are clean, so it recovered with no intervention. Final tally I1
37 PASS / 2 VIOLATION, I1-pair 36 PASS / 3 VIOLATION. On the quiesced box one slow
detach with 4 minutes either side produced a perfect pair. And the alarming
false-healthy (mentes bound=False while degraded=false) does not survive
quiescence - I had been reading the two halves at different instants of a detach.
No R-n.

Separately cleared: the hub's SQLITE_BUSY event drops. 7 in 24h including one for
the real customer demo-felhom, and the hub does return 500 with notification
dispatch only after a successful save - so a lost event would be a lost alarm. But
the controller retries 3 times and ZERO events exhausted their attempts; the
07:04:39 drop landed at 07:04:42. Nothing lost. Only cosmetic note: the ERROR line
reads like data loss and is not.
2026-08-02 07:10:49 +02:00

134 lines
6.8 KiB
Markdown

# OPEN OBSERVATION — the `backup_target_*` pair stopped firing under rapid detach/reattach cycling
**Not filed as a finding yet.** The system was still being hammered when this was observed, and a
verdict taken on a system mid-abuse is worth little. The disposition below says exactly what would
settle it.
## What was observed (2026-08-02, run 2b, cycles ~30-32)
Three violations in ~5 minutes, all of the same shape — the expected event simply absent:
04:36:55 I1-pair mentes return -> got=None sev=None (want backup_target_restored/info)
04:39:27 I1 mentes absent -> got=None sev=None (want backup_target_absent/error)
04:41:42 I1-pair mentes return -> got=None sev=None (want backup_target_restored/info)
## It is NOT hub-side suppression, and NOT a truncated log
The hub pod has **0 restarts over 43 h**, so its log is intact, and the controller's own log matches
the hub's line for line — the events were **never emitted**, not emitted-and-dropped:
controller 02:32:34 Event pushed: backup_target_absent (error) — … Mentes …
controller 02:32:38 Event pushed: whole_guest_backup_failed (error) — … felhom-backup tier …
controller 02:35:32 Event pushed: health_degraded (warning) …
controller 02:42:08 Event pushed: storage_disconnected (error) — … Adatok <-- generic path STILL WORKS
(no backup_target_restored, and no second backup_target_absent, at any point after 02:32:34)
So this is controller-side emission, and it is **specific to the `backup_target_*` pair**: the generic
`storage_disconnected` / `storage_reconnected` pair for the *other* drive kept firing normally
throughout the same window (02:16:02, 02:18:21, 02:27:38, 02:29:35, 02:42:08).
## The internally inconsistent state alongside it
Sampled while it was happening:
backup-target: {"degraded": false, "known": true, "label": "Mentes", "target": "felhom-backup"}
drives: adatok bound_under_parent=False backup_target=None
mentes bound_under_parent=False backup_target=True
`mentes` is the backup target, reads **not bound**, and the target state simultaneously reports
**`degraded: false`**. Those two cannot both be right. If that survives quiescence it is the more
serious half of this observation — a **false healthy** on the backup target, which is I5/I6's
failure mode and worse than a missing event.
## What is NOT yet established
- Whether the pair recovers once the cycling stops. The harness detaches and reattaches roughly every
two minutes; a real customer does not. Rapid cycling may be outside the design envelope, in which
case this is a robustness note rather than a defect.
- Whether the controller restart at 02:25:37 is implicated. In this controller instance there was
**1 `backup_target_absent` and 0 `backup_target_restored`**; the previous instance emitted complete
pairs (02:13:21 restored). That is suggestive, not established.
- Whether the `degraded: false` reading was a transient mid-flux sample or a stuck state.
## Disposition — how to settle it
After run 2b ends, let the box **quiesce with both drives attached**, then:
1. confirm `bound_under_parent` returns to `True` for both drives and the target still reads healthy —
if it does not, the false-healthy is real and this becomes a finding;
2. do **one** slow detach/reattach of `mentes` with several minutes either side, and check the pair
fires. If it does, the observation is "the pair does not survive rapid cycling"; if it does not,
the target alarm has silently stopped working, which is severe — an alarm that never fires again
after its first firing is worse than no alarm.
Only then does it earn an `R-n` or a retraction.
---
# RESOLVED (2026-08-02) — transient, self-recovered. NOT filed.
Both halves of the disposition were run. Neither survived.
## 1. It self-recovered, mid-run, with no intervention
The violations are **clustered at cycles 31-33 and nowhere else** across 39 cycles:
c28 I1 PASS c28 I1-pair PASS
c29 I1 PASS c29 I1-pair PASS
c30 I1 PASS c30 I1-pair PASS
c31 I1 PASS c31 I1-pair VIOLATION
c32 I1 VIOLATION c32 I1-pair VIOLATION
c33 I1 VIOLATION c33 I1-pair VIOLATION
c34 I1 PASS c34 I1-pair PASS <-- recovered on its own
c35..c39 all PASS
Final tally **I1 37 PASS / 2 VIOLATION, I1-pair 36 PASS / 3 VIOLATION** — a ~3-cycle window inside a
13.5-hour run of sustained 2-minute detach/reattach cycling.
## 2. A slow cycle on the quiesced box works perfectly
With the run finished and the box quiet, one detach with 4 minutes either side:
07:00:08 backup_target_absent (error) — A rendszermentés meghajtója nem érhető el: Mentes
07:04:42 backup_target_restored (info) — A rendszermentés meghajtója újra elérhető: Mentes
07:06:37 health_recovered (info) — Rendszer állapot helyreállt: ok (volt: warn)
## 3. The "false healthy" was a mid-flux sample, not a stuck state
The alarming pair (`mentes bound_under_parent=False` **and** `degraded: false`) does not survive
quiescence. Three minutes after the run ended:
drives: adatok bound=True mentes bound=True backup_target=True
target: {"degraded": false, "known": true, "label": "Mentes", "target": "felhom-backup"}
Consistent. I was sampling a system mid-detach and reading the two halves at different instants.
## Verdict
**No `R-n`.** The target alarm does not fire during a narrow window under detach/reattach cycling far
faster than any real box sees, and it resumes by itself. Recorded so a future session that sees the
same three-cycle cluster knows it was chased to the ground and what settled it.
---
# Also investigated and cleared: the hub's SQLITE_BUSY event drops
Chased during the same test and **also not a finding**, recorded because the log line is alarming:
[ERROR] Failed to save event from c10-soak: database is locked (5) (SQLITE_BUSY)
7 occurrences in 24 h, **including one for the real customer `demo-felhom`** — so it is not a
campaign artifact. The hub returns HTTP 500 on the failed save (`handler.go:1715`) and dispatches
notifications only *after* a successful save, so a genuinely lost event would be a lost alarm.
**But the controller retries 3 times**, and **0 events exhausted their attempts** across the whole
run (`grep -c "Event push failed after 3 attempts"` = 0). The 07:04:39 drop landed 3 seconds later:
07:04:39 [ERROR] Failed to save event … SQLITE_BUSY
07:04:42 [INFO] Event from c10-soak: backup_target_restored (info) … <-- same event, retried
**Nothing was lost.** The one observation worth keeping is cosmetic: `[ERROR] Failed to save event`
reads like data loss and is not — a reader would reasonably conclude an alarm had been dropped. The
same contention also skipped monitor ticks (Host OOB, Offsite, restore-test, log-bundle purge), which
are periodic and simply run again.