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
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
|
/**
* Tests for the connection establishment metrics.
*
* @tags: [requires_fcv_63]
*/
(function() {
"use strict";
load("jstests/libs/fail_point_util.js");
load("jstests/libs/log.js");
load("jstests/libs/parallel_shell_helpers.js");
function hasNonNegativeAttr(entry, attrName) {
return entry.attr.hasOwnProperty(attrName) && entry.attr[attrName] >= 0;
}
function hasNullAttr(entry, attrName) {
return entry.attr.hasOwnProperty(attrName) && entry.attr[attrName] == null;
}
function hasOptionalMillisAttr(entry, attrName) {
return hasNullAttr(entry, attrName) || hasNonNegativeAttr(entry, attrName + 'Millis');
}
function validateSlowConnectionLogEntry(entry) {
assert(entry.hasOwnProperty('attr'));
assert(entry.attr.hasOwnProperty('hostAndPort'));
assert(hasNonNegativeAttr(entry, 'dnsResolutionTimeMillis'));
assert(hasNonNegativeAttr(entry, 'tcpConnectionTimeMillis'));
assert(hasOptionalMillisAttr(entry, 'tlsHandshakeTime'));
assert(hasNonNegativeAttr(entry, 'authTimeMillis'));
assert(hasOptionalMillisAttr(entry, 'hookTime'));
assert(hasNonNegativeAttr(entry, 'totalTimeMillis'));
let total = entry.attr.dnsResolutionTimeMillis + entry.attr.tcpConnectionTimeMillis +
entry.attr.authTimeMillis;
if (entry.attr.tlsHandshakeTimeMillis >= 0) {
total += entry.attr.tlsHandshakeTimeMillis;
}
if (entry.attr.hookTimeMillis >= 0) {
total += entry.attr.hookTimeMillis;
}
assert.eq(total, entry.attr.totalTimeMillis);
}
function validateLogAndExtractEntry(st) {
const mongosLog = assert.commandWorked(st.s.adminCommand({getLog: "global"}));
let queryLogEntry = null;
for (const line of findMatchingLogLines(mongosLog.log, {id: 6496400})) {
let entry = JSON.parse(line);
validateSlowConnectionLogEntry(entry);
if (entry.attr.totalTimeMillis >= kConnectionEstablishmentDelayMillis) {
queryLogEntry = entry;
}
}
return queryLogEntry;
}
function validateLogAndExtractCountAndEntry(st) {
const mongosLog = assert.commandWorked(st.s.adminCommand({getLog: "global"}));
let queryLogEntry = null;
let matchingLines = findMatchingLogLines(mongosLog.log, {id: 6496400});
for (const line of matchingLines) {
let entry = JSON.parse(line);
validateSlowConnectionLogEntry(entry);
if (entry.attr.totalTimeMillis >= kConnectionEstablishmentDelayMillis) {
queryLogEntry = entry;
}
}
return {count: matchingLines.length, entry: queryLogEntry};
}
const kConnectionEstablishmentDelayMillis = 250;
const kDBName = 'TestDB';
const kCollectionName = 'sharded_coll';
const kKeyName = 'foo';
let runTest = (connectionHealthLoggingOn) => {
let st = new ShardingTest({shards: 1});
if (!connectionHealthLoggingOn) {
assert.commandWorked(st.s.adminCommand(
{setParameter: 1, enableDetailedConnectionHealthMetricLogLines: false}));
}
const initialLogEntryCount = validateLogAndExtractCountAndEntry(st).count;
jsTestLog("Setting up the test collection.");
assert.commandWorked(st.s.adminCommand({enableSharding: kDBName}));
assert.commandWorked(st.s.adminCommand(
{shardcollection: `${kDBName}.${kCollectionName}`, key: {[kKeyName]: 1}}));
let db = st.getDB(kDBName);
assert.commandWorked(db[kCollectionName].insertOne({primaryOnly: true, [kKeyName]: 42}));
jsTestLog("Activating the delay in connection establishment.");
let connDelayFailPoint = configureFailPoint(
st.s, 'asioTransportLayerDelayConnection', {millis: kConnectionEstablishmentDelayMillis});
assert.commandWorked(st.s.adminCommand(
{setParameter: 1, slowConnectionThresholdMillis: kConnectionEstablishmentDelayMillis}));
assert.commandWorked(
st.s.adminCommand({dropConnections: 1, hostAndPort: [st.rs0.getPrimary().host]}));
jsTestLog("Running the query.");
function runTestQuery(db) {
return startParallelShell(
funWithArgs((host, dbName, collName, keyName) => {
let conn = new Mongo(host);
assert.eq(1,
conn.getDB(dbName)
.getCollection(collName)
.find({primaryOnly: true, [keyName]: 42})
.itcount());
}, db.getMongo().host, db.getName(), kCollectionName, kKeyName), null, true);
}
let queryShell = runTestQuery(db);
if (connectionHealthLoggingOn) {
jsTestLog("Checking the mongos log.");
assert.soon(() => validateLogAndExtractCountAndEntry(st).entry != null,
"Slow connection establishment log entry not found.");
queryShell();
connDelayFailPoint.off();
jsTestLog("Checking the output of serverStatus.");
let queryLogEntry = validateLogAndExtractCountAndEntry(st).entry;
let status = assert.commandWorked(st.s.adminCommand({serverStatus: 1}));
printjson(status);
assert.gte(status.metrics.network.totalEgressConnectionEstablishmentTimeMillis,
queryLogEntry.attr.totalTimeMillis);
} else {
assert.eq(validateLogAndExtractCountAndEntry(st).count, initialLogEntryCount);
queryShell();
connDelayFailPoint.off();
jsTestLog("Checking the output of serverStatus.");
let status = assert.commandWorked(st.s.adminCommand({serverStatus: 1}));
printjson(status);
assert.gte(status.metrics.network.totalEgressConnectionEstablishmentTimeMillis, 0);
}
st.stop();
};
// Parameter is connectionHealthLoggingOn == true/false
runTest(true);
runTest(false);
})();
|
