summaryrefslogtreecommitdiff
path: root/jstests/replsets/read_after_optime.js
blob: 30cf77826799e506f5fd981f91d578740f2982d7 (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
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
// Test read after opTime functionality with maxTimeMS.

(function() {
    "use strict";

    var replTest = new ReplSetTest({nodes: 2});
    replTest.startSet();
    replTest.initiate();
    var config = replTest.getReplSetConfigFromNode();

    var runTest = function(testDB, primaryConn) {
        primaryConn.getDB('test').user.insert({x: 1}, {writeConcern: {w: 2}});

        var localDB = primaryConn.getDB('local');

        var oplogTS = localDB.oplog.rs.find().sort({$natural: -1}).limit(1).next();
        var twoSecTS = new Timestamp(oplogTS.ts.getTime() + 2, 0);

        var term = -1;
        if (config.protocolVersion === 1) {
            term = oplogTS.t;
        }

        // Test timeout with maxTimeMS
        var runTimeoutTest = function() {
            var timeoutResult = assert.commandFailedWithCode(testDB.runCommand({
                find: 'user',
                filter: {x: 1},
                readConcern: {afterOpTime: {ts: twoSecTS, t: term}},
                maxTimeMS: 5000,
            }),
                                                             ErrorCodes.ExceededTimeLimit);
            assert.gt(timeoutResult.waitedMS, 500);
        };

        var countLogMessages = function(msg) {
            var total = 0;
            var logMessages = assert.commandWorked(testDB.adminCommand({getLog: 'global'})).log;
            for (var i = 0; i < logMessages.length; i++) {
                if (logMessages[i].indexOf(msg) != -1) {
                    total++;
                }
            }
            return total;
        };

        var checkLog = function(msg, expectedCount) {
            var count;
            assert.soon(
                function() {
                    count = countLogMessages(msg);
                    return expectedCount == count;
                },
                'Expected ' + expectedCount + ', but instead saw ' + count +
                    ' log entries containing the following message: ' + msg,
                60000,
                300);
        };

        // Run the time out test 3 times with replication debug log level increased to 2
        // for first and last run. The time out message should be logged twice.
        testDB.setLogLevel(2, 'command');
        runTimeoutTest();
        testDB.setLogLevel(0, 'command');

        var msg = 'Command on database ' + testDB.getName() +
            ' timed out waiting for read concern to be satisfied. Command:';
        checkLog(msg, 1);

        // Read concern timed out message should not be logged.
        runTimeoutTest();

        testDB.setLogLevel(2, 'command');
        runTimeoutTest();
        testDB.setLogLevel(0, 'command');

        checkLog(msg, 2);

        // Test read on future afterOpTime that will eventually occur.
        var insertFunc = startParallelShell(
            "sleep(2100); db.user.insert({ y: 1 }, { writeConcern: { w: 2 }});", primaryConn.port);

        var res = assert.commandWorked(testDB.runCommand({
            find: 'user',
            filter: {x: 1},
            readConcern: {
                afterOpTime: {ts: twoSecTS, t: term},
            },
            maxTimeMS: 10 * 1000,
        }));

        assert.eq(null, res.code);
        assert.gt(res.waitedMS, 0);

        insertFunc();
    };

    var primary = replTest.getPrimary();
    runTest(primary.getDB('test'), primary);
    runTest(replTest.getSecondary().getDB('test'), primary);

    replTest.stopSet();

})();