Mongoose: Want to $inc 1, but it's actually increasing by 2

[iTonyYo]

• mongodb v3.6.3
• mongoose v5.0.11
• node v8.9.4

The strange problem is described in the comment below.

async function newVisit(ctx) {
  let {
    shortid,
  } = ctx.params;

  let { stringify } = JSON;
  let { openSync } = maxmind;

  let cityLookup = openSync(process.env.GEODATA);

  // test ip: 219.76.153.227
  let city = cityLookup.get('219.76.153.227');

  let TblShortUrlVisiting = ctx.model('Short Url Visiting');

  let shortUrlVisitingRecord = await TblShortUrlVisiting.findOne({
    'stId': shortid,
  });

  // no visiting record
  if (isEmpty(shortUrlVisitingRecord)) {
    let toBeSave = {
      stId: shortid,
      birth: now(),
      visitDetails: [
        {
          date: now(),
          ua: stringify(ctx.userAgent),
          geo: stringify(city),
        }
      ],
    };

    let tblShortUrlVisiting = new TblShortUrlVisiting(toBeSave);

    await tblShortUrlVisiting.save();

  } else {

    // has visiting record

    await TblShortUrlVisiting.update({
      'stId': shortid,
    }, {

      /**
       * ATTENTION:
       * 
       * I have to set 0.5 to increment 1.
       * If I set 1, it will going to increment by 2.
       * OMG!
       */
      $inc: {
        visitTimes: 0.5,
      },

      // This has been pushed twice...
      $push: {
        visitDetails: {
          date: now(),
          ua: stringify(ctx.userAgent),
          geo: stringify(city),
        },
      },
    }, {
      safe: true,
      upsert: false,
    }, (err, rawResponse) => {
      if (err) {
        throw err;
      }
    });

  }
}

[lineus]

Hi @iTonyYo have you tried setting mongoose.set('debug', true) ? If that doesn't help (ie. seeing multiple .update() calls when you only expect one, etc) then please comment here with a minimal but complete example of how to reproduce the behavior you are seeing.

Here is an example of a reproducible example:

6271.js

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

const assert = require('assert')
const mongoose = require('mongoose')
mongoose.connect('mongodb://localhost/test')
const Schema = mongoose.Schema

const schema = new Schema({
  name: String,
  age: Number
})

const Person = mongoose.model('person', schema)

const billy = new Person({
  name: 'William',
  age: 1
})

async function run () {
  await Person.remove({})
  await billy.save()
  let cond = { _id: billy._id }
  let upd = { $inc: { age: 1 } }
  let opts = { safe: true, upsert: false }
  for (let i = 0; i < 9; i++) {
    await Person.findOneAndUpdate(cond, upd, opts).exec()
  }
  let { age, name } = await Person.findOne(cond)
  assert.equal(age, 10)
  console.log(`Happy 10th Birthday ${name}!`)
  return mongoose.connection.close()
}

run()

Output:

issues: ./6271.js 
Happy 10th Birthday William!
issues: 

[varunjayaraman]

yeah, could you show us your mongoose debug output @iTonyYo ?

[iTonyYo]

@lineus @varunjayaraman

The above code，

Here is the mongoose debug output,

  <-- GET /SJ0cZTaQf
Mongoose: suvs.findOne({ stId: 'SJ0cZTaQf' }, { fields: {} })
Mongoose: suvs.ensureIndex({ stId: 1 }, { background: true })
Mongoose: suvs.ensureIndex({ birth: 1 }, { background: true })
Mongoose: suvs.update({ stId: 'SJ0cZTaQf' }, { '$setOnInsert': { createdAt: new Date("Wed, 28 Mar 2018 04:47:47 GMT") }, '$set': {}, '$push': { visitDetails: { _id: ObjectId("5abb1e73857d5543e846ed75"), date: new Date("Wed, 28 Mar 2018 04:47:47 GMT"), ua: '{"isAuthoritative":false,"isMobile":false,"isTablet":false,"isiPad":false,"isiPod":false,"isiPhone":false,"isAndroid":false,"isBlackberry":false,"isOpera":false,"isIE":false,"isEdge":false,"isIECompatibilityMode":false,"isSafari":false,"isFirefox":false,"isWebkit":false,"isChrome":false,"isKonqueror":false,"isOmniWeb":false,"isSeaMonkey":false,"isFlock":false,"isAmaya":false,"isPhantomJS":false,"isEpiphany":false,"isDesktop":false,"isWindows":false,"isLinux":false,"isLinux64":false,"isMac":false,"isChromeOS":false,"isBada":false,"isSamsung":false,"isRaspberry":false,"isBot":false,"isCurl":false,"isAndroidTablet":false,"isWinJs":false,"isKindleFire":false,"isSilk":false,"isCaptive":false,"isSmartTV":false,"isUC":false,"isElectron":false,"silkAccelerated":false,"browser":"PostmanRuntime","version":"7.1.1","os":"unknown","platform":"unknown","geoIp":{},"electronVersion":"","source":"PostmanRuntime/7.1.1"}', geo: '{"city":{"geoname_id":1818501,"names":{"en":"Tsimshatsui","zh-CN":"尖沙咀"}},"continent":{"code":"AS","geoname_id":6255147,"names":{"de":"Asien","en":"Asia","es":"Asia","fr":"Asie","ja":"アジア","pt-BR":"Ásia","ru":"Азия","zh-CN":"亚洲"}},"country":{"geoname_id":1819730,"iso_code":"HK","names":{"de":"Hongkong","en":"Hong Kong","es":"Hong Kong","fr":"Hong Kong","ja":"香港","pt-BR":"Hong Kong","ru":"Гонконг","zh-CN":"香港"}},"location":{"accuracy_radius":1,"latitude":22.3,"longitude":114.1667,"time_zone":"Asia/Hong_Kong"},"registered_country":{"geoname_id":1819730,"iso_code":"HK","names":{"de":"Hongkong","en":"Hong Kong","es":"Hong Kong","fr":"Hong Kong","ja":"香港","pt-BR":"Hong Kong","ru":"Гонконг","zh-CN":"香港"}},"subdivisions":[{"geoname_id":7533612,"iso_code":"KKC","names":{"en":"Kowloon City","ja":"九龍城区","ru":"Коулун-Сити"}}]}' } }, '$inc': { visitTimes: 0.5 } }, { upsert: false, overwrite: undefined })
Mongoose: suvs.update({ stId: 'SJ0cZTaQf' }, { '$setOnInsert': { createdAt: new Date("Wed, 28 Mar 2018 04:47:47 GMT") }, '$set': {}, '$push': { visitDetails: { _id: ObjectId("5abb1e73857d5543e846ed75"), date: new Date("Wed, 28 Mar 2018 04:47:47 GMT"), ua: '{"isAuthoritative":false,"isMobile":false,"isTablet":false,"isiPad":false,"isiPod":false,"isiPhone":false,"isAndroid":false,"isBlackberry":false,"isOpera":false,"isIE":false,"isEdge":false,"isIECompatibilityMode":false,"isSafari":false,"isFirefox":false,"isWebkit":false,"isChrome":false,"isKonqueror":false,"isOmniWeb":false,"isSeaMonkey":false,"isFlock":false,"isAmaya":false,"isPhantomJS":false,"isEpiphany":false,"isDesktop":false,"isWindows":false,"isLinux":false,"isLinux64":false,"isMac":false,"isChromeOS":false,"isBada":false,"isSamsung":false,"isRaspberry":false,"isBot":false,"isCurl":false,"isAndroidTablet":false,"isWinJs":false,"isKindleFire":false,"isSilk":false,"isCaptive":false,"isSmartTV":false,"isUC":false,"isElectron":false,"silkAccelerated":false,"browser":"PostmanRuntime","version":"7.1.1","os":"unknown","platform":"unknown","geoIp":{},"electronVersion":"","source":"PostmanRuntime/7.1.1"}', geo: '{"city":{"geoname_id":1818501,"names":{"en":"Tsimshatsui","zh-CN":"尖沙咀"}},"continent":{"code":"AS","geoname_id":6255147,"names":{"de":"Asien","en":"Asia","es":"Asia","fr":"Asie","ja":"アジア","pt-BR":"Ásia","ru":"Азия","zh-CN":"亚洲"}},"country":{"geoname_id":1819730,"iso_code":"HK","names":{"de":"Hongkong","en":"Hong Kong","es":"Hong Kong","fr":"Hong Kong","ja":"香港","pt-BR":"Hong Kong","ru":"Гонконг","zh-CN":"香港"}},"location":{"accuracy_radius":1,"latitude":22.3,"longitude":114.1667,"time_zone":"Asia/Hong_Kong"},"registered_country":{"geoname_id":1819730,"iso_code":"HK","names":{"de":"Hongkong","en":"Hong Kong","es":"Hong Kong","fr":"Hong Kong","ja":"香港","pt-BR":"Hong Kong","ru":"Гонконг","zh-CN":"香港"}},"subdivisions":[{"geoname_id":7533612,"iso_code":"KKC","names":{"en":"Kowloon City","ja":"九龍城区","ru":"Коулун-Сити"}}]}' } }, '$inc': { visitTimes: 0.5 } }, { upsert: false, overwrite: undefined })
Mongoose: suvs.ensureIndex({ createdAt: -1, birth: -1 }, { background: true })

events.js:183
      throw er; // Unhandled 'error' event
      ^
MongoError: '$set' is empty. You must specify a field like so: {$set: {<field>: ...}}
    at Function.MongoError.create (/Users/iTonyYo/Development/huso/inner/huso.io/node_modules/mongodb-core/lib/error.js:45:10)
    at toError (/Users/iTonyYo/Development/huso/inner/huso.io/node_modules/mongodb/lib/utils.js:149:22)
    at /Users/iTonyYo/Development/huso/inner/huso.io/node_modules/mongodb/lib/collection.js:1035:39
    at /Users/iTonyYo/Development/huso/inner/huso.io/node_modules/mongodb-core/lib/connection/pool.js:541:18
    at _combinedTickCallback (internal/process/next_tick.js:131:7)
    at process._tickDomainCallback (internal/process/next_tick.js:218:9)
[nodemon] app crashed - waiting for file changes before starting...

It could have been executed successfully, but now it can only be stored successfully without the same stId, unable to update doc of the same stId.

[iTonyYo]

@lineus @varunjayaraman

A minimal but complete example,

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

const _ = require('lodash');
const mongoose = require('mongoose');

mongoose
  .set('debug', true);

mongoose
  .connect(
    'mongodb://...'
  );

const Schema = mongoose.Schema;
const schema = new Schema(
  {
    stId: {
      type: String,
      required: true,
      index: true,
    },

    birth: {
      type: Date,
      required: true,
      index: true,
    },

    visitDetails: [{
      date: {
        type: Date,
        required: true,
      },

      ua: {
        type: String,
        required: true,
      },

      geo: {
        type: String,
        required: true,
      },
    }],

    visitTimes: {
      type: Number,
      default: 1,
    }
  },

  {
    timestamps: {
      updatedAt: false,
    },
  }
);

const SHORT_ID = 'DA8LAQYICgk';
const TblHus = mongoose.model('hus', schema);

(async () => {
  let existenceOfStId = await TblHus.findOne({
    'stId': SHORT_ID,
  });

  // no visiting record
  if (_.isEmpty(existenceOfStId)) {
    let tblHus = new TblHus(
      {
        stId: SHORT_ID,
        birth: _.now(),
        visitDetails: [
          {
            date: _.now(),
            ua: 'example',
            geo: 'example',
          }
        ],
      }
    );

    await tblHus.save();

  } else {

    // has visiting record

    await TblHus.update(
      {
        'stId': SHORT_ID,
      },

      {
        $inc: {
          visitTimes: 0.5,
        },

        $push: {
          visitDetails: {
            date: _.now(),
            ua: 'example',
            geo: 'example',
          },
        },
      },

      {
        safe: true,
        upsert: false,
      },

      (err, rawResponse) => {
        if (err) {
          throw err;
        }
      }
    );

  }

  mongoose.connection.close();
})();

:cyclone: it can only be stored successfully without the same stId,

Mongoose: hus.ensureIndex({ stId: 1 }, { background: true })
Mongoose: hus.findOne({ stId: 'DA8LAQYICgk' }, { fields: {} })
Mongoose: hus.insert({ visitTimes: 1, _id: ObjectId("5abb28e2a80ce36e105b4863"), stId: 'DA8LAQYICgk', birth: new Date("Wed, 28 Mar 2018 05:32:18 GMT"), visitDetails: [ { _id: ObjectId("5abb28e2a80ce36e105b4864"), date: new Date("Wed, 28 Mar 2018 05:32:18 GMT"), ua: 'example', geo: 'example' } ], createdAt: new Date("Wed, 28 Mar 2018 05:32:18 GMT"), __v: 0 })

:cyclone: unable to update doc, and it tries to update twice,

Mongoose: hus.ensureIndex({ stId: 1 }, { background: true })
Mongoose: hus.findOne({ stId: 'DA8LAQYICgk' }, { fields: {} })
Mongoose: hus.ensureIndex({ birth: 1 }, { background: true })
Mongoose: hus.update({ stId: 'DA8LAQYICgk' }, { '$set': {}, '$setOnInsert': { __v: 0, createdAt: new Date("Wed, 28 Mar 2018 05:33:09 GMT") }, '$push': { visitDetails: { _id: ObjectId("5abb291550ee016ed44d8010"), date: new Date("Wed, 28 Mar 2018 05:33:09 GMT"), ua: 'example', geo: 'example' } }, '$inc': { visitTimes: 0.5 } }, { safe: true, upsert: true, overwrite: undefined })
Mongoose: hus.update({ stId: 'DA8LAQYICgk' }, { '$set': {}, '$setOnInsert': { __v: 0, createdAt: new Date("Wed, 28 Mar 2018 05:33:09 GMT") }, '$push': { visitDetails: { _id: ObjectId("5abb291550ee016ed44d8010"), date: new Date("Wed, 28 Mar 2018 05:33:09 GMT"), ua: 'example', geo: 'example' } }, '$inc': { visitTimes: 0.5 } }, { safe: true, upsert: true, overwrite: undefined })

events.js:183
      throw er; // Unhandled 'error' event
      ^
MongoError: '$set' is empty. You must specify a field like so: {$set: {<field>: ...}}
    at Function.MongoError.create (/Users/iTonyYo/Development/huso/inner/huso.io/node_modules/mongodb-core/lib/error.js:45:10)
    at toError (/Users/iTonyYo/Development/huso/inner/huso.io/node_modules/mongodb/lib/utils.js:149:22)
    at /Users/iTonyYo/Development/huso/inner/huso.io/node_modules/mongodb/lib/collection.js:1035:39
    at /Users/iTonyYo/Development/huso/inner/huso.io/node_modules/mongodb-core/lib/connection/pool.js:541:18
    at _combinedTickCallback (internal/process/next_tick.js:131:7)
    at process._tickCallback (internal/process/next_tick.js:180:9)

:cyclone: fixed MongoError: '$set' is empty. by adding $set below,

$set: {
  birth: existenceOfStId.birth,
},

the debug output is,

Mongoose: hus.ensureIndex({ stId: 1 }, { background: true })
Mongoose: hus.findOne({ stId: 'DA8LAQYICgk' }, { fields: {} })
Mongoose: hus.ensureIndex({ birth: 1 }, { background: true })
Mongoose: hus.update({ stId: 'DA8LAQYICgk' }, { '$setOnInsert': { createdAt: new Date("Wed, 28 Mar 2018 05:49:10 GMT") }, '$push': { visitDetails: { _id: ObjectId("5abb2cd65d54177d581daa8c"), date: new Date("Wed, 28 Mar 2018 05:49:10 GMT"), ua: 'example', geo: 'example' } }, '$inc': { visitTimes: 0.5 }, '$set': { birth: new Date("Wed, 28 Mar 2018 05:47:27 GMT") } }, { safe: true, upsert: false, overwrite: undefined })
Mongoose: hus.update({ stId: 'DA8LAQYICgk' }, { '$setOnInsert': { createdAt: new Date("Wed, 28 Mar 2018 05:49:10 GMT") }, '$push': { visitDetails: { _id: ObjectId("5abb2cd65d54177d581daa8c"), date: new Date("Wed, 28 Mar 2018 05:49:10 GMT"), ua: 'example', geo: 'example' } }, '$inc': { visitTimes: 0.5 }, '$set': { birth: new Date("Wed, 28 Mar 2018 05:47:27 GMT") } }, { safe: true, upsert: false, overwrite: undefined })

