Invalid response_to for query, RuntimeException

[keita1314]

PHP Fatal error: Uncaught exception 'MongoDB\\Driver\\Exception\\RuntimeException' with message 'Invalid response_to for query. Expected 18989, got 18988.'

mongodb 1.2.5
mongodb/mongodb 1.1.1 MongoDB driver library

This exception is occasional.
Any solution? Thanks!

[jmikola]

That error originates from _mongoc_cursor_op_query() in libmongoc and should certainly not happen in normal operation. Are you attempting to use threads or forked processes in your PHP application by any chance? If so, that may lead to sockets being inadvertently shared between contexts.

[keita1314]

I just use apache mod_php, no threads or forked process in my php application!

[kideny]

@jmikola how to fix this error ?

my app use threads to execute mongo commands.

[jmikola]

@kideny: MongoDB\Driver\Manager objects, and objects derived from them (e.g. cursors) cannot be shared acrossed processes and threads. This is touched upon in the note on MongoDB\Driver\Manager::__construct().

[kideny]

@jmikola thanks，brother！

[xepa]

Getting this error occasionally when nginx times-out the fcgi process, this happens when we are doing a long series of mongo queries, without sending output to nginx. When this happens this fpm process (I think) is not properly handeling the exception leading to stale reuse issues on the mongo connections leading to 'Authentication failed' exceptions.

After some further debugging it seems that once nginx aborts the php process there still are mongo queries inflight, on the next request new mongo queries are sent and the old (from the aborted fpm process) are returning triggering this 'Invalid response_to for query' error.

[jmikola]

Getting this error occasionally when nginx times-out the fcgi process, this happens when we are doing a long series of mongo queries, without sending output to nginx.

What do you mean by "nginx times-out the fcgi process"? Is the PHP process (i.e. FPM worker) terminating due to max_execution_time (in php.ini) or request_terminate_timeout (in php-fpm.conf)? If nginx is giving up on reading a response from PHP FPM, then I expect the PHP worker is still running and would ultimately obtain the results of those queries -- unless you have evidence that the PHP worker is actually being terminated?

leading to stale reuse issues on the mongo connections leading to 'Authentication failed' exceptions.

Are these exceptions instances of MongoDB\Driver\Exception\AuthenticationException? Are you seeing these "Authentication failed" exceptions on subsequent requests served by the PHP FPM worker process? If so, I'm curious how you then receive exceptions indicating "Invalid response_to" errors.

After some further debugging it seems that once nginx aborts the php process there still are mongo queries inflight, on the next request new mongo queries are sent and the old (from the aborted fpm process) are returning triggering this 'Invalid response_to for query' error.

To clarify: nginx doesn't actually abort the PHP process. AFAIK, that would be the responsibility of the FPM pool or PHP itself. When you say that "on the next request new mongo queries are sent" are you certain that those requests are being served by an FPM worker that previously handled a long-running query? Is it possible to reproduce this by configuring an FPM pool with only one worker and then watching to see if new connections are opened/closed on the MongoDB server?

@derickr: can you chime in on whether we should expect a request timeout to terminate the entire worker process, or would that only trigger the RSHUTDOWN handler (thereby leaving all of our persisted clients in play)? I'm trying to discern how a fresh request might end up inheriting sockets with leftover data still coming down the pipeline.

[xepa]

After looking at it again it might only be the max_execution_time.

As far as I know nginx aborting the request might signal the fpm pool to terminate the request (needs testing), as to keep the fcgi process running you might have to ignore_user_abort, but I am not that sure on this.
edit: The fcgi process does not terminate if nginx times out the read [confirmed this].

It is not the request_terminate_timeout (this setting is set to the default [0] disabling this feature).

Are these exceptions instances of MongoDB\Driver\Exception\AuthenticationException?

From the errors in our logs and the corresponding code the 'Authentication failed.' is an exception (we are currently not logging the type, sorry) with the code 11, maybe this helps.

It seems (from the logs that the following is happening, error wise), please note that this happens to only one fpm process, ie the pid is the same for this sequence, all other fpm processes are unaffected.

