error event not triggered

[OmisNomis]

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

Bug

What is the current behavior?

The error event on mongoose.connection.on('error') is never triggered, when it was on previous versions. For example:

mongoose.connection.on('error', () => {
  console.error('connection error');
});

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

• Start a docker container running Mongo
• Run the application
• Amend the network to 'none'
• Error event is never triggered

What is the expected behavior?

The error event is triggered. This is triggered on previous versions (v4.9.5)

Please mention your node.js, mongoose and MongoDB version.

node - V9.2.0
mongoose - 5.0.4
MongoDB - docker latest

[ghost]

here's the code I used to test this:

#!/usr/bin/env node
'use strict'

const badPortURI = 'mongodb://localhost:111111111111111/test'
const badHostURI = 'mongodb://illbetthishostdoesnthave.dns:27017/test'
const badProtoURI = 'monodb://localhost:27017/test'
const goodUriNoNet = 'mongodb://192.168.1.15:27017/test'
const mongoose = require('mongoose')
mongoose.connection.on('error', function () {
  console.log('rick says: ')
})

mongoose.connect(badPortURI).then(null, function () {
  console.log('never gonna give you up.')
  mongoose.connect(badHostURI).then(null, function () {
    console.log('never gonna let you down.')
    mongoose.connect(badProtoURI).then(null, function () {
      console.log('never gonna run around and desert you.')
      mongoose.connect(goodUriNoNet).then(null, function () {
        console.log('never gonna get real far.')
      })
    })
  })
})

here's my version info and output:

5: nvm current
v9.2.0
5: grep version ../node_modules/mongoose/package.json 
  "version": "5.0.4"
5: ./6131.js 
rick says: 
never gonna give you up.
rick says: 
never gonna let you down.
rick says: 
never gonna run around and desert you.
rick says: 
never gonna get real far.
5: 

there was a delay between my last console message and the termination of the script. I'm guessing total time around a minute, but I did not attempt to time it. Can you try a trivial example like mine, just to see if it behaves as expected?

[OmisNomis]

Hi Lineus,

