[SERVER-43098] Further enhance LDAP log lines to reflect uncertainty from libldap Created: 30/Aug/19  Updated: 29/Oct/23  Resolved: 29/Apr/20

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: 4.7.0

Type: Improvement Priority: Major - P3
Reporter: Nic Cottrell Assignee: Sara Golemon
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Sprint: Security 2020-05-04
Participants:
Case:

 Description   

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



 Comments   
Comment by Githook User [ 29/Apr/20 ]

Author:

{'name': 'Sara Golemon', 'email': 'sara.golemon@mongodb.com', 'username': 'sgolemon'}

Message: SERVER-43098 Clarify openLDAP connecting message and surface async option
Branch: master
https://github.com/10gen/mongo-enterprise-modules/commit/b281ee7db3a6df72d800fae4597f73ee60cbfa5d

Comment by Sara Golemon [ 28/Apr/20 ]

Gotcha.  It's interesting that you see different values for that at all since it appears to reflect the value of the LDAP_OPT_CONNECT_ASYNC flag which we never actually set.

My best guess is that different versions of OpenLDAP have different options for this value.  That or different versions of MongoDB invoke OpenLDAP different.

Either way, I'll just query ldap_get_option() and that'll give us the value that would be logged by ldap_pvt_connect.

Comment by Nic Cottrell [ 28/Apr/20 ]

sara.golemon Thanks for all the progress so far. Sorry about 3. looks like I had missed to add that I wanted the async value . I forget the exact context, but I believe that this information was useful when debugging how the libldap library was connecting to an LDAP server with TLS.

Examples: 

ldap_pvt_connect: fd: 19 tm: 0 async: -1

and

ldap_pvt_connect: fd: 10 tm: -1 async: 0

Comment by Sara Golemon [ 20/Apr/20 ]

nicholas.cottrell

  1. Easily done!
  2. Already done! SERVER-45836
  3. Could you clarify?  ldap_pvt_connect() is a function internal to OpenLDAP.  In your example this is reached in a roundabout way via ldap_sasl_bind_s shown in your logs as returning -1.
Generated at Thu Feb 08 05:02:16 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.