Mongoose: No document found for query "{ _id: xxx }"

[adamreisnz]

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

What is the current behavior?
We have an automated task that runs every week, and every week we get this error thrown from the task:

No document found for query "{ _id: xxxxx }"

If the current behavior is a bug, please provide the steps to reproduce.
I don't know how to reproduce it or why this bug is happening. The document exists in the database. The related code is:

ScheduleSchema.methods.updateLastRun = function() {
  this.lastRun = Date.now();
  return this.save();
};

What's odd is that the document does seem to update/be saved, despite the error.

What is the expected behavior?
If I had more understanding of why this error is thrown, I would be able to better assess this.

What are the versions of Node.js, Mongoose and MongoDB you are using? Note that "latest" is not a version.
Node 10.15.3
Mongoose 5.4.20

[vkarpov15]

@adamreisnz see my comments from https://github.com/Automattic/mongoose/issues/6215#issuecomment-496995182 . The below code sample throws the 'No document found' error:

const assert = require('assert');
const mongoose = require('mongoose');
mongoose.set('debug', true);

const GITHUB_ISSUE = `gh6215`;
const connectionString = `mongodb://localhost:27017/${ GITHUB_ISSUE }`;
const { Schema } = mongoose;

run().then(() => console.log('done')).catch(error => console.error(error.stack));

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

  const schema = new Schema({ name: String });
  const Model = mongoose.model('Test', schema);

  const doc = await Model.create({ name: 'foo' });

  await Model.deleteMany({});

  doc.name = 'bar';
  await doc.save();
}

It looks like you know the save() call that is causing this, so stack trace won't be helpful. Can you clarify what version of MongoDB you're running?

[adamreisnz]

Thanks for your reply. I can confirm that the document is not being deleted from the database at any stage. We have some static configuration schedules in the database, to dictate when certain tasks are to be run, and when they run, we update their lastRun timestamp and that's all that happens. This happens with a regular .save() call as per the above.

Moreover, we've had this setup running for more than 2 years now, with various tasks, but this error only occurs with this one particular task, and only started happening in the last month or so, without us making any changes to the task.

So it seems like the problem may lie deeper.

We are running on mongod version 3.6.11 (MMAPv1) at the moment.

[vkarpov15]

How certain are you that is the update that's causing this error message? Here's a couple possibilities:

1) The MongoDB driver is sending back a result that Mongoose can't understand when it attempts to figure out whether the document was updated or not

2) A different save() is causing this error.

I haven't been able to repro this against MongoDB 3.6.11, but I can add a couple properties to the DocumentNotFoundError that may be able to help us figure out what's going on here. Would you be able to upgrade to 5.5.x?

[adamreisnz]

Based on the stack trace, I'm 100% certain it's coming from the update. Here is the stack trace for reference:

No document found for query "{ _id: 5acc19781ab6fd00041d4208 }"
node_modules/mongoose/lib/error/notFound.js in new DocumentNotFoundError at line 31:11
node_modules/mongoose/lib/model.js in $__handleSave at line 376:17
node_modules/mongoose/lib/model.js in null.<anonymous> at line 308:9
node_modules/mongodb/lib/utils.js in result at line 414:17
node_modules/mongodb/lib/utils.js in session.endSession at line 401:11
node_modules/mongodb-core/lib/sessions.js in ClientSession.endSession at line 129:41
node_modules/mongodb/lib/utils.js in executeCallback at line 397:17
node_modules/mongodb/lib/operations/collection_ops.js in updateCallback at line 1362:3
node_modules/mongodb/lib/operations/collection_ops.js in updateDocuments at line 1451:62
node_modules/mongodb/lib/utils.js in handleCallback at line 128:55
node_modules/mongodb/lib/operations/collection_ops.js in coll.s.topology.update at line 1416:5
node_modules/mongodb-core/lib/topologies/replset.js in handler at line 1197:22
node_modules/mongodb-core/lib/connection/pool.js in null.<anonymous> at line 532:18
internal/process/next_tick.js in process._tickCallback at line 61:11
node_modules/mongoose/lib/utils.js in Object.promiseOrCallback at line 269:10
node_modules/mongoose/lib/model.js in model.Model.save at line 455:16
app/components/shared/schedule.model.js in model.ScheduleSchema.methods.updateLastRun at line 48:15
app/components/shared/schedule.model.js in Function.ScheduleSchema.statics.check at line 120:18

The code for updateLastRun is listed above in my original post, which all it does really is update a property and save.

And the issue comes up every week like clockwork, whenever the weekly task is scheduled to run. There is no other save() that would run at the same time, and if it would be a code issue, we would be running into it with all our tasks, as they all call the same method. It only started happening a few weeks ago, possible after we updated Mongoose or our MongoDB version.

The whole collection only contains 5 documents, and the affected document looks like this:

{
    "_id" : ObjectId("5acc19781ab6fd00041d4208"),
    "isEnabled" : true,
    "times" : [ 
        630
    ],
    "margin" : 90,
    "lastRun" : ISODate("2019-06-02T22:01:28.552Z"),
    "identifier" : "email/financial-summary",
    "__v" : 2,
    "daysOfWeek" : [ 
        1
    ],
    "daysOfMonth" : []
}

As you can see by the lastRun timestamp, the update is successful and the document does get updated.

Yes, I'm happy to update the version of Mongoose if that'll help debugging this. Let me know if you need me to log some additional properties or data.

[vkarpov15]

@adamreisnz I added two properties to the error to help debug, err.numAffected and err.result. This will help us figure out whether there's an unexpected result from the MongoDB server or if there's something else going on. Try console.log(err.numAffected) and console.log(err.result) when the error occurs.

[adamreisnz]

Thanks, Sentry should display those extra properties for us when it captures the error.
I'll upgrade to the latest Mongoose and see what we find. It will only occur again next week though, when the task next runs.

[vkarpov15]

@adamreisnz we just shipped v5.5.15 with the new numAffected and result properties for DocumentNotFoundError. Please upgrade and we'll see if we can catch this bug. I appreciate your patience - debugging remotely is tricky :+1:

[adamreisnz]

No worries, appreciate you looking into it. I've bumped our version to 5.5.15, so come Monday we will hopefully have more information as to what's happening 👀

[vkarpov15]

@adamreisnz any more info on your end?

[adamreisnz]

Sorry, I've had to fly overseas urgently. I will investigate shortly and
see if we have additional data to debug this.

On Sat, 22 Jun 2019 at 03:19, Valeri Karpov [e-mail]
wrote:

@adamreisnz https://github.com/adamreisnz any more info on your end?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/Automattic/mongoose/issues/7844?email_source=notifications&email_token=AADXYQSKNPJBQ6ZFZUHZZC3P3TWR5A5CNFSM4HPZZRYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODYIYJ4Q#issuecomment-504464626,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AADXYQTAFYEYKYX6KOGTJZ3P3TWR5ANCNFSM4HPZZRYA
.

[adamreisnz]

Hi @vkarpov15, I've had a look, but all the data I can see on the error is the following:

Is this a different error that's being captured here, or are we somehow not seeing the numAffected and result properties?

(The data and status properties are coming from our BaseError class)

[vkarpov15]

@adamreisnz are you sure you upgraded to at least v5.5.15?

Also, do you use the orFail() function in your codebase?

[adamreisnz]

Looks like according to Sentry we aren't, despite having upgraded to 5.5.15 in our codebase. I might be seeing old error event data, Sentry can be a bit convoluted at times...

I will double check and remove this error so that we get a fresh report next monday.

No, we don't use the orFail() function. All errors are caught in our own middleware.

[adamreisnz]

