[CDRIVER-4812] Single-threaded monitoring commands may include saslSupportedMechs beyond initial handshake Created: 10/Jan/24  Updated: 16/Jan/24

Status: Backlog
Project: C Driver
Component/s: Authentication, Handshake, SDAM
Affects Version/s: 1.11.0
Fix Version/s: None

Type: Bug Priority: Minor - P4
Reporter: Jeremy Mikola Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
is related to CDRIVER-2579 Handshake changes for SDAM and Auth Closed
Epic Link: Easier debugging with standardized logging
Quarter: FY24Q4

 Description   

Summary

In mongodb/mongo-php-driver#1506, a user reported seeing AuthenticationAbandoned(337) errors in their server logs, which correlated with monitoring commands issued from the PHP driver.

{"t":{"$date":"2024-01-10T11:01:49.512-05:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"127.0.0.1:57402","uuid":{"uuid":{"$uuid":"659588ac-bded-4f19-b188-b921c80431d9"}},"connectionId":19,"connectionCount":3}}
{"t":{"$date":"2024-01-10T11:01:49.513-05:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn19","msg":"client metadata","attr":{"remote":"127.0.0.1:57402","client":"conn19","doc":{"driver":{"name":"mongoc / ext-mongodb:PHP / PHPLIB ","version":"1.25.2 / 1.18.0 / dev-master@92e"},"os":{"type":"Linux","name":"Ubuntu","version":"22.04","architecture":"x86_64"},"platform":"PHP 8.2.13 cfg=0x03d15ea8e9 posix=200809 stdc=201710 CC=GCC 11.4.0 CFLAGS=\"\" LDFLAGS=\"\""}}}
{"t":{"$date":"2024-01-10T11:01:49.513-05:00"},"s":"I",  "c":"ACCESS",   "id":6788604, "ctx":"conn19","msg":"Auth metrics report","attr":{"metric":"acquireUser","micros":0}}
{"t":{"$date":"2024-01-10T11:01:49.551-05:00"},"s":"I",  "c":"ACCESS",   "id":5286306, "ctx":"conn19","msg":"Successfully authenticated","attr":{"client":"127.0.0.1:57402","isSpeculative":true,"isClusterMember":false,"mechanism":"SCRAM-SHA-256","user":"root","db":"admin","result":0,"metrics":{"conversation_duration":{"micros":38396,"summary":{"0":{"step":1,"step_total":2,"duration_micros":47},"1":{"step":2,"step_total":2,"duration_micros":24}}}},"extraInfo":{}}}
{"t":{"$date":"2024-01-10T11:01:49.552-05:00"},"s":"I",  "c":"NETWORK",  "id":6788700, "ctx":"conn19","msg":"Received first command on ingress connection since session start or auth handshake","attr":{"elapsedMillis":0}}
 
{"t":{"$date":"2024-01-10T11:01:51.556-05:00"},"s":"I",  "c":"ACCESS",   "id":5286307, "ctx":"conn19","msg":"Failed to authenticate","attr":{"client":"127.0.0.1:57402","isSpeculative":false,"isClusterMember":false,"mechanism":"","user":"","db":"","error":"AuthenticationAbandoned: Overridden by new authentication session","result":337,"metrics":{"conversation_duration":{"micros":1003018,"summary":{}}},"extraInfo":{}}}

This does not interfere with the client's ability to authenticate or use an existing connection. The only issue appears to be superfluous log output on the server side.

By tracing outgoing monitoring commands, I noticed that libmongoc was still appending "saslSupportedMechs" to hello commands beyond the initial handshake. This appears to date back to mongodb/mongo-c-driver@c67dc16 for CDRIVER-2579, when negotiated_sasl_supported_mechs was introduced on mongoc_topology_scanner_node but never set to true. It's not immediately clear to me when that should be done – presumably not when _begin_hello_cmd() initially calls _mongoc_handshake_append_sasl_supported_mechs() but instead later when _mongoc_handshake_parse_sasl_supported_mechs() is called during response handling (although the scanner node doesn't appear to be available there).

Environment

User reproduced this with PHPC 1.17.2 and libmongoc 1.25.2. Full client metadata:

{"t":{"$date":"2024-01-03T12:16:48.551+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn704","msg":"client metadata","attr":{"remote":"127.0.0.6:35615","client":"conn704","doc":{"driver":{"name":"mongoc / ext-mongodb:PHP / PHPLIB/symfony-mongodb ","version":"1.25.2 / 1.17.2 / 1.17.0/2.6.1 "},"os":{"type":"Linux","name":"Alpine Linux","version":"3.19.0","architecture":"x86_64"},"platform":"PHP 8.3.0 cfg=0x03d21ea8f9 posix=200809 stdc=201710 CC=GCC 13.2.1 20231014 CFLAGS=\"\" LDFLAGS=\"\""}}}

How to Reproduce

See attached files for scripts to both start a local 7.0 replica set with auth and a PHP script to issue repeated ping commands against the primary.

To debug outgoing hello commands, I also made the following modification to mongoc-async-cmd.c:

diff --git a/src/libmongoc/src/mongoc/mongoc-async-cmd.c b/src/libmongoc/src/mongoc/mongoc-async-cmd.c
index 3ba899618..32f2dd608 100644
--- a/src/libmongoc/src/mongoc/mongoc-async-cmd.c
+++ b/src/libmongoc/src/mongoc/mongoc-async-cmd.c
@@ -225,6 +225,8 @@ mongoc_async_cmd_new (mongoc_async_t *async,
    acmd->connect_started = bson_get_monotonic_time ();
    bson_copy_to (cmd, &acmd->cmd);
 
+   fprintf(stderr, "mongoc_async_cmd_new: %s\n", bson_as_json(cmd, NULL));
+
    if (MONGOC_OP_CODE_MSG == cmd_opcode) {
       /* If we're sending an OP_MSG, we need to add the "db" field: */
       bson_append_utf8 (&acmd->cmd, "$db", 3, "admin", 5);

Related Documentation


Generated at Wed Feb 07 21:22:01 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.