From 15ad6bbe39f1a8d77d0fc81469a10b7c0edffdac Mon Sep 17 00:00:00 2001 From: Pigbibi <20649888+Pigbibi@users.noreply.github.com> Date: Thu, 16 Jul 2026 00:54:13 +0800 Subject: [PATCH 1/2] fix: bind gateway recovery epochs to replacement identity Co-Authored-By: Codex --- .github/workflows/ci.yml | 2 + 2fa_bot.py | 2 +- .../classify_ib_gateway_epoch_activity.awk | 61 +++++++ scripts/ib_gateway_container_epoch.sh | 32 ++++ scripts/recover_ib_gateway_ready.sh | 168 +++++++++++++----- tests/test_gateway_recovery_scripts.sh | 19 +- .../test_gateway_replacement_epoch_policy.sh | 124 +++++++++++++ tests/test_workflow_shared_config.sh | 3 + 8 files changed, 354 insertions(+), 57 deletions(-) create mode 100644 scripts/classify_ib_gateway_epoch_activity.awk create mode 100755 scripts/ib_gateway_container_epoch.sh create mode 100644 tests/test_gateway_replacement_epoch_policy.sh diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 79014cc..1e2e532 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -21,5 +21,7 @@ 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_replacement_epoch_policy.sh bash tests/test_workflow_shared_config.sh bash tests/test_docker_compose_ports.sh diff --git a/2fa_bot.py b/2fa_bot.py index e402027..f1b7bff 100644 --- a/2fa_bot.py +++ b/2fa_bot.py @@ -290,7 +290,7 @@ def find_dismissible_dialogs(): def dismiss_dialog(candidate): if candidate.window_id not in dismissed_dialog_windows: log.info( - "Dismissing post-login dialog (id=%s, title=%r, size=%sx%s)", + "Dismissing gateway dialog candidate (id=%s, title=%r, size=%sx%s)", candidate.window_id, candidate.title, candidate.width or "?", diff --git a/scripts/classify_ib_gateway_epoch_activity.awk b/scripts/classify_ib_gateway_epoch_activity.awk new file mode 100644 index 0000000..c4c9c2a --- /dev/null +++ b/scripts/classify_ib_gateway_epoch_activity.awk @@ -0,0 +1,61 @@ +function canonical_timestamp(value, fraction, digits) { + if (value ~ /^[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}(\.[0-9]+)?Z$/) { + sub(/Z$/, "", value) + sub(/T/, " ", value) + } else if (value !~ /^[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}(\.[0-9]+)?$/) { + return "" + } + + if (value ~ /\./) { + fraction = value + sub(/^.*\./, "", fraction) + sub(/\..*$/, "", value) + } else { + fraction = "" + } + digits = length(fraction) + if (digits > 9) { + fraction = substr(fraction, 1, 9) + } + while (length(fraction) < 9) { + fraction = fraction "0" + } + return value "." fraction +} + +BEGIN { + epoch_timestamp = canonical_timestamp(epoch_started_at) + if (epoch_timestamp == "") { + exit 2 + } +} + +{ + line_timestamp = "" + if ($0 ~ /^[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}(\.[0-9]+)?Z[[:space:]]/) { + line_timestamp = $1 + } else if ($0 ~ /^[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}(\.[0-9]+)?[[:space:]]/) { + line_timestamp = $1 " " $2 + } + + line_timestamp = canonical_timestamp(line_timestamp) + if (line_timestamp == "" || line_timestamp < epoch_timestamp) { + next + } + if ($0 ~ terminal_regex) { + terminal_found = 1 + } + if ($0 ~ progress_regex) { + progress_found = 1 + } +} + +END { + if (terminal_found) { + print "terminal" + } else if (progress_found) { + print "progress" + } else { + print "none" + } +} diff --git a/scripts/ib_gateway_container_epoch.sh b/scripts/ib_gateway_container_epoch.sh new file mode 100755 index 0000000..2fa2764 --- /dev/null +++ b/scripts/ib_gateway_container_epoch.sh @@ -0,0 +1,32 @@ +#!/usr/bin/env bash + +ib_gateway_started_at_is_valid() { + local started_at="${1:-}" + + [[ "${started_at}" =~ ^[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}(\.[0-9]+)?Z$ ]] \ + && [[ "${started_at}" != 0001-01-01T00:00:00* ]] +} + +ib_gateway_inspect_container_epoch() { + local container_ref="${1:-}" + local inspect_record container_id started_at + + [ -n "${container_ref}" ] || return 1 + inspect_record="$(docker inspect --format '{{.Id}} {{.State.StartedAt}}' "${container_ref}" 2>/dev/null)" \ + || return 1 + read -r container_id started_at <<<"${inspect_record}" + [ -n "${container_id}" ] || return 1 + ib_gateway_started_at_is_valid "${started_at}" || return 1 + printf '%s %s\n' "${container_id}" "${started_at}" +} + +ib_gateway_validate_replacement_epoch() { + local old_container_id="${1:-}" + local replacement_container_id="${2:-}" + local replacement_started_at="${3:-}" + + [ -n "${old_container_id}" ] \ + && [ -n "${replacement_container_id}" ] \ + && [ "${old_container_id}" != "${replacement_container_id}" ] \ + && ib_gateway_started_at_is_valid "${replacement_started_at}" +} diff --git a/scripts/recover_ib_gateway_ready.sh b/scripts/recover_ib_gateway_ready.sh index 730e2ee..9f8c94c 100755 --- a/scripts/recover_ib_gateway_ready.sh +++ b/scripts/recover_ib_gateway_ready.sh @@ -10,13 +10,19 @@ 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. +# restart itself before the API socket listens. Extend only within the +# replacement container epoch, and never past a terminal authentication event. 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:}" +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|Passed token authentication|Authentication completed|Security code:}" +default_terminal_regex='Connection reset by peer|Server disconnected|IBC: .*(Authentication|Login).*(timed out|timeout|failed)|IBC: .*(timed out|timeout).*(Authentication|Login)' +terminal_regex="${IB_GATEWAY_RECOVERY_TERMINAL_REGEX:-$default_terminal_regex}" lock_file="${IB_GATEWAY_RECOVERY_LOCK_FILE:-/var/lock/ib_gateway_recovery.lock}" lock_wait_seconds="${IB_GATEWAY_RECOVERY_LOCK_WAIT_SECONDS:-900}" +classifier="${script_dir}/classify_ib_gateway_epoch_activity.awk" + +# shellcheck source=ib_gateway_container_epoch.sh +source "${script_dir}/ib_gateway_container_epoch.sh" cd "${repo_dir}" @@ -36,65 +42,87 @@ 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}" +classify_epoch_activity() { + local epoch_started_at="$1" + + awk \ + -v epoch_started_at="${epoch_started_at}" \ + -v progress_regex="${progress_regex}" \ + -v terminal_regex="${terminal_regex}" \ + -f "${classifier}" } -gateway_recently_progressing_from_file_logs() { - docker exec "${container_name}" sh -s -- "${progress_window_seconds}" "${progress_regex}" <<'SH' -set -eu +gateway_epoch_activity_from_docker_logs() { + local epoch_container_id="$1" + local epoch_started_at="$2" -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")" + docker logs --timestamps --since "${epoch_started_at}" "${epoch_container_id}" 2>&1 \ + | classify_epoch_activity "${epoch_started_at}" +} -for log_path in /home/ibgateway/Jts/launcher.log /home/ibgateway/2fa.log; do - if [ ! -f "${log_path}" ]; then - continue - fi +gateway_epoch_activity_from_file_logs() { + local epoch_container_id="$1" + local epoch_started_at="$2" + + docker exec "${epoch_container_id}" sh -s <<'SH' \ + | classify_epoch_activity "${epoch_started_at}" +set -eu - 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 +for log_path in /home/ibgateway/Jts/launcher.log /home/ibgateway/2fa.log; do + if [ -f "${log_path}" ]; then + cat "${log_path}" 2>/dev/null || true fi done - -exit 1 SH } -gateway_recently_progressing() { - gateway_recently_progressing_from_docker_logs || gateway_recently_progressing_from_file_logs +gateway_epoch_activity() { + local epoch_container_id="$1" + local epoch_started_at="$2" + local docker_activity file_activity + + docker_activity="$(gateway_epoch_activity_from_docker_logs "${epoch_container_id}" "${epoch_started_at}")" + file_activity="$(gateway_epoch_activity_from_file_logs "${epoch_container_id}" "${epoch_started_at}")" + if [ "${docker_activity}" = "terminal" ] || [ "${file_activity}" = "terminal" ]; then + echo terminal + elif [ "${docker_activity}" = "progress" ] || [ "${file_activity}" = "progress" ]; then + echo progress + else + echo none + fi } 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 extension=0 activity - 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 + activity="$(gateway_epoch_activity "${epoch_container_id}" "${epoch_started_at}")" + if [ "${activity}" = "terminal" ]; then + echo "Terminal IB gateway authentication event detected during ${stage} replacement epoch; refusing to extend readiness wait." >&2 + return 1 + fi + if [ "${activity}" != "progress" ]; 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 + echo "Current replacement epoch shows IB gateway login/config progress 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}" "${epoch_container_id}"; then return 0 fi done @@ -103,35 +131,83 @@ 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" +} + +inspect_current_container() { + local inspect_record + + inspect_record="$(ib_gateway_inspect_container_epoch "${container_name}")" || { + echo "Unable to establish a valid identity/StartedAt epoch for ${container_name}." >&2 + return 1 + } + read -r epoch_container_id epoch_started_at <<<"${inspect_record}" +} + +replace_gateway_container() { + local replacement_mode="$1" + local old_container_id replacement_container_id replacement_started_at inspect_record + + old_container_id="$(docker inspect --format '{{.Id}}' "${container_name}" 2>/dev/null)" || { + echo "Unable to capture the current container identity for ${container_name}." >&2 + return 1 + } + [ -n "${old_container_id}" ] || return 1 + + docker compose stop "${compose_service_name}" + docker compose rm -f "${compose_service_name}" + if docker inspect "${old_container_id}" >/dev/null 2>&1; then + echo "Old container identity still exists after controlled removal." >&2 + return 1 + fi + + if [ "${replacement_mode}" = "recreate" ]; then + docker compose up -d --force-recreate --no-build "${compose_service_name}" + else + docker compose up -d --no-build "${compose_service_name}" + fi + + inspect_record="$(ib_gateway_inspect_container_epoch "${container_name}")" || { + echo "Unable to inspect replacement container identity/StartedAt." >&2 + return 1 + } + read -r replacement_container_id replacement_started_at <<<"${inspect_record}" + ib_gateway_validate_replacement_epoch "${old_container_id}" "${replacement_container_id}" "${replacement_started_at}" || { + echo "Replacement container identity/StartedAt validation failed closed." >&2 + return 1 + } + epoch_container_id="${replacement_container_id}" + epoch_started_at="${replacement_started_at}" } echo "Ensuring ${container_name} is running before readiness check." docker compose up -d --no-build "${compose_service_name}" -ensure_2fa_bot_running +inspect_current_container +ensure_2fa_bot_running "${epoch_container_id}" -if wait_for_ready_with_progress "${initial_wait_seconds}" "initial"; then +if wait_for_ready "${initial_wait_seconds}" "${epoch_container_id}"; then exit 0 fi -echo "IB gateway API was not ready; restarting ${container_name} and retrying." >&2 +echo "IB gateway API was not ready; replacing ${container_name} and retrying." >&2 docker compose ps >&2 || true -docker compose restart "${compose_service_name}" -ensure_2fa_bot_running +replace_gateway_container restart +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}" "replacement" "${epoch_container_id}" "${epoch_started_at}"; then exit 0 fi echo "IB gateway API is still not ready; recreating ${container_name} and retrying." >&2 -docker compose up -d --force-recreate --no-build "${compose_service_name}" -ensure_2fa_bot_running +replace_gateway_container recreate +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}"; then exit 0 fi -echo "IB gateway API did not recover after restart/recreate." >&2 +echo "IB gateway API did not recover after controlled replacements." >&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_scripts.sh b/tests/test_gateway_recovery_scripts.sh index 09f7b27..4a7be24 100644 --- a/tests/test_gateway_recovery_scripts.sh +++ b/tests/test_gateway_recovery_scripts.sh @@ -24,28 +24,27 @@ 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 'default_terminal_regex=' "$recover_script" +grep -Fq 'gateway_epoch_activity()' "$recover_script" +grep -Fq 'gateway_epoch_activity_from_docker_logs()' "$recover_script" +grep -Fq 'gateway_epoch_activity_from_file_logs()' "$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 'Terminal IB gateway authentication event detected' "$recover_script" +grep -Fq 'Current replacement epoch shows IB gateway login/config progress' "$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" 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 stop "${compose_service_name}"' "$recover_script" +grep -Fq 'docker compose rm -f "${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 diff --git a/tests/test_gateway_replacement_epoch_policy.sh b/tests/test_gateway_replacement_epoch_policy.sh new file mode 100644 index 0000000..e42678e --- /dev/null +++ b/tests/test_gateway_replacement_epoch_policy.sh @@ -0,0 +1,124 @@ +#!/usr/bin/env bash +set -euo pipefail + +repo_dir="$(cd "$(dirname "$0")/.." && pwd)" +recover_script="$repo_dir/scripts/recover_ib_gateway_ready.sh" +epoch_helpers="$repo_dir/scripts/ib_gateway_container_epoch.sh" +classifier="$repo_dir/scripts/classify_ib_gateway_epoch_activity.awk" +twofa_bot="$repo_dir/2fa_bot.py" + +test -f "$epoch_helpers" +test -f "$classifier" +# shellcheck source=/dev/null +source "$epoch_helpers" + +valid_started_at='2026-07-15T16:38:21.973425214Z' +ib_gateway_validate_replacement_epoch old-id new-id "$valid_started_at" +if ib_gateway_validate_replacement_epoch old-id '' "$valid_started_at"; then + echo 'Missing replacement ID must fail closed' >&2 + exit 1 +fi +if ib_gateway_validate_replacement_epoch '' new-id "$valid_started_at"; then + echo 'Missing old ID must fail closed' >&2 + exit 1 +fi +if ib_gateway_validate_replacement_epoch old-id old-id "$valid_started_at"; then + echo 'Same replacement ID must fail closed' >&2 + exit 1 +fi +if ib_gateway_validate_replacement_epoch old-id new-id '0001-01-01T00:00:00Z'; then + echo 'Invalid StartedAt must fail closed' >&2 + exit 1 +fi + +inspected_epoch="$({ + docker() { + test "$1" = inspect + printf '%s\n' 'new-id 2026-07-15T16:38:21.973425214Z' + } + ib_gateway_inspect_container_epoch ib-gateway +})" +test "$inspected_epoch" = 'new-id 2026-07-15T16:38:21.973425214Z' +if ( + docker() { return 1; } + ib_gateway_inspect_container_epoch ib-gateway +); then + echo 'Missing inspect result must fail closed' >&2 + exit 1 +fi +if ( + docker() { printf '%s\n' 'new-id invalid-started-at'; } + ib_gateway_inspect_container_epoch ib-gateway +); then + echo 'Invalid inspected StartedAt must fail closed' >&2 + exit 1 +fi + +default_progress_regex="$(sed -n 's/^progress_regex="${IB_GATEWAY_RECOVERY_PROGRESS_REGEX:-\(.*\)}"$/\1/p' "$recover_script")" +default_terminal_regex="$(sed -n "s/^default_terminal_regex='\\(.*\\)'$/\\1/p" "$recover_script")" +test -n "$default_progress_regex" +test -n "$default_terminal_regex" + +classify() { + local epoch_started_at="$1" + awk \ + -v epoch_started_at="$epoch_started_at" \ + -v progress_regex="$default_progress_regex" \ + -v terminal_regex="$default_terminal_regex" \ + -f "$classifier" +} + +old_shutdown_ignored="$(printf '%s\n' \ + '2026-07-15T16:38:21.900000000Z Server disconnected' \ + '2026-07-15T16:38:21.980000000Z IBC: Login attempt' \ + | classify "$valid_started_at")" +test "$old_shutdown_ignored" = 'progress' + +replacement_terminal_sticky="$(printf '%s\n' \ + '2026-07-15T16:38:21.980000000Z Connection reset by peer' \ + '2026-07-15T16:38:22.100000000Z Security code:' \ + '2026-07-15T16:38:22.200000000Z Authentication completed' \ + | classify "$valid_started_at")" +test "$replacement_terminal_sticky" = 'terminal' + +untimestamped_terminal="$(printf '%s\n' \ + 'Server disconnected' \ + '2026-07-15T16:38:22.100000000Z IBC: Login attempt' \ + | classify "$valid_started_at")" +test "$untimestamped_terminal" = 'progress' + +grep -Fq 'replace_gateway_container()' "$recover_script" +grep -Fq 'old_container_id="$(docker inspect --format '\''{{.Id}}'\'' "${container_name}"' "$recover_script" +grep -Fq 'docker compose stop "${compose_service_name}"' "$recover_script" +grep -Fq 'docker compose rm -f "${compose_service_name}"' "$recover_script" +grep -Fq 'docker inspect "${old_container_id}"' "$recover_script" +grep -Fq 'ib_gateway_inspect_container_epoch "${container_name}"' "$recover_script" +grep -Fq 'ib_gateway_validate_replacement_epoch "${old_container_id}" "${replacement_container_id}" "${replacement_started_at}"' "$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 'IB_GATEWAY_CONTAINER_NAME="${epoch_container_id}"' "$recover_script" +grep -Fq 'if wait_for_ready "${initial_wait_seconds}" "${epoch_container_id}"; then' "$recover_script" +if grep -Fq 'wait_for_ready_with_progress "${initial_wait_seconds}"' "$recover_script"; then + echo 'Pre-replacement container logs must not be classified as a recovery epoch' >&2 + exit 1 +fi +if grep -Eq 'docker (logs|exec).*\$\{container_name\}' "$recover_script"; then + echo 'Log classification must never fall back to the reusable container name' >&2 + exit 1 +fi +if grep -Fq 'tail -n' "$recover_script"; then + echo 'Sticky terminal classification must scan the complete current epoch' >&2 + exit 1 +fi + +ready_line="$(grep -n 'if wait_for_ready "${timeout_seconds}" "${epoch_container_id}"; then' "$recover_script" | head -n 1 | cut -d: -f1)" +activity_line="$(grep -n 'activity="$(gateway_epoch_activity "${epoch_container_id}" "${epoch_started_at}")"' "$recover_script" | head -n 1 | cut -d: -f1)" +test -n "$ready_line" +test -n "$activity_line" +test "$ready_line" -lt "$activity_line" + +grep -Fq 'Dismissing gateway dialog candidate' "$twofa_bot" +if grep -Fq 'Dismissing post-login dialog' "$recover_script" "$twofa_bot"; then + echo 'Ambiguous dialog dismissal must not be recovery progress' >&2 + exit 1 +fi diff --git a/tests/test_workflow_shared_config.sh b/tests/test_workflow_shared_config.sh index 3511333..79d83bd 100644 --- a/tests/test_workflow_shared_config.sh +++ b/tests/test_workflow_shared_config.sh @@ -3,6 +3,7 @@ set -euo pipefail repo_dir="$(cd "$(dirname "$0")/.." && pwd)" workflow_file="$repo_dir/.github/workflows/main.yml" +ci_workflow_file="$repo_dir/.github/workflows/ci.yml" maintenance_workflow_file="$repo_dir/.github/workflows/remote-maintenance.yml" diagnose_workflow_file="$repo_dir/.github/workflows/diagnose.yml" @@ -15,6 +16,8 @@ grep -Fq 'providers/github-ibkr-gateway-main' "$workflow_file" grep -Fq 'ibkr-gateway-deploy@interactivebrokersquant.iam.gserviceaccount.com' "$workflow_file" grep -Fq 'id-token: write' "$workflow_file" grep -Fq 'timeout-minutes: 60' "$workflow_file" +grep -Fq 'bash tests/test_gateway_recovery_scripts.sh' "$ci_workflow_file" +grep -Fq 'bash tests/test_gateway_replacement_epoch_policy.sh' "$ci_workflow_file" grep -Fq 'sync_github_secrets_to_secret_manager:' "$workflow_file" grep -Fq 'deploy_mode:' "$workflow_file" grep -Fq 'workload_identity_provider: ${{ env.GCP_WORKLOAD_IDENTITY_PROVIDER }}' "$workflow_file" From b10c427bb9bff18553997e1fb80e8d9f4b0ea345 Mon Sep 17 00:00:00 2001 From: Pigbibi <20649888+Pigbibi@users.noreply.github.com> Date: Thu, 16 Jul 2026 01:00:10 +0800 Subject: [PATCH 2/2] fix: preserve initial epoch recovery evidence Co-Authored-By: Codex --- scripts/classify_ib_gateway_epoch_activity.awk | 3 ++- scripts/recover_ib_gateway_ready.sh | 17 +++++++++++++---- tests/test_gateway_replacement_epoch_policy.sh | 14 +++++++++----- 3 files changed, 24 insertions(+), 10 deletions(-) diff --git a/scripts/classify_ib_gateway_epoch_activity.awk b/scripts/classify_ib_gateway_epoch_activity.awk index c4c9c2a..699147c 100644 --- a/scripts/classify_ib_gateway_epoch_activity.awk +++ b/scripts/classify_ib_gateway_epoch_activity.awk @@ -1,4 +1,5 @@ function canonical_timestamp(value, fraction, digits) { + sub(/,/, ".", value) if (value ~ /^[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}(\.[0-9]+)?Z$/) { sub(/Z$/, "", value) sub(/T/, " ", value) @@ -34,7 +35,7 @@ BEGIN { line_timestamp = "" if ($0 ~ /^[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2}(\.[0-9]+)?Z[[:space:]]/) { line_timestamp = $1 - } else if ($0 ~ /^[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}(\.[0-9]+)?[[:space:]]/) { + } else if ($0 ~ /^[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}([.,][0-9]+)?[[:space:]]/) { line_timestamp = $1 " " $2 } diff --git a/scripts/recover_ib_gateway_ready.sh b/scripts/recover_ib_gateway_ready.sh index 9f8c94c..d416365 100755 --- a/scripts/recover_ib_gateway_ready.sh +++ b/scripts/recover_ib_gateway_ready.sh @@ -88,8 +88,14 @@ gateway_epoch_activity() { local epoch_started_at="$2" local docker_activity file_activity - docker_activity="$(gateway_epoch_activity_from_docker_logs "${epoch_container_id}" "${epoch_started_at}")" - file_activity="$(gateway_epoch_activity_from_file_logs "${epoch_container_id}" "${epoch_started_at}")" + if ! docker_activity="$(gateway_epoch_activity_from_docker_logs "${epoch_container_id}" "${epoch_started_at}")"; then + echo "Unable to classify replacement epoch Docker logs for ${epoch_container_id}." >&2 + return 1 + fi + if ! file_activity="$(gateway_epoch_activity_from_file_logs "${epoch_container_id}" "${epoch_started_at}")"; then + echo "Unable to classify replacement epoch file logs for ${epoch_container_id}." >&2 + return 1 + fi if [ "${docker_activity}" = "terminal" ] || [ "${file_activity}" = "terminal" ]; then echo terminal elif [ "${docker_activity}" = "progress" ] || [ "${file_activity}" = "progress" ]; then @@ -111,7 +117,10 @@ wait_for_ready_with_progress() { fi while [ "${extension}" -lt "${progress_extensions}" ]; do - activity="$(gateway_epoch_activity "${epoch_container_id}" "${epoch_started_at}")" + if ! activity="$(gateway_epoch_activity "${epoch_container_id}" "${epoch_started_at}")"; then + echo "Replacement epoch activity is unavailable during ${stage}; refusing to extend readiness wait." >&2 + return 1 + fi if [ "${activity}" = "terminal" ]; then echo "Terminal IB gateway authentication event detected during ${stage} replacement epoch; refusing to extend readiness wait." >&2 return 1 @@ -186,7 +195,7 @@ docker compose up -d --no-build "${compose_service_name}" inspect_current_container ensure_2fa_bot_running "${epoch_container_id}" -if wait_for_ready "${initial_wait_seconds}" "${epoch_container_id}"; then +if wait_for_ready_with_progress "${initial_wait_seconds}" "initial" "${epoch_container_id}" "${epoch_started_at}"; then exit 0 fi diff --git a/tests/test_gateway_replacement_epoch_policy.sh b/tests/test_gateway_replacement_epoch_policy.sh index e42678e..161f0fc 100644 --- a/tests/test_gateway_replacement_epoch_policy.sh +++ b/tests/test_gateway_replacement_epoch_policy.sh @@ -81,6 +81,12 @@ replacement_terminal_sticky="$(printf '%s\n' \ | classify "$valid_started_at")" test "$replacement_terminal_sticky" = 'terminal' +comma_fraction_terminal="$(printf '%s\n' \ + '2026-07-15 16:38:21,980 Server disconnected' \ + '2026-07-15 16:38:22,100 Authentication completed' \ + | classify "$valid_started_at")" +test "$comma_fraction_terminal" = 'terminal' + untimestamped_terminal="$(printf '%s\n' \ 'Server disconnected' \ '2026-07-15T16:38:22.100000000Z IBC: Login attempt' \ @@ -97,11 +103,7 @@ grep -Fq 'ib_gateway_validate_replacement_epoch "${old_container_id}" "${replace 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 'IB_GATEWAY_CONTAINER_NAME="${epoch_container_id}"' "$recover_script" -grep -Fq 'if wait_for_ready "${initial_wait_seconds}" "${epoch_container_id}"; then' "$recover_script" -if grep -Fq 'wait_for_ready_with_progress "${initial_wait_seconds}"' "$recover_script"; then - echo 'Pre-replacement container logs must not be classified as a recovery epoch' >&2 - exit 1 -fi +grep -Fq 'if wait_for_ready_with_progress "${initial_wait_seconds}" "initial" "${epoch_container_id}" "${epoch_started_at}"; then' "$recover_script" if grep -Eq 'docker (logs|exec).*\$\{container_name\}' "$recover_script"; then echo 'Log classification must never fall back to the reusable container name' >&2 exit 1 @@ -116,6 +118,8 @@ activity_line="$(grep -n 'activity="$(gateway_epoch_activity "${epoch_container_ test -n "$ready_line" test -n "$activity_line" test "$ready_line" -lt "$activity_line" +grep -Fq 'if ! docker_activity="$(gateway_epoch_activity_from_docker_logs' "$recover_script" +grep -Fq 'if ! file_activity="$(gateway_epoch_activity_from_file_logs' "$recover_script" grep -Fq 'Dismissing gateway dialog candidate' "$twofa_bot" if grep -Fq 'Dismissing post-login dialog' "$recover_script" "$twofa_bot"; then