DRIVERS-2884: CSOT avoid connection churn when operations timeout

Author: sanych-sun

source/client-side-operations-timeout/tests/pending-response.yml

@@ -122,8 +122,6 @@ tests:
         events:
           - commandFailedEvent:
               commandName: insert
-              # No second failed event since we timed out attempting to check out
-              # the connection for the second operation.
           - commandSucceededEvent:
               commandName: find
       - client: *client

source/connection-monitoring-and-pooling/tests/README.md

@@ -32,8 +32,8 @@ non-auth, and non-compression connections.
 
 #### Recover Partial Header Response
 
-This test verifies that if only part of a response header arrives before a socket timeout, the driver can drain the rest
-of the response and reuse the connection for the next operation.
+This test verifies that if only part of a response header arrives before a timeout, the driver can drain the rest of the
+response and reuse the connection for the next operation.
 
 1. Connect to the proxy server with `maxPoolSize=1` and `direct=true`, subscribing to the following CMAP events:
     - `PendingResponseStarted`
@@ -44,12 +44,14 @@ of the response and reuse the connection for the next operation.
     - `sendBytes`: any value between 1 and 3
     - `delayMS`: 400 ( to exceed the 200 ms timeout)
     - `sendAll`: `true`
-3. Issue any follow-up operation and assert that it does not return an error.
-4. Verify that we've received the following events from the `insertOne` step:
-    - 1x`ConnectionPendingResponseStarted`
-    - 0x`ConnectionPendingResponseFailed`
-    - 1x`ConnectionPendingResponseSucceeded`
-    - 0x`ConnectionClosed`
+3. Assert that the operation failed with timeout error.
+4. Issue another operation (e.g. another insert) and assert that it does not return an error.
+5. Verify that the following sequence of events was observed:
+    - `ConnectionPendingResponseStarted`
+    - `ConnectionPendingResponseSucceeded`
+6. Verify that NONE the following events was observed:
+    - `ConnectionPendingResponseFailed`
+    - `ConnectionClosed`
 
 #### Recover Partial Body Response
 
@@ -65,16 +67,18 @@ of the response and reuse the connection for the next operation.
     - `sendBytes`: Any value > 16
     - `delayMS`: 400 ( to exceed the 200 ms timeout)
     - `sendAll`: `true`
-3. Issue any follow-up operation and assert that it does not return an error.
-4. Verify that we've received the following events from the `insertOne` step:
-    - 1x`ConnectionPendingResponseStarted`
-    - 0x`ConnectionPendingResponseFailed`
-    - 1x`ConnectionPendingResponseSucceeded`
-    - 0x`ConnectionClosed`
+3. Assert that the operation failed with timeout error.
+4. Issue another operation (e.g. another insert) and assert that it does not return an error.
+5. Verify that the following sequence of events was observed:
+    - `ConnectionPendingResponseStarted`
+    - `ConnectionPendingResponseSucceeded`
+6. Verify that NONE the following events was observed:
+    - `ConnectionPendingResponseFailed`
+    - `ConnectionClosed`
 
 #### Non-destructive Aliveness Check
 
-This test verifies that if a connection idles past the driver's aliveness window (3 seconds) after a partial header, the
+This test verifies that if a connection idles past the pending response window (3 seconds) after a partial header, the
 aliveness check does not attempt to discard bytes from the TCP stream.
 
 1. Connect to the proxy server with `maxPoolSize=1` and `direct=true`, subscribing to the following CMAP events:
@@ -86,13 +90,16 @@ aliveness check does not attempt to discard bytes from the TCP stream.
     - `sendBytes`: any value between 1 and 3
     - `delayMS`: 400 ( to exceed the 200 ms timeout)
     - `sendAll`: `true`
-3. Sleep for 3 seconds
-4. Issue any follow-up operation and assert that it does not return an error.
-5. Verify that we've received the following events from the `insertOne` step:
-    - 2x`ConnectionPendingResponseStarted`
-    - 1x`ConnectionPendingResponseFailed`
-    - 1x`ConnectionPendingResponseSucceeded`
-    - 0x`ConnectionClosed`
+3. Assert that the operation failed with timeout error.
+4. Sleep for 3 seconds
+5. Issue another operation (e.g. another insert) and assert that it does not return an error.
+6. Verify that the following sequence of events was observed:
+    - `ConnectionPendingResponseStarted`
+    - `ConnectionPendingResponseFailed`
+    - `ConnectionPendingResponseStarted`
+    - `ConnectionPendingResponseSucceeded`
+7. Verify that NONE the following events was observed:
+    - `ConnectionClosed`
 
 #### Exhaust Cursors
 

source/connection-monitoring-and-pooling/tests/logging/connection-logging-csot.json

@@ -22,6 +22,7 @@ tests:
                 uriOptions:
                   retryReads: false
                   appname: &clientAppName clientAppName
+                  maxPoolSize: 1
                   # use a high heartbeatFrequencyMS to avoid a successful monitor check marking the pool as
                   # ready (and emitting another event) during the course of test execution.
                   heartbeatFrequencyMS: 10000
@@ -55,7 +56,7 @@ tests:
             data:
               failCommands: ["insert"]
               blockConnection: true
-              blockTimeMS: 200
+              blockTimeMS: 300
 
       # Execute operation with timeout less than block time
       - name: insertOne
@@ -68,11 +69,11 @@ tests:
 
       # Execute a subsequent operation which should time out during the 
       # pending response read attempt.
-      - name: findOne
+      - name: find
         object: *collection
         arguments:
           filter: { _id: 1 }
-          timeoutMS: 100
+          timeoutMS: 75
         expectError:
           isTimeoutError: true
 
@@ -81,10 +82,10 @@ tests:
       # operation.
         object: testRunner
         arguments:
-          ms: 75
+          ms: 200
 
       # Execute a subsequent operation which should completed the pending read.
-      - name: findOne
+      - name: find
         object: *collection
         arguments:
           filter: { _id: 1 }
@@ -201,6 +202,13 @@ tests:
               requestId: { $$type: [int, long] }
               reason: "timeout"
 
+          - level: debug
+            component: connection
+            data:
+              message: "Connection checkout failed"
+              serverHost: { $$type: string }
+              serverPort: { $$type: [ int, long ] }
+
           # Second Find 
           - level: debug
             component: connection