A never-ending query after upgrade to MongoDB 6.0.3

[pavelsc]

Bug Report

Hello, I have an issue with execution of a simple findOne query which worked correctly before mongodb upgrade to 6.0.3. There are no errors when the script is executed, it just stays in a running state with no response after a successfull connection. Error reporting is set to E_ALL. Compass app shows tables and data without delays.

Query is a quite simple

$this->client->findOne([
    'contact_id'   => 'xxx@gmail.com',
    'contact_type' => 'email',
    'product_id'   => 3000,
  ], [
  'projection' => [
    '_id' => 0
  ],
]);

Also I tried to ping MongoDB:

strace -tt php -r '$m = new MongoDB\Driver\Manager( "mongodb://10.60.75.73:27017,10.60.75.74:27017,10.60.75.75:27017/?replicaSet=rs0" ); var_dump($m->executeCommand( "admin", new MongoDB\Driver\Command( [ "ping" => 1] ) ) );'

Pastebin

Environment

I use PHP 8.1.14 (cli) (built: Jan 4 2023 06:45:14) (NTS gcc x86_64)
with mongodb/mongodb 1.15.0
MongoDB version 6.0.3

mongodb
libbson bundled version => 1.23.1
libmongoc bundled version => 1.23.1
libmongoc SSL => enabled
libmongoc SSL library => OpenSSL
libmongoc crypto => enabled
libmongoc crypto library => libcrypto
libmongoc crypto system profile => enabled
libmongoc SASL => enabled
libmongoc ICU => enabled
libmongoc compression => enabled
libmongoc compression snappy => enabled
libmongoc compression zlib => enabled
libmongoc compression zstd => enabled
libmongocrypt bundled version => 1.5.2
libmongocrypt crypto => enabled
libmongocrypt crypto library => libcrypto
mongodb.debug => no value => no value

I tried it from scratch with Docker configuration listed below with the same result:

FROM phpdockerio/php:8.1-cli

