From b6e1b5e470dadfde7a102073c2e0f6ffa875650a Mon Sep 17 00:00:00 2001 From: David F Glidden Date: Mon, 17 Aug 2026 14:57:48 +0200 Subject: [PATCH] [FIX] The unwrapped-session detector compared two different clocks MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The wake digest's `PREVIOUS SESSION DID NOT WRAP` alarm fired falsely at three consecutive wakes and was overridden by hand at two of them. It was scoped as a two-valued-detector problem. Diagnosing the class first found four defects, and the scoped one was not the cause: 1. TIME BASE (the cause). Transcript timestamps are UTC (`...Z`); the code dropped the suffix and called `time.mktime`, which reads a struct_time as LOCAL, then compared the result against `os.path.getmtime`, a true epoch. Measured: +7201 s skew against a 900 s tolerance. Because the skew exceeds the tolerance, a wrap written at the end of a session could NEVER land inside the window — the alarm was systematic, not intermittent. 2. SELECTION. "Newest transcript quiet for >60 s" excluded the previous session at exactly the moment it mattered: on 2026-08-17 it had ended 12 s before the wake, was skipped, and the session from four days earlier was reported instead. The defect is time-dependent and disappears ~60 s later, which is why re-running the digest afterwards showed nothing wrong. 3. EVIDENCE. Wrap records were dated by mtime, which any later edit moves — the 08-14 record read 08-17 because a CODA was appended to it. Now dated by git add-time, which cannot move once committed; mtime is a labelled fallback. 4. ARITY. `verdict is None` (could not assess) was folded into silence with "wrapped fine". Now four outcomes, per REVIEWED-104: wrapped · unwrapped · unassessable-subject (environment) · unassessable-check (defect). Acceptance is old-vs-new on the real case, not a unit pass. At the reconstructed wake instant the old code selects the wrong transcript AND returns a false alarm on the right one; the new code selects correctly and returns `wrapped`. Both defects independently produced the alarm, so fixing only the arity — the scoped task — would have shipped a fix that left it firing. The selftest gains a control derived from the property rather than from the check: a transcript's last inner timestamp and its file mtime are two readings of one moment, so their MEDIAN skew detects a systematic clock mismatch (1 s now, ~7200 s before). Max is printed too, because one transcript legitimately skews 31 h — the same mutable-mtime problem, on the transcript side. The old real-substrate gate demanded both verdicts occur across live sessions and PASSED while the detector was broken: it established that outcomes were spread, never that any was correct. Demoted to a printed note with its limit stated beside it. Filed as PENDING-142 ADDENDUM 1. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_013Y6t6qx7cpaCu5xGdD36u4 --- scripts/wake-digest.py | 297 ++++++++++++++++++++++++++++++++++------- 1 file changed, 249 insertions(+), 48 deletions(-) diff --git a/scripts/wake-digest.py b/scripts/wake-digest.py index acfa86f..e68fa35 100755 --- a/scripts/wake-digest.py +++ b/scripts/wake-digest.py @@ -16,7 +16,7 @@ if it cannot be computed it says so rather than emitting nothing. Provenance: 2026-07-28, steward-authorized alongside the PENDING split and the CLAUDE.md doctrine annotation. Sibling of governance-drift-check.py. """ -import os, re, subprocess, sys, time +import calendar, os, re, subprocess, sys, time HOME = os.path.expanduser("~") D = os.path.join(HOME, "dotfiles") @@ -138,6 +138,41 @@ def wrap_records(): if f.startswith("session-") and not f.startswith("session-ledger-")] +def parse_iso(s): + """ISO-8601 -> true epoch, honouring the zone suffix. + + THE 2026-08-17 BUG, and it is the whole reason the alarm below misfired. + Transcript timestamps are UTC (`2026-08-14T07:29:36.852Z`). The previous + implementation dropped the `Z` and called `time.mktime`, which reads a + struct_time as LOCAL — putting the span in a different time base from + `os.path.getmtime()`, which returns a true epoch. Measured that day: a + +2 h (CEST) skew against a 15 min tolerance. Since the skew exceeds the + tolerance, a wrap written at the end of a session could NEVER land inside + the window — so `PREVIOUS SESSION DID NOT WRAP` was systematic, not + occasional. It had been overridden by hand at two consecutive wakes. + + Naive strings (no zone) are still read as local: that is what they mean. + """ + m = re.match(r"(\d{4}-\d{2}-\d{2})[T ](\d{2}:\d{2}:\d{2})", s or "") + if not m: + return None + try: + st = time.strptime(f"{m.group(1)}T{m.group(2)}", "%Y-%m-%dT%H:%M:%S") + except (ValueError, OverflowError): + return None + z = re.match(r"(?:\.\d+)?(Z|[+-]\d{2}:?\d{2})", s[m.end():]) + if not z: + try: + return time.mktime(st) + except (ValueError, OverflowError): + return None + tag = z.group(1) + if tag == "Z": + return calendar.timegm(st) + sign = 1 if tag[0] == "+" else -1 + return calendar.timegm(st) - sign * (int(tag[1:3]) * 3600 + int(tag[-2:]) * 60) + + def transcript_span(path): """ A session's true span, from the timestamps INSIDE the transcript — never mtime. @@ -148,28 +183,115 @@ def transcript_span(path): try: with open(path, errors="ignore") as f: for line in f: - m = re.search(r'"timestamp"\s*:\s*"([0-9T:\-]{19})', line) + m = re.search(r'"timestamp"\s*:\s*"([^"]{19,40})"', line) if m: + e = parse_iso(m.group(1)) + if e is None: + continue if first is None: - first = m.group(1) - last = m.group(1) + first = e + last = e except OSError: return None, None - - def epoch(s): - try: - return time.mktime(time.strptime(s, "%Y-%m-%dT%H:%M:%S")) - except (ValueError, OverflowError): - return None - return epoch(first), epoch(last) + return first, last -def wrap_inside(span, wrap_mtimes, lead=300, lag=900): - """Did a wrap record get written inside this session's span?""" +def wrap_events(): + """-> [(path, epoch, source)] — when each wrap record CAME INTO EXISTENCE. + + Not mtime. A wrap record edited later — a CODA appended, a correction made — + carries the edit's mtime, so an ordinary and correct act destroys the evidence + that the wrap happened inside its own session. Measured 2026-08-17: the 08-14 + record's mtime read 08-17 for exactly that reason. Git's add-time cannot move + once committed; mtime is the fallback for a not-yet-committed record and is + labelled so the caller can tell the two apart. + """ + added, at = {}, None + out = sh(["git", "-C", D, "log", "--diff-filter=A", "--format=%at", + "--name-only", "--", os.path.relpath(os.path.realpath(MEM), D)]) + for line in (out or "").split("\n"): + line = line.strip() + if re.fullmatch(r"\d{9,11}", line): + at = int(line) + elif line and at is not None: + base = line.rsplit("/", 1)[-1] + if base not in added or at < added[base]: + added[base] = at # earliest add wins + ev = [] + for p in wrap_records(): + base = os.path.basename(p) + if base in added: + ev.append((p, added[base], "git")) + else: + try: + ev.append((p, os.path.getmtime(p), "mtime")) + except OSError: + pass + return ev + + +def previous_transcript(now, spans): + """The session before this one, selected by SPAN — never by 'quiet for >60 s'. + + The old rule excluded any transcript touched within 60 s as 'the current + session'. That is wrong at precisely the moment it matters: on 2026-08-17 the + previous session had ended 12 s before the wake, was excluded as too recent, + and the digest reported the session from four days earlier instead — 'ended + ~Aug 13 21:36'. The defect is time-dependent and disappears ~60 s later, which + is why re-running the digest afterwards showed nothing wrong. + + THIS session's transcript is the one most recently STARTED that is still being + appended. Keying on start alone breaks once the current session has run a + while; keying on end alone cannot tell a live session from one that ended + seconds ago. Both together identify it, and at most one is ever excluded — so + a just-ended prior session can no longer be skipped. + + Residual, stated rather than hidden: if the current session's transcript holds + no parseable timestamp yet, the newest START is the previous session, and if it + also ended moments ago it is excluded and the one before it is reported. That + is the old failure in a much smaller window, and it is why the caller treats a + 'no wrap' result as advisory rather than as proof. + """ + dated = [r for r in spans if r[1] is not None and r[2] is not None] + if not dated: + return None + live = max(dated, key=lambda r: r[1]) # newest start … + rest = [r for r in dated if r is not live] if live[2] >= now - 120 else dated + return max(rest, key=lambda r: r[2]) if rest else None # … and still growing + + +def wrap_verdict(span, events, lead=300, lag=10800): + """-> (state, detail). FOUR outcomes, because 'I could not tell' is two things. + + REVIEWED-104: a check whose subject can be absent may not be two-valued, and + the third outcome is itself two kinds — subject absent (environment, must not + block) versus check broken (defect). The previous version folded both into + silence via `verdict is None`, so 'I could not look' read as 'it wrapped'. + """ a, b = span if a is None or b is None: - return None # unreadable — not the same as 'no wrap' - return any(a - lead <= m <= b + lag for m in wrap_mtimes) + return "unassessable-subject", ("the previous session's transcript carries " + "no readable timestamps") + if not events: + return "unassessable-check", "no wrap records could be enumerated" + if any(a - lead <= e <= b + lag for _p, e, _s in events): + return "wrapped", "" + # No event in the window. Before alarming, ask whether some wrap record NAMES a + # day inside this span: commit lag can push real evidence past the window, and + # an alarm that cannot be substantiated is worse than an honest non-answer. + days, t, guard = set(), int(a), 0 + while t <= int(b) + 86400 and guard < 60: + days.add(time.strftime("%Y-%m-%d", time.localtime(t))) + t += 86400 + guard += 1 + named = [os.path.basename(p) for p, _e, _s in events + if any(d in os.path.basename(p) for d in days)] + if named: + return ("unassessable-check", + f"no wrap event inside the span, but {named[0]} names a day within " + f"it — a real wrap with lagged evidence cannot be told apart from " + f"another session's record") + return "unwrapped", "" def sec_unwrapped(): @@ -182,30 +304,44 @@ def sec_unwrapped(): detected this via a MemPalace Stop hook; that hook is retired, but the failure it named is live. The transcripts are the only witness that a session ran at all. + + Rebuilt 2026-08-17, after the alarm fired falsely at three consecutive wakes + and was overridden by hand at two of them. FOUR defects were found, and only + one was the one the work had been scoped to: + 1. a UTC/local time-base mismatch (see `parse_iso`) — THE CAUSE, and large + enough that an end-of-session wrap could never be seen; + 2. a selection rule that skipped a session which had just ended; + 3. wrap evidence read from mutable mtimes; + 4. a two-valued verdict over an assessment that can fail. + Fixing only (4), as scoped, would have left the false alarms firing. """ proj = os.path.dirname(os.path.join(HOME, ".claude", "projects", "-Users-davidglidden", "memory")) try: tx = [os.path.join(proj, f) for f in os.listdir(proj) if f.endswith(".jsonl")] except OSError: + warn.append("session transcripts unreadable — wrap check did not run") return None - now = time.time() - # The current session's transcript is being appended right now; the previous - # session's is the newest one that has gone quiet. - prior = [p for p in tx if now - os.path.getmtime(p) > 60] - if not prior: + if not tx: return None - last = max(prior, key=os.path.getmtime) - verdict = wrap_inside(transcript_span(last), - [os.path.getmtime(w) for w in wrap_records()]) - if verdict is None or verdict: + prev = previous_transcript(time.time(), [(p,) + transcript_span(p) for p in tx]) + if prev is None: return None - ended = time.strftime("%b %d %H:%M", time.localtime(os.path.getmtime(last))) - return (f"⚠ PREVIOUS SESSION DID NOT WRAP (ended ~{ended}). The thread and " - f"question below are inherited from an OLDER session — treat them as " - f"possibly stale, and expect no record of what that session did.\n" - f" Not established: whether that session did work worth keeping. The " - f"transcript is on disk and can be read if the gap matters.") + _path, a, b = prev + state, detail = wrap_verdict((a, b), wrap_events()) + if state == "wrapped": + return None + ended = time.strftime("%b %d %H:%M", time.localtime(b)) + if state == "unwrapped": + return (f"⚠ PREVIOUS SESSION DID NOT WRAP (ended ~{ended}). The thread and " + f"question below are inherited from an OLDER session — treat them as " + f"possibly stale, and expect no record of what that session did.\n" + f" Not established: whether that session did work worth keeping. The " + f"transcript is on disk and can be read if the gap matters.") + return (f"◌ WRAP STATUS UNDETERMINED for the previous session (ended ~{ended}) — " + f"{detail}.\n" + f" This is neither an alarm nor a clean pass: the check could establish " + f"neither. Open the newest session record to see what it actually holds.") def ruled_pendings(reviewed_text): @@ -805,26 +941,91 @@ def selftest(): chk("is_homed FALSE for a symlink pointing OUTSIDE maps/", not is_homed(os.path.join(HOME, ".claude"), MAPS_DIR)) print("\nunwrapped-session detector [PENDING-S2's obligation, our substrate]:") - chk("wrap_inside TRUE when a wrap falls inside the span", - wrap_inside((1000.0, 2000.0), [1500.0])) - chk("wrap_inside TRUE for a wrap just after the last write [wraps land near the end]", - wrap_inside((1000.0, 2000.0), [2400.0])) - chk("wrap_inside FALSE when every wrap is outside [negative control]", - not wrap_inside((1000.0, 2000.0), [500.0, 5000.0])) - chk("wrap_inside returns None on an unreadable span [must NOT read as 'no wrap']", - wrap_inside((None, None), [1500.0]) is None) - # Discrimination on REAL sessions: the detector must return BOTH verdicts over - # the actual transcript history. One verdict everywhere = it discriminates nothing. + # --- time base. The 2026-08-17 cause, and the control that was missing. ---- + _utc = calendar.timegm(time.strptime("2026-08-14T07:29:36", "%Y-%m-%dT%H:%M:%S")) + chk("parse_iso reads a 'Z' timestamp as UTC [the 2026-08-17 cause]", + parse_iso("2026-08-14T07:29:36.852Z") == _utc) + _agrees = (parse_iso("2026-08-14T07:29:36.852Z") + == time.mktime(time.strptime("2026-08-14T07:29:36", "%Y-%m-%dT%H:%M:%S"))) + _utc_box = (time.altzone if time.daylight else time.timezone) == 0 + chk("parse_iso differs from the old mktime reading unless the box is on UTC" + " [negative control — proves the line above can fail]", _agrees == _utc_box) + chk("parse_iso honours an explicit offset", + parse_iso("2026-08-14T09:29:36+02:00") == parse_iso("2026-08-14T07:29:36Z")) + chk("parse_iso returns None on junk [must not invent a span]", + parse_iso("not a timestamp") is None and parse_iso("") is None) + # THE END-TO-END FORM, derived from the property rather than from the check: + # a transcript's last inner timestamp and its file mtime are two readings of + # one moment. If they disagree by more than minutes, the detector is comparing + # two different clocks — which is exactly what it was doing (~7200 s skew). _proj = os.path.dirname(MEM) _tx = sorted((os.path.join(_proj, f) for f in os.listdir(_proj) - if f.endswith(".jsonl")), key=os.path.getmtime)[-14:-1] - _wm = [os.path.getmtime(w) for w in wrap_records()] - _v = [wrap_inside(transcript_span(p), _wm) for p in _tx] - chk(f"real sessions read as WRAPPED [{sum(1 for x in _v if x is True)} of {len(_v)}]", - any(x is True for x in _v)) - chk(f"real sessions read as UNWRAPPED [{sum(1 for x in _v if x is False)} of {len(_v)}]" - " — the negative instance; without one the detector is unproven", - any(x is False for x in _v)) + if f.endswith(".jsonl")), key=os.path.getmtime) + # MEDIAN, not max, and the reason is itself a finding: a clock mismatch is + # SYSTEMATIC — it shifts every transcript by the same amount, so it moves the + # median. A lone large skew is a different phenomenon: 2026-08-10's transcript + # was touched 31 h after its last line. That is the very mutable-mtime problem + # `wrap_events` routes around, measured here on the transcript side. Max is + # printed so the outlier stays visible instead of being averaged away. + _skew = sorted(abs(os.path.getmtime(p) - transcript_span(p)[1]) + for p in _tx[-8:] if transcript_span(p)[1] is not None) + _med = _skew[len(_skew) // 2] if _skew else -1 + chk(f"transcript span END agrees with file mtime" + f" [median {_med:.0f}s, max {max(_skew) if _skew else -1:.0f}s;" + f" median was ~7200s before the fix]", + bool(_skew) and _med < 900) + # --- the four outcomes ----------------------------------------------------- + _E = [("/w/session-2026-01-02-x.md", 1500.0, "git")] + chk("wrap_verdict WRAPPED when an event lands inside the span", + wrap_verdict((1000.0, 2000.0), _E)[0] == "wrapped") + chk("wrap_verdict WRAPPED for an event just after the last write [wraps land near the end]", + wrap_verdict((1000.0, 2000.0), [("/w/session-2026-01-02-x.md", 2400.0, "git")])[0] + == "wrapped") + chk("wrap_verdict UNWRAPPED when every event is outside [negative control]", + wrap_verdict((1000.0, 2000.0), [("/w/session-1999-01-01-a.md", 500.0, "git"), + ("/w/session-1999-01-01-b.md", 5.0e8, "git")])[0] + == "unwrapped") + chk("wrap_verdict UNASSESSABLE-SUBJECT on an unreadable span [must NOT read as 'no wrap']", + wrap_verdict((None, None), _E)[0] == "unassessable-subject") + chk("wrap_verdict UNASSESSABLE-CHECK when no wrap record can be enumerated", + wrap_verdict((1000.0, 2000.0), [])[0] == "unassessable-check") + _t0 = time.time() + chk("wrap_verdict declines to alarm when a record NAMES a day inside the span" + " [commit lag must not become a false alarm]", + wrap_verdict((_t0, _t0 + 3600), + [(f"/w/session-{time.strftime('%Y-%m-%d', time.localtime(_t0))}-x.md", + _t0 + 10 * 86400, "git")])[0] == "unassessable-check") + # --- selection ------------------------------------------------------------- + _now = 1_000_000.0 + _spans = [("cur.jsonl", _now - 5, _now), + ("prev.jsonl", _now - 86400, _now - 12), + ("old.jsonl", _now - 400000, _now - 350000)] + chk("previous_transcript picks the session that ended 12 s ago [the 2026-08-17 miss]", + previous_transcript(_now, _spans)[0] == "prev.jsonl") + _mid = [("cur.jsonl", _now - 1380, _now), # running 23 min — a manual run + ("prev.jsonl", _now - 86400, _now - 1400), + ("old.jsonl", _now - 400000, _now - 350000)] + chk("previous_transcript excludes a LONG-running current session [manual mid-session run;" + " keying on start alone regressed here]", + previous_transcript(_now, _mid)[0] == "prev.jsonl") + chk("previous_transcript keeps a quiet newest-start transcript [negative control —" + " exclusion needs BOTH signals, not just newest start]", + previous_transcript(_now, _mid[1:])[0] == "prev.jsonl") + # --- real substrate -------------------------------------------------------- + _ev = wrap_events() + _git = sum(1 for _p, _e, _s in _ev if _s == "git") + chk(f"wrap evidence is taken from git add-time, not mutable mtimes" + f" [{_git} of {len(_ev)} from git]", len(_ev) > 0 and _git > len(_ev) // 2) + _v = [wrap_verdict(transcript_span(p), _ev)[0] for p in _tx[-14:-1]] + chk(f"a real session reads as WRAPPED end-to-end [{_v.count('wrapped')} of {len(_v)}]", + "wrapped" in _v) + # ⚠ The old gate here demanded a real UNWRAPPED instance too, and PASSED on + # 2026-08-17 while the detector was systematically broken — it established that + # both verdicts OCCUR, never that either was CORRECT. Its subject was the + # spread of outcomes; the claim was their truth. Reported, not asserted. + print(f" [note] real-session outcome spread: " + + ", ".join(f"{s}={_v.count(s)}" for s in sorted(set(_v))) + + " — a spread is not a proof of correctness; the controls above are.") print("\nlive substrate:") chk("PENDING.md readable", read(PENDING) is not None)