mongodb / mongo-php-driver

The Official MongoDB PHP driver

https://pecl.php.net/package/mongodb

Apache License 2.0

882 stars 200 forks source link

MongoDuplicateKeyException E11000 duplicate key error collection #868

Closed kralos closed 4 years ago

kralos commented 6 years ago

Description

Using MongoDB\BSON\ObjectId causes collisions

Test case:

I'm running multiple crons on 1 host at the same time which will collide on {_id} when inserting.

Environment

software	version
debian	9.4
php	7.2.6
ext-mongodb	1.5.0
libbson	1.11.0
libmongoc	1.11.0

I'm using a php docker image build off php:7.2.6-cli with ext-mongodb 1.5.0 installed.

php -i | grep -E 'mongodb|libmongoc|libbson'

/usr/local/etc/php/conf.d/docker-php-ext-mongodb.ini,
mongodb
libbson bundled version => 1.11.0
libmongoc bundled version => 1.11.0
libmongoc SSL => enabled
libmongoc SSL library => OpenSSL
libmongoc crypto => enabled
libmongoc crypto library => libcrypto
libmongoc crypto system profile => disabled
libmongoc SASL => disabled
libmongoc ICU => enabled
libmongoc compression => enabled
libmongoc compression snappy => disabled
libmongoc compression zlib => enabled
mongodb.debug => no value => no value

Dockerfile

FROM php:7.2.6-cli

RUN pecl channel-update pecl.php.net \
    && pecl install \
    mongodb-1.5.0 \
    && docker-php-ext-enable \
    mongodb

docker build -t dev/php:7.2.6-cli

I've created a wrapper to execute php inside docker from the host OS:

$ cat /usr/bin/php 
#!/bin/sh

docker run \
    --rm \
    --network=host \
    -v /test:/test \
    -w "$PWD" \
    dev/php:7.2.6-cli \
    php -d memory_limit=-1 "$@"

exit $?

Test Script

test-ext-mongodb.php

#!/usr/bin/env php
<?php

// ext-mongodb
$manager = new MongoDB\Driver\Manager('mongodb://127.0.0.1');
$bulk = new MongoDB\Driver\BulkWrite();
$objectId = new MongoDB\BSON\ObjectId();
$bulk->insert([
    '_id' => $objectId,
    'name' => 'ext-mongodb',
]);
$manager->executeBulkWrite('collisions.test', $bulk);

crontab

*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php
*  *    *   *   *       /test/test-ext-mongodb.php

(There are 20 entries)

Expected and Actual Behavior

We are expecting 20 documents to be inserted into collisions.test in the next minute.

Instead 15 documents are inserted and I get 5 emails from crontab with E11000 duplicate key error collection.

Debug Log

> db.test.find().count();
15
>

I get 5 emails like this:

PHP Fatal error: Uncaught MongoDB\Driver\Exception\BulkWriteException: E11000 duplicate key error collection: collisions.test index: _id_ dup key: { : ObjectId('5b3599369ce09000010f0a72') } in /test/test-ext-mongodb.php:12
Stack trace:
#0 /test/test-ext-mongodb.php(12): MongoDB\Driver\Manager->executeBulkWrite('collisions.test', Object(MongoDB\Driver\BulkWrite))
#1 {main}
thrown in /test/test-ext-mongodb.php on line 12

Fatal error: Uncaught MongoDB\Driver\Exception\BulkWriteException: E11000 duplicate key error collection: collisions.test index: _id_ dup key: { : ObjectId('5b3599369ce09000010f0a72') } in /test/test-ext-mongodb.php on line 12

MongoDB\Driver\Exception\BulkWriteException: E11000 duplicate key error collection: collisions.test index: _id_ dup key: { : ObjectId('5b3599369ce09000010f0a72') } in /test/test-ext-mongodb.php on line 12

Call Stack:
0.0001 389200 1. {main}() /test/test-ext-mongodb.php:0
0.0251 389888 2. MongoDB\Driver\Manager->executeBulkWrite() /test/test-ext-mongodb.php:12

kralos commented 6 years ago

I've found from time to time the collisions don't happen, if you can't reproduce this, try increasing the number of cron entries (simultaneous inserts) and even leave it to run for a little while.

You might see something like this:

> db.test.find().count();
438
>

with 2 exception emails.

timwhitlock commented 5 years ago

@kralos have you got anywhere with this?

I'm having this issue in production. Very occasionally I get a conflict on another id generated in the same process. I've been unable to find a fault on the application side and unable to reproduce it.

In my case the collisions happens when hundreds of ids are generated in the same script. I guess that differs from your case where the clashes are cross-process. I can provide example IDs if it helps diagnose.

kralos commented 5 years ago

@timwhitlock I'm not working on this, I only reported it. At this stage I could only suggest you try generating the ids your self. I have some code leveraging random_bytes however my id's are then not orderable.

<?php

declare(strict_types=1);

namespace App\MongoDb\Id;

use Doctrine\ODM\MongoDB\DocumentManager;
use Doctrine\ODM\MongoDB\Id\AbstractIdGenerator;
use function hash;
use function random_bytes;

class CSPRNGenerator extends AbstractIdGenerator
{
    const ENTROPY_SIZE = 500;

    public function generate(DocumentManager $dm, $document): string
    {
        $entropy = random_bytes(self::ENTROPY_SIZE);
        return hash('sha256', $entropy);
    }
}

timwhitlock commented 5 years ago

Thanks for the tip. I'll look into it.

jmikola commented 5 years ago

Sorry for losing track of this issue and not replying sooner. We just caught it again via the notifications for the most recent comments over the past few days.

My understanding from this Stack Overflow thread is that each process within the Docker container still gets a unique PID on the host, independent of any namespaced PID within the container.

Per the MongoDB\BSON\ObjectId documentation, the ObjectId's 12-byte value consists of:

a 4-byte value representing the seconds since the Unix epoch,
a 3-byte machine identifier,
a 2-byte process ID, and
a 3-byte counter, starting with a random value.

All other fields being equal, the 3-byte counter allows up to 2^24 (i.e. 16777216) distinct values to be generated by the same process on the same machine within the same second. The 3-byte counter itself is also initialized to a random value (seed noted in the comments), so it's not as if each ObjectId starts its counter at zero.

Based on the crontab, 20 copies of test-ext-mongodb.php are executed each minute. Based on the code in the OP, each instance of this script inserts a single document. If we expect the time and machine identifier to be the same, each process should at least have a unique PID. We can reasonably assume the counter will be unique, although there is a chance two randomly generated values could conflict.

If two randomly generated counter values do conflict, the only thing I can think of is that a PID is being reused within the same second. This might be possible if, over the course of launching 20 instances of test-ext-mongodb.php, one of those processes completes very quickly and its PID is used by a later process in the crontab sequence.

In my case the collisions happens when hundreds of ids are generated in the same script. I guess that differs from your case where the clashes are cross-process.

This is more curious, as the 3-byte counter should increment with each ObjectId constructed. Assuming all other fields remain constant (4-byte timestamp, 3-byte machine ID, 2-byte PID), each ObjectId should still be unique. I realize you said you've been unable to reproduce this, but I'd be very interested if more details show up down the line.

The only thing I can think to ask is whether you're using ext-mongodb directly, or perhaps using mongo-php-adapter or some other library abstracting the driver.

The discussion above pertains to the current version of the driver (1.5.3) and libmongoc/libbson 1.13.

In future versions the behavior for generating ObjectIds will change so that the 5-byte segment in the middle of the ObjectId is also randomly generated for the process instead of being derived directly from the machine ID (e.g. hostname) and PID. These changes are documented in the ObjectId specification and the current version of the MongoDB manual. The development version of libbson has already implemented these changes in https://github.com/mongodb/mongo-c-driver/commit/8130e791c2a101a38fe5551c253c7b0dda894d3a and we expect they'll show up in the forthcoming 1.6.0 release of the driver.

At this stage I could only suggest you try generating the ids your self. I have some code leveraging random_bytes however my id's are then not orderable.

If you'd like to preserve order, you can still prefix your generated ObjectId strings with a 4-byte unique timestamp (in big endian byte order, per the spec) and then use random data for the remaining 8-bytes. The raw bytes for the time component can be created with pack('N', time()) (see: mongofill for some prior art).

timwhitlock commented 5 years ago

Thank you for the thorough information. Not being the original poster, I was looking for known issues with collisions. I'll continue to try to reproduce an error. From what I've seen it does seem a collision is a practical impossibility within the same second on the same machine.

alcaeus commented 4 years ago

Closing due to inactivity.

kralos commented 3 years ago

I just got this problem again on a different application. I have 2 crons (docker wrapped php scripts) which are simultaneously inserting into 1 collection at a reasonable rate (maybe 2/second each for ~10 documents). These crons run every 15 minutes and I get collisions on _id ~once every 2-3 days.

using doctrine/mongodb-odm + mongodb/mongodb to do the inserts

"name": "doctrine/mongodb-odm",
"version": "2.1.3",

"name": "mongodb/mongodb",
"version": "1.8.0",

$ php -i | grep -i mongo | grep version
MongoDB extension version => 1.8.2
libmongoc bundled version => 1.17.2
libmongocrypt bundled version => 1.0.4
$ php -v
PHP 7.4.12 (cli) (built: Nov  5 2020 20:09:22) ( NTS )
Copyright (c) The PHP Group
Zend Engine v3.4.0, Copyright (c) Zend Technologies
    with Zend OPcache v7.4.12, Copyright (c), by Zend Technologies
    with Xdebug v2.9.8, Copyright (c) 2002-2020, by Derick Rethans