1. max_execution_time
2. Invalid response_to for query [code:14] (may happen multiple times in different requests)
3. Authentication failure. [code:11] for the duration of the lifetime of this fpm process.

Is it possible to reproduce this by configuring an FPM pool with only one worker and then watching to see if new connections are opened/closed on the MongoDB server?
We had trouble reproducing this on our development environment, I will try to reproduce this in development, as I am sure you understand setting the production to behave this way is a nogo ;)

We mitigated this error by forcing the php process to complete the request, ie sending output in the mongo loop and resetting the max timeout, to prevent it timing out.

Sidenote: we should not really process these types of requests inline, we should offload these to a background worker, it has been scheduled but you know how this goes ;)

[xepa]

Has anyone been able to look into this issue ? If there is something that I can do from my side please let me know.

[jmikola]

@xepa: Apologies for losing track of this. We haven't had a chance to investigate this further, as we're presently wrapping up tasks for the 1.4.0 release.

I poked @derickr again regarding my outstanding question about "whether we should expect a request timeout to terminate the entire worker process" and his response was "I don't think so". I will likely need to verify this myself to be sure.

Assuming max_execution_time is not killing the worker process, then I would expect the libmongoc client to remain persisted in memory and reused by a subsequent request that constructs the MongoDB\Client or MongoDB\Driver\Manager with the same arguments. I believe that would explain the "Invalid response_to for query" error, especially if the numbers were off by one. The response from the previous (timed-out) request's last operation would still be present in the socket buffer and inadvertently read when your current request tries to read the response for its first operation.

If we're able to detect an aborted request due to max_execution_time, we may be able to look into implementing a workaround in the driver. A crude solution may be to simply terminate the libmongoc client on the basis that it's sockets are left in an unknown state. In any event, I don't believe any solution would warrant an API change necessitating a new minor version, so we'll have to revisit this as a bug fix. I'm opening PHPC-1101 to track this improvement.

[derickr]

@xepa, I have tried to replicate this issue today, but not with any success.

I tried:

• timeouts where PHP was doing CPU intensive work (calculating things in a tight loop), with a only reading results of the cursor once in a while. It would timeout before I had read all documents, but it probably did not leave any unread data on the socket.
• timeouts where I issued a sleep(8000) to the MongoD server with eval, which does not cause any timeouts on the PHP side, as waiting for network IO doesn't count towards max_execution_timeout.

It did become clear that, as expected, max_execution_time timeouts do not kill the FPM worker process and/or close the MongoD connection.

What sort of long-running queries or commands are you are running which cause the issue?

Continuing with one more thing to try... (calling exit() in a CommandStarted APM handler)

[xepa]

@derickr thank you for looking into the issue.

One thing I forgot to mention that the site where this can happen is still running php56 .. I have been able to reproduce the bug (for code see below) there but not with other sites running php72 (still investigating). Another option as far as I can tell at the moment is to migrate to 7.2.

<?php
require_once __DIR__ . '/../vendor/autoload.php';
// allow max_execution_time to kick in early
ini_set('max_execution_time', 1);
try {
        $client = new MongoDB\Client("mongodb://<user>:<pass>@localhost:27017/", array('authSource' => 'admin'));
        $db = $client->test;
        $db->dropCollection('test');
        $db->createCollection('test', array('capped' => true, 'size' => 10*1024, 'max' => 10));
        $collection = $db->test;
        while (true) {
                $result = $collection->insertOne(array('name' => time()));
        }
        $db->dropCollection('test');
} catch (\MongoDB\Driver\Exception\AuthenticationException $e) {
        echo 'A previous request hit bug';
} catch (\MongoDB\Driver\Exception\RuntimeException $e) {
        // is not always thrown ..
        echo 'Triggered Bug';
} catch (\Exception $e) {
        var_dump($e);
}

Driver version tested on all php versions [1.3.4]

[derickr]

Do I understand correctly that you can reproduce it with just the code you've just submitted? (And obviously, the MongoDB PHP library through vendor?)

But as this runs on just one specific request - indefinitely, how can another request come into play here?

[xepa]

Yea I can trigger this bug using the above code, under php 5.6.33 running via fpm under nginx.