SERVER-108870: "searchScore"/"vectorSearchScore" warning log should only be logged when invalid usage (#39703)

GitOrigin-RevId: 2eccff6039929394453ffca59f30a6d1cba738ba
This commit is contained in:
Will Buerger 2025-08-06 13:18:08 -04:00 committed by MongoDB Bot
parent 8f2c658842
commit f0cb4751ff
3 changed files with 111 additions and 16 deletions

View File

@ -2,6 +2,14 @@
* Tests that when "searchScore" and "vectorSearchScore" metadata fields are referenced in an
* invalid way, a warning log line will occasionally be printed to the logs.
*
* The test in with_mongot/e2e/metadata/search_score_meta_validation_warning_log.js is responsible
* for testing that the warning log lines are _not_ printed when the metadata is referenced
* correctly.
*
* The testing must be separate since this test requires noPassthrough to manually check the
* correct node's logs, but the other test requires a real mongot to run valid $search/$vectorSearch
* queries. We do not have the infrastructure to run a noPassthrough test on a real mongot.
*
* @tags: [requires_fcv_82]
*/
import {iterateMatchingLogLines} from "jstests/libs/log.js";

View File

@ -0,0 +1,85 @@
/**
* Tests that when "searchScore" and "vectorSearchScore" metadata fields are referenced
* in a _valid_ way, no warning log lines are printed.
*
* The test in noPassthrough/query/search_score_meta_validation_warning_log.js is responsible
* for testing that the warning log lines _are_ printed when the metadata is referenced incorrectly.
*
* The testing must be separate since this test requires a valid $search/$vectorSearch query run on
* mongot, but the other test requires noPassthrough to manually check the correct node's logs. We
* do not have the infrastructure to run a noPassthrough test on a real mongot.
*
* @tags: [requires_fcv_82]
*/
import {iterateMatchingLogLines} from "jstests/libs/log.js";
const warningLogMessage =
"The query attempts to retrieve metadata at a place in the pipeline where that metadata type is not available";
const dbName = "test";
const collName = "search_score_meta_validation_e2e";
const data = [
{a: 1, b: "foo", score: 10},
{a: 2, b: "bar", score: 20},
{a: 3, b: "baz", score: 30},
{a: 4, b: "qux", score: 40},
{a: 5, b: "quux", score: 50},
];
function checkNoWarningLogs(db) {
const globalLogs = db.adminCommand({getLog: 'global'});
const matchingLogLines = [...iterateMatchingLogLines(globalLogs.log, {msg: warningLogMessage})];
assert.eq(matchingLogLines.length, 0, matchingLogLines);
}
const testDB = db.getSiblingDB(dbName);
const coll = testDB.getCollection(collName);
coll.drop();
assert.commandWorked(coll.insertMany(data));
// Clear logs before running.
assert.commandWorked(testDB.adminCommand({clearLog: "global"}));
function runValidQueries() {
// Valid $meta: "searchScore" usage in $project.
assert.commandWorked(testDB.runCommand({
aggregate: collName,
pipeline: [
{$search: {text: {query: "foo", path: "b"}}},
{$project: {_id: 0, b: 1, score: {$meta: "searchScore"}}}
],
cursor: {}
}));
// Valid $meta: "vectorSearchScore" usage in $project.
assert.commandWorked(testDB.runCommand({
aggregate: collName,
pipeline: [
{
$vectorSearch: {
queryVector: [0.1, 0.2, 0.3],
path: "embedding",
numCandidates: 5,
index: "vector_index",
limit: 5
}
},
{$project: {_id: 0, b: 1, score: {$meta: "vectorSearchScore"}}}
],
cursor: {}
}));
}
runValidQueries();
// Check that no warning logs are present.
checkNoWarningLogs(testDB);
// Check that we can run valid queries multiple times without generating warning logs.
for (let i = 0; i < 50; i++) {
runValidQueries();
}
// Check that still no warning logs are present.
checkNoWarningLogs(testDB);

View File

@ -138,23 +138,25 @@ void DepsTracker::setNeedsMetadata(DocumentMetadataFields::MetaType type) {
if (shouldBeValidated) {
auto& availableMetadataBitSet = std::get<QueryMetadataBitSet>(_availableMetadata);
// Occasionally log a message in the logs when this error is hit for gently validated
// fields.
if (kMetadataFieldsToBeGentlyValidatedWithTicker.contains(type) &&
kMetadataFieldsToBeGentlyValidatedWithTicker.at(type).tick()) {
LOGV2_WARNING(10846800,
"The query attempts to retrieve metadata at a place in the pipeline "
"where that metadata type is not available",
"metadataType"_attr =
DocumentMetadataFields::typeNameToDebugString(type));
}
// If the metadata type is not available, we either log a warning or throw an error.
if (!availableMetadataBitSet[type]) {
// Occasionally log a message in the logs when this error is hit for gently validated
// fields.
if (kMetadataFieldsToBeGentlyValidatedWithTicker.contains(type) &&
kMetadataFieldsToBeGentlyValidatedWithTicker.at(type).tick()) {
LOGV2_WARNING(10846800,
"The query attempts to retrieve metadata at a place in the pipeline "
"where that metadata type is not available",
"metadataType"_attr =
DocumentMetadataFields::typeNameToDebugString(type));
}
// uassert for stages that should be strictly validated.
if (kMetadataFieldsToBeStrictlyValidated.contains(type)) {
uassert(40218,
str::stream() << "query requires " << type
<< " metadata, but it is not available",
availableMetadataBitSet[type]);
// uassert for stages that should be strictly validated.
if (kMetadataFieldsToBeStrictlyValidated.contains(type)) {
uasserted(40218,
str::stream()
<< "query requires " << type << " metadata, but it is not available");
}
}
}