BulkWrite error :: '$set' is empty. You must specify a field like so: {$set: {<field>: ...}}

Shaked commented 8 years ago

Hey,

We recently switched our production server to PHP7:

$ php -v
PHP 7.0.4-7+deb.sury.org~trusty+2 (cli) ( NTS )
Copyright (c) 1997-2016 The PHP Group
Zend Engine v3.0.0, Copyright (c) 1998-2016 Zend Technologies
    with Zend OPcache v7.0.6-dev, Copyright (c) 1999-2016, by Zend Technologies

And using the new Mongodb driver (1.1.5).

We noticed that sometimes there's a weird behaviour but unfortunately I can't reproduce it yet (it's quite random but for sure happens only on PHP7 servers). When I run the code on dev it works perfectly. I am seeing the following error:

BulkWrite error :: '$set' is empty. You must specify a field like so: {$set: {<field>: ...}}
app/vendor/composer/mongodb/mongodb/src/Operation/Update.php (121)
MongoDB\Driver\Server::executeBulkWrite

File:      app/vendor/composer//mongodb-odm-light/lib/Doctrine/MongoDB/Collection.php in line 1397
Method:    MongoCollection->update
Parameter: [['_id' => 'req-a10cd3c3-8485-4d21-9928-239379251472'], ['$set' => ['creatorHostname' => 'prod.cloud.net', 'handledAt' => MongoDate]], ['upsert' => true]]

File:      app/vendor/composer/alcaeus/mongo-php-adapter/lib/Mongo/MongoCollection.php in line 387
Method:    Alcaeus\MongoDbAdapter\ExceptionConverter::toLegacy
Parameter: [MongoDB\Driver\Exception\BulkWriteException]

As you can see, the $set parameter is definitely not empty. I have tried to debug a bit but still can't figure this issue.

I am not sure if this bug should be here so I opened it also under mongo-php-adapter's repository: https://github.com/alcaeus/mongo-php-adapter/issues/93

The moment I have a way to reproduce it, will attach a code snippet but maybe in the meanwhile there's something I have missed.

Thank you

jmikola commented 8 years ago

The BulkWrite error message you're seeing originates from the server, so I believe this may be an issue higher up the stack. I'll defer to @alcaeus to confirm in https://github.com/alcaeus/mongo-php-adapter/issues/93 first, but I'm happy to investigate if he concludes it's a driver issue.

Are you using Doctrine ODM by any chance? The error calls to mind https://github.com/doctrine/mongodb-odm/issues/741, which was something we resolved quite a long time ago for MongoDB 2.6 compatibility. At the time, ODM was prone to creating empty $set objects, which older versions of the server would accept and NOP.

bashofmann commented 8 years ago

We also see this error without Doctrine ODM and according to the stack traces the $set object is definitely not empty

Strange is also that we only see these errors on PHP 7 and not PHP 5.6, code base is exactly the same

alcaeus commented 8 years ago

According to the trace provided in alcaeus/mongo-php-adapter#93, the call to MongoCollection::update contains parameters and they get lost sometime after that call. When you say the error does not occur on PHP 5.6, are you using mongo-php-adapter there as well or are you relying on ext-mongo for PHP 5.6?

bashofmann commented 8 years ago

We use the adapter there as well with ext-mongodb, exact same code

alcaeus commented 8 years ago

In that case, I'd like to push the ball back to @jmikola and blame mongo-php-driver or mongo-php-library :grin:

Shaked commented 8 years ago

I don't know if it's related but maybe the failing tests https://travis-ci.org/mongodb/mongo-php-driver/jobs/122810859 have something to do with this issue? It seems that bson-ods-001 and bson-ods-002 are failing over an empty bulk write. Having said that, the tests are failing both on php7 and php5.6.

Shaked Klein Orbach http://www.shakedos.com/about

On Thu, Apr 14, 2016 at 2:24 PM, Andreas notifications@github.com wrote:

In that case, I'd like to push the ball back to @jmikola https://github.com/jmikola and blame mongo-php-driver or mongo-php-library [image: :grin:]

— You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub https://github.com/mongodb/mongo-php-driver/issues/293#issuecomment-209912718

derickr commented 8 years ago

@Shaked — no, those two ODS test failures are XFAIL: expected failures.

Shaked commented 8 years ago

Hey, I got another update:

It seems that, sometimes, although the $set error appears, the data is being written to mongo but is corrupted. For example [['_id' => 'req-a10cd3c3-8485-4d21-9928-239379251472'], ['$set' => ['creatorHostname' => 'prod.cloud.net', 'handledAt' => MongoDate]], ['upsert' => true]] will end up as an empty array [], which of course, is not the correct value.

Another issue I have mentioned in the adapter bug, this also happens with $pull \ $pullAll.

jmikola commented 8 years ago

The aforementioned ODS tests are being removed in https://github.com/mongodb/mongo-php-driver/pull/303.

@Shaked: I'm still not having any luck reproducing the issue. I'm attempting to do so with the following script:

<pre style="font-size:1em"><?php

define('URI', 'mongodb://192.168.112.10:2000');
define('NS', 'test.foo');

$m = new MongoDB\Driver\Manager(URI);

$cmd = new MongoDB\Driver\Command(['drop' => explode('.', NS)[1]]);
try {
    $m->executeCommand(explode('.', NS)[0], $cmd);
} catch (MongoDB\Driver\Exception\RuntimeException $e) {}

$bulk = new MongoDB\Driver\BulkWrite;
$bulk->update(
    ['_id' => 'req-a10cd3c3-8485-4d21-9928-239379251472'],
    ['$set' => ['creatorHostname' => 'prod.cloud.net', 'handledAt' => new MongoDB\BSON\UTCDateTime(random_int(0, 999999999))]],
    ['upsert' => true]
);

$r = $m->executeBulkWrite(NS, $bulk);
printf("nMatched: %d\n", $r->getMatchedCount());
printf("nModified: %d\n", $r->getModifiedCount());
printf("nUpserted: %d\n", $r->getUpsertedCount());
// WriteResult::getUpsertedIds() doesn't handle all ID types (see: PHPC-624)

echo "\n";

$q = new MongoDB\Driver\Query(['_id' => 'req-a10cd3c3-8485-4d21-9928-239379251472']);
$c = $m->executeQuery(NS, $q);
$docs = $c->toArray();
var_dump($docs);

if (count((array) $docs[0]) !== 3) {
    fprintf(fopen('php://stderr', 'w'), "Unexpected upsert:\n\n%s\n", var_export($docs[0], true));
}

I served this via PHP 7.0.1's built-in web server (e.g. php -S localhost:8888) and began spamming hundreds of requests, but the document always has three fields after upserting. I assume it would have only an _id field if the problem manifested itself.

Can you attempt to reproduce using this script, or otherwise tweak it?

Shaked commented 8 years ago

@jmikola Thank you for getting back to me.

We have been trying few more things in the last couple of days and I believe it is worth mentioning them in here. Having said that, we are still not sure how to reproduce this error.

We have changed an entry in our codebase to directly use the mongo driver without using the php adapter. A side effect of that, ended up with us passing arrays to the update method instead of passing BSONDocument. Up until now, specifically for this entry we don't see any errors.

We don't know if the problem is related to the driver or the adapter, therefore we will be testing the same change, changing the adapter to use arrays instead of BSONDocument. We suspect that as objects are passed by reference in PHP and arrays are only passed by copy, it might be that the object is being changed somewhere later on, as we do see that the data in the object is correct until the bulk write is executed.

As well, I have tried to use the example above both with arrays and BSONDocument, unfortunately I still can't reproduce the issue.

Feel free to ask more question, I would be more than happy to help solving this issue.

Shaked commented 8 years ago

After updating the adapter code by passing arrays instead of passing BSONDocument, as mentioned above, we have encountered more mongo failures. Theses are 2 very clear examples, including the error message and then stacktrace:

BulkWrite error :: upsert { q: {}, u: {}, multi: false, upsert: true } does not contain shard key for pattern { ac: 1.0 }
/home/prd/v95.6.5/vendor/composer/mongodb/mongodb/src/Operation/Update.php (121)
MongoDB\Driver\Server::executeBulkWrite

[29]
File:      /home/prd/v95.6.5/vendor/composer/alcaeus/mongo-php-adapter/lib/Mongo/MongoCollection.php in line 394
Method:    MongoDB\Collection->updateOne
Parameter: [['ac' => 1, 'cc' => 26], ['$set' => ['ga' => MongoDB\BSON\UTCDateTime: 2016-04-21T14:12:12+0000]], ['upsert' => true, 'writeConcern' => MongoDB\Driver\WriteConcern: 1]]

[30]
File:      /home/prd/v95.6.5/vendor/composer/mongodb/mongodb/src/Collection.php in line 712
Method:    MongoDB\Operation\UpdateOne->execute
Parameter: [MongoDB\Driver\Server]

[31]
File:      /home/prd/v95.6.5/vendor/composer/mongodb/mongodb/src/Operation/UpdateOne.php in line 68
Method:    MongoDB\Operation\Update->execute
Parameter: [MongoDB\Driver\Server]

[32]
File:      /home/prd/v95.6.5/vendor/composer/mongodb/mongodb/src/Operation/Update.php in line 121
Method:    MongoDB\Driver\Server->executeBulkWrite
Parameter: ['mails.mailData', MongoDB\Driver\BulkWrite, MongoDB\Driver\WriteConcern: 1

BulkWrite error :: $and/$or/$nor must be a nonempty array
/home/prd/v95.6.5/vendor/composer/mongodb/mongodb/src/Operation/Delete.php (78)
MongoDB\Driver\Server::executeBulkWrite

[26]
File:      /home/prd/v95.6.5/vendor/composer/alcaeus/mongo-php-adapter/lib/Mongo/MongoCollection.php in line 434
Method:    MongoDB\Collection->deleteMany
Parameter: [['$and' => ['0' => ['si' => 1], '1' => ['ty' => 20]]], ['writeConcern' => MongoDB\Driver\WriteConcern: 1]]

[27]
File:      /home/prd/v95.6.5/vendor/composer/mongodb/mongodb/src/Collection.php in line 299
Method:    MongoDB\Operation\DeleteMany->execute
Parameter: [MongoDB\Driver\Server]

[28]
File:      /home/prd/v95.6.5/vendor/composer/mongodb/mongodb/src/Operation/DeleteMany.php in line 47
Method:    MongoDB\Operation\Delete->execute
Parameter: [MongoDB\Driver\Server]

[29]
File:      /home/prd/v95.6.5/vendor/composer/mongodb/mongodb/src/Operation/Delete.php in line 78
Method:    MongoDB\Driver\Server->executeBulkWrite
Parameter: ['suggestions001.quality', MongoDB\Driver\BulkWrite, MongoDB\Driver\WriteConcern: 1]

It is worth mentioning that after we pushed the code above to production, and put the server back into load, it took around 30 minutes until errors started to happen. As well, we don't always see these errors, and when we tried it on production ourselves but it didn't fail at all.

jmikola commented 8 years ago

We don't know if the problem is related to the driver or the adapter, therefore we will be testing the same change, changing the adapter to use arrays instead of BSONDocument. We suspect that as objects are passed by reference in PHP and arrays are only passed by copy, it might be that the object is being changed somewhere later on, as we do see that the data in the object is correct until the bulk write is executed.

...

After updating the adapter code by passing arrays instead of passing BSONDocument, as mentioned above, we have encountered more mongo failures.

If I understand correctly, the second quote implies that this isn't a case of the object being modified by reference and wiped out later on?

The driver serializes BulkWrite::update() arguments to BSON, which is all happening within the library's Update::execute() method. The $filter and $update arguments do get saved as private properties on that object, but shouldn't be accessible otherwise.

Shaked commented 8 years ago

The second quote can also hint that whatever happens with the BSON object, also happens with the array and both are wiped out, doesn't it? Maybe the casting from within the driver?

As you can see in my previous comment, the problem occurred while executing Delete::execute which means it is probably not an update issue.

BTW, we are constantly testing our changes both with php7.0 and php5.6 and php5.6 doesn't seem to produce any errors at all.

bashofmann commented 8 years ago

This also happens with MongoDB driver version 1.1.6.

Also this is a very serious issue, since it not only happens sometimes that a query is invalid and you get exceptions, but sometimes we also saw that a query was modified somehow somewhere outside of PHP user land code but was still valid and because of this not doing what it is supposed to do, which can be especially bad for update or delete statements.

jmikola commented 8 years ago

@bashofmann, @Shaked: I created a patch for the BulkWrite's debug handler to dump the BSON payload within the mongoc_bulk_operation_t structure, which our object wraps. You can find the diff here: https://gist.github.com/jmikola/5070358321f0cbc6fa57a09015986129

This will add a "commands" field to the debug array, in which I'm appending a JSON rendering of each write command's BSON payload (appending JSON strings was much simpler than converting back into a PHP value, and is just as useful in this case). For instance, if the BulkWrite had multiple updates, we might see a single payload for an update command with multiple update operations. If you mix operations within the same BulkWrite, which I expect you're not doing, we'd get multiple command payloads in the output.

Would you be able to use this in conjunction with some debugging on the arguments going into the BulkWrite methods to narrow down the point when the data is corrupted?

bashofmann commented 8 years ago

This will take a couple of days until we can test this. I'll keep you updated.

bashofmann commented 8 years ago

@jmikola Here is another stacktrace with the debug output from your patch

As you can see at this call to MongoDB\Collection::updateOne the query is still correct and both $inc and $set are set.

Method:    MongoDB\Collection->updateOne
Parameter: [MongoDB\Model\BSONDocument: ['experimentId' => MongoDB\BSON\ObjectID: 54b3da8fcf57d7472a8b4569, 'variantName' => 'default (3)'], MongoDB\Model\BSONDocument: ['$inc' => MongoDB\Model\BSONDocument: ['dailyHistory.2016-05-02.views' => 1, 'dailyHistory.2016-05-02.viewsMobile' => 1], '$set' => MongoDB\Model\BSONDocument: ['dailyHistory.2016-05-02.date' => MongoDB\BSON\UTCDateTime: 2016-05-02T00:00:00+0000]], ['writeConcern' => MongoDB\Driver\WriteConcern: 1]]

But the resulting query in the driver sent in the end only has $set set and $inc is empty

    [commands] => Array
        (
            [0] => { "0" : { "q" : { "experimentId" : { "$oid" : "54b3da8fcf57d7472a8b4569" }, "variantName" : "default (3)" }, "u" : { "$inc" : {  }, "$set" : { "dailyHistory.2016-05-02.date" : { "$date" : 1462147200000 } } }, "upsert" : false, "multi" : false } }
        )

jmikola commented 8 years ago

@Shaked, @bashofmann: Looking at the start of the trace, I see that your update arguments are both PHP arrays:

q: [['experimentId' => MongoId: 54b3da8fcf57d7472a8b4569, 'variantName' => 'default (3)']
u: ['$inc' => ['dailyHistory.2016-05-02.views' => 1, 'dailyHistory.2016-05-02.viewsMobile' => 1], '$set' => ['dailyHistory.2016-05-02.date' => MongoDate: 2016-05-02T00:00:00+0000]]

These later show up as BSONDocument instances, which I assume are generated by these TypeConverter::fromLegacy() calls in the adapter library.

If we look into TypeConverter::fromLegacy(), it constructs an internal array to populate with fields from the input array/object, which is later converted to a new BSONDocument before being returned.

The error you're seeing looks like a use-after-free scenario, where the array data within the $inc BSONDocument (really an ArrayObject) was garbage-collected. Running the same script through Valgrind may be able to confirm this. If the difficulty in reproducing is due to GC kicking in rather arbitrarily, perhaps a manual call to gc_collect_cycles() might help.

Independent from that, I wonder if constructing the BSONDocument before populating its fields would make a difference. That would mean embedding the logic in ensureCorrectType() in fromLegacy() when the $result value is initialized, so that the foreach directly operates on the document. Currently, all signs point to this issue happening in userland (outside of the driver). I'm suspect there could be a bug with PHP 7 tracking references in the ArrayObject's fields. If so, I'm curious if this experiement would circumvent that.

In the meantime, I'll also attempt to reproduce this by forcing gc_collect_cycles().

Also, I didn't see it mentioned above, but do you have any other notable extensions running in PHP 7 when this issue presents itself (e.g. Xdebug)?

bashofmann commented 8 years ago

We had the same problem when patching the fromLegacy logic to use a plain array instead of a BSONDocument (see https://github.com/mongodb/mongo-php-driver/issues/293#issuecomment-212942110).

The issue only appears infrequently under production load, so I can't really run valgrind.

Xdebug is not present.

List of extensions:

[PHP Modules]
apc
apcu
ast
bcmath
calendar
Core
ctype
curl
date
dom
exif
fileinfo
filter
ftp
gd
gettext
gmp
hash
iconv
imagick
imap
intl
json
ldap
libsodium
libxml
mbstring
mcrypt
memcached
mogilefs
mongodb
msgpack
openssl
pcntl
pcre
PDO
pdo_pgsql
pdo_sqlite
pgsql
Phar
posix
readline
Reflection
session
shmop
SimpleXML
soap
sockets
SPL
sqlite3
standard
stats
sysvmsg
sysvsem
sysvshm
tideways
tidy
tokenizer
uuid
v8js
wddx
xml
xmlreader
xmlrpc
xmlwriter
xsl
Zend OPcache
zip
zlib

[Zend Modules]
Zend OPcache

bashofmann commented 8 years ago

@jmikola Any news on this?

I don't know if this is related but there has been an issue in apcu discovered that looks a bit similar:

https://github.com/krakjoe/apcu/issues/168

jmikola commented 8 years ago

@bashofmann: I haven't made any progress on diagnosing this. I've run the extension's BSON tests (90 files) through Valgrind and found nothing that hints towards an issue with the BSON encoding. I assume by this point you've examined the BulkWrite methods and noted how simple they are (calling zend_parse_parameters(), encoding to a bson_t, and calling the libmongoc methods, which copy memory). I don't have any ideas for proceeding without a method of reproducing the issue in an environment we can observe/debug.

Is the ticket you referenced indicative of a bug in PHP 7.0 core or just the APCu extension?

bashofmann commented 8 years ago

It was a bug in the APCu extension.

We tested again with the updated and fixed APCu extension and the issue does not appear anymore so it seems APCu was the culprit, though it is still a bit strange since the BsonDocuments were never stored or read from APCu.

Nonetheless, I think we can close the issue :)

derickr commented 8 years ago

That's good to hear! Would you have a link to the APCu bug/changelog so we can add that here for reference purposes?

bashofmann commented 8 years ago

Yes, the one I posted above:

https://github.com/krakjoe/apcu/issues/168

alcaeus commented 8 years ago

Thanks @bashofmann!

Xonshiz commented 5 years ago

Digging this old issue. I'm on PHP 7 and I'm facing the same issue. Not sure what to do. :/

jmikola commented 5 years ago

@Xonshiz: Please open a new issue. You can always link back to this thread for context. When doing so, the template should request much more information about your environment, so please provide as much of that as possible ("PHP 7" is not nearly enough to go on). Since the issue in this thread was attributed to APCu, it'd be helpful to include any details about that extension in your report. Also, if the error is reproducible, any steps to do so would certainly help.

Xonshiz commented 5 years ago

Sure, thanks.

mongodb / mongo-php-driver

BulkWrite error :: '$set' is empty. You must specify a field like so: {$set: {<field>: ...}} #293