Test that durations are included on relevant pool events

driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-checkin-make-available.json

@@ -22,7 +22,8 @@
     {
       "type": "ConnectionCheckedOut",
       "connectionId": 1,
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckedIn",
@@ -32,7 +33,8 @@
     {
       "type": "ConnectionCheckedOut",
       "connectionId": 1,
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [

driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-checkout-connection.json

@@ -23,12 +23,14 @@
     {
       "type": "ConnectionReady",
       "connectionId": 1,
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckedOut",
       "connectionId": 1,
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [

driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-checkout-error-closed.json

@@ -38,7 +38,8 @@
     {
       "type": "ConnectionCheckedOut",
       "address": 42,
-      "connectionId": 42
+      "connectionId": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckedIn",
@@ -56,6 +57,7 @@
     {
       "type": "ConnectionCheckOutFailed",
       "address": 42,
+      "duration": 42,
       "reason": "poolClosed"
     }
   ],

driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-checkout-maxConnecting-timeout.json

@@ -89,7 +89,8 @@
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "timeout",
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [

driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-clear-clears-waitqueue.json

@@ -59,7 +59,8 @@
     },
     {
       "type": "ConnectionCheckedOut",
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckOutStarted",
@@ -76,17 +77,20 @@
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "connectionError",
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "connectionError",
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "connectionError",
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [

driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-clear-ready.json

@@ -40,7 +40,8 @@
     {
       "type": "ConnectionCheckedOut",
       "address": 42,
-      "connectionId": 42
+      "connectionId": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionPoolCleared",
@@ -49,6 +50,7 @@
     {
       "type": "ConnectionCheckOutFailed",
       "address": 42,
+      "duration": 42,
       "reason": "connectionError"
     },
     {
@@ -57,7 +59,8 @@
     },
     {
       "type": "ConnectionCheckedOut",
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [

driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-ready.json

@@ -31,7 +31,8 @@
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "connectionError",
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionPoolReady",
@@ -47,7 +48,8 @@
     },
     {
       "type": "ConnectionCheckedOut",
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [

driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/wait-queue-timeout.json

@@ -48,7 +48,8 @@
     {
       "type": "ConnectionCheckedOut",
       "connectionId": 42,
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckOutStarted",
@@ -57,7 +58,8 @@
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "timeout",
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckedIn",

driver-core/src/test/unit/com/mongodb/internal/connection/AbstractConnectionPoolTest.java

@@ -78,11 +78,14 @@
 import java.util.concurrent.Future;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicLong;
+import java.util.stream.Collectors;
 
 import static com.mongodb.assertions.Assertions.assertFalse;
 import static com.mongodb.internal.thread.InterruptionUtil.interruptAndCreateMongoInterruptedException;
 import static java.lang.String.format;
+import static java.util.Arrays.asList;
 import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertTrue;
 import static org.junit.Assert.fail;
 import static org.junit.Assume.assumeFalse;
 import static org.junit.Assume.assumeNotNull;
@@ -285,40 +288,59 @@ public void shouldPassAllOutcomes() throws Exception {
                 BsonDocument expectedEvent = cur.asDocument();
                 String type = expectedEvent.getString("type").getValue();
                 if (type.equals("ConnectionPoolCreated")) {
+                    assertHasOnlySupportedKeys(expectedEvent, "type", "address", "options");
                     ConnectionPoolCreatedEvent actualEvent = getNextEvent(actualEventsIterator, ConnectionPoolCreatedEvent.class);
                     assertAddressMatch(expectedEvent, actualEvent.getServerId().getAddress());
                     assertEquals(settings, actualEvent.getSettings());
                 } else if (type.equals("ConnectionPoolCleared")) {
+                    assertHasOnlySupportedKeys(expectedEvent, "type", "address");
                     ConnectionPoolClearedEvent actualEvent = getNextEvent(actualEventsIterator, ConnectionPoolClearedEvent.class);
                     assertAddressMatch(expectedEvent, actualEvent.getServerId().getAddress());
                 } else if (type.equals("ConnectionPoolReady")) {
+                    assertHasOnlySupportedKeys(expectedEvent, "type", "address");
                     ConnectionPoolReadyEvent actualEvent = getNextEvent(actualEventsIterator, ConnectionPoolReadyEvent.class);
                     assertAddressMatch(expectedEvent, actualEvent.getServerId().getAddress());
                 } else if (type.equals("ConnectionPoolClosed")) {
+                    assertHasOnlySupportedKeys(expectedEvent, "type", "address");
                     ConnectionPoolClosedEvent actualEvent = getNextEvent(actualEventsIterator, ConnectionPoolClosedEvent.class);
                     assertAddressMatch(expectedEvent, actualEvent.getServerId().getAddress());
                 } else if (type.equals("ConnectionCreated")) {
+                    assertHasOnlySupportedKeys(expectedEvent, "type", "address", "connectionId");
                     ConnectionCreatedEvent actualEvent = getNextEvent(actualEventsIterator, ConnectionCreatedEvent.class);
+                    assertAddressMatch(expectedEvent, actualEvent.getConnectionId().getServerId().getAddress());
                     assertConnectionIdMatch(expectedEvent, actualEvent.getConnectionId());
                 } else if (type.equals("ConnectionReady")) {
+                    assertHasOnlySupportedKeys(expectedEvent, "type", "address", "connectionId", "duration");
                     ConnectionReadyEvent actualEvent = getNextEvent(actualEventsIterator, ConnectionReadyEvent.class);
                     assertAddressMatch(expectedEvent, actualEvent.getConnectionId().getServerId().getAddress());
+                    assertConnectionIdMatch(expectedEvent, actualEvent.getConnectionId());
+                    assertDurationMatch(expectedEvent, actualEvent);
                 } else if (type.equals("ConnectionClosed")) {
+                    assertHasOnlySupportedKeys(expectedEvent, "type", "address", "connectionId", "reason");
                     ConnectionClosedEvent actualEvent = getNextEvent(actualEventsIterator, ConnectionClosedEvent.class);
+                    assertAddressMatch(expectedEvent, actualEvent.getConnectionId().getServerId().getAddress());
                     assertConnectionIdMatch(expectedEvent, actualEvent.getConnectionId());
                     assertReasonMatch(expectedEvent, actualEvent);
                 } else if (type.equals("ConnectionCheckOutStarted")) {
+                    assertHasOnlySupportedKeys(expectedEvent, "type", "address");
                     ConnectionCheckOutStartedEvent actualEvent = getNextEvent(actualEventsIterator, ConnectionCheckOutStartedEvent.class);
                     assertAddressMatch(expectedEvent, actualEvent.getServerId().getAddress());
                 } else if (type.equals("ConnectionCheckOutFailed")) {
+                    assertHasOnlySupportedKeys(expectedEvent, "type", "address", "reason", "duration");
                     ConnectionCheckOutFailedEvent actualEvent = getNextEvent(actualEventsIterator, ConnectionCheckOutFailedEvent.class);
                     assertAddressMatch(expectedEvent, actualEvent.getServerId().getAddress());
                     assertReasonMatch(expectedEvent, actualEvent);
+                    assertDurationMatch(expectedEvent, actualEvent);
                 } else if (type.equals("ConnectionCheckedOut")) {
+                    assertHasOnlySupportedKeys(expectedEvent, "type", "address", "connectionId", "duration");
                     ConnectionCheckedOutEvent actualEvent = getNextEvent(actualEventsIterator, ConnectionCheckedOutEvent.class);
+                    assertAddressMatch(expectedEvent, actualEvent.getConnectionId().getServerId().getAddress());
                     assertConnectionIdMatch(expectedEvent, actualEvent.getConnectionId());
+                    assertDurationMatch(expectedEvent, actualEvent);
                 } else if (type.equals("ConnectionCheckedIn")) {
+                    assertHasOnlySupportedKeys(expectedEvent, "type", "address", "connectionId");
                     ConnectionCheckedInEvent actualEvent = getNextEvent(actualEventsIterator, ConnectionCheckedInEvent.class);
+                    assertAddressMatch(expectedEvent, actualEvent.getConnectionId().getServerId().getAddress());
                     assertConnectionIdMatch(expectedEvent, actualEvent.getConnectionId());
                 } else {
                     throw new UnsupportedOperationException("Unsupported event type " + type);
@@ -327,6 +349,16 @@ public void shouldPassAllOutcomes() throws Exception {
         }
     }
 
+    private static void assertHasOnlySupportedKeys(final BsonDocument document, final String... supportedKeys) {
+        List<String> supportedKeysList = asList(supportedKeys);
+        List<String> unsupportedKeys = document.keySet().stream()
+                .filter(key -> !supportedKeysList.contains(key))
+                .collect(Collectors.toList());
+        if (!unsupportedKeys.isEmpty()) {
+            fail(format("The runner encountered not yet supported keys %s in %s", unsupportedKeys, document));
+        }
+    }
+
     private void assertReasonMatch(final BsonDocument expectedEvent, final ConnectionClosedEvent connectionClosedEvent) {
         if (!expectedEvent.containsKey("reason")) {
             return;
@@ -400,6 +432,32 @@ private void assertConnectionIdMatch(final BsonDocument expectedEvent, final Con
         }
     }
 
+    private static void assertDurationMatch(final BsonDocument expectedEvent, final ConnectionReadyEvent actualEvent) {
+        assertDurationMatch(expectedEvent, actualEvent.getElapsedTime(TimeUnit.MILLISECONDS));
+    }
+
+    private static void assertDurationMatch(final BsonDocument expectedEvent, final ConnectionCheckOutFailedEvent actualEvent) {
+        assertDurationMatch(expectedEvent, actualEvent.getElapsedTime(TimeUnit.MILLISECONDS));
+    }
+
+    private static void assertDurationMatch(final BsonDocument expectedEvent, final ConnectionCheckedOutEvent actualEvent) {
+        assertDurationMatch(expectedEvent, actualEvent.getElapsedTime(TimeUnit.MILLISECONDS));
+    }
+
+    private static void assertDurationMatch(final BsonDocument expectedEvent, final long actualDurationMillis) {
+        String durationKey = "duration";
+        if (expectedEvent.isNumber(durationKey)) {
+            assertTrue("actualDurationMillis must not be negative", actualDurationMillis >= 0);
+            long expectedDurationMillis = expectedEvent.getNumber(durationKey).longValue();
+            if (expectedDurationMillis != ANY_INT) {
+                fail(format("Unsupported duration value %d. Pay attention to the expected value unit when supporting the value",
+                        expectedDurationMillis));
+            }
+        } else if (expectedEvent.containsKey(durationKey)) {
+            fail(format("Unsupported value %s", expectedEvent.get(durationKey)));
+        }
+    }
+
     private long adjustedConnectionIdLocalValue(final long connectionIdLocalValue) {
         if (pool instanceof ConnectionIdAdjustingConnectionPool) {
             return ((ConnectionIdAdjustingConnectionPool) pool).adjustedConnectionIdLocalValue(connectionIdLocalValue);