SERVER-50605 Add logMessage test-only command

9 files changed, 155 insertions, 0 deletions

diff --git a/jstests/core/views/views_all_commands.js b/jstests/core/views/views_all_commands.js
index f3fe02590b3..249adfa521a 100644
--- a/jstests/core/views/views_all_commands.js
+++ b/jstests/core/views/views_all_commands.js
@@ -385,6 +385,7 @@ let viewsCommandTests = {
     listShards: {skip: isUnrelated},
     lockInfo: {skip: isUnrelated},
     logApplicationMessage: {skip: isUnrelated},
+    logMessage: {skip: isUnrelated},
     logRotate: {skip: isUnrelated},
     logout: {skip: isUnrelated},
     makeSnapshot: {skip: isAnInternalCommand},
diff --git a/jstests/noPassthrough/log-escape.js b/jstests/noPassthrough/log-escape.js
new file mode 100644
index 00000000000..f559de7b5ab
--- /dev/null
+++ b/jstests/noPassthrough/log-escape.js
@@ -0,0 +1,40 @@
+// Test escaping of user provided data in logs
+
+(function() {
+'use strict';
+
+const mongo = MongoRunner.runMongod({useLogFiles: true});
+const admin = mongo.getDB('admin');
+
+// Use our own log parser instead of `checkLog`
+// because we want to force reading from a file.
+// {getLog: 'global'} could mask output encoding issues.
+function assertContainsLog(msg) {
+    assert.soon(function() {
+        // Search by splitting the log file on newlines,
+        // filtering out blanks, parsing the remains as JSON,
+        // then filtering to id===5060500 and msg==expect.
+        // We should get precisely one match.
+        // Too few and we didn't log,
+        // too many and we didn't make the message unique enough.
+        const count = cat(mongo.fullOptions.logFile)
+                          .split("\n")
+                          .filter((l) => l != '')
+                          .map((l) => JSON.parse(l))
+                          .filter((l) => (l.id === 5060500) && (l.attr.msg === msg))
+                          .length;
+        // Wrap msg in tojson for assert message so that we can see what character wasn't found.
+        assert.lt(count, 2, "Repeated entry for message: " + tojson(msg));
+        return count === 1;
+    }, "Expected message not found: " + tojson(msg), 10 * 1000);
+}
+
+// Test a range of characters sent to the global log
+for (let i = 0; i < 256; ++i) {
+    const msg = "Hello" + String.fromCharCode(i) + "World";
+    assert.commandWorked(admin.runCommand({logMessage: msg}));
+    assertContainsLog(msg);
+}
+
+MongoRunner.stopMongod(mongo);
+})();
diff --git a/jstests/noPassthrough/log-message.js b/jstests/noPassthrough/log-message.js
new file mode 100644
index 00000000000..b5e876b8ea9
--- /dev/null
+++ b/jstests/noPassthrough/log-message.js
@@ -0,0 +1,108 @@
+// Test behavior of {logMessage: ... } test-only command.
+
+(function() {
+'use strict';
+
+const mongo = MongoRunner.runMongod({useLogFiles: true});
+const admin = mongo.getDB('admin');
+
+// Use our own log parser instead of `checkLog`
+// because we want to force reading from a file.
+// {getLog: 'global'} could mask output encoding issues.
+// It would also be swell to get the record back as a return value.
+function assertContainsLog(expectLog, severityCode) {
+    const assertMsg = tojson(expectLog) + '(' + severityCode + ')';
+    assert.soon(function() {
+        // Search by splitting the log file on newlines,
+        // filtering out blanks, parsing the remains as JSON,
+        // then filtering on id, attr, and s.
+        //
+        // We should get precisely one match.
+        // Too few and we didn't log,
+        // too many and we didn't make the message unique enough.
+        const count = cat(mongo.fullOptions.logFile)
+                          .split("\n")
+                          .filter((l) => l != '')
+                          .map((l) => JSON.parse(l))
+                          .filter((l) => (l.id === 5060500) && (l.s === severityCode) &&
+                                      (0 === bsonWoCompare(l.attr, expectLog)))
+                          .length;
+
+        assert.lt(count, 2, "Repeated log entry: " + assertMsg);
+        return count === 1;
+    }, "Expected log not found: " + assertMsg, 20 * 1000);
+}
+
+const severities = {
+    'severe': 'F',  // As in 'F'atal.
+    'error': 'E',
+    'warning': 'W',
+    'info': 'I',
+    'log': 'I',    // Not a typo.
+    'debug': 'D',  // Actually D1-D5, overridden by main loop.
+};
+
+function test(msg, extra = undefined, severity = undefined, debug = undefined) {
+    // Add entropy to msg to disambiguate multiple passes of the loop.
+    if (severity !== undefined) {
+        msg = severity + debug + ": " + msg;
+    }
+
+    const payload = {logMessage: msg};
+    const expectLog = {msg: msg};
+    if (extra !== undefined) {
+        payload.extra = extra;
+        expectLog.extra = extra;
+    }
+
+    let expectSeverity = severities['log'];
+    if (severity !== undefined) {
+        payload.severity = severity;
+        if (severity === 'debug') {
+            if (debug !== undefined) {
+                payload.debugLevel = NumberInt(debug);
+            }
+            expectSeverity = 'D' + (debug ? debug : 1);
+        } else {
+            expectSeverity = severities[severity];
+        }
+    }
+
+    assert.commandWorked(admin.runCommand(payload));
+    assertContainsLog(expectLog, expectSeverity);
+}
+
+// Quick sanity check before diving deep.
+test('Hello World');
+test('Hello World', {arg: 'value'});
+
+// Don't up the log level till now in order to avoid aggregious spammage.
+admin.setLogLevel(5);
+
+// Now roll up sleeves and check them all.
+const testMessage = 'The quick "brown" \'fox\' jumped over,\nthe lazy\tdog.\u0000';
+const extras = [
+    undefined,
+    {},
+    {arg: 'value'},
+    {arg: [{foo: 'bar'}], baz: 'qux'},
+];
+
+extras.forEach(function(extra) {
+    Object.keys(severities).forEach(function(severity) {
+        test(testMessage, extra, severity);
+        if (severity === 'debug') {
+            // Above call tests as default debug level,
+            // Following loop tests at explicitly debug levels.
+            for (let debug = 1; debug < 6; ++debug) {
+                test(testMessage, extra, severity, debug);
+            }
+        }
+    });
+});
+
+// Reset log level to avoid spammage during shutdown.
+admin.setLogLevel(0);
+
+MongoRunner.stopMongod(mongo);
+})();
diff --git a/jstests/replsets/db_reads_while_recovering_all_commands.js b/jstests/replsets/db_reads_while_recovering_all_commands.js
index 249fb867072..a25196b42b3 100644
--- a/jstests/replsets/db_reads_while_recovering_all_commands.js
+++ b/jstests/replsets/db_reads_while_recovering_all_commands.js
@@ -219,6 +219,7 @@ const allCommands = {
     },
     lockInfo: {skip: isPrimaryOnly},
     logApplicationMessage: {skip: isNotAUserDataRead},
+    logMessage: {skip: isNotAUserDataRead},
     logRotate: {skip: isNotAUserDataRead},
     logout: {skip: isNotAUserDataRead},
     makeSnapshot: {skip: isNotAUserDataRead},
diff --git a/jstests/sharding/database_versioning_all_commands.js b/jstests/sharding/database_versioning_all_commands.js
index 97f65342750..ea03029cf4b 100644
--- a/jstests/sharding/database_versioning_all_commands.js
+++ b/jstests/sharding/database_versioning_all_commands.js
@@ -489,6 +489,7 @@ let testCases = {
     },
     listShards: {skip: "does not forward command to primary shard"},
     logApplicationMessage: {skip: "not on a user database", conditional: true},
+    logMessage: {skip: "not on a user database"},
     logRotate: {skip: "executes locally on mongos (not sent to any remote node)"},
     logout: {skip: "not on a user database"},
     mapReduce: {
diff --git a/jstests/sharding/read_write_concern_defaults_application.js b/jstests/sharding/read_write_concern_defaults_application.js
index b319ef460b2..543f4ed3602 100644
--- a/jstests/sharding/read_write_concern_defaults_application.js
+++ b/jstests/sharding/read_write_concern_defaults_application.js
@@ -482,6 +482,7 @@ let testCases = {
     listShards: {skip: "does not accept read or write concern"},
     lockInfo: {skip: "does not accept read or write concern"},
     logApplicationMessage: {skip: "does not accept read or write concern"},
+    logMessage: {skip: "does not accept read or write concern"},
     logRotate: {skip: "does not accept read or write concern"},
     logout: {skip: "does not accept read or write concern"},
     makeSnapshot: {skip: "does not accept read or write concern"},
diff --git a/jstests/sharding/safe_secondary_reads_drop_recreate.js b/jstests/sharding/safe_secondary_reads_drop_recreate.js
index 2ec89cecc1c..99a2d7ceadb 100644
--- a/jstests/sharding/safe_secondary_reads_drop_recreate.js
+++ b/jstests/sharding/safe_secondary_reads_drop_recreate.js
@@ -208,6 +208,7 @@ let testCases = {
     listShards: {skip: "does not return user data"},
     lockInfo: {skip: "primary only"},
     logApplicationMessage: {skip: "primary only"},
+    logMessage: {skip: "does not return user data"},
     logRotate: {skip: "does not return user data"},
     logout: {skip: "does not return user data"},
     makeSnapshot: {skip: "does not return user data"},
diff --git a/jstests/sharding/safe_secondary_reads_single_migration_suspend_range_deletion.js b/jstests/sharding/safe_secondary_reads_single_migration_suspend_range_deletion.js
index 5fae7205463..809b02595e6 100644
--- a/jstests/sharding/safe_secondary_reads_single_migration_suspend_range_deletion.js
+++ b/jstests/sharding/safe_secondary_reads_single_migration_suspend_range_deletion.js
@@ -242,6 +242,7 @@ let testCases = {
     listShards: {skip: "does not return user data"},
     lockInfo: {skip: "primary only"},
     logApplicationMessage: {skip: "primary only"},
+    logMessage: {skip: "does not return user data"},
     logRotate: {skip: "does not return user data"},
     logout: {skip: "does not return user data"},
     makeSnapshot: {skip: "does not return user data"},
diff --git a/jstests/sharding/safe_secondary_reads_single_migration_waitForDelete.js b/jstests/sharding/safe_secondary_reads_single_migration_waitForDelete.js
index 09485bd07c2..de809fafe4e 100644
--- a/jstests/sharding/safe_secondary_reads_single_migration_waitForDelete.js
+++ b/jstests/sharding/safe_secondary_reads_single_migration_waitForDelete.js
@@ -213,6 +213,7 @@ let testCases = {
     listShards: {skip: "does not return user data"},
     lockInfo: {skip: "primary only"},
     logApplicationMessage: {skip: "primary only"},
+    logMessage: {skip: "does not return user data"},
     logRotate: {skip: "does not return user data"},
     logout: {skip: "does not return user data"},
     makeSnapshot: {skip: "does not return user data"},