Skip to content

Commit dbff862

Browse files
Pigbibicodex
Pigbibi
and
codex
committed
fix(ops): scope terminal veto to recovery epoch
Co-Authored-By: Codex <noreply@openai.com>
1 parent e001c6d commit dbff862

7 files changed

Lines changed: 212 additions & 44 deletions

‎.github/workflows/ci.yml‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,5 +21,7 @@ jobs:
2121
set -euo pipefail
2222
bash tests/test_install_2fa_bot_watcher.sh
2323
bash tests/test_wait_for_ib_gateway_ready.sh
24+
bash tests/test_gateway_recovery_scripts.sh
25+
bash tests/test_gateway_recovery_epoch_policy.sh
2426
bash tests/test_workflow_shared_config.sh
2527
bash tests/test_docker_compose_ports.sh

‎2fa_bot.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -290,7 +290,7 @@ def find_dismissible_dialogs():
290290
def dismiss_dialog(candidate):
291291
if candidate.window_id not in dismissed_dialog_windows:
292292
log.info(
293-
"Dismissing post-login dialog (id=%s, title=%r, size=%sx%s)",
293+
"Dismissing gateway dialog candidate (id=%s, title=%r, size=%sx%s)",
294294
candidate.window_id,
295295
candidate.title,
296296
candidate.width or "?",

‎scripts/classify_ib_gateway_epoch_activity.awk‎

Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,52 @@
1+
BEGIN {
2+
file_timestamp_pattern = "^[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9] [0-9][0-9]:[0-9][0-9]:[0-9][0-9]$"
3+
rfc3339_timestamp_pattern = "^[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9]T[0-9][0-9]:[0-9][0-9]:[0-9][0-9](\\.[0-9]+)?Z$"
4+
epoch_start = normalize_timestamp(attempt_start)
5+
if (epoch_start == "") {
6+
exit 2
7+
}
8+
}
9+
10+
function normalize_timestamp(raw, fraction_at, fraction) {
11+
if (raw ~ rfc3339_timestamp_pattern) {
12+
sub(/Z$/, "", raw)
13+
gsub("T", " ", raw)
14+
} else if (raw !~ file_timestamp_pattern) {
15+
return ""
16+
}
17+
18+
fraction_at = index(raw, ".")
19+
if (fraction_at == 0) {
20+
return raw ".000000000"
21+
}
22+
fraction = substr(raw, fraction_at + 1)
23+
while (length(fraction) < 9) {
24+
fraction = fraction "0"
25+
}
26+
return substr(raw, 1, fraction_at) substr(fraction, 1, 9)
27+
}
28+
29+
{
30+
event_timestamp = normalize_timestamp($1)
31+
if (event_timestamp == "") {
32+
event_timestamp = normalize_timestamp(substr($0, 1, 19))
33+
}
34+
if (event_timestamp == "" || event_timestamp < epoch_start) {
35+
next
36+
}
37+
38+
if ($0 ~ terminal_regex) {
39+
terminal_seen = 1
40+
}
41+
if ($0 ~ progress_regex) {
42+
progress_seen = 1
43+
}
44+
}
45+
46+
END {
47+
if (terminal_seen) {
48+
print "terminal"
49+
} else if (progress_seen) {
50+
print "progress"
51+
}
52+
}

‎scripts/recover_ib_gateway_ready.sh‎

Lines changed: 63 additions & 36 deletions
Original file line numberDiff line numberDiff line change
@@ -13,8 +13,11 @@ recreate_wait_seconds="${IB_GATEWAY_RECOVERY_RECREATE_WAIT_SECONDS:-600}"
1313
# restart itself before the API socket listens. Do not interrupt that progress.
1414
progress_wait_seconds="${IB_GATEWAY_RECOVERY_PROGRESS_WAIT_SECONDS:-420}"
1515
progress_extensions="${IB_GATEWAY_RECOVERY_PROGRESS_EXTENSIONS:-2}"
16-
progress_window_seconds="${IB_GATEWAY_RECOVERY_PROGRESS_WINDOW_SECONDS:-420}"
17-
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:}"
16+
log_probe_timeout_seconds="${IB_GATEWAY_RECOVERY_LOG_PROBE_TIMEOUT_SECONDS:-10}"
17+
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:}"
18+
default_terminal_regex='Connection reset by peer|Server disconnected|IBC: .*(Authentication|Login).*(timed out|timeout|failed)|IBC: .*(timed out|timeout).*(Authentication|Login)'
19+
terminal_regex="${IB_GATEWAY_RECOVERY_TERMINAL_REGEX:-$default_terminal_regex}"
20+
activity_classifier="${script_dir}/classify_ib_gateway_epoch_activity.awk"
1821
lock_file="${IB_GATEWAY_RECOVERY_LOCK_FILE:-/var/lock/ib_gateway_recovery.lock}"
1922
lock_wait_seconds="${IB_GATEWAY_RECOVERY_LOCK_WAIT_SECONDS:-900}"
2023

@@ -41,56 +44,77 @@ wait_for_ready() {
4144
bash "${script_dir}/wait_for_ib_gateway_ready.sh" "${gateway_mode}"
4245
}
4346

44-
gateway_recently_progressing_from_docker_logs() {
45-
docker logs --since "${progress_window_seconds}s" "${container_name}" 2>&1 \
46-
| grep -Eiq "${progress_regex}"
47+
new_recovery_epoch() {
48+
date -u "+%Y-%m-%dT%H:%M:%S.%NZ"
4749
}
4850

49-
gateway_recently_progressing_from_file_logs() {
50-
docker exec "${container_name}" sh -s -- "${progress_window_seconds}" "${progress_regex}" <<'SH'
51-
set -eu
51+
gateway_epoch_activity_from_docker_logs() {
52+
local attempt_start="$1"
53+
timeout "${log_probe_timeout_seconds}" \
54+
docker logs --timestamps --since "${attempt_start}" "${container_name}" 2>&1 \
55+
| awk -v attempt_start="${attempt_start}" \
56+
-v progress_regex="${progress_regex}" \
57+
-v terminal_regex="${terminal_regex}" \
58+
-f "${activity_classifier}"
59+
}
5260

53-
progress_window_seconds="$1"
54-
progress_regex="$2"
55-
now="$(date +%s)"
56-
cutoff_timestamp="$(date -u -d "@$((now - progress_window_seconds))" "+%Y-%m-%d %H:%M:%S")"
61+
gateway_epoch_activity_from_file_logs() {
62+
local attempt_start="$1"
63+
local log_path
5764

58-
for log_path in /home/ibgateway/Jts/launcher.log /home/ibgateway/2fa.log; do
59-
if [ ! -f "${log_path}" ]; then
60-
continue
61-
fi
65+
for log_path in /home/ibgateway/Jts/launcher.log /home/ibgateway/2fa.log; do
66+
{ timeout "${log_probe_timeout_seconds}" docker exec "${container_name}" tail -n 400 "${log_path}" 2>/dev/null || true; } \
67+
| awk -v attempt_start="${attempt_start}" \
68+
-v progress_regex="${progress_regex}" \
69+
-v terminal_regex="${terminal_regex}" \
70+
-f "${activity_classifier}"
71+
done
72+
}
6273

63-
log_mtime="$(stat -c %Y "${log_path}" 2>/dev/null || echo 0)"
64-
if [ $((now - log_mtime)) -le "${progress_window_seconds}" ]; then
65-
tail -n 400 "${log_path}" 2>/dev/null \
66-
| awk -v cutoff_timestamp="${cutoff_timestamp}" -v progress_regex="${progress_regex}" '
67-
substr($0, 1, 19) >= cutoff_timestamp && $0 ~ progress_regex { found = 1 }
68-
END { exit found ? 0 : 1 }
69-
' && exit 0
70-
fi
71-
done
74+
gateway_epoch_activity() {
75+
local attempt_start="$1"
76+
local progress_seen=false
77+
local state
7278

73-
exit 1
74-
SH
75-
}
79+
while IFS= read -r state; do
80+
if [ "${state}" = "terminal" ]; then
81+
echo terminal
82+
return 0
83+
fi
84+
if [ "${state}" = "progress" ]; then
85+
progress_seen=true
86+
fi
87+
done < <(
88+
gateway_epoch_activity_from_docker_logs "${attempt_start}" || true
89+
gateway_epoch_activity_from_file_logs "${attempt_start}" || true
90+
)
7691

77-
gateway_recently_progressing() {
78-
gateway_recently_progressing_from_docker_logs || gateway_recently_progressing_from_file_logs
92+
if [ "${progress_seen}" = "true" ]; then
93+
echo progress
94+
fi
7995
}
8096

8197
wait_for_ready_with_progress() {
8298
local timeout_seconds="$1"
8399
local stage="$2"
100+
local attempt_start="$3"
84101
local extension=0
102+
local activity
85103

86104
if wait_for_ready "${timeout_seconds}"; then
87105
return 0
88106
fi
89107

90108
while [ "${extension}" -lt "${progress_extensions}" ]; do
91-
if ! gateway_recently_progressing; then
92-
return 1
93-
fi
109+
activity="$(gateway_epoch_activity "${attempt_start}")"
110+
case "${activity}" in
111+
terminal)
112+
echo "Recent terminal IB gateway authentication failure detected in the current recovery epoch after ${stage} wait; skipping progress extension." >&2
113+
return 1
114+
;;
115+
progress) ;;
116+
*) return 1 ;;
117+
esac
94118

