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

retryWrites seems not to work as expected in failover test

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 3.5.2
    • Affects Version/s: 3.4.1
    • Component/s: None
    • Labels:

      In my failover test, retryWrites is turned on. "not master" errors are observed in a very high frequency.

      On server side, I use a 3-node replica-set, setup by docker. There are 2 test files written in javascript and python respectively. What these test files do is to insert documents repeatedly for every 3 seconds. When these tests are running, I run 'rs.stepDown()' on the primary node from time to time. I expect that the insertions will be successful, assuming that the replica-set election doesn't take more than 30 seconds (default serverSelectionTimeoutMS) to complete. My tests show following result

      • Nodejs version test, with retryWrites always turned on, received a lot of 'not master' error. The error rate is basically equal to the rate in python version test with retryWrites is turned off.
      • Python version test, if retryWrites is not turned off explicitly, received almost no error, unless the replica-set takes too much time to elect a new primary.
      • Nodejs version test may be blocked in 'await insertOne()', if the insertion has no wtimeout option.

       

      Mongodb: 4.2.2

      Nodejs driver: mongodb 3.4.1

      Python driver: pymongo 3.10

       

      Mongodb Replica-Set docker stack file

       

      version: '3.4'
      services:
        mdb1:
          image: mongo:4.2
          volumes:
            - ./test/mongodb-rs1:/data/db
          command: mongod --replSet gs --wiredTigerCacheSizeGB 1
          networks:
            - flowers  
      
        mdb2:
          image: mongo:4.2
          volumes:
            - ./test/mongodb-rs2:/data/db
          command: mongod --replSet gs --wiredTigerCacheSizeGB 1
          networks:
            - flowers  
      
        mdb3:
          image: mongo:4.2
          volumes:
            - ./test/mongodb-rs3:/data/db
          command: mongod --replSet gs --wiredTigerCacheSizeGB 1
          networks:
            - flowers  
      
        exp4:
          image: "node:12"
          user: node
          volumes:
            - ./test/nodejs:/usr/src/app
          networks:
            - flowers
          working_dir: /usr/src/app    
          stdin_open: true
          tty: true
          command: bash  
      
        exp5:
          image: "python"
          volumes:
            - ./test/python:/usr/src/app
          networks:
            - flowers
          working_dir: /usr/src/app    
          stdin_open: true
          tty: true
          command: bash
      
      networks:
        flowers:
      

       

       

      nodejs test

      var MongoClient = require('mongodb').MongoClient;
      var errs = 0, total = 0;
      async function write(db, start) {
        console.log('Writing', start);
        total ++;
        try {
          await db.collection('test').insertOne(
            { time: start, by: 'nodejs' }, {wtimeout: 40000});
          var now = new Date();
          console.log(`Insert finished in ${now.getTime() - start.getTime()}, <= ${start}, Stats <${errs}/${total}>`);
        } catch (error) {
          errs ++;
          console.error('Insertion test error:', start, error);
          console.log(`Stats: <${errs}/${total}>`);
        }
      }
      
      function delay(ms) {
        return new Promise((resolve, reject) => {
          setTimeout(() => resolve(), ms);
        });
      }
      
      (async function(){
        var url = 'mongodb://mdb1:27017,mdb2:27017,mdb3:27017/geekmooc?replicaSet=gs&retryWrites=true&w=majority&serverSelectionTimeoutMS=30000';
        console.log(`Connecting to ${url}`);
        try {
          var client = await MongoClient.connect(url, {
            useNewUrlParser: true, useUnifiedTopology: true,
            replicaSet: 'gs',
          });
          var db = client.db('geekmooc');
          while (true) {
            await write(db, new Date());
            await delay(3000);
          }
        } catch (error) {
          console.error('Connection failure', error);
        }
      })();

      Python test

      import random, string, datetime, sys, time, logging, traceback
      import pymongo
      
      logger = logging.getLogger("test")
      out_hdlr = logging.StreamHandler(sys.stdout)
      out_hdlr.setFormatter(logging.Formatter('%(asctime)s %(message)s'))
      out_hdlr.setLevel(logging.INFO)
      logger.addHandler(out_hdlr)
      logger.setLevel(logging.INFO)MONGO_URI = 'mongodb://mdb1:27017,mdb2:27017,mdb3:27017/geekmooc?replicaSet=gs&retryWrites=false&w=majority&serverSelectionTimeoutMS=30000'logger.info("Attempting to connect...")
      
      client = pymongo.MongoClient(MONGO_URI)
      logger.info("Connected")
      db = client['test']
      coll = db['test']
      collection = coll.with_options(write_concern=pymongo.WriteConcern(w=2, wtimeout=40000))
      i = 0
      errs = 0
      total = 0
      while True:
          try:
              total += 1
              start = datetime.datetime.utcnow()
              logger.info("Inserting: %s" %start)
              text = ''.join(random.choices(string.ascii_uppercase + string.digits, k = 3))
              doc = { "idx": i, "date" : start, "text" : text}
              i += 1
              id = collection.insert_one(doc).inserted_id
              logger.info("Record inserted - id: %s, stats: %d/%d" %(str(id), errs, total))
              time.sleep(3)
          except Exception as e:  # pymongo.errors.ConnectionFailure
              errs += 1
              logger.error("Exception seen: " + str(e))
              traceback.print_exc(file = sys.stdout)
              logger.info("Retrying...")logger.info("Done...")
      client.close()

            Assignee:
            matt.broadstone@mongodb.com Matt Broadstone
            Reporter:
            qu.dongsheng@gmail.com Qu Dongsheng
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: