Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-36821

Cursor id not found even though it did not time out

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.6.7
    • Component/s: Querying
    • Labels:
      None
    • ALL
    • Hide

      I'm putting together a repo to reproduce in a systematic way but so far I'm only able to have the error happening in the main repo. I'll update as soon I've a reproducible way.

      If that can help:

      • The app is connected to two databases
      • Each connection has a pool of 7
      • Setting higher log levels did not show any error on the server side
      • For the test 20 cursors are instantiated each with the same query
      • When one fails all the others start to fail too
      • It happens very randomly sometimes you've to wait couple of seconds for the error to happen sometimes it's almost immediate
      • Server is start with --noJournal, running as a container
      Show
      I'm putting together a repo to reproduce in a systematic way but so far I'm only able to have the error happening in the main repo. I'll update as soon I've a reproducible way. If that can help: The app is connected to two databases Each connection has a pool of 7 Setting higher log levels did not show any error on the server side For the test 20 cursors are instantiated each with the same query When one fails all the others start to fail too It happens very randomly sometimes you've to wait couple of seconds for the error to happen sometimes it's almost immediate Server is start with --noJournal, running as a container

      Getting cursor id not found errors from the server even though multiple getMore where emitted soon before. The cursor is not up since more than 10mi and anyhow if previous getMore worked within less than 10min this shouldn't happen.

      Cursor is started and the error occurs at 2018-08-23T11:05:28.528Z

      Many getMore are occuring the last 5 ones being respectively at:

      • [2018-08-23T11:05:25.467Z] schedule getMore call for query {"bson":{},"ns":"fdp-collector.$cmd","query":{"find":"items","filter":
        Unknown macro: {"contents.iid"}

        ,"projection":{},"batchSize":100,"returnKey":false,"showRecordId":false,"lsid":{"id":"TIRV4MZNTSON2fMvPNiSpw=="}},"options":{"numberToSkip":0,"numberToReturn":1,"checkKeys":false,"returnFieldSelector":null,"serializeFunctions":false,"ignoreUndefined":false},"numberToSkip":0,"numberToReturn":1,"returnFieldSelector":null,"requestId":154,"serializeFunctions":false,"ignoreUndefined":false,"maxBsonSize":16777216,"checkKeys":false,"batchSize":1,"tailable":false,"slaveOk":false,"oplogReplay":false,"noCursorTimeout":false,"awaitData":false,"exhaust":false,"partial":false,"documentsReturnedIn":"firstBatch"} cursorId: 19000582380

      • [2018-08-23T11:05:26.378Z] schedule getMore call for query {"bson":{},"ns":"fdp-collector.$cmd","query":{"find":"items","filter":
        Unknown macro: {"contents.iid"}

        ,"projection":{},"batchSize":100,"returnKey":false,"showRecordId":false,"lsid":{"id":"TIRV4MZNTSON2fMvPNiSpw=="}},"options":{"numberToSkip":0,"numberToReturn":1,"checkKeys":false,"returnFieldSelector":null,"serializeFunctions":false,"ignoreUndefined":false},"numberToSkip":0,"numberToReturn":1,"returnFieldSelector":null,"requestId":154,"serializeFunctions":false,"ignoreUndefined":false,"maxBsonSize":16777216,"checkKeys":false,"batchSize":1,"tailable":false,"slaveOk":false,"oplogReplay":false,"noCursorTimeout":false,"awaitData":false,"exhaust":false,"partial":false,"documentsReturnedIn":"firstBatch"}cursorId: 19000582380

      • [2018-08-23T11:05:26.434Z] schedule getMore call for query {"bson":{},"ns":"fdp-collector.$cmd","query":{"find":"items","filter":
        Unknown macro: {"contents.iid"}

        ,"projection":{},"batchSize":100,"returnKey":false,"showRecordId":false,"lsid":{"id":"TIRV4MZNTSON2fMvPNiSpw=="}},"options":{"numberToSkip":0,"numberToReturn":1,"checkKeys":false,"returnFieldSelector":null,"serializeFunctions":false,"ignoreUndefined":false},"numberToSkip":0,"numberToReturn":1,"returnFieldSelector":null,"requestId":154,"serializeFunctions":false,"ignoreUndefined":false,"maxBsonSize":16777216,"checkKeys":false,"batchSize":1,"tailable":false,"slaveOk":false,"oplogReplay":false,"noCursorTimeout":false,"awaitData":false,"exhaust":false,"partial":false,"documentsReturnedIn":"firstBatch"}cursorId: 19000582380

      • [2018-08-23T11:05:27.096Z] schedule getMore call for query {"bson":{},"ns":"fdp-collector.$cmd","query":{"find":"items","filter":
        Unknown macro: {"contents.iid"}

        ,"projection":{},"batchSize":100,"returnKey":false,"showRecordId":false,"lsid":{"id":"TIRV4MZNTSON2fMvPNiSpw=="}},"options":{"numberToSkip":0,"numberToReturn":1,"checkKeys":false,"returnFieldSelector":null,"serializeFunctions":false,"ignoreUndefined":false},"numberToSkip":0,"numberToReturn":1,"returnFieldSelector":null,"requestId":154,"serializeFunctions":false,"ignoreUndefined":false,"maxBsonSize":16777216,"checkKeys":false,"batchSize":1,"tailable":false,"slaveOk":false,"oplogReplay":false,"noCursorTimeout":false,"awaitData":false,"exhaust":false,"partial":false,"documentsReturnedIn":"firstBatch"}cursorId: 19000582380',
        '[2018-08-23T11:05:27.333Z] schedule getMore call for query {"bson":{},"ns":"fdp-collector.$cmd","query":{"find":"items","filter":

        Unknown macro: {"contents.iid"}

        ,"projection":{},"batchSize":100,"returnKey":false,"showRecordId":false,"lsid":{"id":"TIRV4MZNTSON2fMvPNiSpw=="}},"options":{"numberToSkip":0,"numberToReturn":1,"checkKeys":false,"returnFieldSelector":null,"serializeFunctions":false,"ignoreUndefined":false},"numberToSkip":0,"numberToReturn":1,"returnFieldSelector":null,"requestId":154,"serializeFunctions":false,"ignoreUndefined":false,"maxBsonSize":16777216,"checkKeys":false,"batchSize":1,"tailable":false,"slaveOk":false,"oplogReplay":false,"noCursorTimeout":false,"awaitData":false,"exhaust":false,"partial":false,"documentsReturnedIn":"firstBatch"}cursorId: 19000582380

      • [2018-08-23T11:05:27.914Z] schedule getMore call for query {"bson":{},"ns":"fdp-collector.$cmd","query":{"find":"items","filter":
        Unknown macro: {"contents.iid"}

        ,"projection":{},"batchSize":100,"returnKey":false,"showRecordId":false,"lsid":{"id":"TIRV4MZNTSON2fMvPNiSpw=="}},"options":{"numberToSkip":0,"numberToReturn":1,"checkKeys":false,"returnFieldSelector":null,"serializeFunctions":false,"ignoreUndefined":false},"numberToSkip":0,"numberToReturn":1,"returnFieldSelector":null,"requestId":154,"serializeFunctions":false,"ignoreUndefined":false,"maxBsonSize":16777216,"checkKeys":false,"batchSize":1,"tailable":false,"slaveOk":false,"oplogReplay":false,"noCursorTimeout":false,"awaitData":false,"exhaust":false,"partial":false,"documentsReturnedIn":"firstBatch"}cursorId: 19000582380

      As you can see the error happens less than a second after the last getMore

            Assignee:
            kelsey.schubert@mongodb.com Kelsey Schubert
            Reporter:
            YouriT Youri Tolstoy
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: