Uploaded image for project: 'Node.js Driver'
  1. Node.js Driver
  2. NODE-99

Cursor.nextObject() callback called twice.

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • 1.4
    • Affects Version/s: 1.3
    • Component/s: None
    • Labels:
    • Environment:
      ubuntu: 12.04 LTS
      node: 0.10.22
      mongodb module: 1.3.19
      mongodb server: 2.4.8 git version: a350fc38922fbda2cec8d5dd842237b904eafc14

      My mongodb setup is simple. I run a two node local replicaset. One of the mongod runs as an arbiter.
      Repro steps:
      1. run the program below.
      2. kill the arbiter mongod process
      3. primary becomes secondary because he is alone.
      4. start arbiter mongod
      5. primary elects itself
      6. the program will detect a callback that is called twice.

      The first time the callback is called it has an error parameter:

      { [MongoError: connection to [127.0.0.1:27017] timed out]
  name: 'MongoError',
  err: 'connection to [127.0.0.1:27017] timed out' }

      At this point the cursor is closed, e.g. cursor.isClosed() returns true.

      The second time the callback is called it has the same error and it is still closed.
      It seems there are internal retries somewhere that keep failing and calling the callback.
      Here is the test program:

      /*jslint nomen: true, node: true, indent: 4 */
'use strict';

var mongodb = require('mongodb'),
    async = require('async'),
    ObjectId = mongodb.ObjectID,
    dbUrl = 'mongodb://127.0.0.1:27017/mydb?replicaSet=rs0',
    dbOptions = {
        db: {
            w: 1
        },
        server: {
            auto_reconnect: true,
            poolSize: 5
        }
    },
    callbacksCalled = {};

function runTest(db, col) {
    var i = 0;

    function next(cursor, id) {
        cursor.nextObject(function (err, doc) {
            if (err) {
                console.log('nextObject', id, 'error:', err);
            } else {
                if (doc) {
                    console.log('nextObject', id, 'found:', doc);
                } else {
                    console.log('nextObject', id, 'no document');
                }
            }

            if (callbacksCalled[id]) {
                console.log('callback', id, 'called twice');
                console.log('dumping the cursor nextObject was called on:');
                console.log(cursor);
                process.exit(1);
            }

            callbacksCalled[id] = true;

            if (cursor.isClosed()) {
                console.log('cursor closed');
                // restart
                i += 10;
                start();
            } else {
                i += 1;
                next(cursor, i);
            }
        });
    }

    function start() {
        var cursor = col.find({}, {tailable: true, numberOfRetries: -1}).
                sort({$natural: 1});
        next(cursor, i);
    }

    start();
}

mongodb.Db.connect(dbUrl, dbOptions, function (err, db) {
    if (err) {
        console.log(err);
        process.exit(1);
    }

    console.log('database connected');

    db.on('error', function (err) {
        console.log('db.on(\'error\'):', err);
    });

    db.createCollection('testCapped', {capped: true, w: 1, size: 100000, max: 20}, function (err, col) {
        if (err) {
            console.log(err);
            process.exit(1);
        }

        console.log('collection created');

        runTest(db, col);
    });
});

      Important note: If you add 

      awaitdata: true

      to the cursor options at line 56, the bug doesn't happen.
      Instead, the callback receives a first error a lot faster and the error is 

      [Error: connection closed]

      That callback is never called again.
      However, you will get timeout errors every 30 seconds. These timeout errors do not happen until you kill the arbiter. This doesn't cause problems in my actual application but I thought I should mention it anyway.

            Assignee:
            christkv Christian Amor Kvalheim
            Reporter:
            sbeaule Stéphane Beaulé
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: