fix(tor): survive container restarts and run Tor as debian-tor (#1517)

With USING_TOR=true, any restart that reuses the container (docker
restart, a Docker daemon restart, a host reboot) put it in a restart
loop. Only recreating the container ended it.

Tor appends to /var/log/tor/notices.log, and the file survives the
restart. tor.sh waited for Tor by grepping that log for "Bootstrapped
100%", so the previous boot's line passed at once, before Tor had
connected to anything. The NAT rules then went live, Tor could not
finish bootstrapping behind them, the connectivity check could not
resolve check.torproject.org, and the next boot found the same stale
line. tor.sh now moves the previous log to notices.log.prev before it
starts Tor, so the wait and the watchdog only see this boot's output.

Tor could not finish behind the NAT rules because it ran as root. The
rules exempt only debian-tor's traffic from the transparent redirect, so
every relay connection Tor opened after they went live was redirected
into its own TransPort: the log shows dozens of TLS handshakes dying.
This also meant a Tor that lost its guard could never reconnect, on any
kernel. torrc now has `User debian-tor` and `DataDirectory
/var/lib/tor`. Tor still binds DNSPort 53 as root, then drops. It opens
its log after dropping and refuses to start if it cannot, so tor.sh
hands the fresh log to debian-tor first.

The check also failed without a word. `RESULT=$(curl -s ...)` under
`set -e` ended tor.sh with curl's exit status, so the only trace was
ExitCode=6 (could not resolve host) in `docker inspect`. A reply that
was not the expected JSON did the same through grep. The check now:
- retries twice, 10s apart, since a fresh circuit can fail its first
  lookup;
- logs each failure with curl's exit status and error;
- says when it gives up and prints the last Tor log lines;
- still stops the container when traffic does not go through Tor.

- Reproduced on the v1.4.0 image (tor.sh is unchanged since then): after
  one `docker restart` the container restarted 9 times in 150s, each
  boot ending at "Verifying Tor connectivity...".
- With the new tor.sh mounted into the same image, the container went
  through 2 restarts in a row. Each boot verified Tor and reached
  gunicorn within 15-21s, and the restart policy never had to step in.
  Tor runs as debian-tor and its logs belong to it.
- Restarting Tor (`supervisorctl restart tor`) once the NAT rules were
  live, so it had to open new relay connections: as debian-tor it
  bootstrapped again in 4s and traffic still went through Tor. As root
  it had not bootstrapped after 120s, 1775 TLS handshakes had died, and
  curl could not resolve check.torproject.org (exit 6).
- A SIGHUP, which the rotation monitor sends every 5 minutes, keeps
  DNSPort 53 working after the drop to debian-tor.
- 9 new tests in tests/config/test_tor_script_rules.py. 8 of them fail
  on the old tor.sh; the 9th checks that traffic outside Tor still stops
  the container. Three need `grep -P` and skip on macOS, so I also ran
  the file in the Debian image: 23 passed.
- The `make python-checks` tools pass (ruff check and format,
  basedpyright on the app and tests, vulture). The non-e2e suite
  passes: 4366 tests on 86943f5.

Fixes #1502

tests/config/test_tor_script_rules.py

@@ -71,7 +71,7 @@ echo "$*" >> "$FAKE_IPTABLES_LOG"
 exit 0
 """
 
-# tor.sh resolves the Tor uid with `id -u debian-tor`; that account only exists
+# tor.sh resolves the Tor uid with `id -u "$TOR_USER"`; that account only exists
 # inside the image, so stub it out with the uid the Debian tor package uses.
 ID_STUB = """#!/bin/bash
 echo 107
@@ -99,6 +99,7 @@ def _run_tor_iptables_block(tmp_path: Path, *, owner_match_supported: bool):
         text=True,
         env={
             "PATH": f"{bin_dir}:/usr/bin:/bin",
+            "TOR_USER": "debian-tor",
             "FAKE_IPTABLES_LOG": str(applied_rules_log),
             "FAKE_OWNER_MATCH_SUPPORTED": "1" if owner_match_supported else "0",
         },
@@ -227,6 +228,146 @@ def _run_tor_watchdog(
     return reset_signal, stdout
 
 
+BOOTSTRAP_BLOCK_START = 'if [ -f "$TOR_NOTICES_LOG" ]; then'
+BOOTSTRAP_BLOCK_END = 'echo "[✓] Tor is ready."'
+
+SUPERVISORD_STUB = """#!/bin/bash
+# Emulates supervisord launching Tor, which appends this boot's progress to the
+# notices log.
+echo "supervisord" >> "$FAKE_CALLS_LOG"
+printf '%s\\n' "$FAKE_TOR_BOOT_LINE" >> "$TOR_NOTICES_LOG"
+"""
+
+# The Tor account only exists inside the image, so record the call instead.
+CHOWN_STUB = """#!/bin/bash
+echo "chown $*" >> "$FAKE_CALLS_LOG"
+"""
+
+
+def _tor_bootstrap_block(timeout_seconds: int) -> str:
+    """Extract tor.sh from the notices-log reset through the bootstrap wait."""
+    script = TOR_SCRIPT_PATH.read_text()
+    block = script[script.index(BOOTSTRAP_BLOCK_START) : script.index(BOOTSTRAP_BLOCK_END)]
+    for original, replacement in (
+        ("/usr/bin/supervisord", "supervisord"),
+        ("BOOTSTRAP_TIMEOUT=300", f"BOOTSTRAP_TIMEOUT={timeout_seconds}"),
+    ):
+        assert original in block
+        block = block.replace(original, replacement)
+    return block
+
+
+def _run_tor_bootstrap_wait(tmp_path: Path, *, previous_log: str | None, boot_line: str):
+    """Run tor.sh's bootstrap wait against a fake Tor that logs ``boot_line``.
+
+    ``previous_log`` is what the last boot of the same container left in the
+    notices log, or ``None`` for a container's first boot. Returns the completed
+    process, the notices log, and the calls made to supervisord and chown in
+    order.
+    """
+    bin_dir = tmp_path / "bin"
+    bin_dir.mkdir()
+    for name, source in (("supervisord", SUPERVISORD_STUB), ("chown", CHOWN_STUB)):
+        stub = bin_dir / name
+        stub.write_text(source)
+        stub.chmod(0o755)
+
+    notices_log = tmp_path / "notices.log"
+    if previous_log is not None:
+        notices_log.write_text(previous_log)
+    calls_log = tmp_path / "calls.log"
+
+    result = subprocess.run(
+        ["bash", "-c", "set -e\n" + _tor_bootstrap_block(timeout_seconds=1)],
+        capture_output=True,
+        text=True,
+        env={
+            "PATH": f"{bin_dir}:/usr/bin:/bin",
+            "TOR_NOTICES_LOG": str(notices_log),
+            "TOR_USER": "debian-tor",
+            "FAKE_TOR_BOOT_LINE": boot_line,
+            "FAKE_CALLS_LOG": str(calls_log),
+        },
+        timeout=30,
+    )
+    calls = calls_log.read_text().splitlines() if calls_log.exists() else []
+    return result, notices_log, calls
+
+
+VERIFY_BLOCK_START = 'echo "[*] Verifying Tor connectivity..."'
+VERIFY_BLOCK_END = "# Set correct timezone"
+
+CURL_STUB = """#!/bin/bash
+# Emulates curl against check.torproject.org: the first FAKE_CURL_FAILURES calls
+# fail the way curl does when Tor cannot resolve the host yet, later calls print
+# FAKE_CURL_BODY.
+calls=$(cat "$FAKE_CURL_CALLS" 2>/dev/null || echo 0)
+echo $((calls + 1)) > "$FAKE_CURL_CALLS"
+if [ "$calls" -lt "$FAKE_CURL_FAILURES" ]; then
+    echo "curl: (6) Could not resolve host: check.torproject.org" >&2
+    exit 6
+fi
+printf '%s' "$FAKE_CURL_BODY"
+"""
+
+# The retry delay is real wall-clock time, so skip it.
+SLEEP_STUB = """#!/bin/bash
+exit 0
+"""
+
+
+def _grep_supports_pcre() -> bool:
+    grep = shutil.which("grep")
+    if grep is None:
+        return False
+    result = subprocess.run([grep, "-qP", "x"], input="x", capture_output=True, text=True)
+    return result.returncode == 0
+
+
+# tor.sh parses the check.torproject.org reply with `grep -P`, which the BSD grep
+# on stock macOS does not have.
+requires_grep_pcre = pytest.mark.skipif(
+    not _grep_supports_pcre(), reason="grep with -P (PCRE) support is required"
+)
+
+
+def _run_tor_connectivity_check(tmp_path: Path, *, curl_failures: int, curl_body: str = ""):
+    """Run tor.sh's connectivity check against a fake curl.
+
+    Returns the completed process plus how many times curl was called.
+    """
+    bin_dir = tmp_path / "bin"
+    bin_dir.mkdir()
+    for name, source in (("curl", CURL_STUB), ("sleep", SLEEP_STUB)):
+        stub = bin_dir / name
+        stub.write_text(source)
+        stub.chmod(0o755)
+
+    notices_log = tmp_path / "notices.log"
+    notices_log.write_text("[warn] Failed to resolve check.torproject.org: no exit available\n")
+    curl_calls = tmp_path / "curl-calls"
+
+    grep = shutil.which("grep")
+    grep_dir = f"{Path(grep).parent}:" if grep else ""
+    script = TOR_SCRIPT_PATH.read_text()
+    block = script[script.index(VERIFY_BLOCK_START) : script.index(VERIFY_BLOCK_END)]
+    result = subprocess.run(
+        ["bash", "-c", "set -e\n" + block],
+        capture_output=True,
+        text=True,
+        env={
+            "PATH": f"{bin_dir}:{grep_dir}/usr/bin:/bin",
+            "TOR_NOTICES_LOG": str(notices_log),
+            "FAKE_CURL_CALLS": str(curl_calls),
+            "FAKE_CURL_FAILURES": str(curl_failures),
+            "FAKE_CURL_BODY": curl_body,
+        },
+        timeout=30,
+    )
+    calls = int(curl_calls.read_text()) if curl_calls.exists() else 0
+    return result, calls
+
+
 def test_tor_nat_rules_bypass_private_networks_before_tcp_redirect():
     lines = _tor_script_rule_lines()
     tcp_redirect_index = _line_index(lines, "--syn -j REDIRECT --to-ports 9040")
@@ -381,3 +522,139 @@ def test_tor_watchdog_escalates_to_container_reset_not_in_place_restart():
 
     assert "kill -TERM" in healthcheck_script
     assert "supervisorctl restart" not in healthcheck_script
+
+
+PREVIOUS_BOOT_LOG = (
+    "Oct 20 16:40:02.000 [notice] Bootstrapped 100% (done): Done\n"
+    "Oct 20 17:01:08.000 [notice] Catching signal TERM, exiting cleanly.\n"
+)
+
+
+@requires_bash
+def test_tor_bootstrap_wait_ignores_previous_boot_log(tmp_path):
+    """Regression test for issue #1502.
+
+    The container filesystem survives a restart, and Tor appends to its notices
+    log. The previous boot's "Bootstrapped 100%" line must not pass for this
+    boot's, or the NAT rules go live before Tor has connected to anything and
+    the container fails its connectivity check on every boot from then on.
+    """
+    result, _, _ = _run_tor_bootstrap_wait(
+        tmp_path,
+        previous_log=PREVIOUS_BOOT_LOG,
+        boot_line="Oct 20 17:01:30.000 [notice] Bootstrapped 5% (conn): Connecting to a relay",
+    )
+
+    assert "Tor bootstrap complete" not in result.stdout
+    assert "Tor bootstrap timed out" in result.stdout
+    assert result.returncode == 1
+
+
+@requires_bash
+def test_tor_keeps_previous_boot_log(tmp_path):
+    """Starting the new log must not throw away the previous boot's history."""
+    boot_line = "Oct 20 17:01:31.000 [notice] Bootstrapped 100% (done): Done"
+    result, notices_log, _ = _run_tor_bootstrap_wait(
+        tmp_path, previous_log=PREVIOUS_BOOT_LOG, boot_line=boot_line
+    )
+
+    assert result.returncode == 0, result.stdout + result.stderr
+    assert (tmp_path / "notices.log.prev").read_text() == PREVIOUS_BOOT_LOG
+    assert notices_log.read_text() == boot_line + "\n"
+
+
+@requires_bash
+def test_tor_hands_its_log_to_the_tor_account_before_starting_it(tmp_path):
+    """Tor opens its log after dropping root and refuses to start if it can't."""
+    result, notices_log, calls = _run_tor_bootstrap_wait(
+        tmp_path,
+        previous_log=PREVIOUS_BOOT_LOG,
+        boot_line="Oct 20 17:01:31.000 [notice] Bootstrapped 100% (done): Done",
+    )
+
+    assert result.returncode == 0, result.stdout + result.stderr
+    assert calls == [f"chown debian-tor {notices_log}", "supervisord"]
+
+
+def test_tor_drops_to_the_account_the_owner_exemption_matches():
+    """As root, Tor's own relay traffic was redirected back into its TransPort.
+
+    The NAT rules only exempt the Tor account's traffic, so Tor has to drop to
+    that same account, with a data directory that account owns.
+    """
+    script = TOR_SCRIPT_PATH.read_text()
+    torrc = script[script.index("cat <<EOF > /etc/tor/torrc") : script.index("\nEOF\n")]
+
+    assert "TOR_USER=debian-tor\n" in script
+    assert "User ${TOR_USER}\n" in torrc
+    assert "DataDirectory /var/lib/tor\n" in torrc
+    assert 'TOR_UID=$(id -u "$TOR_USER")' in _tor_iptables_block()
+
+
+@requires_bash
+def test_tor_bootstrap_wait_completes_on_first_boot(tmp_path):
+    """A container's first boot has no previous log to set aside."""
+    result, _, _ = _run_tor_bootstrap_wait(
+        tmp_path,
+        previous_log=None,
+        boot_line="Oct 20 16:40:02.000 [notice] Bootstrapped 100% (done): Done",
+    )
+
+    assert result.returncode == 0, result.stdout + result.stderr
+    assert "Tor bootstrap complete" in result.stdout
+    assert not (tmp_path / "notices.log.prev").exists()
+
+
+@requires_bash
+def test_tor_connectivity_check_failure_is_reported(tmp_path):
+    """Issue #1502: a failed check stopped the container without a word.
+
+    Under `set -e` curl's exit status (6, could not resolve host) ended tor.sh
+    before anything was logged. The failure, its cause and Tor's own view of it
+    have to reach the log.
+    """
+    result, curl_calls = _run_tor_connectivity_check(tmp_path, curl_failures=99)
+
+    assert result.returncode == 1
+    assert curl_calls == 3
+    assert "curl exit 6" in result.stdout
+    assert "Could not resolve host: check.torproject.org" in result.stdout
+    assert "Could not reach check.torproject.org through Tor" in result.stdout
+    assert "Failed to resolve check.torproject.org: no exit available" in result.stdout
+
+
+@requires_bash
+@requires_grep_pcre
+def test_tor_connectivity_check_retries_transient_failure(tmp_path):
+    """A fresh circuit failing its first lookup must not restart the container."""
+    result, curl_calls = _run_tor_connectivity_check(
+        tmp_path, curl_failures=1, curl_body='{"IsTor":true,"IP":"185.220.100.240"}'
+    )
+
+    assert result.returncode == 0, result.stdout + result.stderr
+    assert curl_calls == 2
+    assert "Success! Traffic is routed through Tor. Current IP: 185.220.100.240" in result.stdout
+
+
+@requires_bash
+@requires_grep_pcre
+def test_tor_connectivity_check_reports_unexpected_reply(tmp_path):
+    """A reply that is not the expected JSON must still say why tor.sh stopped."""
+    result, _ = _run_tor_connectivity_check(
+        tmp_path, curl_failures=0, curl_body="<html>Too Many Requests</html>"
+    )
+
+    assert result.returncode == 1
+    assert "Traffic is NOT using Tor" in result.stdout
+
+
+@requires_bash
+@requires_grep_pcre
+def test_tor_connectivity_check_still_fails_closed_on_clear_net(tmp_path):
+    """Traffic leaving outside Tor must still stop the container."""
+    result, _ = _run_tor_connectivity_check(
+        tmp_path, curl_failures=0, curl_body='{"IsTor":false,"IP":"203.0.113.7"}'
+    )
+
+    assert result.returncode == 1
+    assert "Traffic is NOT using Tor. Current IP: 203.0.113.7" in result.stdout

tor.sh

@@ -64,12 +64,22 @@ echo "Release version: $RELEASE_VERSION"
 echo "[*] Installing Tor and dependencies..."
 echo "[*] Writing Tor transparent proxy config..."
 
+TOR_NOTICES_LOG=/var/log/tor/notices.log
+# The account Tor drops to once its listeners are bound (DNSPort 53 needs root).
+# The NAT rules below exempt this account's traffic from the transparent
+# redirect. Tor used to stay root, which the exemption never matched, so every
+# relay connection Tor opened after the rules went live was redirected back
+# into its own TransPort.
+TOR_USER=debian-tor
+
 cat <<EOF > /etc/tor/torrc
+User ${TOR_USER}
+DataDirectory /var/lib/tor
 VirtualAddrNetworkIPv4 10.192.0.0/10
 AutomapHostsOnResolve 1
 TransPort 9040
 DNSPort 53
-Log notice file /var/log/tor/notices.log
+Log notice file ${TOR_NOTICES_LOG}
 
 # Circuit management to prevent stale circuits after inactivity
 MaxCircuitDirtiness 600
@@ -203,6 +213,21 @@ done
 HC
 chmod +x /app/tor_healthcheck.sh
 
+# Tor appends to its notices log, and the container filesystem survives a
+# restart (docker restart, a Docker daemon restart, a host reboot). The
+# "Bootstrapped 100%" line left by the previous boot made the wait below, and
+# the watchdog, treat a Tor that had not connected to anything yet as ready. The
+# NAT rules then went live too early and the connectivity check failed on every
+# boot from then on (#1502). Start each boot with an empty log and keep the
+# previous one.
+if [ -f "$TOR_NOTICES_LOG" ]; then
+    mv -f "$TOR_NOTICES_LOG" "${TOR_NOTICES_LOG}.prev" || true
+fi
+# Tor opens the log after it has dropped to TOR_USER, and refuses to start at
+# all if it cannot.
+: > "$TOR_NOTICES_LOG"
+chown "$TOR_USER" "$TOR_NOTICES_LOG"
+
 echo "[*] Starting Tor via Supervisor..."
 /usr/bin/supervisord -c /etc/supervisor/supervisord.conf
 
@@ -211,7 +236,7 @@ echo "[*] Waiting for Tor to finish bootstrapping... (up to 5 minutes)"
 BOOTSTRAP_TIMEOUT=300
 BOOTSTRAP_START=$(date +%s)
 while true; do
-    if grep -q "Bootstrapped 100%" /var/log/tor/notices.log 2>/dev/null; then
+    if grep -q "Bootstrapped 100%" "$TOR_NOTICES_LOG" 2>/dev/null; then
         echo ""
         echo "[✓] Tor bootstrap complete."
         break
@@ -224,7 +249,7 @@ while true; do
         exit 1
     fi
 
-    CURRENT_LOG=$(tail -n 1 /var/log/tor/notices.log 2>/dev/null || true)
+    CURRENT_LOG=$(tail -n 1 "$TOR_NOTICES_LOG" 2>/dev/null || true)
     printf "\r\033[K[%ds] %s" "$ELAPSED" "$CURRENT_LOG"
     sleep 1
 done
@@ -235,7 +260,7 @@ echo "[*] Setting up iptables rules..."
 
 iptables -F
 iptables -t nat -F
-TOR_UID=$(id -u debian-tor)
+TOR_UID=$(id -u "$TOR_USER")
 
 # Allow loopback
 iptables -t nat -A OUTPUT -o lo -j RETURN
@@ -278,10 +303,29 @@ echo "[✓] Transparent Tor routing enabled."
 sleep 5
 # Check if outgoing IP is using Tor
 echo "[*] Verifying Tor connectivity..."
-RESULT=$(curl -s https://check.torproject.org/api/ip)
+# A fresh circuit can fail its first lookup, so retry before giving up. Never
+# let a failed curl or an unparseable reply end the script on its own: under
+# `set -e` that stopped the container with no message, leaving only curl's
+# exit code in `docker inspect` (#1502).
+VERIFY_ATTEMPTS=3
+RESULT=""
+for ((attempt = 1; attempt <= VERIFY_ATTEMPTS; attempt++)); do
+    RESULT=$(curl -sS --max-time 30 https://check.torproject.org/api/ip 2>&1) && break
+    CURL_STATUS=$?
+    echo "[!] Tor connectivity check ${attempt}/${VERIFY_ATTEMPTS} failed (curl exit ${CURL_STATUS}): ${RESULT}"
+    RESULT=""
+    if [ "$attempt" -lt "$VERIFY_ATTEMPTS" ]; then
+        sleep 10
+    fi
+done
+if [ -z "$RESULT" ]; then
+    echo "[✗] Could not reach check.torproject.org through Tor. Last Tor log lines:"
+    tail -n 20 "$TOR_NOTICES_LOG" 2>/dev/null || true
+    exit 1
+fi
 echo "RESULT: $RESULT"
-IS_TOR=$(echo "$RESULT" | grep -oP '"IsTor":\s*\K(true|false)')
-IP=$(echo "$RESULT" | grep -oP '"IP":\s*"\K[^"]+')
+IS_TOR=$(echo "$RESULT" | grep -oP '"IsTor":\s*\K(true|false)' || true)
+IP=$(echo "$RESULT" | grep -oP '"IP":\s*"\K[^"]+' || true)
 if [[ "$IS_TOR" == "true" ]]; then
     echo "[✓] Success! Traffic is routed through Tor. Current IP: $IP"
 else