I just also re-tested with the originally reported method and I get exactly the same result (on the above version of php / monodb / libmongoc etc:

sometimes all 20 inserts work, sometimes 1 or more fail.

PHP Fatal error: Uncaught MongoDB\Driver\Exception\BulkWriteException: E11000 duplicate key error collection: collisions.test index: _id_ dup key: { _id: ObjectId('5ff4f27e46d90f055672e5d2') } in /test/test-ext-mongodb.php:12
Stack trace:
#0 /test/test-ext-mongodb.php(12): MongoDB\Driver\Manager->executeBulkWrite('collisions.test', Object(MongoDB\Driver\BulkWrite))
#1 {main}
thrown in /test/test-ext-mongodb.php on line 12

Fatal error: Uncaught MongoDB\Driver\Exception\BulkWriteException: E11000 duplicate key error collection: collisions.test index: _id_ dup key: { _id: ObjectId('5ff4f27e46d90f055672e5d2') } in /test/test-ext-mongodb.php on line 12

MongoDB\Driver\Exception\BulkWriteException: E11000 duplicate key error collection: collisions.test index: _id_ dup key: { _id: ObjectId('5ff4f27e46d90f055672e5d2') } in /test/test-ext-mongodb.php on line 12

Call Stack:
0.0001 392264 1. {main}() /test/test-ext-mongodb.php:0
0.0003 393096 2. MongoDB\Driver\Manager->executeBulkWrite() /test/test-ext-mongodb.php:12

kralos commented 3 years ago

Testing

Please see test environment:

https://gist.github.com/kralos/75eac36a863cdfaf7d101f73d916a1a0

If I run test-sleep.php, inside the docker containers I'm getting pid 1 for all instances.

on the host machine I'm getting different pids:

$ ps -ef | grep test-sleep
kralos    158876  158851  0 10:44 ?        00:00:00 /bin/sh -c /tmp/mongo-php-driver-868/php /tmp/mongo-php-driver-868/test-sleep.php
kralos    158880  158853  0 10:44 ?        00:00:00 /bin/sh -c /tmp/mongo-php-driver-868/php /tmp/mongo-php-driver-868/test-sleep.php
kralos    158881  158852  0 10:44 ?        00:00:00 /bin/sh -c /tmp/mongo-php-driver-868/php /tmp/mongo-php-driver-868/test-sleep.php
kralos    158894  158876  0 10:44 ?        00:00:00 /bin/sh /tmp/mongo-php-driver-868/php /tmp/mongo-php-driver-868/test-sleep.php
kralos    158901  158881  0 10:44 ?        00:00:00 /bin/sh /tmp/mongo-php-driver-868/php /tmp/mongo-php-driver-868/test-sleep.php
kralos    158907  158880  0 10:44 ?        00:00:00 /bin/sh /tmp/mongo-php-driver-868/php /tmp/mongo-php-driver-868/test-sleep.php
kralos    158911  158894  0 10:44 ?        00:00:00 docker run --rm --network=host -v /tmp/mongo-php-driver-868:/tmp/mongo-php-driver-868 mongo-php-driver-868/php php /tmp/mongo-php-driver-868/test-sleep.php
kralos    158913  158901  0 10:44 ?        00:00:00 docker run --rm --network=host -v /tmp/mongo-php-driver-868:/tmp/mongo-php-driver-868 mongo-php-driver-868/php php /tmp/mongo-php-driver-868/test-sleep.php
kralos    158924  158907  0 10:44 ?        00:00:00 docker run --rm --network=host -v /tmp/mongo-php-driver-868:/tmp/mongo-php-driver-868 mongo-php-driver-868/php php /tmp/mongo-php-driver-868/test-sleep.php
root      159667  159509  0 10:44 ?        00:00:00 php /tmp/mongo-php-driver-868/test-sleep.php
root      159864  159740  0 10:44 ?        00:00:00 php /tmp/mongo-php-driver-868/test-sleep.php
root      159883  159781  0 10:44 ?        00:00:00 php /tmp/mongo-php-driver-868/test-sleep.php
kralos    160265   13707  0 10:44 pts/1    00:00:00 grep test-sleep

Re-validated issue on php 7.4.13:

$ /tmp/mongo-php-driver-868/php -v
PHP 7.4.13 (cli) (built: Dec 18 2020 21:12:27) ( NTS )
Copyright (c) The PHP Group
Zend Engine v3.4.0, Copyright (c) Zend Technologies
kralos@maia:/tmp/mongo-php-driver-868$ /tmp/mongo-php-driver-868/php -i | grep -i mongo | grep ersion
MongoDB extension version => 1.9.0
libmongoc bundled version => 1.17.2

Still getting duplicate _id on insert with above environment.

Also tried php 8.0.0, same results.

$ /tmp/mongo-php-driver-868/php -v
PHP 8.0.0 (cli) (built: Dec 18 2020 21:07:48) ( NTS )
Copyright (c) The PHP Group
Zend Engine v4.0.0-dev, Copyright (c) Zend Technologies
$ /tmp/mongo-php-driver-868/php -i | grep -i mongo | grep ersion
MongoDB extension version => 1.9.0
libmongoc bundled version => 1.17.2

Making docker use host PID

In order for the client driver to more reliably generate a unique ObjectId, if using docker to execute php, you can tell docker to use the host's PID. https://docs.docker.com/engine/reference/run/#pid-settings---pid

docker run --pid=host ###

I re-tested with this and can't get a collision now.

test-sleep.php does yield different pid's per instance now.

kralos commented 3 years ago

@timwhitlock out of interest, are you using docker to execute php?

timwhitlock commented 3 years ago

@kralos Hi. No I'm not. PHP runs on a VPS cluster. My issue has disappeared in the two years since my post. I can't remember if I ever got to the bottom of it, but I suspect it was a code error on my part and not a fault with the driver.

alcaeus commented 3 years ago

@kralos thanks for following up. I noted that the original issue affected version 1.5.0 of the extension, with the new issue affecting 1.8.2. With version 1.6.0, the extension uses a libmongoc version that implements the ObjectID specification mentioned above. This changes the components of an ObjectID. Before 1.6.0, this was the structure of an ObjectID generated by the extension (as noted by @jmikola earlier in this thread):

a 4-byte value representing the seconds since the Unix epoch,

a 3-byte machine identifier,

a 2-byte process ID, and

a 3-byte counter, starting with a random value.

As per the new specification, the machine and PID components were replaced with a random value, making this the new structure of an ObjectID

a 4-byte value representing the seconds since the Unix epoch in the highest order bytes,

a 5-byte random number unique to a machine and process,

a 3-byte counter, starting with a random value.

Here's an excerpt from libmongoc where the 5-byte random number is generated (full source):

   unsigned int seed = 0;
   // [...]

   /*
    * The seed consists of the following xor'd together:
    * - current time in seconds
    * - current time in milliseconds
    * - current pid
    * - current hostname
    */
   bson_gettimeofday (&tv);
   seed ^= (unsigned int) tv.tv_sec;
   seed ^= (unsigned int) tv.tv_usec;
   seed ^= (unsigned int) context->pid;
   // Omitted hostname for brevity

   rand_bytes = _get_rand (&seed);
   rand_bytes <<= 32;
   rand_bytes |= _get_rand (&seed);

   /* Copy five random bytes, endianness does not matter. */
   memcpy (&context->rand, (char *) &rand_bytes, sizeof (context->rand));
}

Using the reproducer you provided, I ran the following test-oid.php script. Using your test-sleep.php script I have previously confirmed that the PID is 1 in all these processes:

<?php

var_dump((string) (new MongoDB\BSON\ObjectId));

I run this in the background using a bash script test-oid.sh:

#!/bin/bash
docker run --rm --network=host -v $(pwd):/tmp/test-oid mongo-php-driver-868/php php /tmp/test-oid/test-oid.php &

Here's the output from parallel runs. Note that I have sorted the output using sort for subsequent analysis:

$ for iter in {1..20}; do ./test-oid.sh; done
string(24) "5ff8371c9faf472e6b573dc1"
string(24) "5ff8371cbd77f8208f4d19c1"
string(24) "5ff8371cd869c3638773a391"
string(24) "5ff8371cdbdab6778154bb41"
string(24) "5ff8371cf6059666660082e1"
string(24) "5ff8371cfa596474d176bdd1"
string(24) "5ff8371d124a8f6ba060fcd1"
string(24) "5ff8371d2e678a028613a621"
string(24) "5ff8371d34f1214e92642091"
string(24) "5ff8371d4339605e167a6531"
string(24) "5ff8371d59130f0e196c49c1"
string(24) "5ff8371d74f087099d67fa01"
string(24) "5ff8371d908d742f9a27fb31"
string(24) "5ff8371d9ab5e71b957a6fe1"
string(24) "5ff8371daedc310f883b6521"
string(24) "5ff8371db14d2523831c7cd1"
string(24) "5ff8371dc218976e10492ed1"
string(24) "5ff8371dcc7de65c0a04afc1"
string(24) "5ff8371dea82de7b8107d4e1"
string(24) "5ff8371df6962f15c832c3e1"

Let's analyse two random object identifiers generated earlier:

Time    |Random    |Counter
--------|----------|------
5ff8371d|2e678a0286|13a621
5ff8371d|ea82de7b81|07d4e1

As you can see, while the timestamp is the same, both the random component and the counter differ, which is expected due to them being completely random. In my tests, I haven't gotten a duplicate random component twice, let alone the same random component and same counter in the same second. I haven't bothered using the crontab method of executing processes in parallel, but the invocation method should not make a difference.

For a completely hypothetical and far-fetched example, let's assume that two processes A and B start with similar initial values for the counter:

A: 0x13a621
B: 0x13a623

Generating two ObjectId instances in A will "synchronise" the counter values. Assuming that we then generate an ObjectId in each process in the exact same second, the ObjectIds will look like this:

Time    |Random    |Counter
--------|----------|------
5ff8371d|__________|13a623
5ff8371d|__________|13a623

As you can see, they are identical except for the random value generated when the first ObjectId is generated. The chances of this happening are next to none, and I'm not entirely sure how you manage to reproduce such a scenario.

vkatochka commented 3 years ago

I ran tests as part of ticket #1104. A few months ago I was doing a test that was consistently producing error E11000. The insertion took place on an empty database. From the data it can be seen that about ~ 5000 first records, the "Random" value is the same. The script was run from the shell as "php test &" several times simultaneously.

#Row|Time    |Random    |Counter
----|--------|----------|------
   1|5f27363c|52d7d00d6b|786784
   2|5f27363c|52d7d00d6b|786787
   3|5f27363c|52d7d00d6b|78678a
     .....
4001|5f27363e|52d7d00d6b|789664
     .....
5001|5f27363e|52d7d00d6b|78a21c
     .....
6001|5f273646|086a6b1bf3|269bf4

example of data

"_id" : ObjectId("5f27363c52d7d00d6b786784")
"_id" : ObjectId("5f27363c52d7d00d6b786787")
"_id" : ObjectId("5f27363c52d7d00d6b78678a")
"_id" : ObjectId("5f27363c52d7d00d6b78678d")
"_id" : ObjectId("5f27363c52d7d00d6b786790")
"_id" : ObjectId("5f27363c52d7d00d6b786793")
"_id" : ObjectId("5f27363c52d7d00d6b786796")
"_id" : ObjectId("5f27363c52d7d00d6b786799")
"_id" : ObjectId("5f27363c52d7d00d6b78679c")
"_id" : ObjectId("5f27363c52d7d00d6b78679f")
"_id" : ObjectId("5f27363c52d7d00d6b7867a2")
"_id" : ObjectId("5f27363c52d7d00d6b7867a5")
"_id" : ObjectId("5f27363c52d7d00d6b7867a8")
"_id" : ObjectId("5f27363c52d7d00d6b7867ab")
"_id" : ObjectId("5f27363c52d7d00d6b7867ae")
"_id" : ObjectId("5f27363c52d7d00d6b7867b1")
"_id" : ObjectId("5f27363c52d7d00d6b7867b4")
"_id" : ObjectId("5f27363c52d7d00d6b7867b7")
"_id" : ObjectId("5f27363c52d7d00d6b7867ba")
"_id" : ObjectId("5f27363c52d7d00d6b7867bd")
"_id" : ObjectId("5f27363c52d7d00d6b7867c0")
"_id" : ObjectId("5f27363c52d7d00d6b7867c3")
"_id" : ObjectId("5f27363c52d7d00d6b7867c6")
"_id" : ObjectId("5f27363c52d7d00d6b7867c9")
"_id" : ObjectId("5f27363c52d7d00d6b7867cc")
"_id" : ObjectId("5f27363c52d7d00d6b7867cf")
"_id" : ObjectId("5f27363c52d7d00d6b7867d2")
"_id" : ObjectId("5f27363c52d7d00d6b7867d5")
"_id" : ObjectId("5f27363c52d7d00d6b7867d8")
"_id" : ObjectId("5f27363c52d7d00d6b7867db")
"_id" : ObjectId("5f27363c52d7d00d6b7867de")
"_id" : ObjectId("5f27363c52d7d00d6b7867e1")
"_id" : ObjectId("5f27363c52d7d00d6b7867e4")
"_id" : ObjectId("5f27363c52d7d00d6b7867e7")
"_id" : ObjectId("5f27363c52d7d00d6b7867ea")
"_id" : ObjectId("5f27363c52d7d00d6b7867ed")
"_id" : ObjectId("5f27363c52d7d00d6b7867f0")
"_id" : ObjectId("5f27363c52d7d00d6b7867f3")
"_id" : ObjectId("5f27363c52d7d00d6b7867f6")
"_id" : ObjectId("5f27363c52d7d00d6b7867f9")
"_id" : ObjectId("5f27363c52d7d00d6b7867fc")
"_id" : ObjectId("5f27363c52d7d00d6b7867ff")
"_id" : ObjectId("5f27363c52d7d00d6b786802")
"_id" : ObjectId("5f27363c52d7d00d6b786805")
"_id" : ObjectId("5f27363c52d7d00d6b786808")
"_id" : ObjectId("5f27363c52d7d00d6b78680b")
"_id" : ObjectId("5f27363c52d7d00d6b78680e")
"_id" : ObjectId("5f27363c52d7d00d6b786811")
"_id" : ObjectId("5f27363c52d7d00d6b786814")
"_id" : ObjectId("5f27363c52d7d00d6b786817")

alcaeus commented 3 years ago

@vkatochka thanks for following up. For the record, we expect the random portion of the ObjectIds to be the same for multiple ObjectIds generated in the same process, as this is initialised when the first ObjectId is generated and re-used. It is only re-generated if the PID of the process generating the ObjectId differs from the one stored when generating the first ObjectId.

Edit to follow up: how was the list above generated? I'm curious by the random component to change somewhere after 5000 ObjectIds - was this output collected from separate processes or how did you fetch it? Did you see the same random segment in ObjectIds generated from separate processes or did all processes have a unique random segment in all ObjectIds they generated?

vkatochka commented 3 years ago

Still reproducible in MongoDB 5.0.1.

Reproduced in two places. New server hardware Proxmox LXD container. Home hardware Ubuntu LXD container.

Two php script run in parallel from console generate the same OID, see below. This raises an error:

E11000 duplicate key error collection: bug2.mc1 index: _id_ dup key: { _id: ObjectId('6101a9f3b0ad1c482949ffb0') }

grep log files

Logfile        Date                           PID     OID                        iteration "foreach"
OIDs-21533.log:[2021-07-28 19:03:15.486226]   21533   6101a9f3b0ad1c482949ffb0   i=5967
OIDs-21534.log:[2021-07-28 19:03:15.215409]   21534   6101a9f3b0ad1c482949ffb0   i=5967

OIDs-21533.log:[2021-07-28 19:03:15.486439]   21533   6101a9f3b0ad1c482949ffb1   i=5968
OIDs-21534.log:[2021-07-28 19:03:15.215553]   21534   6101a9f3b0ad1c482949ffb1   i=5968

OIDs-21533.log:[2021-07-28 19:03:15.486653]   21533   6101a9f3b0ad1c482949ffb2   i=5969
OIDs-21534.log:[2021-07-28 19:03:15.215698]   21534   6101a9f3b0ad1c482949ffb2   i=5969

OIDs-21533.log:[2021-07-28 19:03:15.486866]   21533   6101a9f3b0ad1c482949ffb3   i=5970
OIDs-21534.log:[2021-07-28 19:03:15.215841]   21534   6101a9f3b0ad1c482949ffb3   i=5970

OIDs-21533.log:[2021-07-28 19:03:15.487077]   21533   6101a9f3b0ad1c482949ffb4   i=5971
OIDs-21534.log:[2021-07-28 19:03:15.215983]   21534   6101a9f3b0ad1c482949ffb4   i=5971

OIDs-21533.log:[2021-07-28 19:03:15.487287]   21533   6101a9f3b0ad1c482949ffb5   i=5972
OIDs-21534.log:[2021-07-28 19:03:15.216139]   21534   6101a9f3b0ad1c482949ffb5   i=5972