95119
extension=$((extension + 1))
96120
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
@@ -107,27 +131,30 @@ ensure_2fa_bot_running() {
107131
}
108132

109133
echo "Ensuring ${container_name} is running before readiness check."
134+
attempt_start="$(new_recovery_epoch)"
110135
docker compose up -d --no-build "${compose_service_name}"
111136
ensure_2fa_bot_running
112137

113-
if wait_for_ready_with_progress "${initial_wait_seconds}" "initial"; then
138+
if wait_for_ready_with_progress "${initial_wait_seconds}" "initial" "${attempt_start}"; then
114139
exit 0
115140
fi
116141

117142
echo "IB gateway API was not ready; restarting ${container_name} and retrying." >&2
118143
docker compose ps >&2 || true
144+
attempt_start="$(new_recovery_epoch)"
119145
docker compose restart "${compose_service_name}"
120146
ensure_2fa_bot_running
121147

122-
if wait_for_ready_with_progress "${restart_wait_seconds}" "restart"; then
148+
if wait_for_ready_with_progress "${restart_wait_seconds}" "restart" "${attempt_start}"; then
123149
exit 0
124150
fi
125151

126152
echo "IB gateway API is still not ready; recreating ${container_name} and retrying." >&2
153+
attempt_start="$(new_recovery_epoch)"
127154
docker compose up -d --force-recreate --no-build "${compose_service_name}"
128155
ensure_2fa_bot_running
129156

130-
if wait_for_ready_with_progress "${recreate_wait_seconds}" "recreate"; then
157+
if wait_for_ready_with_progress "${recreate_wait_seconds}" "recreate" "${attempt_start}"; then
131158
exit 0
132159
fi
133160

‎tests/test_gateway_recovery_epoch_policy.sh‎