I think it was a node modules caching issue, i've purged that and forced a rebuild of all packages, so next monday we should have better results.

[vkarpov15]

Was it package-lock.json?

[adamreisnz]

No, Heroku had node modules caching enabled and wasn't respecting the lock files.

[adamreisnz]

It's still reporting as Mongoose 5.4.20, at this point I don't know if it's a Sentry caching issue or Heroku again, or me. Will change the error description from our end so Sentry treats it like a new error, and force Heroku to rebuild all packages again.. 😕

[vkarpov15]

@adamreisnz any more info from this Monday's run?

[adamreisnz]

Unfortunately still the same result. I'm back in the office now though, so I'll have more time to analyse this and make sure the correct package is used on the server.

[adamreisnz]

I'm really not sure what's going on. I nuked the Heroku cache, but Sentry keeps reporting the same old Mongoose package for the error.

However, running a list of packages on the Heroku instance shows that an up-to-date version is installed:

The data I'm seeing logged is still the same:

I suspect Sentry is caching the data I'm seeing and reporting incorrect packages, so I've taken it out of the loop and applied some custom logging straight to the console instead, which will be picked up by LogDNA.

I'll report back in another week! 🕵

[vkarpov15]

A small suggestion: I've had similar cases and it often ends up being that someone is running the project locally while pointing to the production sentry DSN. Is this a possibility?

[adamreisnz]

Thanks for the tip, but in this case no that's not happening. The script is only being run via the weekly task on Heroku, and the production Sentry key is only being used in Heroku production, so no chance of that being the case. Also, the ID that is being reported matches a production data ID.

Wish it were that simple though :)

[adamreisnz]

I'm kind of at the end of my ropes with this one. The error was triggered again by Sentry, and I hopped into our logs to find the raw error, only to discover that no error was logged at all.

Could it be that this error is triggered asynchronously outside of the regular code flow?

Below is our code which should have captured the error.

This is the method that contains the save call which triggers the error:

ScheduleSchema.methods.updateLastRun = function() {
  this.lastRun = Date.now();
  return this.save();
};

And this is the code that triggers the call, which should capture and log any errors thrown:

  try {
    await schedule.updateLastRun();
  }
  catch (error) {
    console.error(`Update last run failed for schedule ${identifier}:`);
    console.error(error);
  }

Going by the logs, it appears the script runs fine and no error is thrown though. So could it be something internal to Mongoose that's being executed outside of the regular code flow?

At this point I'm inclined to just delete that document from the database and create a new one for it, thinking it just might be corrupted in some way.

We are also upgrading Sentry in our next release, maybe that will be of use.

Sorry this hasn't been easy to track down 😞

[vkarpov15]

That's strange, so you're seeing the DocumentNotFoundError in your logs, but the console.error(Update last run failed) line doesn't print?

[adamreisnz]

Yes, so that tells me the error is not thrown directly from the thread that runs the .save() command, but rather that maybe it's thrown asynchronously and then caught and processed as an uncaught exception by Sentry.

This seems to be supported by the fact that the save operation completes successfully as expected, so the error is not impacting that.

[vkarpov15]

Does sentry log the result and numAffected properties on the DocumentNotFoundError? Those might help explain what's going on here.

[adamreisnz]

Nope it doesn't, which means either the error thrown is not actually a DocumentNotFoundError, or there's something messed up with Sentry. The only data we get in the error which seems to come from Mongoose is the filter and query property.

[vkarpov15]

Can you show me the stack trace for the document not found error? There might be some insights there...

[adamreisnz]

Yes, here it is:

BaseError: No document found for query "{ _id: 5acc19781ab6fd00041d4208 }"
  File "node_modules/mongoose/lib/error/notFound.js", line 31, col 11, in new DocumentNotFoundError
  File "node_modules/mongoose/lib/model.js", line 376, col 17, in $__handleSave
  File "node_modules/mongoose/lib/model.js", line 308, col 9, in null.<anonymous>
  File "node_modules/mongodb/lib/utils.js", line 414, col 17, in result
  File "node_modules/mongodb/lib/utils.js", line 401, col 11, in session.endSession
  File "node_modules/mongodb-core/lib/sessions.js", line 129, col 41, in ClientSession.endSession
  File "node_modules/mongodb/lib/utils.js", line 397, col 17, in executeCallback
  File "node_modules/mongodb/lib/operations/collection_ops.js", line 1362, col 3, in updateCallback
  File "node_modules/mongodb/lib/operations/collection_ops.js", line 1451, col 62, in updateDocuments
  File "node_modules/mongodb/lib/utils.js", line 128, col 55, in handleCallback
  File "node_modules/mongodb/lib/operations/collection_ops.js", line 1416, col 5, in coll.s.topology.update
  File "node_modules/mongodb-core/lib/topologies/replset.js", line 1197, col 22, in handler
  File "node_modules/mongodb-core/lib/connection/pool.js", line 532, col 18, in null.<anonymous>
  File "internal/process/next_tick.js", line 61, col 11, in process._tickCallback
  File "node_modules/mongoose/lib/utils.js", line 269, col 10, in Object.promiseOrCallback
  File "node_modules/mongoose/lib/model.js", line 455, col 16, in model.Model.save
  File "app/components/shared/schedule.model.js", line 48, col 15, in model.ScheduleSchema.methods.updateLastRun
  File "app/components/shared/schedule.model.js", line 120, col 18, in Function.ScheduleSchema.statics.check

[adamreisnz]

Are the new properties that you added onto the error enumerable? If not, maybe that's why Sentry is not picking them up.

[vkarpov15]

They should be enumerable, no reason why not. Here's what I get when I console.log() the error:

{ DocumentNotFoundError: No document found for query "{ _id: 5d45c21b0f85fd1af24c627c }" on model "Test"
    at new DocumentNotFoundError (/home/val/Workspace/MongoDB/mongoose/lib/error/notFound.js:34:11)
    at $__handleSave (/home/val/Workspace/MongoDB/mongoose/lib/model.js:375:17)
    at /home/val/Workspace/MongoDB/mongoose/lib/model.js:306:9
    at result (/home/val/Workspace/MongoDB/mongoose/node_modules/mongodb/lib/utils.js:410:17)
    at session.endSession (/home/val/Workspace/MongoDB/mongoose/node_modules/mongodb/lib/utils.js:398:11)
    at ClientSession.endSession (/home/val/Workspace/MongoDB/mongoose/node_modules/mongodb-core/lib/sessions.js:134:41)
    at executeCallback (/home/val/Workspace/MongoDB/mongoose/node_modules/mongodb/lib/utils.js:395:17)
    at updateCallback (/home/val/Workspace/MongoDB/mongoose/node_modules/mongodb/lib/operations/collection_ops.js:1413:3)
    at updateDocuments (/home/val/Workspace/MongoDB/mongoose/node_modules/mongodb/lib/operations/collection_ops.js:1502:62)
    at handleCallback (/home/val/Workspace/MongoDB/mongoose/node_modules/mongodb/lib/utils.js:128:55)
    at coll.s.topology.update (/home/val/Workspace/MongoDB/mongoose/node_modules/mongodb/lib/operations/collection_ops.js:1467:5)
    at /home/val/Workspace/MongoDB/mongoose/node_modules/mongodb-core/lib/connection/pool.js:397:18
    at _combinedTickCallback (internal/process/next_tick.js:131:7)
    at process._tickCallback (internal/process/next_tick.js:180:9)
  message: 'No document found for query "{ _id: 5d45c21b0f85fd1af24c627c }" on model "Test"',
  name: 'DocumentNotFoundError',
  result: 
   CommandResult {
     result: 
      { n: 0,
        nModified: 0,
        opTime: [Object],
        electionId: 7fffffff0000000000000001,
        ok: 1,
        operationTime: [Object],
        '$clusterTime': [Object] },
     connection: 
      Connection {
        domain: null,
        _events: [Object],
        _eventsCount: 5,
        _maxListeners: undefined,
        id: 0,
        options: [Object],
        logger: [Object],
        bson: BSON {},
        tag: undefined,
        maxBsonMessageSize: 67108864,
        port: 27017,
        host: 'localhost',
        socketTimeout: 360000,
        keepAlive: true,
        keepAliveInitialDelay: 300000,
        connectionTimeout: 30000,
        responseOptions: [Object],
        flushing: false,
        queue: [],
        writeStream: null,
        destroyed: false,
        hashedName: '29bafad3b32b11dc7ce934204952515ea5984b3c',
        workItems: [],
        socket: [Object],
        buffer: null,
        sizeOfMessage: 0,
        bytesRead: 0,
        stubBuffer: null,
        ismaster: [Object],
        lastIsMasterMS: 5 },
     message: 
      BinMsg {
        parsed: true,
        raw: <Buffer f5 00 00 00 d6 04 00 00 04 00 00 00 dd 07 00 00 00 00 00 00 00 e0 00 00 00 10 6e 00 00 00 00 00 10 6e 4d 6f 64 69 66 69 65 64 00 00 00 00 00 03 6f 70 ... >,
        data: <Buffer 00 00 00 00 00 e0 00 00 00 10 6e 00 00 00 00 00 10 6e 4d 6f 64 69 66 69 65 64 00 00 00 00 00 03 6f 70 54 69 6d 65 00 1c 00 00 00 11 74 73 00 05 00 00 ... >,
        bson: BSON {},
        opts: [Object],
        length: 245,
        requestId: 1238,
        responseTo: 4,
        opCode: 2013,
        fromCompressed: undefined,
        responseFlags: 0,
        checksumPresent: false,
        moreToCome: false,
        exhaustAllowed: false,
        promoteLongs: true,
        promoteValues: true,
        promoteBuffers: false,
        documents: [Array],
        index: 229,
        hashedName: '29bafad3b32b11dc7ce934204952515ea5984b3c' },
     modifiedCount: 0,
     upsertedId: null,
     upsertedCount: 0,
     matchedCount: 0,
     '$where': { _id: 5d45c21b0f85fd1af24c627c } },
  numAffected: 0,
  filter: { _id: 5d45c21b0f85fd1af24c627c },
  query: { _id: 5d45c21b0f85fd1af24c627c } }

Based on the error message, it looks like you're still running an older version of Mongoose. With #6215 we changed the error message to include the model name, so you should be seeing a No document found for query "{ _id: 5acc19781ab6fd00041d4208 }" on model "Schedule" error if you're using at least version 5.5.15.

Maybe try adding the Mongoose version to the error getting sent to sentry using mongoose.version? I have my doubts that you're running Mongoose 5.6...

[adamreisnz]

Hello good sir, I may have cracked the mystery. I believe this code was running on a (cloned) custom production server, which hadn't been upgraded as you suggested. The ID of the item was the same in both databases, so hence why I thought I was on the right server, whereas I wasn't.

This server has now been shut down, so I don't expect this error to be happening again in the same script. I will close this for now and if it does occur again, we can pick up the trail and see how we go from there.

Thanks for your help looking into it.

[vkarpov15]

Glad you found it and thanks for your patience :+1:

[segevsh]

You already solved it, but perhaps my comment can help the next person with the No document found for query "{ _id: xxx }" problem.

Version is one possible cause, and changing the versionKey , resetting the version or incrementing it did in fact do the trick for my team on a few occasions in the past.

Last time we had that problem the solution was way simpler - the developer accidentally added _id to schema and defined it as string.

The solution was painfully simple - we removed the _id field (mongoose includes _id automatically anyway)