From b5afce3beb33358eb8c228cfc241c1fd8d6bd960 Mon Sep 17 00:00:00 2001 From: Pigbibi <20649888+Pigbibi@users.noreply.github.com> Date: Thu, 16 Jul 2026 06:12:11 +0800 Subject: [PATCH 1/2] fix: bound gateway recovery epochs Co-Authored-By: Codex --- .github/workflows/ci.yml | 8 +- scripts/recover_ib_gateway_ready.sh | 174 ++++++++++--------------- tests/test_gateway_recovery_scripts.sh | 26 ++-- 3 files changed, 87 insertions(+), 121 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 79014cc..22cd4f5 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -19,7 +19,7 @@ jobs: - name: Run shell tests run: | set -euo pipefail - bash tests/test_install_2fa_bot_watcher.sh - bash tests/test_wait_for_ib_gateway_ready.sh - bash tests/test_workflow_shared_config.sh - bash tests/test_docker_compose_ports.sh + for test_file in tests/*.sh; do + echo "== ${test_file} ==" + bash "${test_file}" + done diff --git a/scripts/recover_ib_gateway_ready.sh b/scripts/recover_ib_gateway_ready.sh index 730e2ee..f50441e 100755 --- a/scripts/recover_ib_gateway_ready.sh +++ b/scripts/recover_ib_gateway_ready.sh @@ -9,129 +9,99 @@ 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:}" +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}" cd "${repo_dir}" - mkdir -p "$(dirname "${lock_file}")" 2>/dev/null || true exec 9>"${lock_file}" -if [ "${lock_wait_seconds}" = "0" ]; then - if ! flock -n 9; then - echo "Another IB gateway recovery is already running; skipping this check." - exit 0 - fi -elif ! flock -w "${lock_wait_seconds}" 9; then - echo "Timed out waiting for IB gateway recovery lock: ${lock_file}" >&2 - exit 1 -fi - -echo "Acquired IB gateway recovery lock: ${lock_file}" +if [ "${lock_wait_seconds}" = 0 ]; then flock -n 9 || exit 0; else flock -w "${lock_wait_seconds}" 9; fi -wait_for_ready() { - local timeout_seconds="$1" - IB_GATEWAY_CONTAINER_NAME="${container_name}" \ - IB_GATEWAY_READY_TIMEOUT_SECONDS="${timeout_seconds}" \ - bash "${script_dir}/wait_for_ib_gateway_ready.sh" "${gateway_mode}" +inspect_epoch() { + local identity + identity="$(docker inspect --format '{{.Id}} {{.State.StartedAt}}' "${container_name}" 2>/dev/null)" || return 1 + read -r epoch_id epoch_started_at <<<"${identity}" + [ -n "${epoch_id}" ] && [[ "${epoch_started_at}" =~ ^[0-9]{4}-[0-9]{2}-[0-9]{2}T.*Z$ ]] } -gateway_recently_progressing_from_docker_logs() { - docker logs --since "${progress_window_seconds}s" "${container_name}" 2>&1 \ - | grep -Eiq "${progress_regex}" +assessment_lower_bound() { + local stage="$1" + python3 - "${stage}" "${epoch_started_at}" "${initial_snapshot_window_seconds}" <<'PY' +import sys +from datetime import datetime, timedelta, timezone +stage, started_at, window = sys.argv[1:] +start = datetime.fromisoformat(started_at.replace("Z", "+00:00")) +if stage == "initial": + lower = max(start, datetime.now(timezone.utc) - timedelta(seconds=int(window))) +else: + lower = start +print(lower.isoformat(timespec="microseconds").replace("+00:00", "Z")) +PY } -gateway_recently_progressing_from_file_logs() { - docker exec "${container_name}" sh -s -- "${progress_window_seconds}" "${progress_regex}" <<'SH' -set -eu - -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")" - -for log_path in /home/ibgateway/Jts/launcher.log /home/ibgateway/2fa.log; do - if [ ! -f "${log_path}" ]; then - continue - 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 +snapshot_decision() { + local stage="$1" expected_id="$2" expected_started_at="$3" lower decision + if ! inspect_epoch || [ "${epoch_id}" != "${expected_id}" ] || [ "${epoch_started_at}" != "${expected_started_at}" ]; then + echo epoch_changed; return 0 fi -done - -exit 1 -SH + lower="$(assessment_lower_bound "${stage}")" || { echo invalid; return 0; } + decision="$({ + docker logs --timestamps --since "${lower}" "${expected_id}" 2>&1 | sed 's/^/D\t/' || printf 'X\n' + docker exec "${expected_id}" sh -c ' + for p in /home/ibgateway/Jts/launcher.log /home/ibgateway/2fa.log; do + [ ! -e "$p" ] || [ -f "$p" ] || exit 42 + [ ! -f "$p" ] || tail -n 400 "$p" + done + ' | sed 's/^/F\t/' || printf 'X\n' + } | python3 -c ' +import re, sys +from datetime import datetime, timezone +lower = datetime.fromisoformat(sys.argv[1].replace("Z", "+00:00")) +terminal = re.compile(r"IBC closing because login has not completed|(?:authentication|login).*(?:timeout|timed out|failed)", re.I) +progress = re.compile(r"IBC: (Starting Gateway|Login attempt|Second Factor Authentication|Login has completed|Configuration tasks completed)|Authentication window found|Auto-fill submitted|Passed token authentication|Authentication completed|Security code:", re.I) +seen_progress = False +for raw in sys.stdin: + if raw == "X\n": print("invalid"); raise SystemExit + try: _, line = raw.split("\t", 1) + except ValueError: print("invalid"); raise SystemExit + m = re.match(r"(\d{4}-\d\d-\d\d[T ]\d\d:\d\d:\d\d)(?:[.,:](\d{1,9}))?Z?", line) + if not m: continue + stamp = datetime.fromisoformat((m.group(1).replace(" ", "T") + "." + (m.group(2) or "0") + "+00:00")) + if stamp < lower: continue + if terminal.search(line): print("terminal"); raise SystemExit + if progress.search(line): seen_progress = True +print("progress" if seen_progress else "none") +' "${lower}" +)" || decision=invalid + if ! inspect_epoch || [ "${epoch_id}" != "${expected_id}" ] || [ "${epoch_started_at}" != "${expected_started_at}" ]; then echo epoch_changed; else echo "${decision}"; fi } -gateway_recently_progressing() { - gateway_recently_progressing_from_docker_logs || gateway_recently_progressing_from_file_logs -} - -wait_for_ready_with_progress() { - local timeout_seconds="$1" - local stage="$2" - local extension=0 - - if wait_for_ready "${timeout_seconds}"; then - return 0 - fi - - while [ "${extension}" -lt "${progress_extensions}" ]; do - if ! gateway_recently_progressing; then - return 1 - fi - - 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 - return 0 - fi +wait_ready() { IB_GATEWAY_CONTAINER_NAME="$2" IB_GATEWAY_READY_TIMEOUT_SECONDS="$1" bash "${script_dir}/wait_for_ib_gateway_ready.sh" "${gateway_mode}"; } +assess_stage() { + local timeout="$1" stage="$2" reassessments=0 extension decision + while [ "$reassessments" -lt 2 ]; do + inspect_epoch || return 1 + local assessed_id="$epoch_id" assessed_started="$epoch_started_at" + CONTAINER_NAME="$assessed_id" bash "${script_dir}/ensure_2fa_bot_running.sh" + wait_ready "$timeout" "$assessed_id" && return 0 + extension=0 + while [ "$extension" -lt "$progress_extensions" ]; do + decision="$(snapshot_decision "$stage" "$assessed_id" "$assessed_started")" + case "$decision" in terminal|invalid|none) return 1;; epoch_changed) reassessments=$((reassessments+1)); continue 2;; progress) ;; esac + extension=$((extension+1)); wait_ready "$progress_wait_seconds" "$assessed_id" && return 0 + done + return 1 done - return 1 } -ensure_2fa_bot_running() { - CONTAINER_NAME="${container_name}" 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 wait_for_ready_with_progress "${initial_wait_seconds}" "initial"; then - exit 0 -fi - -echo "IB gateway API was not ready; restarting ${container_name} and retrying." >&2 -docker compose ps >&2 || true +assess_stage "$initial_wait_seconds" initial && exit 0 docker compose restart "${compose_service_name}" -ensure_2fa_bot_running - -if wait_for_ready_with_progress "${restart_wait_seconds}" "restart"; then - exit 0 -fi - -echo "IB gateway API is still not ready; recreating ${container_name} and retrying." >&2 +assess_stage "$restart_wait_seconds" restart && exit 0 docker compose up -d --force-recreate --no-build "${compose_service_name}" -ensure_2fa_bot_running - -if wait_for_ready_with_progress "${recreate_wait_seconds}" "recreate"; 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 +assess_stage "$recreate_wait_seconds" recreate && exit 0 exit 1 diff --git a/tests/test_gateway_recovery_scripts.sh b/tests/test_gateway_recovery_scripts.sh index 09f7b27..3efdebc 100644 --- a/tests/test_gateway_recovery_scripts.sh +++ b/tests/test_gateway_recovery_scripts.sh @@ -24,19 +24,17 @@ 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 'IB_GATEWAY_RECOVERY_INITIAL_SNAPSHOT_WINDOW_SECONDS:-420' "$recover_script" +grep -Fq 'assessment_lower_bound()' "$recover_script" +grep -Fq 'max(start, datetime.now(timezone.utc)' "$recover_script" +grep -Fq 'snapshot_decision()' "$recover_script" +grep -Fq 'epoch_changed' "$recover_script" +grep -Fq 'tail -n 400' "$recover_script" 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 'date -u -d' "$recover_script" +! grep -Fq 'Dismissing post-login dialog' "$recover_script" +grep -Fq 'assess_stage()' "$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" @@ -44,10 +42,8 @@ grep -Fq 'flock -w "${lock_wait_seconds}" 9' "$recover_script" grep -Fq 'compose_service_name="${IB_GATEWAY_COMPOSE_SERVICE_NAME:-ib-gateway}"' "$recover_script" 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" -ensure_count="$(grep -c 'ensure_2fa_bot_running' "$recover_script")" -test "$ensure_count" -ge 4 +grep -Fq 'IB_GATEWAY_READY_TIMEOUT_SECONDS="$1"' "$recover_script" +grep -Fq 'CONTAINER_NAME="$assessed_id" bash "${script_dir}/ensure_2fa_bot_running.sh"' "$recover_script" 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" From 07f080958e280a829ae52dc1541119246db3edec Mon Sep 17 00:00:00 2001 From: Pigbibi <20649888+Pigbibi@users.noreply.github.com> Date: Thu, 16 Jul 2026 06:19:25 +0800 Subject: [PATCH 2/2] fix: preserve nanosecond gateway epoch bounds Co-Authored-By: Codex --- scripts/recover_ib_gateway_ready.sh | 25 ++++++++++++++++++++----- tests/test_gateway_recovery_scripts.sh | 5 ++++- 2 files changed, 24 insertions(+), 6 deletions(-) diff --git a/scripts/recover_ib_gateway_ready.sh b/scripts/recover_ib_gateway_ready.sh index f50441e..aa59ddd 100755 --- a/scripts/recover_ib_gateway_ready.sh +++ b/scripts/recover_ib_gateway_ready.sh @@ -33,12 +33,21 @@ assessment_lower_bound() { import sys from datetime import datetime, timedelta, timezone stage, started_at, window = sys.argv[1:] -start = datetime.fromisoformat(started_at.replace("Z", "+00:00")) +def parse_rfc3339(value): + base, fraction = value.rstrip("Z").split(".", 1) if "." in value else (value.rstrip("Z"), "") + return (datetime.fromisoformat(base).replace(tzinfo=timezone.utc), int((fraction + "0" * 9)[:9])) + +def render(value): + moment, nanos = value + return moment.strftime("%Y-%m-%dT%H:%M:%S") + ".%09dZ" % nanos + +start = parse_rfc3339(started_at) if stage == "initial": - lower = max(start, datetime.now(timezone.utc) - timedelta(seconds=int(window))) + now = datetime.now(timezone.utc) - timedelta(seconds=int(window)) + lower = max(start, (now.replace(microsecond=0), now.microsecond * 1000)) else: lower = start -print(lower.isoformat(timespec="microseconds").replace("+00:00", "Z")) +print(render(lower)) PY } @@ -59,7 +68,13 @@ snapshot_decision() { } | python3 -c ' import re, sys from datetime import datetime, timezone -lower = datetime.fromisoformat(sys.argv[1].replace("Z", "+00:00")) +def parse_stamp(value): + match = re.fullmatch(r"(\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d)(?:\.(\d{1,9}))?Z", value) + if not match: + raise ValueError("invalid timestamp") + return (datetime.fromisoformat(match.group(1)).replace(tzinfo=timezone.utc), int(((match.group(2) or "") + "0" * 9)[:9])) + +lower = parse_stamp(sys.argv[1]) terminal = re.compile(r"IBC closing because login has not completed|(?:authentication|login).*(?:timeout|timed out|failed)", re.I) progress = re.compile(r"IBC: (Starting Gateway|Login attempt|Second Factor Authentication|Login has completed|Configuration tasks completed)|Authentication window found|Auto-fill submitted|Passed token authentication|Authentication completed|Security code:", re.I) seen_progress = False @@ -69,7 +84,7 @@ for raw in sys.stdin: except ValueError: print("invalid"); raise SystemExit m = re.match(r"(\d{4}-\d\d-\d\d[T ]\d\d:\d\d:\d\d)(?:[.,:](\d{1,9}))?Z?", line) if not m: continue - stamp = datetime.fromisoformat((m.group(1).replace(" ", "T") + "." + (m.group(2) or "0") + "+00:00")) + stamp = (datetime.fromisoformat(m.group(1).replace(" ", "T")).replace(tzinfo=timezone.utc), int(((m.group(2) or "") + "0" * 9)[:9])) if stamp < lower: continue if terminal.search(line): print("terminal"); raise SystemExit if progress.search(line): seen_progress = True diff --git a/tests/test_gateway_recovery_scripts.sh b/tests/test_gateway_recovery_scripts.sh index 3efdebc..a6af554 100644 --- a/tests/test_gateway_recovery_scripts.sh +++ b/tests/test_gateway_recovery_scripts.sh @@ -26,7 +26,10 @@ 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 'assessment_lower_bound()' "$recover_script" -grep -Fq 'max(start, datetime.now(timezone.utc)' "$recover_script" +grep -Fq 'lower = max(start, (now.replace(microsecond=0), now.microsecond * 1000))' "$recover_script" +grep -Fq 'def parse_rfc3339(value):' "$recover_script" +grep -Fq '".%09dZ" % nanos' "$recover_script" +grep -Fq 'def parse_stamp(value):' "$recover_script" grep -Fq 'snapshot_decision()' "$recover_script" grep -Fq 'epoch_changed' "$recover_script" grep -Fq 'tail -n 400' "$recover_script"