Skip to content

Commit d08d455

Browse files
author
mdbmes
authored
CDRIVER-4487 server selection logging (#1821)
This change addresses CDRIVER-4487 (structured log messages for server selection) * src/libmongoc/tests/json/server_selection/* were synchronized from the specifications repo, commit ccb981601f3400784d187bb583b5c3d1dac7a963 * src/libmongoc/tests/mock_server/future* were auto-generated by build/generate-future-functions.py * Adds a new "server selection log context" that must be supplied to functions like mongoc_topology_select, to indicate which operation the server selection takes place for. * log messages: server selection started/ended, waiting for suitable server to become available * Added server_selection/logging to unified test runner * unified runner: add topologyDescriptionChangedEvent * unified tests: URI parameters need to be case insensitive * more serialization for topology descriptions * test_check_event: previousDescription and newDescription fields
1 parent 7ec599e commit d08d455

File tree

72 files changed

+2469
-173
lines changed

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

72 files changed

+2469
-173
lines changed

‎build/generate-future-functions.py

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -102,6 +102,8 @@
102102
typedef("const_mongoc_read_prefs_ptr", "const mongoc_read_prefs_t *"),
103103
typedef("const_mongoc_write_concern_ptr",
104104
"const mongoc_write_concern_t *"),
105+
typedef("const_mongoc_ss_log_context_ptr",
106+
"const mongoc_ss_log_context_t *"),
105107
]
106108

107109
type_list = [T.name for T in typedef_list]
@@ -453,6 +455,7 @@
453455
"mongoc_topology_select",
454456
[param("mongoc_topology_ptr", "topology"),
455457
param("mongoc_ss_optype_t", "optype"),
458+
param("const_mongoc_ss_log_context_ptr", "log_context"),
456459
param("const_mongoc_read_prefs_ptr", "read_prefs"),
457460
param("bool_ptr", "must_use_primary"),
458461
param("bson_error_ptr", "error")]),

‎src/libmongoc/src/mongoc/mongoc-aggregate.c

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -295,7 +295,8 @@ _mongoc_aggregate (mongoc_client_t *client,
295295
cursor->is_aggr_with_write_stage = has_write_key;
296296

297297
/* server id isn't enough. ensure we're connected & know wire version */
298-
server_stream = _mongoc_cursor_fetch_stream (cursor);
298+
const mongoc_ss_log_context_t ss_log_context = {.operation = "aggregate"};
299+
server_stream = _mongoc_cursor_fetch_stream (cursor, &ss_log_context);
299300
if (!server_stream) {
300301
GOTO (done);
301302
}

‎src/libmongoc/src/mongoc/mongoc-bulk-operation.c

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -777,20 +777,23 @@ mongoc_bulk_operation_execute (mongoc_bulk_operation_t *bulk, /* IN */
777777
}
778778

779779
for (size_t i = 0u; i < bulk->commands.len; i++) {
780+
command = &_mongoc_array_index (&bulk->commands, mongoc_write_command_t, i);
781+
780782
if (bulk->server_id) {
781783
server_stream = mongoc_cluster_stream_for_server (
782784
cluster, bulk->server_id, true /* reconnect_ok */, bulk->session, reply, error);
783785
} else {
784-
server_stream = mongoc_cluster_stream_for_writes (cluster, bulk->session, NULL, reply, error);
786+
const mongoc_ss_log_context_t ss_log_context = {.operation = _mongoc_write_command_get_name (command),
787+
.has_operation_id = true,
788+
.operation_id = command->operation_id};
789+
server_stream = mongoc_cluster_stream_for_writes (cluster, &ss_log_context, bulk->session, NULL, reply, error);
785790
}
786791

787792
if (!server_stream) {
788793
/* stream_for_server and stream_for_writes initialize reply on error */
789794
RETURN (false);
790795
}
791796

792-
command = &_mongoc_array_index (&bulk->commands, mongoc_write_command_t, i);
793-
794797
_mongoc_write_command_execute (command,
795798
bulk->client,
796799
server_stream,

‎src/libmongoc/src/mongoc/mongoc-bulkwrite.c

Lines changed: 10 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1558,6 +1558,9 @@ mongoc_bulkwrite_execute (mongoc_bulkwrite_t *self, const mongoc_bulkwriteopts_t
15581558
goto fail;
15591559
}
15601560

1561+
const mongoc_ss_log_context_t ss_log_context = {
1562+
.operation = "bulkWrite", .has_operation_id = true, .operation_id = self->operation_id};
1563+
15611564
// Select a stream.
15621565
{
15631566
bson_t reply;
@@ -1567,7 +1570,7 @@ mongoc_bulkwrite_execute (mongoc_bulkwrite_t *self, const mongoc_bulkwriteopts_t
15671570
&self->client->cluster, opts->serverid, true /* reconnect_ok */, self->session, &reply, &error);
15681571
} else {
15691572
ss = mongoc_cluster_stream_for_writes (
1570-
&self->client->cluster, self->session, NULL /* deprioritized servers */, &reply, &error);
1573+
&self->client->cluster, &ss_log_context, self->session, NULL /* deprioritized servers */, &reply, &error);
15711574
}
15721575

15731576
if (!ss) {
@@ -1815,8 +1818,12 @@ mongoc_bulkwrite_execute (mongoc_bulkwrite_t *self, const mongoc_bulkwriteopts_t
18151818
bson_t reply;
18161819
// Select a server and create a stream again.
18171820
mongoc_server_stream_cleanup (ss);
1818-
ss = mongoc_cluster_stream_for_writes (
1819-
&self->client->cluster, NULL /* session */, NULL /* deprioritized servers */, &reply, &error);
1821+
ss = mongoc_cluster_stream_for_writes (&self->client->cluster,
1822+
&ss_log_context,
1823+
NULL /* session */,
1824+
NULL /* deprioritized servers */,
1825+
&reply,
1826+
&error);
18201827

18211828
if (ss) {
18221829
parts.assembled.server_stream = ss;

‎src/libmongoc/src/mongoc/mongoc-change-stream.c

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -267,8 +267,9 @@ _make_cursor (mongoc_change_stream_t *stream)
267267
goto cleanup;
268268
}
269269

270-
server_stream =
271-
mongoc_cluster_stream_for_reads (&stream->client->cluster, stream->read_prefs, cs, NULL, &reply, &stream->err);
270+
const mongoc_ss_log_context_t ss_log_context = {.operation = "aggregate"};
271+
server_stream = mongoc_cluster_stream_for_reads (
272+
&stream->client->cluster, &ss_log_context, stream->read_prefs, cs, NULL, &reply, &stream->err);
272273
if (!server_stream) {
273274
bson_destroy (&stream->err_doc);
274275
bson_copy_to (&reply, &stream->err_doc);

‎src/libmongoc/src/mongoc/mongoc-client-private.h

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -193,7 +193,9 @@ _mongoc_client_command_with_opts (mongoc_client_t *client,
193193
bson_error_t *error);
194194

195195
mongoc_server_session_t *
196-
_mongoc_client_pop_server_session (mongoc_client_t *client, bson_error_t *error);
196+
_mongoc_client_pop_server_session (mongoc_client_t *client,
197+
const mongoc_ss_log_context_t *log_context,
198+
bson_error_t *error);
197199

198200
bool
199201
_mongoc_client_lookup_session (const mongoc_client_t *client,

‎src/libmongoc/src/mongoc/mongoc-client-session.c

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1036,8 +1036,9 @@ mongoc_client_session_start_transaction (mongoc_client_session_t *session,
10361036
BSON_ASSERT (session);
10371037

10381038
ret = true;
1039+
const mongoc_ss_log_context_t ss_log_context = {.operation = "mongoc_client_session_start_transaction"};
10391040
server_stream = mongoc_cluster_stream_for_writes (
1040-
&session->client->cluster, session, NULL /* deprioritized servers */, NULL /* reply */, error);
1041+
&session->client->cluster, &ss_log_context, session, NULL /* deprioritized servers */, NULL /* reply */, error);
10411042
if (!server_stream) {
10421043
ret = false;
10431044
GOTO (done);

‎src/libmongoc/src/mongoc/mongoc-client.c

Lines changed: 29 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -1239,7 +1239,8 @@ mongoc_client_start_session (mongoc_client_t *client, const mongoc_session_opt_t
12391239

12401240
ENTRY;
12411241

1242-
ss = _mongoc_client_pop_server_session (client, error);
1242+
const mongoc_ss_log_context_t ss_log_context = {.operation = "startSession"};
1243+
ss = _mongoc_client_pop_server_session (client, &ss_log_context, error);
12431244
if (!ss) {
12441245
RETURN (NULL);
12451246
}
@@ -1661,8 +1662,13 @@ _mongoc_client_retryable_read_command_with_stream (mongoc_client_t *client,
16611662
mongoc_deprioritized_servers_add_if_sharded (ds, server_stream->topology_type, server_stream->sd);
16621663
}
16631664

1665+
const mongoc_ss_log_context_t ss_log_context = {
1666+
.operation = parts->assembled.command_name,
1667+
.has_operation_id = true,
1668+
.operation_id = parts->assembled.operation_id,
1669+
};
16641670
retry_server_stream = mongoc_cluster_stream_for_reads (
1665-
&client->cluster, parts->read_prefs, parts->assembled.session, ds, NULL, &ignored_error);
1671+
&client->cluster, &ss_log_context, parts->read_prefs, parts->assembled.session, ds, NULL, &ignored_error);
16661672

16671673
mongoc_deprioritized_servers_destroy (ds);
16681674
}
@@ -1761,7 +1767,8 @@ mongoc_client_command_simple (mongoc_client_t *client,
17611767
* configuration. The generic command method SHOULD allow an optional read
17621768
* preference argument."
17631769
*/
1764-
server_stream = mongoc_cluster_stream_for_reads (cluster, read_prefs, NULL, NULL, reply, error);
1770+
const mongoc_ss_log_context_t ss_log_context = {.operation = _mongoc_get_command_name (command)};
1771+
server_stream = mongoc_cluster_stream_for_reads (cluster, &ss_log_context, read_prefs, NULL, NULL, reply, error);
17651772

17661773
if (server_stream) {
17671774
ret = _mongoc_client_command_with_stream (client, &parts, read_prefs, server_stream, reply, error);
@@ -1895,6 +1902,7 @@ _mongoc_client_command_with_opts (mongoc_client_t *client,
18951902
prefs = NULL;
18961903
}
18971904

1905+
const mongoc_ss_log_context_t ss_log_context = {.operation = command_name};
18981906
if (read_write_opts.serverId) {
18991907
/* "serverId" passed in opts */
19001908
server_stream = mongoc_cluster_stream_for_server (
@@ -1904,9 +1912,9 @@ _mongoc_client_command_with_opts (mongoc_client_t *client,
19041912
parts.user_query_flags |= MONGOC_QUERY_SECONDARY_OK;
19051913
}
19061914
} else if (parts.is_write_command) {
1907-
server_stream = mongoc_cluster_stream_for_writes (cluster, cs, NULL, reply_ptr, error);
1915+
server_stream = mongoc_cluster_stream_for_writes (cluster, &ss_log_context, cs, NULL, reply_ptr, error);
19081916
} else {
1909-
server_stream = mongoc_cluster_stream_for_reads (cluster, prefs, cs, NULL, reply_ptr, error);
1917+
server_stream = mongoc_cluster_stream_for_reads (cluster, &ss_log_context, prefs, cs, NULL, reply_ptr, error);
19101918
}
19111919

19121920
if (!server_stream) {
@@ -2691,7 +2699,8 @@ mongoc_client_select_server (mongoc_client_t *client,
26912699
return NULL;
26922700
}
26932701

2694-
sd = mongoc_topology_select (client->topology, optype, prefs, NULL /* chosen read mode */, error);
2702+
const mongoc_ss_log_context_t ss_log_context = {.operation = "mongoc_client_select_server"};
2703+
sd = mongoc_topology_select (client->topology, optype, &ss_log_context, prefs, NULL /* chosen read mode */, error);
26952704
if (!sd) {
26962705
return NULL;
26972706
}
@@ -2703,7 +2712,7 @@ mongoc_client_select_server (mongoc_client_t *client,
27032712

27042713
/* check failed, retry once */
27052714
mongoc_server_description_destroy (sd);
2706-
sd = mongoc_topology_select (client->topology, optype, prefs, NULL /* chosen read mode */, error);
2715+
sd = mongoc_topology_select (client->topology, optype, &ss_log_context, prefs, NULL /* chosen read mode */, error);
27072716
if (sd) {
27082717
return sd;
27092718
}
@@ -2752,11 +2761,13 @@ mongoc_client_set_appname (mongoc_client_t *client, const char *appname)
27522761
}
27532762

27542763
mongoc_server_session_t *
2755-
_mongoc_client_pop_server_session (mongoc_client_t *client, bson_error_t *error)
2764+
_mongoc_client_pop_server_session (mongoc_client_t *client,
2765+
const mongoc_ss_log_context_t *log_context,
2766+
bson_error_t *error)
27562767
{
27572768
BSON_ASSERT_PARAM (client);
27582769

2759-
return _mongoc_topology_pop_server_session (client->topology, error);
2770+
return _mongoc_topology_pop_server_session (client->topology, log_context, error);
27602771
}
27612772

27622773
/*
@@ -2845,8 +2856,15 @@ _mongoc_client_end_sessions (mongoc_client_t *client)
28452856

28462857
while (!mongoc_server_session_pool_is_empty (t->session_pool)) {
28472858
prefs = mongoc_read_prefs_new (MONGOC_READ_PRIMARY_PREFERRED);
2848-
server_id = mongoc_topology_select_server_id (
2849-
t, MONGOC_SS_READ, prefs, NULL /* chosen read mode */, NULL /* deprioritized servers */, &error);
2859+
const mongoc_ss_log_context_t ss_log_context = {
2860+
.operation = "endSessions", .has_operation_id = true, .operation_id = 1 + cluster->operation_id};
2861+
server_id = mongoc_topology_select_server_id (t,
2862+
MONGOC_SS_READ,
2863+
&ss_log_context,
2864+
prefs,
2865+
NULL /* chosen read mode */,
2866+
NULL /* deprioritized servers */,
2867+
&error);
28502868

28512869
mongoc_read_prefs_destroy (prefs);
28522870
if (!server_id) {

‎src/libmongoc/src/mongoc/mongoc-cluster-private.h

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -120,6 +120,7 @@ mongoc_cluster_try_recv (mongoc_cluster_t *cluster,
120120
*/
121121
mongoc_server_stream_t *
122122
mongoc_cluster_stream_for_reads (mongoc_cluster_t *cluster,
123+
const mongoc_ss_log_context_t *log_context,
123124
const mongoc_read_prefs_t *read_prefs,
124125
mongoc_client_session_t *cs,
125126
const mongoc_deprioritized_servers_t *ds,
@@ -139,6 +140,7 @@ mongoc_cluster_stream_for_reads (mongoc_cluster_t *cluster,
139140
*/
140141
mongoc_server_stream_t *
141142
mongoc_cluster_stream_for_writes (mongoc_cluster_t *cluster,
143+
const mongoc_ss_log_context_t *log_context,
142144
mongoc_client_session_t *cs,
143145
const mongoc_deprioritized_servers_t *ds,
144146
bson_t *reply,
@@ -158,6 +160,7 @@ mongoc_cluster_stream_for_writes (mongoc_cluster_t *cluster,
158160
*/
159161
mongoc_server_stream_t *
160162
mongoc_cluster_stream_for_aggr_with_write (mongoc_cluster_t *cluster,
163+
const mongoc_ss_log_context_t *log_context,
161164
const mongoc_read_prefs_t *read_prefs,
162165
mongoc_client_session_t *cs,
163166
bson_t *reply,

‎src/libmongoc/src/mongoc/mongoc-cluster.c

Lines changed: 21 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -2449,6 +2449,7 @@ static uint32_t
24492449
_mongoc_cluster_select_server_id (mongoc_client_session_t *cs,
24502450
mongoc_topology_t *topology,
24512451
mongoc_ss_optype_t optype,
2452+
const mongoc_ss_log_context_t *log_context,
24522453
const mongoc_read_prefs_t *read_prefs,
24532454
bool *must_use_primary,
24542455
const mongoc_deprioritized_servers_t *ds,
@@ -2465,13 +2466,15 @@ _mongoc_cluster_select_server_id (mongoc_client_session_t *cs,
24652466
if (_in_sharded_txn (cs)) {
24662467
server_id = cs->server_id;
24672468
if (!server_id) {
2468-
server_id = mongoc_topology_select_server_id (topology, optype, read_prefs, must_use_primary, ds, error);
2469+
server_id =
2470+
mongoc_topology_select_server_id (topology, optype, log_context, read_prefs, must_use_primary, ds, error);
24692471
if (server_id) {
24702472
_mongoc_client_session_pin (cs, server_id);
24712473
}
24722474
}
24732475
} else {
2474-
server_id = mongoc_topology_select_server_id (topology, optype, read_prefs, must_use_primary, ds, error);
2476+
server_id =
2477+
mongoc_topology_select_server_id (topology, optype, log_context, read_prefs, must_use_primary, ds, error);
24752478
/* Transactions Spec: Additionally, any non-transaction operation using a
24762479
* pinned ClientSession MUST unpin the session and the operation MUST
24772480
* perform normal server selection. */
@@ -2504,6 +2507,7 @@ _mongoc_cluster_select_server_id (mongoc_client_session_t *cs,
25042507
static mongoc_server_stream_t *
25052508
_mongoc_cluster_stream_for_optype (mongoc_cluster_t *cluster,
25062509
mongoc_ss_optype_t optype,
2510+
const mongoc_ss_log_context_t *log_context,
25072511
const mongoc_read_prefs_t *read_prefs,
25082512
mongoc_client_session_t *cs,
25092513
bool is_retryable,
@@ -2526,7 +2530,8 @@ _mongoc_cluster_stream_for_optype (mongoc_cluster_t *cluster,
25262530

25272531
BSON_ASSERT (cluster);
25282532

2529-
server_id = _mongoc_cluster_select_server_id (cs, topology, optype, read_prefs, &must_use_primary, ds, error);
2533+
server_id =
2534+
_mongoc_cluster_select_server_id (cs, topology, optype, log_context, read_prefs, &must_use_primary, ds, error);
25302535

25312536
if (!server_id) {
25322537
if (reply) {
@@ -2538,7 +2543,8 @@ _mongoc_cluster_stream_for_optype (mongoc_cluster_t *cluster,
25382543

25392544
if (!mongoc_cluster_check_interval (cluster, server_id)) {
25402545
/* Server Selection Spec: try once more */
2541-
server_id = _mongoc_cluster_select_server_id (cs, topology, optype, read_prefs, &must_use_primary, ds, error);
2546+
server_id =
2547+
_mongoc_cluster_select_server_id (cs, topology, optype, log_context, read_prefs, &must_use_primary, ds, error);
25422548

25432549
if (!server_id) {
25442550
if (reply) {
@@ -2610,6 +2616,7 @@ _mongoc_cluster_stream_for_optype (mongoc_cluster_t *cluster,
26102616

26112617
mongoc_server_stream_t *
26122618
mongoc_cluster_stream_for_reads (mongoc_cluster_t *cluster,
2619+
const mongoc_ss_log_context_t *log_context,
26132620
const mongoc_read_prefs_t *read_prefs,
26142621
mongoc_client_session_t *cs,
26152622
const mongoc_deprioritized_servers_t *ds,
@@ -2626,11 +2633,12 @@ mongoc_cluster_stream_for_reads (mongoc_cluster_t *cluster,
26262633
mongoc_uri_get_option_as_bool (cluster->uri, MONGOC_URI_RETRYREADS, MONGOC_DEFAULT_RETRYREADS);
26272634

26282635
return _mongoc_cluster_stream_for_optype (
2629-
cluster, MONGOC_SS_READ, prefs_override, cs, is_retryable, ds, reply, error);
2636+
cluster, MONGOC_SS_READ, log_context, prefs_override, cs, is_retryable, ds, reply, error);
26302637
}
26312638

26322639
mongoc_server_stream_t *
26332640
mongoc_cluster_stream_for_writes (mongoc_cluster_t *cluster,
2641+
const mongoc_ss_log_context_t *log_context,
26342642
mongoc_client_session_t *cs,
26352643
const mongoc_deprioritized_servers_t *ds,
26362644
bson_t *reply,
@@ -2639,11 +2647,13 @@ mongoc_cluster_stream_for_writes (mongoc_cluster_t *cluster,
26392647
const bool is_retryable =
26402648
mongoc_uri_get_option_as_bool (cluster->uri, MONGOC_URI_RETRYWRITES, MONGOC_DEFAULT_RETRYWRITES);
26412649

2642-
return _mongoc_cluster_stream_for_optype (cluster, MONGOC_SS_WRITE, NULL, cs, is_retryable, ds, reply, error);
2650+
return _mongoc_cluster_stream_for_optype (
2651+
cluster, MONGOC_SS_WRITE, log_context, NULL, cs, is_retryable, ds, reply, error);
26432652
}
26442653

26452654
mongoc_server_stream_t *
26462655
mongoc_cluster_stream_for_aggr_with_write (mongoc_cluster_t *cluster,
2656+
const mongoc_ss_log_context_t *log_context,
26472657
const mongoc_read_prefs_t *read_prefs,
26482658
mongoc_client_session_t *cs,
26492659
bson_t *reply,
@@ -2656,7 +2666,7 @@ mongoc_cluster_stream_for_aggr_with_write (mongoc_cluster_t *cluster,
26562666
mongoc_uri_get_option_as_bool (cluster->uri, MONGOC_URI_RETRYWRITES, MONGOC_DEFAULT_RETRYWRITES);
26572667

26582668
return _mongoc_cluster_stream_for_optype (
2659-
cluster, MONGOC_SS_AGGREGATE_WITH_WRITE, prefs_override, cs, is_retryable, NULL, reply, error);
2669+
cluster, MONGOC_SS_AGGREGATE_WITH_WRITE, log_context, prefs_override, cs, is_retryable, NULL, reply, error);
26602670
}
26612671

26622672
static bool
@@ -3615,8 +3625,10 @@ mongoc_cluster_run_retryable_write (mongoc_cluster_t *cluster,
36153625
// If talking to a sharded cluster, deprioritize the just-used mongos to prefer a new mongos for the retry.
36163626
mongoc_deprioritized_servers_add_if_sharded (ds, cmd->server_stream->topology_type, cmd->server_stream->sd);
36173627

3618-
*retry_server_stream =
3619-
mongoc_cluster_stream_for_writes (cluster, cmd->session, ds, NULL /* reply */, &ignored_error);
3628+
const mongoc_ss_log_context_t ss_log_context = {
3629+
.operation = cmd->command_name, .has_operation_id = true, .operation_id = cmd->operation_id};
3630+
*retry_server_stream = mongoc_cluster_stream_for_writes (
3631+
cluster, &ss_log_context, cmd->session, ds, NULL /* reply */, &ignored_error);
36203632

36213633
mongoc_deprioritized_servers_destroy (ds);
36223634
}

0 commit comments

Comments
 (0)