diff --git a/source/client-side-operations-timeout/tests/pending-response.json b/source/client-side-operations-timeout/tests/pending-response.json new file mode 100644 index 0000000000..05c1e8b53c --- /dev/null +++ b/source/client-side-operations-timeout/tests/pending-response.json @@ -0,0 +1,390 @@ +{ + "description": "Connection churn is prevented by reading pending responses during connection checkout", + "schemaVersion": "1.24", + "runOnRequirements": [ + { + "minServerVersion": "4.4", + "topologies": [ + "single", + "replicaset" + ] + } + ], + "createEntities": [ + { + "client": { + "id": "failPointClient", + "useMultipleMongoses": false + } + }, + { + "client": { + "id": "client", + "uriOptions": { + "maxPoolSize": 1 + }, + "useMultipleMongoses": false, + "observeEvents": [ + "commandFailedEvent", + "commandSucceededEvent", + "connectionCheckedOutEvent", + "connectionCheckedInEvent", + "connectionClosedEvent", + "connectionPendingResponseSucceeded", + "connectionPendingResponseStarted", + "connectionPendingResponseFailed" + ] + } + }, + { + "database": { + "id": "test", + "client": "client", + "databaseName": "test" + } + }, + { + "collection": { + "id": "coll", + "database": "test", + "collectionName": "coll" + } + } + ], + "initialData": [ + { + "collectionName": "coll", + "databaseName": "test", + "documents": [] + } + ], + "tests": [ + { + "description": "non-timeout op with response and no error", + "operations": [ + { + "name": "runCommand", + "object": "test", + "arguments": { + "command": { + "ping": 1 + } + } + }, + { + "name": "failPoint", + "object": "testRunner", + "arguments": { + "client": "failPointClient", + "failPoint": { + "configureFailPoint": "failCommand", + "mode": { + "times": 1 + }, + "data": { + "failCommands": [ + "insert" + ], + "blockConnection": true, + "blockTimeMS": 100 + } + } + } + }, + { + "name": "insertOne", + "object": "coll", + "arguments": { + "timeoutMS": 75, + "document": { + "_id": 3, + "x": 1 + } + }, + "expectError": { + "isTimeoutError": true + } + }, + { + "name": "findOne", + "object": "coll", + "arguments": { + "filter": { + "_id": 1 + } + } + } + ], + "expectEvents": [ + { + "client": "client", + "events": [ + { + "commandSucceededEvent": { + "commandName": "ping" + } + }, + { + "commandFailedEvent": { + "commandName": "insert" + } + }, + { + "commandSucceededEvent": { + "commandName": "find" + } + } + ] + }, + { + "client": "client", + "eventType": "cmap", + "events": [ + { + "connectionCheckedOutEvent": {} + }, + { + "connectionCheckedInEvent": {} + }, + { + "connectionCheckedOutEvent": {} + }, + { + "connectionCheckedInEvent": {} + }, + { + "connectionPendingResponseStarted": {} + }, + { + "connectionPendingResponseSucceeded": {} + }, + { + "connectionCheckedOutEvent": {} + }, + { + "connectionCheckedInEvent": {} + } + ] + } + ] + }, + { + "description": "non-timeout op with no response", + "operations": [ + { + "name": "runCommand", + "object": "test", + "arguments": { + "command": { + "ping": 1 + } + } + }, + { + "name": "failPoint", + "object": "testRunner", + "arguments": { + "client": "failPointClient", + "failPoint": { + "configureFailPoint": "failCommand", + "mode": { + "times": 1 + }, + "data": { + "failCommands": [ + "insert" + ], + "blockConnection": true, + "blockTimeMS": 3100 + } + } + } + }, + { + "name": "insertOne", + "object": "coll", + "arguments": { + "timeoutMS": 50, + "document": { + "_id": 3, + "x": 1 + } + }, + "expectError": { + "isTimeoutError": true + } + }, + { + "name": "findOne", + "object": "coll", + "arguments": { + "filter": { + "_id": 1 + } + }, + "expectError": { + "isTimeoutError": true + } + } + ], + "expectEvents": [ + { + "client": "client", + "events": [ + { + "commandSucceededEvent": { + "commandName": "ping" + } + }, + { + "commandFailedEvent": { + "commandName": "insert" + } + } + ] + }, + { + "client": "client", + "eventType": "cmap", + "events": [ + { + "connectionCheckedOutEvent": {} + }, + { + "connectionCheckedInEvent": {} + }, + { + "connectionCheckedOutEvent": {} + }, + { + "connectionCheckedInEvent": {} + }, + { + "connectionPendingResponseStarted": {} + }, + { + "connectionPendingResponseFailed": { + "reason": "timeout" + } + }, + { + "connectionClosedEvent": { + "reason": "error" + } + } + ] + } + ] + }, + { + "description": "timeout op with response and no error", + "operations": [ + { + "name": "runCommand", + "object": "test", + "arguments": { + "command": { + "ping": 1 + } + } + }, + { + "name": "failPoint", + "object": "testRunner", + "arguments": { + "client": "failPointClient", + "failPoint": { + "configureFailPoint": "failCommand", + "mode": { + "times": 1 + }, + "data": { + "failCommands": [ + "insert" + ], + "blockConnection": true, + "blockTimeMS": 250 + } + } + } + }, + { + "name": "insertOne", + "object": "coll", + "arguments": { + "timeoutMS": 75, + "document": { + "_id": 3, + "x": 1 + } + }, + "expectError": { + "isTimeoutError": true + } + }, + { + "name": "findOne", + "object": "coll", + "arguments": { + "timeoutMS": 200, + "filter": { + "_id": 1 + } + } + } + ], + "expectEvents": [ + { + "client": "client", + "events": [ + { + "commandSucceededEvent": { + "commandName": "ping" + } + }, + { + "commandFailedEvent": { + "commandName": "insert" + } + }, + { + "commandSucceededEvent": { + "commandName": "find" + } + } + ] + }, + { + "client": "client", + "eventType": "cmap", + "events": [ + { + "connectionCheckedOutEvent": {} + }, + { + "connectionCheckedInEvent": {} + }, + { + "connectionCheckedOutEvent": {} + }, + { + "connectionCheckedInEvent": {} + }, + { + "connectionPendingResponseStarted": {} + }, + { + "connectionPendingResponseSucceeded": {} + }, + { + "connectionCheckedOutEvent": {} + }, + { + "connectionCheckedInEvent": {} + } + ] + } + ] + } + ] +} diff --git a/source/client-side-operations-timeout/tests/pending-response.yml b/source/client-side-operations-timeout/tests/pending-response.yml new file mode 100644 index 0000000000..931436d5a0 --- /dev/null +++ b/source/client-side-operations-timeout/tests/pending-response.yml @@ -0,0 +1,211 @@ +description: "Connection churn is prevented by reading pending responses during connection checkout" +schemaVersion: "1.24" +runOnRequirements: + - minServerVersion: "4.4" + # TODO(SERVER-96344): When using failpoints, mongos returns MaxTimeMSExpired + # after maxTimeMS, whereas mongod returns it after + # max(blockTimeMS, maxTimeMS). Until this ticket is resolved, these tests + # will not pass on sharded clusters. + topologies: ["single", "replicaset"] +createEntities: + - client: + id: &failPointClient failPointClient + useMultipleMongoses: false + - client: + id: &client client + uriOptions: + maxPoolSize: 1 + useMultipleMongoses: false + observeEvents: + - commandFailedEvent + - commandSucceededEvent + - connectionCheckedOutEvent + - connectionCheckedInEvent + - connectionClosedEvent + - connectionPendingResponseSucceeded + - connectionPendingResponseStarted + - connectionPendingResponseFailed + - database: + id: &database test + client: *client + databaseName: *database + - collection: + id: &collection coll + database: *database + collectionName: *collection +initialData: + - collectionName: *collection + databaseName: *database + documents: [] +tests: + # Attempting a pending response read on a non-timeout operation that can + # immediately read from the TCP buffer should complete the pending read and + # the connection should be checked out. + - description: "non-timeout op with response and no error" + operations: + # Run a ping command to pre-load the pool with a connection. + - name: runCommand + object: *database + arguments: + command: + ping: 1 + # Create a failpoint to block the first operation. + - name: failPoint + object: testRunner + arguments: + client: *failPointClient + failPoint: + configureFailPoint: failCommand + mode: {times: 1} + data: + failCommands: ["insert"] + blockConnection: true + blockTimeMS: 100 + # Execute operation with timeout less than block time. + - name: insertOne + object: *collection + arguments: + timeoutMS: 75 + document: {_id: 3, x: 1} + expectError: + isTimeoutError: true + # Execute a subsequent operation to complete the read. + - name: findOne + object: *collection + arguments: + filter: {_id: 1} + expectEvents: + - client: *client + events: + - commandSucceededEvent: + commandName: ping # Pre-loading the connection pool. + - commandFailedEvent: + commandName: insert + - commandSucceededEvent: + commandName: find + - client: *client + eventType: cmap + events: + - connectionCheckedOutEvent: {} + - connectionCheckedInEvent: {} # Ping finishes. + - connectionCheckedOutEvent: {} + - connectionCheckedInEvent: {} # Insert fails. + - connectionPendingResponseStarted: {} + - connectionPendingResponseSucceeded: {} # Find operation drains connection. + - connectionCheckedOutEvent: {} + - connectionCheckedInEvent: {} # Find succeeds. + # Attempting a pending response read on a non-timeout operation that gets no + # response from the server after 3s should close the connection. + - description: "non-timeout op with no response" + operations: + # Run a ping command to pre-load the pool with a connection. + - name: runCommand + object: *database + arguments: + command: + ping: 1 + # Create a failpoint to block the first operation. + - name: failPoint + object: testRunner + arguments: + client: *failPointClient + failPoint: + configureFailPoint: failCommand + mode: {times: 1} + data: + failCommands: ["insert"] + blockConnection: true + blockTimeMS: 3100 + # Execute operation with timeout less than block time. + - name: insertOne + object: *collection + arguments: + timeoutMS: 50 + document: {_id: 3, x: 1} + expectError: + isTimeoutError: true + # Execute a subsequent operation to complete the read. + - name: findOne + object: *collection + arguments: + filter: {_id: 1} + expectError: + isTimeoutError: true + expectEvents: + - client: *client + events: + - commandSucceededEvent: + commandName: ping # Pre-loading the connection pool. + - commandFailedEvent: + commandName: insert + # No second failed event since we timed out attempting to check out + # the connection for the second operation. + - client: *client + eventType: cmap + events: + - connectionCheckedOutEvent: {} + - connectionCheckedInEvent: {} # Ping finishes. + - connectionCheckedOutEvent: {} + - connectionCheckedInEvent: {} # Insert fails. + - connectionPendingResponseStarted: {} + - connectionPendingResponseFailed: + reason: timeout + - connectionClosedEvent: + reason: error + # Attempting a pending response read on a realistic timeout operation that can + # immediately read from the TCP buffer should complete the pending read and + # the connection should be checked out. + - description: "timeout op with response and no error" + operations: + # Run a ping command to pre-load the pool with a connection. + - name: runCommand + object: *database + arguments: + command: + ping: 1 + # Create a failpoint to block the first operation. + - name: failPoint + object: testRunner + arguments: + client: *failPointClient + failPoint: + configureFailPoint: failCommand + mode: {times: 1} + data: + failCommands: ["insert"] + blockConnection: true + blockTimeMS: 250 + # Execute operation with timeout less than block time. + - name: insertOne + object: *collection + arguments: + timeoutMS: 75 + document: {_id: 3, x: 1} + expectError: + isTimeoutError: true + # Execute a subsequent operation to complete the read. + - name: findOne + object: *collection + arguments: + timeoutMS: 200 + filter: {_id: 1} + expectEvents: + - client: *client + events: + - commandSucceededEvent: + commandName: ping # Pre-loading the connection pool. + - commandFailedEvent: + commandName: insert + - commandSucceededEvent: + commandName: find + - client: *client + eventType: cmap + events: + - connectionCheckedOutEvent: {} + - connectionCheckedInEvent: {} # Ping finishes. + - connectionCheckedOutEvent: {} + - connectionCheckedInEvent: {} # Insert fails. + - connectionPendingResponseStarted: {} + - connectionPendingResponseSucceeded: {} + - connectionCheckedOutEvent: {} + - connectionCheckedInEvent: {} # Find succeeds. diff --git a/source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.md b/source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.md index b6e5ebc81b..f4487f1e2a 100644 --- a/source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.md +++ b/source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.md @@ -576,7 +576,106 @@ other threads from checking out [Connections](#connection) while establishing a Before a given [Connection](#connection) is returned from checkOut, it must be marked as "in use", and the pool's availableConnectionCount MUST be decremented. -```text +If an operation times out the socket while awaiting a server response and CSOT is enabled and `maxTimeMS` was added to +the command, the driver MUST mark the connection as "pending" and record the current time in a way that can be updated. +The next time the connection is checked out, the driver MUST attempt to read and discard the remaining response from the +socket. The workflow for this is as follows: + +- The connection MUST persist the current time recorded immediately after the original socket timeout, and this + timestamp MUST be updated to the current time whenever any data is successfully read from the socket during a + pending response read attempt. +- If the connection remains idle (i.e., no data is read) for more than 3 seconds since the pending state began or since + the last successful read, the driver MUST attempt to verify the connection's health by either performing a + non-blocking read or using the minimal possible timeout to check if at least one byte can be read. +- If a user-provided timeout is specified for the pending response read, the driver MUST use the minimum of the + remaining time before the 3-second pending-response window elapses and the user-provided timeout as the effective + timeout for the read operation. +- If no user-provided timeout is specified, the driver MUST use the minimum of the remaining 3-second pending-response + window and the socketTimeoutMS (if supported by the driver) as the effective timeout for the read operation. +- If reading from the socket results in an error that is not a timeout, or if the connection exceeds the 3-second + pending-response window, the driver MUST close the connection. +- If the pending response is fully read and successfully discarded, and the connection remains healthy, the pending + state may be cleared and the connection MAY be returned to the pool for reuse. + +```mermaid +sequenceDiagram + participant Driver + participant Pool + participant Conn as Connection (*) + participant Server + + Driver->>Pool: Checkout Connection (*) + Pool->>Driver: Return connection (*) + + Driver->>Conn: Send operation (1) (CSOT enabled, maxTimeMS > 0) + Conn->>Server: Send command + Server-->>Conn: (No response, socket times out) + Conn->>Conn: Mark as "pending", record current time + Conn-->>Driver: Error + + Driver->>Pool: Checkout Connection (*) + Pool->>Driver: Return connection (*) + + Driver->>Conn: Send operation (2) + + + Conn->>Server: Attempt to discard pending response from operation (1) + Conn->>Conn: Update pending read timestamp if bytes read + + alt Timeout window exceeded or non-timeout error + Conn->>Conn: Close connection + Conn-->>Driver: Error + else Timeout window not exceeded + alt Error + Conn->>Conn: Clear pending read state + Conn->>Conn: Reset to current time + Conn->>Pool: Check connection back into pool + Conn-->>Driver: Error + else No error + Conn->>Conn: Clear pending read state + Conn->>Driver: Return connection to execute operation + end + end +``` + +```python +PENDING_RESPONSE_TIMEOUT_MS = 3000 # static timeout + +def await_pending_response(timeout, conn): + # Note: conn.pending_start is initialized after the original socket timeout + # and not in this function since the connection will sit in the pool for some + # non-deterministic amount of time after the socket timeout. + + remaining_time = (conn.pending_start + PENDING_RESPONSE_TIMEOUT_MS) - current_time() + if remaining_time <= 0: + # Use the smallest timeout (or enable non-blocking read). + remaining_time = 0.001 + + if timeout is None: + timeout = min(remaining_time, conn.socket_timeout_ms) + else: + timeout = min(remaining_time, timeout) + + data, error = execute_pending_response(timeout, conn) + end_time = current_time() + + if error is not None and error is not timeout: + close_connection(conn) + raise + + if len(data) > 0: + # Refresh the remaining time upon a successful read + conn.pending_start = end_time + + # Check if the remaining time has been exceeded + if end_time - conn.pending_start >= PENDING_RESPONSE_TIMEOUT_MS: + close_connection(conn) + + if error is not None: + raise error +``` + +```python connection = Null tConnectionCheckOutStarted = current instant (use a monotonic clock if possible) emit ConnectionCheckOutStartedEvent and equivalent log message @@ -633,6 +732,11 @@ if connection state is "pending": decrement pendingConnectionCount else: decrement availableConnectionCount + +error = await_pending_response(pool, connection) +if error: + return error + set connection state to "in use" # If there is no background thread, the pool MUST ensure that @@ -997,6 +1101,79 @@ interface ConnectionCheckedInEvent { */ connectionId: int64; } + +/** + * Emitted when the connection being checked out is attempting to read and + * discard a pending server response. + */ +interface PendingResponseStarted { + /** + * The ServerAddress of the Endpoint the pool is attempting to connect to. + */ + address: string; + + /** + * The ID of the Connection. + */ + connectionId: int64; + + /** + * The driver-generated request ID associated with the network timeout. + */ + requestId: int64; +} + +/** + * Emitted when the connection successfully read the pending read and is ready + * to be checked out. + */ +interface PendingResponseSucceeded { + /** + * The ServerAddress of the Endpoint the pool is attempting to connect to. + */ + address: string; + + /** + * The ID of the Connection. + */ + connectionId: int64; + + /** + * The time it took to complete the pending read. + */ + duration: Duration; + + /** + * The driver-generated request ID associated with the network timeout. + */ + requestId: int64; +} + +/** + * Emitted when the connection being checked out failed to complete the pending + * read. + */ +interface PendingResponseFailed { + /** + * The ServerAddress of the Endpoint the pool is attempting to connect to. + */ + address: string; + + /** + * The ID of the Connection. + */ + connectionId: int64; + + /** + * The driver-generated request ID associated with the network timeout. + */ + requestId: int64; + + /** + * The reason for why the pending read failed. + */ + reason: string; +} ``` ### Connection Pool Logging @@ -1194,6 +1371,56 @@ placeholders as appropriate: > Connection checked in: address={{serverHost}}:{{serverPort}}, driver-generated ID={{driverConnectionId}} +#### Connection Pending Response Started + +In addition to the common fields defined above, this message MUST contain the following key-value pairs: + +| Key | Suggested Type | Value | +| ------------------ | -------------- | ------------------------------------------------------------------- | +| message | string | "Pending response started" | +| driverConnectionId | int64 | The driver-generated ID for the connection | +| requestId | int64 | The driver-generated request ID associated with the network timeout | + +The unstructured form SHOULD be as follows, using the values defined in the structured format above to fill in +placeholders as appropriate: + +> Pending response started: address={{serverHost}}:{{serverPort}}, driver-generated ID={{driverConnectionId}}, +> request ID={{requestId}} + +#### Connection Pending Response Succeeded + +In addition to the common fields defined above, this message MUST contain the following key-value pairs: + +| Key | Suggested Type | Value | +| ------------------ | ------------------ | ------------------------------------------------------------------- | +| message | string | "Pending response succeeded" | +| driverConnectionId | int64 | The driver-generated ID for the connection | +| requestId | int64 | The driver-generated request ID associated with the network timeout | +| durationMS | Int32/Int64/Double | The time it took to complete the pending read | + +The unstructured form SHOULD be as follows, using the values defined in the structured format above to fill in +placeholders as appropriate: + +> Pending response started: address={{serverHost}}:{{serverPort}}, driver-generated ID={{driverConnectionId}}, +> request ID={{requestId}}, duration={{durationMS}} ms + +#### Connection Pending Response Failed + +In addition to the common fields defined above, this message MUST contain the following key-value pairs: + +| Key | Suggested Type | Value | +| ------------------ | -------------- | --------------------------------------------------- | +| message | string | "Pending response failed" | +| driverConnectionId | int64 | The driver-generated ID for the connection | +| requestId | int64 | The driver-generated request ID associated with the network timeout | +| reason | string | The reason for why the pending response read failed | + +The unstructured form SHOULD be as follows, using the values defined in the structured format above to fill in +placeholders as appropriate: + +> Pending response started: address={{serverHost}}:{{serverPort}}, driver-generated ID={{driverConnectionId}}, +> request ID={{requestId}}, reason={{reason}} + ### Connection Pool Errors A connection pool throws errors in specific circumstances. These Errors MUST be emitted by the pool. Errors SHOULD be @@ -1339,6 +1566,35 @@ some equivalent configuration, but this configuration will also require target f 5.0. The advantage of using Background Thread to manage perished connections is that it will work regardless of environment setup. +### Why is pending response read timeout not calculated dynamically? Why is it specifically 3 seconds? + +Using a dynamic timeout introduces additional complexity. In particular, RTT is an unreliable metric for predicting +future operation latency as both server and network conditions are unpredictable. Benchmarks demonstrate that even in +slow, high-latency scenarios (e.g. reading a 16MiB document over cross-country), reads reliably complete in under 1 +second. The 3-second timeout ensures that every realistic pending response read will not result in premature connection +closure, but will still close in pathological conditions (e.g., a dead server or true network outage). + +### Why is the pending response read timeout not configurable? + +Because of the +["no knobs" mantra](https://github.com/mongodb/specifications/blob/master/source/driver-mantras.md#no-knobs). We can +always reconsider this in the future. + +### Why does the pending response read timeout include the time the connection is idle in the pool? + +The pending response read timeout includes idle time in the pool so that stale or unusable connections (e.g., if the +socket is dead) are detected and closed promptly instead of incurring an additional 3-second wait upon checkout. By +tracking the timeout during idle periods, we ensure that the driver can quickly determine if the connection should be +closed with a fast, non-blocking check as soon as it’s checked out, avoiding introducing unnecessary latency while still +protecting connection availability. This approach maintains a balance between minimizing connection churn and ensuring +users don't encounter avoidable delays. + +### Why do we refresh the pending response read timeout each time we successfully read bytes from the TCP stream? + +By refreshing the timeout after each successful read, we acknowledge that progress is being made, and we provide a new +time window for the next segment of data to arrive. Refreshing is less costly than re-establishing a connection since +there is no reason to believe that a new connection would reduce latency. + ## Backwards Compatibility As mentioned in [Deprecated Options](#deprecated-options), some drivers currently implement the options `waitQueueSize` @@ -1414,4 +1670,7 @@ to close and remove from its pool a [Connection](#connection) which has unread e - 2023-10-04: Commit to the currently specified requirements regarding durations in events. +- Improved connection reuse and availability by allowing pending server responses to be read with a 3-second static + timeout after a client-side operation timeout. + ______________________________________________________________________ diff --git a/source/connection-monitoring-and-pooling/tests/README.md b/source/connection-monitoring-and-pooling/tests/README.md index 3d8aee40aa..df4f45edc9 100644 --- a/source/connection-monitoring-and-pooling/tests/README.md +++ b/source/connection-monitoring-and-pooling/tests/README.md @@ -21,6 +21,51 @@ The following tests have not yet been automated, but MUST still be tested: 5. When a check out attempt fails because connection set up throws an error, assert that a ConnectionCheckOutFailedEvent with reason="connectionError" is emitted. +### Pending Response: Connection Aliveness Tests + +If a connection with a pending response is idle for > 3 seconds, then drivers are expected to perform an aliveness check +by attempting a non-blocking read of 1 byte from the inbound TCP buffer. The following two cases test both a successful +read and a failed one. + +#### Connection Aliveness Check Fails + +1. Initialize a mock TCP listener to simulate the server-side behavior. The listener should write at least 5 bytes to + the connection to prevent size-related errors (e.g. `0x01, 0x02, 0x03, 0x04, 0x05, 0xFF`). The response should be + delayed by 2x the size of the socket timeout. +2. Implement a monitoring mechanism to capture the `ConnectionPendingResponseStarted` and + `ConnectionPendingResponseFailed` events. +3. Instantiate a connection pool using the mock listener’s address, ensuring readiness without error. Attach the event + monitor to observe the connection’s state. +4. Check out a connection from the pool and initiate a read operation with an appropriate socket timeout (e.g, 10ms) + that will trigger a timeout due to the artificial delay of 2x the socket timeout (step 1). Ensure that the read + operation returns a timeout error. +5. Check the connection back into the pool and sleep for 3 seconds so that the pending response state timestamp exceeds + the pending response timeout, forcing an aliveness check. +6. Check the connection out. The aliveness check should fail since no additional bytes were added after the delay in + step 1. +7. Verify that one event for each `ConnectionPendingResponseStarted` and `ConnectionPendingResponseFailed` was emitted. + Also verify that the fields were correctly set for each event. + +#### Connection Aliveness Check Succeeds + +1. Initialize a mock TCP listener to simulate the server-side behavior. The listener should write at least 5 bytes to + the connection to prevent size-related errors (e.g. `0x01, 0x02, 0x03, 0x04, 0x05, 0xFF`). The response should be + delayed by 2x the size of the socket timeout. Write at least 1 additional byte after the delay so that the + aliveness check succeeds (e.g. `0xAA`). +2. Implement a monitoring mechanism to capture the `ConnectionPendingResponseStarted` and + `ConnectionPendingResponseSucceeded` events. +3. Instantiate a connection pool using the mock listener’s address, ensuring readiness without error. Attach the event + monitor to observe the connection’s state. +4. Check out a connection from the pool and initiate a read operation with an appropriate socket timeout (e.g, 10ms) + that will trigger a timeout due to the artificial delay of 2x the socket timeout (step 1). Ensure that the read + operation returns a timeout error. +5. Check the connection back into the pool and sleep for 3 seconds so that the pending response state timestamp exceeds + the pending response timeout, forcing an aliveness check. +6. Check the connection out. The aliveness check should succeed since no additional bytes were added after the delay in + step 1. +7. Verify that one event for each `ConnectionPendingResponseStarted` and `ConnectionPendingResponseSucceeded` was + emitted. Also verify that the fields were correctly set for each event. + ## Logging Tests Tests for connection pool logging can be found in the `/logging` subdirectory and are written in the diff --git a/source/connection-monitoring-and-pooling/tests/logging/connection-logging.json b/source/connection-monitoring-and-pooling/tests/logging/connection-logging.json index 72103b3cab..d545e8034c 100644 --- a/source/connection-monitoring-and-pooling/tests/logging/connection-logging.json +++ b/source/connection-monitoring-and-pooling/tests/logging/connection-logging.json @@ -1,6 +1,6 @@ { "description": "connection-logging", - "schemaVersion": "1.13", + "schemaVersion": "1.24", "runOnRequirements": [ { "topologies": [ @@ -518,6 +518,546 @@ ] } ] + }, + { + "description": "force a pending response read, fail first try, succeed second try", + "operations": [ + { + "name": "createEntities", + "object": "testRunner", + "arguments": { + "entities": [ + { + "client": { + "id": "client", + "uriOptions": { + "retryReads": false, + "appname": "clientAppName", + "heartbeatFrequencyMS": 10000 + }, + "observeLogMessages": { + "connection": "debug" + } + } + }, + { + "database": { + "id": "test", + "client": "client", + "databaseName": "test" + } + }, + { + "collection": { + "id": "coll", + "database": "test", + "collectionName": "coll" + } + } + ] + } + }, + { + "name": "runCommand", + "object": "test", + "arguments": { + "command": { + "ping": 1 + } + } + }, + { + "name": "failPoint", + "object": "testRunner", + "arguments": { + "client": "failPointClient", + "failPoint": { + "configureFailPoint": "failCommand", + "mode": { + "times": 1 + }, + "data": { + "failCommands": [ + "insert" + ], + "blockConnection": true, + "blockTimeMS": 200 + } + } + } + }, + { + "name": "insertOne", + "object": "coll", + "arguments": { + "timeoutMS": 50, + "document": { + "_id": 3, + "x": 1 + } + }, + "expectError": { + "isTimeoutError": true + } + }, + { + "name": "findOne", + "object": "coll", + "arguments": { + "filter": { + "_id": 1 + }, + "timeoutMS": 100 + }, + "expectError": { + "isTimeoutError": true + } + }, + { + "name": "wait", + "object": "testRunner", + "arguments": { + "ms": 75 + } + }, + { + "name": "findOne", + "object": "coll", + "arguments": { + "filter": { + "_id": 1 + } + } + } + ], + "expectLogMessages": [ + { + "client": "client", + "ignoreExtraMessages": true, + "messages": [ + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection pool created", + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection pool ready", + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection checkout started", + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection created", + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection ready", + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + }, + "durationMS": { + "$$type": [ + "double", + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection checked out", + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + }, + "durationMS": { + "$$type": [ + "double", + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection checked in", + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection checkout started", + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection checked out", + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + }, + "durationMS": { + "$$type": [ + "double", + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection checked in", + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection checkout started", + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Pending response started", + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + }, + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "requestId": { + "$$type": [ + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Pending response failed", + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + }, + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "requestId": { + "$$type": [ + "int", + "long" + ] + }, + "reason": "timeout" + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection checkout started", + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Pending response started", + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + }, + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "requestId": { + "$$type": [ + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Pending response succeeded", + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + }, + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "requestId": { + "$$type": [ + "int", + "long" + ] + }, + "durationMS": { + "$$type": [ + "double", + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection checked out", + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + }, + "durationMS": { + "$$type": [ + "double", + "int", + "long" + ] + } + } + }, + { + "level": "debug", + "component": "connection", + "data": { + "message": "Connection checked in", + "driverConnectionId": { + "$$type": [ + "int", + "long" + ] + }, + "serverHost": { + "$$type": "string" + }, + "serverPort": { + "$$type": [ + "int", + "long" + ] + } + } + } + ] + } + ] } ] } diff --git a/source/connection-monitoring-and-pooling/tests/logging/connection-logging.yml b/source/connection-monitoring-and-pooling/tests/logging/connection-logging.yml index 49868a062e..7e5102bb95 100644 --- a/source/connection-monitoring-and-pooling/tests/logging/connection-logging.yml +++ b/source/connection-monitoring-and-pooling/tests/logging/connection-logging.yml @@ -1,6 +1,6 @@ description: "connection-logging" -schemaVersion: "1.13" +schemaVersion: "1.24" runOnRequirements: - topologies: @@ -222,3 +222,236 @@ tests: reason: "An error occurred while trying to establish a new connection" error: { $$exists: true } durationMS: { $$type: [double, int, long] } + + - description: "force a pending response read, fail first try, succeed second try" + operations: + - name: createEntities + object: testRunner + arguments: + entities: + - client: + id: &client client + uriOptions: + retryReads: false + appname: &clientAppName clientAppName + # 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 + observeLogMessages: + connection: debug + - database: + id: &database test + client: *client + databaseName: *database + - collection: + id: &collection coll + database: *database + collectionName: *collection + + # Run a ping command to pre-load the pool with a connection. + - name: runCommand + object: *database + arguments: + command: + ping: 1 + + # Create a failpoint to block the first operation + - name: failPoint + object: testRunner + arguments: + client: *failPointClient + failPoint: + configureFailPoint: failCommand + mode: { times: 1 } + data: + failCommands: ["insert"] + blockConnection: true + blockTimeMS: 200 + + # Execute operation with timeout less than block time + - name: insertOne + object: *collection + arguments: + timeoutMS: 50 + document: { _id: 3, x: 1 } + expectError: + isTimeoutError: true + + # Execute a subsequent operation which should time out during the + # pending response read attempt. + - name: findOne + object: *collection + arguments: + filter: { _id: 1 } + timeoutMS: 100 + expectError: + isTimeoutError: true + + # Wait for the blocked connection to free up. + - name: wait + # operation. + object: testRunner + arguments: + ms: 75 + + # Execute a subsequent operation which should completed the pending read. + - name: findOne + object: *collection + arguments: + filter: { _id: 1 } + + expectLogMessages: + - client: *client + ignoreExtraMessages: true + messages: + - level: debug + component: connection + data: + message: "Connection pool created" + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + + - level: debug + component: connection + data: + message: "Connection pool ready" + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + + # Ping + - level: debug + component: connection + data: + message: "Connection checkout started" + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + + - level: debug + component: connection + data: + message: "Connection created" + driverConnectionId: { $$type: [int, long] } + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + + - level: debug + component: connection + data: + message: "Connection ready" + driverConnectionId: { $$type: [int, long] } + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + durationMS: { $$type: [double, int, long] } + + - level: debug + component: connection + data: + message: "Connection checked out" + driverConnectionId: { $$type: [int, long] } + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + durationMS: { $$type: [double, int, long] } + + - level: debug + component: connection + data: + message: "Connection checked in" + driverConnectionId: { $$type: [int, long] } + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + + # Insert + - level: debug + component: connection + data: + message: "Connection checkout started" + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + + - level: debug + component: connection + data: + message: "Connection checked out" + driverConnectionId: { $$type: [int, long] } + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + durationMS: { $$type: [double, int, long] } + + - level: debug + component: connection + data: + message: "Connection checked in" + driverConnectionId: { $$type: [int, long] } + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + + # First Find + - level: debug + component: connection + data: + message: "Connection checkout started" + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + + - level: debug + component: connection + data: + message: "Pending response started" + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + driverConnectionId: { $$type: [int, long] } + requestId: { $$type: [int, long] } + + - level: debug + component: connection + data: + message: "Pending response failed" + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + driverConnectionId: { $$type: [int, long] } + requestId: { $$type: [int, long] } + reason: "timeout" + + # Second Find + - level: debug + component: connection + data: + message: "Connection checkout started" + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + + - level: debug + component: connection + data: + message: "Pending response started" + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + driverConnectionId: { $$type: [int, long] } + requestId: { $$type: [int, long] } + + - level: debug + component: connection + data: + message: "Pending response succeeded" + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + driverConnectionId: { $$type: [int, long] } + requestId: { $$type: [int, long] } + durationMS: { $$type: [double, int, long] } + + - level: debug + component: connection + data: + message: "Connection checked out" + driverConnectionId: { $$type: [int, long] } + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } + durationMS: { $$type: [double, int, long] } + + - level: debug + component: connection + data: + message: "Connection checked in" + driverConnectionId: { $$type: [int, long] } + serverHost: { $$type: string } + serverPort: { $$type: [int, long] } diff --git a/source/unified-test-format/schema-1.24.json b/source/unified-test-format/schema-1.24.json new file mode 100644 index 0000000000..b19fd02548 --- /dev/null +++ b/source/unified-test-format/schema-1.24.json @@ -0,0 +1,1181 @@ +{ + "$schema": "http://json-schema.org/draft-07/schema#", + "title": "Unified Test Format", + "type": "object", + "additionalProperties": false, + "required": [ + "description", + "schemaVersion", + "tests" + ], + "properties": { + "description": { + "type": "string" + }, + "schemaVersion": { + "$ref": "#/definitions/version" + }, + "runOnRequirements": { + "type": "array", + "minItems": 1, + "items": { + "$ref": "#/definitions/runOnRequirement" + } + }, + "createEntities": { + "type": "array", + "minItems": 1, + "items": { + "$ref": "#/definitions/entity" + } + }, + "initialData": { + "type": "array", + "minItems": 1, + "items": { + "$ref": "#/definitions/collectionData" + } + }, + "tests": { + "type": "array", + "minItems": 1, + "items": { + "$ref": "#/definitions/test" + } + }, + "_yamlAnchors": { + "type": "object", + "additionalProperties": true + } + }, + "definitions": { + "version": { + "type": "string", + "pattern": "^[0-9]+(\\.[0-9]+){1,2}$" + }, + "runOnRequirement": { + "type": "object", + "additionalProperties": false, + "minProperties": 1, + "properties": { + "maxServerVersion": { + "$ref": "#/definitions/version" + }, + "minServerVersion": { + "$ref": "#/definitions/version" + }, + "topologies": { + "type": "array", + "minItems": 1, + "items": { + "type": "string", + "enum": [ + "single", + "replicaset", + "sharded", + "sharded-replicaset", + "load-balanced" + ] + } + }, + "serverless": { + "type": "string", + "enum": [ + "require", + "forbid", + "allow" + ] + }, + "serverParameters": { + "type": "object", + "minProperties": 1 + }, + "auth": { + "type": "boolean" + }, + "authMechanism": { + "type": "string" + }, + "csfle": { + "type": "boolean" + } + } + }, + "entity": { + "type": "object", + "additionalProperties": false, + "maxProperties": 1, + "minProperties": 1, + "properties": { + "client": { + "type": "object", + "additionalProperties": false, + "required": [ + "id" + ], + "properties": { + "id": { + "type": "string" + }, + "uriOptions": { + "type": "object" + }, + "useMultipleMongoses": { + "type": "boolean" + }, + "observeEvents": { + "type": "array", + "minItems": 1, + "items": { + "type": "string", + "enum": [ + "commandStartedEvent", + "commandSucceededEvent", + "commandFailedEvent", + "poolCreatedEvent", + "poolReadyEvent", + "poolClearedEvent", + "poolClosedEvent", + "connectionCreatedEvent", + "connectionReadyEvent", + "connectionClosedEvent", + "connectionCheckOutStartedEvent", + "connectionCheckOutFailedEvent", + "connectionCheckedOutEvent", + "connectionCheckedInEvent", + "connectionPendingResponseSucceeded", + "connectionPendingResponseStarted", + "connectionPendingResponseFailed", + "serverDescriptionChangedEvent", + "topologyDescriptionChangedEvent" + ] + } + }, + "ignoreCommandMonitoringEvents": { + "type": "array", + "minItems": 1, + "items": { + "type": "string" + } + }, + "storeEventsAsEntities": { + "type": "array", + "minItems": 1, + "items": { + "$ref": "#/definitions/storeEventsAsEntity" + } + }, + "observeLogMessages": { + "type": "object", + "minProperties": 1, + "additionalProperties": false, + "properties": { + "command": { + "$ref": "#/definitions/logSeverityLevel" + }, + "topology": { + "$ref": "#/definitions/logSeverityLevel" + }, + "serverSelection": { + "$ref": "#/definitions/logSeverityLevel" + }, + "connection": { + "$ref": "#/definitions/logSeverityLevel" + } + } + }, + "serverApi": { + "$ref": "#/definitions/serverApi" + }, + "observeSensitiveCommands": { + "type": "boolean" + }, + "autoEncryptOpts": { + "type": "object", + "additionalProperties": false, + "required": [ + "keyVaultNamespace", + "kmsProviders" + ], + "properties": { + "keyVaultNamespace": { + "type": "string" + }, + "bypassAutoEncryption": { + "type": "boolean" + }, + "kmsProviders": { + "$ref": "#/definitions/kmsProviders" + }, + "schemaMap": { + "type": "object", + "additionalProperties": { + "type": "object" + } + }, + "extraOptions": { + "type": "object" + }, + "encryptedFieldsMap": { + "type": "object", + "additionalProperties": { + "type": "object" + } + }, + "bypassQueryAnalysis": { + "type": "boolean" + }, + "keyExpirationMS": { + "type": "integer" + } + } + } + } + }, + "clientEncryption": { + "type": "object", + "additionalProperties": false, + "required": [ + "id", + "clientEncryptionOpts" + ], + "properties": { + "id": { + "type": "string" + }, + "clientEncryptionOpts": { + "$ref": "#/definitions/clientEncryptionOpts" + } + } + }, + "database": { + "type": "object", + "additionalProperties": false, + "required": [ + "id", + "client", + "databaseName" + ], + "properties": { + "id": { + "type": "string" + }, + "client": { + "type": "string" + }, + "databaseName": { + "type": "string" + }, + "databaseOptions": { + "$ref": "#/definitions/collectionOrDatabaseOptions" + } + } + }, + "collection": { + "type": "object", + "additionalProperties": false, + "required": [ + "id", + "database", + "collectionName" + ], + "properties": { + "id": { + "type": "string" + }, + "database": { + "type": "string" + }, + "collectionName": { + "type": "string" + }, + "collectionOptions": { + "$ref": "#/definitions/collectionOrDatabaseOptions" + } + } + }, + "session": { + "type": "object", + "additionalProperties": false, + "required": [ + "id", + "client" + ], + "properties": { + "id": { + "type": "string" + }, + "client": { + "type": "string" + }, + "sessionOptions": { + "type": "object" + } + } + }, + "bucket": { + "type": "object", + "additionalProperties": false, + "required": [ + "id", + "database" + ], + "properties": { + "id": { + "type": "string" + }, + "database": { + "type": "string" + }, + "bucketOptions": { + "type": "object" + } + } + }, + "thread": { + "type": "object", + "additionalProperties": false, + "required": [ + "id" + ], + "properties": { + "id": { + "type": "string" + } + } + } + } + }, + "logComponent": { + "type": "string", + "enum": [ + "command", + "topology", + "serverSelection", + "connection" + ] + }, + "logSeverityLevel": { + "type": "string", + "enum": [ + "emergency", + "alert", + "critical", + "error", + "warning", + "notice", + "info", + "debug", + "trace" + ] + }, + "clientEncryptionOpts": { + "type": "object", + "additionalProperties": false, + "required": [ + "keyVaultClient", + "keyVaultNamespace", + "kmsProviders" + ], + "properties": { + "keyVaultClient": { + "type": "string" + }, + "keyVaultNamespace": { + "type": "string" + }, + "kmsProviders": { + "$ref": "#/definitions/kmsProviders" + }, + "keyExpirationMS": { + "type": "integer" + } + } + }, + "kmsProviders": { + "$defs": { + "stringOrPlaceholder": { + "oneOf": [ + { + "type": "string" + }, + { + "type": "object", + "additionalProperties": false, + "required": [ + "$$placeholder" + ], + "properties": { + "$$placeholder": {} + } + } + ] + } + }, + "type": "object", + "additionalProperties": false, + "patternProperties": { + "^aws(:[a-zA-Z0-9_]+)?$": { + "type": "object", + "additionalProperties": false, + "properties": { + "accessKeyId": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + }, + "secretAccessKey": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + }, + "sessionToken": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + } + } + }, + "^azure(:[a-zA-Z0-9_]+)?$": { + "type": "object", + "additionalProperties": false, + "properties": { + "tenantId": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + }, + "clientId": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + }, + "clientSecret": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + }, + "identityPlatformEndpoint": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + } + } + }, + "^gcp(:[a-zA-Z0-9_]+)?$": { + "type": "object", + "additionalProperties": false, + "properties": { + "email": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + }, + "privateKey": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + }, + "endpoint": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + } + } + }, + "^kmip(:[a-zA-Z0-9_]+)?$": { + "type": "object", + "additionalProperties": false, + "properties": { + "endpoint": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + } + } + }, + "^local(:[a-zA-Z0-9_]+)?$": { + "type": "object", + "additionalProperties": false, + "properties": { + "key": { + "$ref": "#/definitions/kmsProviders/$defs/stringOrPlaceholder" + } + } + } + } + }, + "storeEventsAsEntity": { + "type": "object", + "additionalProperties": false, + "required": [ + "id", + "events" + ], + "properties": { + "id": { + "type": "string" + }, + "events": { + "type": "array", + "minItems": 1, + "items": { + "type": "string", + "enum": [ + "PoolCreatedEvent", + "PoolReadyEvent", + "PoolClearedEvent", + "PoolClosedEvent", + "ConnectionCreatedEvent", + "ConnectionReadyEvent", + "ConnectionClosedEvent", + "ConnectionCheckOutStartedEvent", + "ConnectionCheckOutFailedEvent", + "ConnectionCheckedOutEvent", + "ConnectionCheckedInEvent", + "CommandStartedEvent", + "CommandSucceededEvent", + "CommandFailedEvent", + "ServerDescriptionChangedEvent", + "TopologyDescriptionChangedEvent" + ] + } + } + } + }, + "collectionData": { + "type": "object", + "additionalProperties": false, + "required": [ + "collectionName", + "databaseName", + "documents" + ], + "properties": { + "collectionName": { + "type": "string" + }, + "databaseName": { + "type": "string" + }, + "createOptions": { + "type": "object", + "properties": { + "writeConcern": false + } + }, + "documents": { + "type": "array", + "items": { + "type": "object" + } + } + } + }, + "expectedEventsForClient": { + "type": "object", + "additionalProperties": false, + "required": [ + "client", + "events" + ], + "properties": { + "client": { + "type": "string" + }, + "eventType": { + "type": "string", + "enum": [ + "command", + "cmap", + "sdam" + ] + }, + "events": { + "type": "array" + }, + "ignoreExtraEvents": { + "type": "boolean" + } + }, + "oneOf": [ + { + "required": [ + "eventType" + ], + "properties": { + "eventType": { + "const": "command" + }, + "events": { + "type": "array", + "items": { + "$ref": "#/definitions/expectedCommandEvent" + } + } + } + }, + { + "required": [ + "eventType" + ], + "properties": { + "eventType": { + "const": "cmap" + }, + "events": { + "type": "array", + "items": { + "$ref": "#/definitions/expectedCmapEvent" + } + } + } + }, + { + "required": [ + "eventType" + ], + "properties": { + "eventType": { + "const": "sdam" + }, + "events": { + "type": "array", + "items": { + "$ref": "#/definitions/expectedSdamEvent" + } + } + } + }, + { + "additionalProperties": false, + "properties": { + "client": { + "type": "string" + }, + "events": { + "type": "array", + "items": { + "$ref": "#/definitions/expectedCommandEvent" + } + }, + "ignoreExtraEvents": { + "type": "boolean" + } + } + } + ] + }, + "expectedCommandEvent": { + "type": "object", + "additionalProperties": false, + "maxProperties": 1, + "minProperties": 1, + "properties": { + "commandStartedEvent": { + "type": "object", + "additionalProperties": false, + "properties": { + "command": { + "type": "object" + }, + "commandName": { + "type": "string" + }, + "databaseName": { + "type": "string" + }, + "hasServiceId": { + "type": "boolean" + }, + "hasServerConnectionId": { + "type": "boolean" + } + } + }, + "commandSucceededEvent": { + "type": "object", + "additionalProperties": false, + "properties": { + "reply": { + "type": "object" + }, + "commandName": { + "type": "string" + }, + "databaseName": { + "type": "string" + }, + "hasServiceId": { + "type": "boolean" + }, + "hasServerConnectionId": { + "type": "boolean" + } + } + }, + "commandFailedEvent": { + "type": "object", + "additionalProperties": false, + "properties": { + "commandName": { + "type": "string" + }, + "databaseName": { + "type": "string" + }, + "hasServiceId": { + "type": "boolean" + }, + "hasServerConnectionId": { + "type": "boolean" + } + } + } + } + }, + "expectedCmapEvent": { + "type": "object", + "additionalProperties": false, + "maxProperties": 1, + "minProperties": 1, + "properties": { + "poolCreatedEvent": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "poolReadyEvent": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "poolClearedEvent": { + "type": "object", + "additionalProperties": false, + "properties": { + "hasServiceId": { + "type": "boolean" + }, + "interruptInUseConnections": { + "type": "boolean" + } + } + }, + "poolClosedEvent": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "connectionCreatedEvent": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "connectionReadyEvent": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "connectionClosedEvent": { + "type": "object", + "additionalProperties": false, + "properties": { + "reason": { + "type": "string" + } + } + }, + "connectionCheckOutStartedEvent": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "connectionCheckOutFailedEvent": { + "type": "object", + "additionalProperties": false, + "properties": { + "reason": { + "type": "string" + } + } + }, + "connectionCheckedOutEvent": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "connectionCheckedInEvent": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "connectionPendingResponseStarted": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "connectionPendingResponseSucceeded": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "connectionPendingResponseFailed": { + "type": "object", + "additionalProperties": false, + "properties": { + "reason": { + "type": "string" + } + } + } + } + }, + "expectedSdamEvent": { + "type": "object", + "additionalProperties": false, + "maxProperties": 1, + "minProperties": 1, + "properties": { + "serverDescriptionChangedEvent": { + "type": "object", + "additionalProperties": false, + "properties": { + "previousDescription": { + "$ref": "#/definitions/serverDescription" + }, + "newDescription": { + "$ref": "#/definitions/serverDescription" + } + } + }, + "topologyDescriptionChangedEvent": { + "type": "object", + "additionalProperties": false, + "properties": { + "previousDescription": { + "$ref": "#/definitions/topologyDescription" + }, + "newDescription": { + "$ref": "#/definitions/topologyDescription" + } + } + }, + "serverHeartbeatStartedEvent": { + "type": "object", + "additionalProperties": false, + "properties": { + "awaited": { + "type": "boolean" + } + } + }, + "serverHeartbeatSucceededEvent": { + "type": "object", + "additionalProperties": false, + "properties": { + "awaited": { + "type": "boolean" + } + } + }, + "serverHeartbeatFailedEvent": { + "type": "object", + "additionalProperties": false, + "properties": { + "awaited": { + "type": "boolean" + } + } + }, + "topologyOpeningEvent": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "topologyClosedEvent": { + "type": "object", + "additionalProperties": false, + "properties": {} + } + } + }, + "serverDescription": { + "type": "object", + "additionalProperties": false, + "properties": { + "type": { + "type": "string", + "enum": [ + "Standalone", + "Mongos", + "PossiblePrimary", + "RSPrimary", + "RSSecondary", + "RSOther", + "RSArbiter", + "RSGhost", + "LoadBalancer", + "Unknown" + ] + } + } + }, + "topologyDescription": { + "type": "object", + "additionalProperties": false, + "properties": { + "type": { + "type": "string", + "enum": [ + "Single", + "Unknown", + "ReplicaSetNoPrimary", + "ReplicaSetWithPrimary", + "Sharded", + "LoadBalanced" + ] + } + } + }, + "expectedLogMessagesForClient": { + "type": "object", + "additionalProperties": false, + "required": [ + "client", + "messages" + ], + "properties": { + "client": { + "type": "string" + }, + "messages": { + "type": "array", + "items": { + "$ref": "#/definitions/expectedLogMessage" + } + }, + "ignoreExtraMessages": { + "type": "boolean" + }, + "ignoreMessages": { + "type": "array", + "items": { + "$ref": "#/definitions/expectedLogMessage" + } + } + } + }, + "expectedLogMessage": { + "type": "object", + "additionalProperties": false, + "required": [ + "level", + "component", + "data" + ], + "properties": { + "level": { + "$ref": "#/definitions/logSeverityLevel" + }, + "component": { + "$ref": "#/definitions/logComponent" + }, + "data": { + "type": "object" + }, + "failureIsRedacted": { + "type": "boolean" + } + } + }, + "collectionOrDatabaseOptions": { + "type": "object", + "additionalProperties": false, + "properties": { + "readConcern": { + "type": "object" + }, + "readPreference": { + "type": "object" + }, + "writeConcern": { + "type": "object" + }, + "timeoutMS": { + "type": "integer" + } + } + }, + "serverApi": { + "type": "object", + "additionalProperties": false, + "required": [ + "version" + ], + "properties": { + "version": { + "type": "string" + }, + "strict": { + "type": "boolean" + }, + "deprecationErrors": { + "type": "boolean" + } + } + }, + "operation": { + "type": "object", + "additionalProperties": false, + "required": [ + "name", + "object" + ], + "properties": { + "name": { + "type": "string" + }, + "object": { + "type": "string" + }, + "arguments": { + "type": "object" + }, + "ignoreResultAndError": { + "type": "boolean" + }, + "expectError": { + "$ref": "#/definitions/expectedError" + }, + "expectResult": {}, + "saveResultAsEntity": { + "type": "string" + } + }, + "allOf": [ + { + "not": { + "required": [ + "expectError", + "expectResult" + ] + } + }, + { + "not": { + "required": [ + "expectError", + "saveResultAsEntity" + ] + } + }, + { + "not": { + "required": [ + "ignoreResultAndError", + "expectResult" + ] + } + }, + { + "not": { + "required": [ + "ignoreResultAndError", + "expectError" + ] + } + }, + { + "not": { + "required": [ + "ignoreResultAndError", + "saveResultAsEntity" + ] + } + } + ] + }, + "expectedError": { + "type": "object", + "additionalProperties": false, + "minProperties": 1, + "properties": { + "isError": { + "type": "boolean", + "const": true + }, + "isClientError": { + "type": "boolean" + }, + "isTimeoutError": { + "type": "boolean" + }, + "errorContains": { + "type": "string" + }, + "errorCode": { + "type": "integer" + }, + "errorCodeName": { + "type": "string" + }, + "errorLabelsContain": { + "type": "array", + "minItems": 1, + "items": { + "type": "string" + } + }, + "errorLabelsOmit": { + "type": "array", + "minItems": 1, + "items": { + "type": "string" + } + }, + "writeErrors": { + "type": "object" + }, + "writeConcernErrors": { + "type": "array", + "items": { + "type": "object" + } + }, + "errorResponse": { + "type": "object" + }, + "expectResult": {} + } + }, + "test": { + "type": "object", + "additionalProperties": false, + "required": [ + "description", + "operations" + ], + "properties": { + "description": { + "type": "string" + }, + "runOnRequirements": { + "type": "array", + "minItems": 1, + "items": { + "$ref": "#/definitions/runOnRequirement" + } + }, + "skipReason": { + "type": "string" + }, + "operations": { + "type": "array", + "items": { + "$ref": "#/definitions/operation" + } + }, + "expectEvents": { + "type": "array", + "minItems": 1, + "items": { + "$ref": "#/definitions/expectedEventsForClient" + } + }, + "expectLogMessages": { + "type": "array", + "minItems": 1, + "items": { + "$ref": "#/definitions/expectedLogMessagesForClient" + } + }, + "outcome": { + "type": "array", + "minItems": 1, + "items": { + "$ref": "#/definitions/collectionData" + } + } + } + } + } +} diff --git a/source/unified-test-format/schema-latest.json b/source/unified-test-format/schema-latest.json index b454199b05..b19fd02548 100644 --- a/source/unified-test-format/schema-latest.json +++ b/source/unified-test-format/schema-latest.json @@ -143,6 +143,9 @@ "connectionCheckOutFailedEvent", "connectionCheckedOutEvent", "connectionCheckedInEvent", + "connectionPendingResponseSucceeded", + "connectionPendingResponseStarted", + "connectionPendingResponseFailed", "serverDescriptionChangedEvent", "topologyDescriptionChangedEvent" ] @@ -784,6 +787,25 @@ "type": "object", "additionalProperties": false, "properties": {} + }, + "connectionPendingResponseStarted": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "connectionPendingResponseSucceeded": { + "type": "object", + "additionalProperties": false, + "properties": {} + }, + "connectionPendingResponseFailed": { + "type": "object", + "additionalProperties": false, + "properties": { + "reason": { + "type": "string" + } + } } } }, @@ -1156,4 +1178,4 @@ } } } -} \ No newline at end of file +} diff --git a/source/unified-test-format/tests/Makefile b/source/unified-test-format/tests/Makefile index 1a049e72ce..eea2977432 100644 --- a/source/unified-test-format/tests/Makefile +++ b/source/unified-test-format/tests/Makefile @@ -1,4 +1,4 @@ -SCHEMA=../schema-1.23.json +SCHEMA=../schema-1.24.json .PHONY: all invalid valid-fail valid-pass atlas-data-lake versioned-api load-balancers gridfs transactions transactions-convenient-api crud collection-management read-write-concern retryable-reads retryable-writes sessions command-logging-and-monitoring client-side-operations-timeout HAS_AJV diff --git a/source/unified-test-format/unified-test-format.md b/source/unified-test-format/unified-test-format.md index a2c0522eb2..3cc15b351d 100644 --- a/source/unified-test-format/unified-test-format.md +++ b/source/unified-test-format/unified-test-format.md @@ -2,7 +2,7 @@ - Status: Accepted - Minimum Server Version: N/A -- Current Schema Version: 1.19.0 +- Current Schema Version: 1.24.0 ______________________________________________________________________ @@ -480,6 +480,9 @@ The structure of this object is as follows: - [connectionCheckOutFailedEvent](#expectedEvent_connectionCheckOutFailedEvent) - [connectionCheckedOutEvent](#expectedEvent_connectionCheckedOutEvent) - [connectionCheckedInEvent](#expectedEvent_connectionCheckedInEvent) + - [connectionPendingResponseStarted](#expectedEvent_connectionPendingResponseStarted) + - [connectionPendingResponseSucceeded](#expectedEvent_connectionPendingResponseSucceeded) + - connectionPendingResponseFailed](#expectedEvent_connectionPendingResponseFailed) - [serverDescriptionChangedEvent](#expectedEvent_serverDescriptionChangedEvent) - [serverHeartbeatStartedEvent](#expectedEvent_serverHeartbeatStartedEvent) - [serverHeartbeatSucceededEvent](#expectedEvent_serverHeartbeatSucceededEvent) @@ -1149,6 +1152,27 @@ The structure of this object is as follows: - `connectionCheckedInEvent`: Optional object. If present, this object MUST be an empty document as all fields in this event are non-deterministic. + + +- `connectionPendingResponseStarted`: Optional object. If present, this object MUST be an empty document as all fields in this + event are non-deterministic. + + + +- `connectionPendingResponseSucceeded`: Optional object. If present, this object MUST be an empty document as all fields in this + event are non-deterministic. + + + +- `connectionPendingResponseFailed`: Optional object. Assertions for one or more + [connectionPendingResponseFailed](../connection-monitoring-and-pooling/connection-monitoring-and-pooling.md#events) + fields. + + The structure of this object is as follows: + + - `reason`: Optional string. Test runners MUST assert that the reason in the published event matches this value. Valid + values for this field are defined in the CMAP spec. + ##### expectedSdamEvent The structure of this object is as follows: @@ -3555,6 +3579,11 @@ other specs *and* collating spec changes developed in parallel or during the sam ## Changelog +- 2025-04-25: **Schema version 1.24** + + Add pending response events to `expectEvents` and `observeEvents` for client entities. These include + `PendingResponseStartedEvent`, `PendingResponseSucceededEvent`, and `PendingResponseFailedEvent`. + - 2025-01-21: **Schema version 1.23.** Support automatic encryption. Add `autoEncryptOpts` to `client` entity.