Uploaded image for project: 'C Driver'
  1. C Driver
  2. CDRIVER-4812

Single-threaded monitoring commands may include saslSupportedMechs beyond initial handshake

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Unresolved
    • Priority: Icon: Minor - P4 Minor - P4
    • None
    • Affects Version/s: 1.11.0
    • Component/s: Authentication, Handshake, SDAM
    • Labels:
      None

      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

            Assignee:
            Unassigned Unassigned
            Reporter:
            jmikola@mongodb.com Jeremy Mikola
            Votes:
            1 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated: