[PR #1025] [MERGED] server: Remove session-wide logging, add session_uuid to message logs #1079

New issue

Closed

opened 2026-02-27 09:10:50 +03:00 by kerem · 0 comments

kerem commented

2026-02-27 09:10:50 +03:00

Owner

📋 Pull Request Information

Original PR: https://github.com/lldap/lldap/pull/1025
Author: @nitnelave
Created: 11/4/2024
Status: ✅ Merged
Merged: 11/4/2024
Merged by: @nitnelave

Base: main ← Head: logging

📝 Commits (1)

f5fbb8b server: Remove session-wide logging, add session_uuid to message logs

📊 Changes

2 files changed (+27 additions, -2 deletions)

View changed files

📝 server/src/infra/ldap_handler.rs (+21 -0)
📝 server/src/infra/ldap_server.rs (+6 -2)

📄 Description

When clients keep long-running LDAP sessions, the logs get endlessly buffered, turning into a slow memory leak. This change removes the session-long span, in favor of adding a session UUID to identify requests from the same UUID.

Sample non-verbose log:

2024-11-04T20:20:55.440854116+00:00  INFO     LDAP request [ 646ms | 100.00% ] session_id: d27e7230-19fe-4697-bb7c-a0ac732482d3
2024-11-04T20:20:55.442111783+00:00  INFO     ┕━ ｉ [info]: Login attempt for "admin"
2024-11-04T20:20:56.087854432+00:00  INFO     LDAP request [ 80.2ms | 100.00% ] session_id: d27e7230-19fe-4697-bb7c-a0ac732482d3
2024-11-04T20:20:56.169710414+00:00  INFO     LDAP request [ 23.9µs | 100.00% ] session_id: d27e7230-19fe-4697-bb7c-a0ac732482d3
2024-11-04T20:20:56.169840501+00:00  INFO     ｉ [info]: LDAP session end: d27e7230-19fe-4697-bb7c-a0ac732482d3

Sample verbose log:

2024-11-04T20:21:08.559247278+00:00  INFO     LDAP request [ 638ms | 0.00% / 100.00% ] session_id: ec554aee-9f47-471e-822c-0509fcbdc276
2024-11-04T20:21:08.559323675+00:00  DEBUG    ┝━ 🐛 [debug]:  | msg: LdapMsg { msgid: 1, op: BindRequest(LdapBindRequest { dn: "cn=admin,ou=people,dc=example,dc=com", cred: LdapBindCred::Simple }), ctrl: [] }
2024-11-04T20:21:08.559372395+00:00  DEBUG    ┝━ do_bind [ 638ms | 0.00% / 100.00% ] dn: cn=admin,ou=people,dc=example,dc=com
2024-11-04T20:21:08.559467153+00:00  DEBUG    │  ┝━ bind [ 636ms | 0.00% / 99.79% ]
2024-11-04T20:21:08.559520140+00:00  DEBUG    │  │  ┝━ get_password_file_for_user [ 1.01ms | 0.16% ] user_id: "admin"
2024-11-04T20:21:08.560691612+00:00  INFO     │  │  ┝━ ｉ [info]: Login attempt for "admin"
2024-11-04T20:21:08.560725174+00:00  DEBUG    │  │  ┕━ passwords_match [ 635ms | 99.64% ] username: admin
2024-11-04T20:21:09.196188979+00:00  DEBUG    │  ┝━ get_user_groups [ 1.31ms | 0.21% ] user_id: "admin"
2024-11-04T20:21:09.198078090+00:00  DEBUG    │  │  ┕━ 🐛 [debug]:  | return: {GroupDetails { group_id: 1, display_name: "lldap_admin", creation_date: 2024-10-03T13:50:59.506334784, uuid: "7497eefb-5fc8-3e79-aa1d-8ffb0a7d8117", attributes: [] }}
2024-11-04T20:21:09.198127365+00:00  DEBUG    │  ┕━ 🐛 [debug]: Success!
2024-11-04T20:21:09.198162609+00:00  DEBUG    ┕━ 🐛 [debug]:  | response: BindResponse(LdapBindResponse { res: LdapResult { code: Success, matcheddn: "", message: "", referral: [] }, saslcreds: None })
2024-11-04T20:21:09.198627777+00:00  INFO     LDAP request [ 2.06ms | 0.00% / 100.00% ] session_id: ec554aee-9f47-471e-822c-0509fcbdc276
2024-11-04T20:21:09.198645352+00:00  DEBUG    ┝━ 🐛 [debug]:  | msg: LdapMsg { msgid: 2, op: SearchRequest(LdapSearchRequest { base: "ou=people,dc=example,dc=com", scope: Subtree, aliases: Never, sizelimit: 0, timelimit: 0, typesonly: false, filter: Equality("uid", "bob"), attrs: [] }), ctrl: [] }
2024-11-04T20:21:09.198659713+00:00  DEBUG    ┝━ do_search [ 2.06ms | 39.54% / 100.00% ]
2024-11-04T20:21:09.200802449+00:00  DEBUG    │  ┝━ 🐛 [debug]:  | request.base: "ou=people,dc=example,dc=com" | scope: Users
2024-11-04T20:21:09.200820530+00:00  DEBUG    │  ┕━ get_user_list [ 1.25ms | 0.00% / 60.46% ]
2024-11-04T20:21:09.200837718+00:00  DEBUG    │     ┝━ 🐛 [debug]:  | filters: UserId("bob")
2024-11-04T20:21:09.200852598+00:00  DEBUG    │     ┕━ list_users [ 1.25ms | 60.46% ] filters: Some(UserId("bob")) | _get_groups: false
2024-11-04T20:21:09.202595053+00:00  DEBUG    │        ┕━ 🐛 [debug]:  | return: []
2024-11-04T20:21:09.202671956+00:00  DEBUG    ┕━ 🐛 [debug]:  | response: SearchResultDone(LdapResult { code: Success, matcheddn: "", message: "", referral: [] })
2024-11-04T20:21:09.202961623+00:00  INFO     LDAP request [ 27.6µs | 100.00% ] session_id: ec554aee-9f47-471e-822c-0509fcbdc276
2024-11-04T20:21:09.202974240+00:00  DEBUG    ┝━ 🐛 [debug]:  | msg: LdapMsg { msgid: 3, op: UnbindRequest, ctrl: [] }
2024-11-04T20:21:09.202985717+00:00  DEBUG    ┕━ 🐛 [debug]: Unbind request for admin
2024-11-04T20:21:09.203058096+00:00  INFO     ｉ [info]: LDAP session end: ec554aee-9f47-471e-822c-0509fcbdc276

_{🔄 This issue represents a GitHub Pull Request. It cannot be merged through Gitea due to API limitations.}

## 📋 Pull Request Information **Original PR:** https://github.com/lldap/lldap/pull/1025 **Author:** [@nitnelave](https://github.com/nitnelave) **Created:** 11/4/2024 **Status:** ✅ Merged **Merged:** 11/4/2024 **Merged by:** [@nitnelave](https://github.com/nitnelave) **Base:** `main` ← **Head:** `logging` --- ### 📝 Commits (1) - [`f5fbb8b`](https://github.com/lldap/lldap/commit/f5fbb8b49ce545c6f096c833eee5f82a0f33105e) server: Remove session-wide logging, add session_uuid to message logs ### 📊 Changes **2 files changed** (+27 additions, -2 deletions) <details> <summary>View changed files</summary> 📝 `server/src/infra/ldap_handler.rs` (+21 -0) 📝 `server/src/infra/ldap_server.rs` (+6 -2) </details> ### 📄 Description When clients keep long-running LDAP sessions, the logs get endlessly buffered, turning into a slow memory leak. This change removes the session-long span, in favor of adding a session UUID to identify requests from the same UUID. Sample non-verbose log: ``` 2024-11-04T20:20:55.440854116+00:00 INFO LDAP request [ 646ms | 100.00% ] session_id: d27e7230-19fe-4697-bb7c-a0ac732482d3 2024-11-04T20:20:55.442111783+00:00 INFO ┕━ ｉ [info]: Login attempt for "admin" 2024-11-04T20:20:56.087854432+00:00 INFO LDAP request [ 80.2ms | 100.00% ] session_id: d27e7230-19fe-4697-bb7c-a0ac732482d3 2024-11-04T20:20:56.169710414+00:00 INFO LDAP request [ 23.9µs | 100.00% ] session_id: d27e7230-19fe-4697-bb7c-a0ac732482d3 2024-11-04T20:20:56.169840501+00:00 INFO ｉ [info]: LDAP session end: d27e7230-19fe-4697-bb7c-a0ac732482d3 ``` Sample verbose log: ``` 2024-11-04T20:21:08.559247278+00:00 INFO LDAP request [ 638ms | 0.00% / 100.00% ] session_id: ec554aee-9f47-471e-822c-0509fcbdc276 2024-11-04T20:21:08.559323675+00:00 DEBUG ┝━ 🐛 [debug]: | msg: LdapMsg { msgid: 1, op: BindRequest(LdapBindRequest { dn: "cn=admin,ou=people,dc=example,dc=com", cred: LdapBindCred::Simple }), ctrl: [] } 2024-11-04T20:21:08.559372395+00:00 DEBUG ┝━ do_bind [ 638ms | 0.00% / 100.00% ] dn: cn=admin,ou=people,dc=example,dc=com 2024-11-04T20:21:08.559467153+00:00 DEBUG │ ┝━ bind [ 636ms | 0.00% / 99.79% ] 2024-11-04T20:21:08.559520140+00:00 DEBUG │ │ ┝━ get_password_file_for_user [ 1.01ms | 0.16% ] user_id: "admin" 2024-11-04T20:21:08.560691612+00:00 INFO │ │ ┝━ ｉ [info]: Login attempt for "admin" 2024-11-04T20:21:08.560725174+00:00 DEBUG │ │ ┕━ passwords_match [ 635ms | 99.64% ] username: admin 2024-11-04T20:21:09.196188979+00:00 DEBUG │ ┝━ get_user_groups [ 1.31ms | 0.21% ] user_id: "admin" 2024-11-04T20:21:09.198078090+00:00 DEBUG │ │ ┕━ 🐛 [debug]: | return: {GroupDetails { group_id: 1, display_name: "lldap_admin", creation_date: 2024-10-03T13:50:59.506334784, uuid: "7497eefb-5fc8-3e79-aa1d-8ffb0a7d8117", attributes: [] }} 2024-11-04T20:21:09.198127365+00:00 DEBUG │ ┕━ 🐛 [debug]: Success! 2024-11-04T20:21:09.198162609+00:00 DEBUG ┕━ 🐛 [debug]: | response: BindResponse(LdapBindResponse { res: LdapResult { code: Success, matcheddn: "", message: "", referral: [] }, saslcreds: None }) 2024-11-04T20:21:09.198627777+00:00 INFO LDAP request [ 2.06ms | 0.00% / 100.00% ] session_id: ec554aee-9f47-471e-822c-0509fcbdc276 2024-11-04T20:21:09.198645352+00:00 DEBUG ┝━ 🐛 [debug]: | msg: LdapMsg { msgid: 2, op: SearchRequest(LdapSearchRequest { base: "ou=people,dc=example,dc=com", scope: Subtree, aliases: Never, sizelimit: 0, timelimit: 0, typesonly: false, filter: Equality("uid", "bob"), attrs: [] }), ctrl: [] } 2024-11-04T20:21:09.198659713+00:00 DEBUG ┝━ do_search [ 2.06ms | 39.54% / 100.00% ] 2024-11-04T20:21:09.200802449+00:00 DEBUG │ ┝━ 🐛 [debug]: | request.base: "ou=people,dc=example,dc=com" | scope: Users 2024-11-04T20:21:09.200820530+00:00 DEBUG │ ┕━ get_user_list [ 1.25ms | 0.00% / 60.46% ] 2024-11-04T20:21:09.200837718+00:00 DEBUG │ ┝━ 🐛 [debug]: | filters: UserId("bob") 2024-11-04T20:21:09.200852598+00:00 DEBUG │ ┕━ list_users [ 1.25ms | 60.46% ] filters: Some(UserId("bob")) | _get_groups: false 2024-11-04T20:21:09.202595053+00:00 DEBUG │ ┕━ 🐛 [debug]: | return: [] 2024-11-04T20:21:09.202671956+00:00 DEBUG ┕━ 🐛 [debug]: | response: SearchResultDone(LdapResult { code: Success, matcheddn: "", message: "", referral: [] }) 2024-11-04T20:21:09.202961623+00:00 INFO LDAP request [ 27.6µs | 100.00% ] session_id: ec554aee-9f47-471e-822c-0509fcbdc276 2024-11-04T20:21:09.202974240+00:00 DEBUG ┝━ 🐛 [debug]: | msg: LdapMsg { msgid: 3, op: UnbindRequest, ctrl: [] } 2024-11-04T20:21:09.202985717+00:00 DEBUG ┕━ 🐛 [debug]: Unbind request for admin 2024-11-04T20:21:09.203058096+00:00 INFO ｉ [info]: LDAP session end: ec554aee-9f47-471e-822c-0509fcbdc276 ``` --- <sub>🔄 This issue represents a GitHub Pull Request. It cannot be merged through Gitea due to API limitations.</sub>