Test that durations are included on relevant pool events (#1370)

stIncMale · web-flow · commit f9edd86a7f01 · 2024-04-23T09:22:48.000-06:00
JAVA-5426
diff --git a/driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-checkin-make-available.json b/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": [
diff --git a/driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-checkout-connection.json b/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": [
diff --git a/driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-checkout-error-closed.json b/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"
     }
   ],
diff --git a/driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-checkout-maxConnecting-timeout.json b/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": [
diff --git a/driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-clear-clears-waitqueue.json b/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": [
diff --git a/driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-clear-ready.json b/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": [
diff --git a/driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/pool-ready.json b/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": [
diff --git a/driver-core/src/test/resources/connection-monitoring-and-pooling/cmap-format/wait-queue-timeout.json b/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",
diff --git a/driver-core/src/test/unit/com/mongodb/internal/connection/AbstractConnectionPoolTest.java b/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);

Original file line number	Diff line number	Diff line change
`@@ -22,7 +22,8 @@`
`22`	`22`	`{`
`23`	`23`	`"type": "ConnectionCheckedOut",`
`24`	`24`	`"connectionId": 1,`
`25`		`- "address": 42`
	`25`	`+ "address": 42,`
	`26`	`+ "duration": 42`
`26`	`27`	`},`
`27`	`28`	`{`
`28`	`29`	`"type": "ConnectionCheckedIn",`
`@@ -32,7 +33,8 @@`
`32`	`33`	`{`
`33`	`34`	`"type": "ConnectionCheckedOut",`
`34`	`35`	`"connectionId": 1,`
`35`		`- "address": 42`
	`36`	`+ "address": 42,`
	`37`	`+ "duration": 42`
`36`	`38`	`}`
`37`	`39`	`],`
`38`	`40`	`"ignore": [`
Original file line number	Diff line number	Diff line change
`@@ -23,12 +23,14 @@`
`23`	`23`	`{`
`24`	`24`	`"type": "ConnectionReady",`
`25`	`25`	`"connectionId": 1,`
`26`		`- "address": 42`
	`26`	`+ "address": 42,`
	`27`	`+ "duration": 42`
`27`	`28`	`},`
`28`	`29`	`{`
`29`	`30`	`"type": "ConnectionCheckedOut",`
`30`	`31`	`"connectionId": 1,`
`31`		`- "address": 42`
	`32`	`+ "address": 42,`
	`33`	`+ "duration": 42`
`32`	`34`	`}`
`33`	`35`	`],`
`34`	`36`	`"ignore": [`
Original file line number	Diff line number	Diff line change
`@@ -38,7 +38,8 @@`
`38`	`38`	`{`
`39`	`39`	`"type": "ConnectionCheckedOut",`
`40`	`40`	`"address": 42,`
`41`		`- "connectionId": 42`
	`41`	`+ "connectionId": 42,`
	`42`	`+ "duration": 42`
`42`	`43`	`},`
`43`	`44`	`{`
`44`	`45`	`"type": "ConnectionCheckedIn",`
`@@ -56,6 +57,7 @@`
`56`	`57`	`{`
`57`	`58`	`"type": "ConnectionCheckOutFailed",`
`58`	`59`	`"address": 42,`
	`60`	`+ "duration": 42,`
`59`	`61`	`"reason": "poolClosed"`
`60`	`62`	`}`
`61`	`63`	`],`
Original file line number	Diff line number	Diff line change
`@@ -89,7 +89,8 @@`
`89`	`89`	`{`
`90`	`90`	`"type": "ConnectionCheckOutFailed",`
`91`	`91`	`"reason": "timeout",`
`92`		`- "address": 42`
	`92`	`+ "address": 42,`
	`93`	`+ "duration": 42`
`93`	`94`	`}`
`94`	`95`	`],`
`95`	`96`	`"ignore": [`
Original file line number	Diff line number	Diff line change
`@@ -59,7 +59,8 @@`
`59`	`59`	`},`
`60`	`60`	`{`
`61`	`61`	`"type": "ConnectionCheckedOut",`
`62`		`- "address": 42`
	`62`	`+ "address": 42,`
	`63`	`+ "duration": 42`
`63`	`64`	`},`
`64`	`65`	`{`
`65`	`66`	`"type": "ConnectionCheckOutStarted",`
`@@ -76,17 +77,20 @@`
`76`	`77`	`{`
`77`	`78`	`"type": "ConnectionCheckOutFailed",`
`78`	`79`	`"reason": "connectionError",`
`79`		`- "address": 42`
	`80`	`+ "address": 42,`
	`81`	`+ "duration": 42`
`80`	`82`	`},`
`81`	`83`	`{`
`82`	`84`	`"type": "ConnectionCheckOutFailed",`
`83`	`85`	`"reason": "connectionError",`
`84`		`- "address": 42`
	`86`	`+ "address": 42,`
	`87`	`+ "duration": 42`
`85`	`88`	`},`
`86`	`89`	`{`
`87`	`90`	`"type": "ConnectionCheckOutFailed",`
`88`	`91`	`"reason": "connectionError",`
`89`		`- "address": 42`
	`92`	`+ "address": 42,`
	`93`	`+ "duration": 42`
`90`	`94`	`}`
`91`	`95`	`],`
`92`	`96`	`"ignore": [`
Original file line number	Diff line number	Diff line change
`@@ -40,7 +40,8 @@`
`40`	`40`	`{`
`41`	`41`	`"type": "ConnectionCheckedOut",`
`42`	`42`	`"address": 42,`
`43`		`- "connectionId": 42`
	`43`	`+ "connectionId": 42,`
	`44`	`+ "duration": 42`
`44`	`45`	`},`
`45`	`46`	`{`
`46`	`47`	`"type": "ConnectionPoolCleared",`
`@@ -49,6 +50,7 @@`
`49`	`50`	`{`
`50`	`51`	`"type": "ConnectionCheckOutFailed",`
`51`	`52`	`"address": 42,`
	`53`	`+ "duration": 42,`
`52`	`54`	`"reason": "connectionError"`
`53`	`55`	`},`
`54`	`56`	`{`
`@@ -57,7 +59,8 @@`
`57`	`59`	`},`
`58`	`60`	`{`
`59`	`61`	`"type": "ConnectionCheckedOut",`
`60`		`- "address": 42`
	`62`	`+ "address": 42,`
	`63`	`+ "duration": 42`
`61`	`64`	`}`
`62`	`65`	`],`
`63`	`66`	`"ignore": [`
Original file line number	Diff line number	Diff line change
`@@ -31,7 +31,8 @@`
`31`	`31`	`{`
`32`	`32`	`"type": "ConnectionCheckOutFailed",`
`33`	`33`	`"reason": "connectionError",`
`34`		`- "address": 42`
	`34`	`+ "address": 42,`
	`35`	`+ "duration": 42`
`35`	`36`	`},`
`36`	`37`	`{`
`37`	`38`	`"type": "ConnectionPoolReady",`
`@@ -47,7 +48,8 @@`
`47`	`48`	`},`
`48`	`49`	`{`
`49`	`50`	`"type": "ConnectionCheckedOut",`
`50`		`- "address": 42`
	`51`	`+ "address": 42,`
	`52`	`+ "duration": 42`
`51`	`53`	`}`
`52`	`54`	`],`
`53`	`55`	`"ignore": [`
Original file line number	Diff line number	Diff line change
`@@ -48,7 +48,8 @@`
`48`	`48`	`{`
`49`	`49`	`"type": "ConnectionCheckedOut",`
`50`	`50`	`"connectionId": 42,`
`51`		`- "address": 42`
	`51`	`+ "address": 42,`
	`52`	`+ "duration": 42`
`52`	`53`	`},`
`53`	`54`	`{`
`54`	`55`	`"type": "ConnectionCheckOutStarted",`
`@@ -57,7 +58,8 @@`
`57`	`58`	`{`
`58`	`59`	`"type": "ConnectionCheckOutFailed",`
`59`	`60`	`"reason": "timeout",`
`60`		`- "address": 42`
	`61`	`+ "address": 42,`
	`62`	`+ "duration": 42`
`61`	`63`	`},`
`62`	`64`	`{`
`63`	`65`	`"type": "ConnectionCheckedIn",`