From 6ac2b861700e37869e636ecc5779cf8ea6e5a641 Mon Sep 17 00:00:00 2001 From: Hitesh Sharma Date: Tue, 10 Nov 2026 19:21:19 -0800 Subject: [PATCH 1/2] fix(devtools): wait for the MongoDB primary on a condition check-mongodb-auth fails intermittently with "create the administrator: MongoServerError: not primary" (main 2026-11-10 twice, merge queue for #830 and #901, and PR #923). Its readiness probe took a refused connection for success: mongosh prints "connect ECONNREFUSED 127.0.0.1:27081", which passes `.endswith("1")` on CI's port 27081. When mongod started slowly, rs.initiate ran against a closed port, its result was ignored, the primary loop ran out its 60 tries silently, and the next command reported the misleading "not primary". start_mongo had the probe fixed in #672 but also ignored the initiate. Both now call become_primary: one mongosh --nodb process waits for mongod to answer, initiates rs0 (skipped if hello already names a set), and waits for the election with an awaitable hello rather than sleep and retry, all against one deadline. A failure names the step that ran out of time with what it last saw and the container's log. Tested against a local mongod 7.0 with a key file through a docker stand-in: mongod started 5 s after the waiter (the CI race) became primary and took the first user under the localhost exception; a second call succeeds; with nothing listening it fails after its deadline naming the refused connection. --- devtools/catalog_checks.py | 73 +++++++++++++++++++++++++++++++------ devtools/check-mongodb-auth | 17 ++------- 2 files changed, 65 insertions(+), 25 deletions(-) diff --git a/devtools/catalog_checks.py b/devtools/catalog_checks.py index 3dc664bf8..0dca13a18 100644 --- a/devtools/catalog_checks.py +++ b/devtools/catalog_checks.py @@ -176,15 +176,64 @@ def start_mongo(container: str, port: int, mongod_args: tuple[str, ...] = (), mo ) if started.returncode != 0: return report(False, f"start {container}", started.stderr) - for _ in range(60): - # The whole output must be the `1`: a refused connection's error - # names the port, and a port ending in 1 would pass an `endswith`. - if mongosh(container, port, "db.runCommand({ping: 1}).ok")[1].strip() == "1": - break - time.sleep(1) - mongosh(container, port, f"rs.initiate({{_id: 'rs0', members: [{{_id: 0, host: 'localhost:{port}'}}]}})") - for _ in range(60): - if mongosh(container, port, "db.hello().isWritablePrimary")[1].strip().endswith("true"): - return True - time.sleep(1) - return report(False, f"{container} did not become primary", docker("logs", container).stdout[-2000:]) + return become_primary(container, port) + + +# Waits for mongod to answer, initiates the one-member set rs0 and waits for +# the member to be primary, all in one mongosh process against one deadline, +# so a slow start costs only time. Prints `primary`, or throws naming the +# step that ran out of time and what it last saw. The caller defines PORT and +# SECONDS. Every command here is allowed by the localhost exception. +_BECOME_PRIMARY_JS = """ +const deadline = Date.now() + SECONDS * 1000; +const left = () => deadline - Date.now(); +let last = "nothing tried"; +let admin = null; +while (admin === null) { + if (left() <= 0) throw new Error(`mongod on ${PORT} did not answer within ${SECONDS} s (last: ${last})`); + try { + const db = connect(`mongodb://localhost:${PORT}/admin?directConnection=true&serverSelectionTimeoutMS=1000`); + if (db.runCommand({ping: 1}).ok === 1) admin = db; + } catch (e) { + last = e.message; + sleep(100); + } +} +// An initiated member names its set in hello, which needs no login; once a +// user exists the localhost exception no longer allows replSetInitiate. +if (!admin.runCommand({hello: 1}).setName) { + const initiated = admin.runCommand( + {replSetInitiate: {_id: "rs0", members: [{_id: 0, host: `localhost:${PORT}`}]}}); + if (initiated.ok !== 1 && initiated.codeName !== "AlreadyInitialized") { + throw new Error(`replSetInitiate failed: ${JSON.stringify(initiated)}`); + } +} +// An awaitable hello answers when the topology changes, so this waits for +// the election instead of sleeping and asking again. +let hello = admin.runCommand({hello: 1}); +while (!hello.isWritablePrimary) { + if (left() <= 0) throw new Error(`not primary within ${SECONDS} s: ${JSON.stringify(hello)}`); + hello = admin.runCommand( + {hello: 1, topologyVersion: hello.topologyVersion, maxAwaitTimeMS: Math.min(left(), 10000)}); +} +print("primary"); +""" + + +def become_primary(container: str, port: int, seconds: int = 120) -> bool: + """Make the mongod in `container` on `port` a one-member replica set rs0 + and wait for it to be primary. The check fails with what mongosh last saw + and the end of the container's log, at the step that failed, instead of + at whatever command runs next.""" + script = f"const PORT = {port}, SECONDS = {seconds};\n{_BECOME_PRIMARY_JS}" + try: + done = docker("exec", container, "mongosh", "--nodb", "--quiet", "--eval", script, timeout=seconds + 30) + out = done.stdout + done.stderr + ok = done.returncode == 0 and out.strip() == "primary" + except subprocess.TimeoutExpired as e: + ok, out = False, f"mongosh did not finish within {seconds + 30} s\n{_text(e.stdout)}{_text(e.stderr)}" + if ok: + return True + logs = docker("logs", container) + return report(False, f"{container} becomes primary", f"{out}\n--- docker logs ---\n" + f"{(logs.stdout + logs.stderr)[-2000:]}") diff --git a/devtools/check-mongodb-auth b/devtools/check-mongodb-auth index d3bec4f95..dd8b47c0f 100755 --- a/devtools/check-mongodb-auth +++ b/devtools/check-mongodb-auth @@ -21,9 +21,8 @@ import shutil import subprocess import sys import tempfile -import time -from catalog_checks import docker, expect_exit, finish, healthy, report, run, start, stop +from catalog_checks import become_primary, docker, expect_exit, finish, healthy, report, run, start, stop HERE = os.path.dirname(os.path.realpath(__file__)) SEED = os.path.join(HERE, "..", "crates", "storage-mongodb", "tests", "fixtures", "released", "seed.py") @@ -47,17 +46,9 @@ def start_with_auth(container: str, port: int) -> bool: ) if not report(started.returncode == 0, f"start {container} with access control", started.stderr): return False - for _ in range(60): - if shell(container, port, "db.runCommand({ping: 1}).ok", root=False)[1].strip().endswith("1"): - break - time.sleep(1) - # The localhost exception allows the first user and the initiation. - shell(container, port, f"rs.initiate({{_id: 'rs0', members: [{{_id: 0, host: 'localhost:{port}'}}]}})", - root=False) - for _ in range(60): - if shell(container, port, "db.hello().isWritablePrimary", root=False)[1].strip().endswith("true"): - break - time.sleep(1) + # The localhost exception allows the initiation and the first user. + if not become_primary(container, port): + return False code, out = shell(container, port, f"db.getSiblingDB('admin').createUser({{user: 'root', pwd: " f"'{ROOT_PASSWORD}', roles: ['root']}})", root=False) if not report(code == 0, "create the administrator", out): From ea5da4615667beea21a4430df95d319b30ef6ed4 Mon Sep 17 00:00:00 2001 From: Hitesh Sharma Date: Tue, 10 Nov 2026 22:38:43 -0800 Subject: [PATCH 2/2] fix(devtools): Pause on error replies, read last line Address review on #952. become_primary required stdout and stderr together to be exactly `primary`, so a warning mongosh prints on either stream failed the step while the member was primary. It now reads the last line of stdout and keeps the combined output for the failure text. Two paths in the script looped with no pause until the deadline: a ping answering with ok other than 1 (opening a new connection each time), and a hello returning an error document, which has no topologyVersion to wait on. Both now sleep 100 ms; the ping path closes its connection and keeps the reply in `last`, and the hello timeout already names the last reply. --- devtools/catalog_checks.py | 26 +++++++++++++++++++++----- 1 file changed, 21 insertions(+), 5 deletions(-) diff --git a/devtools/catalog_checks.py b/devtools/catalog_checks.py index 0dca13a18..189aafe7e 100644 --- a/devtools/catalog_checks.py +++ b/devtools/catalog_checks.py @@ -193,7 +193,14 @@ def start_mongo(container: str, port: int, mongod_args: tuple[str, ...] = (), mo if (left() <= 0) throw new Error(`mongod on ${PORT} did not answer within ${SECONDS} s (last: ${last})`); try { const db = connect(`mongodb://localhost:${PORT}/admin?directConnection=true&serverSelectionTimeoutMS=1000`); - if (db.runCommand({ping: 1}).ok === 1) admin = db; + const pong = db.runCommand({ping: 1}); + if (pong.ok === 1) { + admin = db; + } else { + last = JSON.stringify(pong); + db.getMongo().close(); + sleep(100); + } } catch (e) { last = e.message; sleep(100); @@ -209,12 +216,18 @@ def start_mongo(container: str, port: int, mongod_args: tuple[str, ...] = (), mo } } // An awaitable hello answers when the topology changes, so this waits for -// the election instead of sleeping and asking again. +// the election instead of sleeping and asking again. An error reply has no +// topologyVersion to wait on, so that path pauses and asks plainly. let hello = admin.runCommand({hello: 1}); while (!hello.isWritablePrimary) { if (left() <= 0) throw new Error(`not primary within ${SECONDS} s: ${JSON.stringify(hello)}`); - hello = admin.runCommand( - {hello: 1, topologyVersion: hello.topologyVersion, maxAwaitTimeMS: Math.min(left(), 10000)}); + if (hello.ok === 1 && hello.topologyVersion) { + hello = admin.runCommand( + {hello: 1, topologyVersion: hello.topologyVersion, maxAwaitTimeMS: Math.min(left(), 10000)}); + } else { + sleep(100); + hello = admin.runCommand({hello: 1}); + } } print("primary"); """ @@ -229,7 +242,10 @@ def become_primary(container: str, port: int, seconds: int = 120) -> bool: try: done = docker("exec", container, "mongosh", "--nodb", "--quiet", "--eval", script, timeout=seconds + 30) out = done.stdout + done.stderr - ok = done.returncode == 0 and out.strip() == "primary" + # mongosh may add warnings on either stream; the script's own answer + # is the last line it prints. + lines = done.stdout.strip().splitlines() + ok = done.returncode == 0 and bool(lines) and lines[-1].strip() == "primary" except subprocess.TimeoutExpired as e: ok, out = False, f"mongosh did not finish within {seconds + 30} s\n{_text(e.stdout)}{_text(e.stderr)}" if ok: