mongo-php-driver: Intermittent error: MongoConnectionException:No suitable servers found (`serverselectiontryonce` set): [Server closed connection. calling ismaster on 'x.x.x.x:27017']'
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:
- Converted all hostnames to ip addresses in connection strings (https://github.com/mongodb/mongo-php-driver/issues/133)
- Set default connectTimeoutMS and socketTimeoutMS to 20000ms (https://github.com/mongodb/mongo-php-driver/issues/374)
- Set default ‘w’ to 1, and wTimeoutMS to 20000ms (https://groups.google.com/forum/#!msg/mongodb-dev/zlzvXo6pOcI/1y5KcEZ-IwAJ)
- Backed out to 1.1.9 (https://github.com/mongodb/mongo-php-driver/issues/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
About this issue
- Original URL
- State: closed
- Created 7 years ago
- Comments: 31 (12 by maintainers)
Reading through older posts in this thread, I imagine this might have been due to CDRIVER-2075 being included in PHP driver 1.3.0, which was released in September 2017 (after the last activity on this thread). That added logic in libmongoc to retry failed
isMastercommands exactly once, which allows for recovering from a dropped connection despite the MongoDB server still being available.Either way, thanks for confirming that the previous error is resolved on your end.
It looks like this issue is resolved with latest versions of:
@narcoticfresh: If you look through the MongoDB PHP library source, you’ll see that it frequently calls
MongoDB\Driver\Manager::selectServer()to select a single server before executing an operation. If you have not configured a custom read preference, we use “primary” by default (which works just fine for a standalone topology). The role of read preferences in server selection is explained thoroughly in our Server Selection specification.That said, the library’s server selection is largely an implementation detail. We need a
MongoDB\Driver\Serverobject to extract version information to construct our commands according to server-side API differences (seeMongoDB\Operation\ListIndexes::execute()for one example). We then want to ensure that the command is executed on the very same server whose information we considered, so we rely on theMongoDB\Driver\Server::executeBulkWrite(),executeCommand(), andexecuteQuery()methods instead of those found onMongoDB\Driver\Manager.If you were using the driver directly and called
executeBulkWrite(),executeCommand(), orexecuteQuery()on theMongoDB\Driver\Managerobject, server selection would still happen internally and potentially throw the same “No suitable servers found” exception.To clarify, “No suitable servers found” is the general exception that server selection failed. This could happen for any number of reasons: selecting a secondary when none exist; applying read preference tags that do not match any servers; loss of connectivity to previously available servers. When reporting a server selection error, libmongoc aggregates any internal errors in its message, which we use for our exception message. The relevant error in your case is what follows “No suitable servers found”: “Server closed connection. calling ismaster on mongodb.myhost.internal:27017.” That hints towards a connectivity issue and may be the result of HAProxy terminating connections.
As I mentioned above in my replies to @sandrokeil,
serverSelectionTryOnce=falsemay help by allowing the driver to make repeated attempts to find a server up to a configurable timeout (default is 30 seconds). This comes at the expense of potentially delaying your application’s response times if no server is available, which is why it is disabled by default. The current fail-fast behavior is also similar to how the legacy driver performed.I elaborate on
serverSelectionTryOnce=falsea bit more in https://github.com/mongodb/mongo-php-driver/issues/564#issuecomment-288427486 if you’d like to read that for additional context.This agrees with what I shared in the middle of my second-to-last post. Adding
serverSelectionTryOnce=falseto the URI only suppresses the “No suitable servers found” errors, as it allows to driver up to 30 seconds to select a server. If no suitable servers are found during that selection window, the driver will more actively monitor the known servers according tominHeartbeatFrequencyMS, which is 500ms. I realize the spec doesn’t refer to single-threaded implementations in that section, although libmongoc does follow the same logic for PHP. I’ve opened SPEC-866 to request that the spec be updated to note the applications to single-threaded implementations.The “insert” and “find” failures due to “socket error or timeout” were expected, as the driver is realizing that the connection was closed at the time it’s trying to use it for an operation. It is the application’s responsibility to catch that exception and decide if it should retry it. The “not master” exception was also expected since the node reporting that error was last known to be a primary when server selection took place. The driver does not realize that it’s ineligible to handle a write until that error comes across.
As mentioned in the opening paragraphs of my previous post, reducing
heartbeatFrequencyMSis really the only way to reduce the frequency of these errors (at the cost of increased monitoring overhead). Earlier, I was able to guarantee error-free operations by using a 10-second monitoring interval and trusting that queries were issued no sooner than 15 seconds (which I reduced from 60 seconds) after the last topology change (i.e. shutting down and restarting a node). That assumption is obviously is not practical for a live application when requests can come at any time, so even a reduced monitoring interval could have windows of time where the driver is prone to unexpected topology changes and throw an exception.That looks like a fine result from the
replSetGetStatuscommand. Based on the documentation example, “could not find member to sync from” appears to be an expected “infoMessage” value for a primary server. FWIW, that seems like a redundant message, since primaries do not sync by definition.@sandrokeil: I spoke with @ajdavis about the “not master” error and it does appear to be within spec. To elaborate, the situation entails a primary restarting between the driver’s heartbeat intervals. At the time the driver selects a server for the insert, the topology state still believes that node0 is the primary. This is part to the fact that node0 was abruptly terminated, so its previous error would have been a socket timeout. In such cases, SDAM removes the sockets but leaves the node’s state as-is, per Network error when reading or writing:
Getting back to the situation, node0 is selected for the insert. The driver no longer has a connection to this node and must create a new one, which is followed by an
isMastercommand (like all new connections). In this response, node0 identifies itself as a secondary and points to node2 as the new primary. Despite this new information and ensuing topology update (i.e. “Transitioning to RSWithPrimary for RSSecondary” in the trace above), node0 remains the selected node for this operation and we predictably get a “not master” error.Per SPEC-863, the SDAM spec purposefully does not suggest retrying server selection in this case in order to limit complexity. Only a primary server’s
isMasterresponse is authoritative, so doing so would also require immediate monitoring updates from other nodes in the cluster (node2 in this case). If there were multiple elections or network interruptions in this period, we could see the process chain several times. By not retrying and sticking to the topology state at the time the operation was invoked, we can fail fast and allow the application to proceed as it likes. In this case, a “not master” error can be immediately retried since there is no risk that the write partially succeeded.I opened SPEC-863 to request that the SDAM spec clarify why server selection is not retried. Additionally, I mentioned in the last paragraph that “only a primary server’s
isMasterresponse is authoritative”, yet we clearly saw libmongoc update the topology state based on node0’sisMasterresponse after we reconnected and it identified itself as a secondary. This is an outstanding question for the spec, which I’ve asked in SPEC-864. In this particular case, we know that node0 has good information, so trusting itsisMasterresponse actually helps us by providing current topology info for the subsequent driver operations; however, I would like to confirm whether this is acceptable.With all of that said, I don’t believe we have any driver bugs present here. If SPEC-864 results in a change to the SDAM spec, there will be ensuing driver tickets created, which will result in possible changes to libmongoc. I realize our SPEC project is private in JIRA, but I’ve referenced this GitHub issue in those tickets and will try to follow up here if there is significant activity on those tickets.
@sandrokeil: When running your Docker environment as-is, I did not see any errors in the FPM logs. This may be because the
start.shscript sleeps 60 seconds after stopping and restarting a node, which allows the driver adequate time to pick up on any changes. I’ll note thatheartbeatFrequencyMSdefaults 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:
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.
At this point I decided to make a single adjustment and reduce the
heartbeatFrequencyMSvalue for both clients created inpublic/index.php($clientPrimaryPreferredand$clientSecondaryPreferred). I left the script’s sleep time at 15 seconds but reducedheartbeatFrequencyMSto 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
heartbeatFrequencyMSchange and instead addedserverSelectionTryOnce=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.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:
The server
node0.mongodb.local:27017is 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 anisMastercommand to that node. TheisMasterresult reports thatnode0is actually a secondary and thatnode2is the primary; however, the write is still issued tonode0and we see a “not master” error. I suspected that this may be due to the PHP library selecting a server inCollection::insertOne()before we actually construct and execute theInsertOneoperation 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.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.