Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-46412

Log time spent waiting for an authorization lock in the locks section

    XMLWordPrintable

    Details

    • Type: Improvement
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 5.0.0-rc0
    • Component/s: Logging
    • Labels:
      None
    • 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
    • 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.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              varun.ravichandran Varun Ravichandran
              Reporter:
              andrey.brindeyev Andrey Brindeev
              Participants:
              Votes:
              0 Vote for this issue
              Watchers:
              10 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: