php7 + opcache + mongodb: Query and php array is getting changed randomly.

[cb-msales]

We found some strange behaviour where queries sent to mongodb don't match what we intended to send.

After digging deeper we found that under load with multiple requests handeled concurrently by php-fpm, the system randomly starts changing the php array (!).
This only happens when the array is sent to the mongodb find operation (other operations not tested).

We have only seen it changing the array when it has been sent to mongodb. Not calling ->find() does not produce the error.

Also opcache need to be enabled for the file where the query array is defined. With opcache disabled it will not fail.

The array is changed in a way that 'static' contents seem to be removed. We don't know if any more is getting replaced or changed. For example the part '[10, 12]' is replaced with NULL in our test case.
Replacing one value with dynamic content eliminates the error too: repalce for example 12 with (int)$_GET['id'], call the test script with parameter test.php?id=10 and it will NOT fail.

When using json_decode(json_encode($test), true) before submitting the data to ->find it will NOT fail and not change any contents of $test.

The database and selection does not exist in our test case.

We have tested with
ext-mongodb 1.1.8
mongodb/mongodb 1.0.2
PHP 7.0.8-4

Below the test script, run with apache benchmark

require __DIR__ . '/../vendor/autoload.php';

$test = ['test' => ['$in' => [10, 12]]];

$client = new MongoDB\Client();
$client->selectCollection('a','b')->find($test);

file_put_contents('/tmp/mongodb-errors.log', (int)(serialize($test) == 'a:1:{s:4:"test";a:1:{s:3:"$in";a:2:{i:0;i:10;i:1;i:12;}}}'), FILE_APPEND);

Run ab test:
(optional) > sudo service php-fpm restart;

ab -c 40 -n 1000 http://your.domain.goes.here/test.php

Example result: 1 = success, array not changed, 0 = error, array has been changed. '[10, 12]' has been nulled.

