Bug 1945888

Summary:	Inconsistant debug level for connection logging
Product:	Red Hat Enterprise Linux 8	Reporter:	Emmanuel Kasper <ekasprzy>
Component:	sssd	Assignee:	Alexey Tikhonov <atikhono>
Status:	CLOSED ERRATA	QA Contact:	Jakub Vavra <jvavra>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	8.2	CC:	atikhono, dlavu, grajaiya, jbreitwe, jhrozek, lslebodn, mzidek, pbrezina, peter.vreman, tscherf
Target Milestone:	beta	Keywords:	Triaged
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:	sync-to-jira
Fixed In Version:	sssd-2.5.0-1.el8	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2021-11-09 19:47:10 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Emmanuel Kasper 2021-04-02 13:19:32 UTC

Description of problem: Inconsistant debug level for connection logging


How reproducible: always


Steps to Reproduce:
Set IPA clients we have debug level 3 logging


Actual results:
In the backend log file we see:
(Sun Mar 28 06:37:28 2021) [sdap_id_conn_data_expire_handler] (0x0080): connection is about to expire, releasing it
(Sun Mar 28 06:37:36 2021) [ipa_sudo_fetch_addtl_cmdgroups_done] (0x0040): Received 0 additional command groups
(Sun Mar 28 06:37:36 2021) [ipa_sudo_fetch_rules_done] (0x0040): Received 0 sudo rules
(Sun Mar 28 06:52:28 2021) [sdap_id_conn_data_expire_handler] (0x0080): connection is about to expire, releasing it
(Sun Mar 28 06:52:36 2021) [ipa_sudo_fetch_addtl_cmdgroups_done] (0x0040): Received 0 additional command groups
(Sun Mar 28 06:52:36 2021) [ipa_sudo_fetch_rules_done] (0x0040): Received 0 sudo rules
(Sun Mar 28 07:07:28 2021) [sdap_id_conn_data_expire_handler] (0x0080): connection is about to expire, releasing it
(Sun Mar 28 07:07:36 2021) [ipa_sudo_fetch_addtl_cmdgroups_done] (0x0040): Received 0 additional command groups
(Sun Mar 28 07:07:36 2021) [ipa_sudo_fetch_rules_done] (0x0040): Received 0 sudo rules

Expected results:
Connection, (optional Expire-timers), Disconnect are logged at the same loglevel.

Additional info:
On loglevel 4 (0x0100) we see log messages like:
------
(Wed Mar 31 13:41:53 2021)  [fo_set_port_status] (0x0100): Marking port 389 of server 'li-ld-2351.hag
.hilti.com' as 'working'
(Wed Mar 31 13:41:53 2021)  [set_server_common_status] (0x0100): Marking server 'li-ld-2351.hag.hilti
.com' as 'working'
-----

The purpose of the log message about 'expire' on debug level 3 (0x0080) without a corresponding connection log message is unclear.

Comment 2 Alexey Tikhonov 2021-04-06 18:37:10 UTC

https://github.com/SSSD/sssd/pull/5570 changes
```
[sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [...] with fd [...].
[sdap_id_conn_data_expire_handler] (0x0080): connection is about to expire, releasing it
[sdap_id_release_conn_data] (0x4000): releasing unused connection
```
to use the same debug level 0x0400.

Take a note that debug level of "Received ... additional command groups" and "Received ... sudo rules" was changed in 8.4 already.

Comment 4 Alexey Tikhonov 2021-04-29 11:17:07 UTC

Pushed PR: https://github.com/SSSD/sssd/pull/5570

* `master`
    * 99beee3c320f2d81ffad6290c58ef303623b2f89 - LDAP: make connection log levels consistent

Comment 10 Jakub Vavra 2021-06-09 07:59:38 UTC

Fix is present and working in nightly compose RHEL-8.5.0-20210609.n.0, the loglevels are now consistent:
[root@client ~]# grep sdap_ldap_connect_callback_add /var/log/sssd/sssd_testrealm.test.log 
(2021-06-09  3:51:52): [be[testrealm.test]] [sdap_ldap_connect_callback_add] (0x4000): New connection to [ldap://master.testrealm.test:389/??base] with fd [26]
[root@client ~]# grep sdap_id_conn_data_expire_handler /var/log/sssd/sssd_testrealm.test.log 
(2021-06-09  3:52:44): [be[testrealm.test]] [sdap_id_conn_data_expire_handler] (0x4000): Connection is about to expire, releasing it
[root@client ~]# grep sdap_id_release_conn_data /var/log/sssd/sssd_testrealm.test.log 
(2021-06-09  3:52:44): [be[testrealm.test]] [sdap_id_release_conn_data] (0x4000): Releasing unused connection with fd [26]
[root@client ~]# grep sdap_id_op_done /var/log/sssd/sssd_testrealm.test.log 
(2021-06-09  3:51:53): [be[testrealm.test]] [sdap_id_op_done] (0x4000): releasing operation connection
(2021-06-09  3:52:20): [be[testrealm.test]] [sdap_id_op_done] (0x4000): releasing operation connection

Comment 12 errata-xmlrpc 2021-11-09 19:47:10 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (sssd bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2021:4435