path: root/jstests/noPassthrough/log_format_slowms_samplerate_loglevel.js

/**
 * Confirms that log output for each operation adheres to the expected, consistent format, including
 * query/write metrics where applicable, on both mongoD and mongoS and under both legacy and command
 * protocols.
 * @tags: [requires_replication, requires_sharding]
 */
(function() {
"use strict";

// This test looks for exact matches in log output, which does not account for implicit
// sessions.
TestData.disableImplicitSessions = true;

load("jstests/libs/fixture_helpers.js");  // For FixtureHelpers.

// Prevent the mongo shell from gossiping its cluster time, since this will increase the amount
// of data logged for each op. For some of the testcases below, including the cluster time would
// cause them to be truncated at the 512-byte RamLog limit, and some of the fields we need to
// check would be lost.
TestData.skipGossipingClusterTime = true;

// Set up a 2-shard single-node replicaset cluster.
const stParams = {
    name: jsTestName(),
    shards: 2,
    rs: {nodes: 1}
};
const st = new ShardingTest(stParams);

// Obtain one mongoS connection and a second direct to the shard.
const shardConn = st.rs0.getPrimary();
const mongosConn = st.s;

const dbName = "logtest";

const mongosDB = mongosConn.getDB(dbName);
const shardDB = shardConn.getDB(dbName);

// Enable sharding on the the test database and ensure that the primary is on shard0.
assert.commandWorked(mongosDB.adminCommand({enableSharding: mongosDB.getName()}));
st.ensurePrimaryShard(mongosDB.getName(), shardConn.name);

// Drops and re-shards the test collection, then splits at {_id: 0} and moves the upper chunk to
// the second shard.
function dropAndRecreateTestCollection() {
    assert(mongosDB.test.drop());
    st.shardColl(mongosDB.test, {_id: 1}, {_id: 0}, {_id: 1}, mongosDB.getName(), true);
}

// Configures logging parameters on the target environment, constructs a list of test operations
// depending on the deployment type, runs each of these in turn, and searches the logs for the
// corresponding output. Returns a pair of arrays [testsRun, logLines]; the former is the set of
// test cases that were run, while the latter contains the logline for each test, or null if no
// such logline was found.
function runLoggingTests({db, readWriteMode, slowMs, logLevel, sampleRate}) {
    dropAndRecreateTestCollection();

    const coll = db.test;

    // Transparently handles assert.writeOK for legacy writes.
    function assertWriteOK(writeResponse) {
        if (!writeResponse) {
            assert(db.getMongo().writeMode !== "commands");
            assert(db.runCommand({getLastError: 1}).err == null);
        } else {
            assert.commandWorked(writeResponse);
        }
    }

    for (let i = 1; i <= 5; ++i) {
        assertWriteOK(coll.insert({_id: i, a: i, loc: {type: "Point", coordinates: [i, i]}}));
        assertWriteOK(coll.insert({_id: -i, a: -i, loc: {type: "Point", coordinates: [-i, -i]}}));
    }
    assertWriteOK(coll.createIndex({loc: "2dsphere"}));

    const isMongos = FixtureHelpers.isMongos(db);

    // Set the shell read/write mode.
    db.getMongo().forceWriteMode(readWriteMode);
    db.getMongo().forceReadMode(readWriteMode);

    // Build a string that identifies the parameters of this test run. Individual ops will
    // use this string as their comment where applicable, and we also print it to the logs.
    const logFormatTestComment = (isMongos ? 'mongos' : 'mongod') + "_" + readWriteMode +
        "_slowms:" + slowMs + "_logLevel:" + logLevel + "_sampleRate:" + sampleRate;
    jsTestLog(logFormatTestComment);

    // Set all logging parameters. If slowMs is null, we set a high threshold here so that
    // logLevel can be tested in cases where operations should not otherwise be logged.
    assert.commandWorked(db.adminCommand(
        {profile: 0, slowms: (slowMs == null) ? 1000000 : slowMs, sampleRate: sampleRate}));
    assert.commandWorked(db.setLogLevel(logLevel, "command"));
    assert.commandWorked(db.setLogLevel(logLevel, "write"));

    // Certain fields in the log lines on mongoD are not applicable in their counterparts on
    // mongoS, and vice-versa. Ignore these fields when examining the logs of an instance on
    // which we do not expect them to appear.
    const ignoreFields =
            (isMongos
                 ? ["docsExamined", "keysExamined", "keysInserted", "keysDeleted", "planSummary", 
					 "usedDisk", "hasSortStage"]
                 : ["nShards"]);

    // Legacy operations do not produce a 'command: <name>' field in the log.
    if (readWriteMode === "legacy") {
        ignoreFields.push("command");
    }

    function confirmLogContents(db, {test, logFields}, testIndex) {
        // Clear the log before running the test, to guarantee that we do not match against any
        // similar tests which may have run previously.
        assert.commandWorked(db.adminCommand({clearLog: "global"}));

        // Run the given command in order to generate a log line. If slowMs is non-null and
        // greater than 0, apply that slowMs to every second test.
        if (slowMs != null && slowMs > 0) {
            db.adminCommand({profile: 0, slowms: (testIndex % 2 ? slowMs : -1)});
        }
        assert.doesNotThrow(() => test(db));

        // Confirm whether the operation was logged or not.
        const globalLog = assert.commandWorked(db.adminCommand({getLog: "global"}));
        return findMatchingLogLine(globalLog.log, logFields, ignoreFields);
    }

    //
    // Defines the set of test operations and associated log output fields.
    //
    const testList = [
        {
            test: function(db) {
                assert.eq(db.test
                              .aggregate([{$match: {a: 1}}], {
                                  comment: logFormatTestComment,
                                  collation: {locale: "fr"},
                                  hint: {_id: 1},
                              })
                              .itcount(),
                          1);
            },
            logFields: {
                command: "aggregate",
                aggregate: coll.getName(),
                pipeline: [{$match: {a: 1}}],
                comment: logFormatTestComment,
                collation: {locale: "fr"},
                hint: {_id: 1},
                planSummary: "IXSCAN { _id: 1 }",
                cursorExhausted: 1,
                docsExamined: 10,
                keysExamined: 10,
                nreturned: 1,
                nShards: stParams.shards
            }
        },
        {
            test: function(db) {
                assert.eq(db.test.find({a: 1, $comment: logFormatTestComment})
                              .collation({locale: "fr"})
                              .count(),
                          1);
            },
            logFields: {
                command: "count",
                count: coll.getName(),
                query: {a: 1, $comment: logFormatTestComment},
                collation: {locale: "fr"},
                planSummary: "COLLSCAN"
            }
        },
        {
            test: function(db) {
                assert.eq(
                    db.test.distinct(
                        "a", {a: 1, $comment: logFormatTestComment}, {collation: {locale: "fr"}}),
                    [1]);
            },
            logFields: {
                command: "distinct",
                distinct: coll.getName(),
                query: {a: 1, $comment: logFormatTestComment},
                planSummary: "COLLSCAN",
                $comment: logFormatTestComment,
                collation: {locale: "fr"}
            }
        },
        {
            test: function(db) {
                assert.eq(db.test.find({_id: 1}).comment(logFormatTestComment).itcount(), 1);
            },
            logFields: {
                command: "find",
                find: coll.getName(),
                comment: logFormatTestComment,
                planSummary: "IDHACK",
                cursorExhausted: 1,
                keysExamined: 1,
                docsExamined: 1,
                nreturned: 1,
                nShards: 1
            }
        },
        {
            test: function(db) {
                assert.eq(db.test.findAndModify({
                    query: {_id: 1, a: 1, $comment: logFormatTestComment},
                    update: {$inc: {b: 1}},
                    collation: {locale: "fr"}
                }),
                          {_id: 1, a: 1, loc: {type: "Point", coordinates: [1, 1]}});
            },
            // TODO SERVER-34208: display FAM update metrics in mongoS logs.
            logFields: Object.assign((isMongos ? {} : {nMatched: 1, nModified: 1}), {
                command: "findAndModify",
                findandmodify: coll.getName(),
                planSummary: "IXSCAN { _id: 1 }",
                keysExamined: 1,
                docsExamined: 1,
                $comment: logFormatTestComment,
                collation: {locale: "fr"}
            })
        },
        {
            test: function(db) {
                assert.commandWorked(db.test.mapReduce(() => {}, (a, b) => {}, {
                    query: {$comment: logFormatTestComment},
                    out: {inline: 1},
                }));
            },
            logFields: {
                command: "mapReduce",
                mapreduce: coll.getName(),
                planSummary: "COLLSCAN",
                keysExamined: 0,
                docsExamined: 10,
                $comment: logFormatTestComment,
                out: {inline: 1}
            }
        },
        {
            test: function(db) {
                assertWriteOK(db.test.update(
                    {a: 1, $comment: logFormatTestComment}, {$inc: {b: 1}}, {multi: true}));
            },
            logFields: (isMongos ? {
                command: "update",
                update: coll.getName(),
                ordered: true,
                nMatched: 1,
                nModified: 1,
                nShards: stParams.shards
            }
                                 : {
                                       q: {a: 1, $comment: logFormatTestComment},
                                       u: {$inc: {b: 1}},
                                       multi: true,
                                       planSummary: "COLLSCAN",
                                       keysExamined: 0,
                                       docsExamined: 10,
                                       nMatched: 1,
                                       nModified: 1
                                   })
        },
        {
            test: function(db) {
                assertWriteOK(db.test.update({_id: 100, $comment: logFormatTestComment},
                                             {$inc: {b: 1}},
                                             {multi: true, upsert: true}));
            },
            logFields: (isMongos ? {
                command: "update",
                update: coll.getName(),
                ordered: true,
                nMatched: 0,
                nModified: 0,
                upsert: 1,
                nShards: 1
            }
                                 : {
                                       q: {_id: 100, $comment: logFormatTestComment},
                                       u: {$inc: {b: 1}},
                                       multi: true,
                                       planSummary: "IXSCAN { _id: 1 }",
                                       keysExamined: 0,
                                       docsExamined: 0,
                                       nMatched: 0,
                                       nModified: 0,
                                       upsert: 1
                                   })
        },
        {
            test: function(db) {
                assertWriteOK(db.test.insert({z: 1, comment: logFormatTestComment}));
            },
            logFields: {
                command: "insert",
                insert: `${coll.getName()}|${coll.getFullName()}`,
                keysInserted: 1,
                ninserted: 1,
                nShards: 1
            }
        },
        {
            test: function(db) {
                assertWriteOK(db.test.remove({z: 1, $comment: logFormatTestComment}));
            },
            logFields: (isMongos ? {
                command: "delete",
                delete: coll.getName(),
                ordered: true,
                ndeleted: 1,
                nShards: stParams.shards
            }
                                 : {
                                       q: {z: 1, $comment: logFormatTestComment},
                                       limit: 0,
                                       planSummary: "COLLSCAN",
                                       keysExamined: 0,
                                       docsExamined: 12,
                                       ndeleted: 1,
                                       keysDeleted: 1
                                   })
        },
        {
            test: function(db) {
                const originalSortBytes = db.adminCommand(
                    {getParameter: 1, internalQueryMaxBlockingSortMemoryUsageBytes: 1});
                assert.commandWorked(originalSortBytes);
                assert.commandWorked(db.adminCommand(
                    {setParameter: 1, internalQueryMaxBlockingSortMemoryUsageBytes: 10}));
                assert.eq(coll.aggregate([{$match: {a: 1}}, {$sort: {a: 1}}], {allowDiskUse: true})
                              .itcount(),
                          1);
                assert.commandWorked(db.adminCommand({
                    setParameter: 1,
                    internalQueryMaxBlockingSortMemoryUsageBytes:
                        originalSortBytes.internalQueryMaxBlockingSortMemoryUsageBytes
                }));
            },
            logFields:
                {command: "aggregate", aggregate: coll.getName(), hasSortStage: 1, usedDisk: 1}
        }
    ];

    // Confirm log contains collation for find command.
    if (readWriteMode === "commands") {
        testList.push({
            test: function(db) {
                assert.eq(db.test.find({_id: {$in: [1, 5]}})
                              .comment(logFormatTestComment)
                              .collation({locale: "fr"})
                              .itcount(),
                          2);
            },
            logFields: {
                command: "find",
                find: coll.getName(),
                planSummary: "IXSCAN { _id: 1 }",
                comment: logFormatTestComment,
                collation: {locale: "fr"},
                cursorExhausted: 1,
                keysExamined: 4,
                docsExamined: 2,
                nreturned: 2,
                nShards: 1
            }
        });
    }

    // Confirm log content for getMore on both find and aggregate cursors.
    const originatingCommands = {
        find: {find: coll.getName(), batchSize: 0},
        aggregate: {aggregate: coll.getName(), pipeline: [], cursor: {batchSize: 0}}
    };

    for (let cmdName in originatingCommands) {
        const cmdObj = originatingCommands[cmdName];
        const cmdRes = assert.commandWorked(db.runCommand(cmdObj));

        testList.push({
            test: function(db) {
                const cursor = new DBCommandCursor(db, cmdRes);
                assert.eq(cursor.itcount(), 11);
            },
            logFields: Object.assign({getMore: cmdRes.cursor.id}, cmdObj, {
                cursorid: cmdRes.cursor.id,
                planSummary: "COLLSCAN",
                cursorExhausted: 1,
                docsExamined: 11,
                keysExamined: 0,
                nreturned: 11,
                nShards: stParams.shards
            })
        });
    }

    // Run each of the test in the array, recording the log line found for each.
    const logLines =
        testList.map((testCase, arrIndex) => confirmLogContents(db, testCase, arrIndex));

    return [testList, logLines];
}

//
// Helper functions.
//

// Finds and returns a logline containing all the specified fields, or null if no such logline
// was found. The regex escape function used here is drawn from the following:
// https://stackoverflow.com/questions/3561493/is-there-a-regexp-escape-function-in-javascript
// https://github.com/ljharb/regexp.escape
function findMatchingLogLine(logLines, fields, ignoreFields) {
    function escapeRegex(input) {
        return (typeof input === "string" ? input.replace(/[\^\$\\\.\*\+\?\(\)\[\]\{\}]/g, '\\$&')
                                          : input);
    }
    function lineMatches(line, fields, ignoreFields) {
        const fieldNames =
            Object.keys(fields).filter((fieldName) => !ignoreFields.includes(fieldName));
        return fieldNames.every((fieldName) => {
            const fieldValue = fields[fieldName];
            let regex = escapeRegex(fieldName) + ":? ?(" +
                escapeRegex(checkLog.formatAsLogLine(fieldValue)) + "|" +
                escapeRegex(checkLog.formatAsLogLine(fieldValue, true)) + ")";
            const match = line.match(regex);
            return match && match[0];
        });
    }

    for (let line of logLines) {
        if (lineMatches(line, fields, ignoreFields)) {
            return line;
        }
    }
    return null;
}

// In cases where some tests were not logged, this helper will identify and return them.
function getUnloggedTests(testsRun, logLines) {
    return testsRun.filter((testCase, arrIndex) => !logLines[arrIndex]);
}

//
// Test cases for varying values of logLevel, slowms, and sampleRate.
//

for (let testDB of [shardDB, mongosDB]) {
    for (let readWriteMode of ["commands", "legacy"]) {
        // Test that all operations are logged when slowMs is < 0 and sampleRate is 1 at the
        // default logLevel.
        let [testsRun, logLines] = runLoggingTests(
            {db: testDB, readWriteMode: readWriteMode, slowMs: -1, logLevel: 0, sampleRate: 1.0});
        let unlogged = getUnloggedTests(testsRun, logLines);
        assert.eq(unlogged.length, 0, () => tojson(unlogged));

        // Test that only some operations are logged when sampleRate is < 1 at the default
        // logLevel, even when slowMs is < 0. The actual sample rate is probabilistic, and may
        // therefore vary quite significantly from 0.5. However, we have already established
        // that with sampleRate 1 *all* ops are logged, so here it is sufficient to confirm that
        // some ops are not. We repeat the test 5 times to minimize the odds of failure.
        let sampleRateTestsRun = 0, sampleRateTestsLogged = 0;
        for (let i = 0; i < 5; i++) {
            [testsRun, logLines] = runLoggingTests({
                db: testDB,
                readWriteMode: readWriteMode,
                slowMs: -1,
                logLevel: 0,
                sampleRate: 0.5
            });
            unlogged = getUnloggedTests(testsRun, logLines);
            sampleRateTestsLogged += (testsRun.length - unlogged.length);
            sampleRateTestsRun += testsRun.length;
        }
        assert.betweenEx(0, sampleRateTestsLogged, sampleRateTestsRun);

        // Test that only operations which exceed slowMs are logged when slowMs > 0 and
        // sampleRate is 1, at the default logLevel. The given value of slowMs will be applied
        // to every second op in the test, so only half of the ops should be logged.
        [testsRun, logLines] = runLoggingTests({
            db: testDB,
            readWriteMode: readWriteMode,
            slowMs: 1000000,
            logLevel: 0,
            sampleRate: 1.0
        });
        unlogged = getUnloggedTests(testsRun, logLines);
        assert.eq(unlogged.length, Math.floor(testsRun.length / 2), () => tojson(unlogged));

        // Test that all operations are logged when logLevel is 1, regardless of sampleRate and
        // slowMs. We pass 'null' for slowMs to signify that a high threshold should be set
        // (such that, at logLevel 0, no operations would be logged) and that this value should
        // be applied for all operations, rather than for every second op as in the case of the
        // slowMs test.
        [testsRun, logLines] = runLoggingTests(
            {db: testDB, readWriteMode: readWriteMode, slowMs: null, logLevel: 1, sampleRate: 0.5});
        unlogged = getUnloggedTests(testsRun, logLines);
        assert.eq(unlogged.length, 0, () => tojson(unlogged));
    }
}
st.stop();
})();