I'm experiencing issue when trying to connect to my MongoDB server, which requires SSL/TLS, using the PHP mongodb extension:
PHP Fatal error: Uncaught MongoDB\Driver\Exception\ConnectionTimeoutException: No suitable servers found (`serverSelectionTryOnce` set): [Failed to receive length header from server. calling ismaster on 'mongodb.example.com:27017'] in /tmp/mongodb-test/vendor/mongodb/mongodb/src/Client.php:228
I've gone through tens of similar issues online and it seems that this is actually a generic error from the extension when there are connection problems. So far I've tried these common solutions but none of them worked for me:
- Use IPv4 address instead of host name (usually happens when MongoDB is running locally and
localhost, which is resolved to::1, when IPv6 is not enabled in MongoDB configuration). I've also tried putting the IPv4 address in my /etc/hosts, didn't help, either. setsebool -P httpd_can_network_connect on. Caused by SELinux, which I'm not using.- Set
net.ssl.allowConnectionsWithoutCertificatestofalse. It didn't seem to be relevant but I tested it nevertheless, didn't help.
I'm using a connection string and just to make things even more strange, the very same connection string works perfectly with mongo Shell, Compass and pymongo on the same machine, and also PHP 7.3 w/ mongodb 1.5.5 under macOS.
Here are some details:
I'm using PHP 7.3.7 with mongodb 1.5.5 under Arch Linux (I've also tested under Ubuntu, same symptom).
$ php --version
PHP 7.3.7 (cli) (built: Jul 3 2019 13:55:48) ( NTS )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.3.7, Copyright (c) 1998-2018 Zend Technologies
with Xdebug v2.7.2, Copyright (c) 2002-2019, by Derick Rethans
$ php -i | grep -i mongo
MongoDB support => enabled
MongoDB extension version => 1.5.5
MongoDB extension stability => stable
libmongoc bundled version => 1.13.0
libmongoc SSL => enabled
libmongoc SSL library => OpenSSL
libmongoc crypto => enabled
libmongoc crypto library => libcrypto
libmongoc crypto system profile => disabled
libmongoc SASL => enabled
libmongoc ICU => enabled
libmongoc compression => enabled
libmongoc compression snappy => enabled
libmongoc compression zlib => enabled
mongodb.debug => stderr => stderr
The server is MongoDB 4.0.10 and here's its /etc/mongodb.conf:
---
net:
bindIpAll: true
ipv6: true
ssl:
PEMKeyFile: /etc/ssl/mongodb.pem # Let's Encrypt certificate
mode: requireSSL
security:
authorization: "enabled"
storage:
dbPath: /var/lib/mongodb
systemLog:
destination: file
logAppend: true
path: /var/log/mongodb/mongod.log
quiet: false
When I ran the following script
require 'vendor/autoload.php';
// I've also tried copying the URI parameters to the second argument, didn't work
// allow_invalid_hostname and weak_cert_validation didn't help, either
$client = new MongoDB\Client(
'mongodb://frederick:password@mongodb.example.com/?ssl=true&authSource=admin'
);
var_dump( $client->listDatabases() );
...it failed with (full log here, it's too long and causes this post to exceed the length limit)
_mongoc_socket_capture_errno():68 setting errno: 11 Resource temporarily unavailable
[2019-07-07T11:14:36.047790+00:00] socket: TRACE > TRACE: _mongoc_socket_errno_is_again():620 errno is: 11
[2019-07-07T11:14:36.047795+00:00] socket: TRACE > ENTRY: _mongoc_socket_wait():148
[2019-07-07T11:14:36.047801+00:00] socket: TRACE > EXIT: _mongoc_socket_wait():243
[2019-07-07T11:14:36.047805+00:00] socket: TRACE > EXIT: mongoc_socket_recv():1088
[2019-07-07T11:14:36.047828+00:00] stream: TRACE > EXIT: _mongoc_stream_socket_readv():162
[2019-07-07T11:14:36.047834+00:00] stream: TRACE > TRACE: mongoc_stream_readv():239 readv = 0x7fff8fef5eb0 [1]
[2019-07-07T11:14:36.047842+00:00] stream: TRACE > 00000: 17 03 03 00 fa . . . . .
[2019-07-07T11:14:36.047847+00:00] stream: TRACE > EXIT: mongoc_stream_readv():242
[2019-07-07T11:14:36.047852+00:00] stream: TRACE > EXIT: mongoc_stream_read():283
[2019-07-07T11:14:36.047857+00:00] stream-tls-openssl-bio: TRACE > EXIT: mongoc_stream_tls_openssl_bio_read():230
[2019-07-07T11:14:36.047863+00:00] stream-tls-openssl: TRACE > EXIT: _mongoc_stream_tls_openssl_readv():463
[2019-07-07T11:14:36.047868+00:00] stream: TRACE > EXIT: mongoc_stream_readv():242
[2019-07-07T11:14:36.047873+00:00] stream: TRACE > EXIT: mongoc_stream_read():283
[2019-07-07T11:14:36.047878+00:00] buffer: TRACE > EXIT: _mongoc_buffer_try_append_from_stream():357
[2019-07-07T11:14:36.047884+00:00] stream: TRACE > ENTRY: mongoc_stream_failed():80
[2019-07-07T11:14:36.047892+00:00] stream-tls-openssl-bio: TRACE > ENTRY: mongoc_stream_tls_openssl_bio_write():257
[2019-07-07T11:14:36.047899+00:00] stream-tls-openssl-bio: TRACE > TRACE: mongoc_stream_tls_openssl_bio_write():274 mongoc_stream_writev is expected to write: 24
[2019-07-07T11:14:36.047904+00:00] stream: TRACE > ENTRY: mongoc_stream_writev():152
[2019-07-07T11:14:36.047910+00:00] stream: TRACE > TRACE: mongoc_stream_writev():164 writev = 0x7fff8fef5030 [1]
[2019-07-07T11:14:36.047920+00:00] stream: TRACE > 00000: 17 03 03 00 13 f5 ec f9 74 9e 90 99 01 e7 46 48 . . . . . . . . t . . . . . F H
[2019-07-07T11:14:36.047929+00:00] stream: TRACE > 00010: ... lots of data ...
[2019-07-07T11:14:36.047934+00:00] stream: TRACE > ENTRY: _mongoc_stream_socket_writev():203
[2019-07-07T11:14:36.047938+00:00] socket: TRACE > ENTRY: mongoc_socket_sendv():1360
[2019-07-07T11:14:36.047944+00:00] socket: TRACE > ENTRY: _mongoc_socket_try_sendv():1265
[2019-07-07T11:14:36.047948+00:00] socket: TRACE > TRACE: _mongoc_socket_try_sendv():1271 sendbuf = 0x56300c145e10 [1]
[2019-07-07T11:14:36.047958+00:00] socket: TRACE > 00000: 17 03 03 00 13 f5 ec f9 74 9e 90 99 01 e7 46 48 . . . . . . . . t . . . . . F H
[2019-07-07T11:14:36.047967+00:00] socket: TRACE > 00010: ... lots of data ...
[2019-07-07T11:14:36.047980+00:00] socket: TRACE > TRACE: _mongoc_socket_try_sendv():1291 Send 24 out of 24 bytes
[2019-07-07T11:14:36.047985+00:00] socket: TRACE > EXIT: _mongoc_socket_try_sendv():1321
[2019-07-07T11:14:36.047991+00:00] socket: TRACE > TRACE: mongoc_socket_sendv():1371 Sent 24 (of 24) out of iovcnt=1
[2019-07-07T11:14:36.047996+00:00] socket: TRACE > TRACE: mongoc_socket_sendv():1397 still got bytes left: sent -= iov_len: 24 -= 24
[2019-07-07T11:14:36.048000+00:00] socket: TRACE > TRACE: mongoc_socket_sendv():1408 Finished the iovecs
[2019-07-07T11:14:36.048005+00:00] socket: TRACE > EXIT: mongoc_socket_sendv():1443
[2019-07-07T11:14:36.048009+00:00] socket: TRACE > TRACE: mongoc_socket_errno():595 Current errno: 11
[2019-07-07T11:14:36.048014+00:00] stream: TRACE > EXIT: _mongoc_stream_socket_writev():209
[2019-07-07T11:14:36.048019+00:00] stream: TRACE > EXIT: mongoc_stream_writev():167
[2019-07-07T11:14:36.048024+00:00] stream-tls-openssl-bio: TRACE > TRACE: mongoc_stream_tls_openssl_bio_write():282 Completed the 24
[2019-07-07T11:14:36.048028+00:00] stream-tls-openssl-bio: TRACE > EXIT: mongoc_stream_tls_openssl_bio_write():293
[2019-07-07T11:14:36.048066+00:00] stream: TRACE > ENTRY: mongoc_stream_destroy():104
[2019-07-07T11:14:36.048070+00:00] stream: TRACE > ENTRY: _mongoc_stream_socket_destroy():72
[2019-07-07T11:14:36.048073+00:00] socket: TRACE > ENTRY: mongoc_socket_close():779
[2019-07-07T11:14:36.048088+00:00] socket: TRACE > EXIT: mongoc_socket_close():814
[2019-07-07T11:14:36.048092+00:00] stream: TRACE > EXIT: _mongoc_stream_socket_destroy():86
[2019-07-07T11:14:36.048095+00:00] stream: TRACE > EXIT: mongoc_stream_destroy():114
[2019-07-07T11:14:36.048557+00:00] stream: TRACE > EXIT: mongoc_stream_failed():90
[2019-07-07T11:14:36.048563+00:00] mongoc: TRACE > ENTRY: mongoc_server_description_handle_ismaster():513
[2019-07-07T11:14:36.048586+00:00] mongoc: TRACE > EXIT: mongoc_server_description_handle_ismaster():520
[2019-07-07T11:14:36.048592+00:00] mongoc: TRACE > TRACE: mongoc_topology_description_handle_ismaster():1953 No transition entry to Single for Unknown
[2019-07-07T11:14:36.048599+00:00] mongoc: TRACE > ENTRY: mongoc_topology_description_select():798
[2019-07-07T11:14:36.048602+00:00] mongoc: TRACE > TRACE: mongoc_topology_description_select():807 Topology type single, [mongodb.example.com:27017] is down
[2019-07-07T11:14:36.048605+00:00] mongoc: TRACE > EXIT: mongoc_topology_description_select():808
PHP Fatal error: Uncaught MongoDB\Driver\Exception\ConnectionTimeoutException: No suitable servers found (`serverSelectionTryOnce` set): [Failed to receive length header from server. calling ismaster on 'mongodb.example.com:27017'] in /tmp/mongodb-test/vendor/mongodb/mongodb/src/Client.php:228
Stack trace:
#0 /tmp/mongodb-test/vendor/mongodb/mongodb/src/Client.php(228): MongoDB\Driver\Manager->selectServer(Object(MongoDB\Driver\ReadPreference))
#1 /tmp/mongodb-test/test.php(9): MongoDB\Client->listDatabases()
#2 {main}
thrown in /tmp/mongodb-test/vendor/mongodb/mongodb/src/Client.php on line 228
[2019-07-07T11:14:36.048728+00:00] mongoc: DEBUG > Not destroying persistent client for Manager
And the logs from the server side are:
2019-07-07T19:58:54.571+1000 D COMMAND [conn1] run command admin.$cmd { isMaster: 1, client: { driver: { name: "mongoc / ext-mongodb:PHP", version: "1.13.0 / 1.5.5" }, os: { type: "Linux",
name: "Arch Linux", version: "rolling", architecture: "x86_64" }, platform: "cfg=0xd15ea8e9 posix=200809 stdc=201710 CC=GCC 9.1.0 CFLAGS="" LDFLAGS="" / PHP 7.3.7" }, compression: [], saslSu
pportedMechs: "admin.frederick", $readPreference: { mode: "secondaryPreferred" }, $db: "admin" }
2019-07-07T19:58:54.572+1000 I NETWORK [conn1] received client metadata from x.x.x.x:35394 conn1: { driver: { name: "mongoc / ext-mongodb:PHP", version: "1.13.0 / 1.5.5" }, os: { type:
"Linux", name: "Arch Linux", version: "rolling", architecture: "x86_64" }, platform: "cfg=0xd15ea8e9 posix=200809 stdc=201710 CC=GCC 9.1.0 CFLAGS="" LDFLAGS="" / PHP 7.3.7" }
2019-07-07T19:58:54.572+1000 D NETWORK [conn1] Starting server-side compression negotiation
2019-07-07T19:58:54.572+1000 D NETWORK [conn1] No compressors provided
2019-07-07T19:58:54.572+1000 D STORAGE [conn1] NamespaceUUIDCache: registered namespace admin.system.users with UUID 4bb34abc-a662-424b-9c52-bf3947bb6006
2019-07-07T19:58:54.573+1000 D QUERY [conn1] Beginning planning...
=============================
Options = INDEX_INTERSECTION SPLIT_LIMITED_SORT CANNOT_TRIM_IXISECT
Canonical query:
ns=admin.system.usersTree: $and
db $eq "admin"
user $eq "frederick"
Sort: {}
Proj: {}
=============================
2019-07-07T19:58:54.573+1000 D QUERY [conn1] Index 0 is kp: { _id: 1 } unique name: '_id_' io: { v: 2, key: { _id: 1 }, name: "_id_", ns: "admin.system.users" }
2019-07-07T19:58:54.573+1000 D QUERY [conn1] Index 1 is kp: { user: 1, db: 1 } unique name: 'user_1_db_1' io: { v: 2, unique: true, key: { user: 1, db: 1 }, name: "user_1_db_1", ns: "admi
n.system.users" }
2019-07-07T19:58:54.573+1000 D QUERY [conn1] Predicate over field 'user'
2019-07-07T19:58:54.573+1000 D QUERY [conn1] Predicate over field 'db'
2019-07-07T19:58:54.573+1000 D QUERY [conn1] Relevant index 0 is kp: { user: 1, db: 1 } unique name: 'user_1_db_1' io: { v: 2, unique: true, key: { user: 1, db: 1 }, name: "user_1_db_1",
ns: "admin.system.users" }
2019-07-07T19:58:54.574+1000 D QUERY [conn1] Rated tree:
$and
db $eq "admin" || First: notFirst: 0 full path: db
user $eq "frederick" || First: 0 notFirst: full path: user
2019-07-07T19:58:54.574+1000 D QUERY [conn1] Tagging memoID 1
2019-07-07T19:58:54.574+1000 D QUERY [conn1] Enumerator: memo just before moving:
[Node #1]: AND enumstate counter 0
choice 0:
subnodes:
idx[0]
pos 0 pred user $eq "frederick"
pos 1 pred db $eq "admin"
2019-07-07T19:58:54.574+1000 D QUERY [conn1] About to build solntree from tagged tree:
$and
db $eq "admin" || Selected Index #0 pos 1 combine 1
user $eq "frederick" || Selected Index #0 pos 0 combine 1
2019-07-07T19:58:54.574+1000 D QUERY [conn1] Planner: adding solution:
FETCH
---fetched = 1
---sortedByDiskLoc = 1
---getSort = [{ db: 1 }, { user: 1 }, { user: 1, db: 1 }, ]
---Child:
------IXSCAN
---------indexName = user_1_db_1
keyPattern = { user: 1, db: 1 }
---------direction = 1
---------bounds = field #0['user']: ["frederick", "frederick"], field #1['db']: ["admin", "admin"]
---------fetched = 0
---------sortedByDiskLoc = 1
---------getSort = [{ db: 1 }, { user: 1 }, { user: 1, db: 1 }, ]
2019-07-07T19:58:54.574+1000 D QUERY [conn1] Planner: outputted 1 indexed solutions.
2019-07-07T19:58:54.574+1000 D QUERY [conn1] Only one plan is available; it will be run but will not be cached. query: { user: "frederick", db: "admin" } sort: {} projection: {}, planSummary: IXSCAN { user: 1, db: 1 }
2019-07-07T19:58:54.574+1000 D STORAGE [conn1] WT begin_transaction for snapshot id 23
2019-07-07T19:58:54.575+1000 D STORAGE [conn1] WT rollback_transaction for snapshot id 23
2019-07-07T19:58:54.576+1000 I COMMAND [conn1] command admin.system.users command: isMaster { isMaster: 1, client: { driver: { name: "mongoc / ext-mongodb:PHP", version: "1.13.0 / 1.5.5" }, os: { type: "Linux", name: "Arch Linux", version: "rolling", architecture: "x86_64" }, platform: "cfg=0xd15ea8e9 posix=200809 stdc=201710 CC=GCC 9.1.0 CFLAGS="" LDFLAGS="" / PHP 7.3.7" }, compression: [], saslSupportedMechs: "admin.frederick", $readPreference: { mode: "secondaryPreferred" }, $db: "admin" } numYields:0 reslen:304 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } storage:{ data: { bytesRead: 114, timeReadingMicros: 10 } } protocol:op_query 4ms
2019-07-07T19:58:54.576+1000 D NETWORK [conn1] Session from x.x.x.x:35394 encountered a network error during SourceMessage: HostUnreachable: Connection closed by peer
2019-07-07T19:58:54.576+1000 D NETWORK [conn1] Cancelling outstanding I/O operations on connection to x.x.x.x:35394
So it seems that it managed to connect to the server but somehow failed with errno: 11 Resource temporarily unavailable. And if I disable SSL/TLS, the issue immediately goes away without requiring any further changes.
I feel really clueless now so please shed some light on me... Thanks.
