Bug 57845 - BACKTRACE logs in sssd_nonposixldap.log
Summary: BACKTRACE logs in sssd_nonposixldap.log
Status: NEW
Alias: None
Product: UCS
Classification: Unclassified
Component: SSSD
Version: UCS 5.2
Hardware: Other Linux
: P5 normal
Target Milestone: ---
Assignee: UCS maintainers
QA Contact: UCS maintainers
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2025-01-09 00:14 CET by Arvid Requate
Modified: 2025-03-27 19:00 CET (History)
2 users (show)

See Also:
What kind of report is it?: Development Internal
What type of bug is this?: ---
Who will be affected by this bug?: ---
How will those affected feel about the bug?: ---
User Pain:
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional): Cleanup
Customer ID:
Max CVSS v3 score:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Arvid Requate univentionstaff 2025-01-09 00:14:03 CET
More often than I'd like there are large backtrace logs in sssd_nonposixldap.log, I think they are triggered by slapd restarts:

====
(2025-01-08 17:05:54): [be[nonposixldap]] [sdap_process_result] (0x0040): ldap_result error: [Can't contact LDAP server]
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:
[...]
   *  (2025-01-08 16:59:09): [be[nonposixldap]] [be_ptask_online_cb] (0x0400): Back end is online
   *  (2025-01-08 16:59:09): [be[nonposixldap]] [be_ptask_enable] (0x0080): Task [SUDO Full Refresh]: already enabled
   *  (2025-01-08 16:59:09): [be[nonposixldap]] [sdap_sudo_online_cb] (0x0400): We are back online. SUDO host information will be renewed on next refresh.
   *  (2025-01-08 17:05:54): [be[nonposixldap]] [sdap_process_result] (0x2000): Trace: sh[0x5638ecaf5370], connected[1], ops[(nil)], ldap[0x5638ecb5d490]
   *  (2025-01-08 17:05:54): [be[nonposixldap]] [sdap_ldap_connect_callback_del] (0x4000): Closing LDAP connection with fd [21].
   *  (2025-01-08 17:05:54): [be[nonposixldap]] [sdap_process_result] (0x0040): ldap_result error: [Can't contact LDAP server]
********************** BACKTRACE DUMP ENDS HERE *********************************

The timestamps seem relevant here.
Looks like the backtraces are harmeless so I'm leaving this bug here as a kind of documentation until we find out to tame these down.
Comment 1 Arvid Requate univentionstaff 2025-01-09 00:19:19 CET
Btw: the "nonposixldap" refers to the config section "[application/nonposixldap]" in
/etc/sssd/sssd.conf , which was originally added to allow Non-Posix accounts of UDM object type "users/ldap" to be recognized by sssd (and allowed login via the UMC PAM stack. But it looks like sssd treats this section in a preferred way. At least most LDAP lookups are logged into that file.
Comment 2 Arvid Requate univentionstaff 2025-01-20 12:25:29 CET
On a performance test https://jenkins2022.knut.univention.de/view/Seed%20Jobs/job/UCS-5.2/job/UCS-5.2-0/view/Product%20Tests/job/product-test-ucsschool-performance-new65000/3/console
we saw that every 15 minutes:

===
[...]
   *  (2025-01-19 12:22:27): [be[nonposixldap]] [be_ptask_online_cb] (0x0400): Back end is online
   *  (2025-01-19 12:22:27): [be[nonposixldap]] [be_ptask_enable] (0x0080): Task [SUDO Full Refresh]: already enabled
   *  (2025-01-19 12:22:27): [be[nonposixldap]] [sdap_sudo_online_cb] (0x0400): We are back online. SUDO host information will be renewed on next refresh.
   *  (2025-01-19 12:22:28): [be[nonposixldap]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do.
   *  (2025-01-19 12:22:28): [be[nonposixldap]] [check_if_online_delayed] (0x2000): Backend is already online, nothing to do.
   *  (2025-01-19 12:28:41): [be[nonposixldap]] [sdap_process_result] (0x2000): Trace: sh[0x558d5cdcd860], connected[1], ops[(nil)], ldap[0x558d5cdaf3b0]
   *  (2025-01-19 12:28:41): [be[nonposixldap]] [sdap_ldap_connect_callback_del] (0x4000): Closing LDAP connection with fd [21].
   *  (2025-01-19 12:28:41): [be[nonposixldap]] [sdap_process_result] (0x0040): ldap_result error: [Can't contact LDAP server]
********************** BACKTRACE DUMP ENDS HERE *********************************

(2025-01-19 12:40:47): [be[nonposixldap]] [sdap_process_result] (0x0040): ldap_result error: [Can't contact LDAP server]
   *  ... skipping repetitive backtrace ...
(2025-01-19 12:52:42): [be[nonposixldap]] [sdap_process_result] (0x0040): ldap_result error: [Can't contact LDAP server]
   *  ... skipping repetitive backtrace ...
(2025-01-19 13:14:13): [be[nonposixldap]] [sdap_process_result] (0x0040): ldap_result error: [Can't contact LDAP server]
   *  ... skipping repetitive backtrace ...
(2025-01-19 13:29:23): [be[nonposixldap]] [sdap_process_result] (0x0040): ldap_result error: [Can't contact LDAP server]
   *  ... skipping repetitive backtrace ...
(2025-01-19 13:44:33): [be[nonposixldap]] [sdap_process_result] (0x0040): ldap_result error: [Can't contact LDAP server]
   *  ... skipping repetitive backtrace ...
(2025-01-19 13:59:43): [be[nonposixldap]] [sdap_process_result] (0x0040): ldap_result error: [Can't contact LDAP server]

===

Maybe related to default sssd timeout settings? E.g. https://pagure.io/SSSD/sssd/issue/3217