Skip to content
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions .github/workflows/ci.yml
Original file line number Diff line number Diff line change
Expand Up @@ -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
2 changes: 1 addition & 1 deletion 2fa_bot.py
Original file line number Diff line number Diff line change
Expand Up @@ -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 "?",
Expand Down
62 changes: 62 additions & 0 deletions scripts/classify_ib_gateway_epoch_activity.awk
Original file line number Diff line number Diff line change
@@ -0,0 +1,62 @@
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$/) {

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2 Badge Avoid mawk-incompatible timestamp regexes

On hosts where plain awk resolves to mawk (common on Ubuntu/Debian images), this interval regexp with an optional group aborts the classifier with a REcompile() - panic error; because recover_ib_gateway_ready.sh invokes awk directly, replacement log classification then produces no activity instead of detecting progress or terminal events. Use a POSIX-compatible pattern or require gawk so recovery does not silently skip the new epoch policy on those hosts.

Useful? React with 👍 / 👎.

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) {

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2 Badge Don't drop same-second file log events

When /home/ibgateway/2fa.log or launcher.log emits its normal YYYY-MM-DD HH:MM:SS timestamp during the same second as a replacement whose Docker StartedAt has fractional seconds, canonical_timestamp pads the log line to .000000000, so this < epoch_timestamp check skips it even if it happened after the container started. That makes post-replacement progress or terminal evidence in that first second invisible and can prevent the intended wait extension or terminal veto.

Useful? React with 👍 / 👎.

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"
}
}
32 changes: 32 additions & 0 deletions scripts/ib_gateway_container_epoch.sh
Original file line number Diff line number Diff line change
@@ -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}"
}
177 changes: 131 additions & 46 deletions scripts/recover_ib_gateway_ready.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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}"

Expand All @@ -36,65 +42,96 @@ 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"

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
docker exec "${epoch_container_id}" sh -s <<'SH' \
| classify_epoch_activity "${epoch_started_at}"
set -eu

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

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
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
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
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
Expand All @@ -103,35 +140,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_with_progress "${initial_wait_seconds}" "initial" "${epoch_container_id}" "${epoch_started_at}"; 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
19 changes: 9 additions & 10 deletions tests/test_gateway_recovery_scripts.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
Loading
Loading