From efea8091bdbc21c40be4954ec657dc5a2ebbd74b Mon Sep 17 00:00:00 2001 From: Pigbibi <20649888+Pigbibi@users.noreply.github.com> Date: Thu, 16 Jul 2026 02:30:42 +0800 Subject: [PATCH 1/2] fix: classify gateway recovery epochs in Python Co-Authored-By: Codex --- .github/workflows/ci.yml | 3 + scripts/classify_gateway_recovery_snapshot.sh | 7 + scripts/gateway_recovery_classifier.py | 278 ++++++++++++++++++ scripts/recover_ib_gateway_ready.sh | 164 ++++++++--- tests/test_gateway_recovery_classifier.py | 159 ++++++++++ ..._gateway_recovery_classifier_invocation.sh | 35 +++ tests/test_gateway_recovery_scripts.sh | 38 ++- 7 files changed, 624 insertions(+), 60 deletions(-) create mode 100755 scripts/classify_gateway_recovery_snapshot.sh create mode 100644 scripts/gateway_recovery_classifier.py create mode 100644 tests/test_gateway_recovery_classifier.py create mode 100644 tests/test_gateway_recovery_classifier_invocation.sh diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 79014cc..a8a286a 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -21,5 +21,8 @@ jobs: set -euo pipefail bash tests/test_install_2fa_bot_watcher.sh bash tests/test_wait_for_ib_gateway_ready.sh + bash tests/test_gateway_recovery_scripts.sh + bash tests/test_gateway_recovery_classifier_invocation.sh + python3 tests/test_gateway_recovery_classifier.py bash tests/test_workflow_shared_config.sh bash tests/test_docker_compose_ports.sh diff --git a/scripts/classify_gateway_recovery_snapshot.sh b/scripts/classify_gateway_recovery_snapshot.sh new file mode 100755 index 0000000..246cc50 --- /dev/null +++ b/scripts/classify_gateway_recovery_snapshot.sh @@ -0,0 +1,7 @@ +#!/usr/bin/env bash +set -euo pipefail + +script_dir="$(cd "$(dirname "$0")" && pwd)" +classifier_python="${IB_GATEWAY_RECOVERY_CLASSIFIER_PYTHON:-python3}" + +exec "${classifier_python}" "${script_dir}/gateway_recovery_classifier.py" "$@" diff --git a/scripts/gateway_recovery_classifier.py b/scripts/gateway_recovery_classifier.py new file mode 100644 index 0000000..24e8a3a --- /dev/null +++ b/scripts/gateway_recovery_classifier.py @@ -0,0 +1,278 @@ +"""Pure, bounded classifier for one immutable IB Gateway recovery epoch snapshot.""" + +from __future__ import annotations + +import argparse +import re +import sys +from dataclasses import dataclass +from datetime import datetime, timezone +from enum import StrEnum +from typing import Iterable, TextIO + + +MAX_SNAPSHOT_EVENTS = 512 +MAX_SNAPSHOT_BYTES = 256 * 1024 +MAX_LINE_BYTES = 4096 + +DOCKER_TIMESTAMP = re.compile( + r"^(?P\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2})(?:\.(?P\d{1,9}))?Z(?:\s|$)" +) +FILE_TIMESTAMP = re.compile( + r"^(?P\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2})(?:(?P[.,:])(?P\d{1,9}))?(?:\s|$)" +) +TIMESTAMP_PREFIX = re.compile(r"^\d{4}-\d{2}-\d{2}[ T]") +PROGRESS_MARKER = re.compile( + r"IBC: (Starting Gateway|Login attempt|Second Factor Authentication|Login has completed|" + r"Configuration tasks completed|Found Gateway main window|Getting config dialog|Getting main window)|" + r"Authentication window found|Auto-fill submitted|Passed token authentication|" + r"Authentication completed|Security code:", + re.IGNORECASE, +) +AUTH_CONTEXT_MARKER = re.compile(r"login|authentication|security code|token authentication", re.IGNORECASE) +EXPLICIT_TERMINAL_MARKER = re.compile( + r"IBC closing because login has not completed|" + r"(?:authentication|login).*(?:timed out|timeout|failed)|" + r"(?:timed out|timeout|failed).*(?:authentication|login)", + re.IGNORECASE, +) +GENERIC_DISCONNECT_MARKER = re.compile(r"connection reset by peer|server disconnected", re.IGNORECASE) + + +class SnapshotError(ValueError): + """The primitive event snapshot cannot be safely classified.""" + + +class Decision(StrEnum): + READY = "ready" + TERMINAL = "terminal" + PROGRESS = "progress" + NONE = "none" + INVALID = "invalid" + + +@dataclass(frozen=True) +class Epoch: + container_id: str + started_at: str + old_container_id: str | None = None + replacement_identity: bool = False + + def __post_init__(self) -> None: + if not self.container_id: + raise SnapshotError("missing epoch container identity") + if self.replacement_identity and ( + not self.old_container_id or self.old_container_id == self.container_id + ): + raise SnapshotError("invalid replacement identity") + parse_rfc3339_nanos(self.started_at) + + @property + def started_key(self) -> tuple[datetime, int]: + return parse_rfc3339_nanos(self.started_at) + + +@dataclass(frozen=True) +class PrimitiveEvent: + source: str + container_id: str + line: str + + +@dataclass(frozen=True) +class FrozenSnapshot: + events: tuple[PrimitiveEvent, ...] + + +@dataclass(frozen=True) +class ParsedTimestamp: + key: tuple[datetime, int] + precision: str + + +def parse_rfc3339_nanos(value: str) -> tuple[datetime, int]: + match = re.fullmatch(r"(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2})(?:\.(\d{1,9}))?Z", value) + if match is None: + raise SnapshotError("invalid epoch StartedAt") + seconds = datetime.strptime(match.group(1), "%Y-%m-%dT%H:%M:%S").replace(tzinfo=timezone.utc) + return seconds, _fraction_to_nanos(match.group(2)) + + +def _fraction_to_nanos(fraction: str | None) -> int: + if fraction is None: + return 0 + return int((fraction + "0" * 9)[:9]) + + +def parse_event_timestamp(source: str, line: str) -> ParsedTimestamp | None: + if source == "docker": + match = DOCKER_TIMESTAMP.match(line) + if match is None: + return _reject_malformed_timestamp(line) + seconds = datetime.strptime(match.group("date"), "%Y-%m-%dT%H:%M:%S").replace( + tzinfo=timezone.utc + ) + return ParsedTimestamp((seconds, _fraction_to_nanos(match.group("fraction"))), "exact") + if source == "file": + match = FILE_TIMESTAMP.match(line) + if match is None: + return _reject_malformed_timestamp(line) + seconds = datetime.strptime(match.group("date"), "%Y-%m-%d %H:%M:%S").replace( + tzinfo=timezone.utc + ) + fraction = match.group("fraction") + precision = "seconds" if fraction is None else "fractional" + return ParsedTimestamp((seconds, _fraction_to_nanos(fraction)), precision) + raise SnapshotError("unknown snapshot source") + + +def _reject_malformed_timestamp(line: str) -> ParsedTimestamp | None: + if TIMESTAMP_PREFIX.match(line): + raise SnapshotError("malformed timestamp") + return None + + +def freeze_snapshot(events: Iterable[PrimitiveEvent]) -> FrozenSnapshot: + frozen: list[PrimitiveEvent] = [] + total_bytes = 0 + for event in events: + if event.source not in {"docker", "file"}: + raise SnapshotError("unknown snapshot source") + encoded_size = len(event.line.encode("utf-8", errors="replace")) + if encoded_size > MAX_LINE_BYTES: + raise SnapshotError("snapshot line exceeds limit") + total_bytes += encoded_size + if total_bytes > MAX_SNAPSHOT_BYTES: + raise SnapshotError("snapshot exceeds byte limit") + frozen.append(event) + if len(frozen) > MAX_SNAPSHOT_EVENTS: + raise SnapshotError("snapshot exceeds event limit") + return FrozenSnapshot(tuple(frozen)) + + +class RecoveryEpochMachine: + """Sticky terminal state scoped to one explicit recovery attempt.""" + + def __init__(self, epoch: Epoch) -> None: + self.epoch = epoch + self._terminal = False + + def begin_new_attempt(self, epoch: Epoch) -> None: + self.epoch = epoch + self._terminal = False + + def classify(self, snapshot: FrozenSnapshot, *, stable_ready: bool = False) -> Decision: + if stable_ready: + return Decision.READY + if self._terminal: + return Decision.TERMINAL + try: + decision = self._classify_frozen_snapshot(snapshot) + except SnapshotError: + return Decision.INVALID + if decision is Decision.TERMINAL: + self._terminal = True + return decision + + def _classify_frozen_snapshot(self, snapshot: FrozenSnapshot) -> Decision: + progress_seen = False + auth_context_seen = False + generic_disconnect_seen = False + + for event in snapshot.events: + if event.container_id == self.epoch.old_container_id: + continue + if event.container_id != self.epoch.container_id: + continue + timestamp = parse_event_timestamp(event.source, event.line) + if timestamp is None or not self._is_in_epoch(timestamp): + continue + if EXPLICIT_TERMINAL_MARKER.search(event.line): + return Decision.TERMINAL + if PROGRESS_MARKER.search(event.line): + progress_seen = True + if AUTH_CONTEXT_MARKER.search(event.line): + auth_context_seen = True + if GENERIC_DISCONNECT_MARKER.search(event.line): + generic_disconnect_seen = True + + if generic_disconnect_seen and auth_context_seen: + return Decision.TERMINAL + if progress_seen: + return Decision.PROGRESS + return Decision.NONE + + def _is_in_epoch(self, timestamp: ParsedTimestamp) -> bool: + epoch_seconds, epoch_nanos = self.epoch.started_key + event_seconds, event_nanos = timestamp.key + if event_seconds > epoch_seconds: + return True + if event_seconds < epoch_seconds: + return False + if timestamp.precision == "seconds": + # A replacement ID proves the file stream belongs to this attempt, + # but a seconds-only line cannot be ordered against StartedAt nanos. + # Include it conservatively; without that identity fail closed. + if self.epoch.replacement_identity: + return True + raise SnapshotError("ambiguous same-second file event") + return event_nanos >= epoch_nanos + + +def parse_protocol_snapshot(stream: TextIO) -> FrozenSnapshot: + events: list[PrimitiveEvent] = [] + total_bytes = 0 + protocol_line_limit = MAX_LINE_BYTES + 256 + while True: + raw_line = stream.readline(protocol_line_limit + 1) + if not raw_line: + break + if len(raw_line) > protocol_line_limit or ( + len(raw_line) == protocol_line_limit and not raw_line.endswith("\n") + ): + raise SnapshotError("snapshot protocol line exceeds limit") + line = raw_line.rstrip("\n") + if line.startswith("X\t"): + raise SnapshotError("snapshot source failed") + fields = line.split("\t", 2) + if len(fields) != 3: + raise SnapshotError("invalid snapshot protocol") + source_code, container_id, message = fields + source = {"D": "docker", "F": "file"}.get(source_code) + if source is None: + raise SnapshotError("unknown snapshot source") + encoded_size = len(message.encode("utf-8", errors="replace")) + if encoded_size > MAX_LINE_BYTES: + raise SnapshotError("snapshot line exceeds limit") + total_bytes += encoded_size + if total_bytes > MAX_SNAPSHOT_BYTES: + raise SnapshotError("snapshot exceeds byte limit") + events.append(PrimitiveEvent(source=source, container_id=container_id, line=message)) + if len(events) > MAX_SNAPSHOT_EVENTS: + raise SnapshotError("snapshot exceeds event limit") + return FrozenSnapshot(tuple(events)) + + +def main() -> int: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("--epoch-container-id", required=True) + parser.add_argument("--epoch-started-at", required=True) + parser.add_argument("--old-container-id") + parser.add_argument("--replacement-identity", action="store_true") + args = parser.parse_args() + try: + epoch = Epoch( + container_id=args.epoch_container_id, + started_at=args.epoch_started_at, + old_container_id=args.old_container_id, + replacement_identity=args.replacement_identity, + ) + snapshot = parse_protocol_snapshot(sys.stdin) + print(RecoveryEpochMachine(epoch).classify(snapshot).value) + except SnapshotError: + print(Decision.INVALID.value) + return 0 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/scripts/recover_ib_gateway_ready.sh b/scripts/recover_ib_gateway_ready.sh index 730e2ee..646d81b 100755 --- a/scripts/recover_ib_gateway_ready.sh +++ b/scripts/recover_ib_gateway_ready.sh @@ -9,14 +9,11 @@ gateway_mode="${1:-${IB_GATEWAY_MODE:-paper}}" initial_wait_seconds="${IB_GATEWAY_RECOVERY_INITIAL_WAIT_SECONDS:-240}" restart_wait_seconds="${IB_GATEWAY_RECOVERY_RESTART_WAIT_SECONDS:-300}" recreate_wait_seconds="${IB_GATEWAY_RECOVERY_RECREATE_WAIT_SECONDS:-600}" -# IBC can spend several minutes in first-run login/config flows and then -# restart itself before the API socket listens. Do not interrupt that progress. progress_wait_seconds="${IB_GATEWAY_RECOVERY_PROGRESS_WAIT_SECONDS:-420}" progress_extensions="${IB_GATEWAY_RECOVERY_PROGRESS_EXTENSIONS:-2}" -progress_window_seconds="${IB_GATEWAY_RECOVERY_PROGRESS_WINDOW_SECONDS:-420}" -progress_regex="${IB_GATEWAY_RECOVERY_PROGRESS_REGEX:-IBC: (Starting Gateway|Login attempt|Second Factor Authentication|Login has completed|Configuration tasks completed|Found Gateway main window|Getting config dialog|Getting main window)|Authentication window found|Auto-fill submitted|Dismissing post-login dialog|Passed token authentication|Authentication completed|Security code:}" lock_file="${IB_GATEWAY_RECOVERY_LOCK_FILE:-/var/lock/ib_gateway_recovery.lock}" lock_wait_seconds="${IB_GATEWAY_RECOVERY_LOCK_WAIT_SECONDS:-900}" +classifier_wrapper="${script_dir}/classify_gateway_recovery_snapshot.sh" cd "${repo_dir}" @@ -36,65 +33,112 @@ echo "Acquired IB gateway recovery lock: ${lock_file}" wait_for_ready() { local timeout_seconds="$1" - IB_GATEWAY_CONTAINER_NAME="${container_name}" \ + local epoch_container_id="$2" + + IB_GATEWAY_CONTAINER_NAME="${epoch_container_id}" \ IB_GATEWAY_READY_TIMEOUT_SECONDS="${timeout_seconds}" \ bash "${script_dir}/wait_for_ib_gateway_ready.sh" "${gateway_mode}" } -gateway_recently_progressing_from_docker_logs() { - docker logs --since "${progress_window_seconds}s" "${container_name}" 2>&1 \ - | grep -Eiq "${progress_regex}" -} - -gateway_recently_progressing_from_file_logs() { - docker exec "${container_name}" sh -s -- "${progress_window_seconds}" "${progress_regex}" <<'SH' -set -eu +inspect_epoch_identity() { + local container_ref="$1" + local identity -progress_window_seconds="$1" -progress_regex="$2" -now="$(date +%s)" -cutoff_timestamp="$(date -u -d "@$((now - progress_window_seconds))" "+%Y-%m-%d %H:%M:%S")" + identity="$(docker inspect --format '{{.Id}} {{.State.StartedAt}}' "${container_ref}" 2>/dev/null)" || return 1 + read -r epoch_container_id epoch_started_at <<<"${identity}" + [ -n "${epoch_container_id}" ] \ + && [[ "${epoch_started_at}" =~ ^[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}(\.[0-9]+)?Z$ ]] \ + && [[ "${epoch_started_at}" != 0001-01-01T00:00:00* ]] +} -for log_path in /home/ibgateway/Jts/launcher.log /home/ibgateway/2fa.log; do - if [ ! -f "${log_path}" ]; then - continue +capture_epoch_decision() { + local epoch_container_id="$1" + local epoch_started_at="$2" + local old_container_id="$3" + local replacement_identity="$4" + local -a classifier_args + local decision + + classifier_args=( + --epoch-container-id "${epoch_container_id}" + --epoch-started-at "${epoch_started_at}" + ) + if [ -n "${old_container_id}" ]; then + classifier_args+=(--old-container-id "${old_container_id}") fi - - log_mtime="$(stat -c %Y "${log_path}" 2>/dev/null || echo 0)" - if [ $((now - log_mtime)) -le "${progress_window_seconds}" ]; then - tail -n 400 "${log_path}" 2>/dev/null \ - | awk -v cutoff_timestamp="${cutoff_timestamp}" -v progress_regex="${progress_regex}" ' - substr($0, 1, 19) >= cutoff_timestamp && $0 ~ progress_regex { found = 1 } - END { exit found ? 0 : 1 } - ' && exit 0 + if [ "${replacement_identity}" = "true" ]; then + classifier_args+=(--replacement-identity) fi -done -exit 1 -SH -} + if ! decision="$({ + if ! docker logs --timestamps --since "${epoch_started_at}" "${epoch_container_id}" 2>&1 \ + | sed "s/^/D\\t${epoch_container_id}\\t/"; then + printf 'X\tdocker\n' + fi + if ! docker exec "${epoch_container_id}" sh -c ' + for log_path in /home/ibgateway/Jts/launcher.log /home/ibgateway/2fa.log; do + if [ -e "${log_path}" ] && [ ! -f "${log_path}" ]; then + exit 42 + fi + if [ -f "${log_path}" ]; then + cat "${log_path}" + fi + done + ' | sed "s/^/F\\t${epoch_container_id}\\t/"; then + printf 'X\tfile\n' + fi + } | "${classifier_wrapper}" "${classifier_args[@]}")"; then + echo "Python recovery classifier invocation failed; refusing progress extension." >&2 + echo invalid + return 0 + fi -gateway_recently_progressing() { - gateway_recently_progressing_from_docker_logs || gateway_recently_progressing_from_file_logs + case "${decision}" in + terminal|progress|none|invalid) + echo "${decision}" + ;; + *) + echo "Python recovery classifier returned an invalid decision; refusing progress extension." >&2 + echo invalid + ;; + esac } wait_for_ready_with_progress() { local timeout_seconds="$1" local stage="$2" - local extension=0 + local epoch_container_id="$3" + local epoch_started_at="$4" + local old_container_id="$5" + local replacement_identity="$6" + local extension=0 decision - if wait_for_ready "${timeout_seconds}"; then + if wait_for_ready "${timeout_seconds}" "${epoch_container_id}"; then return 0 fi - while [ "${extension}" -lt "${progress_extensions}" ]; do - if ! gateway_recently_progressing; then + # Freeze the bounded primitive event snapshot once for this attempt. Every + # extension decision below uses this immutable result and never rereads logs. + decision="$(capture_epoch_decision \ + "${epoch_container_id}" "${epoch_started_at}" "${old_container_id}" "${replacement_identity}")" + case "${decision}" in + terminal) + echo "Terminal authentication event detected in the current recovery epoch; refusing extension." >&2 return 1 - fi + ;; + invalid|none) + echo "No safe progress evidence in the current immutable recovery snapshot; refusing extension." >&2 + return 1 + ;; + progress) + ;; + esac + while [ "${extension}" -lt "${progress_extensions}" ]; do extension=$((extension + 1)) - echo "Recent IB gateway login/config progress detected after ${stage} wait; extending readiness wait (${extension}/${progress_extensions}) by ${progress_wait_seconds}s before external recovery." >&2 - if wait_for_ready "${progress_wait_seconds}"; then + echo "Immutable recovery snapshot shows login/config progress after ${stage} wait;" \ + "extending readiness wait (${extension}/${progress_extensions}) by ${progress_wait_seconds}s." >&2 + if wait_for_ready "${progress_wait_seconds}" "${epoch_container_id}"; then return 0 fi done @@ -103,35 +147,57 @@ wait_for_ready_with_progress() { } ensure_2fa_bot_running() { - CONTAINER_NAME="${container_name}" bash "${script_dir}/ensure_2fa_bot_running.sh" + local epoch_container_id="$1" + CONTAINER_NAME="${epoch_container_id}" bash "${script_dir}/ensure_2fa_bot_running.sh" } echo "Ensuring ${container_name} is running before readiness check." docker compose up -d --no-build "${compose_service_name}" -ensure_2fa_bot_running +if ! inspect_epoch_identity "${container_name}"; then + echo "Unable to establish a valid initial container identity/StartedAt." >&2 + exit 1 +fi +ensure_2fa_bot_running "${epoch_container_id}" -if wait_for_ready_with_progress "${initial_wait_seconds}" "initial"; then +if wait_for_ready_with_progress \ + "${initial_wait_seconds}" "initial" "${epoch_container_id}" "${epoch_started_at}" "" "false"; then exit 0 fi echo "IB gateway API was not ready; restarting ${container_name} and retrying." >&2 docker compose ps >&2 || true docker compose restart "${compose_service_name}" -ensure_2fa_bot_running +if ! inspect_epoch_identity "${container_name}"; then + echo "Unable to establish a valid restart container identity/StartedAt." >&2 + exit 1 +fi +ensure_2fa_bot_running "${epoch_container_id}" -if wait_for_ready_with_progress "${restart_wait_seconds}" "restart"; then +if wait_for_ready_with_progress \ + "${restart_wait_seconds}" "restart" "${epoch_container_id}" "${epoch_started_at}" "" "false"; then exit 0 fi echo "IB gateway API is still not ready; recreating ${container_name} and retrying." >&2 +old_container_id="$(docker inspect --format '{{.Id}}' "${container_name}" 2>/dev/null)" || { + echo "Unable to capture the old container identity before recreate." >&2 + exit 1 +} docker compose up -d --force-recreate --no-build "${compose_service_name}" -ensure_2fa_bot_running +if ! inspect_epoch_identity "${container_name}" \ + || [ "${epoch_container_id}" = "${old_container_id}" ]; then + echo "Unable to establish a distinct replacement container identity/StartedAt." >&2 + exit 1 +fi +ensure_2fa_bot_running "${epoch_container_id}" -if wait_for_ready_with_progress "${recreate_wait_seconds}" "recreate"; then +if wait_for_ready_with_progress \ + "${recreate_wait_seconds}" "recreate" "${epoch_container_id}" "${epoch_started_at}" \ + "${old_container_id}" "true"; then exit 0 fi echo "IB gateway API did not recover after restart/recreate." >&2 docker compose ps >&2 || true -docker logs --tail 160 "${container_name}" >&2 || true +docker logs --tail 160 "${epoch_container_id}" >&2 || true exit 1 diff --git a/tests/test_gateway_recovery_classifier.py b/tests/test_gateway_recovery_classifier.py new file mode 100644 index 0000000..fe54fa6 --- /dev/null +++ b/tests/test_gateway_recovery_classifier.py @@ -0,0 +1,159 @@ +from __future__ import annotations + +import unittest +import sys +from io import StringIO +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parents[1])) +from scripts import gateway_recovery_classifier as classifier + + +EPOCH = classifier.Epoch( + container_id="new-container", + started_at="2026-07-15T16:38:21.973425214Z", + old_container_id="old-container", + replacement_identity=True, +) + + +def event(source: str, container_id: str, line: str) -> classifier.PrimitiveEvent: + return classifier.PrimitiveEvent(source=source, container_id=container_id, line=line) + + +class GatewayRecoveryClassifierTests(unittest.TestCase): + def classify(self, events: list[classifier.PrimitiveEvent]) -> classifier.Decision: + machine = classifier.RecoveryEpochMachine(EPOCH) + return machine.classify(classifier.freeze_snapshot(events)) + + def test_old_container_events_are_ignored(self) -> None: + decision = self.classify( + [ + event( + "docker", + "old-container", + "2026-07-15T16:38:22.000000000Z IBC closing because login has not completed", + ), + event("docker", "new-container", "2026-07-15T16:38:22.000000000Z IBC: Login attempt"), + ] + ) + self.assertEqual(decision, classifier.Decision.PROGRESS) + + def test_same_second_low_precision_replacement_event_is_included(self) -> None: + decision = self.classify( + [event("file", "new-container", "2026-07-15 16:38:21 Security code:")] + ) + self.assertEqual(decision, classifier.Decision.PROGRESS) + + def test_same_second_low_precision_nonreplacement_fails_closed(self) -> None: + epoch = classifier.Epoch( + container_id="restarted-container", + started_at="2026-07-15T16:38:21.973425214Z", + replacement_identity=False, + ) + machine = classifier.RecoveryEpochMachine(epoch) + snapshot = classifier.freeze_snapshot( + [event("file", "restarted-container", "2026-07-15 16:38:21 Security code:")] + ) + self.assertEqual(machine.classify(snapshot), classifier.Decision.INVALID) + + def test_all_supported_timestamp_formats(self) -> None: + decision = self.classify( + [ + event("docker", "new-container", "2026-07-15T16:38:21.973425215Z IBC: Login attempt"), + event("file", "new-container", "2026-07-15 16:38:22.001 IBC: Login attempt"), + event("file", "new-container", "2026-07-15 16:38:22,002 IBC: Login attempt"), + event("file", "new-container", "2026-07-15 16:38:22:003 IBC: Login attempt"), + ] + ) + self.assertEqual(decision, classifier.Decision.PROGRESS) + + def test_untimestamped_is_ignored_but_malformed_fails_closed(self) -> None: + self.assertEqual( + self.classify([event("docker", "new-container", "Server disconnected")]), + classifier.Decision.NONE, + ) + self.assertEqual( + self.classify([event("file", "new-container", "2026-07-15 16:38:21: malformed")]), + classifier.Decision.INVALID, + ) + + def test_terminal_is_sticky_after_later_progress(self) -> None: + machine = classifier.RecoveryEpochMachine(EPOCH) + terminal_snapshot = classifier.freeze_snapshot( + [event("docker", "new-container", "2026-07-15T16:38:22Z IBC closing because login has not completed")] + ) + progress_snapshot = classifier.freeze_snapshot( + [event("docker", "new-container", "2026-07-15T16:38:23Z IBC: Login attempt")] + ) + self.assertEqual(machine.classify(terminal_snapshot), classifier.Decision.TERMINAL) + self.assertEqual(machine.classify(progress_snapshot), classifier.Decision.TERMINAL) + + def test_progress_then_auth_disconnect_is_terminal(self) -> None: + decision = self.classify( + [ + event("docker", "new-container", "2026-07-15T16:38:22Z Security code:"), + event("docker", "new-container", "2026-07-15T16:38:23Z Server disconnected"), + ] + ) + self.assertEqual(decision, classifier.Decision.TERMINAL) + + def test_stable_readiness_succeeds_without_classifying_logs(self) -> None: + machine = classifier.RecoveryEpochMachine(EPOCH) + terminal_snapshot = classifier.freeze_snapshot( + [event("docker", "new-container", "2026-07-15T16:38:22Z IBC closing because login has not completed")] + ) + self.assertEqual(machine.classify(terminal_snapshot, stable_ready=True), classifier.Decision.READY) + + def test_new_recovery_attempt_resets_terminal_state(self) -> None: + machine = classifier.RecoveryEpochMachine(EPOCH) + terminal_snapshot = classifier.freeze_snapshot( + [event("docker", "new-container", "2026-07-15T16:38:22Z IBC closing because login has not completed")] + ) + self.assertEqual(machine.classify(terminal_snapshot), classifier.Decision.TERMINAL) + + new_epoch = classifier.Epoch( + container_id="newer-container", + started_at="2026-07-15T16:40:00.000000000Z", + old_container_id="new-container", + replacement_identity=True, + ) + machine.begin_new_attempt(new_epoch) + progress_snapshot = classifier.freeze_snapshot( + [event("docker", "newer-container", "2026-07-15T16:40:01Z IBC: Login attempt")] + ) + self.assertEqual(machine.classify(progress_snapshot), classifier.Decision.PROGRESS) + + def test_snapshot_is_bounded_and_immutable_across_source_divergence(self) -> None: + events = [event("docker", "new-container", "2026-07-15T16:38:22Z IBC: Login attempt")] + snapshot = classifier.freeze_snapshot(events) + events.append( + event("docker", "new-container", "2026-07-15T16:38:23Z IBC closing because login has not completed") + ) + machine = classifier.RecoveryEpochMachine(EPOCH) + self.assertEqual(machine.classify(snapshot), classifier.Decision.PROGRESS) + self.assertEqual(machine.classify(snapshot), classifier.Decision.PROGRESS) + + oversized = [event("docker", "new-container", "x")] * (classifier.MAX_SNAPSHOT_EVENTS + 1) + with self.assertRaises(classifier.SnapshotError): + classifier.freeze_snapshot(oversized) + protocol = StringIO( + "".join( + "D\tnew-container\t2026-07-15T16:38:22Z IBC: Login attempt\n" + for _ in range(classifier.MAX_SNAPSHOT_EVENTS + 1) + ) + ) + with self.assertRaises(classifier.SnapshotError): + classifier.parse_protocol_snapshot(protocol) + with self.assertRaises(classifier.SnapshotError): + classifier.parse_protocol_snapshot( + StringIO("D\tnew-container\t" + "x" * (classifier.MAX_LINE_BYTES + 1)) + ) + + def test_source_failure_sentinel_is_sanitized_fail_closed(self) -> None: + with self.assertRaises(classifier.SnapshotError): + classifier.parse_protocol_snapshot(StringIO("X\\tfile\\n")) + + +if __name__ == "__main__": + unittest.main() diff --git a/tests/test_gateway_recovery_classifier_invocation.sh b/tests/test_gateway_recovery_classifier_invocation.sh new file mode 100644 index 0000000..2d5e169 --- /dev/null +++ b/tests/test_gateway_recovery_classifier_invocation.sh @@ -0,0 +1,35 @@ +#!/usr/bin/env bash +set -euo pipefail + +repo_dir="$(cd "$(dirname "$0")/.." && pwd)" +wrapper="$repo_dir/scripts/classify_gateway_recovery_snapshot.sh" + +test -x "$wrapper" + +decision="$(printf '%s\n' \ + $'D\tnew-container\t2026-07-15T16:38:22.000000000Z IBC: Login attempt' \ + | "$wrapper" \ + --epoch-container-id new-container \ + --epoch-started-at 2026-07-15T16:38:21.973425214Z \ + --old-container-id old-container \ + --replacement-identity)" +test "$decision" = progress + +tmp_dir="$(mktemp -d)" +trap 'rm -rf "$tmp_dir"' EXIT +failing_python="$tmp_dir/failing-python" +cat >"$failing_python" <<'SH' +#!/usr/bin/env bash +exit 42 +SH +chmod +x "$failing_python" + +if printf '%s\n' $'D\tnew-container\t2026-07-15T16:38:22Z IBC: Login attempt' \ + | IB_GATEWAY_RECOVERY_CLASSIFIER_PYTHON="$failing_python" "$wrapper" \ + --epoch-container-id new-container \ + --epoch-started-at 2026-07-15T16:38:21.973425214Z \ + --old-container-id old-container \ + --replacement-identity; then + echo 'Python invocation failure must propagate to recovery as fail-closed.' >&2 + exit 1 +fi diff --git a/tests/test_gateway_recovery_scripts.sh b/tests/test_gateway_recovery_scripts.sh index 09f7b27..fd852a2 100644 --- a/tests/test_gateway_recovery_scripts.sh +++ b/tests/test_gateway_recovery_scripts.sh @@ -3,12 +3,17 @@ set -euo pipefail repo_dir="$(cd "$(dirname "$0")/.." && pwd)" recover_script="$repo_dir/scripts/recover_ib_gateway_ready.sh" +classifier_script="$repo_dir/scripts/gateway_recovery_classifier.py" +classifier_wrapper="$repo_dir/scripts/classify_gateway_recovery_snapshot.sh" +ci_workflow="$repo_dir/.github/workflows/ci.yml" swap_script="$repo_dir/scripts/ensure_host_swap.sh" daily_restart_script="$repo_dir/scripts/restart_ib_gateway_daily.sh" health_watcher_script="$repo_dir/scripts/install_gateway_health_watcher.sh" unit_helper_script="$repo_dir/scripts/ibkr_gateway_units.sh" test -f "$recover_script" +test -f "$classifier_script" +test -x "$classifier_wrapper" test -f "$swap_script" test -f "$daily_restart_script" test -f "$health_watcher_script" @@ -24,19 +29,26 @@ grep -Fq 'IB_GATEWAY_RECOVERY_RESTART_WAIT_SECONDS:-300' "$recover_script" grep -Fq 'IB_GATEWAY_RECOVERY_RECREATE_WAIT_SECONDS:-600' "$recover_script" grep -Fq 'IB_GATEWAY_RECOVERY_PROGRESS_WAIT_SECONDS:-420' "$recover_script" grep -Fq 'IB_GATEWAY_RECOVERY_PROGRESS_EXTENSIONS:-2' "$recover_script" -grep -Fq 'IB_GATEWAY_RECOVERY_PROGRESS_WINDOW_SECONDS:-420' "$recover_script" -grep -Fq 'Passed token authentication' "$recover_script" -grep -Fq 'Authentication completed' "$recover_script" -grep -Fq 'gateway_recently_progressing()' "$recover_script" -grep -Fq 'gateway_recently_progressing_from_docker_logs()' "$recover_script" -grep -Fq 'gateway_recently_progressing_from_file_logs()' "$recover_script" +grep -Fq 'capture_epoch_decision()' "$recover_script" +grep -Fq 'classify_gateway_recovery_snapshot.sh' "$recover_script" +grep -Fq 'Python recovery classifier invocation failed' "$recover_script" +grep -Fq 'Immutable recovery snapshot shows login/config progress after ${stage} wait;' "$recover_script" +grep -Fq 'Freeze the bounded primitive event snapshot once for this attempt' "$recover_script" +grep -Fq "docker logs --timestamps --since \"\${epoch_started_at}\" \"\${epoch_container_id}\"" "$recover_script" +grep -Fq "docker exec \"\${epoch_container_id}\"" "$recover_script" +grep -Fq "[ -e \"\${log_path}\" ] && [ ! -f \"\${log_path}\" ]" "$recover_script" +grep -Fq "printf 'X\\tfile\\n'" "$recover_script" +expected_old_container_lookup='old_container_id="$(docker inspect --format '\''{{.Id}}'\'' "${container_name}"' +grep -Fq "$expected_old_container_lookup" "$recover_script" +grep -Fq "[ \"\${epoch_container_id}\" = \"\${old_container_id}\" ]" "$recover_script" +if grep -Fq 'IB_GATEWAY_RECOVERY_PROGRESS_WINDOW_SECONDS' "$recover_script" \ + || grep -Fq 'awk ' "$recover_script" \ + || grep -Fq 'Dismissing post-login dialog' "$recover_script"; then + exit 1 +fi grep -Fq '/home/ibgateway/Jts/launcher.log' "$recover_script" grep -Fq '/home/ibgateway/2fa.log' "$recover_script" -grep -Fq 'stat -c %Y "${log_path}"' "$recover_script" -grep -Fq 'cutoff_timestamp="$(date -u -d "@$((now - progress_window_seconds))" "+%Y-%m-%d %H:%M:%S")"' "$recover_script" -grep -Fq 'substr($0, 1, 19) >= cutoff_timestamp && $0 ~ progress_regex' "$recover_script" grep -Fq 'wait_for_ready_with_progress()' "$recover_script" -grep -Fq 'Recent IB gateway login/config progress detected' "$recover_script" grep -Fq 'IB_GATEWAY_RECOVERY_LOCK_FILE:-/var/lock/ib_gateway_recovery.lock' "$recover_script" grep -Fq 'IB_GATEWAY_RECOVERY_LOCK_WAIT_SECONDS:-900' "$recover_script" grep -Fq 'flock -n 9' "$recover_script" @@ -45,10 +57,14 @@ grep -Fq 'compose_service_name="${IB_GATEWAY_COMPOSE_SERVICE_NAME:-ib-gateway}"' grep -Fq 'docker compose restart "${compose_service_name}"' "$recover_script" grep -Fq 'docker compose up -d --force-recreate --no-build "${compose_service_name}"' "$recover_script" grep -Fq 'IB_GATEWAY_READY_TIMEOUT_SECONDS="${timeout_seconds}"' "$recover_script" -grep -Fq 'CONTAINER_NAME="${container_name}" bash "${script_dir}/ensure_2fa_bot_running.sh"' "$recover_script" +grep -Fq 'CONTAINER_NAME="${epoch_container_id}" bash "${script_dir}/ensure_2fa_bot_running.sh"' "$recover_script" ensure_count="$(grep -c 'ensure_2fa_bot_running' "$recover_script")" test "$ensure_count" -ge 4 +grep -Fq 'bash tests/test_gateway_recovery_scripts.sh' "$ci_workflow" +grep -Fq 'bash tests/test_gateway_recovery_classifier_invocation.sh' "$ci_workflow" +grep -Fq 'python3 tests/test_gateway_recovery_classifier.py' "$ci_workflow" + grep -Fq 'swap_size_mib="${IB_GATEWAY_SWAP_SIZE_MIB:-2048}"' "$swap_script" grep -Fq 'fallocate -l "${swap_size_mib}M" "${swap_file}"' "$swap_script" grep -Fq 'swapon "${swap_file}"' "$swap_script" From 2179e03ba2641cf98757c058fc725456467bf19b Mon Sep 17 00:00:00 2001 From: Pigbibi <20649888+Pigbibi@users.noreply.github.com> Date: Thu, 16 Jul 2026 03:28:02 +0800 Subject: [PATCH 2/2] fix: tighten gateway recovery epoch evaluation Co-Authored-By: Codex --- .github/workflows/ci.yml | 1 + scripts/gateway_recovery_classifier.py | 23 ++- scripts/recover_ib_gateway_ready.sh | 149 ++++++++++++------ tests/test_gateway_recovery_classifier.py | 47 +++++- .../test_gateway_recovery_runtime_contract.sh | 110 +++++++++++++ tests/test_gateway_recovery_scripts.sh | 15 +- 6 files changed, 293 insertions(+), 52 deletions(-) create mode 100755 tests/test_gateway_recovery_runtime_contract.sh diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index a8a286a..265eae6 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -23,6 +23,7 @@ jobs: bash tests/test_wait_for_ib_gateway_ready.sh bash tests/test_gateway_recovery_scripts.sh bash tests/test_gateway_recovery_classifier_invocation.sh + bash tests/test_gateway_recovery_runtime_contract.sh python3 tests/test_gateway_recovery_classifier.py bash tests/test_workflow_shared_config.sh bash tests/test_docker_compose_ports.sh diff --git a/scripts/gateway_recovery_classifier.py b/scripts/gateway_recovery_classifier.py index 24e8a3a..8b802dd 100644 --- a/scripts/gateway_recovery_classifier.py +++ b/scripts/gateway_recovery_classifier.py @@ -7,7 +7,7 @@ import sys from dataclasses import dataclass from datetime import datetime, timezone -from enum import StrEnum +from enum import Enum from typing import Iterable, TextIO @@ -37,13 +37,14 @@ re.IGNORECASE, ) GENERIC_DISCONNECT_MARKER = re.compile(r"connection reset by peer|server disconnected", re.IGNORECASE) +DISMISSAL_MARKER = re.compile(r"dismissing post-login dialog", re.IGNORECASE) class SnapshotError(ValueError): """The primitive event snapshot cannot be safely classified.""" -class Decision(StrEnum): +class Decision(str, Enum): READY = "ready" TERMINAL = "terminal" PROGRESS = "progress" @@ -55,6 +56,7 @@ class Decision(StrEnum): class Epoch: container_id: str started_at: str + event_not_before: str | None = None old_container_id: str | None = None replacement_identity: bool = False @@ -66,11 +68,17 @@ def __post_init__(self) -> None: ): raise SnapshotError("invalid replacement identity") parse_rfc3339_nanos(self.started_at) + if self.event_not_before is not None: + parse_rfc3339_nanos(self.event_not_before) @property def started_key(self) -> tuple[datetime, int]: return parse_rfc3339_nanos(self.started_at) + @property + def event_lower_bound(self) -> tuple[datetime, int]: + return parse_rfc3339_nanos(self.event_not_before or self.started_at) + @dataclass(frozen=True) class PrimitiveEvent: @@ -176,6 +184,7 @@ def classify(self, snapshot: FrozenSnapshot, *, stable_ready: bool = False) -> D def _classify_frozen_snapshot(self, snapshot: FrozenSnapshot) -> Decision: progress_seen = False + dismissal_seen = False auth_context_seen = False generic_disconnect_seen = False @@ -189,6 +198,8 @@ def _classify_frozen_snapshot(self, snapshot: FrozenSnapshot) -> Decision: continue if EXPLICIT_TERMINAL_MARKER.search(event.line): return Decision.TERMINAL + if DISMISSAL_MARKER.search(event.line): + dismissal_seen = True if PROGRESS_MARKER.search(event.line): progress_seen = True if AUTH_CONTEXT_MARKER.search(event.line): @@ -198,12 +209,16 @@ def _classify_frozen_snapshot(self, snapshot: FrozenSnapshot) -> Decision: if generic_disconnect_seen and auth_context_seen: return Decision.TERMINAL + # A dismissed dialog is ambiguous. It is only auxiliary evidence after + # an independent current-epoch auth/login progress marker is present. + if dismissal_seen and not progress_seen: + return Decision.NONE if progress_seen: return Decision.PROGRESS return Decision.NONE def _is_in_epoch(self, timestamp: ParsedTimestamp) -> bool: - epoch_seconds, epoch_nanos = self.epoch.started_key + epoch_seconds, epoch_nanos = self.epoch.event_lower_bound event_seconds, event_nanos = timestamp.key if event_seconds > epoch_seconds: return True @@ -257,6 +272,7 @@ def main() -> int: parser = argparse.ArgumentParser(description=__doc__) parser.add_argument("--epoch-container-id", required=True) parser.add_argument("--epoch-started-at", required=True) + parser.add_argument("--event-not-before") parser.add_argument("--old-container-id") parser.add_argument("--replacement-identity", action="store_true") args = parser.parse_args() @@ -264,6 +280,7 @@ def main() -> int: epoch = Epoch( container_id=args.epoch_container_id, started_at=args.epoch_started_at, + event_not_before=args.event_not_before, old_container_id=args.old_container_id, replacement_identity=args.replacement_identity, ) diff --git a/scripts/recover_ib_gateway_ready.sh b/scripts/recover_ib_gateway_ready.sh index 646d81b..6ef4d66 100755 --- a/scripts/recover_ib_gateway_ready.sh +++ b/scripts/recover_ib_gateway_ready.sh @@ -11,6 +11,7 @@ restart_wait_seconds="${IB_GATEWAY_RECOVERY_RESTART_WAIT_SECONDS:-300}" recreate_wait_seconds="${IB_GATEWAY_RECOVERY_RECREATE_WAIT_SECONDS:-600}" progress_wait_seconds="${IB_GATEWAY_RECOVERY_PROGRESS_WAIT_SECONDS:-420}" progress_extensions="${IB_GATEWAY_RECOVERY_PROGRESS_EXTENSIONS:-2}" +initial_snapshot_window_seconds="${IB_GATEWAY_RECOVERY_INITIAL_SNAPSHOT_WINDOW_SECONDS:-420}" lock_file="${IB_GATEWAY_RECOVERY_LOCK_FILE:-/var/lock/ib_gateway_recovery.lock}" lock_wait_seconds="${IB_GATEWAY_RECOVERY_LOCK_WAIT_SECONDS:-900}" classifier_wrapper="${script_dir}/classify_gateway_recovery_snapshot.sh" @@ -51,17 +52,54 @@ inspect_epoch_identity() { && [[ "${epoch_started_at}" != 0001-01-01T00:00:00* ]] } -capture_epoch_decision() { - local epoch_container_id="$1" +epoch_matches_current() { + local expected_container_id="$1" + local expected_started_at="$2" + + if ! inspect_epoch_identity "${container_name}"; then + return 1 + fi + [ "${epoch_container_id}" = "${expected_container_id}" ] \ + && [ "${epoch_started_at}" = "${expected_started_at}" ] +} + +snapshot_not_before() { + local stage="$1" local epoch_started_at="$2" - local old_container_id="$3" - local replacement_identity="$4" + + if [ "${stage}" != "initial" ]; then + echo "${epoch_started_at}" + return 0 + fi + if ! [[ "${initial_snapshot_window_seconds}" =~ ^[0-9]+$ ]]; then + return 1 + fi + date -u -d "@$(( $(date +%s) - initial_snapshot_window_seconds ))" "+%Y-%m-%dT%H:%M:%SZ" +} + +capture_epoch_decision() { + local stage="$1" + local epoch_container_id="$2" + local epoch_started_at="$3" + local old_container_id="$4" + local replacement_identity="$5" + local event_not_before local -a classifier_args local decision + if ! epoch_matches_current "${epoch_container_id}" "${epoch_started_at}"; then + echo epoch_changed + return 0 + fi + if ! event_not_before="$(snapshot_not_before "${stage}" "${epoch_started_at}")"; then + echo invalid + return 0 + fi + classifier_args=( --epoch-container-id "${epoch_container_id}" --epoch-started-at "${epoch_started_at}" + --event-not-before "${event_not_before}" ) if [ -n "${old_container_id}" ]; then classifier_args+=(--old-container-id "${old_container_id}") @@ -71,7 +109,7 @@ capture_epoch_decision() { fi if ! decision="$({ - if ! docker logs --timestamps --since "${epoch_started_at}" "${epoch_container_id}" 2>&1 \ + if ! docker logs --timestamps --since "${event_not_before}" "${epoch_container_id}" 2>&1 \ | sed "s/^/D\\t${epoch_container_id}\\t/"; then printf 'X\tdocker\n' fi @@ -81,7 +119,7 @@ capture_epoch_decision() { exit 42 fi if [ -f "${log_path}" ]; then - cat "${log_path}" + tail -n 400 "${log_path}" fi done ' | sed "s/^/F\\t${epoch_container_id}\\t/"; then @@ -93,8 +131,13 @@ capture_epoch_decision() { return 0 fi + if ! epoch_matches_current "${epoch_container_id}" "${epoch_started_at}"; then + echo epoch_changed + return 0 + fi + case "${decision}" in - terminal|progress|none|invalid) + terminal|progress|none|invalid|epoch_changed) echo "${decision}" ;; *) @@ -117,24 +160,29 @@ wait_for_ready_with_progress() { return 0 fi - # Freeze the bounded primitive event snapshot once for this attempt. Every - # extension decision below uses this immutable result and never rereads logs. - decision="$(capture_epoch_decision \ - "${epoch_container_id}" "${epoch_started_at}" "${old_container_id}" "${replacement_identity}")" - case "${decision}" in - terminal) - echo "Terminal authentication event detected in the current recovery epoch; refusing extension." >&2 - return 1 - ;; - invalid|none) - echo "No safe progress evidence in the current immutable recovery snapshot; refusing extension." >&2 - return 1 - ;; - progress) - ;; - esac - while [ "${extension}" -lt "${progress_extensions}" ]; do + # Each evaluation freezes one bounded snapshot. A later failed wait begins + # a new evaluation so fresh terminal evidence cannot be skipped. + decision="$(capture_epoch_decision \ + "${stage}" "${epoch_container_id}" "${epoch_started_at}" \ + "${old_container_id}" "${replacement_identity}")" + case "${decision}" in + terminal) + echo "Terminal authentication event detected in the current recovery epoch; refusing extension." >&2 + return 1 + ;; + epoch_changed) + echo "Container identity/StartedAt changed; discarding snapshot for a new epoch assessment." >&2 + return 2 + ;; + invalid|none) + echo "No safe progress evidence in the current immutable recovery snapshot; refusing extension." >&2 + return 1 + ;; + progress) + ;; + esac + extension=$((extension + 1)) echo "Immutable recovery snapshot shows login/config progress after ${stage} wait;" \ "extending readiness wait (${extension}/${progress_extensions}) by ${progress_wait_seconds}s." >&2 @@ -146,6 +194,36 @@ wait_for_ready_with_progress() { return 1 } +run_stage_assessment() { + local timeout_seconds="$1" + local stage="$2" + local old_container_id="$3" + local replacement_identity="$4" + local epoch_reassessments=0 result + + while [ "${epoch_reassessments}" -lt 2 ]; do + if ! inspect_epoch_identity "${container_name}"; then + echo "Unable to establish a valid ${stage} container identity/StartedAt." >&2 + return 1 + fi + ensure_2fa_bot_running "${epoch_container_id}" + if wait_for_ready_with_progress \ + "${timeout_seconds}" "${stage}" "${epoch_container_id}" "${epoch_started_at}" \ + "${old_container_id}" "${replacement_identity}"; then + return 0 + else + result=$? + fi + if [ "${result}" -ne 2 ]; then + return "${result}" + fi + epoch_reassessments=$((epoch_reassessments + 1)) + done + + echo "Container identity kept changing; refusing additional epoch assessments." >&2 + return 1 +} + ensure_2fa_bot_running() { local epoch_container_id="$1" CONTAINER_NAME="${epoch_container_id}" bash "${script_dir}/ensure_2fa_bot_running.sh" @@ -153,28 +231,14 @@ ensure_2fa_bot_running() { echo "Ensuring ${container_name} is running before readiness check." docker compose up -d --no-build "${compose_service_name}" -if ! inspect_epoch_identity "${container_name}"; then - echo "Unable to establish a valid initial container identity/StartedAt." >&2 - exit 1 -fi -ensure_2fa_bot_running "${epoch_container_id}" - -if wait_for_ready_with_progress \ - "${initial_wait_seconds}" "initial" "${epoch_container_id}" "${epoch_started_at}" "" "false"; then +if run_stage_assessment "${initial_wait_seconds}" "initial" "" "false"; then exit 0 fi echo "IB gateway API was not ready; restarting ${container_name} and retrying." >&2 docker compose ps >&2 || true docker compose restart "${compose_service_name}" -if ! inspect_epoch_identity "${container_name}"; then - echo "Unable to establish a valid restart container identity/StartedAt." >&2 - exit 1 -fi -ensure_2fa_bot_running "${epoch_container_id}" - -if wait_for_ready_with_progress \ - "${restart_wait_seconds}" "restart" "${epoch_container_id}" "${epoch_started_at}" "" "false"; then +if run_stage_assessment "${restart_wait_seconds}" "restart" "" "false"; then exit 0 fi @@ -189,11 +253,8 @@ if ! inspect_epoch_identity "${container_name}" \ echo "Unable to establish a distinct replacement container identity/StartedAt." >&2 exit 1 fi -ensure_2fa_bot_running "${epoch_container_id}" -if wait_for_ready_with_progress \ - "${recreate_wait_seconds}" "recreate" "${epoch_container_id}" "${epoch_started_at}" \ - "${old_container_id}" "true"; then +if run_stage_assessment "${recreate_wait_seconds}" "recreate" "${old_container_id}" "true"; then exit 0 fi diff --git a/tests/test_gateway_recovery_classifier.py b/tests/test_gateway_recovery_classifier.py index fe54fa6..b0e164d 100644 --- a/tests/test_gateway_recovery_classifier.py +++ b/tests/test_gateway_recovery_classifier.py @@ -1,5 +1,6 @@ from __future__ import annotations +import ast import unittest import sys from io import StringIO @@ -68,6 +69,14 @@ def test_all_supported_timestamp_formats(self) -> None: ) self.assertEqual(decision, classifier.Decision.PROGRESS) + def test_python_310_compatible_import_surface(self) -> None: + source = (Path(__file__).resolve().parents[1] / "scripts/gateway_recovery_classifier.py").read_text( + encoding="utf-8" + ) + ast.parse(source, feature_version=(3, 10)) + self.assertNotIn("StrEnum", source) + self.assertEqual(classifier.Decision.PROGRESS.value, "progress") + def test_untimestamped_is_ignored_but_malformed_fails_closed(self) -> None: self.assertEqual( self.classify([event("docker", "new-container", "Server disconnected")]), @@ -80,12 +89,16 @@ def test_untimestamped_is_ignored_but_malformed_fails_closed(self) -> None: def test_terminal_is_sticky_after_later_progress(self) -> None: machine = classifier.RecoveryEpochMachine(EPOCH) + first_progress_snapshot = classifier.freeze_snapshot( + [event("docker", "new-container", "2026-07-15T16:38:21.974Z IBC: Login attempt")] + ) terminal_snapshot = classifier.freeze_snapshot( [event("docker", "new-container", "2026-07-15T16:38:22Z IBC closing because login has not completed")] ) progress_snapshot = classifier.freeze_snapshot( [event("docker", "new-container", "2026-07-15T16:38:23Z IBC: Login attempt")] ) + self.assertEqual(machine.classify(first_progress_snapshot), classifier.Decision.PROGRESS) self.assertEqual(machine.classify(terminal_snapshot), classifier.Decision.TERMINAL) self.assertEqual(machine.classify(progress_snapshot), classifier.Decision.TERMINAL) @@ -98,6 +111,38 @@ def test_progress_then_auth_disconnect_is_terminal(self) -> None: ) self.assertEqual(decision, classifier.Decision.TERMINAL) + def test_initial_recency_window_ignores_stale_progress(self) -> None: + epoch = classifier.Epoch( + container_id="long-lived-container", + started_at="2026-07-10T00:00:00.000000000Z", + event_not_before="2026-07-15T16:38:00.000000000Z", + ) + snapshot = classifier.freeze_snapshot( + [ + event("file", "long-lived-container", "2026-07-14 16:38:22 IBC: Login attempt"), + event("file", "long-lived-container", "2026-07-15 16:38:01 IBC: Login attempt"), + ] + ) + self.assertEqual(classifier.RecoveryEpochMachine(epoch).classify(snapshot), classifier.Decision.PROGRESS) + + stale_only = classifier.freeze_snapshot( + [event("file", "long-lived-container", "2026-07-14 16:38:22 IBC: Login attempt")] + ) + self.assertEqual(classifier.RecoveryEpochMachine(epoch).classify(stale_only), classifier.Decision.NONE) + + def test_dismissal_requires_current_epoch_auth_progress(self) -> None: + dialog_only = self.classify( + [event("docker", "new-container", "2026-07-15T16:38:22Z Dismissing post-login dialog")] + ) + contextual = self.classify( + [ + event("docker", "new-container", "2026-07-15T16:38:22Z Dismissing post-login dialog"), + event("docker", "new-container", "2026-07-15T16:38:23Z Authentication completed"), + ] + ) + self.assertEqual(dialog_only, classifier.Decision.NONE) + self.assertEqual(contextual, classifier.Decision.PROGRESS) + def test_stable_readiness_succeeds_without_classifying_logs(self) -> None: machine = classifier.RecoveryEpochMachine(EPOCH) terminal_snapshot = classifier.freeze_snapshot( @@ -147,7 +192,7 @@ def test_snapshot_is_bounded_and_immutable_across_source_divergence(self) -> Non classifier.parse_protocol_snapshot(protocol) with self.assertRaises(classifier.SnapshotError): classifier.parse_protocol_snapshot( - StringIO("D\tnew-container\t" + "x" * (classifier.MAX_LINE_BYTES + 1)) + StringIO("F\tnew-container\t" + "x" * (classifier.MAX_LINE_BYTES + 1)) ) def test_source_failure_sentinel_is_sanitized_fail_closed(self) -> None: diff --git a/tests/test_gateway_recovery_runtime_contract.sh b/tests/test_gateway_recovery_runtime_contract.sh new file mode 100755 index 0000000..b1ddc64 --- /dev/null +++ b/tests/test_gateway_recovery_runtime_contract.sh @@ -0,0 +1,110 @@ +#!/bin/bash +set -euo pipefail + +repo_dir="$(cd "$(dirname "$0")/.." && pwd)" +recover_script="$repo_dir/scripts/recover_ib_gateway_ready.sh" + +run_scenario() { + local scenario="$1" + local tmp_dir output + + tmp_dir="$(mktemp -d)" + trap 'rm -rf "$tmp_dir"' RETURN + cat >"$tmp_dir/docker" <<'SH' +#!/bin/bash +set -euo pipefail + +state_dir="${MOCK_STATE_DIR:?}" +next_count() { + local name="$1" value=0 + if [ -f "$state_dir/$name" ]; then + value="$(cat "$state_dir/$name")" + fi + value=$((value + 1)) + printf '%s' "$value" >"$state_dir/$name" + printf '%s\n' "$value" +} + +case "$1" in + compose) + exit 0 + ;; + inspect) + count="$(next_count inspect)" + if [ "${MOCK_SCENARIO}" = drift ] && [ "$count" -ge 4 ]; then + printf '%s\n' 'new-container 2026-07-15T16:39:00.000000000Z' + else + printf '%s\n' 'new-container 2026-07-15T16:38:00.000000000Z' + fi + ;; + logs) + count="$(next_count logs)" + if [ "${MOCK_SCENARIO}" = terminal ] && [ "$count" -ge 2 ]; then + printf '%s\n' '2026-07-15T16:38:02.000000000Z IBC closing because login has not completed' + else + printf '%s\n' '2026-07-15T16:38:01.000000000Z IBC: Login attempt' + fi + ;; + exec) + exit 0 + ;; + *) + exit 1 + ;; +esac +SH + cat >"$tmp_dir/bash" <<'SH' +#!/bin/bash +set -euo pipefail + +case "$1" in + */wait_for_ib_gateway_ready.sh) + count_file="${MOCK_STATE_DIR:?}/wait" + count=0 + [ -f "$count_file" ] && count="$(cat "$count_file")" + count=$((count + 1)) + printf '%s' "$count" >"$count_file" + if [ "$count" -le 2 ]; then + exit 1 + fi + exit 0 + ;; + */ensure_2fa_bot_running.sh) + exit 0 + ;; + *) + exec /bin/bash "$@" + ;; +esac +SH + cat >"$tmp_dir/flock" <<'SH' +#!/bin/bash +exit 0 +SH + chmod +x "$tmp_dir/docker" "$tmp_dir/bash" "$tmp_dir/flock" + + output="$(PATH="$tmp_dir:$PATH" \ + MOCK_SCENARIO="$scenario" \ + MOCK_STATE_DIR="$tmp_dir" \ + IB_GATEWAY_RECOVERY_LOCK_FILE="$tmp_dir/recovery.lock" \ + IB_GATEWAY_RECOVERY_INITIAL_WAIT_SECONDS=0 \ + IB_GATEWAY_RECOVERY_RESTART_WAIT_SECONDS=0 \ + IB_GATEWAY_RECOVERY_RECREATE_WAIT_SECONDS=0 \ + IB_GATEWAY_RECOVERY_PROGRESS_WAIT_SECONDS=0 \ + IB_GATEWAY_RECOVERY_PROGRESS_EXTENSIONS=2 \ + bash "$recover_script" paper 2>&1)" + printf '%s\n' "$output" + + if [ "$scenario" = terminal ]; then + grep -Fq 'Terminal authentication event detected in the current recovery epoch' <<<"$output" + test "$(cat "$tmp_dir/wait")" -eq 3 + test "$(cat "$tmp_dir/logs")" -eq 2 + else + grep -Fq 'Container identity/StartedAt changed; discarding snapshot for a new epoch assessment.' <<<"$output" + test "$(cat "$tmp_dir/wait")" -eq 3 + test "$(cat "$tmp_dir/logs")" -eq 1 + fi +} + +run_scenario terminal >/dev/null +run_scenario drift >/dev/null diff --git a/tests/test_gateway_recovery_scripts.sh b/tests/test_gateway_recovery_scripts.sh index fd852a2..f0c1f3e 100644 --- a/tests/test_gateway_recovery_scripts.sh +++ b/tests/test_gateway_recovery_scripts.sh @@ -29,14 +29,20 @@ grep -Fq 'IB_GATEWAY_RECOVERY_RESTART_WAIT_SECONDS:-300' "$recover_script" grep -Fq 'IB_GATEWAY_RECOVERY_RECREATE_WAIT_SECONDS:-600' "$recover_script" grep -Fq 'IB_GATEWAY_RECOVERY_PROGRESS_WAIT_SECONDS:-420' "$recover_script" grep -Fq 'IB_GATEWAY_RECOVERY_PROGRESS_EXTENSIONS:-2' "$recover_script" +grep -Fq 'IB_GATEWAY_RECOVERY_INITIAL_SNAPSHOT_WINDOW_SECONDS:-420' "$recover_script" grep -Fq 'capture_epoch_decision()' "$recover_script" +grep -Fq 'run_stage_assessment()' "$recover_script" +grep -Fq 'epoch_matches_current()' "$recover_script" +grep -Fq 'snapshot_not_before()' "$recover_script" grep -Fq 'classify_gateway_recovery_snapshot.sh' "$recover_script" grep -Fq 'Python recovery classifier invocation failed' "$recover_script" -grep -Fq 'Immutable recovery snapshot shows login/config progress after ${stage} wait;' "$recover_script" -grep -Fq 'Freeze the bounded primitive event snapshot once for this attempt' "$recover_script" -grep -Fq "docker logs --timestamps --since \"\${epoch_started_at}\" \"\${epoch_container_id}\"" "$recover_script" +grep -Fq 'Container identity/StartedAt changed; discarding snapshot for a new epoch assessment.' "$recover_script" +grep -Fq 'Each evaluation freezes one bounded snapshot.' "$recover_script" +grep -Fq 'event_not_before="$(snapshot_not_before' "$recover_script" +grep -Fq "docker logs --timestamps --since \"\${event_not_before}\" \"\${epoch_container_id}\"" "$recover_script" grep -Fq "docker exec \"\${epoch_container_id}\"" "$recover_script" grep -Fq "[ -e \"\${log_path}\" ] && [ ! -f \"\${log_path}\" ]" "$recover_script" +grep -Fq 'tail -n 400 "${log_path}"' "$recover_script" grep -Fq "printf 'X\\tfile\\n'" "$recover_script" expected_old_container_lookup='old_container_id="$(docker inspect --format '\''{{.Id}}'\'' "${container_name}"' grep -Fq "$expected_old_container_lookup" "$recover_script" @@ -59,10 +65,11 @@ grep -Fq 'docker compose up -d --force-recreate --no-build "${compose_service_na grep -Fq 'IB_GATEWAY_READY_TIMEOUT_SECONDS="${timeout_seconds}"' "$recover_script" grep -Fq 'CONTAINER_NAME="${epoch_container_id}" bash "${script_dir}/ensure_2fa_bot_running.sh"' "$recover_script" ensure_count="$(grep -c 'ensure_2fa_bot_running' "$recover_script")" -test "$ensure_count" -ge 4 +test "$ensure_count" -ge 2 grep -Fq 'bash tests/test_gateway_recovery_scripts.sh' "$ci_workflow" grep -Fq 'bash tests/test_gateway_recovery_classifier_invocation.sh' "$ci_workflow" +grep -Fq 'bash tests/test_gateway_recovery_runtime_contract.sh' "$ci_workflow" grep -Fq 'python3 tests/test_gateway_recovery_classifier.py' "$ci_workflow" grep -Fq 'swap_size_mib="${IB_GATEWAY_SWAP_SIZE_MIB:-2048}"' "$swap_script"