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

Further enhance LDAP log lines to reflect uncertainty from libldap

XMLWordPrintableJSON

    • Type: Icon: Improvement Improvement
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 4.7.0
    • Affects Version/s: None
    • Component/s: None
    • None
    • Fully Compatible
    • Security 2020-05-04

      The logging seems to indicate that an LDAP connection has been established correctly when it appears (in some cases at least) that the connection was failing due to a failed TLS handshake on the LDAP server-side.

      In the example below we see a "Connected to LDAP server" followed 10 seconds later by "failed to bind to LDAP server". This and some packet captures seems to indicate that the connection was not established.

      I want to request a couple of additional logging changes to those already performed in SERVER-37155:

      1. Change "Connected to LDAP server..." to "Connecting to LDAP server..."
      2. Use the libldap callback to show the IP address of the LDAP host so that the error level log "failed to bind to LDAP server at default" becomes "failed to bind to LDAP server at <IP>"
      3. Add the async value from ldap_pvt_connect to the LDAPAPIInfo debug-level log entry

      2019-08-08T09:35:30.389+0100 D ACCESS   [LDAPUserCacheInvalidator] Invalidating user cache entries of external users
2019-08-08T09:35:30.652+0100 D ACCESS   [conn78993] LDAPAPIInfo: { ldapai_info_version: 1, ldapai_api_version: 3001, ldap_protocol_version: 3, ldapai_extensions: [X_OPENLDAP], ldapai_vendor_name: OpenLDAP, ldapai_vendor_version: 20444}
2019-08-08T09:35:30.653+0100 D ACCESS   [conn78993] Binding to LDAP server "default" with bind parameters: {BindDN: sysmngdldap@INTRANET.xyz.com, authenticationType: simple}
2019-08-08T09:35:30.659+0100 D ACCESS   [conn78993] Connected to LDAP server at 10.40.113.137:3269 with LDAP URL: ldaps://ldapad.gbr.intranet.xyz.com:3269
2019-08-08T09:35:40.669+0100 E ACCESS   [conn78993] OperationFailed: LDAP operation <ldap_sasl_bind_s>, failed to bind to LDAP server at default". (-1/Can't contact LDAP server): No error could be retrieved from the LDAP server.. Bind parameters were: {BindDN: sysmngdldap@INTRANET.xyz.com, authenticationType: simple}
2019-08-08T09:35:40.669+0100 E ACCESS   [conn78993] LDAP authorization failed: FailedToParse: Failed to transform bind user name to LDAP DN: Failed to transform user 'sysfsvcontmongoprod'. No matching transformation out of 2 available transformations. Results: { rule: { match: "(.+)@INTRANET.xyz.com" ldapQuery: "DC=INTRANET,DC=XYZ,DC=com??sub?(sAMAccountName={0})" } error: "FailedToParse: Regular expression did not match input string sysfsvcontmongoprod" }, { rule: { match: "(.+)" ldapQuery: "DC=INTRANET,DC=XYZ,DC=com??sub?(sAMAccountName={0})" } error: "OperationFailed: LDAP bind failed with error: Can't contact LDAP server" },
2019-08-08T09:35:40.670+0100 W ACCESS   [conn78993] Could not fetch updated user privilege information for sysfsvcontmongoprod@$external; continuing to use old information.  Reason is OperationFailed: Failed to acquire LDAP group membership
2019-08-08T09:35:40.670+0100 D ACCESS   [conn68766] LDAPAPIInfo: { ldapai_info_version: 1, ldapai_api_version: 3001, ldap_protocol_version: 3, ldapai_extensions: [X_OPENLDAP], ldapai_vendor_name: OpenLDAP, ldapai_vendor_version: 20444}
2019-08-08T09:35:40.670+0100 D ACCESS   [conn68766] Binding to LDAP server "default" with bind parameters: {BindDN: sysmngdldap@INTRANET.xyz.com, authenticationType: simple}
2019-08-08T09:35:40.675+0100 D ACCESS   [conn68766] Connected to LDAP server at 10.40.113.157:3269 with LDAP URL: ldaps://ldapad.gbr.intranet.xyz.com:3269
2019-08-08T09:35:40.697+0100 D ACCESS   [conn68766] Performing LDAP query: BaseDN: "DC=INTRANET,DC=XYZ,DC=com", Scope: "sub", Filter: "(sAMAccountName=sysfsvcontmongoprod)"
2019-08-08T09:35:40.704+0100 D ACCESS   [conn68766] From LDAP query result, got an entry with DN: CN=sysfsvcontmongoprod,OU=SystemAccounts,OU=_Infrastructure,DC=INTRANET,DC=XYZ,DC=com
2019-08-08T09:35:40.704+0100 D ACCESS   [conn68766] From LDAP entry with DN CN=sysfsvcontmongoprod,OU=SystemAccounts,OU=_Infrastructure,DC=INTRANET,DC=XYZ,DC=com, got attribute objectClass
2019-08-08T09:35:40.704+0100 D ACCESS   [conn68766] From LDAP entry with DN CN=sysfsvcontmongoprod,OU=SystemAccounts,OU=_Infrastructure,DC=INTRANET,DC=XYZ,DC=com, got attribute cn
2

            Assignee:
            sara.golemon@mongodb.com Sara Golemon
            Reporter:
            nicholas.cottrell@mongodb.com Nic Cottrell
            Votes:
            0 Vote for this issue
            Watchers:
            7 Start watching this issue

              Created:
              Updated:
              Resolved: