MongoDB\Driver\Exception\RuntimeException: cursor id not found

[Algatux]

Description

We are experiencing some issues with cursors on long-running tasks receiving this error:
MongoDB\Driver\Exception\RuntimeException: cursor id 115794413245 not found

We are iterating over a set of about 2M+ documents, and already tried to set noCursorTimeout to true and batchSize to smaller amounts like 1k

We encountered this issue updating the extension from version 1.3.4 to 1.4.2+ never tried 1.4.0.

Environment

Ubuntu Server 16.04
PHP 7.2.4-1+ubuntu16.04.1+deb.sury.org+1 (cli) (built: Apr 5 2018 08:53:57) ( NTS )
Zend OPcache v7.2.4-1+ubuntu16.04.1+deb.sury.org+1
MongoDb extension versions 1.4.2 from ubuntu's ppa and 1.4.3 compiled with pecl.
libbson bundled version => 1.9.4
libmongoc bundled version => 1.9.4
libmongoc SSL => enabled
libmongoc SSL library => OpenSSL
libmongoc crypto => enabled
libmongoc crypto library => libcrypto
libmongoc crypto system profile => disabled
libmongoc SASL => enabled
libmongoc compression => enabled
libmongoc compression snappy => disabled
libmongoc compression zlib => enabled

Mongodb version is 3.6.2 with authentication enabled

[jmikola]

Can you share the code that yields this cursor? Specifically, I'd like to see what time of command you're executing (e.g. find(), aggregate()) and any/all options pass to it.

Additionally, please run the serverStatus command after your query executes and while the cursor is still alive. The easiest way to do this may be running db.serverStatus() from the mongo shell. Specifically, I'd like to see the metrics.cursor document in the result, which should tell us whether the cursor has its timeout disabled as we expect.

It you have many cursors open on the server, I might suggest running this both before and after executing the cursor-yielding operation in PHP. That will allow us to compare output and better identify the cursor in question. If so, it should be easy to run the command from PHP as well. Assuming you're using the library:

$result = $client->admin->command([`serverStatus' => 1])->toArray()[0];
$cursorMetricsBefore = $result['metrics']['cursor'];

// run your operation

$result = $client->admin->command([`serverStatus' => 1])->toArray()[0];
$cursorMetricsAfter = $result['metrics']['cursor'];

// var_dump() before/after metrics to share in this issue

[Algatux]

Most of the times we are getting cursors with a query like this one:

find(
    ['_id' => ['$gt' => $id],'type' => ['$in' => $types] ],
    ['noCursorTimeout' => true, 'sort' => ['meta.createdAt' => 1]]
);

wrapping it inside a \IteratorIterator sometimes calling next it throws the error.

I'm sorry but actually I don't have enough permissions on the database to obtain the metrics you asked for

[jmikola]

I don't have enough permissions on the database to obtain the metrics you asked for

Noted. Since you're running 3.6, I have another theory that the cursor may be expiring due to a session timeout instead of a cursor timeout.

By default, cursors on the server expire after approximately ten minutes of inactivity (i.e. the driver has not sent a getMore command to obtain the next batch of results). The noCursorTimeout option can be used to disable that timeout. As of MongoDB 3.6, each interaction with the server now utilizes a logical session. In the PHP driver, these sessions are represented by a MongoDB\Driver\Session. You can create those explicitly and pass them as an option to operations, such as queries and writes, but without doing so the driver will create an implicit session internally. In both cases, your query/write/command is associated with a logical session on the server side.

By default, sessions expire after 30 minutes of inactivity. When expiring, all resources associated with that session are also closed, which will include any associated cursors or long-running commands. The noCursorTimeout option does not override this behavior, which is by design to ensure that drivers cannot inadvertently leak resources on the server. Prior to 3.6, it was possible for cursors with noCursorTimeout to remain alive on the server long after the driver disconnected, which we refer to as zombie cursors.

Can you provide the the response to an isMaster command when run against the primary? Specifically, I'd like to see the value of logicalSessionTimeoutMinutes.

Also, any measurement you can provide about the time when these "cursor id not found" exceptions appear would help confirm whether a session timeout is at play. Specifically, I'd like to compare the difference in time between the last find or getMore command. You can use the PHP driver's APM functionality to track this. For an example, take a look at cursor-batchsize-001.phpt from our test suite. Therein, we register a CommandSubscriber implementation that watches for aggregate and getMore commands -- it should be trivial to change that to watch for find and getMore and simply update a timestamp global. Consider:

class MySubscriber implements MongoDB\Driver\Monitoring\CommandSubscriber
{
    public $lastFind;
    public $lastGetMore;

    public function commandStarted(\MongoDB\Driver\Monitoring\CommandStartedEvent $event)
    {
        if ($event->getCommandName() === 'find') {
            $this->lastFind = new \DateTimeImmutable();
        }

        if ($event->getCommandName() === 'getMore') {
            $this->lastGetMore = new \DateTimeImmutable();
        }
    }
    public function commandSucceeded(\MongoDB\Driver\Monitoring\CommandSucceededEvent $event)
    {
    }
    public function commandFailed(\MongoDB\Driver\Monitoring\CommandFailedEvent $event)
    {
    }
}

$subscriber = new MySubscriber;

MongoDB\Driver\Monitoring\addSubscriber($subscriber);

try {
    // your long-running operation here
} catch (\MongoDB\Driver\Exception\RuntimeException $e) {
    printf("RuntimeException(%d): %s\n", $e->getCode(), $e->getMessage());
    printf("lastFind: %s\n", $subscriber->lastFind ? $subscriber->lastFind->format('r') : 'never');
    printf("lastGetMore: %s\n", $subscriber->lastGetMore ? $subscriber->lastGetMore->format('r') : 'never');
    printf("now: %s\n", (new \DateTime)->format('r'));
} finally {
    MongoDB\Driver\Monitoring\removeSubscriber($subscriber);
}

If the timing agrees with the session timeout value from isMaster, I think we can safely conclude that the cursor's noCursorTimeout option is being properly applied but the implicit session is simply timing out. From there, I can then propose two possible solutions:

• Lower the batchSize for your query. This will lower the number of documents sent back with each batch (for the initial find command and subsequent getMore commands) and effectively cause the driver to issue getMore command more frequently. In turn, this activity will reset the countdown on both the cursor and session timeouts -- possibly allowing you to avoid using noCursorTimeout as well.
• Manually create a session with either MongoDB\Client::startSession() or MongoDB\Driver\Manager::startSession() (depending on whether you're using the extension directly or the userland library). Then, pass this as a session option to your query. At regular intervals during your long-running iteration, perform some other database interaction (e.g. ping command) and pass the same session object as the session option to that operation. This activity will reset the session's timeout; however, it will do nothing to keep the cursor alive, so you may still need to use noCursorTimeout.

[Algatux]

@jmikola I do not think that the problem is the logicalSessionTimeoutMinutes because we tried to setup our command to run for a maximum of 2 minutes, working on a smaller chunk of results and than shutdown. to restart from the last element after another 2 minutes . This worked for 2-3 times but we received the error on the 4th start of the command. It seems to be randomic. For now we had to downgrade the extension version to 1.3.4

We will try your subscriber to debug the issue, in the meantime this is the response to isMaster:

{
	"hosts" : [
		"x.x.x.x:27017",
		"x.x.x.x:27017",
		"x.x.x.x:27017"
	],
	"setName" : "rs0",
	"setVersion" : 15073,
	"ismaster" : true,
	"secondary" : false,
	"primary" : "x.x.x.x:27017",
	"me" : "x.x.x.x:27017",
	"electionId" : ObjectId("7fffffff000000000000001f"),
	"lastWrite" : {
		"opTime" : {
			"ts" : Timestamp(1525448796, 7),
			"t" : 31
		},
		"lastWriteDate" : ISODate("2018-05-04T17:46:36.000+02:00"),
		"majorityOpTime" : {
			"ts" : Timestamp(1525448796, 7),
			"t" : 31
		},
		"majorityWriteDate" : ISODate("2018-05-04T17:46:36.000+02:00")
	},
	"maxBsonObjectSize" : 16777216,
	"maxMessageSizeBytes" : 48000000,
	"maxWriteBatchSize" : 100000,
	"localTime" : ISODate("2018-05-04T17:46:36.550+02:00"),
	"logicalSessionTimeoutMinutes" : 30,
	"minWireVersion" : 0,
	"maxWireVersion" : 6,
	"readOnly" : false,
	"ok" : 1,
	"operationTime" : Timestamp(1525448796, 7),
	"$clusterTime" : {
		"clusterTime" : Timestamp(1525448796, 7),
		"signature" : {
			"hash" : BinData(0,"******"),
			"keyId" : NumberLong("6719584086155728111")
		}
	}

[jmikola]

It's possible that this issue may be related to one of the following outstanding server issues:

• SERVER-34053: Cursor not found error when running long query on secondary with noCursorTimeout
• SERVER-34810: Session cache refresh can erroneously kill cursors that are still in use

As noted in this comment, it's also possible that both issues are one and the same; however, we've not yet been able to confirm.

If this is caused by a server bug, downgrading to 1.3.4 may be the only immediate workaround as that version of the driver does not support sessions.

[smaftoul]

Still present in 1.5.0

[jmikola]

SERVER-34053 was resolved as a duplicate of SERVER-34810, and the latter issue still appears to be outstanding in the server's recent 4.0 release according to a recent comment in JIRA.

AFAICT, this is not a driver bug (SERVER-34053 was originally reported by users of the Ruby driver). Short of downgrading the driver to 1.3.4 (the most recent version before sessions were introduced), the only course of action would be to wait for SERVER-34810 to be addressed. If you have a JIRA account, I would encourage anyone following this to both watch and vote for the issue to raise its visibility (no need to leave a "me too" comment, since someone has already reported that the issue persists in server 4.0).

[Algatux]

@jmikola it seems that it's solved in new releases of server [3.6.6, 4.0.1, 4.1.1,] right ?

[jmikola]

@Algatux: SERVER-34810 appears to have been resolved and the fix has been backported to the 3.6 and 4.0 branches. At this moment, it looks like only the 3.6.6-rc0 release of the server has been published. I assume that means a non-RC 3.6.6 release is imminent, but I'm not sure what the timeline is for 4.0.1.

3.6.6-rc0 appears to already be available in Download Center: Development Releases, as are 4.0 nightlies, if you'd like to test those versions locally to see if the issue has been fixed. For any production upgrades, I would certainly suggest waiting for the stable releases for 3.6.6 and 4.0.1.

[salvatorecordiano]

@jmikola: we upgraded our MongoDB server to version 3.6.6, but we didn't solve our issue using:

MongoDB extension version => 1.4.2 (libmongoc bundled version => 1.9.3)
MongoDB extension version => 1.5.1 (libmongoc bundled version => 1.11.0)

So, we are still using:

MongoDB extension version => 1.3.4 (libmongoc bundled version => 1.8.2)

cc @Algatux

[jmikola]

@salvatorecordiano: SERVER-36808 just came in a few days ago via the Python driver, so we do have evidence that SERVER-34810 did not completely resolve the issue. The new ticket also includes repro steps (those appear to correlate with @Algatux's original description), so hopefully an upcoming patch release of the server can get this addressed completely. Please watch that ticket for updates.

[derickr]

This could be fixed in MongoDB 3.6.8, as per https://jira.mongodb.org/browse/SERVER-36332 — can you please test that version of MongoDB?

[watari]

Hi there. Few days ago we encountered same problem with cursor. We updated to 3.6.8 as @derickr suggested, but error was reproduced on this version too. Also we tried 4.0.3 without results.
In our case problem was fixed by specifying noCursorTimeout option.
Firstly problem was encountered on 3.6.5.
I applied monitoring from sample provided by @jmikola - last call to getMore method was in range 2-10 minutes before error. By this reason I think that this is the same problem.
Maybe it will be useful. After updating to 3.6.8 cursor work correctly longer.

[jmikola]

@watari: Can you clarify the following statements:

We updated to 3.6.8 as @derickr suggested, but error was reproduced on this version too

This sounds as if you're still seeing cursors disappear prematurely on 3.6.8.

After updating to 3.6.8 cursor work correctly longer.

But this sounds as if the cursors are behaving correctly and not dying premature.

Note that the MongoDB server naturally expires idle cursors after ten minutes, as discussed in #825 (comment) and Closure of Inactive Cursors. If you are not interacting with a cursor (i.e. iterating enough to invoke a getMore command), I would expect the server to kill that cursor after ten minutes of inactivity. As mentioned earlier, you can lower the batch size of a cursor to increase the frequency of getMore commands during iteration or utilize the noCursorTimeout option.

The bug that was fixed in 3.6.8 is related to server sessions being closed prematurely and closing any cursors created within that session. With that bug, cursors were disappearing much sooner than ten minutes and irrespective of whether getMore commands were invoked.

[watari]

@jmikola , sorry for delay. I was on the sick leave.

We updated to 3.6.8 as @derickr suggested, but error was reproduced on this version too

By this I mean that error still occurs after version update.

After updating to 3.6.8 cursor work correctly longer.

By this I mean that time before error is increased.
Yesterday I checked other long running task in which error is appears. Here is debug output provided by monitoring subscriber for cursor without noCursorTimeout option specified:

Started: 2018-10-18T18:02:04+03:00
RuntimeException(43): cursor id 145221446137 not found
lastFind: Thu, 18 Oct 2018 18:46:50 +0300
lastGetMore: Thu, 18 Oct 2018 18:46:50 +0300
now: 2018-10-18 18:46:50

Another run of task performed today:

2018-10-19T09:45:13+03:00
RuntimeException(43): cursor id 144438985256 not found
lastFind: Fri, 19 Oct 2018 10:29:29 +0300
lastGetMore: Fri, 19 Oct 2018 10:29:29 +0300
now: 2018-10-19T10:29:29+03:00

The output of isMaster command is next:

{
"ismaster" : true,
"maxBsonObjectSize" : 16777216.0,
"maxMessageSizeBytes" : 48000000.0,
"maxWriteBatchSize" : 100000.0,
"localTime" : ISODate("2018-10-19T06:41:02.404+0000"),
"logicalSessionTimeoutMinutes" : 30.0,
"minWireVersion" : 0.0,
"maxWireVersion" : 7.0,
"readOnly" : false,
"ok" : 1.0
}

UPD. For this second task, on which monitoring was performed noCursorTimeout option has no effect. Error occurs even when cursor is 'immortal'
There is debugging outputs for several runs with noCursorTimeout option specified:

2018-10-19T10:32:31+03:00
RuntimeException(43): cursor id 143472535882 not found
lastFind: Fri, 19 Oct 2018 11:16:56 +0300
lastGetMore: Fri, 19 Oct 2018 11:16:56 +0300
now: 2018-10-19T11:16:56+03:00

2018-10-19T11:19:07+03:00
RuntimeException(43): cursor id 145134176827 not found
lastFind: Fri, 19 Oct 2018 12:03:50 +0300
lastGetMore: Fri, 19 Oct 2018 12:03:50 +0300
now: 2018-10-19T12:03:51+03:00

When my previous message was written error was occurred on other task in which set of cursors was used. In those task noCursorTimeout option removed error. But in those task cursors used for shorter period of time.

So we have two cases when problem was occurred.
First case. Long running task where set of cursors was used. This cursors was build from criteria before usage. Error was gone when cursors was made 'immortal' by noCursorTimeout option. There also I applied monitoring and there was no inactivity before error.
Second case. Long running task where one cursor is used. Error occurs approximately after 45 minutes of work. Option noCursorTimeout is not removing error.

Output of mongod -version:

db version v4.0.3
git version: 7ea530946fa7880364d88c8d8b6026bbc9ffa48c
OpenSSL version: OpenSSL 1.1.0f 25 May 2017
allocator: tcmalloc
modules: none
build environment:
distmod: debian92
distarch: x86_64
target_arch: x86_64

Do you have any ideas about reasons of such behavior?