RUN apt-get update \
    && apt-get upgrade -y \
    && apt-get -y --no-install-recommends install php-pear php-pgsql php-bcmath php-http-request2 \
    && apt-get install -y libpq-dev tzdata gettext-base gettext msmtp procps php8.1-dev libpcre3 libpcre3-dev git \
    && apt-get clean \
    && rm -rf /var/lib/apt/lists/* /tmp/* /var/tmp/* /usr/share/doc/*

RUN pecl install mongodb

RUN echo "extension=mongodb.so" > /etc/php/8.1/cli/conf.d/20-mongodb.ini && \
	echo "extension=mongodb.so" > /etc/php/8.1/mods-available/mongodb.ini

RUN apt-get update && apt-get install -y supervisor
RUN mkdir -p /var/log/supervisor

COPY ./ /var/www/services/
COPY ./config/ /var/www/services/config/
COPY ./build/php8.1-cli-supervisor/supervisord.d/association-services.conf /etc/supervisor/conf.d/association-services.conf

RUN echo user=root >>  /etc/supervisor/supervisord.conf

CMD ["/usr/bin/supervisord","-n"]

[alcaeus]

Looking at the trace you provided, I can see a legacy hello being sent to the server, but I can't see a response received from the server. This indicates that while the driver was able to establish a connection to the server (ruling out SSL issues etc.), the handshake does not complete successfully. However, I'm not sure what exactly is causing this.

As an alternative to strace, could you please try to run the small ping example with the mongodb.debug ini setting enabled? You can enable this by calling php with php -d mongodb.debug=stderr ... to have the debug log printed to your error output. This limits debug information to the PHP driver and would make it a little easier to trace messages to and from the server without having a number of unrelated log messages bloat the log.

One more thing, did you try downgrading to an older MongoDB version? I've been running 6.0.3 without having this issue, and it surprises me that it would hang like this when other tools connect just fine. Figuring out whether it happens only on 6.0.3 or on older versions as well would help us in trying to locate the source of the problem.

[pavelsc]

Thanks for your help.
I downgraded MongoDb works just fine with the same example.

As an alternative to strace, could you please try to run the small ping example with the mongodb.debug ini setting enabled?

Custom error log remains empty as well as /var/log/php/php-errors.log

[alcaeus]

Custom error log remains empty as well as /var/log/php/php-errors.log

That is odd. Running the code as above should definitely produce some output. Here is an example from my machine:

$ php -d mongodb.debug=stderr -r "(new MongoDB\Driver\Manager)->executeCommand('test', new MongoDB\Driver\Command(['ping' => 1]));"
[2023-02-20T11:45:58.820582+00:00]     PHONGO: DEBUG   > Connection string: 'mongodb://127.0.0.1/'
[...]

Even without running a command there should be some output, as instantiating a Manager instance will create log output even when it doesn't connect to a cluster.

[pavelsc]

FInally I sorted it out. It doesn't connect when the connection string is for cluster, I mean it looks like this:

mongodb://10.60.75.73:27017,10.60.75.74:27017,10.60.75.75:27017/?replicaSet=rs0

But it's ok when I connect to a single server of a cluster:

mongodb://10.60.75.73:27017

I created a repo https://github.com/pavelsc/mongodb-php-test to reproduce. It consists of two docker containers: mongo-db and mongo-php-app. mongo-php-app connects to a mongo-db single instance by default and works correctly. If you have a mongo cluster you can change config config/mongo.php to something like this:

<?php

return [
  "username"    => "",
  "password"    => "",
  "database"    => "dev", // dev should exist or pick your own, also there is a volume db-data for mongo in the repo
  "replica_set" => "rs0",
  "host"        => [
    "your-server-1:27017",
    "your-server-2:27017",
    "your-server-3:27017"
  ]
];

then build mongo-php-app and run php index.php in it - nothing happens.
If you leave only one server in the config and rerun php index.php - it will work (of course you need to remove replica_set).
And the weirdest thing - the same config with 3 servers connects to the same mongo cluster if I run php on Windows system.

[jmikola]

I cloned https://github.com/pavelsc/mongodb-php-test to attempt reproduction.

I extracted /volumes/db-data.tar.zst to the /volumes/db-data directory. I found it necessary to remove the external: true option from the volumes.db-data configuration in docker-compose.yaml.

I started both containers with docker-compose up and then opened a shell in the mongo-php-app container to run index.php. The script appeared to connect successfully to the server in the mongo-db container.

If you have a mongo cluster you can change config config/mongo.php...

I then created an Atlas M0 cluster (server version 6.0.5) and obtained the non-SRV connection string so I could enter each of the three hosts and replica set name in the config/mongo.php file. The modified file resembled the following:

@@ -1,11 +1,13 @@
 <?php
 
 return [
-  "username"    => "root",
-  "password"    => "example",
+  "username"    => "<username>",
+  "password"    => "<password>",
   "database"    => "dev",
-  "replica_set" => "",
+  "replica_set" => 'atlas-r3glsi-shard-0',
   "host"        => [
-    "mongo-db:27017"
+    'ac-tkwmcmr-shard-00-00.07pgo2r.mongodb.net:27017',
+    'ac-tkwmcmr-shard-00-01.07pgo2r.mongodb.net:27017',
+    'ac-tkwmcmr-shard-00-02.07pgo2r.mongodb.net:27017',
   ]
 ];

I then modified src/MongoDBTest/MongoHelper.php to add the necessary ssl=true URI option (required for Atlas) and dump the result of a ping command immediately after Client construction. Diff as follows:

@@ -62,11 +62,12 @@ class MongoHelper
     }
 
     try {
-      $connStr = "mongodb://{$mongoDbAuth}{$host}/?{$replicaSet}";
+      $connStr = "mongodb://{$mongoDbAuth}{$host}/?ssl=true&{$replicaSet}";
       echo $connStr . "\r\n";
       $client                   = new Client($connStr);
       $this->contactsDb         = $client->{$this->database};
       $this->contactsCollection = $this->contactsDb->{$this->contactsCollectionName};
+      var_dump($client->admin->command(['ping' => 1])->toArray()[0]);
     } catch (Exception $e) {
       echo $e->getMessage();
       exit();

After modifying both files, I rebuilt the containers using docker-compose up --build. This also launched the mongo-db container, although it is not used in this example. I then opened a shell in the mongo-php-app container and ran index.php:

$ docker exec -it mongodb-php-test_mongo-php-app_1 bash
root@36c99abffa01:/var/www/mongodb-php-test# php index.php 
mongodb://<username>:<password>@ac-tkwmcmr-shard-00-00.07pgo2r.mongodb.net:27017,ac-tkwmcmr-shard-00-01.07pgo2r.mongodb.net:27017,ac-tkwmcmr-shard-00-02.07pgo2r.mongodb.net:27017/?ssl=true&replicaSet=atlas-r3glsi-shard-0
object(MongoDB\Model\BSONDocument)#17 (1) {
  ["storage":"ArrayObject":private]=>
  array(1) {
    ["ok"]=>
    int(1)
  }
}
Start...
Total time: 0.032139961s
root@36c99abffa01:/var/www/mongodb-php-test# 

The script had no trouble connecting to and pinging the Atlas M0 cluster.

[pavelsc]

@jmikola wow, thanks, that was unexpected. Seems I gotta check my cluster setup