Firstly; this is the code I was using (I wasn't using promise chains).

'use strict';

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

const port = process.env.PORT || 8086;
const uri = process.env.MONGO || 'mongodb://localhost:27017/test';

const app = express();

mongoose.Promise = global.Promise;

const options = {
  reconnectTries: 1,
  reconnectInterval: 1000,
  bufferMaxEntries: 0,
};

mongoose.connection.on('connected', () => {
  console.log('Connected to Mongo');
});
mongoose.connection.on('reconnected', () => {
  console.log('Reconnected to Mongo');
});
mongoose.connection.on('error', () => {
  console.error('connection error');
});
mongoose.connection.on('disconnected', () => {
  console.log('Mongo disconnected!');
});

mongoose.connect(uri, options);

const server = app.listen(port, () => {
  console.log(`listening on port: ${port}`);
});

module.exports = server;

If I copy and paste your example then it works as expected.

However, if I use a similar syntax (code below), run the application, and then drop database from the network it is not triggered (because the callback has already run).

const uri = 'mongodb://localhost:27017/test';
const mongoose = require('mongoose');
mongoose.connection.on('error', function() {
  console.log('rick says: ');
});

mongoose.connect(uri).then(null, function() {
  console.log('never gonna give you up.');
});

So while the callback method will work to catch errors on initial connection; neither that method nor the Event Emitters seem to work when the database loses connection after it has initially connected.

Hopefully that makes sense??

P.S.... Thanks for rick rolling me!

[OmisNomis]

As an additional point - I tried the following code and the readyState does not change from 1, even when the network is dropped.

'use strict';
const mongoose = require('mongoose');

const port = process.env.PORT || 8086;
const uri = process.env.MONGO || 'mongodb://localhost:27017/test';

mongoose.Promise = global.Promise;

mongoose.connect(uri);

setInterval(() => {
  console.log(mongoose.connection.readyState);
}, 500);

[OmisNomis]

I just debugged a little bit and I can see that when the database is dropped from the network the timeout event is emitted instead of the error event.

This is in lib/connection.js.

db.on('timeout', function() {
          _this.emit('timeout');
        });

Is this by design?

[ghost]

@OmisNomis I apologize for not catching the order of operations in your initial report.

losing your connection to mongodb server after initial connection seems to result in a close event being emitted only if useMongoClient !== true.

In mongoose 4 :

#!/usr/bin/env node
'use strict'

const URI = 'mongodb://localhost:27017/test'
const URI2 = 'mongodb://localhost:27018/test'
const mongoose = require('mongoose')
mongoose.Promise = global.Promise
const mongooseOptions = { }
mongoose.connection.on('error', function () {
  console.log('error event emitted!')
})
mongoose.connection.on('open', function () {
  console.log('open event emitted!')
})
mongoose.connection.on('timeout', function () {
  console.log('timeout event emitted!')
})
mongoose.connection.on('close', function () {
  console.log('close event emitted!')
})
mongoose.connection.on('disconnected', function () {
  console.log('native driver lost connection')
})

mongoose.connect(URI, mongooseOptions)

in all following examples, I kill (^c) mongodb server after connection is made
output:

4: ./6131_3.js 
(node:18221) DeprecationWarning: `open()` is deprecated in mongoose >= 4.11.0, use `openUri()` instead, or set the `useMongoClient` option if using `connect()` or `createConnection()`. See http://mongoosejs.com/docs/connections.html#use-mongo-client
open event emitted!
close event emitted!

after adding useMongoClient: true to mongooseOptions in the code above:

4: ./6131_3.js 
open event emitted!
4:

since mongoose 5 defaults useMongoClient to true, the behavior is the same:

5: ./6131_3.js 
open event emitted!
5: 

after learning about (being reminded of) the disconnect event:

5: ./6131_3.js 
open event emitted!
native driver lost connection
^C
5: 

[OmisNomis]

Thank @lineus but it's not the close event I'm having issue with (mainly because it throws the disconnected event if you kill the Mongo server after connection has been made.)

The event that isn't being triggered is the error event.

[ghost]

I can't believe I didn't know (forgot?) about the disconnected event! I also can't believe it was in your comment above the whole time and I missed it :) thanks for being so patient while I learn this stuff @OmisNomis. I'll leave it to @vkarpov15 or @varunjayaraman to answer your question.

[OmisNomis]

Don't worry about it @lineus - we all have those moments, and we all have to learn. I'm happy to do some more debugging my side if it helps; I just thought I'd post it here in case the error event had been removed on purpose (maybe in favour of timeout?)

[vkarpov15]

The 'error' event is not emitted in either 4.x or 5.x when mongoose loses connection after initial connection was made. The 'error' event only gets emitted when the initial connection fails. Below is the output I get in 4.x when I kill the underlying mongodb database:

$ node gh-6131.js 
(node:14513) DeprecationWarning: `open()` is deprecated in mongoose >= 4.11.0, use `openUri()` instead, or set the `useMongoClient` option if using `connect()` or `createConnection()`. See http://mongoosejs.com/docs/connections.html#use-mongo-client
open event emitted!
1
1
1
1
native driver lost connection
close event emitted!
0
0
0
0
0
0
^C
$ 

And 5.x:

$ node gh-6131.js 
open event emitted!
1
1
1
1
native driver lost connection
0
0
0
0
0
0
1
1
1
1
1
1
1
1
1
1
1
1
1
1
1
1
1
native driver lost connection
0
0
0
^C
$ 

Below is the script:

const URI = 'mongodb://localhost:27017/test'
const mongoose = require('mongoose')
mongoose.Promise = global.Promise
const mongooseOptions = { }
mongoose.connection.on('error', function () {
  console.log('error event emitted!')
})
mongoose.connection.on('open', function () {
  console.log('open event emitted!')
})
mongoose.connection.on('timeout', function () {
  console.log('timeout event emitted!')
})
mongoose.connection.on('close', function () {
  console.log('close event emitted!')
})
mongoose.connection.on('disconnected', function () {
  console.log('native driver lost connection')
})
setInterval(() => {
  console.log(mongoose.connection.readyState);
}, 500);

mongoose.connect(URI, mongooseOptions)

The 'close' event did change slightly in 5.x, right now we only emit 'close' when you explicitly close() the connection as opposed to when the connection is lost.

Can you provide me a link to the mongodb docker image you're using and the steps necessary to "Amend the network to none" in docker? I don't really use docker so there might be some issue there.

[OmisNomis]

@vkarpov15 - Here's an example using version 4.9.5 of Mongoose. Note when I reference using Docker, I'll probably be using Kitematic so will give instructions for that...

• Create a docker container using mongo:latest
• Create a new project, with Mongoose version 4.9.5 and create an index.js file with the following code:

'use strict';

const mongoose = require('mongoose');

const uri = process.env.MONGO || 'mongodb://localhost:27017/test';
mongoose.Promise = global.Promise;

mongoose.connection.on('connected', () => {
  console.log('Connected to Mongo');
});
mongoose.connection.on('error', () => {
  console.error('connection error');
});

mongoose.connect(uri);

• Change the connection string to whatever port your Mongo container is listening on.
• Run your index.js file and ensure you get the Connected to Mongo console log
• Open Kitematic > Select the MongoDB container > Settings > Network > Select none under Configure Network > save
• Go back to the console that is running the application
• After some time (this does take a little while as it's going through the retry count) the console will display connection error

If you now try and do the same thing with version 5.x.x the error event is not triggered, but a new timeout event is.

[sobafuchs]

Isn't this normal? You aren't shutting the database down, youre; changing how the DNS resolves inside your docker network. So the issue isn't really an "error", your connection string was correct when you initially connected, that DNS is now invalid. it's going to timeout in that case

[OmisNomis]

@varunjayaraman my point is in the previous version it triggered the error event, in the latest version it doesn't. It triggers the timeout event instead.

I think the most important thing is if that's the expected behaviour. If it is, maybe the documentation could be updated to reflect the change?

[dcolens]

Repro steps

1. Run (while mongo is running)

const URI = 'mongodb://localhost:27017/test';
const mongoose = require('mongoose');
mongoose.Promise = global.Promise;
const mongooseOptions = {
  socketTimeoutMS: 1000
};

mongoose.connection.on('error', function() {
  console.log('error event emitted!');
});
mongoose.connection.on('open', function() {
  console.log('open event emitted!');
});
mongoose.connection.on('timeout', function() {
  console.log('timeout event emitted!');
});
mongoose.connection.on('close', function() {
  console.log('close event emitted!');
});
mongoose.connection.on('disconnected', function() {
  console.log('native driver lost connection');
});
setInterval(() => {
  console.log(mongoose.connection.readyState);
}, 500);

mongoose.connect(URI, mongooseOptions);

2. Stop the mongo process

Results:

• node v9.3.0
• [email protected]

open event emitted!
1
1
timeout event emitted!
1
1
1
1
timeout event emitted!
1
1
1
1
1
1
timeout event emitted!
1
1
1
timeout event emitted!
1
1
1
1
...

• no event triggered when mongo stops
• timeout events regularly emitted before mongo is stopped
• mongoose still shows as connected while mongo is not running.

Expected Results:

• disconnected event triggered
• no timeout events (am not too sure why we get those anyway?)
• mongoose's connection.readyState is not 1

[vkarpov15]

I think this is the same issue as #6244, because with that fix I get the below output:

$ node gh-6131.js 
open event emitted!
1
1
1
1
native driver lost connection
0
0
0
0
0
0
0
0
0
^C
$ 

Fix should be in 5.0.12