fix: use emitWarning API for internal messages (#2743)

Updates all logging statements to use node's process.emitWarning API.
Allows for filtering, capturing and silencing of warnings.

NODE-2317, NODE-3114

Author: nbbeeken

.eslintrc.json

@@ -21,7 +21,7 @@
     "es/no-destructuring": "error",
     "es/no-rest-spread-properties": "error",
     "es/no-spread-elements": "error",
-    "no-console": "off",
+    "no-console": "error",
     "eqeqeq": ["error", "always", { "null": "ignore" }],
     "strict": ["error", "global"]
   },

lib/collection.js

@@ -2,6 +2,7 @@
 
 const deprecate = require('util').deprecate;
 const deprecateOptions = require('./utils').deprecateOptions;
+const emitWarningOnce = require('./utils').emitWarningOnce;
 const checkCollectionName = require('./utils').checkCollectionName;
 const ObjectID = require('./core').BSON.ObjectID;
 const MongoError = require('./core').MongoError;
@@ -323,7 +324,7 @@ Collection.prototype.find = deprecateOptions(
   function(query, options, callback) {
     if (typeof callback === 'object') {
       // TODO(MAJOR): throw in the future
-      console.warn('Third parameter to `find()` must be a callback or undefined');
+      emitWarningOnce('Third parameter to `find()` must be a callback or undefined');
     }
 
     let selector = query;
@@ -1092,7 +1093,7 @@ Collection.prototype.findOne = deprecateOptions(
   function(query, options, callback) {
     if (typeof callback === 'object') {
       // TODO(MAJOR): throw in the future
-      console.warn('Third parameter to `findOne()` must be a callback or undefined');
+      emitWarningOnce('Third parameter to `findOne()` must be a callback or undefined');
     }
 
     if (typeof query === 'function') (callback = query), (query = {}), (options = {});

lib/core/auth/scram.js

@@ -4,6 +4,7 @@ const Buffer = require('safe-buffer').Buffer;
 const retrieveBSON = require('../connection/utils').retrieveBSON;
 const MongoError = require('../error').MongoError;
 const AuthProvider = require('./auth_provider').AuthProvider;
+const emitWarningOnce = require('../../utils').emitWarning;
 
 const BSON = retrieveBSON();
 const Binary = BSON.Binary;
@@ -24,7 +25,7 @@ class ScramSHA extends AuthProvider {
   prepare(handshakeDoc, authContext, callback) {
     const cryptoMethod = this.cryptoMethod;
     if (cryptoMethod === 'sha256' && saslprep == null) {
-      console.warn('Warning: no saslprep library specified. Passwords will not be sanitized');
+      emitWarningOnce('Warning: no saslprep library specified. Passwords will not be sanitized');
     }
 
     crypto.randomBytes(24, (err, nonce) => {

lib/core/connection/logger.js

@@ -37,6 +37,7 @@ var Logger = function(className, options) {
   if (options.logger) {
     currentLogger = options.logger;
   } else if (currentLogger == null) {
+    // eslint-disable-next-line no-console
     currentLogger = console.log;
   }
 

lib/core/connection/msg.js

@@ -31,6 +31,7 @@ const Buffer = require('safe-buffer').Buffer;
 const opcodes = require('../wireprotocol/shared').opcodes;
 const databaseNamespace = require('../wireprotocol/shared').databaseNamespace;
 const ReadPreference = require('../topologies/read_preference');
+const MongoError = require('../../core/error').MongoError;
 
 // Incrementing request id
 let _requestId = 0;
@@ -196,7 +197,8 @@ class BinMsg {
     while (this.index < this.data.length) {
       const payloadType = this.data.readUInt8(this.index++);
       if (payloadType === 1) {
-        console.error('TYPE 1');
+        // It was decided that no driver makes use of payload type 1
+        throw new MongoError('OP_MSG Payload Type 1 detected unsupported protocol');
       } else if (payloadType === 0) {
         const bsonSize = this.data.readUInt32LE(this.index);
         const bin = this.data.slice(this.index, this.index + bsonSize);

lib/core/sdam/topology.js

@@ -27,6 +27,7 @@ const ServerSessionPool = require('../sessions').ServerSessionPool;
 const makeClientMetadata = require('../utils').makeClientMetadata;
 const CMAP_EVENT_NAMES = require('../../cmap/events').CMAP_EVENT_NAMES;
 const compareTopologyVersion = require('./server_description').compareTopologyVersion;
+const emitWarning = require('../../utils').emitWarning;
 
 const common = require('./common');
 const drainTimerQueue = common.drainTimerQueue;
@@ -739,7 +740,7 @@ class Topology extends EventEmitter {
   }
 
   unref() {
-    console.log('not implemented: `unref`');
+    emitWarning('not implemented: `unref`');
   }
 
   // NOTE: There are many places in code where we explicitly check the last isMaster

lib/core/tools/smoke_plugin.js

@@ -52,6 +52,7 @@ exports.attachToRunner = function(runner, outputFile) {
     fs.writeFileSync(outputFile, JSON.stringify(smokeOutput));
 
     // Standard NodeJS uncaught exception handler
+    // eslint-disable-next-line no-console
     console.error(err.stack);
     process.exit(1);
   });

lib/core/topologies/read_preference.js

@@ -1,4 +1,5 @@
 'use strict';
+const emitWarningOnce = require('../../utils').emitWarningOnce;
 
 /**
  * The **ReadPreference** class is a class that represents a MongoDB ReadPreference and is
@@ -20,7 +21,7 @@ const ReadPreference = function(mode, tags, options) {
 
   // TODO(major): tags MUST be an array of tagsets
   if (tags && !Array.isArray(tags)) {
-    console.warn(
+    emitWarningOnce(
       'ReadPreference tags must be an array, this will change in the next major version'
     );
 

lib/core/uri_parser.js

@@ -4,6 +4,7 @@ const qs = require('querystring');
 const dns = require('dns');
 const MongoParseError = require('./error').MongoParseError;
 const ReadPreference = require('./topologies/read_preference');
+const emitWarningOnce = require('../utils').emitWarningOnce;
 
 /**
  * The following regular expression validates a connection string and breaks the
@@ -438,7 +439,7 @@ function parseQueryString(query, options) {
   // special cases for known deprecated options
   if (result.wtimeout && result.wtimeoutms) {
     delete result.wtimeout;
-    console.warn('Unsupported option `wtimeout` specified');
+    emitWarningOnce('Unsupported option `wtimeout` specified');
   }
 
   return Object.keys(result).length ? result : null;

lib/core/wireprotocol/kill_cursors.js

@@ -5,6 +5,7 @@ const MongoError = require('../error').MongoError;
 const MongoNetworkError = require('../error').MongoNetworkError;
 const collectionNamespace = require('./shared').collectionNamespace;
 const maxWireVersion = require('../utils').maxWireVersion;
+const emitWarning = require('../utils').emitWarning;
 const command = require('./command');
 
 function killCursors(server, ns, cursorState, callback) {
@@ -31,7 +32,7 @@ function killCursors(server, ns, cursorState, callback) {
         if (typeof callback === 'function') {
           callback(err, null);
         } else {
-          console.warn(err);
+          emitWarning(err);
         }
       }
     }

lib/db.js

@@ -12,7 +12,7 @@ const MongoError = require('./core').MongoError;
 const ObjectID = require('./core').ObjectID;
 const Logger = require('./core').Logger;
 const Collection = require('./collection');
-const mergeOptionsAndWriteConcern = require('./utils').mergeOptionsAndWriteConcern;
+const conditionallyMergeWriteConcern = require('./utils').conditionallyMergeWriteConcern;
 const executeLegacyOperation = require('./utils').executeLegacyOperation;
 const ChangeStream = require('./change_stream');
 const deprecate = require('util').deprecate;
@@ -382,7 +382,7 @@ Db.prototype.admin = function() {
  * @param {AggregationCursor} cursor The cursor if the aggregation command was executed successfully.
  */
 
-const collectionKeys = [
+const COLLECTION_OPTION_KEYS = [
   'pkFactory',
   'readPreference',
   'serializeFunctions',
@@ -433,8 +433,14 @@ Db.prototype.collection = function(name, options, callback) {
     options.ignoreUndefined = this.s.options.ignoreUndefined;
   }
 
+  for (const collectionOptionKey of COLLECTION_OPTION_KEYS) {
+    if (!(collectionOptionKey in options) && this.s.options[collectionOptionKey] !== undefined) {
+      options[collectionOptionKey] = this.s.options[collectionOptionKey];
+    }
+  }
+
   // Merge in all needed options and ensure correct writeConcern merging from db level
-  options = mergeOptionsAndWriteConcern(options, this.s.options, collectionKeys, true);
+  options = conditionallyMergeWriteConcern(options, this.s.options, COLLECTION_OPTION_KEYS, true);
 
   // Execute
   if (options == null || !options.strict) {

lib/operations/add_user.js

@@ -6,6 +6,7 @@ const defineAspects = require('./operation').defineAspects;
 const crypto = require('crypto');
 const handleCallback = require('../utils').handleCallback;
 const toError = require('../utils').toError;
+const emitWarning = require('../utils').emitWarning;
 
 class AddUserOperation extends CommandOperation {
   constructor(db, username, password, options) {
@@ -29,7 +30,7 @@ class AddUserOperation extends CommandOperation {
     // If not roles defined print deprecated message
     // TODO: handle deprecation properly
     if (roles.length === 0) {
-      console.log('Creating a user without roles is deprecated in MongoDB >= 2.6');
+      emitWarning('Creating a user without roles is deprecated in MongoDB >= 2.6');
     }
 
     // Check the db name and add roles if needed

lib/operations/connect.js

@@ -13,6 +13,7 @@ const ReplSet = require('../topologies/replset');
 const Server = require('../topologies/server');
 const ServerSessionPool = require('../core').Sessions.ServerSessionPool;
 const emitDeprecationWarning = require('../utils').emitDeprecationWarning;
+const emitWarningOnce = require('../utils').emitWarningOnce;
 const fs = require('fs');
 const WriteConcern = require('../write_concern');
 const BSON = require('../core/connection/utils').retrieveBSON();
@@ -182,12 +183,12 @@ function validOptions(options) {
       if (options.validateOptions) {
         return new MongoError(`option ${name} is not supported`);
       } else {
-        console.warn(`the options [${name}] is not supported`);
+        emitWarningOnce(`the options [${name}] is not supported`);
       }
     }
 
     if (legacyOptionNames.indexOf(name) !== -1) {
-      console.warn(
+      emitWarningOnce(
         `the server/replset/mongos/db options are deprecated, ` +
           `all their options are supported at the top level of the options object [${validOptionNames}]`
       );
@@ -257,9 +258,6 @@ function resolveTLSOptions(options) {
   });
 }
 
-const emitDeprecationForNonUnifiedTopology = deprecate(() => {},
-'current Server Discovery and Monitoring engine is deprecated, and will be removed in a future version. ' + 'To use the new Server Discover and Monitoring engine, pass option { useUnifiedTopology: true } to the MongoClient constructor.');
-
 function connect(mongoClient, url, options, callback) {
   options = Object.assign({}, options);
 
@@ -335,7 +333,9 @@ function connect(mongoClient, url, options, callback) {
       return createTopology(mongoClient, 'unified', _finalOptions, connectCallback);
     }
 
-    emitDeprecationForNonUnifiedTopology();
+    emitWarningOnce(
+      'Current Server Discovery and Monitoring engine is deprecated, and will be removed in a future version. To use the new Server Discover and Monitoring engine, pass option { useUnifiedTopology: true } to the MongoClient constructor.'
+    );
 
     // Do we have a replicaset then skip discovery and go straight to connectivity
     if (_finalOptions.replicaSet || _finalOptions.rs_name) {

lib/utils.js

@@ -287,39 +287,38 @@ var filterOptions = function(options, names) {
 };
 
 // Write concern keys
-var writeConcernKeys = ['w', 'j', 'wtimeout', 'fsync'];
+const WRITE_CONCERN_KEYS = ['w', 'j', 'wtimeout', 'fsync', 'writeConcern'];
 
-// Merge the write concern options
-var mergeOptionsAndWriteConcern = function(targetOptions, sourceOptions, keys, mergeWriteConcern) {
-  // Mix in any allowed options
-  for (var i = 0; i < keys.length; i++) {
-    if (!targetOptions[keys[i]] && sourceOptions[keys[i]] !== undefined) {
-      targetOptions[keys[i]] = sourceOptions[keys[i]];
-    }
-  }
-
-  // No merging of write concern
-  if (!mergeWriteConcern) return targetOptions;
-
-  // Found no write Concern options
-  var found = false;
-  for (i = 0; i < writeConcernKeys.length; i++) {
-    if (targetOptions[writeConcernKeys[i]]) {
+/**
+ * If there is no WriteConcern related options defined on target then inherit from source.
+ * Otherwise, do not inherit **any** options from source.
+ * @internal
+ * @param {object} target - options object conditionally receiving the writeConcern options
+ * @param {object} source - options object containing the potentially inherited writeConcern options
+ */
+function conditionallyMergeWriteConcern(target, source) {
+  let found = false;
+  for (const wcKey of WRITE_CONCERN_KEYS) {
+    if (wcKey in target) {
+      // Found a writeConcern option
       found = true;
       break;
     }
   }
 
   if (!found) {
-    for (i = 0; i < writeConcernKeys.length; i++) {
-      if (sourceOptions[writeConcernKeys[i]]) {
-        targetOptions[writeConcernKeys[i]] = sourceOptions[writeConcernKeys[i]];
+    for (const wcKey of WRITE_CONCERN_KEYS) {
+      if (source[wcKey]) {
+        if (!('writeConcern' in target)) {
+          target.writeConcern = {};
+        }
+        target.writeConcern[wcKey] = source[wcKey];
       }
     }
   }
 
-  return targetOptions;
-};
+  return target;
+}
 
 /**
  * Executes the given operation with provided arguments.
@@ -534,7 +533,9 @@ function decorateWithExplain(command, explain) {
   return { explain: command, verbosity: explain.verbosity };
 }
 
-const emitProcessWarning = msg => process.emitWarning(msg, 'DeprecationWarning');
+const emitProcessWarning = msg =>
+  process.emitWarning(msg, { type: 'DeprecationWarning', code: MONGODB_WARNING_CODE });
+// eslint-disable-next-line no-console
 const emitConsoleWarning = msg => console.error(msg);
 const emitDeprecationWarning = process.emitWarning ? emitProcessWarning : emitConsoleWarning;
 
@@ -816,6 +817,48 @@ function hasAtomicOperators(doc) {
   );
 }
 
+/**
+ * When the driver used emitWarning the code will be equal to this.
+ * @public
+ *
+ * @example
+ * ```js
+ * process.on('warning', (warning) => {
+ *  if (warning.code === MONGODB_WARNING_CODE) console.error('Ah an important warning! :)')
+ * })
+ * ```
+ */
+const MONGODB_WARNING_CODE = 'MONGODB DRIVER';
+
+/**
+ * @internal
+ * @param {string} message - message to warn about
+ */
+function emitWarning(message) {
+  if (process.emitWarning) {
+    return process.emitWarning(message, { code: MONGODB_WARNING_CODE });
+  } else {
+    // Approximate the style of print out on node versions pre 8.x
+    // eslint-disable-next-line no-console
+    return console.error(`[${MONGODB_WARNING_CODE}] Warning:`, message);
+  }
+}
+
+const emittedWarnings = new Set();
+/**
+ * Will emit a warning once for the duration of the application.
+ * Uses the message to identify if it has already been emitted
+ * so using string interpolation can cause multiple emits
+ * @internal
+ * @param {string} message - message to warn about
+ */
+function emitWarningOnce(message) {
+  if (!emittedWarnings.has(message)) {
+    emittedWarnings.add(message);
+    return emitWarning(message);
+  }
+}
+
 module.exports = {
   filterOptions,
   mergeOptions,
@@ -832,7 +875,7 @@ module.exports = {
   isObject,
   debugOptions,
   MAX_JS_INT: Number.MAX_SAFE_INTEGER + 1,
-  mergeOptionsAndWriteConcern,
+  conditionallyMergeWriteConcern,
   executeLegacyOperation,
   applyRetryableWrites,
   applyWriteConcern,
@@ -849,5 +892,8 @@ module.exports = {
   now,
   calculateDurationInMs,
   makeInterruptableAsyncInterval,
-  hasAtomicOperators
+  hasAtomicOperators,
+  MONGODB_WARNING_CODE,
+  emitWarning,
+  emitWarningOnce
 };