DRIVERS-2677: clarify when ServerHeartbeatStartedEvent should be emitted #1483

W-A-James · 2023-12-14T20:51:11Z

Changes

Specifies that ServerHeartbeatStartedEvent MUST be emitted just after monitor creates monitoring connection and before the first hello is emitted.
Add prose test to verify ordering of event emission and handshake is correct

POC on Node driver

Please complete the following before merging:

Update changelog.
Make sure there are generated JSON files from the YAML test files.
Test changes in at least one language driver.
Test these changes against all server versions and topologies (including standalone, replica set, sharded clusters, and serverless).

…irements

…tor connection creation

…rted-event-ordering

…of github.com:W-A-James/specifications into DRIVERS-2677/clarify-heartbeat-started-event-ordering

W-A-James · 2024-01-09T15:31:52Z

source/server-discovery-and-monitoring/tests/README.rst

+Heartbeat Tests
+~~~~~~~~~~~~~~~
+
+1. Test that ``ServerHeartbeatStartedEvent`` is emitted after the monitoring socket was created and before the ``hello`` is sent to the server
+
+   #. Create a mock TCP server (example shown below) that pushes a ``client connected`` event to a shared array when a client connects and a ``client hello received`` event when the server receives the client hello and then closes the connection::
+
+        let events = [];
+        server = createServer(clientSocket => {
+          events.push('client connected');
+
+          clientSocket.on('data', () => {
+            events.push('client hello received');
+            clientSocket.end();
+          });
+        });
+        server.listen(9999);
+
+   #. Create a client with ``serverSelectionTimeoutMS: 500, maxPoolSize: 1, minPoolSize: 0`` and listen to ``ServerHeartbeatStartedEvent`` and ``ServerHeartbeatFailedEvent``, pushing the event name to the same shared array as the mock TCP server.
+
+   #. Attempt to connect client to previously created TCP server, catching the error when the client fails to connect 
+
+   #. Assert that the event array has a length of 4
+
+   #. Assert that the first event is the ``client connected`` event
+
+   #. Assert that the second event is the ``serverHeartbeatStartedEvent``
+
+   #. Assert that the third event is the ``client hello received`` event
+
+   #. Assert that the fourth event is the ``serverHeartbeatFailedEvent``
+


Do we think this test will be accurate with respect to the relative ordering of events on the driver side even though we'll be using sockets (albeit locally)?

This seems to be the best approach for now since we don't have more granular logging for when the the monitoring connection is created and when the hello itself is sent.

Seems so to me.

even though we'll be using sockets

What is the implied concern here?

I was thinking of whether or not the delay between creating the connection and emitting the ServerHeartbeatStartedEvent on the client side would be shorter than the time it takes for the mock server to emit the client connected event as in the following sequence diagram:

client server

create connection .

emit heartbeat started .

. receive connection; emit client connected

send hello .

. receive hello; emit client hello received; close connection

emit heartbeat failed .

which would lead the events buffer to look like this

[ 'serverHeartbeatStartedEvent', 'client connected', 'client hello received', 'serverHeartbeatFiledEvent' ]

and report a false failure since the client actually performed the steps in the correct order

Makes sense. There is a bit of an assumption going on here that there wouldn't be any multithreading or multiprocessing forcing the server's "client connected" to strictly proceed the driver code getting an opportunity to run whatever "connection established" handling it has.

Perhaps the test could divest its core assertions a bit from the suggested implementation. A compiled language may be able to accomplish the same goal if it were to supplant the socket API with a function under its control to get notified of socket construction.

I hope there is enough prior art to make this test accessible:

https://nodejs.org/docs/latest/api/net.html#class-netserver

https://docs.python.org/3/library/socketserver.html#socketserver-tcpserver-example

https://ruby-doc.org/stdlib-2.4.0/libdoc/socket/rdoc/TCPServer.html

https://docs.oracle.com/javase/8/docs/api/java/net/ServerSocket.html

https://learn.microsoft.com/en-us/dotnet/api/system.net.sockets.tcplistener?view=net-8.0

Update: we want the order to be

['serverHeartbeatStarted', 'client connected', 'client hello received', 'serverHeartbeatFailed']

...e/server-discovery-and-monitoring/server-discovery-and-monitoring-logging-and-monitoring.rst

source/server-discovery-and-monitoring/tests/README.rst

nbbeeken · 2024-01-09T16:16:12Z

source/server-discovery-and-monitoring/tests/README.rst

+Heartbeat Tests
+~~~~~~~~~~~~~~~
+
+1. Test that ``ServerHeartbeatStartedEvent`` is emitted after the monitoring socket was created and before the ``hello`` is sent to the server
+
+   #. Create a mock TCP server (example shown below) that pushes a ``client connected`` event to a shared array when a client connects and a ``client hello received`` event when the server receives the client hello and then closes the connection::
+
+        let events = [];
+        server = createServer(clientSocket => {
+          events.push('client connected');
+
+          clientSocket.on('data', () => {
+            events.push('client hello received');
+            clientSocket.end();
+          });
+        });
+        server.listen(9999);
+
+   #. Create a client with ``serverSelectionTimeoutMS: 500, maxPoolSize: 1, minPoolSize: 0`` and listen to ``ServerHeartbeatStartedEvent`` and ``ServerHeartbeatFailedEvent``, pushing the event name to the same shared array as the mock TCP server.
+
+   #. Attempt to connect client to previously created TCP server, catching the error when the client fails to connect 
+
+   #. Assert that the event array has a length of 4
+
+   #. Assert that the first event is the ``client connected`` event
+
+   #. Assert that the second event is the ``serverHeartbeatStartedEvent``
+
+   #. Assert that the third event is the ``client hello received`` event
+
+   #. Assert that the fourth event is the ``serverHeartbeatFailedEvent``
+


Seems so to me.

even though we'll be using sockets

What is the implied concern here?

baileympearson · 2024-01-09T17:08:23Z

source/server-discovery-and-monitoring/tests/README.rst

+
+   #. Assert that the third event is the ``client hello received`` event
+
+   #. Assert that the fourth event is the ``serverHeartbeatFailedEvent``


What's the significance of the "failed" event? It seems like we could just

test against a standalone

connect

confirm the ordering of events (connected, heartbeat started, hello received, heartbeat succeeded)

The failed event is expected as the mock server doesn't need to be able to properly reply to the hello for this test to prove the ordering so we expect that it is the case that it won't. As a result, we just want to be sure that the driver fails its heartbeat since the monitoring connection will be closed. I'm open to removing that as a requirement for the test, but it seems appropriate to include.

When you say test against a standalone, how would we track when the connection was created and the hello was received when testing against an actual Mongo server?

baileympearson · 2024-01-09T21:04:18Z

...e/server-discovery-and-monitoring/server-discovery-and-monitoring-logging-and-monitoring.rst

@@ -138,7 +138,7 @@ Events that MUST be published (with their conditions) are as follows.
   * - ``TopologyClosedEvent``
     - When a topology is shut down - this MUST be the last SDAM event fired.
   * - ``ServerHeartbeatStartedEvent``
-     - Published when the server monitor sends its ``hello`` or legacy hello call to the server.
+     - Published when the server monitor sends its ``hello`` or legacy hello call to the server. When the monitor is creating a new connection, this event MUST be published just after the socket is created and just before the ``hello`` or legacy hello.


is this right? I don't think this is what we do in Node. we emit heartbeat started events before establishing a socket (before a call to connect)

Shane and I are discussing this further, but our initial decision was to do what we currently do in the Node driver, but this does make it so that the the duration on the first ServerHeartbeatSucceededEvent would include the time taken to complete the TCP handshake which adds at least another network round trip, artificially inflating the RTT since that gets calculated from the aforementioned duration field.

How I currently have this written would avoid this, but would require changes in the Node driver among others.

Update: Will change this to expect the ServerHeartbeatStartedEvent before connection creation. There was confusion on my end as I thought we had to measure the start time as when the ServerHeartbeatStartedEvent was emitted. On Node's end this will require still require us to change how we implement our monitoring since we currently measure the heartbeat duration starting as mentioned above.

W-A-James · 2024-01-11T18:33:10Z

source/server-discovery-and-monitoring/tests/README.rst