[lineus]

@iTonyYo I don't think you want to modify the birth field of the document just to increment the visit counter. I understand why you did it to make the query work, but I assume you'd like to ultimately keep it set to when the document was actually "born".

I believe that you've either identified a bug in Model.update, or a place for improvement in the docs (or a gap in my knowledge). I'll explore this further.

In the meantime, you can call TblHus.findOneAndUpdate( instead of TblHus.update(. This will allow you to remove the unwanted mutation of the birth: path and since only one findAndModify() will run, you can change your $inc to 1.

Here's how I modified your example:

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

const _ = require('lodash')
const mongoose = require('mongoose')
mongoose.set('debug', true)
mongoose.connect('mongodb://localhost/test')
const Schema = mongoose.Schema
const schema = new Schema({
  stId: {
    type: String,
    required: true,
    index: true
  },
  birth: {
    type: Date,
    required: true,
    index: true
  },
  visitDetails: [{
    date: {
      type: Date,
      required: true
    },
    ua: {
      type: String,
      required: true
    },
    geo: {
      type: String,
      required: true
    }
  }],
  visitTimes: {
    type: Number,
    default: 1
  }
},
{
  timestamps: {
    updatedAt: false
  }
}
)

const SHORT_ID = 'DA8LAQYICgk'
const TblHus = mongoose.model('hus', schema)

async function addOrUpdate () {
  let existenceOfStId = await TblHus.findOne({ 'stId': SHORT_ID })

  if (_.isEmpty(existenceOfStId)) {
    let tblHus = new TblHus(
      {
        stId: SHORT_ID,
        birth: _.now(),
        visitDetails: [
          {
            date: _.now(),
            ua: 'example',
            geo: 'example'
          }
        ]
      })

    await tblHus.save()
  } else {
    await TblHus.findOneAndUpdate({
      'stId': SHORT_ID
    },
    {
      $inc: {
        visitTimes: 1
      },
      $push: {
        visitDetails: {
          date: _.now(),
          ua: 'example',
          geo: 'example'
        }
      }
    }, {
      safe: true,
      upsert: false,
      new: true
    }, (err, doc) => {
      if (err) {
        throw err
      }
      console.log('update:', doc)
      return mongoose.connection.close()
    })
  }
}

addOrUpdate()

Output ( of 2 consecutive runs ):

issues: ./6271_orig.js
Mongoose: hus.ensureIndex({ stId: 1 }, { background: true })
Mongoose: hus.findOne({ stId: 'DA8LAQYICgk' }, { fields: {} })
Mongoose: hus.insert({ visitTimes: 1, _id: ObjectId("5abb557c43793f1fb6145e6f"), stId: 'DA8LAQYICgk', birth: new Date("Wed, 28 Mar 2018 08:42:36 GMT"), visitDetails: [ { _id: ObjectId("5abb557c43793f1fb6145e70"), date: new Date("Wed, 28 Mar 2018 08:42:36 GMT"), ua: 'example', geo: 'example' } ], createdAt: new Date("Wed, 28 Mar 2018 08:42:36 GMT"), __v: 0 })
Mongoose: hus.ensureIndex({ birth: 1 }, { background: true })
^C
issues: ./6271_orig.js
Mongoose: hus.ensureIndex({ stId: 1 }, { background: true })
Mongoose: hus.findOne({ stId: 'DA8LAQYICgk' }, { fields: {} })
Mongoose: hus.ensureIndex({ birth: 1 }, { background: true })
Mongoose: hus.findAndModify({ stId: 'DA8LAQYICgk' }, [], { '$setOnInsert': { createdAt: new Date("Wed, 28 Mar 2018 08:42:39 GMT") }, '$push': { visitDetails: { _id: ObjectId("5abb557f49f0bf1fc9761594"), date: new Date("Wed, 28 Mar 2018 08:42:39 GMT"), ua: 'example', geo: 'example' } }, '$inc': { visitTimes: 1 } }, { safe: true, upsert: false, new: true, overwrite: undefined, remove: false, fields: {} })
update: { visitTimes: 2,
  visitDetails:
   [ { _id: 5abb557c43793f1fb6145e70,
       date: 2018-03-28T08:42:36.053Z,
       ua: 'example',
       geo: 'example' },
     { _id: 5abb557f49f0bf1fc9761594,
       date: 2018-03-28T08:42:39.650Z,
       ua: 'example',
       geo: 'example' } ],
  _id: 5abb557c43793f1fb6145e6f,
  stId: 'DA8LAQYICgk',
  birth: 2018-03-28T08:42:36.053Z,
  createdAt: 2018-03-28T08:42:36.069Z,
  __v: 0 }
issues:

[vkarpov15]

Here's a minimal repro script:

const mongoose = require('mongoose');

mongoose.set('debug', true);

const GITHUB_ISSUE = `gh-6271`;
const connectionString = `mongodb://localhost:27017/${ GITHUB_ISSUE }`;

run().catch(error => console.error(error.stack));

async function run() {
  await mongoose.connect(connectionString);
  await mongoose.connection.dropDatabase();

  const schema = new mongoose.Schema({
    n: Number
  });

  const Model = mongoose.model('Test', schema);

  const doc = await Model.create({ n: 0 });

  await Model.updateOne({ _id: doc._id }, { $inc: { n: 1 } }, err => { console.log(err); });

  // { _id: 5ac4ef85a785710fd239bc04, n: 2, __v: 0 }
  console.log(await Model.findOne());
}

The problem is the callback in your update() call.

await TblShortUrlVisiting.update({
      'stId': shortid,
    }, { /* ... */ }, (err, rawResponse) => {
      if (err) { // <-- Why is this callback here?
        throw err;
      }
    });

When you pass a callback to your query, you execute the query. Then, when you await on the query, you execute it again, so you're actually executing the query twice by passing that unnecessary callback.

[vkarpov15]

As @lineus has pointed out, findOneAndUpdate() behaves differently than updateOne(), so there's still work to be done on this one:

const mongoose = require('mongoose');

mongoose.set('debug', true);

const GITHUB_ISSUE = `gh-6271`;
const connectionString = `mongodb://localhost:27017/${ GITHUB_ISSUE }`;

run().catch(error => console.error(error.stack));

async function run() {
  await mongoose.connect(connectionString);
  await mongoose.connection.dropDatabase();

  const schema = new mongoose.Schema({
    n: Number
  });

  const Model = mongoose.model('Test', schema);

  const doc = await Model.create({ n: 0 });

  await Model.findOneAndUpdate({ _id: doc._id }, { $inc: { n: 1 } }, err => { console.log(err); });

  // { _id: 5ac4fff56268f91c9e58037e, n: 1, __v: 0 }
  console.log(await Model.findOne());
}

[vkarpov15]

In 5.0.13, the findOneAndUpdate() script in the above comment will also print n: 2, because there was a bug where Model.findOneAndUpdate() would not return the query (as documented) if a callback was passed.

[nove1398]

This is happening to me, and based on the debug, i can see the findAndModify is being called twice

[lineus]

@nove1398 can you provide a code sample that demonstrates what you're seeing as well as provide the version of mongoose?

for example:

novel1398.js

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

const assert = require('assert');
const mongoose = require('mongoose');
mongoose.connect('mongodb://localhost:27017/test', { useNewUrlParser: true });
const conn = mongoose.connection;
const Schema = mongoose.Schema;
var called = 0;

function incCalled() {
  called++;
}

const schema = new Schema({
  num: Number
});

schema.pre('update', incCalled);
schema.pre('findOneAndUpdate', incCalled);

const Test = mongoose.model('test', schema);

const test = new Test({ num: 0 });

async function run() {
  await conn.dropDatabase();
  await test.save();
  let cond = { _id: test._id };
  let update = { $inc: { num: 1 } };
  await Test.update(cond, update);
  await Test.findOneAndUpdate(cond, update);
  let { num } = await Test.findOne({ _id: test._id });
  assert.strictEqual(called, 2);
  assert.strictEqual(num, 2);
  console.log(`mongoose@${mongoose.version}: All tests passed.`);
  return conn.close();
}

run().catch(console.error);

output:

issues: ./nove1398.js
[email protected]: All tests passed.
issues:

[nove1398]

After some debugging, I realized that my router in express is being called multiple times, so that must be the problem.