Unexpected Model Error Event

[stieg]

Do you want to request a feature or report a bug?
Bug

What is the current behavior?
Model is emitting an "Error" event when it is not supposed to according to Mongoose documentation. According to the Model event docs:

error: If listening to this event, it is emitted when a document was saved without passing a callback and an error occurred. If not listening, the event bubbles to the connection used to create this Model.

If the current behavior is a bug, please provide the steps to reproduce.
Sample code:

var Promise = require('bluebird');
var mongoose = require('mongoose');

console.log('mongoose version:', mongoose.version);
mongoose.Promise = Promise;

var schema = mongoose.Schema({
  name: {
    index: true,
    required: true,
    type: String,
    unique: true
  }
});

var Model = mongoose.model('Thing', schema);
Model.on('error', function(err) {
  console.log('Hit Model Error ', err.message);
});

var i1 = new Model({ name: 'Foo' });
var i2 = new Model({ name: 'Foo' });

var connPromise = mongoose.connect('mongodb://localhost/testErr');
connPromise.then(function() {
  return i1.save();
}).then(function() {
  return i2.save();
}).then(function(doc) {
  console.log("WAT!");
}).catch(function(err) {
  console.log("Expected Err: " + err);
}).finally(function() {
  i1.remove();
  mongoose.connection.close();
});

$ node index.js
mongoose version: 4.9.7
Hit Model Error  E11000 duplicate key error collection: testErr.things index: name_1 dup key: { : "Foo" }
Expected Err: WriteError({"code":11000,"index":0,"errmsg":"E11000 duplicate key error collection: testErr.things index: name_1 dup key: { : \"Foo\" }","op":{"name":"Foo","_id":"5908f5208606f4699a2f7a8e","__v":0}})

What is the expected behavior?
I would expect only the Expected Error to show up, not the Model Error. I see that they are separate errors so that is probably related.

Please mention your node.js, mongoose and MongoDB version.
Node: v6.10.0
MongoDB: 3.2.12
Mongoose: 4.9.7

[stieg]

Bump Anybody?

[c0d0g3n]

Both errors are the same. (See their messages or try logging them in the same way.)

Also you are not passing a callback right there (as in i1.save(function...)), so you see Model Error because you are listening for and logging it, right? :)

I hope this helps.

[stieg]

LOL. you make a fair point. Even if I rewrite the code I still see the same behavior. Observe:

var Promise = require('bluebird');
var mongoose = require('mongoose');

console.log('mongoose version:', mongoose.version);
mongoose.Promise = Promise;

var schema = mongoose.Schema({
  name: {
    index: true,
    required: true,
    type: String,
    unique: true
  }
});

var Model = mongoose.model('Thing', schema);
Model.on('error', function(err) {
  console.log('Hit Model Error ', err.message);
});

var i1 = new Model({ name: 'Foo' });
var i2 = new Model({ name: 'Foo' });

function cleanup() {
  i1.remove();
  mongoose.connection.close();
}

var connPromise = mongoose.connect('mongodb://localhost/testErr');
connPromise.then(function() {
  i1.save(function(err) {
    if (err) {
      console.log("i1 err save: " + err.message);
      return;
    }

    i2.save(function(err) {
      if (err) {
        console.log("Expected err: " + err.message);
        return cleanup();
      }

      console.log('WAT!');
      return cleanup();
    });
  });
});

Output:

$ node index.js
mongoose version: 4.9.7
Hit Model Error  E11000 duplicate key error collection: testErr.things index: name_1 dup key: { : "Foo" }
Expected err: E11000 duplicate key error collection: testErr.things index: name_1 dup key: { : "Foo" }

So the issue is real... just my initial example was fundamentally flawed. Also this seems silly if the behavior would be like that way for promises. But that is what the documentation says. shrug

[c0d0g3n]

Then either the docs or source code should be changed to align description and behavior. I think most likely the former, as it would be very odd to not receive an event on the model because you were handling it somewhere else. (Imagine hooking a logger into the event, and displaying messages to the user via Promise.catch f.i.)

I'm not the person to make those decisions, though.

[stieg]

@c0d0g3n Indeed. I imagine you are correct with this being a doc error as well. Know who would be the person to ping about such issues?

[c0d0g3n]

@vkarpov15 is this an error in the docs?

[sobafuchs]

thanks for the repro script. I think the Model error should still get triggered (for logging purposes, as @c0d0g3n mentioned), but open to discussion, I'll label this docs for now.

[stieg]

Perhaps some context would shed light on why I raised this issue. Internally we use the model index to enforce a unique email within the system. Recently I started listening to these events to try an diagnose another issue I was occasionally observing in error logs. Upon doing this I started receiving these index alerts (which makes sense, though it is counter to what the docs indicate). I guess I am trying to figure out the value add of keeping the error emitting here every time one occurs. From my perspective the way the docs describe it is the desired behavior. You really only want to emit on this event handler if an error occurs and there is nothing to handle it. This allows developers to have safe catch-alls. Otherwise what is really gained by having this event emitter here that isn't gained by handling the error in a callback method? My 2 cents anyways...

[vkarpov15]

So there's a slight misunderstanding here in that the docs explicitly specify "called without a callback", which you are doing by using promise chaining. Without monkey-patching .then(), there's no way that I'm aware of for mongoose to know whether you attached a then() or catch() to a promise that it returned, so no way for mongoose to know that it should not emit an error if you added .catch() to your promise. I really don't want to patch .then() for transactional code like save().

TLDR; right now if you use promises without a callback you'll always get the error event. I think the better way to do what you're trying to do is node's process.on('unhandledRejection') event.

[stieg]

Hey @vkarpov15 not sure if you saw #5216 (comment) but even if you provide a callback the behavior is still broken based on the docs. I agree with your assessment RE promises; not much to be done there. However it would appear there is still a minor issues here, hence I am re-opening this so you will address that point. I'm not trying to cause an argument; just want to see this settled completely is all.

[vkarpov15]

Yeah there's a bug that's fixed in 0eda07a and 7182998, will be in 4.9.9

[stieg]

Killer. Thanks for the follow up. I do appreciate the work you all do here. Cheers.

On Sat, May 13, 2017 at 6:29 PM Valeri Karpov ***@***.***> wrote: Yeah there's a bug that's fixed in 0eda07a <0eda07a> and 7182998 <7182998>, will be in 4.9.9 — You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub <#5216 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAIoz5finXsuuy1oczt-K57Md6fRiPn9ks5r5jzigaJpZM4NOshq> .

-- -- Andrew Stiegmann