+1. Test that ``ServerHeartbeatStartedEvent`` is emitted after the monitoring socket was created and before the ``hello`` is sent to the server
+
+   #. Create a mock TCP server (example shown below) that pushes a ``client connected`` event to a shared array when a client connects and a ``client hello received`` event when the server receives the client hello and then closes the connection::
+
+        let events = [];
+        server = createServer(clientSocket => {
+          events.push('client connected');
+
+          clientSocket.on('data', () => {
+            events.push('client hello received');
+            clientSocket.end();
+          });
+        });
+        server.listen(9999);
+
+   #. Create a client with ``serverSelectionTimeoutMS: 500`` and listen to ``ServerHeartbeatStartedEvent`` and ``ServerHeartbeatFailedEvent``, pushing the event name to the same shared array as the mock TCP server.
+
+   #. Attempt to connect client to previously created TCP server, catching the error when the client fails to connect 
+
+   #. Assert that the event array has the following contents in the same order:: 
+
+        ['serverHeartbeatStartedEvent', 'client connected', 'client hello received', 'serverHeartbeatFailedEvent']


@ShaneHarvey

Since we're concerned with the the fact that the ServerHeartbeatStartedEvent gets emitted before the connection is created and so we should fail if the connection fails to be established, would it be sufficient for us to just try to connect to a port that has nothing listening on it and expect to get a ServerHeartbeatStartedEvent followed by a ServerHeartbeatFailedEvent, or do we want to keep this granularity?

Yes I think that test would work as well. Would it be easier to implement?

Yes, it would. It wouldn't require the mock server at all.

Revisiting this test; unless a driver can spy on the function that creates the socket, the updated version of this test wouldn't prevent something like this from passing:

let socketOrError = await connect().catch(error => error); if (isSocket(socketOrError)) { emitHBStarted() await runHeartBeat() } else { emitHBStarted() throw socketOrError; } // Assume emitHBFailed will be done if any of the above throws

We should roll back to actually using the mock server as that will provide a stronger guarantee on the ordering we want to test here.

ShaneHarvey · 2024-01-11T20:22:18Z

...e/server-discovery-and-monitoring/server-discovery-and-monitoring-logging-and-monitoring.rst

@@ -138,7 +138,7 @@ Events that MUST be published (with their conditions) are as follows.
   * - ``TopologyClosedEvent``
     - When a topology is shut down - this MUST be the last SDAM event fired.
   * - ``ServerHeartbeatStartedEvent``
-     - Published when the server monitor sends its ``hello`` or legacy hello call to the server.
+     - Published when the server monitor sends its ``hello`` or legacy hello call to the server. When the monitor is creating a new connection, this event MUST be published just before the socket is created


Missing punctuation: created.

ShaneHarvey · 2024-01-11T20:23:26Z

...e/server-discovery-and-monitoring/server-discovery-and-monitoring-logging-and-monitoring.rst

+If the ``serverConnectionId`` is not yet known at the time this log is emitted, the unstructured form SHOULD be as follows:
+
+  Heartbeat started for {{serverHost}}:{{serverPort}} on connection with driver-generated ID {{driverConnectionId}} in topology with ID
+  {{topologyId}}. Awaited: {{awaited}}


Is this documenting behavior that's already tested? Or do we need a new test for this?

I'd note that this seems unrelated to DRIVERS-2677. Can we open a new drivers ticket for this change?

This is new behaviour that needs to be tested, but can't be until a new DRIVERS ticket to add serverConnectionId to ServerHeartbeatStartedEvent as an optional field is created. I'm open to removing this until that ticket is filed and in progress.

Cool, I vote we move it out to that ticket to avoid confusion and reduce the scope here.

ShaneHarvey · 2024-01-11T20:24:09Z

source/server-discovery-and-monitoring/tests/README.rst

+Heartbeat Tests
+~~~~~~~~~~~~~~~
+
+1. Test that ``ServerHeartbeatStartedEvent`` is emitted after the monitoring socket was created and before the ``hello`` is sent to the server


emitted after the monitoring socket was created
This is the opposite of what the current spec says.

ShaneHarvey · 2024-01-11T20:26:35Z

source/server-discovery-and-monitoring/tests/README.rst

+1. Test that ``ServerHeartbeatStartedEvent`` is emitted after the monitoring socket was created and before the ``hello`` is sent to the server
+
+   #. Create a mock TCP server (example shown below) that pushes a ``client connected`` event to a shared array when a client connects and a ``client hello received`` event when the server receives the client hello and then closes the connection::
+
+        let events = [];
+        server = createServer(clientSocket => {
+          events.push('client connected');
+
+          clientSocket.on('data', () => {
+            events.push('client hello received');
+            clientSocket.end();
+          });
+        });
+        server.listen(9999);
+
+   #. Create a client with ``serverSelectionTimeoutMS: 500`` and listen to ``ServerHeartbeatStartedEvent`` and ``ServerHeartbeatFailedEvent``, pushing the event name to the same shared array as the mock TCP server.
+
+   #. Attempt to connect client to previously created TCP server, catching the error when the client fails to connect 
+
+   #. Assert that the event array has the following contents in the same order:: 
+
+        ['serverHeartbeatStartedEvent', 'client connected', 'client hello received', 'serverHeartbeatFailedEvent']


Yes I think that test would work as well. Would it be easier to implement?

ShaneHarvey

Could we remove the serverConnectionId bits from the PR title and description?

ShaneHarvey · 2024-01-12T00:13:24Z

...e/server-discovery-and-monitoring/server-discovery-and-monitoring-logging-and-monitoring.rst

@@ -462,7 +464,7 @@ The following key-value pairs are common to all or several log messages and MUST
   * - serverConnectionId
     - Heartbeat-related log messages
     - Int
-     - The server's ID for the monitoring connection, if known. This value will be unknown and can be omitted in certain cases, e.g. the first
+     - The server's ID for the monitoring connection, if known. This value will be unknown and MUST be omitted in certain cases, e.g. the first


This should also be pushed out to the other ticket.

ShaneHarvey · 2024-01-12T00:19:44Z

source/server-discovery-and-monitoring/tests/README.rst

+
+   #. Attempt to connect client to a local port that is not listening for connections. e.g. ``mongodb://localhost:9999``
+
+   #. Assert that the event array has the following contents in the same order:: 


Since SDAM can try to connect multiple times, I would say:
"Assert that the first two events in the array are::"

ShaneHarvey

LGTM!

W-A-James and others added 4 commits December 14, 2023 15:50

DRIVERS-2677: clarify heartbeat started event ordering and field requ…

c5deb51

…irements

DRIVERS-2677 Clarify ordering of ServerHeartbeatStartedEvent and moni…

00304ba

…tor connection creation

Correct typo

a57b4b3

Merge branch 'mongodb:master' into DRIVERS-2677/clarify-heartbeat-sta…

e6a59c7

…rted-event-ordering

W-A-James changed the title ~~DRIVERS-2677: clarify heartbeat started event ordering and field requ…~~ DRIVERS-2677: clarify when ServerHeartbeatStartedEvent should be emitted and when serverConnectionId should be undefined Jan 5, 2024

W-A-James added 14 commits January 5, 2024 11:49

Update wording on undefined value

5e186b5

Merge branch 'DRIVERS-2677/clarify-heartbeat-started-event-ordering' …

d6bc209

…of github.com:W-A-James/specifications into DRIVERS-2677/clarify-heartbeat-started-event-ordering

Update wording on undefined value

879e676

add rationale

fd946d2

revise ordering

6372ba3

Update spacing

5816c83

Add prose test in progress

3bc7921

formatting

c448f03

formatting

b767798

formatting

cedb0a2

formatting

f236489

ordering

e1d798d

add new prose test

8d1b6be

remove old prose test

1279fa8

W-A-James commented Jan 9, 2024

View reviewed changes

W-A-James marked this pull request as ready for review January 9, 2024 15:38

W-A-James requested a review from a team as a code owner January 9, 2024 15:38

W-A-James requested review from esha-bhargava and ShaneHarvey and removed request for a team January 9, 2024 15:38

nbbeeken requested changes Jan 9, 2024

View reviewed changes

baileympearson reviewed Jan 9, 2024

View reviewed changes

W-A-James added 3 commits January 9, 2024 14:40

remove poolSize settings

434acab

Fix wording and remove unnecessary config

9ec5ddf

refine wording

d8ecff3

W-A-James added 2 commits January 9, 2024 14:53

strengthen wording

ee6c986

remove backticks

1072e22

W-A-James requested a review from nbbeeken January 9, 2024 19:55

baileympearson reviewed Jan 9, 2024

View reviewed changes

W-A-James added 2 commits January 10, 2024 16:22

Reorder events

6b93f0c

capitalize

6b0e0ee

nbbeeken approved these changes Jan 10, 2024

View reviewed changes

W-A-James commented Jan 11, 2024

View reviewed changes

ShaneHarvey requested changes Jan 11, 2024

View reviewed changes

W-A-James added 2 commits January 11, 2024 16:09

Fix spelling and update prose test

c6cc625

Remove section on serverConnectionId

9d33a89

W-A-James requested a review from ShaneHarvey January 11, 2024 21:20

ShaneHarvey requested changes Jan 12, 2024

View reviewed changes

W-A-James changed the title ~~DRIVERS-2677: clarify when ServerHeartbeatStartedEvent should be emitted and when serverConnectionId should be undefined~~ DRIVERS-2677: clarify when ServerHeartbeatStartedEvent should be emitted Jan 12, 2024

Remove references to serverConnectionId

ac2e8bc

W-A-James requested a review from ShaneHarvey January 12, 2024 20:35

update prose tests

8969f1f

W-A-James requested review from ShaneHarvey and removed request for ShaneHarvey January 16, 2024 19:24

ShaneHarvey approved these changes Jan 16, 2024

View reviewed changes

W-A-James merged commit f1bbc24 into mongodb:master Jan 17, 2024
4 checks passed

W-A-James deleted the DRIVERS-2677/clarify-heartbeat-started-event-ordering branch January 17, 2024 16:15

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

DRIVERS-2677: clarify when ServerHeartbeatStartedEvent should be emitted #1483

DRIVERS-2677: clarify when ServerHeartbeatStartedEvent should be emitted #1483

W-A-James commented Dec 14, 2023 •

edited

Loading

W-A-James Jan 9, 2024

nbbeeken Jan 9, 2024

W-A-James Jan 9, 2024

nbbeeken Jan 9, 2024

W-A-James Jan 10, 2024

nbbeeken Jan 9, 2024

baileympearson Jan 9, 2024

W-A-James Jan 9, 2024

baileympearson Jan 9, 2024

W-A-James Jan 10, 2024

W-A-James Jan 10, 2024

W-A-James Jan 11, 2024

ShaneHarvey Jan 11, 2024

W-A-James Jan 11, 2024

W-A-James Jan 12, 2024

ShaneHarvey Jan 11, 2024

ShaneHarvey Jan 11, 2024

ShaneHarvey Jan 11, 2024

W-A-James Jan 11, 2024

ShaneHarvey Jan 11, 2024 •

edited

Loading

ShaneHarvey Jan 11, 2024

W-A-James Jan 11, 2024

ShaneHarvey Jan 11, 2024

ShaneHarvey left a comment

ShaneHarvey Jan 12, 2024

ShaneHarvey Jan 12, 2024

ShaneHarvey left a comment

client	server
create connection	.
emit heartbeat started	.
.	receive connection; emit `client connected`
send hello	.
.	receive hello; emit `client hello received`; close connection
emit heartbeat failed	.


		#. Assert that the third event is the ``client hello received`` event

		#. Assert that the fourth event is the ``serverHeartbeatFailedEvent``


		#. Attempt to connect client to a local port that is not listening for connections. e.g. ``mongodb://localhost:9999``

		#. Assert that the event array has the following contents in the same order::

DRIVERS-2677: clarify when ServerHeartbeatStartedEvent should be emitted #1483

DRIVERS-2677: clarify when ServerHeartbeatStartedEvent should be emitted #1483

Conversation

W-A-James commented Dec 14, 2023 • edited Loading

Changes

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ShaneHarvey Jan 11, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ShaneHarvey left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ShaneHarvey left a comment

Choose a reason for hiding this comment

W-A-James commented Dec 14, 2023 •

edited

Loading

ShaneHarvey Jan 11, 2024 •

edited

Loading