11111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111
11111111111111111111111111111111111111111111111111111111111111111111111111111111111111000000000000000000000000000000000000
00000000000000000000000100000000000000000000000000000000000000000000000000111111111111111111111111111111111111111111111111
11100000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
00000000000000000000000000000000000000000000000000000000000100000000000000000000000000000000000000000000000000000000000000
00000000000000000000000000000000000111111111111111000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000001111111```

[jmikola]

This seems like it may be a duplicate of mongodb/mongo-php-driver#293, which was caused by APCu. Can you read through that issue and confirm?

[cb-msales]

php -i | grep -i apcu
does not give me any result. I think we are not using APCu.

[cb-msales]

If you need any help reproducing the issue let me know. I'll help where I can as this is an important issue for us.

[jmikola]

php -i | grep -i apcu does not give me any result. I think we are not using APCu.

I suppose it might be helpful to get a record of all PHP extensions being used. Or perhaps all php -i output in a gist in case some INI settings are also relevant.

Replacing one value with dynamic content eliminates the error too: replace for example 12 with (int)$_GET['id'], call the test script with parameter test.php?id=10 and it will NOT fail.

When using json_decode(json_encode($test), true) before submitting the data to ->find it will NOT fail and not change any contents of $test.

This sounds quite bizarre, as I don't see how modifying the value beforehand would affect the driver's internal behavior. I imagine it may have implications for opcache, though.

When the MongoDB\Driver\Query is constructed, the argument is immediately serialized to BSON. That BSON is what is ultimately sent to the server. Can you use server-side profiling to log queries sent the to server and compare whether they are also be corrupted? The comment option to find() may be used to make it easier to track these queries.

Also, I noticed that you were dumping serialize($test) after calling find(). I might suggest moving those comparisons to the lines immediately before and after the library constructs a MongoDB\Driver\Query object (here) for testing purposes.

[cb-msales]

More tests made:

Before and after the find call:

require __DIR__ . '/../vendor/autoload.php';

$test = ['test' => ['$in' => [10, 12]]];

$client = new MongoDB\Client();
$a = (int)(\serialize($test) == 'a:1:{s:4:"test";a:1:{s:3:"$in";a:2:{i:0;i:10;i:1;i:12;}}}');
$client->selectCollection('a','b')->find($test);
$b = (int)(\serialize($test) == 'a:1:{s:4:"test";a:1:{s:3:"$in";a:2:{i:0;i:10;i:1;i:12;}}}');
file_put_contents('/tmp/mongodb-errors.log', $a . '-' . $b . " ", FILE_APPEND);

Results:

looks like error manifested like this

1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-0 1-0 1-0 1-0 1-0 1-0 1-0 1-0 1-0 1-0 1-0 1-0 1-0 1-0 1-0 1-0 0-0 1-0 1-0 0-0 0-0 1-0 1-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 1-0 0-0 0-0 0-0 0-0 0-0 0-0 1-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0

and in a laterrun the error disappeared again:

0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-1 0-1 0-1 0-1 1-1 0-1 0-1 1-1 0-1 0-1 1-1 1-1 0-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 0-1 0-1 0-1 0-1 0-1 1-1 1-1 1-1 1-1 1-1 1-1 0-1 0-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1

---

And now as you suggested before and after MongoDB\Driver\Query is constructed

$a = (int)(\serialize($this->filter) == 'a:1:{s:4:"test";a:1:{s:3:"$in";a:2:{i:0;i:10;i:1;i:12;}}}');
$ret = new Query($this->filter, $options);
$b = (int)(\serialize($this->filter) == 'a:1:{s:4:"test";a:1:{s:3:"$in";a:2:{i:0;i:10;i:1;i:12;}}}');
file_put_contents('/tmp/mongodb-errors.log', $a . '-' . $b . " ", FILE_APPEND);
return $ret;

first run:

1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-1 1-0 0-0 0-0 0-0 1-1 0-0 0-0 0-0 0-0 0-0 0-0 0-0 0-0

second run:

0-0 0-0 0-0 0-0 0-1 1-0 0-0 0-0 0-0 0-0

another run after php-fpm restart

0-0 0-0 0-0 0-0 0-0 0-1 0-1 1-1 1-1 1-1 [ more 1-1 here] 1-1 1-1 1-0 1-0 0-0 0-0 0-0 0-0

---

logging queries in mongodb server:

'comment' => 'abc' used:

After running I dumped the result into abc.log

less /var/log/mongodb/mongod.log | grep abc > abc.log

The log file is attached to this issue.

In line 199 is the first error happening:

"{ $comment: "abc", $query: { test: { $in: [] } } }"

The values inside the array have been removed.

It doesn't look like the corrupted php $test array is NOT exactly linked to the number of wrong queries. But still somewhat related.

[cb-msales]

Here my list of extensions:

Core
PDO
Phar
Reflection
SPL
SimpleXML
Zend OPcache
calendar
cgi-fcgi
ctype
curl
date
dom
exif
fileinfo
filter
ftp
gd
gettext
hash
iconv
json
libxml
mbstring
mongodb
openssl
pcre
pdo_pgsql
pgsql
posix
readline
session
sockets
standard
tokenizer
wddx
xml
xmlreader
xmlwriter
xsl
zlib

[cb-msales]

Is anyone able to reproduce the issue?

[jmikola]

In both of your tests (first around Collection::find() and secondly around the Query construction) where you were comparing the serialized filter array to an expected string, you appear to have a mix of both comparisons being false at different times. That hints at some sort of corruption before we even get to the driver code.

If Query::__construct() was at fault, I might expect your output to be a mix of 1-1 and 1-0, but I would not expect the first comparison to ever be false. Essentially, this is failing for you:

$test = ['test' => ['$in' => [10, 12]]];
$a = (int)(\serialize(['test' => ['$in' => [10, 12]]]) == 'a:1:{s:4:"test";a:1:{s:3:"$in";a:2:{i:0;i:10;i:1;i:12;}}}');

Have you tried testing that on its own without using the driver at all?

The log file is attached to this issue.

I don't see any files attached to your earlier posts. You may want to double-check that.

[cb-msales]

I agree, the problem seems to persist across multiple calls. It sometimes comes and sometimes goes away again. And again it only happens when multiple calls are procesed concurrently..

Without the mongodb driver or even without calling ->find($test); method it does not happen.

[cb-msales]

don't see any files attached to your earlier posts. You may want to double-check that.

Here we go:

abc.log.txt

[Visualq]

I have a similar problem which I think is related to this. Also noticed that when I disable opcache it works without a problem.

The query which fails is: $table->find(['_type' => ['$in' => ['website', 'rootnode', 'iqcms']]]); It started to return 0 results. I rewrote the query to test if it mattered to: ['$or' => [['_type' => 'website'], ['_type' => 'iqcms'], ['_type' => 'iqcms']]];

The latter query eventually started producing the following exception:

Fatal error: Uncaught MongoDB\Driver\Exception\ConnectionException: $and/$or/$nor must be a nonempty array in /var/www/iqcms-1.6/vendor/mongodb/mongodb/src/Operation/Find.php:180

I test it by doing a ab -n 4000 -c 20 http://dgd70.localhost.iqcms/ and after 500-5000 requests (seems random) it starts to produce exceptions because the query isn’t returning any results. The code base is a bit large and I haven’t isolated the query to see if I can reproduce it with a smaller set of code.

My opcache config:
[opcache]
zend_extension="opcache.so"
opcache.enable=1
opcache.enable_cli=1
opcache.memory_consumption=256
opcache.interned_strings_buffer=8
opcache.max_accelerated_files=7963
opcache.max_wasted_percentage=5
opcache.use_cwd=1
opcache.validate_timestamps=1
opcache.revalidate_freq=60
opcache.fast_shutdown=1

I encounter the problem with the 1.1.8 driver aswell as the 1.2.0alpha.

Let me know if I need to provide more data.

[cb-msales]

Seems like this is caused at a lower level than the php library, possibly some memory corruption going on here? I created that issue in the mongodb-php-driver repository to get some help from there.

[jmikola]

@cb-msales: Does your opcache configuration agree with @Visualq?

Would either of you be able to attempt reproducing the problem with the Zend memory manager disabled? This will require setting the USE_ZEND_ALLOC environment variable to 0. To ensure that the environment variable is respected, you should see "Zend Memory Manager" marked as "disabled" in phpinfo().

This blog post may be helpful for specifying an environment variable in PHP-FPM.

@derickr suggested this on the off chance that Zend MM is hiding the underlying issue. Reproducing without it may provide a better chance at exposing the root cause.