felhom.eu/documentation/audits/update-night-2026-09-21/phase3_b5.py

#!/usr/bin/env python3
"""Phase 3 leg B5 — a power cut in `backing-up`, and in `safety-dump`.

R-520 cut in `pulling` (nothing had run). R-610 cut after `starting` (the migration had run). The
two phases NOBODY has cut in are the two EARLY ones, and they are the ones that touch the
customer's copy rather than their data:

  backing-up   `RunAppBackupNow` is making the copy the update will lean on
  safety-dump  `WriteUpdateSafetyDump` is writing R-361's undo copy, BEFORE the pin moves

Source says both should end with *nothing moved, the journal entry dropped, and the interrupted
sentence shown*. THE CLAIM THIS LEG EXISTS TO TEST is narrower and nastier than that: **a backup
artefact that was half-written must not be left looking whole**, because the next update's
precondition will believe it.

INSTRUMENT LIMITS, STATED UP FRONT because they bound every claim below:
  * the poll is 200 ms and `pct stop` returns in 3–4 s, so the phase at the DECISION is observed
    and the phase at the FREEZE is inferred. Said every time, never glossed (R-520's own lesson).
  * `backing-up` only happens when no tier holds a copy younger than `update.backup_max_age`, so
    this leg lowers that knob — an operator-owned setting on `controller.yaml`, restored at teardown.
  * `pct mount` shows an EMPTY STUB for the guest's inner mounts, so every post-crash read is taken
    from the BOOTED guest, or with `find` over the whole rootfs and a positive control. An empty
    directory is not evidence of an absent file.
"""
import json, os, re, subprocess, sys, time
from datetime import datetime

HERE = os.path.dirname(os.path.abspath(__file__))
sys.path.insert(0, HERE)
import walk as w   # noqa: E402
from fixtures import FIXTURES   # noqa: E402
from phase3_legs import out, sentences   # noqa: E402

V = "/var/lib/docker/volumes/felhom-controller-data/_data"


def hostsh(cmd, timeout=300):
    return (w.sh(["ssh", "-o", "ConnectTimeout=20", w.HP, cmd], timeout=timeout).stdout or "")


def set_knob(key, value):
    """Set one operator-owned knob in controller.yaml and restart. Restored at teardown."""
    scr = f"""
python3 - <<'PY'
import re
p="{V}/controller.yaml"
s=open(p).read()
if re.search(r'^update:', s, re.M):
    if re.search(r'^(update:\\n(?:    .*\\n)*?)    {key}:.*$', s, re.M):
        s=re.sub(r'^(update:\\n(?:    .*\\n)*?)    {key}:.*$', r'\\g<1>    {key}: {value}', s, count=1, flags=re.M)
    else:
        s=re.sub(r'^update:\\n', 'update:\\n    {key}: {value}\\n', s, count=1, flags=re.M)
else:
    s += "\\nupdate:\\n    {key}: {value}\\n"
open(p,'w').write(s)
PY
sed -n '/^update:/,/^[a-z]/p' {V}/controller.yaml
systemctl restart felhom-controller-bootstrap.service
sleep 22
docker ps --filter name=felhom-controller --format '{{{{.Status}}}}'
"""
    o = w.guest(scr, timeout=400)
    w.say(f"  [knob] {key}={value} :: " + " | ".join(x for x in o.split("\n") if x.strip())[:260])
    w.login()
    return o


def cut_during(app, want_phase, poll=0.2, cap_s=300):
    """Press Update, poll at 200 ms, and pull the plug the moment the wanted phase is observed."""
    code, body = w.ctl("POST", f"/api/stacks/{app}/update")
    w.say(f"  [cut] Update -> {code} {str(body)[:120]}")
    if code not in ("202", "200"):
        return {"pressed": False, "http": code, "body": body}
    seen, t0, decided = [], time.time(), None
    while time.time() - t0 < cap_s:
        st = w.stack(app)
        ph = st.get("update_phase")
        if not seen or seen[-1]["phase"] != ph:
            seen.append({"t": round(time.time() - t0, 3), "phase": ph})
            w.say(f"      +{seen[-1]['t']:>7.3f}s phase={ph}")
        if ph == want_phase:
            decided = datetime.utcnow().isoformat(timespec="milliseconds") + "Z"
            w.say(f"  [cut] phase {want_phase!r} OBSERVED at {decided} — pulling the plug NOW")
            t1 = time.time()
            r = hostsh("pct stop 9202", timeout=180)
            w.say(f"  [cut] `pct stop 9202` returned after {round(time.time()-t1,2)}s :: {r.strip()[:120]}")
            return {"pressed": True, "phases_seen": seen, "cut_decided_at": decided,
                    "pct_stop_returned_after_s": round(time.time() - t1, 2),
                    "instrument_limit": "the phase at the DECISION is observed; the phase at the "
                                        "FREEZE is inferred — pct stop is not instantaneous"}
        if not st.get("updating") and ph in ("done", "failed"):
            w.say(f"  [cut] the update ENDED at phase {ph} before {want_phase!r} was ever seen")
            return {"pressed": True, "phases_seen": seen, "cut_decided_at": None,
                    "missed": want_phase, "ended_phase": ph}
        time.sleep(poll)
    return {"pressed": True, "phases_seen": seen, "cut_decided_at": None, "timeout": True}


def boot_and_read(app):
    hostsh("pct start 9202", timeout=300)
    w.say("  [boot] guest 9202 starting")
    for _ in range(90):
        time.sleep(5)
        o = hostsh("pct exec 9202 -- docker ps --filter name=felhom-controller "
                   "--format '{{.Status}}' 2>/dev/null")
        if "Up" in o:
            w.say(f"  [boot] controller back: {o.strip()}")
            break
    time.sleep(20)
    w.login()
    recovery = w.guest(
        "docker logs felhom-controller 2>&1 | grep -iE 'recover|interrupted|journal|pin .*back|"
        f"resum' | tail -20; echo '--- journal file:'; ls -la {V}/data/update-journal.json 2>&1")
    w.say("  [boot] recovery lines: " + " | ".join(
        x for x in recovery.split("\n") if x.strip())[:500])
    st = w.stack(app)
    return {"recovery_lines": recovery, "state": st.get("state"),
            "update_phase": st.get("update_phase"), "update_error": st.get("update_error"),
            "hold_reason": st.get("hold_reason"), "observables": w.observables(app)}


def backup_artefacts(app):
    """Is a half-written backup artefact left LOOKING WHOLE? The question the leg exists for."""
    return w.guest(f"""
echo "=== the app's own recovery unit + its db dumps, with sizes and times"
find /mnt/sys_drive/felhom-data/backups -path '*{app}*' -type f -printf '%TY-%Tm-%Td %TH:%TM  %10s  %p\\n' 2>/dev/null | sort | tail -25
echo "=== any temp/partial names left behind"
find /mnt/sys_drive/felhom-data/backups -path '*{app}*' \\( -name '*.tmp' -o -name '*.part' -o -name '*partial*' -o -name '*.inprogress' \\) 2>/dev/null | head -10 || true
echo "=== the unit manifest, if there is one"
find /mnt/sys_drive/felhom-data/backups -path '*{app}*' -name 'manifest*.json' -exec sh -c 'echo "--- {{}}"; head -c 700 "{{}}"; echo' \\; 2>/dev/null | head -40
echo "=== ZERO-BYTE files under this app's backups (a half-write that still looks like a file)"
find /mnt/sys_drive/felhom-data/backups -path '*{app}*' -type f -size 0 2>/dev/null | head -10 || echo "(none)"
""", timeout=420)


def run(app, sub, phase, label):
    d = out(f"B5-{label}")
    w.say(f"==== B5: a power cut during `{phase}` on {app}")
    rec = {"leg": f"B5-{label}", "app": app, "phase_targeted": phase}

    # B5 needs a PENDING edge or there is nothing for the cut to interrupt. B4 leaves these apps
    # level with the catalog, so publish one here — the same image under the next tag, so the pull
    # is instant and the cut lands in the EARLY phases this leg is about rather than in `pulling`.
    repo = {"privatebin": "paste", "bentopdf": "pdf"}.get(app)
    if repo:
        cur = None
        for line in open(f"{w.DRILL}/templates/{app}/docker-compose.yml"):
            if line.strip().startswith("image:"):
                cur = line.strip().split("image:", 1)[1].strip()
                break
        nxt = f"localhost:5000/drill/{repo}:2.0.2"
        if cur and cur != nxt:
            w.drill_bump(app, cur, nxt)
            w.sync_rescan()
        st = w.stack(app)
        w.say(f"  [0] pending edge for the cut: installed="
              f"{ {k:(v.get('ref') if isinstance(v,dict) else v) for k,v in ((st.get('app_config') or {}).get('installed_images') or {}).items()} } "
              f"catalog={st.get('catalog_images')}")

    before = w.observables(app)
    rec["observables_before"] = before
    rec["backup_artefacts_before"] = backup_artefacts(app)
    open(f"{d}/00-backups-before.txt", "w").write(rec["backup_artefacts_before"])
    w.say(f"  [0] pinned before = {before['pinned_images']}")

    rec["cut"] = cut_during(app, phase)
    if not rec["cut"].get("cut_decided_at"):
        w.say("  [!] the phase was never observed — the cut did NOT happen. Recorded as a MISS, "
              "not as a pass.")
        json.dump(rec, open(f"{d}/result.json", "w"), indent=2, ensure_ascii=False)
        open(f"{d}/log.txt", "w").write("\n".join(w.LOG) + "\n")
        return

    rec["after_boot"] = boot_and_read(app)
    rec["backup_artefacts_after"] = backup_artefacts(app)
    open(f"{d}/01-backups-after.txt", "w").write(rec["backup_artefacts_after"])
    rec["sentences"] = sentences(app)
    w.say(f"  [2] household sentence HU: {rec['sentences']['hu'][:3]}")
    w.say(f"  [2] household sentence EN: {rec['sentences']['en'][:3]}")

    fx = FIXTURES.get(app)
    if fx:
        tok = fx.seed(w, sub, w.say)
        rec["app_usable_after"] = bool(tok) and fx.verify(w, sub, tok, w.say)
        w.say(f"  [3] the app works and holds data after the cut: {rec['app_usable_after']}")

    a, b = rec["observables_before"], rec["after_boot"]["observables"]
    rec["pin_moved"] = a["pinned_images"] != b["pinned_images"]
    w.say(f"  [4] pinned after = {b['pinned_images']}  (moved: {rec['pin_moved']})")
    json.dump(rec, open(f"{d}/result.json", "w"), indent=2, ensure_ascii=False)
    open(f"{d}/log.txt", "w").write("\n".join(w.LOG) + "\n")


if __name__ == "__main__":
    w.login()
    cmd = sys.argv[1]
    if cmd == "knob":
        set_knob(sys.argv[2], sys.argv[3])
    else:
        run(sys.argv[1], sys.argv[2], sys.argv[3], sys.argv[4])