tests/spec: buffer command-monitoring events per client entity

Plumbing only: a client entity that declares `observeEvents` now gets
`monitorCommands` and a buffer, and nothing reads the buffer. That is the
point of splitting it out -- the totals not moving *is* this commit's test.
Command monitoring changes how the driver builds every command it sends, and
if that alone shifted a result there would be no way to tell it apart from
the assertions landing in the next commit.

193/99/195 before, 193/99/195 after, 175/175 files, 0 errored.

The rules the buffer already enforces, so that the next commit is only about
comparing: `ignoreCommandMonitoringEvents` by command name; sensitive commands
dropped unless `observeSensitiveCommands` says otherwise, with `hello` and
legacy hello inferred sensitive from the driver having redacted them to empty
documents (unified-test-format.md:3070-3075). Neither fires on this corpus --
136 client entities observe `commandStartedEvent`, 6 also
`commandSucceededEvent`, and not one sets either field -- but a rule that only
exists where it is exercised is a rule that will be missing when M7 brings
auth. `cmap` and `sdam` observations are collected by nobody; a test that goes
on to assert them is reported unsupported where it asserts, not where it
declares.

Two things about placement, both load-bearing. Listeners are attached after
`connect()`, so a client's own handshake is not in its own buffer -- measured
rather than assumed: with the buffers dumped, find.json's five cases show
exactly `find`, `getMore`, `getMore` and nothing else. And they are disabled
after the operations and before the outcome check
(unified-test-format.md:3081), plus again unconditionally in the teardown
`finally`, because the outcome check and the teardown both issue commands and
a buffer still growing through them would make the assertion a function of the
harness rather than of the engine.

`MFDB_DUMP_EVENTS=1` prints each case's buffer. That is how the handshake
question above was settled and how a failing event assertion will be triaged.
This commit is contained in:
A.Shakhmatov
2026-08-09 13:05:52 +03:00
parent afa5c6ef9d
commit 6560aec915

View File

@@ -490,9 +490,62 @@ async function seedInitialData(initialData) {
}
}
// ---------------------------------------------------------------------------
// Command monitoring
// ---------------------------------------------------------------------------
// The three event types a `client` entity can ask to observe that this runner
// can produce, mapped to the driver's own event names. `cmap` and `sdam` types
// are simply not collected; a test that goes on to *assert* them is reported
// unsupported at that point rather than here, so declaring an observation this
// runner ignores costs a case nothing.
const COMMAND_EVENTS = {
commandStartedEvent: 'commandStarted',
commandSucceededEvent: 'commandSucceeded',
commandFailedEvent: 'commandFailed',
};
// Sensitive commands, per the command-logging-and-monitoring spec's Security
// section. Events for these are dropped unless the entity sets
// `observeSensitiveCommands` (unified-test-format.md:3070-3075). None of them
// can be issued by this engine yet -- there is no auth and no user management
// before M7 -- so this is here to keep the rule where the rule belongs rather
// than to filter anything today.
const SENSITIVE_COMMANDS = new Set([
'authenticate', 'saslstart', 'saslcontinue', 'getnonce', 'createuser',
'updateuser', 'copydbgetnonce', 'copydbsaslstart', 'copydb',
]);
function isSensitive(ev) {
const name = String(ev.commandName || '').toLowerCase();
if (SENSITIVE_COMMANDS.has(name)) return true;
// `hello` and legacy hello are sensitive only when they carry
// `speculativeAuthenticate`, which the driver does not report either way --
// it redacts both the command and the reply to an empty document, and the
// spec says to infer sensitivity from exactly that.
if (name === 'hello' || name === 'ismaster') {
const body = ev.command || ev.reply;
return !!body && Object.keys(body).length === 0;
}
return false;
}
// Listeners are disabled rather than removed, and disabled before the outcome
// check rather than after it (unified-test-format.md:3081): the teardown that
// follows a case issues commands of its own, and a buffer that kept growing
// through it would make the assertion a function of the harness.
function disableEvents(events) {
if (process.env.MFDB_DUMP_EVENTS) {
for (const [id, buf] of events) console.log(` events ${id}: ${buf.map((e) => `${e.kind}:${e.ev.commandName}`).join(', ')}`);
}
for (const buf of events.values()) buf.enabled = false;
}
// `clients` is supplied by the caller so that entities created before a
// failure are still closed: returning them only on success is what leaked.
async function buildEntities(url, createEntities, clients) {
// `events` is supplied for the same reason -- a case that dies partway still
// has to be able to turn its listeners off.
async function buildEntities(url, createEntities, clients, events) {
const map = {};
for (const spec of createEntities || []) {
const [kind, def] = Object.entries(spec)[0];
@@ -506,10 +559,12 @@ async function buildEntities(url, createEntities, clients) {
// buildEntities -- can create further clients *after* cleanup
// has already run. That is what leaked, and what turned into
// 190 phantom timeout FAILs.
const observed = (def.observeEvents || []).filter((e) => e in COMMAND_EVENTS);
const c = new MongoClient(url, Object.assign({
serverSelectionTimeoutMS: 2000,
connectTimeoutMS: 2000,
timeoutMS: OP_TIMEOUT_MS,
monitorCommands: observed.length > 0,
}, def.uriOptions || {}));
// Registered before connect, so a client whose connect throws
// or is abandoned is still closed by the caller.
@@ -520,6 +575,23 @@ async function buildEntities(url, createEntities, clients) {
await c.close().catch(() => { });
throw new Error('case abandoned');
}
// Subscribed after connect, so the handshake this client just
// performed is not in its own buffer.
if (observed.length) {
const ignore = new Set((def.ignoreCommandMonitoringEvents || []).map((s) => String(s).toLowerCase()));
const buf = [];
buf.enabled = true;
events.set(def.id, buf);
for (const name of observed) {
const kind = name.replace(/Event$/, '');
c.on(COMMAND_EVENTS[name], (ev) => {
if (!buf.enabled) return;
if (ignore.has(String(ev.commandName).toLowerCase())) return;
if (!def.observeSensitiveCommands && isSensitive(ev)) return;
buf.push({ kind, ev });
});
}
}
map[def.id] = c;
break;
}
@@ -531,7 +603,7 @@ async function buildEntities(url, createEntities, clients) {
default: throw new Unsupported(`entity type ${kind}`);
}
}
return { map, clients };
return { map, clients, events };
}
async function verifyOutcome(outcome, entities) {
@@ -570,11 +642,13 @@ async function runFile(file, url, server) {
// Owned out here, not by buildEntities, so a case that dies partway
// still has every client it managed to open closed below.
const clients = [];
const events = new Map();
try {
await withTimeout(async () => {
await seedInitialData(doc.initialData);
const entities = await buildEntities(url, doc.createEntities, clients);
const entities = await buildEntities(url, doc.createEntities, clients, events);
for (const op of test.operations) await runOne(op, entities);
disableEvents(events);
await verifyOutcome(test.outcome, entities);
}, CASE_TIMEOUT_MS, `case exceeded ${CASE_TIMEOUT_MS} ms`);
out.pass++;
@@ -587,6 +661,7 @@ async function runFile(file, url, server) {
// its continuation may still be running and about to open another
// client, which buildEntities closes itself on seeing this.
clients.abandoned = true;
disableEvents(events);
for (const c of clients) await c.close().catch(() => { });
}
}