diff --git a/CLAUDE.md b/CLAUDE.md index d74034e..b364702 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -234,23 +234,48 @@ raise if the call's silence budget passes with no new output — silence, not el time, is the signal, since legitimate transfers range from minutes to 22+ hours (see Known issues below). -The budget is **not one number**: a *create* streams per-file progress, so silence there -really is a hang and it keeps `HTAR_STALL_SECONDS` (2h); the post-create *round-trip -verify retrieve* is silent **by design** while HPSS queues and stages the tape, so both -`ship_object` **and** `send_to_fortress` bound it with the config's -**`retrieve_stall_seconds`** instead (default in `stall_defaults.json` — data, not code; -a per-asset config may override it; there is deliberately no code-side fallback, so a -caller that forgets to thread it down raises). Conflating the two is a real, expensive -bug, not a theoretical one: on 2026-08-03 a single 6.62 GB `X1D_3_metabolomics_rawspectra` -shard (routed via `ship_object`) had its healthy retrieve killed at exactly 2h twice per -job (its stall log reads `activity resumed after 7200.1s silence`), so verify never -passed, no success record was written, and every scheduled run re-shipped the whole -shard — 48 identical tars, ~318 GB of duplicate tape, over 2.5 weeks. The identical bug -independently existed in `send_to_fortress`'s own inline `run_watched()` twin (whole-target -and Phase-3 leveled targets) until it was given the same fix: confirmed hit on +The budget is **not one number** — it has THREE regimes, all fed by the same two +config-ish quantities (`HTAR_STALL_SECONDS`, a constant, and the config's +`retrieve_stall_seconds`): + +1. **Retrieve, the whole call.** The post-create round-trip verify retrieve is silent + **by design** while HPSS queues and stages the tape, so both `ship_object` **and** + `send_to_fortress` bound its ENTIRE duration with the config's + **`retrieve_stall_seconds`** (default in `stall_defaults.json` — data, not code; a + per-asset config may override it; there is deliberately no code-side fallback, so a + caller that forgets to thread it down raises). +2. **Create, before the first byte moves.** A create used to be assumed to stream + per-file progress continuously from the start, so ANY silence meant a hang. That + assumption broke: 2026-07-31 onward (post a Duke Power outage that took Fortress + offline 07-30/31), creates began legitimately queueing at HPSS for well over an + hour with zero output before transfer actually begins — confirmed live on + `repository_X0E_2_spectral-standoff` (job 41943831, 2026-08-12): a create sat + silent for 4260.7s (71 min), then resumed and completed normally. So the create's + INITIAL silence — before ANY output/growth has ever been observed — is now ALSO + bounded by `retrieve_stall_seconds`, the same "HPSS is queueing/staging" budget + retrieve uses, via `_run_with_stall_watch()`'s / `run_watched()`'s + `initial_stall_seconds` parameter. +3. **Create, after the first byte moves.** Once a create HAS started streaming + per-file progress, the original rationale still holds — further silence really is a + hang — so the bound tightens back to the tight `HTAR_STALL_SECONDS` (2h) for the + rest of that call. This is what still catches a genuine mid-transfer hang fast (see + the 32h incident below) without needing to loosen the whole create's budget. + +Conflating any of these is a real, expensive bug, not a theoretical one: on 2026-08-03 +a single 6.62 GB `X1D_3_metabolomics_rawspectra` shard (routed via `ship_object`) had +its healthy retrieve killed at exactly 2h twice per job (its stall log reads `activity +resumed after 7200.1s silence`), so verify never passed, no success record was written, +and every scheduled run re-shipped the whole shard — 48 identical tars, ~318 GB of +duplicate tape, over 2.5 weeks. The identical retrieve bug independently existed in +`send_to_fortress`'s own inline `run_watched()` twin (whole-target and Phase-3 leveled +targets) until it was given the same fix: confirmed hit on `repository_X0H_2_spectral-standoff` (job 41417829, 2026-07-31), a leveled-incremental target whose round-trip retrieve was killed at exactly "no output for 2.0h" after a -successful create. +successful create. That same 07-31 date also marks the onset of the SEPARATE +create-queueing pattern (regime 2 above) — many repository targets (X0C, X0E, X0F, +X1A–X1G, ...) have since failed with a create killed at exactly "no output for 2.0h" +with zero prior progress, a pattern that lines up with the Duke Power outage rather +than a code bug. Short, no-progress calls (`hsi mkdir`/`hsi ls`) just need `timeout=HSI_SHORT_CALL_TIMEOUT_SECONDS` (5 min) on a plain `subprocess.run()`. A new diff --git a/archive.py b/archive.py index e4344d7..65efed8 100644 --- a/archive.py +++ b/archive.py @@ -953,19 +953,30 @@ def decode_blonde(blonde): # # HTAR_STALL_SECONDS bounds how long a CREATE call (and any other stall-watched call # that has no bound of its own) may go without any new stdout/stderr before it's killed -# as a hung HPSS connection (see _run_with_stall_watch). Generous relative to any -# per-file gap observed in practice for a create, which streams per-file progress -# continuously. +# as a hung HPSS connection (see _run_with_stall_watch), ONCE it has started streaming +# per-file progress. Generous relative to any per-file gap observed in practice for a +# create that is actually moving bytes. # -# The post-create round-trip VERIFY RETRIEVE is bounded separately, by the config's -# `retrieve_stall_seconds` (default in stall_defaults.json, threaded into ship_object) -# — 2 hours is wrong there. A retrieve is silent BY DESIGN while HPSS queues and -# stages the tape, so on a large routed shard this bound was killing a healthy -# retrieve: 2026-08-03, repository_X1D_3_metabolomics_rawspectra (one 6,624,961,024-byte -# shard) was killed at exactly the 2h bound on both attempts, and its own stall log -# shows "activity resumed after 7200.1s silence" — 0.1s past the kill line. Verify -# never passed, so no success record was written and every scheduled run re-shipped -# the whole shard: 48 identical 6.62 GB tars (~318 GB of tape) over 2026-07-17..08-03. +# The post-create round-trip VERIFY RETRIEVE is bounded separately for its ENTIRE +# duration, by the config's `retrieve_stall_seconds` (default in stall_defaults.json, +# threaded into both ship_object and send_to_fortress) — 2 hours is wrong there. A +# retrieve is silent BY DESIGN while HPSS queues and stages the tape, so on a large +# routed shard this bound was killing a healthy retrieve: 2026-08-03, +# repository_X1D_3_metabolomics_rawspectra (one 6,624,961,024-byte shard) was killed at +# exactly the 2h bound on both attempts, and its own stall log shows "activity resumed +# after 7200.1s silence" — 0.1s past the kill line. Verify never passed, so no success +# record was written and every scheduled run re-shipped the whole shard: 48 identical +# 6.62 GB tars (~318 GB of tape) over 2026-07-17..08-03. +# +# A create's INITIAL silence — before it has EVER produced output — is ALSO now bounded +# by `retrieve_stall_seconds` rather than this constant (via `initial_stall_seconds` on +# both stall-watch functions): starting 2026-07-31 (a Duke Power outage took Fortress +# offline 07-30/31), creates began legitimately queueing at HPSS for over an hour with +# zero output before transfer starts — confirmed live on repository_X0E_2_spectral-standoff +# (job 41943831, 2026-08-12): silent for 4260.7s (71 min), then resumed and completed +# normally. Once a create HAS produced its first byte, the bound tightens right back to +# HTAR_STALL_SECONDS below — a genuine mid-transfer hang (the original 32h incident) is +# still caught fast; only the "waiting for HPSS to start" phase got the bigger budget. HTAR_STALL_SECONDS = 2 * 60 * 60 # 2 hours # mkdir / ls existence checks return in seconds to low minutes when healthy and carry @@ -997,13 +1008,31 @@ def decode_blonde(blonde): def _run_with_stall_watch(cmd, *, cwd=None, watch_paths=None, - stall_seconds=HTAR_STALL_SECONDS, poll_interval=30, + stall_seconds=HTAR_STALL_SECONDS, + initial_stall_seconds=None, poll_interval=30, activity_log=None): """ Run cmd via Popen, killing it and raising RuntimeError if it goes stall_seconds without producing new output. See HTAR_STALL_SECONDS above for why this watches for silence rather than enforcing a flat overall timeout. + initial_stall_seconds (default None -> same as stall_seconds, exactly today's + behavior): a SEPARATE, typically larger silence budget that applies ONLY before + the very first byte of output/growth is observed. Once ANY activity has been + seen, the bound tightens to stall_seconds for the rest of the call. This exists + because a create can now legitimately sit queued at HPSS for well over an hour + before transferring a single byte (2026-07-31 onward, post Duke-Power-outage + degraded Fortress capacity — confirmed via stall logs showing "activity resumed + after ~4260s silence" on a create that then completed normally), the same + "HPSS queues and stages" phenomenon that justified giving the round-trip verify + retrieve its own larger `retrieve_stall_seconds` budget. But unlike retrieve, + a create that HAS started streaming is not expected to go silent again — once + per-file progress begins, further silence really is a hang (HTAR_STALL_SECONDS' + original 32h-hang rationale still holds for that phase). Passing only + stall_seconds (the default) preserves the original single-bound behavior + exactly — every existing caller that doesn't pass initial_stall_seconds sees no + change. + Two activity-detection modes, picked by whether the caller wants output captured or the shell command redirects its own output to files: @@ -1041,7 +1070,8 @@ def _run_with_stall_watch(cmd, *, cwd=None, watch_paths=None, import time import os - concern_seconds = stall_seconds / 2.0 + initial_stall_seconds = (stall_seconds if initial_stall_seconds is None + else initial_stall_seconds) def _log(msg): if not activity_log: @@ -1059,11 +1089,14 @@ def _log(msg): stdout=subprocess.PIPE, stderr=subprocess.STDOUT) chunks = [] last_activity = time.monotonic() + seen_any_activity = False fd = proc.stdout.fileno() try: while True: + limit = stall_seconds if seen_any_activity else initial_stall_seconds + concern_seconds = limit / 2.0 readable, _, _ = select.select([fd], [], [], - min(poll_interval, stall_seconds)) + min(poll_interval, limit)) if readable: data = os.read(fd, 65536) if data: @@ -1073,6 +1106,7 @@ def _log(msg): _log(f"activity resumed after {gap:.1f}s silence " f"(+{len(data)} bytes)") last_activity = now + seen_any_activity = True chunks.append(data) continue proc.wait() @@ -1082,8 +1116,9 @@ def _log(msg): elapsed = time.monotonic() - last_activity if elapsed > concern_seconds: _log(f"poll: {elapsed:.1f}s since last activity " - f"(stall limit {stall_seconds:.0f}s)") - if elapsed > stall_seconds: + f"(stall limit {limit:.0f}s" + f"{'' if seen_any_activity else ', initial/queueing phase'})") + if elapsed > limit: proc.terminate() try: proc.wait(timeout=10) @@ -1092,9 +1127,11 @@ def _log(msg): proc.wait(timeout=10) _log(f"STALL DETECTED after {elapsed:.1f}s silence — " f"killed pid={proc.pid}") + phase = ("initial connection/queueing wait" + if not seen_any_activity else "mid-transfer") raise RuntimeError( f"command stalled — no output for " - f"{stall_seconds / 3600:.1f}h (HPSS connection likely " + f"{limit / 3600:.1f}h ({phase}; HPSS connection likely " f"hung), pid={proc.pid} killed. cmd={cmd!r}") finally: proc.stdout.close() @@ -1103,28 +1140,48 @@ def _log(msg): proc = subprocess.Popen(cmd, cwd=cwd, shell=True) last_activity = time.monotonic() last_sizes = {} + seen_any_activity = False while True: + limit = stall_seconds if seen_any_activity else initial_stall_seconds + concern_seconds = limit / 2.0 for p in watch_paths: try: sz = os.path.getsize(p) except OSError: continue - if last_sizes.get(p) != sz: - now = time.monotonic() - gap = now - last_activity - if gap > concern_seconds: - _log(f"activity resumed after {gap:.1f}s silence " - f"({p} grew to {sz} bytes)") + first_sighting = p not in last_sizes + if first_sighting: + # The shell creates/truncates a redirect target immediately on + # startup, so the FIRST observation of a watched path is almost + # always a fresh, still-empty file within milliseconds of Popen — + # that must not itself count as "activity" (it would flip + # seen_any_activity before any real work happens, defeating the + # whole two-phase design). Only real pre-existing content (sz > 0, + # e.g. a slow first loop pass that already caught genuine output) + # counts here; establish the baseline either way. last_sizes[p] = sz - last_activity = now + if sz == 0: + continue + elif last_sizes[p] == sz: + continue + else: + last_sizes[p] = sz + now = time.monotonic() + gap = now - last_activity + if gap > concern_seconds: + _log(f"activity resumed after {gap:.1f}s silence " + f"({p} grew to {sz} bytes)") + last_activity = now + seen_any_activity = True rc = proc.poll() if rc is not None: return subprocess.CompletedProcess(cmd, rc) elapsed = time.monotonic() - last_activity if elapsed > concern_seconds: _log(f"poll: {elapsed:.1f}s since last activity " - f"(stall limit {stall_seconds:.0f}s)") - if elapsed > stall_seconds: + f"(stall limit {limit:.0f}s" + f"{'' if seen_any_activity else ', initial/queueing phase'})") + if elapsed > limit: proc.terminate() try: proc.wait(timeout=10) @@ -1132,10 +1189,13 @@ def _log(msg): proc.kill() proc.wait(timeout=10) _log(f"STALL DETECTED after {elapsed:.1f}s silence — killed pid={proc.pid}") + phase = ("initial connection/queueing wait" + if not seen_any_activity else "mid-transfer") raise RuntimeError( - f"command stalled — no output for {stall_seconds / 3600:.1f}h " - f"(HPSS connection likely hung), pid={proc.pid} killed. cmd={cmd!r}") - time.sleep(min(poll_interval, stall_seconds)) + f"command stalled — no output for {limit / 3600:.1f}h " + f"({phase}; HPSS connection likely hung), pid={proc.pid} killed. " + f"cmd={cmd!r}") + time.sleep(min(poll_interval, limit)) class VerifyStallError(RuntimeError): @@ -3060,8 +3120,13 @@ def send_to_fortress(zip_path, zip_checksum, file_checksums, members, HTAR_STALL_SECONDS) — confirmed hit here too on repository_X0H_2_spectral-standoff (job 41417829, 2026-07-31): create succeeded, then the round-trip retrieve was killed at exactly "no output for 2.0h". The create - call keeps the hardcoded 7200s default: a create streams per-file progress, so - silence there really is a hang. + call's OWN INITIAL silence (before it has ever produced output) also now uses this + same retrieve_stall_seconds budget, passed as run_watched()'s initial_stall_seconds + — HPSS can legitimately queue a create for over an hour before moving a byte + (confirmed 2026-08-12, repository_X0E_2_spectral-standoff). Once the create HAS + started streaming per-file progress, the bound tightens back to the hardcoded + 7200s default for the rest of that call: a create actually moving bytes going + silent again really is a hang. extra_record_fields: optional dict merged into run_record at construction (default None is behavior-neutral for the existing whole-target caller). @@ -3264,8 +3329,8 @@ def notify_bell(subject, body): write_log(f"Teams bell not delivered ({type(e).__name__}); email still sent.", level="WARNING") - def run_watched(cmd, watch_paths, stall_seconds=7200, poll_interval=30, - activity_log=None): + def run_watched(cmd, watch_paths, stall_seconds=7200, initial_stall_seconds=None, + poll_interval=30, activity_log=None): """ Inline, Compute-safe twin of the module-level _run_with_stall_watch()'s file-growth mode: kills `cmd` (a shell string that redirects its own @@ -3279,20 +3344,31 @@ def run_watched(cmd, watch_paths, stall_seconds=7200, poll_interval=30, mirrors the module-level HTAR_STALL_SECONDS constant — kept in sync by inspection, same as the notify_bell twin. + initial_stall_seconds (default None -> same as stall_seconds): a separate, + typically larger silence budget that applies ONLY before the first byte of + activity is observed; once any growth has been seen, the bound tightens to + stall_seconds for the rest of the call. Mirrors the module-level twin's + parameter of the same name — see that docstring for the full rationale + (2026-07-31 onward: creates can now legitimately queue at HPSS for over an + hour before transferring a byte). The retrieve call sites here pass a single + value for both (matching retrieve_stall_seconds' existing "silent by design + for the whole call" semantics); only the create call site distinguishes them. + activity_log: same semantics as the module-level twin's — quiet until - silence passes half of stall_seconds, then one durable, timestamped line per - growth event/poll, so a stall that outlives stall_seconds without being - killed leaves a forensic trail instead of requiring a live strace/py-spy - capture to explain (2026-07-20 stall investigation: job 40937735 ran ~30min - past the 2.0h bound with no way, after the fact, to tell whether that was a - last-second activity reset or a real mechanism gap). Kept in sync with the - module-level twin's activity_log behavior. + silence passes half of the CURRENT phase's limit, then one durable, + timestamped line per growth event/poll, so a stall that outlives its limit + without being killed leaves a forensic trail instead of requiring a live + strace/py-spy capture to explain (2026-07-20 stall investigation: job + 40937735 ran ~30min past the 2.0h bound with no way, after the fact, to tell + whether that was a last-second activity reset or a real mechanism gap). + Kept in sync with the module-level twin's activity_log behavior. """ import subprocess import time import os - concern_seconds = stall_seconds / 2.0 + initial_stall_seconds = (stall_seconds if initial_stall_seconds is None + else initial_stall_seconds) def _log(msg): if not activity_log: @@ -3306,28 +3382,48 @@ def _log(msg): proc = subprocess.Popen(cmd, shell=True) last_activity = time.monotonic() last_sizes = {} + seen_any_activity = False while True: + limit = stall_seconds if seen_any_activity else initial_stall_seconds + concern_seconds = limit / 2.0 for p in watch_paths: try: sz = os.path.getsize(p) except OSError: continue - if last_sizes.get(p) != sz: - now = time.monotonic() - gap = now - last_activity - if gap > concern_seconds: - _log(f"activity resumed after {gap:.1f}s silence " - f"({p} grew to {sz} bytes)") + first_sighting = p not in last_sizes + if first_sighting: + # The shell creates/truncates a redirect target immediately on + # startup, so the FIRST observation of a watched path is almost + # always a fresh, still-empty file within milliseconds of + # Popen — that must not itself count as "activity" (it would + # flip seen_any_activity before any real work happens, + # defeating the whole two-phase design). Only real + # pre-existing content (sz > 0) counts here; establish the + # baseline either way. + last_sizes[p] = sz + if sz == 0: + continue + elif last_sizes[p] == sz: + continue + else: last_sizes[p] = sz - last_activity = now + now = time.monotonic() + gap = now - last_activity + if gap > concern_seconds: + _log(f"activity resumed after {gap:.1f}s silence " + f"({p} grew to {sz} bytes)") + last_activity = now + seen_any_activity = True rc = proc.poll() if rc is not None: return subprocess.CompletedProcess(cmd, rc) elapsed = time.monotonic() - last_activity if elapsed > concern_seconds: _log(f"poll: {elapsed:.1f}s since last activity " - f"(stall limit {stall_seconds:.0f}s)") - if elapsed > stall_seconds: + f"(stall limit {limit:.0f}s" + f"{'' if seen_any_activity else ', initial/queueing phase'})") + if elapsed > limit: proc.terminate() try: proc.wait(timeout=10) @@ -3336,11 +3432,13 @@ def _log(msg): proc.wait(timeout=10) _log(f"STALL DETECTED after {elapsed:.1f}s silence — " f"killed pid={proc.pid}") + phase = ("initial connection/queueing wait" + if not seen_any_activity else "mid-transfer") raise RuntimeError( - f"command stalled — no output for {stall_seconds / 3600:.1f}h " - f"(HPSS connection likely hung), pid={proc.pid} killed. " - f"cmd={cmd!r}") - time.sleep(min(poll_interval, stall_seconds)) + f"command stalled — no output for {limit / 3600:.1f}h " + f"({phase}; HPSS connection likely hung), pid={proc.pid} " + f"killed. cmd={cmd!r}") + time.sleep(min(poll_interval, limit)) def run_callable_watched(fn, stall_seconds=7200, poll_interval=30, activity_log=None): @@ -3493,7 +3591,13 @@ def worker(): cmd = (f'cd {src_dir} && htar_large -cvf {fortress_tar} {filename} ' f'>{stdout_log} 2>{stderr_log}') try: + # initial_stall_seconds=retrieve_stall_seconds: HPSS can now legitimately + # queue a create for well over an hour before moving a byte (2026-07-31 + # onward, post Duke-Power-outage degraded capacity — see HTAR_STALL_SECONDS). + # Once transfer actually starts, silence tightens back to the 2h default — + # a genuine mid-transfer hang is still caught fast. result = run_watched(cmd, [stdout_log, stderr_log], + initial_stall_seconds=retrieve_stall_seconds, activity_log=os.path.join(log_dir, f"{zip_ts}.create.stall.log")) except RuntimeError as e: write_log(f"htar_large transfer stalled: {e}", level="ERROR") @@ -3907,13 +4011,18 @@ def ship_object(source_folder, arcnames, object_stem, catalog, fortress_base_dir verify _lg: hsi get -> ; tar xf ; md5 retrieve_stall_seconds is REQUIRED (no code-side default): the silence budget for - the round-trip verify retrieve only, threaded down from the config + the round-trip verify retrieve's ENTIRE duration, threaded down from the config (`retrieve_stall_seconds`, whose own default lives in stall_defaults.json). Passing None raises rather than quietly reinstating the create-side HTAR_STALL_SECONDS, which is far too tight for a large shard's tape stage — the exact regression that burned ~318 GB of duplicate tape on repository_X1D_3_metabolomics_rawspectra (see - HTAR_STALL_SECONDS). The create call keeps HTAR_STALL_SECONDS: a create streams - per-file progress, so silence there really is a hang. + HTAR_STALL_SECONDS). The same value ALSO bounds the create call's own INITIAL + silence (before it has ever produced output), passed as + _run_with_stall_watch()'s initial_stall_seconds — HPSS can legitimately queue a + create for over an hour before moving a byte (confirmed 2026-08-12, + repository_X0E_2_spectral-standoff). Once the create HAS started streaming + per-file progress, the bound tightens back to HTAR_STALL_SECONDS for the rest of + that call: a create actually moving bytes going silent again really is a hang. """ import os import re @@ -3983,8 +4092,14 @@ def ship_object(source_folder, arcnames, object_stem, catalog, fortress_base_dir idx = fortress_tar + ".idx" else: # htar_large — a single >=64 GiB member; pass the path directly cmd = ["htar_large", "-cvf", fortress_tar] + arcnames + # initial_stall_seconds=retrieve_stall_seconds: HPSS can now legitimately + # queue a create for well over an hour before moving a byte (2026-07-31 + # onward, post Duke-Power-outage degraded capacity — see HTAR_STALL_SECONDS). + # Once transfer actually starts, silence tightens back to the 2h default — + # a genuine mid-transfer hang is still caught fast. create = _run_with_stall_watch( cmd, cwd=source_folder, + initial_stall_seconds=retrieve_stall_seconds, activity_log=os.path.join(log_dir, f"{run_timestamp}.create.stall.log")) create_stdout = create.stdout.decode("utf-8", "replace") diff --git a/config.example.json b/config.example.json index 5c12a32..0047396 100644 --- a/config.example.json +++ b/config.example.json @@ -35,7 +35,7 @@ "comment_exclude_optional": "Optional (default []). Per-asset opt-out list of Tier-2 (OPTIONAL) rule ids from the exclude_spec (e.g. omics provenance/QC: aux_info, fastp, checksums). Honored only if this asset's file_pattern also ships the raw inputs those artifacts are regenerable from. Omit to back up all OPTIONAL artifacts (safe default).", "exclude_optional": [], - "comment_retrieve_stall_seconds": "Optional override (default: stall_defaults.json's retrieve_stall_seconds, currently 21600 = 6h). How long the post-create round-trip VERIFY RETRIEVE may go without producing any output before it is killed as a hung HPSS connection — applies whichever transport this target ships through (whole-target/leveled-incremental via send_to_fortress, or size-routed objects via ship_object; see stall_defaults.json). Much larger than the create-side bound on purpose: a retrieve is silent while HPSS queues and stages the tape, and a too-tight bound kills a healthy retrieve — which, because verify never passes, makes the next run re-ship the whole object (the 2026-08 X1D shard loop and the X0H whole-target loop; see stall_defaults.json). Raise it for a target whose tape-stage latency is legitimately longer (e.g. a much larger whole-target tar).", + "comment_retrieve_stall_seconds": "Optional override (default: stall_defaults.json's retrieve_stall_seconds, currently 21600 = 6h). How long HPSS may go without producing any output before it is killed as a hung connection — applies whichever transport this target ships through (whole-target/leveled-incremental via send_to_fortress, or size-routed objects via ship_object; see stall_defaults.json), for TWO phases: (1) the ENTIRE post-create round-trip VERIFY RETRIEVE, and (2) a CREATE's INITIAL silence before it has produced any output at all (once a create starts streaming per-file progress, the tighter create-side bound applies instead — see stall_defaults.json). Much larger than that create-side bound on purpose: HPSS is silent while it queues/stages the tape, and a too-tight bound kills a healthy transfer — which, because verify never passes, makes the next run re-ship the whole object (the 2026-08 X1D shard loop, the X0H whole-target loop, and the 2026-07-31-onward create-queueing pattern; see stall_defaults.json). Raise it for a target whose tape-stage latency is legitimately longer (e.g. a much larger whole-target tar).", "retrieve_stall_seconds": 21600, "comment_size_routing": "Optional (default false). Phase-2 size-routing (docs/RFC_incremental_v2.md §2): instead of one whole-target tar, ship each file >= t_small as its own 'solo' object and bundle smaller files into content-addressed 'shards' (shard = hash(relpath) mod K). Unchanged objects skip, so a GROWING target ships only its new files (the append win). LOCAL mode only — refused under --globus. When true, log_dir MUST be shared+durable (a Depot logs dir), NOT home or scratch: the per-target manifest lives at {log_dir}/_vault/ and reclaim must find it. Omit for the default whole-target behavior.", diff --git a/stall_defaults.json b/stall_defaults.json index a7b1762..eded68c 100644 --- a/stall_defaults.json +++ b/stall_defaults.json @@ -1,6 +1,6 @@ { "comment": "Engine-wide stall-watch defaults. Read by archive.load_config() for EVERY config (per-asset configs may override a key by name). This file is REQUIRED: a missing/malformed/invalid file raises rather than falling back to a value hidden in code, so the operative timeout is always inspectable here.", - "comment_retrieve_stall_seconds": "How long a target's post-create round-trip verify retrieve may go without producing ANY output before it is killed as a hung HPSS connection. Shared by BOTH transport paths: ship_object's routed-object retrieve (htar -xvf, or hsi get + tar xf) and send_to_fortress's whole-target/leveled-incremental retrieve (hsi get + tar xvf) via its own self-contained inline run_watched() twin (invariant #1) — one config knob, same semantics, regardless of which path an asset ships through. Deliberately much larger than the create-side HTAR_STALL_SECONDS (2h): a create streams per-file progress continuously, so silence there really is a hang, whereas a retrieve is silent BY DESIGN while HPSS queues and stages the tape. 2026-08-03 (repository_X1D_3_metabolomics_rawspectra, a single 6,624,961,024-byte routed shard): the retrieve went quiet, was killed at exactly the 2h bound on both attempts, and its own stall log shows activity resuming 0.1s past the kill line ('activity resumed after 7200.1s silence') — legitimate tape-stage latency, misread as a hang. Verify never passed, so no success record was written and the next scheduled run re-shipped the whole shard from scratch: 48 identical 6.62 GB tars (~318 GB of duplicate tape) over 2026-07-17..08-03. The identical bug independently existed in send_to_fortress's retrieve (confirmed on repository_X0H_2_spectral-standoff, job 41417829, 2026-07-31 — a leveled-incremental, multi-TB whole-target tar, killed at exactly 'no output for 2.0h') until it was given this same fix. 6h gives ~3x margin over the one precisely-measured gap (X1D's 0.1s overrun) while staying well inside the 48h Slurm walltime even if both retrieve attempts burn their full budget; a per-asset config may raise this further for a target whose tape-stage latency is legitimately longer (e.g. a much larger whole-target tar like X0H's).", + "comment_retrieve_stall_seconds": "How long HPSS may go without producing ANY output before it is killed as a hung connection, for TWO distinct phases across both transport paths (ship_object's routed-object create/retrieve, and send_to_fortress's whole-target/leveled-incremental create/retrieve via its own self-contained inline run_watched() twin, invariant #1): (1) a post-create round-trip verify retrieve, for its ENTIRE duration, and (2) a create's INITIAL silence, before any output has ever been observed. One config knob, same 'HPSS is queueing/staging' semantics, regardless of which path or which phase. Deliberately much larger than the create-side HTAR_STALL_SECONDS (2h), which still bounds a create's silence AFTER it has started streaming per-file progress — that phase genuinely means a hang. 2026-08-03 (repository_X1D_3_metabolomics_rawspectra, a single 6,624,961,024-byte routed shard): the retrieve went quiet, was killed at exactly the 2h bound on both attempts, and its own stall log shows activity resuming 0.1s past the kill line ('activity resumed after 7200.1s silence') — legitimate tape-stage latency, misread as a hang. Verify never passed, so no success record was written and the next scheduled run re-shipped the whole shard from scratch: 48 identical 6.62 GB tars (~318 GB of duplicate tape) over 2026-07-17..08-03. The identical bug independently existed in send_to_fortress's retrieve (confirmed on repository_X0H_2_spectral-standoff, job 41417829, 2026-07-31 — a leveled-incremental, multi-TB whole-target tar, killed at exactly 'no output for 2.0h') until it was given this same fix. A SEPARATE, later-discovered gap: starting 2026-07-31 (the day of a Duke Power outage that took Fortress offline 07-30/31), CREATES also began legitimately queueing at HPSS for over an hour before moving any bytes — confirmed on repository_X0E_2_spectral-standoff (job 41943831, 2026-08-12): a create sat silent for 4260.7s (71 min) then resumed and completed normally, while other targets in the same window were genuinely killed at the unmodified 2h create bound for the same reason. Giving the create's INITIAL phase this same retrieve_stall_seconds budget (rather than raising HTAR_STALL_SECONDS itself, which would also loosen the tight, still-wanted bound on a genuine MID-transfer hang) fixes that without reopening the original 32h-hang risk. 6h gives ~3x margin over the one precisely-measured retrieve gap (X1D's 0.1s overrun) while staying well inside the 48h Slurm walltime even if both retrieve attempts burn their full budget; a per-asset config may raise this further for a target whose tape-stage latency is legitimately longer (e.g. a much larger whole-target tar like X0H's).", "retrieve_stall_seconds": 21600 } diff --git a/tests/test_retrieve_stall_config.py b/tests/test_retrieve_stall_config.py index 4df945c..d17245c 100644 --- a/tests/test_retrieve_stall_config.py +++ b/tests/test_retrieve_stall_config.py @@ -143,10 +143,10 @@ def test_missing_defaults_file_is_survivable_via_explicit_config(self): class _CapturingStallWatch: - """Wraps the real archive._run_with_stall_watch, recording the stall_seconds each - call was given (and forcing a small effective bound so tests stay fast). Drives - the REAL function — real Popen/select plumbing against the fake hsi/htar bins — - matching this suite's no-subprocess-mocking philosophy.""" + """Wraps the real archive._run_with_stall_watch, recording the stall_seconds AND + initial_stall_seconds each call was given (and forcing small effective bounds so + tests stay fast). Drives the REAL function — real Popen/select plumbing against + the fake hsi/htar bins — matching this suite's no-subprocess-mocking philosophy.""" def __init__(self, fast_seconds=0.5, poll_interval=0.05): self.real = archive._run_with_stall_watch @@ -155,10 +155,11 @@ def __init__(self, fast_seconds=0.5, poll_interval=0.05): self.seen = [] def __call__(self, cmd, *, cwd=None, watch_paths=None, stall_seconds=None, - poll_interval=None, activity_log=None): - self.seen.append((cmd, stall_seconds)) + initial_stall_seconds=None, poll_interval=None, activity_log=None): + self.seen.append((cmd, stall_seconds, initial_stall_seconds)) return self.real(cmd, cwd=cwd, watch_paths=watch_paths, stall_seconds=self.fast_seconds, + initial_stall_seconds=self.fast_seconds, poll_interval=self.poll_interval, activity_log=activity_log) @@ -195,16 +196,28 @@ def test_retrieve_calls_get_the_configured_bound_create_keeps_the_default(self): def _cmd_str(c): return " ".join(c) if isinstance(c, (list, tuple)) else str(c) - create = [s for c, s in watch.seen if _cmd_str(c).startswith("htar -P -cvf")] - retrieve = [s for c, s in watch.seen if _cmd_str(c).startswith("htar -xvf")] + create = [(s, i) for c, s, i in watch.seen + if _cmd_str(c).startswith("htar -P -cvf")] + retrieve = [(s, i) for c, s, i in watch.seen + if _cmd_str(c).startswith("htar -xvf")] self.assertTrue(create, "no create call observed") self.assertTrue(retrieve, "no retrieve call observed") - # The create keeps the module default (passed as None -> signature default). - self.assertTrue(all(s is None for s in create), - f"create must not be re-bounded: {create}") - # Every retrieve call carries the configured bound, NOT the 2h create bound. - self.assertTrue(all(s == 21600 for s in retrieve), + # The create's ONGOING (post-activity) bound stays the module default + # (passed as None -> signature default = HTAR_STALL_SECONDS), but its + # INITIAL (pre-activity) bound is now the configured retrieve_stall_seconds + # — HPSS can legitimately queue a create for over an hour before moving a + # byte (see HTAR_STALL_SECONDS). + self.assertTrue(all(s is None for s, i in create), + f"create's ongoing bound must not be re-bounded: {create}") + self.assertTrue(all(i == 21600 for s, i in create), + f"create's initial bound not threaded through: {create}") + # Every retrieve call carries the configured bound for its WHOLE duration, + # NOT the 2h create bound, and doesn't need its own separate initial bound + # (stall_seconds already covers the whole call). + self.assertTrue(all(s == 21600 for s, i in retrieve), f"retrieve bound not threaded through: {retrieve}") + self.assertTrue(all(i is None for s, i in retrieve), + f"retrieve should not pass its own initial_stall_seconds: {retrieve}") def test_absent_bound_raises_before_any_tape_work(self): """A caller that forgets the value must fail loud, and BEFORE creating a tar diff --git a/tests/test_send_to_fortress_retrieve_stall.py b/tests/test_send_to_fortress_retrieve_stall.py index 6881a4e..1faf07c 100644 --- a/tests/test_send_to_fortress_retrieve_stall.py +++ b/tests/test_send_to_fortress_retrieve_stall.py @@ -234,22 +234,53 @@ def test_tar_extract_retrieve_is_bounded_by_configured_value_not_2h_default(self self.assertTrue(any(c.startswith('tar xvf ') for c in calls), f"expected a stalled tar xvf call, got: {calls}") - def test_create_keeps_its_own_default_unaffected_by_small_retrieve_value(self): - # htar_large stays silent for longer than our tiny configured retrieve - # bound before writing anything — if create wrongly used - # retrieve_stall_seconds instead of its own hardcoded default, it would be - # killed well before the 2s mark; the correct behavior is for it to still - # be running (blocked in the create step) at 1.3s. - env = FakeFortressEnv(create_body="sleep 2; echo HTAR_SUCCESSFUL; exit 0") + def test_create_initial_silence_is_bounded_by_configured_retrieve_value(self): + # htar_large produces NOTHING at all before our tiny configured bound + # elapses — HPSS can now legitimately queue a create for well over an hour + # before moving a byte (2026-07-31 onward, post Duke-Power-outage degraded + # capacity), so this INITIAL silence is bounded by retrieve_stall_seconds, + # not the 2h create default. Correct code kills it quickly; buggy code + # (still using only the hardcoded 7200s default for create) would still be + # running. + env = FakeFortressEnv(create_body="sleep 8; exit 0") with env: - runner = _RunInThread(self._send, 1) # tiny bound — only matters if - # (incorrectly) applied to create + runner = _RunInThread(self._send, 1) + finished = runner.start_and_join(timeout=5) + calls = env.calls() + + self.assertTrue( + finished, + "send_to_fortress did not honor the small retrieve_stall_seconds for " + "create's initial silence — still running after 5s, looks like it " + "kept the hardcoded 2h default for the whole create call") + self.assertIn("error", runner.result) + self.assertIsInstance(runner.result["error"], RuntimeError) + self.assertIn("stalled", str(runner.result["error"])) + self.assertIn("initial connection/queueing wait", str(runner.result["error"])) + self.assertTrue(any(c.startswith('htar_large ') for c in calls), + f"expected a stalled htar_large create call, got: {calls}") + + def test_create_post_activity_silence_keeps_2h_default_even_with_tiny_retrieve_bound(self): + # htar_large writes SOMETHING immediately (so the initial phase — bounded by + # our tiny configured value — is already satisfied), then goes silent for + # 2s before finishing. 2s exceeds the tiny retrieve_stall_seconds (1) but is + # nowhere near the 2h post-activity default — if the post-activity phase + # wrongly kept using the small configured value instead of tightening back + # to HTAR_STALL_SECONDS, this would be killed well before the 2s mark; the + # correct behavior is for it to still be running (blocked in the create + # step, past its initial output) at 1.3s. + env = FakeFortressEnv(create_body='echo "HTAR: a probe.txt"; sleep 2; ' + 'echo "HTAR SUCCESSFUL"; exit 0') + with env: + runner = _RunInThread(self._send, 1) # tiny bound — only matters for + # the INITIAL phase, not here still_running = not runner.start_and_join(timeout=1.3) self.assertTrue( still_running, "create was already finished (and likely killed) well before its " - "own silence window elapsed — looks like it used the small " - "retrieve_stall_seconds instead of its own hardcoded default") + "own post-activity silence window elapsed — looks like it kept " + "using the small retrieve_stall_seconds after activity had " + "already started, instead of tightening back to the 2h default") # Wait for the background thread to fully finish WHILE the fake # bins/PATH are still in place (run_watched's own poll_interval, not # overridable, means detecting the create's completion can itself take diff --git a/tests/test_ship_object_retrieve_retry.py b/tests/test_ship_object_retrieve_retry.py index a051029..d0fa1c8 100644 --- a/tests/test_ship_object_retrieve_retry.py +++ b/tests/test_ship_object_retrieve_retry.py @@ -9,15 +9,17 @@ stalled...") is retried; a genuine extract failure (nonzero rc, corrupt data) is not, since retrying that would just mask a real problem. -ship_object always calls _run_with_stall_watch with its production defaults -(HTAR_STALL_SECONDS=2h, bound at function-definition time) — it never overrides -stall_seconds/poll_interval per call, unlike the direct tests in -test_stall_detection.py and test_stall_activity_log.py. To exercise the retry control -flow in well under a second, these tests wrap archive._run_with_stall_watch with a -thin adapter that forces small stall_seconds/poll_interval while still driving the -REAL function (real Popen/select/os.read plumbing, real fake htar/hsi binaries via -FakeHsiHtarEnv) — no mocking of subprocess itself, matching this suite's existing -philosophy. +ship_object's retrieve call to _run_with_stall_watch uses its production defaults +(HTAR_STALL_SECONDS=2h, bound at function-definition time, via stall_seconds= +retrieve_stall_seconds) and never overrides poll_interval; the create call now also +passes initial_stall_seconds=retrieve_stall_seconds (its own two-phase silence +budget — see HTAR_STALL_SECONDS), unrelated to the retrieve-retry behavior these +tests cover. To exercise the retry control flow in well under a second, these tests +wrap archive._run_with_stall_watch with a thin adapter that forces small +stall_seconds/initial_stall_seconds/poll_interval regardless of what's passed, while +still driving the REAL function (real Popen/select/os.read plumbing, real fake +htar/hsi binaries via FakeHsiHtarEnv) — no mocking of subprocess itself, matching +this suite's existing philosophy. """ import os import shutil @@ -43,9 +45,10 @@ def __init__(self, stall_seconds=0.5, poll_interval=0.05): self.poll_interval = poll_interval def __call__(self, cmd, *, cwd=None, watch_paths=None, stall_seconds=None, - poll_interval=None, activity_log=None): + initial_stall_seconds=None, poll_interval=None, activity_log=None): return self.real(cmd, cwd=cwd, watch_paths=watch_paths, stall_seconds=self.stall_seconds, + initial_stall_seconds=self.stall_seconds, poll_interval=self.poll_interval, activity_log=activity_log) diff --git a/tests/test_stall_detection.py b/tests/test_stall_detection.py index a6c6228..4cf2f85 100644 --- a/tests/test_stall_detection.py +++ b/tests/test_stall_detection.py @@ -93,6 +93,46 @@ def test_shell_string_command_runs_with_shell_true(self): self.assertEqual(result.returncode, 0) self.assertIn(b"from-shell-string", result.stdout) + def test_initial_silence_survives_within_the_generous_initial_budget(self): + # 2026-07-31 onward: a create can now legitimately sit silent for a while + # before HPSS starts moving bytes. A tight stall_seconds paired with a much + # more generous initial_stall_seconds must let this INITIAL gap pass, then + # apply stall_seconds once real output starts. + cmd = ["sh", "-c", "sleep 0.3; echo tick; sleep 0.05; echo tick; exit 0"] + result = archive._run_with_stall_watch(cmd, stall_seconds=0.15, + initial_stall_seconds=1.0, + poll_interval=0.05) + self.assertEqual(result.returncode, 0) + self.assertEqual(result.stdout.count(b"tick"), 2) + + def test_post_activity_silence_still_killed_at_the_tight_bound(self): + # Once real output has started, a subsequent silence must be judged + # against the TIGHT stall_seconds, not the generous initial_stall_seconds + # — a create that's already moving bytes going silent again really is a + # hang (the original 32h-incident rationale). + cmd = ["sh", "-c", "echo tick; sleep 5"] + start = time.monotonic() + with self.assertRaises(RuntimeError) as ctx: + archive._run_with_stall_watch(cmd, stall_seconds=0.2, + initial_stall_seconds=2.0, + poll_interval=0.05) + elapsed = time.monotonic() - start + self.assertIn("mid-transfer", str(ctx.exception)) + self.assertLess(elapsed, 2.0, + "should be killed near the tight 0.2s bound, not survive " + "toward the generous 2.0s initial_stall_seconds") + + def test_default_initial_stall_seconds_matches_stall_seconds(self): + # Omitting initial_stall_seconds (every pre-existing caller) must behave + # EXACTLY as before: a single bound for the whole call. + cmd = ["sh", "-c", "sleep 5"] + start = time.monotonic() + with self.assertRaises(RuntimeError) as ctx: + archive._run_with_stall_watch(cmd, stall_seconds=0.2, poll_interval=0.05) + elapsed = time.monotonic() - start + self.assertIn("initial connection/queueing wait", str(ctx.exception)) + self.assertLess(elapsed, 2.0) + class TestStallWatchFileGrowthMode(unittest.TestCase): """watch_paths=[...] — file-growth mode, used by send_to_fortress's twin.""" @@ -132,6 +172,65 @@ def test_normal_nonzero_exit_unaffected(self): with open(self.out) as fh: self.assertIn("done", fh.read()) + def test_initial_silence_survives_within_the_generous_initial_budget(self): + # 2026-07-31 onward: a create can now legitimately sit silent for a while + # before HPSS starts moving bytes. A tight stall_seconds paired with a much + # more generous initial_stall_seconds must let this INITIAL gap pass, then + # apply stall_seconds once the watched file actually starts growing. + cmd = f"sleep 0.3; echo tick >> {self.out}; sleep 0.05; echo tick >> {self.out}; exit 0" + result = archive._run_with_stall_watch(cmd, watch_paths=[self.out], + stall_seconds=0.15, + initial_stall_seconds=1.0, + poll_interval=0.05) + self.assertEqual(result.returncode, 0) + with open(self.out) as fh: + self.assertEqual(fh.read().count("tick"), 2) + + def test_post_activity_silence_still_killed_at_the_tight_bound(self): + # Once the watched file has genuinely grown, a subsequent silence must be + # judged against the TIGHT stall_seconds, not the generous + # initial_stall_seconds — a create already moving bytes going silent + # again really is a hang (the original 32h-incident rationale). + cmd = f"echo tick >> {self.out}; sleep 5" + start = time.monotonic() + with self.assertRaises(RuntimeError) as ctx: + archive._run_with_stall_watch(cmd, watch_paths=[self.out], + stall_seconds=0.2, + initial_stall_seconds=2.0, + poll_interval=0.05) + elapsed = time.monotonic() - start + self.assertIn("mid-transfer", str(ctx.exception)) + self.assertLess(elapsed, 2.0, + "should be killed near the tight 0.2s bound, not survive " + "toward the generous 2.0s initial_stall_seconds") + + def test_freshly_created_empty_file_is_not_mistaken_for_activity(self): + # Regression test: the shell's own redirect creates/truncates the watched + # file to 0 bytes essentially immediately on startup — that FIRST sighting + # of a path (going from "never seen" to "seen, size 0") must not itself + # flip seen_any_activity. If it did, a create that NEVER produces a single + # byte would be wrongly judged "already active" the instant its redirect + # file appears, silently switching it onto the generous stall_seconds + # bound instead of the tight initial_stall_seconds one — the whole + # two-phase design defeated within milliseconds of every call. Here the + # file is created but NEVER written to at all: with a small + # initial_stall_seconds and a much larger stall_seconds, the correct + # behavior is to be killed at the SMALL bound (still in the initial + # phase) rather than surviving toward the large one. + cmd = f"sleep 5 > {self.out} 2>&1" + start = time.monotonic() + with self.assertRaises(RuntimeError) as ctx: + archive._run_with_stall_watch(cmd, watch_paths=[self.out], + stall_seconds=5.0, + initial_stall_seconds=0.2, + poll_interval=0.05) + elapsed = time.monotonic() - start + self.assertIn("initial connection/queueing wait", str(ctx.exception)) + self.assertLess(elapsed, 2.0, + "should be killed near the small 0.2s initial bound — " + "surviving past it means the empty redirect file's first " + "sighting was wrongly counted as activity") + def test_watch_path_not_yet_created_is_not_activity(self): # A watched path that doesn't exist yet (e.g. hasn't been created by the # shell redirect for some reason) must not be misread as activity — absence