[SERVER-70242] Intracluster X509 authentication can trigger "Different user name was supplied to saslSupportedMechs" Created: 05/Oct/22  Updated: 29/Oct/23  Resolved: 19/Dec/22

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: 6.3.0-rc0, 6.0.7, 5.0.19

Type: Task Priority: Major - P3
Reporter: Spencer Jackson Assignee: Militsa Sotirova
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Depends
Duplicate
is duplicated by SERVER-69464 "Attempt to switch user during SASL a... Closed
Related
related to SERVER-78911 Always suppress "Different user name ... Closed
Backwards Compatibility: Fully Compatible
Backport Requested:
v6.0, v5.0
Sprint: Security 2022-10-17, Security 2022-12-12, Security 2022-12-26
Participants:
Case:

 Description   

Looking at the logs from the most recent run of jstests/ssl_x509/sharding_with_x509.js we can see the following sequence of events:

[js_test:sharding_with_x509] c20043| 2022-10-05T13:12:51.724+00:00 D2 NETWORK  4908000 [conn2] "Client connected with SNI extension","attr":{"sniName":"ip-10-122-35-113.ec2.internal"}
[js_test:sharding_with_x509] c20043| 2022-10-05T13:12:51.724+00:00 I  NETWORK  6723804 [conn2] "Ingress TLS handshake complete","attr":{"durationMillis":6}
[js_test:sharding_with_x509] c20043| 2022-10-05T13:12:51.724+00:00 I  NETWORK  6723801 [conn2] "Accepted TLS connection from peer","attr":{"peerSubject":"CN=clustertest,OU=Kernel,O=MongoDB,L=New York City,ST=New York,C=US","cipher":"TLS_AES_256_GCM_SHA384"}
[js_test:sharding_with_x509] c20043| 2022-10-05T13:12:51.724+00:00 I  NETWORK  51800   [conn2] "client metadata","attr":{"remote":"10.122.35.113:35362","client":"conn2","doc":{"application":{"name":"/data/mci/1b7d5954a7badbd78fb06fecd1355345/src/dist-test/bin/mongod","pid":"14912"},"driver":{"name":"NetworkInterfaceTL-ReplNetwork","version":"6.2.0-alpha-824-gec66667"},"os":{"type":"Linux","name":"Red Hat Enterprise Linux release 8.0 (Ootpa)","architecture":"x86_64","version":"Kernel 4.18.0-80.1.2.el8_0.x86_64"}}}
[js_test:sharding_with_x509] c20043| 2022-10-05T13:12:51.724+00:00 I  ACCESS   5286202 [conn2] "Different user name was supplied to saslSupportedMechs","attr":{"error":{"code":17,"codeName":"ProtocolError","errmsg":"Attempt to switch user during SASL authentication from __system@local to CN=clustertest,OU=Kernel,O=MongoDB,L=New York City,ST=New York,C=US@$external"}}
[js_test:sharding_with_x509] c20043| 2022-10-05T13:12:51.724+00:00 I  ACCESS   20429   [conn2] "Successfully authenticated","attr":{"client":"10.122.35.113:35362","mechanism":"MONGODB-X509","user":"CN=clustertest,OU=Kernel,O=MongoDB,L=New York City,ST=New York,C=US","db":"$external"}

Nothing strictly wrong happened here, but the warning is chatty and misleading. X509 authentication happens on the $external database. But the __system user, which gives the client its privileges lives on the local database. The AuthenticationSession, which knows that internal authentication can happen on admin during testing, but doesn't seem to have an exemption for $external, seems to be getting confused. Strangely, MONGODB-X509 authentication only requires one step, and can entirely start and conclude in speculative hello authentication.

The problem appears to be that a hello command can include a speculativeAuthenticate and a saslSupportedMechs statement. speculativeAuthenticate works just like authenticate and must use the certificate's subject name. saslSupportedMechs has to enumerate a real user identity, so during intracluster auth has to be set to local.__system.

The fault here can either been seen to be arising from the AuthenticationSession not knowing that a saslSupportedMechs call can lead to a cluster auth attempt on the $external database. Alternatively, it can be seen as a result of the egress connection subsystem asking for supported SASL mechanisms when it knows that it's going to make a MONGODB-X509 authentication attempt.



 Comments   
Comment by Oleg Rekutin [ 30/Sep/23 ]

varun.ravichandran@mongodb.com I can confirm that issue still appears in 5.0.21. Looks like an incorrect fix was applied. I see that https://jira.mongodb.org/browse/SERVER-78911 is open to make this fix actually work. Shouldn't we reopen this SERVER-70242 instead?

Also, you stated that this is meant to only fix the log that says "Attempt to switch user...during SASL" whereas we are seeing "Attempt to switch database target during SASL authentication" in our X509 intracluster comms. It seems perfectly reasonable to switch datbase target to $external during intracluster comms. Is it possible that this fix needs more work? Let me know if you need more information.

Comment by Githook User [ 06/Jun/23 ]

Author:

{'name': 'Militsa Sotirova', 'email': 'militsa.sotirova@mongodb.com', 'username': 'militsasotirova'}

Message: SERVER-70242 Remove misleading "Different user name was supplied to saslSupportedMechs" log

(cherry picked from commit ad7d75cf8fd727260f6cfce1f350cb14ee16e927)
(cherry picked from commit 1e0e34547dd8d6065e96cce8b4b31bb215a63bd1)
Branch: v5.0
https://github.com/mongodb/mongo/commit/a9bc4a17bfe9bd0b44b50b27dc4e7ac50563709f

Comment by Githook User [ 05/Jun/23 ]

Author:

{'name': 'Militsa Sotirova', 'email': 'militsa.sotirova@mongodb.com', 'username': 'militsasotirova'}

Message: SERVER-70242 Remove misleading "Different user name was supplied to saslSupportedMechs" log

(cherry picked from commit ad7d75cf8fd727260f6cfce1f350cb14ee16e927)
Branch: v6.0
https://github.com/mongodb/mongo/commit/1e0e34547dd8d6065e96cce8b4b31bb215a63bd1

Comment by Ian Springer [ 27/Apr/23 ]

Hi Varun,

 

It occurs anywhere from 0-25 times per minute on shard replicas and config server replicas - maybe 5-10 times per minute on average. We have 120 shard replicas and 3 config server replicas, so that results in about 600-1200 log messages per minute. I had to exclude the messages from being shipped to our Graylog server due to the high volume.

Comment by Varun Ravichandran [ 24/Apr/23 ]

ian.springer@salesforce.com Hello! This particular fix addresses the following log only when it is emitted during intracluster authentication with X.509:

c20043| 2022-10-05T13:12:51.724+00:00 I  ACCESS   5286202 [conn2] "Different user name was supplied to saslSupportedMechs","attr":{"error":{"code":17,"codeName":"ProtocolError","errmsg":"Attempt to switch user during SASL authentication from __system@local to CN=clustertest,OU=Kernel,O=MongoDB,L=New York City,ST=New York,C=US@$external"}} 

Since intracluster authentication is not expected to be a common event, we only anticipate this log to appear misleadingly when cluster nodes are authenticating to one another during cluster setup.

Are you observing these logs more frequently than we expect during intracluster auth with X.509?

Comment by Ian Springer [ 12/Apr/23 ]

Any chance you can backport the fix for this to 5.0? We're getting a ton of log spam from it since upgrading to 5.0.

Comment by Githook User [ 19/Dec/22 ]

Author:

{'name': 'Militsa Sotirova', 'email': 'militsa.sotirova@mongodb.com', 'username': 'militsasotirova'}

Message: SERVER-70242 Remove misleading "Different user name was supplied to saslSupportedMechs" log
Branch: master
https://github.com/mongodb/mongo/commit/ad7d75cf8fd727260f6cfce1f350cb14ee16e927

Generated at Thu Feb 08 06:15:39 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.