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

Improve logging for LDAP queries

    XMLWordPrintableJSON

Details

    • Icon: Improvement Improvement
    • Resolution: Works as Designed
    • Icon: Major - P3 Major - P3
    • None
    • 3.6.17
    • Logging
    • None
    • Server Security

    Description

      It seems that server is logging the "Performing" log line after receiving the LDAP query results. Here's the log output when the queryUser has a 4-second delay configured:

      2020-02-15T15:41:33.673-0800 D ACCESS   [conn22] LDAPAPIInfo: { ldapai_info_version: 1, ldapai_api_version: 3001, ldap_protocol_version: 3, ldapai_extension
      s: [X_OPENLDAP], ldapai_vendor_name: OpenLDAP, ldapai_vendor_version: 20444}
      2020-02-15T15:41:33.673-0800 D ACCESS   [conn22] Binding to LDAP server "default" with bind parameters: {BindDN: uid=mdb,ou=Users,dc=acme,dc=qa, authenticationType: simple}
      2020-02-15T15:41:33.673-0800 D ACCESS   [conn22] Connected to LDAP server at 127.0.0.1:1389 with LDAP URL: ldap://127.0.0.1:1389
      2020-02-15T15:41:37.674-0800 D ACCESS   [conn22] Performing LDAP query: BaseDN: "ou=Groups,dc=ACME,dc=QA", Scope: "sub", Filter: "(member:=cn=user1,ou=Users,dc=acme,dc=qa)"
      2020-02-15T15:41:37.675-0800 D ACCESS   [conn22] From LDAP query result, got an entry with DN: cn=ReproGroup,ou=Groups,dc=acme,dc=qa
      2020-02-15T15:41:37.675-0800 D ACCESS   [conn22] From LDAP entry with DN cn=ReproGroup,ou=Groups,dc=acme,dc=qa, got attribute objectClass
      2020-02-15T15:41:37.675-0800 D ACCESS   [conn22] From LDAP entry with DN cn=ReproGroup,ou=Groups,dc=acme,dc=qa, got attribute cn
      2020-02-15T15:41:37.675-0800 D ACCESS   [conn22] From LDAP entry with DN cn=ReproGroup,ou=Groups,dc=acme,dc=qa, got attribute member
      2020-02-15T15:41:37.675-0800 D ACCESS   [conn22] Acquiring group DNs from entities which possess user as attribute
      2020-02-15T15:41:37.676-0800 D ACCESS   [conn22] Updated session cache of user information for cn=user1,ou=Users,dc=acme,dc=qa@$external
      

      The actual LDAP query happened between the "Connected to LDAP server" line and the "Performing LDAP query" line which is confusing.

      Having correct timestamps in the log files is crucial for post-mortem investigations, especially for ones involving the slow LDAP servers.

      Attachments

        Activity

          People

            backlog-server-security Backlog - Security Team
            andrey.brindeyev@mongodb.com Andrey Brindeyev
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: