[JAVA-6033] ServerHeartbeatSucceededEvent is not fired for initial POLL monitoring

[nhachicha]

JAVA-6033

[nhachicha]

Test fails as expected https://parsley.corp.mongodb.com/test/mongo_java_driver_tests_jdk8_unsecure__version~4.2_os~linux_topology~replicaset_auth~noauth_ssl~nossl_jdk~jdk8_test_core_task_patch_69a3c1d789271eeee0f5495bd4b6aab2774fec64_6942d2fe80720c0007597da3_25_12_17_15_57_53/0/aaf151003c2ecbd4364096361cc4cd62?bookmarks=0,26&shareLine=0

[rozza]

LGTM - if evergreen's happy, I'm happy

[rozza]

LGTM!

[vbabanin]

Currently, we send two hello commands back-to-back but emit only one sequence of events as if only one heartbeat was sent.

When establishing a new connection, the flow looks like this:

1. At line 286, setupNewConnectionAndGetInitialDescription() calls logAndNotifyHeartbeatStarted() and sets alreadyLoggedHeartBeatStarted = true.
2. We receive the handshake result and return it as the ServerDescription.
3. We detect that this is the initial connection and immediately loop again.
4. On the next loop iteration, we hit line 264, but alreadyLoggedHeartBeatStarted is still true, so we don’t log another “started” event.

We then call doHeartbeat(), which sends a second hello command, without waiting for the selection heartbeat timeout. When it succeeds at line 322, we log the “succeeded” event and reset the flag alreadyLoggedHeartBeatStarted = false.

As a result we get:

• 1 ServerHeartbeatStartedEvent (for the first hello / handshake)
• 2 hello commands sent back-to-back
• 1 ServerHeartbeatSucceededEvent (for the second hello)

This conflicts with the SDAM spec, which requires a correlation between started and succeeded/failed events, and also seem to require treating an initial handshake as a heartbeat event:

“The driver MUST guarantee that every ServerHeartbeatStartedEvent has either a correlating ServerHeartbeatSucceededEvent or ServerHeartbeatFailedEvent.”

“The driver MUST publish a ServerHeartbeatStartedEvent before the driver opens a connection for the next heartbeat to a server…”

Judging by the above, the initial handshake appears to be treated as the first heartbeat. The unified tests confirm this expectation, for example, the serverMonitoringMode.yml unified test explicitly expects this sequence in streaming mode:

serverHeartbeatStartedEvent (awaited: false) - handshake
serverHeartbeatSucceededEvent (awaited: false) - handshake
serverHeartbeatStartedEvent (awaited: false) - next poll after waiting

If we run this test with the current implementation, we get:

HEARTBEAT STARTED connectionId{localValue:7} awaited: false
HEARTBEAT STARTED connectionId{localValue:7, serverValue:242} awaited: true

So the correlation between ServerHeartbeatStartedEvent and ServerHeartbeatSucceededEvent (in terms of awaited) does not match the expectations, and the test fails. These tests are currently ignored here:
https://github.com/vbabanin/mongo-java-driver/blob/5cb23ba8e2a9da83857f3e2f7bbb7e5cfc8dcbe2/driver-sync/src/test/functional/com/mongodb/client/unified/UnifiedTestModifications.java#L410-L412 - the associated ticket is already closed, and I wasn’t able to find additional details on the reason for skipping these tests.

Given the above, it seems we should:

• Align the behavior with the spec (that we missed before this PR) so that the handshake acts as the first heartbeat and we don’t send an extra hello.
• Re-enable the ignored SDAM unified tests.

What do you think?

P.S: We send a ServerHeartbeatSucceededEvent right after receiving the regular heartbeat response. We could do the same for the initial connection: emit the succeeded event right after open, since open already includes receiving the handshake.

connection.open(operationContextFactory.create());
roundTripTimeSampler.addSample(connection.getInitialServerDescription().getRoundTripTimeNanos());

logAndNotifyHeartbeatSucceeded(.....)