[SERVER-46203] Improve logging for LDAP queries Created: 16/Feb/20  Updated: 27/Oct/23  Resolved: 18/Feb/20

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

Type: Improvement Priority: Major - P3
Reporter: Andrey Brindeyev Assignee: Backlog - Security Team
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Documented
Assigned Teams:
Server Security
Participants:

 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.



 Comments   
Comment by Spencer Jackson [ 18/Feb/20 ]

andrey.brindeyev, are you certain the LDAP query is being performed between "Connected to LDAP server" and "Performing LDAP query"? From what I'm aware of your test setup, the 4-second delay that you've introduced manifests during bind attempts to the service account, rather than the actual query execution. If this is the case, I would expect the 4-second delay to occur after connection establishment but before the query is issued.

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