diff --git a/tests/spec/run.js b/tests/spec/run.js index 1d604de..e62988d 100644 --- a/tests/spec/run.js +++ b/tests/spec/run.js @@ -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(() => { }); } }