RUST-1587 Implement server selection tracing events #805

kmahar · 2023-01-12T20:22:37Z

This implements the server selection tracing/log events/messages as defined in mongodb/specifications#1341.

There is a workaround in here for the fact that we still currently perform server selection to detect sessions support; logging messages in those cases makes these tests flaky. That flakiness is why the spec PR hasn't been merged yet, though I expect for any driver that doesn't log on server selection attempts for sessions support the tests will pass.

We could merge this and remove the workaround as part of RUST-1499, or alternatively we can wait to merge until that work is in; I don't have a strong opinion either way.

Will leave some more comments inline.

kmahar · 2023-01-12T20:28:32Z

src/event/sdam/topology_description.rs

@@ -11,7 +11,8 @@ use crate::{

 /// A description of the most up-to-date information known about a topology. Further details can
 /// be found in the [Server Discovery and Monitoring specification](https://github.com/mongodb/specifications/blob/master/source/server-discovery-and-monitoring/server-discovery-and-monitoring.rst).
-#[derive(Clone)]
+#[derive(Clone, derive_more::Display)]
+#[display(fmt = "{}", description)]


this just means that the output will be the Display impl for description. I took advantage of derive_more::Display in a couple places in this PR for the sake of brevity.

also, it was an intentional choice to leave Display prefixed with derive_more rather than importing it throughout this PR. I found myself confused other places in the code base that we were using an imported derive_more because it is easy to mistake it for the std trait with the same name.

kmahar · 2023-01-12T20:29:47Z

src/event/sdam/topology_description.rs

@@ -102,38 +103,3 @@ impl fmt::Debug for TopologyDescription {
            .finish()
    }
 }
-
-impl fmt::Display for TopologyDescription {


this implementation was combined with the existing and more bare-bones implementation of Display on the internal crate::sdam::TopologyDescription type, so that this logic can be reused for the tracing messages, where we only have the internal type available.

kmahar · 2023-01-12T20:30:46Z

src/sdam/description/topology/mod.rs

@@ -25,7 +25,7 @@ use crate::{
 use self::server_selection::IDLE_WRITE_PERIOD;

 /// The possible types for a topology.
-#[derive(Debug, Clone, Copy, Eq, PartialEq, Deserialize, Serialize)]
+#[derive(Debug, Clone, Copy, Eq, PartialEq, Deserialize, Serialize, derive_more::Display)]


it seemed worth adding Display here for use in TopologyDescription's Display impl.

kmahar · 2023-01-12T20:34:47Z

src/sdam/description/topology/server_selection/mod.rs

-        write!(f, "{{ Type: {:?}, Servers: [ ", self.topology_type)?;
-        for server_info in self.servers.values().map(ServerInfo::new_borrowed) {
-            write!(f, "{}, ", server_info)?;
+    fn fmt(&self, f: &mut fmt::Formatter) -> std::result::Result<(), fmt::Error> {


this logic is largely copied over from the event::sdam::TopologyDescription implementation.

kmahar · 2023-01-12T20:35:46Z

src/selection_criteria.rs

@@ -13,18 +13,20 @@ use crate::{
 };

 /// Describes which servers are suitable for a given operation.
-#[derive(Clone, Derivative)]
+#[derive(Clone, Derivative, derive_more::Display)]


see unit tests in src/test/spec/trace.rs to see how the SelectionCriteria gets stringified by this logic.

kmahar · 2023-01-12T20:37:54Z

src/test/spec/unified_runner/entity.rs

@@ -128,13 +128,16 @@ impl TestCursor {

 impl ClientEntity {
    pub(crate) fn new(
-        client: Client,
+        client_options: ClientOptions,


related to the issue we discussed in standup/slack, we just pass the options here now so we can make sure the observer exists first.

kmahar · 2023-01-12T20:41:47Z

src/test/spec/unified_runner/test_runner.rs

@@ -281,7 +280,7 @@ impl TestRunner {
                self.sync_workers().await;

                let all_tracing_events = tracing_subscriber
-                    .collect_events(Duration::from_millis(500), |_| true)
+                    .collect_events(Duration::from_millis(1000), |_| true)


I was running into some cases on macOS sharded clusters with SSL/auth/compression where we occasionally wouldn't see all of the tracing events within 500ms. increasing this fixed that

kmahar · 2023-01-12T20:59:55Z

src/trace.rs

    type Representation;

-    fn tracing_representation(self) -> Self::Representation;
+    fn tracing_representation(&self) -> Self::Representation;


the only implementation of this trait that needed to take ownership of the value was for bson::Document. to save a bunch of unneeded clones of e.g. the topology description, I opted to update this to take self by reference and to remove the implementation of the trait for bson::Document. all document serialization is already currently handled via serialize_command_or_reply so it seemed OK to not rely on the trait and just serialize directly in that method.

abr-egn · 2023-01-13T19:55:25Z

src/client/mod.rs

-                        .description
-                        .server_selection_timeout_error_message(criteria),
+            );
+            match result {


It's really unfortunate how much noise this adds to the function - can logging be factored out to helper methods?

great idea, done. I ended up adding a helper type to store the shared info and avoid having to pass it with each message. this matches nicely with our existing XEventEmitter types for CMAP and command tracing.

…-tracing

abr-egn

LGTM! Just a few comments that don't require re-review.

abr-egn · 2023-01-31T19:06:40Z

src/client/mod.rs

@@ -480,13 +481,18 @@ impl Client {
        &self,
        criteria: Option<&SelectionCriteria>,
    ) -> Result<ServerAddress> {
-        let server = self.select_server(criteria).await?;
+        let server = self.select_server(criteria, "test_select_server").await?;


The names given elsewhere are short phrases rather than a snake_case tag, might be better to be consistent one way or the other.

renamed to "Test select server" for consistency.

abr-egn · 2023-01-31T19:07:35Z

src/client/mod.rs

-                        .description
-                        .server_selection_timeout_error_message(criteria),
+            );
+            match result {


abr-egn · 2023-01-31T19:11:17Z

src/trace/server_selection.rs

+    ) {
+        if trace_or_log_enabled!(target: SERVER_SELECTION_TRACING_EVENT_TARGET, TracingOrLogLevel::Debug)
+        // TODO: RUST-1585 Remove this condition.
+        && self.operation_name != "Check sessions support status"


Since these values are being matched on, they should be named constants.

good point. since the constant needs to be used unconditional of the tracing feature (in get_session_support_status), this couldn't be hidden away in the trace module. I ended up putting it in client/mod.rs for now.

kmahar · 2023-02-01T18:42:37Z

pushed one more small change: I noticed that the other event emitter types were named XTracingEventEmitter but this one was missing the Tracing bit so I've renamed the type.

isabelatkinson

lgtm!

…-tracing

kmahar added 8 commits January 11, 2023 16:23

wip

9ef4a1f

undo moving variable

d4a4e95

get rid of dead code warning

51a965b

don't log sessions support checks

62f4303

use correct selector repr

ce53f0f

increase event collection window

88dba9b

create client after observer to avoid initial event race

50c4182

get rid of document clone

175fb2d

kmahar commented Jan 12, 2023

View reviewed changes

kmahar marked this pull request as ready for review January 12, 2023 21:01

kmahar requested review from a team, JamesKovacs and abr-egn and removed request for a team and JamesKovacs January 12, 2023 21:01

kmahar changed the title ~~RUST-1495 Implement server selection tracing event~~ RUST-1495 Implement server selection tracing events Jan 12, 2023

abr-egn reviewed Jan 13, 2023

View reviewed changes

factor out code for server selection events into helper type

d18f1b9

kmahar changed the title ~~RUST-1495 Implement server selection tracing events~~ RUST-1587 Implement server selection tracing events Jan 31, 2023

kmahar added 2 commits January 31, 2023 10:55

skip flaky tests, update TODOs

a58179d

Merge remote-tracking branch 'origin' into RUST-1495/server-selection…

687989f

…-tracing

abr-egn approved these changes Jan 31, 2023

View reviewed changes

abr-egn requested a review from isabelatkinson January 31, 2023 19:11

kmahar added 2 commits January 31, 2023 14:46

review comments

6a2c9f5

rename event emitter type

a672066

isabelatkinson approved these changes Feb 1, 2023

View reviewed changes

Merge remote-tracking branch 'origin' into RUST-1495/server-selection…

9ccb9c8

…-tracing

kmahar merged commit fa952f4 into mongodb:main Feb 2, 2023

kmahar deleted the RUST-1495/server-selection-tracing branch February 2, 2023 00:56

RUST-1587 Implement server selection tracing events #805

RUST-1587 Implement server selection tracing events #805

Uh oh!

Conversation

kmahar commented Jan 12, 2023

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

abr-egn left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

kmahar commented Feb 1, 2023

Uh oh!

isabelatkinson left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!