summaryrefslogtreecommitdiff
path: root/jstests/noPassthrough/mirrored_reads_slow_query.js
blob: ef022901f9530403831146d08b365e2c3f701976 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
/**
 * Verify that mirroredReads that pass the slow query threshold set mirrored:true.
 *
 * @tags: [
 *   requires_replication,
 *   requires_fcv_61,
 * ]
 */

(function() {
"use strict";

function setParameter({rst, value}) {
    return rst.getPrimary().adminCommand({setParameter: 1, mirrorReads: value});
}

const kDbName = "test";
const kCollName = jsTestName();

function verifySlowLogsIndicateMirroredReads(rst, cmd) {
    jsTestLog("Verifying log message indicates mirrored operation for cmd '" + tojson(cmd));
    let primaryAdminDb = rst.getPrimary().getDB('admin');
    let secondaryAdminDb = rst.getSecondary().getDB('admin');

    rst.getPrimary().getDB(kDbName).runCommand(cmd);

    const logId = 51803;
    // Check that the primary slow log messages do not print with mirrored: true.
    assert(checkLog.checkContainsWithCountJson(primaryAdminDb,
                                               logId,
                                               {mirrored: true},
                                               /*expectedCount=*/ 0,
                                               /*severity=*/ null,
                                               /*isRelaxed=*/ true));
    assert.soon(() => {
        // Check that the secondary slow log message is printed with mirrored: true.
        return checkLog.checkContainsWithCountJson(
            secondaryAdminDb,
            logId,
            {mirrored: true, ns: kDbName.concat(".", kCollName)},
            /*expectedCount=*/ 1,
            /*severity=*/ null,
            /*isRelaxed=*/ true);
    });
    assert.commandWorked(secondaryAdminDb.adminCommand({clearLog: "global"}));
}

{
    const rst = new ReplSetTest({
        nodes: 2,
    });
    rst.startSet();
    rst.initiateWithHighElectionTimeout();

    // Put in a datum
    {
        let ret =
            rst.getPrimary().getDB(kDbName).runCommand({insert: kCollName, documents: [{x: 1}]});
        assert.commandWorked(ret);
    }

    // Set the slow query logging threshold (slowMS) to -1 to ensure every query gets logged on the
    // secondary.
    rst.getSecondary().getDB('admin').setProfilingLevel(0, -1);

    // Have every operation be mirrored.
    assert.commandWorked(setParameter({rst: rst, value: {samplingRate: 1.0}}));

    verifySlowLogsIndicateMirroredReads(rst, {find: kCollName, filter: {}});
    verifySlowLogsIndicateMirroredReads(rst, {count: kCollName, query: {}});
    verifySlowLogsIndicateMirroredReads(rst, {distinct: kCollName, key: "x"});
    verifySlowLogsIndicateMirroredReads(
        rst, {findAndModify: kCollName, query: {}, update: {'$inc': {x: 1}}});
    verifySlowLogsIndicateMirroredReads(
        rst, {update: kCollName, updates: [{q: {_id: 1}, u: {'$inc': {x: 1}}}], ordered: false});

    rst.stopSet();
}
})();