Mongoose - Trying to determine collection and operation inside hook for insert/update/delete queries

README.md

This gist is to help me find a way to determine the updated collection and the operation (document insertion, update or removal) from inside a Mongoose hook.

How to run

1. git clone this gist
2. Run npm install
3. Execute with node app.js

The various hook ouputs are iniated by the following lines of code:

• MyModel.insertMany([
• const findQuery = MyModel.find(
• const aggregateQuery = MyModel.aggregate([

app.js

const { MongoMemoryServer } = require('mongodb-memory-server');

const dbConfig = require('./database');

const mongoServer = new MongoMemoryServer({
    'instance': {
        'dbName': 'temp',
        'port': 35555,
    }
});

dbConfig(console.log); // Configures database stuff (like hooks)
const mongoose = require('mongoose');

mongoose.Promise = Promise;
mongoServer.getConnectionString().then((mongoUri) => {
  const mongooseOpts = {
    autoReconnect: true,
    reconnectTries: Number.MAX_VALUE,
    reconnectInterval: 1000,
  };

  mongoose.connect(mongoUri, mongooseOpts);

  mongoose.connection.on('error', (e) => {
    if (e.message.code === 'ETIMEDOUT') {
      console.log(e);
      mongoose.connect(mongoUri, mongooseOpts);
    }
    console.log(e);
  });

  mongoose.connection.once('open', () => {
    const MyModel = require('./my-mongo-model');

    /** Insert query **/
    MyModel.insertMany(
      [
        {'field1': 1},
        {'field1': 2},
        {'field1': 3},
      ],
      function(err, docs) {
        if (err) {
          throw err;
        }
      }
    );

    /**
    [2019-12-19T10:45:35.260Z] DEBUG: pre-hook: query started at 2019-12-19T10:45:35.260Z
    [2019-12-19T10:45:35.276Z] DEBUG: post-hook: result_or_doc: [ { field1: [ 1 ], _id: 5dfb54cff5182f3dbd36a2f2, __v: 0 },
      { field1: [ 2 ], _id: 5dfb54cff5182f3dbd36a2f3, __v: 0 },
      { field1: [ 3 ], _id: 5dfb54cff5182f3dbd36a2f4, __v: 0 } ]
    [2019-12-19T10:45:35.279Z] DEBUG: post-hook: query ended at 2019-12-19T10:45:35.279Z
    [2019-12-19T10:45:35.279Z] DEBUG: post-hook: Duration: 19
    [2019-12-19T10:45:35.279Z] DEBUG: post-hook: this: Model { my_collection }
    [2019-12-19T10:45:35.279Z] DEBUG: post-hook: collectionName: ElseOperation-Collection
    [2019-12-19T10:45:35.279Z] DEBUG: post-hook: methodName: ElseOperation-Method
    [2019-12-19T10:45:35.279Z] Mongoose: collection:ElseOperation-Collection, method:ElseOperation-Method, query:undefined, duration:19, documentCount:3
    **/
    /** /Insert query **/

    /** Find query **/
    const findQuery = MyModel.find(
      {'field1': 2}
    );
    findQuery.exec((err, results) => {
      if (err) {
        throw err;
      }
    });

    /**
    [2019-12-19T10:48:52.239Z] DEBUG: pre-hook: query started at 2019-12-19T10:48:52.239Z
    [2019-12-19T10:48:52.248Z] DEBUG: post-hook: result_or_doc: []
    [2019-12-19T10:48:52.249Z] DEBUG: post-hook: query ended at 2019-12-19T10:48:52.249Z
    [2019-12-19T10:48:52.249Z] DEBUG: post-hook: Duration: 10
    [2019-12-19T10:48:52.249Z] DEBUG: post-hook: this: Query { ... }
    [2019-12-19T10:48:52.253Z] DEBUG: post-hook: collectionName: my_collections
    [2019-12-19T10:48:52.254Z] DEBUG: post-hook: methodName: find
    [2019-12-19T10:48:52.254Z] Mongoose: collection:my_collections, method:find, query:{"field1":2}, duration:10, documentCount:0
    **/
    /** /Find query **/

    /** Aggregate query **/
    const aggregateQuery = MyModel.aggregate([
      { $project: { a: 1, b: 1 } },
      { $limit: 1 }
    ]);
    aggregateQuery.exec((err, results) => {
      if (err) {
          throw err;
      }
    });

    /**
    [2019-12-19T10:49:26.555Z] DEBUG: pre-hook: query started at 2019-12-19T10:49:26.555Z
    [2019-12-19T10:49:26.564Z] DEBUG: post-hook: result_or_doc: []
    [2019-12-19T10:49:26.565Z] DEBUG: post-hook: query ended at 2019-12-19T10:49:26.565Z
    [2019-12-19T10:49:26.565Z] DEBUG: post-hook: Duration: 10
    [2019-12-19T10:49:26.565Z] DEBUG: post-hook: this: Aggregate {
      _pipeline: [ { '$project': [Object] }, { '$limit': 1 } ],
      _model: Model { my_collection },
      options: { aggregateOption: 'aggregate' },
      _userOptions:
      { profiling:
          { startTime: 2019-12-19T10:49:26.555Z,
            endTime: 2019-12-19T10:49:26.565Z,
            duration: 10 } } }
    [2019-12-19T10:49:26.567Z] DEBUG: post-hook: collectionName: my_collections
    [2019-12-19T10:49:26.567Z] DEBUG: post-hook: methodName: aggregate
    [2019-12-19T10:49:26.567Z] Mongoose: collection:my_collections, method:aggregate, query:[{"$project":{"a":1,"b":1}},{"$limit":1}], duration:10, documentCount:0
    **/
    /** /Aggregate query **/
  });
});

database.js

const mongoose = require('mongoose');
const util = require('util');

function mongooseConfiguration(logger = {}) {
  // Used to enrich Mongoose object with our stuff (eg. a profiler)
  mongoose._userProvidedOptions = {};

  mongoose._userProvidedOptions.profiler = {
    'preHook': function(next) { // Will mark down the query start time

      if (!Object.prototype.hasOwnProperty.call(this, '_userOptions')) {
        this._userOptions = {};
      }

      // The property (of the query) we'll use to store our profiling stuff
      const profilingParentObject = this._userOptions;

      if (
        Object.prototype.hasOwnProperty.call(mongoose, '_userProvidedOptions')
        && Object.prototype.hasOwnProperty.call(mongoose._userProvidedOptions, 'profiler')
      ) {
        profilingParentObject.profiling = {
          'startTime': new Date(),
        };
        console.log(`[${new Date().toISOString()}] DEBUG: pre-hook: query started at ${profilingParentObject.profiling.startTime.toISOString()}`);
      }

      next();
    },
    'postHook': function(result, next) { // Will mark down the query end time and compute execution time
      console.log(`[${new Date().toISOString()}] DEBUG: post-hook: result_or_doc: ${util.inspect(result)}`);

      if (
        Object.prototype.hasOwnProperty.call(mongoose, '_userProvidedOptions')
        && Object.prototype.hasOwnProperty.call(mongoose._userProvidedOptions, 'profiler')
      ) {
        // The property (of the query) we'll use to store our profiling stuff
        let profilingParentObject;
        if (Object.prototype.hasOwnProperty.call(this, '_userOptions')) {
          profilingParentObject = this._userOptions;
          if (Object.prototype.hasOwnProperty.call(profilingParentObject, 'profiling')) {
            profilingParentObject.profiling.endTime = new Date();
            console.log(`[${new Date().toISOString()}] DEBUG: post-hook: query ended at ${profilingParentObject.profiling.endTime.toISOString()}`);
            if (Object.prototype.hasOwnProperty.call(profilingParentObject.profiling, 'startTime')) {
              profilingParentObject.profiling.duration = // In milliseconds
                profilingParentObject.profiling.endTime.getTime()
                - profilingParentObject.profiling.startTime.getTime();
              console.log(`[${new Date().toISOString()}] DEBUG: post-hook: Duration: ${profilingParentObject.profiling.duration}`);
            }
          }
        }

        /*
          Value of `util.inspect(this)`:
          * insertMany operation : Model { my_collection }
          * find operation : Query { ... }
          * aggregate operation : Aggregate { ... }
         */
        console.log(`[${new Date().toISOString()}] DEBUG: post-hook: this: ${util.inspect(this)}`);

        let collectionName;
        let methodName;
        if (this instanceof mongoose.Query || this instanceof mongoose.Aggregate) {
          ({ collectionName } = this.model().collection);
          methodName = this instanceof mongoose.Query ? this.op : 'aggregate';
        } else if (this instanceof mongoose.Model) {
          collectionName = 'ModelOperation-Collection';
          methodName = 'ModelOperation-Method';
        } else {
          collectionName = 'ElseOperation-Collection';
          methodName = 'ElseOperation-Method';
        }
        console.log(`[${new Date().toISOString()}] DEBUG: post-hook: collectionName: ${collectionName}`);
        console.log(`[${new Date().toISOString()}] DEBUG: post-hook: methodName: ${methodName}`);

        // Text version of query:
        const query = this instanceof mongoose.Query ? this._conditions : this._pipeline;
        const queryAsString = JSON.stringify(query);

        // The object to hold obtained profiling information:
        const profilingInfos = {
          'collection': collectionName,
          'method': methodName,
          'query': queryAsString,
        };

        if ( // Append duration information if any
          Object.prototype.hasOwnProperty.call(profilingParentObject, 'profiling')
          && Object.prototype.hasOwnProperty.call(profilingParentObject.profiling, 'duration')
        ) {
          profilingInfos.duration = profilingParentObject.profiling.duration;
        }

        if (result) { // Append obtained document count
          profilingInfos.documentCount = result.length;
        }

        // Assemble log message
        const profilingInfosString = Object.getOwnPropertyNames(profilingInfos)
          .map(key => `${key}:${profilingInfos[key]}`)
          .join(', ');
        const logOutput = `[${new Date().toISOString()}] Mongoose: ${profilingInfosString}`;

        // Log message using defined logger (if any)
        if (Object.prototype.hasOwnProperty.call(mongoose._userProvidedOptions.profiler, 'logger')) {
          mongoose._userProvidedOptions.profiler.logger(logOutput);
        }
      }

      next();
    },
  };

  if (logger) { //
    mongoose._userProvidedOptions.profiler.logger = logger;
  }
}

module.exports = mongooseConfiguration;

my-mongo-model.js

const mongoose = require('mongoose');
const MySchema = new mongoose.Schema({
  'field1': [],
});

// Adds profiler hooks to Mongoose schema if they exists:
if (
  Object.prototype.hasOwnProperty.call(mongoose, '_userProvidedOptions')
  && Object.prototype.hasOwnProperty.call(mongoose._userProvidedOptions, 'profiler')
) {
  if (Object.prototype.hasOwnProperty.call(mongoose._userProvidedOptions.profiler, 'preHook')) {
    MySchema.pre('find', mongoose._userProvidedOptions.profiler.preHook);
    MySchema.pre('aggregate', mongoose._userProvidedOptions.profiler.preHook);

    MySchema.pre('insertMany', mongoose._userProvidedOptions.profiler.preHook);
    MySchema.pre('updateOne', mongoose._userProvidedOptions.profiler.preHook);
    MySchema.pre('remove', { 'query': true }, mongoose._userProvidedOptions.profiler.preHook);
  }
  if (Object.prototype.hasOwnProperty.call(mongoose._userProvidedOptions.profiler, 'postHook')) {
    MySchema.post('find', mongoose._userProvidedOptions.profiler.postHook);
    MySchema.post('aggregate', mongoose._userProvidedOptions.profiler.postHook);

    MySchema.post('insertMany', mongoose._userProvidedOptions.profiler.postHook);
    MySchema.post('updateOne', mongoose._userProvidedOptions.profiler.postHook);
    MySchema.post('remove', { 'query': true }, mongoose._userProvidedOptions.profiler.postHook);
  }
}
/* /Profiler */

module.exports = mongoose.model('my_collection', MySchema);

package.json

{
  "name": "",
  "version": "0.0.0",
  "license": "UNLICENSED",
  "private": false,
  "dependencies": {
    "mongoose": "^5.8.1",
    "mongodb-memory-server": "^6.0.2"
  }
}