[SERVER-58981] Investigate why saslStart/saslContinue commands are sent as OP_QUERY commands Created: 30/Jul/21 Updated: 09/Aug/21 Resolved: 09/Aug/21 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Query Execution |
| Affects Version/s: | None |
| Fix Version/s: | None |
| Type: | Task | Priority: | Major - P3 |
| Reporter: | Yoon Soo Kim | Assignee: | Yoon Soo Kim |
| Resolution: | Done | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
|
||||||||
| Issue Links: |
|
||||||||
| Sprint: | QE 2021-08-09 | ||||||||
| Participants: | |||||||||
| Comments |
| Comment by David Storch [ 09/Aug/21 ] | |||||||||||||||||||||||||||
|
Changing the resolution to "Done", since this ticket just tracked an investigation. | |||||||||||||||||||||||||||
| Comment by David Storch [ 09/Aug/21 ] | |||||||||||||||||||||||||||
|
Thanks yoonsoo.kim, this makes sense! I don't fully follow all the intricacies of how SASL works, but it makes sense that when we bypass the isMaster protocol negotiation we would end up performing authentication-related commands using OP_QUERY. It's good to know that no further action is required right now. | |||||||||||||||||||||||||||
| Comment by Yoon Soo Kim [ 05/Aug/21 ] | |||||||||||||||||||||||||||
|
david.storch, please, take a look at the summary. | |||||||||||||||||||||||||||
| Comment by Yoon Soo Kim [ 05/Aug/21 ] | |||||||||||||||||||||||||||
|
In summary, the reason why saslStart/saslContinue are being sent as OP_QUERY commands is because the repl code bypasses the protocol negotiation when it's sending _isSelf command and it need to send saslStart/saslContinue before sending _isSelf when the internal authentication is turned on and the default rpc protocol was kOpQuery before the following changes in Now the default rpc protocol is kOpMsg for v5.1 and forward. So, _isSelf/saslStart/saslContinue are being sent as OP_MSG commands. There's nothing to fix and no further action is required. | |||||||||||||||||||||||||||
| Comment by Yoon Soo Kim [ 05/Aug/21 ] | |||||||||||||||||||||||||||
|
multiversion_auth_v5.1_kall_v5.0_kall_log.txt log file is attached. | |||||||||||||||||||||||||||
| Comment by Yoon Soo Kim [ 05/Aug/21 ] | |||||||||||||||||||||||||||
|
Experimentation #2: v5.1 uses kAll protocol, v5.0 uses kAll protocol by default by DBClientBase. The code is... Here's the log messages from experimentation: In this log d20030 is v5.0 mongod and b20030 is mongobridge for d20030. 5838802 is the sender-side log message id, 5838801 is the receiver-side log message id.
d20030 isSelf() tries to authenticate itself against itself but it does not send saslStart/saslContinue/_isSelf as OP_QUERY commands. We don't see receiver-side 5838801 logs messages.
The reason why they are sent as OP_MSG commands is because the preferred protocol is kOpMsg if both kOpMsg and kOpQuery are allowed.
DBClientBase::runCommandWithTarget() eventually calls negotiate(). | |||||||||||||||||||||||||||
| Comment by Yoon Soo Kim [ 04/Aug/21 ] | |||||||||||||||||||||||||||
|
In the entire multiversion_auth_v5.1_kall_v5.0_old_log.txt, we can see following occurrences of _isSelf/saslStart/saslContinue.
This means that there's nothing else other than _isSelf/saslStart/saslContinue except isMaster & ismaster. | |||||||||||||||||||||||||||
| Comment by Yoon Soo Kim [ 04/Aug/21 ] | |||||||||||||||||||||||||||
|
multiversion_auth_v5.1_kall_v5.0_old_log.txt log file is attached. | |||||||||||||||||||||||||||
| Comment by Yoon Soo Kim [ 04/Aug/21 ] | |||||||||||||||||||||||||||
|
Experimentation #1: v5.1 uses kAll protocol, v5.0 uses kOpQuery protocol by default by DBClientBase. The code is... Here's the log messages from experimentation: In this log d20030 is v5.0 mongod and b20030 is mongobridge for d20030. 5838802 is the sender-side log message id, 5838801 is the receiver-side log message id.
This process starts with the message "the internal auth is set. isSelf() is authenticating itself" at line 211. This log messages is added to here: If we look at the the following code block, isSelf() authenticates itself against itself when internal auth is set before sending "_isSelf" command. The line 253 leads to DBClientBase::authenticateInternalUser() call which again leads to auth::authenticateInternalClient(). auth::authenticateInternalClient() is given a RunCommandHook which is created by DBClientBase::_makeAuthRunCommandHook(). DBClientBase::_makeAuthRunCommandHook() calls DBClientBase::runCommand() which in turn, calls DBClientBase::runCommandWithTarget() to run an auth command. A log message is added to DBClientBase::runCommandWithTarget(). We can see OpMsgRequest be converted to a request message depending on negotiated rpc protocol (or default rpc protocol) here. If the rpc protocol is kOpQuery, then legacyRequestFromOpMsgRequest() is called. A log message is added to legacyRequestFromOpMsgRequest(). We can see this log message at 221 line in the above log. This means the rpc protocol is kOpQuery for the authentication process. A similar analysis can be done for saslContinue OP_QUERY command. The reason why the rpc protocol is kOpQuery here is that isSelf() bypasses rpc protocol negotiation and instead, uses the default rpc protocol. So, if we change the default rpc protocol to kOpMsgOnly, then saslStart/saslContinue commands will be sent as OP_MSG ones, which we've already done for _isSelf command in In the above log, we can see mongobridge and mongod receive saslStart OP_QUERY command at line 222-225 and saslContinue OP_QUERY command at 229-232. | |||||||||||||||||||||||||||
| Comment by Yoon Soo Kim [ 04/Aug/21 ] | |||||||||||||||||||||||||||
|
Here are changesets for logging:
| |||||||||||||||||||||||||||
| Comment by Yoon Soo Kim [ 04/Aug/21 ] | |||||||||||||||||||||||||||
|
In multiversion_auth test task, the last-lts is 5.0.0-rc5. To differentiate 5.0 sending saslStart/saslContinue OP_QUERY commands from 5.1 more easily, added logging to 5.0 too. Added logging to mongobridge too since multiversion_auth launches mongobridge. | |||||||||||||||||||||||||||
| Comment by Yoon Soo Kim [ 04/Aug/21 ] | |||||||||||||||||||||||||||
|
There are two C++ clients which are used by server internal components. Going to add some logging to two clients along the way for command execution and also authentication code with code = 5838802. And also remove uassert on no OP_QUERY commands condition so that every OP_QUERY command goes on and completes. Otherwise, one blocked OP_QUERY command may lead to failures in next steps. I expect that we should not see OP_QUERY saslStart/saslContinue commands for replica_sets_auth/sharding_auth since both clients are not supposed to send OP_QUERY commands except hello/isMaster. The server side logs OP_QUERY commands with code = 5838801. | |||||||||||||||||||||||||||
| Comment by Yoon Soo Kim [ 04/Aug/21 ] | |||||||||||||||||||||||||||
|
Realized that saslStart/saslContinue commands show up only in *_auth test task such as replica_sets_auth, sharding_auth, or multiversion_auth. They must be related to authentication process. |