mongoose post-save timing

mongoose-post-save.js

const mongoose = require('mongoose');
mongoose.Promise = Promise;

mongoose.connect('mongodb://localhost/test_mongoose_postsave')
.then(testPostSave)
.then(() => mongoose.disconnect());

const log = console.log;

function testPostSave () {
  log('0. init');

  const schema = new mongoose.Schema({
    foo: String,
  });

  schema.pre('validate', function (next) {
    log('3. pre-validate');
    next();
  });

  schema.pre('save', function (next) {
    log('4. pre-save');
    next();
  });

  schema.post('save', function () {
    log('8a. post-save');
    process.nextTick(function () {
      log('8b. post-save async');
      setTimeout(function () {
        log('8c. post-save async even longer');
      }, 1000);
    });
  });

  const Model = mongoose.model('Foo', schema);

  log('1. create');
  const doc = new Model({foo: 'bar'});

  const originalInsert = doc.collection.insert;
  doc.collection.insert = function (obj, safe, cb) {
    originalInsert.call(this, obj, safe, function () {
      setTimeout(function () {
        log('5. finish underlying mongo update');
        cb();
      }, 1000);
    })
  };

  const originalSave = doc.save;
  doc.save = function () {
    return originalSave.apply(this, arguments)
    .then(() => log('6. finish mongoose save'));
  };

  log('2. start save');
  return doc.save()
  .then(() => log('7. save done'));
}

output.txt

0. init
1. create
2. start save
3. pre-validate
4. pre-save
5. finish underlying mongo update
8a. post-save
8b. post-save async
6. finish mongoose save
7. save done
8c. post-save async even longer