OIDs-21533.log:[2021-07-28 19:03:15.487497]   21533   6101a9f3b0ad1c482949ffb6   i=5973
OIDs-21534.log:[2021-07-28 19:03:15.216277]   21534   6101a9f3b0ad1c482949ffb6   i=5973

OIDs-21533.log:[2021-07-28 19:03:15.487704]   21533   6101a9f3b0ad1c482949ffb7   i=5974
OIDs-21534.log:[2021-07-28 19:03:15.216416]   21534   6101a9f3b0ad1c482949ffb7   i=5974

OIDs-21533.log:[2021-07-28 19:03:15.487912]   21533   6101a9f3b0ad1c482949ffb8   i=5975  !!! at the same moment foreach
OIDs-21534.log:[2021-07-28 19:03:15.216556]   21534   6101a9f3b0ad1c482949ffb8   i=5975  !!! at the same moment

Code to reproduce this:

cd
mkdir test && cd test
mkdir -p composer && cd composer
composer require --no-plugins --no-scripts mongodb/mongodb
cd ..
touch test.php

Copy the below code to test.php:

#
$pid = getmypid();

#
include('./composer/vendor/autoload.php');

#
try
{
    $mnc = new MongoDB\Client('mongodb://127.0.0.1:27017');
    $dbc = $mnc->selectDatabase('e11000');
    $dbc->selectCollection('testCheck')->findOne([]);
}
catch(Exception $e)
{
    print("mongodb connection failed\n"); exit();
}

#
$col = $dbc->selectCollection('e11000');

#
foreach(range(1,6000) as $i)
{
    #
    $_id = new MongoDB\BSON\ObjectId();

    #
    $sid = (string)$_id;
    $now = new DateTime('now');

    #
    $data = [
        '_id' => $_id,
        'iii' => $i,
        'pid' => $pid,
    ];

    #
    file_put_contents("OIDs-{$pid}.log",'['. $now->format('Y-m-d H:i:s.u') ."]   {$pid}   {$sid}   i={$i}\n",FILE_APPEND);

    #
    try
    {
        $col->insertOne($data);
    }
    catch(Exception $e)
    {
        #
        $code = $e->getCode();
        $mesg = $e->getMessage();

        #
        print("\n  {$pid}  {$i}: {$code}{$mesg}");
    }
}

php test.php & php test.php & php test.php & php test.php & php test.php & php test.php &

Run (6 scripts at the same time) and wait for execution. Repeat several times. In my environment, the error appears on run 6-8th.

Conditions for faster error detection:

fast server with a large number of cores (in my case 20); CPU idle
SSD disk; without load
free RAM (32Gb in my case)

The error is not reproducible (maybe needed more tries):

on "hardware" with two unloaded cores
where, mongodb is under load

LMCom commented 3 years ago

Update: The problem mentioned below was caused by Laravel's chunk() method. It does repeated queries with LIMIT and OFFSET and can get duplicates, if data changes during that.

Per the MongoDB\BSON\ObjectId documentation, the ObjectId's 12-byte value consists of:
* a 4-byte value representing the seconds since the Unix epoch,

* a 3-byte machine identifier,

* a 2-byte process ID, and

* a 3-byte counter, starting with a random value.
All other fields being equal, the 3-byte counter allows up to 2^24 (i.e. 16777216) distinct values to be generated by the same process on the same machine within the same second. The 3-byte counter itself is also initialized to a random value (seed noted in the comments), so it's not as if each ObjectId starts its counter at zero.

You need really bad luck for a collision!

But it's even crazier in my case. About 50 times per day, I am synchronizing about 2000 records into a Mongo database. These records come from a relational database where each record has a unique key. I am setting this key as _id and doing a bulk insert. On average, this gives me a duplicate key error once per day.

The key has a unique constraint in the relational database and is guaranteed to be unique. The records are also fetched by a query that cannot return duplicates.