Lines changed: 81 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,81 @@
1+
#!/usr/bin/env bash
2+
set -euo pipefail
3+
4+
repo_dir="$(cd "$(dirname "$0")/.." && pwd)"
5+
recover_script="$repo_dir/scripts/recover_ib_gateway_ready.sh"
6+
classifier="$repo_dir/scripts/classify_ib_gateway_epoch_activity.awk"
7+
twofa_bot="$repo_dir/2fa_bot.py"
8+
9+
test -f "$classifier"
10+
grep -Fq 'IB_GATEWAY_RECOVERY_TERMINAL_REGEX' "$recover_script"
11+
grep -Fq 'gateway_epoch_activity()' "$recover_script"
12+
grep -Fq 'new_recovery_epoch()' "$recover_script"
13+
grep -Fq 'activity="$(gateway_epoch_activity "${attempt_start}")"' "$recover_script"
14+
grep -Fq 'Recent terminal IB gateway authentication failure detected in the current recovery epoch' "$recover_script"
15+
grep -Fq 'Dismissing gateway dialog candidate' "$twofa_bot"
16+
if grep -Fq 'Dismissing post-login dialog' "$recover_script" "$twofa_bot"; then
17+
echo 'Ambiguous dialog dismissal must not be recovery progress' >&2
18+
exit 1
19+
fi
20+
21+
default_progress_regex="$(sed -n 's/^progress_regex="${IB_GATEWAY_RECOVERY_PROGRESS_REGEX:-\(.*\)}"$/\1/p' "$recover_script")"
22+
default_terminal_regex="$(sed -n "s/^default_terminal_regex='\\(.*\\)'$/\\1/p" "$recover_script")"
23+
test -n "$default_progress_regex"
24+
test -n "$default_terminal_regex"
25+
case "$default_terminal_regex" in
26+
*'}') echo 'Terminal regex must not contain the shell parameter-expansion delimiter' >&2; exit 1 ;;
27+
esac
28+
printf '%s\n' 'IBC: Login attempt timed out' | grep -Eq "$default_terminal_regex"
29+
printf '%s\n' 'IBC: timed out waiting for Login' | grep -Eq "$default_terminal_regex"
30+
31+
classify() {
32+
local attempt_start="$1"
33+
awk \
34+
-v attempt_start="$attempt_start" \
35+
-v progress_regex="$default_progress_regex" \
36+
-v terminal_regex="$default_terminal_regex" \
37+
-f "$classifier"
38+
}
39+
40+
pre_epoch_terminal="$(printf '%s\n' \
41+
'2026-07-15T16:00:00.100000000Z Server disconnected' \
42+
'2026-07-15T16:00:00.300000000Z IBC: Login attempt' \
43+
| classify '2026-07-15T16:00:00.200000000Z')"
44+
test "$pre_epoch_terminal" = 'progress'
45+
46+
sticky_terminal="$(printf '%s\n' \
47+
'2026-07-15T16:00:00.200000000Z Connection reset by peer' \
48+
'2026-07-15T16:00:00.300000000Z Security code:' \
49+
'2026-07-15T16:00:00.400000000Z Authentication completed' \
50+
| classify '2026-07-15T16:00:00.100000000Z')"
51+
test "$sticky_terminal" = 'terminal'
52+
53+
new_epoch_reset="$(printf '%s\n' \
54+
'2026-07-15T16:00:00.200000000Z Server disconnected' \
55+
'2026-07-15T16:00:00.400000000Z IBC: Login attempt' \
56+
| classify '2026-07-15T16:00:00.300000000Z')"
57+
test "$new_epoch_reset" = 'progress'
58+
59+
untimestamped_terminal="$(printf '%s\n' \
60+
'Server disconnected' \
61+
'2026-07-15T16:00:00.400000000Z IBC: Login attempt' \
62+
| classify '2026-07-15T16:00:00.300000000Z')"
63+
test "$untimestamped_terminal" = 'progress'
64+
65+
ready_line="$(grep -n 'if wait_for_ready "${timeout_seconds}"; then' "$recover_script" | head -n 1 | cut -d: -f1)"
66+
activity_line="$(grep -n 'activity="$(gateway_epoch_activity "${attempt_start}")"' "$recover_script" | head -n 1 | cut -d: -f1)"
67+
test -n "$ready_line"
68+
test -n "$activity_line"
69+
test "$ready_line" -lt "$activity_line"
70+
71+
epoch_count="$(grep -c 'attempt_start="$(new_recovery_epoch)"' "$recover_script")"
72+
test "$epoch_count" -eq 3
73+
awk '
74+
/attempt_start="\$\(new_recovery_epoch\)"/ {
75+
seen += 1
76+
if (getline <= 0 || $0 !~ /^docker compose (up|restart)/) {
77+
exit 1
78+
}
79+
}
80+
END { exit seen == 3 ? 0 : 1 }
81+
' "$recover_script"

‎tests/test_gateway_recovery_scripts.sh‎

Lines changed: 10 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -24,17 +24,20 @@ grep -Fq 'IB_GATEWAY_RECOVERY_RESTART_WAIT_SECONDS:-300' "$recover_script"
2424
grep -Fq 'IB_GATEWAY_RECOVERY_RECREATE_WAIT_SECONDS:-600' "$recover_script"
2525
grep -Fq 'IB_GATEWAY_RECOVERY_PROGRESS_WAIT_SECONDS:-420' "$recover_script"
2626
grep -Fq 'IB_GATEWAY_RECOVERY_PROGRESS_EXTENSIONS:-2' "$recover_script"
27-
grep -Fq 'IB_GATEWAY_RECOVERY_PROGRESS_WINDOW_SECONDS:-420' "$recover_script"
27+
grep -Fq 'IB_GATEWAY_RECOVERY_LOG_PROBE_TIMEOUT_SECONDS:-10' "$recover_script"
28+
if grep -Fq 'IB_GATEWAY_RECOVERY_PROGRESS_WINDOW_SECONDS' "$recover_script"; then
29+
echo 'Recovery activity must be bounded by the current epoch, not a rolling window' >&2
30+
exit 1
31+
fi
2832
grep -Fq 'Passed token authentication' "$recover_script"
2933
grep -Fq 'Authentication completed' "$recover_script"
30-
grep -Fq 'gateway_recently_progressing()' "$recover_script"
31-
grep -Fq 'gateway_recently_progressing_from_docker_logs()' "$recover_script"
32-
grep -Fq 'gateway_recently_progressing_from_file_logs()' "$recover_script"
34+
grep -Fq 'gateway_epoch_activity()' "$recover_script"
35+
grep -Fq 'gateway_epoch_activity_from_docker_logs()' "$recover_script"
36+
grep -Fq 'gateway_epoch_activity_from_file_logs()' "$recover_script"
3337
grep -Fq '/home/ibgateway/Jts/launcher.log' "$recover_script"
3438
grep -Fq '/home/ibgateway/2fa.log' "$recover_script"
35-
grep -Fq 'stat -c %Y "${log_path}"' "$recover_script"
36-
grep -Fq 'cutoff_timestamp="$(date -u -d "@$((now - progress_window_seconds))" "+%Y-%m-%d %H:%M:%S")"' "$recover_script"
37-
grep -Fq 'substr($0, 1, 19) >= cutoff_timestamp && $0 ~ progress_regex' "$recover_script"
39+
grep -Fq 'docker logs --timestamps --since "${attempt_start}"' "$recover_script"
40+
grep -Fq 'timeout "${log_probe_timeout_seconds}" docker exec' "$recover_script"
3841
grep -Fq 'wait_for_ready_with_progress()' "$recover_script"
3942
grep -Fq 'Recent IB gateway login/config progress detected' "$recover_script"
4043
grep -Fq 'IB_GATEWAY_RECOVERY_LOCK_FILE:-/var/lock/ib_gateway_recovery.lock' "$recover_script"

‎tests/test_workflow_shared_config.sh‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ set -euo pipefail
33

44
repo_dir="$(cd "$(dirname "$0")/.." && pwd)"
55
workflow_file="$repo_dir/.github/workflows/main.yml"
6+
ci_workflow_file="$repo_dir/.github/workflows/ci.yml"
67
maintenance_workflow_file="$repo_dir/.github/workflows/remote-maintenance.yml"
78
diagnose_workflow_file="$repo_dir/.github/workflows/diagnose.yml"
89

@@ -15,6 +16,8 @@ grep -Fq 'providers/github-ibkr-gateway-main' "$workflow_file"
1516
grep -Fq 'ibkr-gateway-deploy@interactivebrokersquant.iam.gserviceaccount.com' "$workflow_file"
1617
grep -Fq 'id-token: write' "$workflow_file"
1718
grep -Fq 'timeout-minutes: 60' "$workflow_file"
19+
grep -Fq 'bash tests/test_gateway_recovery_scripts.sh' "$ci_workflow_file"
20+
grep -Fq 'bash tests/test_gateway_recovery_epoch_policy.sh' "$ci_workflow_file"
1821
grep -Fq 'sync_github_secrets_to_secret_manager:' "$workflow_file"
1922
grep -Fq 'deploy_mode:' "$workflow_file"
2023
grep -Fq 'workload_identity_provider: ${{ env.GCP_WORKLOAD_IDENTITY_PROVIDER }}' "$workflow_file"

0 commit comments

Comments
 (0)