Intermittent error: MongoConnectionException:No suitable servers found (`serverselectiontryonce` set): [Server closed connection. calling ismaster on 'x.x.x.x:27017']'

[mmucklo]

Description

Intermittent errors observed with mongo-php-driver.

First tried 1.2.5, but have reverted down to 1.1.9.

1.2.5 had more frequent errors (almost multiple per minute) whereas 1.1.9 is a few per hour or so.

Adjusted the following things:

1. Converted all hostnames to ip addresses in connection strings (No suitable servers found #133)
2. Set default connectTimeoutMS and socketTimeoutMS to 20000ms
   (No suitable servers found (serverselectiontryonce set): [connection error calling ismaster on '114.225.125.126:27017'] #374)
3. Set default 'w' to 1, and wTimeoutMS to 20000ms
   (https://groups.google.com/forum/#!msg/mongodb-dev/zlzvXo6pOcI/1y5KcEZ-IwAJ)
4. Backed out to 1.1.9
   (No suitable servers found (serverselectiontryonce set): [connection error calling ismaster on 'xxx.xxx.xxx.xxx:xxxx'] #425)

Environment

PHP 7.0.15 on CentOS 7.3.1611 x86_64

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

mongodb
mongodb support => enabled
mongodb version => 1.1.9
mongodb stability => stable
libmongoc version => 1.3.6
libbson version => 1.3.6
mongodb.debug => no value => no value

[jmikola]

Can you share how you are constructing the MongoDB\Driver\Manager object? If you are using SSL with 1.1.8, 1.1.9, or 1.1.10, connection persistence is disabled per PHPC-720. That may be masking the exception seen more frequently in 1.2.5, since the driver would be connecting on each request.

Do you have evidence of the closed connections in the server logs? If there is an intermediary between the PHP driver and the server (e.g. AWS ELB, some firewall), that might also be suspect.

If we are diagnosing the issue further, I would insist on investigating the behavior in 1.2.5. We have no plans to maintain 1.1.x beyond necessary security fixes.

[mmucklo]

No ssl, haproxy.

I will try hitting a machine directly to see if it's haproxy closing the connections or starving things in some way...

[mmucklo]

Some good news - removing haproxy has stabilized things on 1.1.9 at least. Thanks for the reply and the pointers!

I'd like to try 1.2.5, however.

I'll get back to you if I get that chance...

[sandrokeil]

Just had the same issue. I use a MongoDB 3.4 cluster of 3 nodes on AWS. I had to recreate every node to launch a new configuration. The cluster is healthy. I use domain names for the connection string, because the IP address of each node has changed or can change. I guess there is a DNS caching issue, but at the moment, I'm not sure if this is a PHP or common server config problem.

• MongoDB PHP ext. 1.2.4
• MongoDB PHP library 1.1.1

[mmucklo]

Update on 1.2.5 - swapped in 1.2.5 while pointing to a single host, and things still appear stable, so I'm thinking that haproxy in the midst is not a good idea (unless it's really configured correctly).

I have a follow on question - for failover purposes, should multiple hosts be added to the connection string and let the driver detect which host(s) are up (will it detect a down host and move on to the next)?

Secondly does that information persist between requests or does it have to re-detect a failed host every request (potentially slowing down the request waiting for a timeout, for example)?

[derickr]

I have a follow on question - for failover purposes, should multiple hosts be added to the connection string and let the driver detect which host(s) are up (will it detect a down host and move on to the next)?

You should add a majority of the host names to the connection string. The names in the string should match the exact names (or IP addresses) as configured in the replica set configuration. Relying on haproxy to route queries is very much not going to work well - leave it to the driver to do this as they've been engineered with MongoDB in mind. It will correctly detect down hosts and according to whether it's a read or write, reroute to the new primary.

Secondly does that information persist between requests or does it have to re-detect a failed host every request (potentially slowing down the request waiting for a timeout, for example)?

In the 1.2 series, the cluster topology is maintained, and it does not have to re-detect a failed host on every request.

[sandrokeil]

In the 1.2 series, the cluster topology is maintained, and it does not have to re-detect a failed host on every request.

@derickr What does this mean exactly if I use domain names in the connection string (mongodb://mongodb01.local:27017,mongodb02.local:27017,mongodb03.local:27017?replicaSet=cluster&connectTimeoutMS=2000&readPreference=primaryPreferred) and the IP address will change? I use Route53 on AWS to update the IP of the mongo node doman name e.g. mongodb01.local.

[derickr]

If your connection string has mongodb01.local:27017,mongodb02.local:27017,mongodb03.local:27017, then mongodb01.local, mongodb02.local and mongodb03.local should be what shows up in rs.status() output.

The driver will connect to all of them, and poll on a regular basis (as is documented through SDAM (sorry, that's a long read)).

When a node fails (i.e., when it gets a new IP) then the driver will notice the connection being gone, and tries to reconnect after doing the DNS lookup. But the driver does not rescan which hosts are part of the replicaset on each PHP Request automatically. Only when SDAM stipulates this is necessary.

The scenario from your latest message should just work™.

[sandrokeil]

@derickr Thank you for your answer. I read the document and I guess the problem is Retry ismaster calls once.

PHP setup (Docker Alpine)

• PHP-FPM 7.1.1 with Opcache
  • pm = static
  • pm.max_children = 30
• MongoDB PHP ext. 1.2.4
• MongoDB PHP library 1.1.1

How to reproduce

1. Create a MongoDB 4.3.1 replication cluster of three nodes
2. Terminate a secondary node and create a new one and wait until cluster is healthy
3. Do step 2 for the other secondary node
4. Do step 2 with the primary node

PHP Exception message

This could happen if the primary is down and a secondary node is not a primary at this time. So no primary exists for a short period.

No suitable servers found (`serverSelectionTryOnce` set): [Server closed connection. calling ismaster on 'node0.mongodb.local:27017'] [Server closed connection. calling ismaster on 'node1.mongodb.local:27017'] [Server closed connection. calling ismaster on 'node2.mongodb.local:27017']

Some information

The cluster was healthy all the time and has negotiated a new primary if necessary. I see that the PHP connection was established to a node.

I NETWORK [conn25] received client metadata from [IP]:53778 conn25: { driver: { name: "mongoc / ext-mongodb:PHP", version: "1.5.4 / 1.2.4" }, os: { type: "Linux", name: "Alpine Linux", version: "3.4.6", architecture: "x86_64" }, platform: "cfg=0x30c9 posix=200809 stdc=201112 CC=GCC 5.3.0 CFLAGS="-g -O2" LDFLAGS="" / PHP 7.1.1" }

Some requests have returned a valid response with data and some requests are failed with the exception above. This happened during a timeframe of 45 minutes, so it has nothing to do with a configuration timeout of the connection itself. I have a huge MongoDB log (verbosity: 5) but I don't know what I'm looking for.

Assumption

Is it possible, that some PHP-FPM children processes saves the wrong connection pool info and don't refresh them? The IPs of the nodes has changed, but the cluster is healthy and some requests are valid and the PHP-FPM children are never respawn in this config (pm.static).

[jmikola]

In the 1.2 series, the cluster topology is maintained, and it does not have to re-detect a failed host on every request.

@sandrokeil: @derickr's previous response was alluding to the connection persistence behavior in 1.2.0+. His comment that "the driver does not rescan which hosts are part of the replicaset on each PHP Request automatically" applies to 1.2.0+; however, previous versions of the driver only persisted sockets instead of the topology state, which meant that the driver had to issue isMaster commands for each PHP request to re-discover the topology.

I read the document and I guess the problem is Retry ismaster calls once.

The paragraph you cited refers to monitoring connections, so I believe it may only be referring to multi-threaded implementations of SDAM with a background monitoring thread. PHP uses the single-threaded model, where sockets are shared for monitoring and application usage. That said, I'm not sure if it applies to our single-threaded model. I reached out to @ajdavis to confirm, but am still awaiting a reply.

PHP Exception message

Am I correct in assuming that the "No suitable servers found" exception you shared is after restarting all nodes in the replica set per your "How to reproduce" steps? The order of events (restarting nodes, PHP exceptions, and PHP connections in the server logs) is not clear to me, but if the single-threaded SDAM implementation does not retry isMaster commands, then I would expect those connection errors as the existing sockets would have been closed when each node was restarted.

Some requests have returned a valid response with data and some requests are failed with the exception above.

Given a pool of FPM worker processes, are some processes never reporting "No suitable servers found" exceptions at all? Is the script always selecting a primary server, or do some queries use other read preferences?

If the driver realized that a connection was closed (e.g. graceful TCP shutdown), it could reconnect during the subsequent monitoring round and thus avoid an exception. Reconnection would also happen after an exception is thrown and the cooldown period has elapsed.

This happened during a timeframe of 45 minutes, so it has nothing to do with a configuration timeout of the connection itself. I have a huge MongoDB log (verbosity: 5) but I don't know what I'm looking for.

I believe the server should log driver connections by default (verbosity level 0). I'm not sure why you would need verbosity level five, as that's going to pollute your logs with messages from internal server threads.

---

For reference, the "Server closed connection" error messages originate in mongoc-async-cmd.c, which is used by the SDAM implementation, and are emitted when libmongoc expected to read data from a socket but zero bytes were available (in contrast to a read error with a negative return value, which would be reported as "Failed to receive...").

[sandrokeil]

@jmikola @derickr I've created a repository which reproduces this issue. You only need Docker 🐳 . Please read the README.md. It contains further information and where you will find the logs of a test run and to see the issue.

I hope this helps to solve this issue. Let me know if I can do anything else.

[Lokomojo]

I'm also experiencing this issue with a newly upgraded cluster. Let me know if I can provide any information to help.

[jmikola]

Regarding Retry ismaster calls once, @ajdavis confirmed that libmongoc currently does not do that for either multi- or single-threaded SDAM implementations. He opened CDRIVER-2075 to track the missing functionality.

I'll look into the Docker environment you shared and follow up in a bit.

[narcoticfresh]

@jmikola any news on this?
we are also experiencing this error using a single server in our connection string, like mongodb://mongodb.myhost.internal:27017

[jmikola]

@sandrokeil: When running your Docker environment as-is, I did not see any errors in the FPM logs. This may be because the start.sh script sleeps 60 seconds after stopping and restarting a node, which allows the driver adequate time to pick up on any changes. I'll note that heartbeatFrequencyMS defaults to 60 seconds in single-threaded SDAM implementations. This determines the frequency of scans during which the topology can be updated before server selection occurs.

For reference, here are my abridged FPM logs running your Docker environment as-is:

Attaching to mongodbreplicaconnectionissue_php_1
php_1       | [16-Mar-2017 20:46:59] NOTICE: fpm is running, pid 1
php_1       | [16-Mar-2017 20:46:59] NOTICE: ready to handle connections
php_1       | 172.18.0.3 -  16/Mar/2017:20:47:27 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:47:27 +0000 "GET /index.php" 200
...

I'm cut out lines after the first pair of requests, but there were no exceptions to report.

I then tweaked your script to only sleep 15 seconds after each node was stopped and restarted and was able to produce some exceptions. Note that the HTTP requests are still successful (i.e. 200 instead of 500) since the exceptions are caught and logged. Since your FPM configuration uses a pool of only two workers and the HTTP requests are dispatched concurrently, most of these exceptions showed up in pairs. The errors do not always appear in the same series of requests (there are sometimes error-free requests between them), although we do see them in both workers over the course of the entire test run.

php_1       | [16-Mar-2017 20:57:52] WARNING: [pool www] child 7 said into stderr: "Failed to send "find" command with database "testing": socket error or timeout"
php_1       | [16-Mar-2017 20:57:52] WARNING: [pool www] child 8 said into stderr: "Failed to send "find" command with database "testing": socket error or timeout"
php_1       | 172.18.0.3 -  16/Mar/2017:20:57:52 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:58:09 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:58:09 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:58:09 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:58:09 +0000 "GET /index.php" 200
php_1       | [16-Mar-2017 20:58:27] WARNING: [pool www] child 7 said into stderr: "Failed to send "insert" command with database "testing": socket error or timeout"
php_1       | 172.18.0.3 -  16/Mar/2017:20:58:27 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:58:27 +0000 "GET /index.php" 200
php_1       | [16-Mar-2017 20:58:27] WARNING: [pool www] child 8 said into stderr: "Failed to send "insert" command with database "testing": socket error or timeout"
php_1       | [16-Mar-2017 20:58:44] WARNING: [pool www] child 8 said into stderr: "No suitable servers found (`serverSelectionTryOnce` set): [Server closed connection. calling ismaster on 'node0.mongodb.local:27017'] [Server closed connection. calling ismaster on 'node1.mongodb.local:27017'] [connection closed calling ismaster on 'node2.mongodb.local:27017']"
php_1       | 172.18.0.3 -  16/Mar/2017:20:58:44 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:58:44 +0000 "GET /index.php" 200
php_1       | [16-Mar-2017 20:58:44] WARNING: [pool www] child 7 said into stderr: "No suitable servers found (`serverSelectionTryOnce` set): [Server closed connection. calling ismaster on 'node0.mongodb.local:27017'] [Server closed connection. calling ismaster on 'node1.mongodb.local:27017'] [connection closed calling ismaster on 'node2.mongodb.local:27017']"
php_1       | [16-Mar-2017 20:58:44] WARNING: [pool www] child 8 said into stderr: "No suitable servers found (`serverSelectionTryOnce` set): [Server closed connection. calling ismaster on 'node0.mongodb.local:27017'] [Server closed connection. calling ismaster on 'node1.mongodb.local:27017'] [connection closed calling ismaster on 'node2.mongodb.local:27017']"
php_1       | 172.18.0.3 -  16/Mar/2017:20:58:44 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:58:44 +0000 "GET /index.php" 200
php_1       | [16-Mar-2017 20:58:44] WARNING: [pool www] child 7 said into stderr: "No suitable servers found (`serverSelectionTryOnce` set): [Server closed connection. calling ismaster on 'node0.mongodb.local:27017'] [Server closed connection. calling ismaster on 'node1.mongodb.local:27017'] [connection closed calling ismaster on 'node2.mongodb.local:27017']"
php_1       | 172.18.0.3 -  16/Mar/2017:20:59:01 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:59:01 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:59:18 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:59:18 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:59:20 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:59:20 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:59:20 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:59:20 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:59:20 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:20:59:20 +0000 "GET /index.php" 200

At this point I decided to make a single adjustment and reduce the heartbeatFrequencyMS value for both clients created in public/index.php ($clientPrimaryPreferred and $clientSecondaryPreferred). I left the script's sleep time at 15 seconds but reduced heartbeatFrequencyMS to 10 seconds to ensure that clients will update their topologies between node changes and web requests. As expected, the FPM logs for this run showed no exceptions at all.

Lastly, I reverted the heartbeatFrequencyMS change and instead added serverSelectionTryOnce=false. Per the server selection spec, this changes the default behavior for single-threaded drivers to continue polling if the first selection attempt fails until a timeout (30 seconds by default) is reached. Running the test again did produce some exceptions in the FPM logs, but "No suitable servers found" were absent as to be expected.

php_1       | 172.18.0.3 -  16/Mar/2017:22:01:37 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:01:37 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:01:43 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:01:43 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:00 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:00 +0000 "GET /index.php" 200
php_1       | [16-Mar-2017 22:02:16] WARNING: [pool www] child 7 said into stderr: "Failed to send "find" command with database "testing": socket error or timeout"
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:16 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:16 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:16 +0000 "GET /index.php" 200
php_1       | [16-Mar-2017 22:02:16] WARNING: [pool www] child 8 said into stderr: "Failed to send "find" command with database "testing": socket error or timeout"
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:16 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:33 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:33 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:50 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:50 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:50 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:02:50 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:03:08 +0000 "GET /index.php" 200
php_1       | [16-Mar-2017 22:03:08] WARNING: [pool www] child 7 said into stderr: "Failed to send "insert" command with database "testing": socket error or timeout"
php_1       | [16-Mar-2017 22:03:08] WARNING: [pool www] child 8 said into stderr: "Failed to send "insert" command with database "testing": socket error or timeout"
php_1       | 172.18.0.3 -  16/Mar/2017:22:03:08 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:03:25 +0000 "GET /index.php" 200
php_1       | [16-Mar-2017 22:03:25] WARNING: [pool www] child 7 said into stderr: "not master"
php_1       | [16-Mar-2017 22:03:25] WARNING: [pool www] child 8 said into stderr: "not master"
php_1       | 172.18.0.3 -  16/Mar/2017:22:03:25 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:03:26 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:03:26 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:03:26 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:03:26 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:03:26 +0000 "GET /index.php" 200
php_1       | 172.18.0.3 -  16/Mar/2017:22:03:26 +0000 "GET /index.php" 200

The first two errors we see here are due to the driver attempting to read or write on a terminated socket. Since the test script kills the nodes abruptly, this error is not unexpected. We might see the same thing for any network interruption. The third "not master" error is the result of the driver not realizing that a secondary server is no longer a primary. By tracing the request I obtained the following log:

     mongoc: TRACE   > ENTRY: mongoc_topology_description_select():747"
     mongoc: TRACE   > TRACE: mongoc_topology_description_select():782 Topology type [ReplicaSetWithPrimary], selected [RSPrimary] [node0.mongodb.local:27017]"
     mongoc: TRACE   >  EXIT: mongoc_topology_description_select():785"
     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():497"
     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():624"
     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():153"
     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():159"
 PHONGO-BSON: TRACE   > Added new _id"
     mongoc: TRACE   > ENTRY: mongoc_bulk_operation_insert():290"
     mongoc: TRACE   > ENTRY: _mongoc_write_command_init_insert():192"
     mongoc: TRACE   > ENTRY: _mongoc_write_command_insert_append():82"
     mongoc: TRACE   >  EXIT: _mongoc_write_command_insert_append():112"
     mongoc: TRACE   >  EXIT: _mongoc_write_command_init_insert():208"
     mongoc: TRACE   >  EXIT: mongoc_bulk_operation_insert():312"
     mongoc: TRACE   > ENTRY: mongoc_bulk_operation_execute():598"
     mongoc: TRACE   > ENTRY: _mongoc_write_result_init():1464"
     mongoc: TRACE   >  EXIT: _mongoc_write_result_init():1474"
    cluster: TRACE   > ENTRY: mongoc_cluster_stream_for_server():1565"
    cluster: TRACE   > ENTRY: _mongoc_cluster_stream_for_server():1501"
 topology_scanner: TRACE   > ENTRY: mongoc_topology_scanner_node_connect_tcp():427"
     socket: TRACE   > ENTRY: mongoc_socket_new():727"
     socket: TRACE   > ENTRY: _mongoc_socket_setnodelay():271"
     socket: TRACE   >  EXIT: _mongoc_socket_setnodelay():283"
     socket: TRACE   >  EXIT: mongoc_socket_new():751"
     socket: TRACE   > ENTRY: mongoc_socket_connect():590"
     socket: TRACE   > TRACE: _mongoc_socket_capture_errno():336 setting errno: 115"
     socket: TRACE   > TRACE: _mongoc_socket_errno_is_again():360 errno is: 115"
     socket: TRACE   > ENTRY: _mongoc_socket_wait():113"
     socket: TRACE   >  EXIT: _mongoc_socket_wait():154"
     socket: TRACE   >  EXIT: mongoc_socket_connect():615"
     stream: TRACE   > ENTRY: mongoc_stream_wait():416"
     stream: TRACE   > ENTRY: _mongoc_stream_socket_poll():226"
     socket: TRACE   > ENTRY: mongoc_socket_poll():217"
     stream: TRACE   >  EXIT: _mongoc_stream_socket_poll():252"
     stream: TRACE   >  EXIT: mongoc_stream_wait():438"
    cluster: TRACE   > ENTRY: _mongoc_stream_run_ismaster():433"
    cluster: TRACE   > ENTRY: mongoc_cluster_run_command_internal():170"
     stream: TRACE   > ENTRY: _mongoc_stream_writev_full():490"
     stream: TRACE   > ENTRY: mongoc_stream_writev():149"
     stream: TRACE   > TRACE: mongoc_stream_writev():161 writev = 0x561dc49bb840 [9]"
     stream: TRACE   > 00000:  3a 00 00 00 06 00 00 00  00 00 00 00 d4 07 00 00  : . . . . . . .  . . . . . . . ."
     stream: TRACE   > 00010:  04 00 00 00 61 64 6d 69  6e 2e 24 63 6d 64 00 00  . . . . a d m i  n . $ c m d . ."
     stream: TRACE   > 00020:  00 00 00 ff ff ff ff 13  00 00 00 10 69 73 6d 61  . . . . . . . .  . . . . i s m a"
     stream: TRACE   > 00030:  73 74 65 72 00 01 00 00  00 00                    s t e r . . . .  . ."
     stream: TRACE   > ENTRY: _mongoc_stream_socket_writev():202"
     socket: TRACE   > ENTRY: mongoc_socket_sendv():1089"
     socket: TRACE   > ENTRY: _mongoc_socket_try_sendv():998"
     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1004 sendbuf = 0x561dc49bb960 [9]"
     socket: TRACE   > 00000:  3a 00 00 00 06 00 00 00  00 00 00 00 d4 07 00 00  : . . . . . . .  . . . . . . . ."
     socket: TRACE   > 00010:  04 00 00 00 61 64 6d 69  6e 2e 24 63 6d 64 00 00  . . . . a d m i  n . $ c m d . ."
     socket: TRACE   > 00020:  00 00 00 ff ff ff ff 13  00 00 00 10 69 73 6d 61  . . . . . . . .  . . . . i s m a"
     socket: TRACE   > 00030:  73 74 65 72 00 01 00 00  00 00                    s t e r . . . .  . ."
     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1020 Send 58 out of 4 bytes"
     socket: TRACE   >  EXIT: _mongoc_socket_try_sendv():1050"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1100 Sent 58 (of 4) out of iovcnt=9"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 58 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 54 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 50 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 46 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 42 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 38 -= 11"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 27 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 23 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 19 -= 19"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1134 Finished the iovecs"
     socket: TRACE   >  EXIT: mongoc_socket_sendv():1165"
     socket: TRACE   > TRACE: mongoc_socket_errno():307 Current errno: 115"
     stream: TRACE   >  EXIT: _mongoc_stream_socket_writev():208"
     stream: TRACE   >  EXIT: mongoc_stream_writev():164"
     stream: TRACE   > TRACE: _mongoc_stream_writev_full():497 writev returned: 58"
     stream: TRACE   >  EXIT: _mongoc_stream_writev_full():521"
     stream: TRACE   > ENTRY: mongoc_stream_read():268"
     stream: TRACE   > ENTRY: mongoc_stream_readv():226"
     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139"
     socket: TRACE   > ENTRY: mongoc_socket_recv():797"
     socket: TRACE   > TRACE: _mongoc_socket_capture_errno():336 setting errno: 11"
     socket: TRACE   > TRACE: _mongoc_socket_errno_is_again():360 errno is: 11"
     socket: TRACE   > ENTRY: _mongoc_socket_wait():113"
     socket: TRACE   >  EXIT: _mongoc_socket_wait():154"
     socket: TRACE   >  GOTO: mongoc_socket_recv():816 again"
     socket: TRACE   >  EXIT: mongoc_socket_recv():826"
     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():188"
     stream: TRACE   > TRACE: mongoc_stream_readv():236 readv = 0x7fff8f7fd1c0 [1]"
     stream: TRACE   > 00000:  01 02 00 00 3b 00 00 00  06 00 00 00 01 00 00 00  . . . . ; . . .  . . . . . . . ."
     stream: TRACE   > 00010:  08 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . ."
     stream: TRACE   > 00020:  01 00 00 00                                       . . . ."
     stream: TRACE   >  EXIT: mongoc_stream_readv():239"
     stream: TRACE   >  EXIT: mongoc_stream_read():280"
     stream: TRACE   > ENTRY: mongoc_stream_read():268"
     stream: TRACE   > ENTRY: mongoc_stream_readv():226"
     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139"
     socket: TRACE   > ENTRY: mongoc_socket_recv():797"
     socket: TRACE   >  EXIT: mongoc_socket_recv():826"
     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():188"
     stream: TRACE   > TRACE: mongoc_stream_readv():236 readv = 0x7fff8f7fd1c0 [1]"
     stream: TRACE   > 00000:  dd 01 00 00 04 68 6f 73  74 73 00 68 00 00 00 02  . . . . . h o s  t s . h . . . ."
     stream: TRACE   > 00010:  30 00 1a 00 00 00 6e 6f  64 65 30 2e 6d 6f 6e 67  0 . . . . . n o  d e 0 . m o n g"
     stream: TRACE   > 00020:  6f 64 62 2e 6c 6f 63 61  6c 3a 32 37 30 31 37 00  o d b . l o c a  l : 2 7 0 1 7 ."
     stream: TRACE   > 00030:  02 31 00 1a 00 00 00 6e  6f 64 65 31 2e 6d 6f 6e  . 1 . . . . . n  o d e 1 . m o n"
     stream: TRACE   > 00040:  67 6f 64 62 2e 6c 6f 63  61 6c 3a 32 37 30 31 37  g o d b . l o c  a l : 2 7 0 1 7"
     stream: TRACE   > 00050:  00 02 32 00 1a 00 00 00  6e 6f 64 65 32 2e 6d 6f  . . 2 . . . . .  n o d e 2 . m o"
     stream: TRACE   > 00060:  6e 67 6f 64 62 2e 6c 6f  63 61 6c 3a 32 37 30 31  n g o d b . l o  c a l : 2 7 0 1"
     stream: TRACE   > 00070:  37 00 00 02 73 65 74 4e  61 6d 65 00 08 00 00 00  7 . . . s e t N  a m e . . . . ."
     stream: TRACE   > 00080:  63 6c 75 73 74 65 72 00  10 73 65 74 56 65 72 73  c l u s t e r .  . s e t V e r s"
     stream: TRACE   > 00090:  69 6f 6e 00 01 00 00 00  08 69 73 6d 61 73 74 65  i o n . . . . .  . i s m a s t e"
     stream: TRACE   > 000a0:  72 00 00 08 73 65 63 6f  6e 64 61 72 79 00 01 02  r . . . s e c o  n d a r y . . ."
     stream: TRACE   > 000b0:  70 72 69 6d 61 72 79 00  1a 00 00 00 6e 6f 64 65  p r i m a r y .  . . . . n o d e"
     stream: TRACE   > 000c0:  32 2e 6d 6f 6e 67 6f 64  62 2e 6c 6f 63 61 6c 3a  2 . m o n g o d  b . l o c a l :"
     stream: TRACE   > 000d0:  32 37 30 31 37 00 02 6d  65 00 1a 00 00 00 6e 6f  2 7 0 1 7 . . m  e . . . . . n o"
     stream: TRACE   > 000e0:  64 65 30 2e 6d 6f 6e 67  6f 64 62 2e 6c 6f 63 61  d e 0 . m o n g  o d b . l o c a"
     stream: TRACE   > 000f0:  6c 3a 32 37 30 31 37 00  03 6c 61 73 74 57 72 69  l : 2 7 0 1 7 .  . l a s t W r i"
     stream: TRACE   > 00100:  74 65 00 40 00 00 00 03  6f 70 54 69 6d 65 00 1c  t e . @ . . . .  o p T i m e . ."
     stream: TRACE   > 00110:  00 00 00 11 74 73 00 01  00 00 00 6f 42 cb 58 12  . . . . t s . .  . . . o B . X ."
     stream: TRACE   > 00120:  74 00 02 00 00 00 00 00  00 00 00 09 6c 61 73 74  t . . . . . . .  . . . . l a s t"
     stream: TRACE   > 00130:  57 72 69 74 65 44 61 74  65 00 98 81 fb d9 5a 01  W r i t e D a t  e . . . . . Z ."
     stream: TRACE   > 00140:  00 00 00 10 6d 61 78 42  73 6f 6e 4f 62 6a 65 63  . . . . m a x B  s o n O b j e c"
     stream: TRACE   > 00150:  74 53 69 7a 65 00 00 00  00 01 10 6d 61 78 4d 65  t S i z e . . .  . . . m a x M e"
     stream: TRACE   > 00160:  73 73 61 67 65 53 69 7a  65 42 79 74 65 73 00 00  s s a g e S i z  e B y t e s . ."
     stream: TRACE   > 00170:  6c dc 02 10 6d 61 78 57  72 69 74 65 42 61 74 63  l . . . m a x W  r i t e B a t c"
     stream: TRACE   > 00180:  68 53 69 7a 65 00 e8 03  00 00 09 6c 6f 63 61 6c  h S i z e . . .  . . . l o c a l"
     stream: TRACE   > 00190:  54 69 6d 65 00 8b 94 fb  d9 5a 01 00 00 10 6d 61  T i m e . . . .  . Z . . . . m a"
     stream: TRACE   > 001a0:  78 57 69 72 65 56 65 72  73 69 6f 6e 00 05 00 00  x W i r e V e r  s i o n . . . ."
     stream: TRACE   > 001b0:  00 10 6d 69 6e 57 69 72  65 56 65 72 73 69 6f 6e  . . m i n W i r  e V e r s i o n"
     stream: TRACE   > 001c0:  00 00 00 00 00 08 72 65  61 64 4f 6e 6c 79 00 00  . . . . . . r e  a d O n l y . ."
     stream: TRACE   > 001d0:  01 6f 6b 00 00 00 00 00  00 00 f0 3f 00           . o k . . . . .  . . . ? ."
     stream: TRACE   >  EXIT: mongoc_stream_readv():239"
     stream: TRACE   >  EXIT: mongoc_stream_read():280"
     mongoc: TRACE   > ENTRY: _mongoc_populate_cmd_error():767"
     mongoc: TRACE   >  EXIT: _mongoc_populate_cmd_error():773"
    cluster: TRACE   >  EXIT: mongoc_cluster_run_command_internal():330"
     mongoc: TRACE   > ENTRY: mongoc_server_description_init():94"
     mongoc: TRACE   >  EXIT: mongoc_server_description_init():131"
     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():497"
     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():624"
     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():497"
     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():624"
     mongoc: TRACE   > TRACE: mongoc_topology_description_handle_ismaster():1726 Transitioning to RSWithPrimary for RSSecondary"
    cluster: TRACE   >  EXIT: _mongoc_stream_run_ismaster():464"
    cluster: TRACE   >  EXIT: _mongoc_cluster_stream_for_server():1533"
    cluster: TRACE   >  EXIT: mongoc_cluster_stream_for_server():1578"
     mongoc: TRACE   > ENTRY: _mongoc_write_command_execute():1395"
     mongoc: TRACE   > ENTRY: _mongoc_write_command():1233"
     mongoc: TRACE   > ENTRY: _mongoc_write_command_init():271"
     mongoc: TRACE   >  EXIT: _mongoc_write_command_init():290"
    cluster: TRACE   > ENTRY: mongoc_cluster_run_command_internal():170"
     stream: TRACE   > ENTRY: _mongoc_stream_writev_full():490"
     stream: TRACE   > ENTRY: mongoc_stream_writev():149"
     stream: TRACE   > TRACE: mongoc_stream_writev():161 writev = 0x561dc49bba60 [9]"
     stream: TRACE   > 00000:  a3 00 00 00 07 00 00 00  00 00 00 00 d4 07 00 00  . . . . . . . .  . . . . . . . ."
     stream: TRACE   > 00010:  00 00 00 00 74 65 73 74  69 6e 67 2e 24 63 6d 64  . . . . t e s t  i n g . $ c m d"
     stream: TRACE   > 00020:  00 00 00 00 00 ff ff ff  ff 7a 00 00 00 02 69 6e  . . . . . . . .  . z . . . . i n"
     stream: TRACE   > 00030:  73 65 72 74 00 0b 00 00  00 77 72 69 74 65 5f 74  s e r t . . . .  . w r i t e _ t"
     stream: TRACE   > 00040:  65 73 74 00 03 77 72 69  74 65 43 6f 6e 63 65 72  e s t . . w r i  t e C o n c e r"
     stream: TRACE   > 00050:  6e 00 05 00 00 00 00 08  6f 72 64 65 72 65 64 00  n . . . . . . .  o r d e r e d ."
     stream: TRACE   > 00060:  01 04 64 6f 63 75 6d 65  6e 74 73 00 36 00 00 00  . . d o c u m e  n t s . 6 . . ."
     stream: TRACE   > 00070:  03 30 00 2e 00 00 00 02  74 65 78 74 00 0e 00 00  . 0 . . . . . .  t e x t . . . ."
     stream: TRACE   > 00080:  00 35 38 63 62 34 32 37  33 63 66 62 37 30 00 07  . 5 8 c b 4 2 7  3 c f b 7 0 . ."
     stream: TRACE   > 00090:  5f 69 64 00 58 cb 42 73  6e 07 1d 00 08 52 33 98  _ i d . X . B s  n . . . . R 3 ."
     stream: TRACE   > 000a0:  00 00 00                                          . . ."
     stream: TRACE   > ENTRY: _mongoc_stream_socket_writev():202"
     socket: TRACE   > ENTRY: mongoc_socket_sendv():1089"
     socket: TRACE   > ENTRY: _mongoc_socket_try_sendv():998"
     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1004 sendbuf = 0x561dc49ba960 [9]"
     socket: TRACE   > 00000:  a3 00 00 00 07 00 00 00  00 00 00 00 d4 07 00 00  . . . . . . . .  . . . . . . . ."
     socket: TRACE   > 00010:  00 00 00 00 74 65 73 74  69 6e 67 2e 24 63 6d 64  . . . . t e s t  i n g . $ c m d"
     socket: TRACE   > 00020:  00 00 00 00 00 ff ff ff  ff 7a 00 00 00 02 69 6e  . . . . . . . .  . z . . . . i n"
     socket: TRACE   > 00030:  73 65 72 74 00 0b 00 00  00 77 72 69 74 65 5f 74  s e r t . . . .  . w r i t e _ t"
     socket: TRACE   > 00040:  65 73 74 00 03 77 72 69  74 65 43 6f 6e 63 65 72  e s t . . w r i  t e C o n c e r"
     socket: TRACE   > 00050:  6e 00 05 00 00 00 00 08  6f 72 64 65 72 65 64 00  n . . . . . . .  o r d e r e d ."
     socket: TRACE   > 00060:  01 04 64 6f 63 75 6d 65  6e 74 73 00 36 00 00 00  . . d o c u m e  n t s . 6 . . ."
     socket: TRACE   > 00070:  03 30 00 2e 00 00 00 02  74 65 78 74 00 0e 00 00  . 0 . . . . . .  t e x t . . . ."
     socket: TRACE   > 00080:  00 35 38 63 62 34 32 37  33 63 66 62 37 30 00 07  . 5 8 c b 4 2 7  3 c f b 7 0 . ."
     socket: TRACE   > 00090:  5f 69 64 00 58 cb 42 73  6e 07 1d 00 08 52 33 98  _ i d . X . B s  n . . . . R 3 ."
     socket: TRACE   > 000a0:  00 00 00                                          . . ."
     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1020 Send 163 out of 4 bytes"
     socket: TRACE   >  EXIT: _mongoc_socket_try_sendv():1050"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1100 Sent 163 (of 4) out of iovcnt=9"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 163 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 159 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 155 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 151 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 147 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 143 -= 13"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 130 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 126 -= 4"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 122 -= 122"
     socket: TRACE   > TRACE: mongoc_socket_sendv():1134 Finished the iovecs"
     socket: TRACE   >  EXIT: mongoc_socket_sendv():1165"
     socket: TRACE   > TRACE: mongoc_socket_errno():307 Current errno: 0"
     stream: TRACE   >  EXIT: _mongoc_stream_socket_writev():208"
     stream: TRACE   >  EXIT: mongoc_stream_writev():164"
     stream: TRACE   > TRACE: _mongoc_stream_writev_full():497 writev returned: 163"
     stream: TRACE   >  EXIT: _mongoc_stream_writev_full():521"
     stream: TRACE   > ENTRY: mongoc_stream_read():268"
     stream: TRACE   > ENTRY: mongoc_stream_readv():226"
     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139"
     socket: TRACE   > ENTRY: mongoc_socket_recv():797"
     socket: TRACE   >  EXIT: mongoc_socket_recv():826"
     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():188"
     stream: TRACE   > TRACE: mongoc_stream_readv():236 readv = 0x7fff8f7fd400 [1]"
     stream: TRACE   > 00000:  6e 00 00 00 3c 00 00 00  07 00 00 00 01 00 00 00  n . . . < . . .  . . . . . . . ."
     stream: TRACE   > 00010:  08 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . ."
     stream: TRACE   > 00020:  01 00 00 00                                       . . . ."
     stream: TRACE   >  EXIT: mongoc_stream_readv():239"
     stream: TRACE   >  EXIT: mongoc_stream_read():280"
     stream: TRACE   > ENTRY: mongoc_stream_read():268"
     stream: TRACE   > ENTRY: mongoc_stream_readv():226"
     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139"
     socket: TRACE   > ENTRY: mongoc_socket_recv():797"
     socket: TRACE   >  EXIT: mongoc_socket_recv():826"
     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():188"
     stream: TRACE   > TRACE: mongoc_stream_readv():236 readv = 0x7fff8f7fd400 [1]"
     stream: TRACE   > 00000:  4a 00 00 00 01 6f 6b 00  00 00 00 00 00 00 00 00  J . . . . o k .  . . . . . . . ."
     stream: TRACE   > 00010:  02 65 72 72 6d 73 67 00  0b 00 00 00 6e 6f 74 20  . e r r m s g .  . . . . n o t  "
     stream: TRACE   > 00020:  6d 61 73 74 65 72 00 10  63 6f 64 65 00 7b 27 00  m a s t e r . .  c o d e . { ' ."
     stream: TRACE   > 00030:  00 02 63 6f 64 65 4e 61  6d 65 00 0a 00 00 00 4e  . . c o d e N a  m e . . . . . N"
     stream: TRACE   > 00040:  6f 74 4d 61 73 74 65 72  00 00                    o t M a s t e r  . ."
     stream: TRACE   >  EXIT: mongoc_stream_readv():239"
     stream: TRACE   >  EXIT: mongoc_stream_read():280"
     mongoc: TRACE   > ENTRY: _mongoc_populate_cmd_error():767"
     mongoc: TRACE   >  EXIT: _mongoc_populate_cmd_error():795"
    cluster: TRACE   >  GOTO: mongoc_cluster_run_command_internal():282 done"
    cluster: TRACE   >  EXIT: mongoc_cluster_run_command_internal():330"
     mongoc: TRACE   > ENTRY: _mongoc_write_result_merge():1767"
     mongoc: TRACE   >  EXIT: _mongoc_write_result_merge():1876"
     mongoc: TRACE   >  EXIT: _mongoc_write_command():1381"
     mongoc: TRACE   >  EXIT: _mongoc_write_command_execute():1444"
     mongoc: TRACE   >  GOTO: mongoc_bulk_operation_execute():672 cleanup"
     mongoc: TRACE   > ENTRY: _mongoc_write_result_complete():1961"
     mongoc: TRACE   >  EXIT: _mongoc_write_result_complete():2010"
     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():153"
     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():159"
     mongoc: TRACE   >  EXIT: mongoc_bulk_operation_execute():687"
child 8 said into stderr: "not master"
     mongoc: TRACE   > ENTRY: _mongoc_write_command_destroy():1451"
     mongoc: TRACE   >  EXIT: _mongoc_write_command_destroy():1457"
     mongoc: TRACE   > ENTRY: _mongoc_write_result_destroy():1481"
     mongoc: TRACE   >  EXIT: _mongoc_write_result_destroy():1489"
     mongoc: DEBUG   > Not destroying persistent client for Manager"
     mongoc: DEBUG   > Not destroying persistent client for Manager"

The server node0.mongodb.local:27017 is selected as a primary according to the current topology state, but the driver has no existing connection to the server. After creating a new connection, the driver issues an isMaster command to that node. The isMaster result reports that node0 is actually a secondary and that node2 is the primary; however, the write is still issued to node0 and we see a "not master" error. I suspected that this may be due to the PHP library selecting a server in Collection::insertOne() before we actually construct and execute the InsertOne operation class, but bypassing the library and using the driver directly produced the same result. I will follow up with the libmongoc folks to share the trace logs and determine whether "not master" is expected behavior in this scenario.