[SERVER-46412] Log time spent waiting for an authorization lock in the locks section Created: 25/Feb/20  Updated: 29/Oct/23  Resolved: 30/Apr/21

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: None
Fix Version/s: 5.0.0-rc0

Type: Improvement Priority: Major - P3
Reporter: Andrey Brindeyev Assignee: Varun Ravichandran
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Documented
is documented by DOCS-14398 [SERVER] Log time spent waiting for a... Closed
Related
related to SERVER-46442 Decouple AuthorizationManager update ... Closed
Backwards Compatibility: Fully Compatible
Sprint: Security 2020-11-02, Security 2020-11-16, Security 2020-11-30, Security 2020-12-14, Security 2020-12-28, Security 2021-03-22, Security 2021-04-05, Security 2021-04-19, Security 2021-05-03
Participants:
Case:

 Description   

When the server tries to (re-)authorize sessions using the slow LDAP server, this will stall all new authorizations, including those using the SCRAM mechanism.

To simplify RCA process I propose to include the new section named Authorization, for example:

Before:

2020-02-25T08:07:44.108-0800 I COMMAND  [conn141] command admin.system.users appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, saslSupportedMechs: "test.local852", lsid: { id: UUID("f7a3f71c-18c2-400a-8e93-4dceb8a26ccb") }, $db: "test" } numYields:0 reslen:268 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } storage:{} protocol:op_msg 11722ms

After:

2020-02-25T08:07:44.108-0800 I COMMAND  [conn141] command admin.system.users appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, saslSupportedMechs: "test.local852", lsid: { id: UUID("f7a3f71c-18c2-400a-8e93-4dceb8a26ccb") }, $db: "test" } numYields:0 reslen:268 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } }, Authorization: { acquireWaitCount: { r: 1 }, timeAcquiringMicros: { w: 11710012 } } } storage:{} protocol:op_msg 11722ms

Right now it's not obvious that a SCRAM authorization stalled due to the exclusive lock which was held by another session's authorization cache refresh (reaching out to the LDAP server and waiting for a response) - unless server has debug logging enabled.



 Comments   
Comment by Githook User [ 30/Apr/21 ]

Author:

{'name': 'Varun Ravichandran', 'email': 'varun.ravichandran@mongodb.com', 'username': 'varunravi98'}

Message: SERVER-46412: Track, log, and profile user cache acquisition stats in CurOp
Branch: master
https://github.com/mongodb/mongo/commit/c1213e2bbfb379d3defdc08a48067a350e84027c

Generated at Thu Feb 08 05:11:25 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.