Mongoose debug, pre, post hooks order

mongoose-debug_pre_post_hooks_order-reproduction-code.js

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

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

mongoose.set('debug', (collectionName, method, query, queryOptions) => {
    console.log(`[${new Date().toISOString()}] debug-mongoose: query (${method}):`, query);
    console.log(`[${new Date().toISOString()}] debug-mongoose: queryOptions:`, queryOptions);

    if (
        queryOptions.hasOwnProperty('profiler')
        && queryOptions.profiler.hasOwnProperty('startTime')
    ) {
        console.log(`[${new Date().toISOString()}] debug-mongoose: query started at ${queryOptions.profiler.startTime.toISOString()}`);
    }
    if (
        queryOptions.hasOwnProperty('profiler')
        && queryOptions.profiler.hasOwnProperty('endTime')
    ) {
        console.log(`[${new Date().toISOString()}] debug-mongoose: query ended at ${queryOptions.profiler.endTime.toISOString()}`);
    }
});
 
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 MySchema = new mongoose.Schema({
        'field1': [],
    });
    
    const preHook = function() {
        this.options.profiler = {
            'startTime': new Date(),
        };
        console.log(`[${new Date().toISOString()}] pre-hook: query started at ${this.options.profiler.startTime.toISOString()}`);
        console.log(`[${new Date().toISOString()}] pre-hook: this.options:`, this.options);
    };
    const postHook = function(result) {
        this.options.profiler.endTime = new Date();
        console.log(`[${new Date().toISOString()}] post-hook: query ended at ${this.options.profiler.endTime.toISOString()}`);
        console.log(`[${new Date().toISOString()}] post-hook: this.options:`, this.options);
    }

    MySchema.pre('find', preHook);
    MySchema.post('find', postHook);

    MySchema.pre('aggregate', preHook);
    MySchema.post('aggregate', postHook);

    const MyModel = mongoose.model('my_collection', MySchema);

    /** Find query **/
    MyModel.find(
        {'foo': 42}
    ).exec((err, results) => {
        if (err) {
            throw err;
        }
    });

    /**
    [2019-03-14T10:27:55.411Z] pre-hook: query started at 2019-03-14T10:27:55.411Z
    [2019-03-14T10:27:55.411Z] pre-hook: this.options: { profiler: { startTime: 2019-03-14T10:27:55.411Z } }
    [2019-03-14T10:27:55.414Z] debug-mongoose: query (find): { foo: 42 }
    [2019-03-14T10:27:55.415Z] debug-mongoose: queryOptions: { profiler: { startTime: 2019-03-14T10:27:55.411Z },
      projection: {} }
    [2019-03-14T10:27:55.415Z] debug-mongoose: query started at 2019-03-14T10:27:55.411Z
    [2019-03-14T10:27:55.424Z] post-hook: query ended at 2019-03-14T10:27:55.424Z
    [2019-03-14T10:27:55.424Z] post-hook: this.options: { profiler:
       { startTime: 2019-03-14T10:27:55.411Z,
         endTime: 2019-03-14T10:27:55.424Z } }
    **/
    /** /Find query **/

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

    /**
    [2019-03-14T10:27:34.742Z] pre-hook: query started at 2019-03-14T10:27:34.742Z
    [2019-03-14T10:27:34.742Z] pre-hook: this.options: { profiler: { startTime: 2019-03-14T10:27:34.742Z } }
    [2019-03-14T10:27:34.747Z] debug-mongoose: query (aggregate): [ { '$project': { a: 1, b: 1 } }, { '$limit': 1 } ]
    [2019-03-14T10:27:34.748Z] debug-mongoose: queryOptions: {}
    [2019-03-14T10:27:34.763Z] post-hook: query ended at 2019-03-14T10:27:34.763Z
    [2019-03-14T10:27:34.763Z] post-hook: this.options: { profiler:
       { startTime: 2019-03-14T10:27:34.742Z,
         endTime: 2019-03-14T10:27:34.763Z } }
    **/
    /** /Aggregate query **/
  });
});

package.json

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

Fixed in mongoose v5.4.22: Automattic/mongoose#7606