p24-infra Docs

mongodb-restore-drill-troubleshooting

10 min read

Playbook: MongoDB Restore Drill — Troubleshooting

Reference for diagnosing failures in scripts/mongodb-restore-drill-cron.sh and scripts/mongodb-restore-drill.sh.

First successful drill run: 2026-07-01 (w3_db + w4_db, backup 2026-06-15). All issues below were discovered and fixed before that run.

Incident 2026-10-01 — timeout → unauthenticated mongod exposed for 7 days (#7609)

What happened. The Q4 2026 quarterly drill started 2026-10-01 03:05 UTC on bms-4 and systemd SIGTERM-killed it at 04:05:49 UTC: TimeoutStartSec was 3600s but the w3_db restore alone took 3397s and w4_db had only just started, so the drill timed out mid-run and produced no complete Q4 verification. Worse, the drill script had no cleanup trap at the time, so the SIGTERM left the throwaway container mongo-drill-1439728 (mongo:7.0, no --auth) running for 7 days publishing 0.0.0.0:27019->27017. Docker’s published ports bypass ufw (iptables DOCKER chain), so an unauthenticated listDatabases on 54.36.123.110:27019 returned the restored production w3_db from the internet. The two production dump archives were also left world-readable (0644) in /tmp.

Connection-log review of the container before removal (IP addresses only, no data): 26 accepted connections from 20 distinct external public IPs over the window (plus 16 local from the drill’s own checks), consistent with internet-wide MongoDB scanners — but because auth was disabled, unauthenticated reads of the restored copy could not be excluded.

Root causes & fixes (this PR):

  1. Timeout too short → TimeoutStartSec raised to 14400s (4h) in deploy/p24-mongodb-restore-drill.service.
  2. No teardown on SIGTERM → scripts/mongodb-restore-drill.sh now installs trap _cleanup EXIT INT TERM (idempotent _CLEANED guard), and the unit has an ExecStopPost= that force-removes any p24.drill=1 container (with -v) even after a SIGKILL.
  3. Internet exposure → the container now publishes on 127.0.0.1 only and runs with enforced --auth (image root env vars, a random single-use credential delivered to mongosh on stdin). Nothing consumes the host port — all checks run via docker exec.
  4. World-readable dumps → umask 077 + a 0700 scratch dir; docker rm -v drops the restored-data volume.
  5. Orphan safety net → scripts/mongodb-drill-orphan-sweep.sh (p24-mongodb-drill-orphan-sweep.{service,timer}, daily 06:00 UTC) removes any labelled drill container older than the max runtime and reports per the Error Notification Standard.

The Q4 2026 DR verification must be re-run (a separate infra-task) now the fix is merged and its result recorded here.

Incident 2026-10-10 — drill exits 1 after a good restore; verdict block skipped (#7847)

What happened. p24-mongodb-restore-drill.service on bms-4 showed failed (exit-code) after the 2026-10-10 02:40 UTC run. The restore and comparisons themselves succeeded (w3_db + w4_db restored, non-zero document counts, OVERALL_STATUS PASS, ERRORS/FAILURES: None), but the mongodb-restore-drill-cron.sh wrapper saw rc=1 and reported “already self-alerted”. The Q4 drill comment on #7609 showed Verdict line: none captured / Fail reason: none captured. The PASS Discord notification and the dev_r_ops_events success row were silently skipped.

Root cause. _cleanup() calls log "Cleanup done." after rm -rf "${SCRATCH_DIR}". Since LOG_FILE lives inside SCRATCH_DIR, the tee -a "${LOG_FILE}" in log() finds the file gone and exits non-zero. Under set -euo pipefail the pipe failure propagates out of _cleanup, and because _cleanup is called before the “Final verdict” block (line ~685), the script exits 1 at that point — before _supabase_log_result, the Discord PASS notification, or exit 0 can run. The _CLEANED guard and EXIT trap added by the #7650 hardening did not introduce the rm-then-log ordering; they exposed it by making _cleanup run reliably on every exit path.

Fix (#7847).

  1. log() is now tolerant: echo ... | tee -a "${LOG_FILE}" 2>/dev/null || true. A missing log file silently drops the message but never aborts the script.
  2. BACKUP_TOO_OLD age guard added to Step 1: date -d computes the backup age in hours; if > 48h, BACKUP_TOO_OLD=true and OVERALL_STATUS is set to FAIL with the age in FAIL_REASONS. This prevents a months-old backup from producing a misleading PASS (the #7717 scenario: backups stopped 2026-06-15; the drill restored that backup and still passed).

What to check if you see a similar rc=1 with a successful restore.

# On bms-4 — check the journal for the relevant drill PID:
journalctl -u p24-mongodb-restore-drill.service --no-pager | grep -E 'tee:|exit|Cleanup|verdict'
# Look for: tee: /tmp/mongo-drill-<PID>/drill.log: No such file or directory
# If present: the drill script pre-dates the #7847 fix — deploy the updated script.

After deploying the fix, re-run the drill in a quiet window (see “Running the drill manually” below). Note: as of 2026-10-13 backups are still stale (#7717, BOM in mongodb-backup.sh on bms-3), so the drill will now correctly report FAIL with a backup-age reason. A meaningful PASS requires fresh backups from bms-3 first.

Orphan drill container cleanup (teardown didn’t fire)

scripts/mongodb-restore-drill.sh names its container mongo-drill-$$ (the script PID), labels it p24.drill=1 / p24.drill.started=<epoch> / p24.drill.pid=<PID>, and tears it down in _cleanup() via a trap _cleanup EXIT INT TERM (docker stop → docker rm -v → rm -rf the /tmp/mongo-drill-$$ scratch dir). That trap now survives the SIGTERM a TimeoutStartSec kill sends; it still does not run on a hard SIGKILL or a host reboot mid-drill. Two further nets cover that residual case: the unit’s ExecStopPost= (fires even after SIGKILL) and the daily p24-mongodb-drill-orphan-sweep.timer. Before #7609 none of these existed, so a killed drill left an orphan mongo-drill-<PID> publishing a mongod — e.g. mongo-drill-3306081 left Up 4 days publishing 0.0.0.0:27019->27017 (#6354), and mongo-drill-1439728 for 7 days (#7609).

A drill runs up to ~4h, so any drill container older than that is an orphan. The automated sweep handles this, but to do it by hand — confirm no drill is actually running, then tear it down exactly as _cleanup() would:

# List drill containers + age (prefer the label; name filter is the legacy fallback)
docker ps -a --filter "label=p24.drill=1" \
  --format '{{.Names}} | {{.Status}} | {{.CreatedAt}}'
docker ps -a --filter "name=mongo-drill" \
  --format '{{.Names}} | {{.Status}} | {{.CreatedAt}}'
 
# For a candidate: verify it is NOT a live drill (label PID, then process scan)
PID=$(docker inspect -f '{{ index .Config.Labels "p24.drill.pid" }}' <name> 2>/dev/null)
kill -0 "$PID" 2>/dev/null && echo "PID ALIVE — do NOT remove" || echo "PID dead — safe"
ps aux | grep -E 'mongo-drill|restore.drill' | grep -v grep   # expect none
tail -n2 /tmp/mongo-drill-<PID>/drill.log 2>/dev/null          # last activity timestamp
 
# Safe to remove — same as _cleanup() / the sweep (−v drops the restored-data volume)
docker rm -vf <name>
rm -rf /tmp/mongo-drill-<PID>
 
# Or just let the automated sweep do it:
sudo -u claude-runner /opt/p24-infra/scripts/mongodb-drill-orphan-sweep.sh

Orphan drill containers are not registered in dev_r_services — they are transient by design — so a leftover one is untracked inventory a D2 compliance audit will flag.

Issue 1 — sops exec-env fails on *.env.sops extension

Symptom: Drill exits with:

Error unmarshalling input json: invalid character 'C' looking for beginning of value

Root cause: sops exec-env detects file format from extension only. The extension *.env.sops is NOT recognized as dotenv (only *.env is recognized). SOPS falls back to JSON parsing; the file starts with CF_API_TOKEN=C... → C is invalid JSON.

The --input-type flag is not available on the exec-env subcommand.

Fix (in mongodb-restore-drill-cron.sh): Replace sops exec-env with explicit decrypt:

_tmpenv=$(mktemp)
chmod 600 "${_tmpenv}"
trap 'rm -f "${_tmpenv}"' EXIT
sops --decrypt --input-type dotenv --output-type dotenv "${MONITORING_SOPS}" >> "${_tmpenv}"
sops --decrypt --input-type dotenv --output-type dotenv "${BMS_SERVERS_SOPS}" >> "${_tmpenv}"
# ... then inject into env (see Issue 2 and 3)

Issue 2 — source fails on values with special characters

Symptom: After decrypting SOPS, env injection silently fails. Some variables not exported. The drill script exits with “SKIPPED (unconfigured)” even though SOPS decrypt succeeded.

Root cause: set -a; source "$tmpenv"; set +a calls source which parses each line as a bash statement. Values like SUPABASE_GRAFANA_PASSWORD=.nSw^Jkn)Y?-(npgCwSW... contain ) which bash interprets as syntax (end of subshell).

Fix: Use a safe line-by-line while loop:

while IFS= read -r _line; do
    [[ -z "${_line}" || "${_line}" == \#* ]] && continue
    _k="${_line%%=*}"
    _v="${_line#*=}"
    [[ "${_k}" =~ ^[a-zA-Z_][a-zA-Z_0-9]*$ ]] || continue  # Issue 3
    export "${_k}"="${_v}"
done < "${_tmpenv}"

Issue 3 — Invalid bash identifiers in dotenv file

Symptom:

export: 'p24-infra-1h-check-claude-discord=...': not a valid identifier

Root cause: Some keys in monitoring.env.sops have hyphens (e.g. p24-infra-1h-check-claude-discord) which are valid in dotenv but not as bash variable names.

Fix: Guard with regex before export (included in Issue 2 fix):

[[ "${_k}" =~ ^[a-zA-Z_][a-zA-Z_0-9]*$ ]] || continue

Issue 4 — MONGODB_ADMIN_PASSWORD not set for --compare-prod

Symptom: Drill logs “WARNING: MONGODB_ADMIN_PASSWORD not set — skipping production comparison”. The --compare-prod step is silently skipped.

Root cause: bms-servers.env.sops uses key mongodb_rs0_admin_password (lowercase) but the drill script expects MONGODB_ADMIN_PASSWORD. After the line-by-line injection, only mongodb_rs0_admin_password is exported.

Fix (in mongodb-restore-drill-cron.sh): Add mapping after env injection:

export MONGODB_ADMIN_PASSWORD="${mongodb_rs0_admin_password:-}"
export MONGODB_ADMIN_USER="${mongodb_rs0_admin_user:-admin}"

Issue 5 — _aws_s3 helper: redundant s3 prefix

Symptom:

aws: [ERROR]: An error occurred (ParamValidation): argument subcommand: Found invalid choice 's3'

Root cause: _aws_s3() already calls aws s3 .... All call sites were passing s3 as the first argument (e.g. _aws_s3 s3 ls), resulting in aws s3 s3 ls which fails because s3 is not a valid subcommand of aws s3.

Fix: Change all call sites to pass only the subcommand:

_aws_s3 ls "s3://bucket/prefix/"   # not: _aws_s3 s3 ls ...
_aws_s3 cp src dst                 # not: _aws_s3 s3 cp ...
_aws_s3 sync src dst               # not: _aws_s3 s3 sync ...

Issue 6 — Wrong Wasabi backup prefix

Symptom: STEP 1: Locating latest backup on Wasabi finds nothing, drill exits immediately with “No backup found”.

Root cause: BACKUP_PREFIX="mongodb/full" in mongodb-restore-drill.sh but actual backups are at s3://p24-infra/mongodb-backups/.

To list the actual structure:

aws s3 ls s3://p24-infra/mongodb-backups/ \
  --endpoint-url https://s3.eu-central-2.wasabisys.com --region eu-central-2
# Expected: w3_db-YYYY-MM-DD.mongodump.gz, w4_db-YYYY-MM-DD.mongodump.gz

Fix: BACKUP_PREFIX="mongodb-backups" and update date extraction to use grep -Eo (extracts date from filenames, not directory prefixes).

Issue 7 — Wrong restore format (directory vs archive)

Symptom: After the drill completes restore, collection counts are all 0 or the restore step fails silently.

Root cause: mongodb-restore-drill.sh was written for mongodump --out DIR --gzip format (per-collection .bson.gz files inside a directory). But actual backups are created with mongodump --archive=FILE --gzip format (single .mongodump.gz per database).

Fix: Restore with --archive flag:

# Inside Docker container:
mongorestore --archive="/tmp/${DB}.mongodump.gz" --gzip --drop --preserveUUID
# NOT: mongorestore --db "$DB" --dir "/dump/${DB}" --gzip ...

Issue 8 — aws CLI not installed on bms-4

Symptom: bash: aws: command not found during STEP 1 or 2.

Fix:

curl -s https://awscli.amazonaws.com/awscli-exe-linux-x86_64.zip -o /tmp/awscliv2.zip
cd /tmp && unzip -q awscliv2.zip
./aws/install --install-dir /usr/local/aws-cli --bin-dir /usr/local/bin
aws --version  # verify

Running the drill manually

# On bms-4 as root:
sudo -u claude-runner /opt/p24-infra/scripts/mongodb-restore-drill-cron.sh
# Logs: /tmp/mongo-drill-$PID/drill.log  (0700 dir; dumps are 0600)
# Duration: up to ~4h — w3_db restore alone measured 3397s on 2026-10-01 (#7609),
#           plus w4_db + integrity checks. The unit's TimeoutStartSec is 14400s to match.
  • scripts/mongodb-restore-drill.sh — main drill logic
  • scripts/mongodb-restore-drill-cron.sh — wrapper for SOPS injection + alerting
  • scripts/mongodb-drill-orphan-sweep.sh — daily orphan-container safety net (#7609)
  • deploy/p24-mongodb-restore-drill.{service,timer} — quarterly drill units
  • deploy/p24-mongodb-drill-orphan-sweep.{service,timer} — daily orphan sweep units (#7609)
  • scripts/mongodb-backup.sh — backup script on bms-3 (Wasabi, weekly → daily after #2367)
  • docs/playbooks/mongodb-rs0-full-restore.md — full DR playbook (Scenario B)
  • Issue #2367 — bms-3 SSH + daily cron fix
  • Issue #2148 — backup gap tracking
  • PR #2371 — all drill script fixes

Graph View

Backlinks