v1.6.4 Initialization Error

[winstonjs]

v1.6.4 Initialization Error

[yurijmikhalevich]

Will be fixed asap. Thank you.

[yurijmikhalevich]

@santanu-biswas checkout version 2.0.0

[yurijmikhalevich]

Fixed in 1.6.6 and 2.0.1.

[santanu-biswas]

Bug resolved!
Thanks!

[perrin4869]

Hm... I'm having this problem still, running node 6.9.1 and mongodb version 3.0.6.

Here's the code used to add the mongodb transport:

    logger.add(winston.transports.MongoDB, {
      db: db.getDatabasePromise(),
      collection: 'logs',
      level: config.logging.db,
    });

The error I get:

Unhandled rejection MongoError: index not found with name [timestamp_1]
    at Function.MongoError.create (/home/perrin4869/projects/websites/serapi/node_modules/mongodb-core/lib/error.js:31:11)
    at /home/perrin4869/projects/websites/serapi/node_modules/mongodb-core/lib/connection/pool.js:483:72
    at authenticateStragglers (/home/perrin4869/projects/websites/serapi/node_modules/mongodb-core/lib/connection/pool.js:429:16)
    at Connection.messageHandler (/home/perrin4869/projects/websites/serapi/node_modules/mongodb-core/lib/connection/pool.js:463:5)
    at Socket.<anonymous> (/home/perrin4869/projects/websites/serapi/node_modules/mongodb-core/lib/connection/connection.js:309:22)
    at emitOne (events.js:96:13)
    at Socket.emit (events.js:188:7)
    at readableAddChunk (_stream_readable.js:176:18)
    at Socket.Readable.push (_stream_readable.js:134:10)
    at TCP.onread (net.js:548:20)
From previous event:
    at runCallback (timers.js:637:20)
    at tryOnImmediate (timers.js:610:5)
    at processImmediate [as _immediateCallback] (timers.js:582:5)
From previous event:
    at new exports.MongoDB (/home/perrin4869/projects/websites/serapi/node_modules/winston-mongodb/lib/winston-mongodb.js:151:13)
    at Logger.add (/home/perrin4869/projects/websites/serapi/node_modules/winston/lib/winston/logger.js:481:41)
    at module.exports (/home/perrin4869/projects/websites/serapi/logger.js:46:12)
    at Object.<anonymous> (/home/perrin4869/projects/websites/serapi/chat_server.js:23:35)
    at Module._compile (module.js:570:32)
    at loader (/home/perrin4869/projects/websites/serapi/node_modules/babel-register/lib/node.js:144:5)
    at Object.require.extensions.(anonymous function) (/home/perrin4869/projects/websites/serapi/node_modules/babel-register/lib/node.js:154:7)
    at Module.load (module.js:487:32)
    at tryModuleLoad (module.js:446:12)
    at Function.Module._load (module.js:438:3)
    at Function.Module._load (/home/perrin4869/projects/websites/serapi/node_modules/mock-require/index.js:14:22)
    at Module.require (module.js:497:17)
    at require (internal/module.js:20:19)
    at Object.<anonymous> (/home/perrin4869/projects/websites/serapi/bin/www:19:26)
    at Module._compile (module.js:570:32)
    at Object.Module._extensions..js (module.js:579:10)
    at Module.load (module.js:487:32)
    at tryModuleLoad (module.js:446:12)
    at Function.Module._load (module.js:438:3)
    at Module.runMain (module.js:604:10)
    at run (bootstrap_node.js:394:7)
    at startup (bootstrap_node.js:149:9)
    at bootstrap_node.js:509:3

[yurijmikhalevich]

@perrin4869 try upgrading to winston-mongodb@2

[yurijmikhalevich]

@perrin4869 will backport fix to 1.6

[perrin4869]

@39dotyt I'm actually using winston-mongodb@2

$ cat node_modules/winston-mongodb/package.json | grep version                                                                                                                 
  "version": "2.0.0"

[yurijmikhalevich]

@perrin4869 what is db.getDatabasePromise()?

Can you post minimum runnable example to reproduce the error?

[perrin4869]

This function:

function getDatabasePromise() {
  return new Promise((resolve) => {
    mongoose.connection.once('open', () => {
      resolve(mongoose.connection.db);
    });
  })
}

Returns a promise to a db connection

[perrin4869]

I have traced down the bug to the createCollection function. I'm using [email protected]:

      return col.dropIndex(ttlIndexName).catch(err=>{
        if (err.code !== 27) {
          throw err;
        }
      }).then(()=>col.createIndex({timestamp: -1}, indexOpts)
      ).then(()=>db);

In the snippet above from the function, dropIndex throws an error, but err.code is undefined and therefore the error is propagated. I have no clue why err.code is undefined though. It might be a problem with mongoose. But I did not have this problem before [email protected].

[perrin4869]

OK, just confirmed the error was introduced in v1.6.5. err.code is undefined. I can also not find it in the documentation here: http://mongodb.github.io/node-mongodb-native/core/api/MongoError.html

[perrin4869]

This is the error thrown btw:

{ MongoError: index not found with name [timestamp_1]
    at Function.MongoError.create (/home/perrin4869/projects/websites/serapi/node_modules/mongodb-core/lib/error.js:31:11)
    at /home/perrin4869/projects/websites/serapi/node_modules/mongodb-core/lib/connection/pool.js:483:72
    at authenticateStragglers (/home/perrin4869/projects/websites/serapi/node_modules/mongodb-core/lib/connection/pool.js:429:16)
    at Connection.messageHandler (/home/perrin4869/projects/websites/serapi/node_modules/mongodb-core/lib/connection/pool.js:463:5)
    at Socket.<anonymous> (/home/perrin4869/projects/websites/serapi/node_modules/mongodb-core/lib/connection/connection.js:339:20)
    at emitOne (events.js:96:13)
    at Socket.emit (events.js:188:7)
    at readableAddChunk (_stream_readable.js:176:18)
    at Socket.Readable.push (_stream_readable.js:134:10)
    at TCP.onread (net.js:548:20)
  name: 'MongoError',
  message: 'index not found with name [timestamp_1]',
  nIndexesWas: 2,
  ok: 0,
  errmsg: 'index not found with name [timestamp_1]' }

[perrin4869]

@39dotyt I can try to put together a PR but I'm not sure what would be a good way to go about fixing this... any ideas?

[tibeoh]

Hi @perrin4869,
I agree with you. The issue is here: https://github.com/winstonjs/winston-mongodb/blob/master/lib/winston-mongodb.js#L117
The error.code doesn't exist in mongodb driver >= v2.0

// TODO: drop index only if params changed
return col.dropIndex(ttlIndexName).catch(err=>{
    if (err.code !== 27) {
       throw err;
    }
}).then(()=>col.createIndex({timestamp: -1}, indexOpts)
).then(()=>db);

I would like to fix issue but I don't understand why we need to drop indextimestamp? It's the createCollection method, so the index doesn't exist, no? If you explain to me the goal of this drop, I can try to fix issue.

[Jeff-Lewis]

@tibeoh sounds like the issue. createIndex() will not update an existing index by the same name. It must be dropped first.

Since this behavior changed in mongodb 2.6 and also the node client might handle this differently, it's safer to check col.getIndexes() first to see if it exists instead of relying on error and error codes.