Bug 1954630

Summary: [RFE] Improve debug messages by adding a unique tag for each request the backend is handling
Product: Red Hat Enterprise Linux 8 Reporter: Pavel Březina <pbrezina>
Component: sssdAssignee: Pavel Březina <pbrezina>
Status: CLOSED ERRATA QA Contact: shridhar <sgadekar>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 8.4CC: atikhono, dlavu, grajaiya, jhrozek, lslebodn, mzidek, pbrezina, sgoveas, tscherf
Target Milestone: betaKeywords: FutureFeature, RFE, Triaged
Target Release: ---Flags: pm-rhel: mirror+
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: sync-to-jira
Fixed In Version: sssd-2.5.2-1.el8 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-11-09 19:47:29 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:
Bug Depends On: 1967137, 1980346    
Bug Blocks:    

Description Pavel Březina 2021-04-28 13:40:42 UTC 
Due to the asynchronous processing of the requests it is not easy for the untrained eye to follow individual requests in the backend because logs messages from different requests might be printed in between.
 
This is an RFE to put an ID to debug messages that are produced by a single incoming request.
Comment 4 Alexey Tikhonov 2021-07-12 19:17:08 UTC 
Pushed PR: https://github.com/SSSD/sssd/pull/5666

* `master`
    * 881a1a412eb036b8df22bc637a4bb38f10cdb9cf - debug: enable chain id in backend
    * f02ac230be3cef8fa83ee8cafea519a22268b23a - debug: add support for tevent chain id
Comment 12 shridhar 2021-07-26 13:24:42 UTC 
Tested with following data:

[root@ipaclient1 ~]# rpm -q sssd
sssd-2.5.2-1.el8.x86_64
[root@ipaclient1 ~]# cat /etc/sssd/sssd.conf 
[domain/testidm.com]

id_provider = ipa
ipa_server = _srv_, ipaserver.testidm.com
ipa_domain = testidm.com
ipa_hostname = ipaclient1.testidm.com
auth_provider = ipa
chpass_provider = ipa
access_provider = ipa
cache_credentials = True
ldap_tls_cacert = /etc/ipa/ca.crt
krb5_store_password_if_offline = True
debug_level = 9
pam_gssapi_services = sudo, sudo-i
[sssd]
services = nss, pam, ssh, sudo
debug_level = 9
domains = testidm.com
[nss]
#homedir_substring = /home
debug_level = 9

[pam]
debug_level = 9
[sudo]

[autofs]

[ssh]
debug_level = 9
[pac]

[ifp]

[secrets]

[session_recording]

[root@ipaclient1 ~]# systemctl stop sssd ; rm -rf /var/log/sssd/* ; rm -rf /var/lib/sss/db/* ; systemctl start sssd
[root@ipaclient1 ~]# id iuser4
uid=1665400020(iuser4) gid=1665400020(iuser4) groups=1665400020(iuser4)
[root@ipaclient1 ~]# 
[root@ipaclient1 ~]# 
[root@ipaclient1 ~]# egrep '\[RID#[2-9]' /var/log/sssd/sssd_testidm.com.log 
(2021-07-26 18:26:37): [be[testidm.com]] [dp_attach_req] (0x0400): [RID#2] DP Request [Account #2]: REQ_TRACE: New request. [sssd.nss CID #1] Flags [0x0001].
(2021-07-26 18:26:37): [be[testidm.com]] [dp_attach_req] (0x0400): [RID#2] Number of active DP request: 1
(2021-07-26 18:26:37): [be[testidm.com]] [sss_domain_get_state] (0x1000): [RID#2] Domain testidm.com is Active
(2021-07-26 18:26:37): [be[testidm.com]] [sss_domain_get_state] (0x1000): [RID#2] Domain testidm.com is Active
(2021-07-26 18:26:37): [be[testidm.com]] [ipa_idmap_check_posix_child] (0x4000): [RID#2] Idmap of domain [S-1-5-21-409446252-625295245-2786187534] already known, nothing to do.
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_id_op_connect_step] (0x4000): [RID#2] reusing cached connection
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_search_user_next_base] (0x0400): [RID#2] Searching for users with base [cn=accounts,dc=testidm,dc=com]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_print_server] (0x2000): [RID#2] Searching 192.168.122.3:389
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x0400): [RID#2] calling ldap_search_ext with [(&(uid=iuser4)(objectclass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=testidm,dc=com].
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [objectClass]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [uid]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [userPassword]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [uidNumber]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [gidNumber]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [gecos]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [homeDirectory]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [loginShell]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [krbPrincipalName]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [cn]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [memberOf]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [ipaUniqueID]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [ipaNTSecurityIdentifier]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [modifyTimestamp]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [entryUSN]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [shadowLastChange]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [shadowMin]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [shadowMax]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [shadowWarning]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [shadowInactive]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [shadowExpire]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [shadowFlag]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [krbLastPwdChange]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [krbPasswordExpiration]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [pwdAttribute]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [authorizedService]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [accountExpires]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [userAccountControl]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [nsAccountLock]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [host]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [loginDisabled]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [loginExpirationTime]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [loginAllowedTimeMap]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [ipaSshPubKey]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [ipaUserAuthType]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [userCertificate;binary]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#2] Requesting attrs: [mail]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x2000): [RID#2] ldap_search_ext called, msgid = 15
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_op_add] (0x2000): [RID#2] New operation 15 timeout 6
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_process_message] (0x4000): [RID#2] Message type: [LDAP_RES_SEARCH_ENTRY]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_entry] (0x1000): [RID#2] OriginalDN: [uid=iuser4,cn=users,cn=accounts,dc=testidm,dc=com].
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [objectClass]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [uid]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [uidNumber]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [gidNumber]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [gecos]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [homeDirectory]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [loginShell]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [krbPrincipalName]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [cn]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [memberOf]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [ipaUniqueID]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [ipaNTSecurityIdentifier]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [modifyTimestamp]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [entryUSN]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [krbLastPwdChange]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [krbPasswordExpiration]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_parse_range] (0x2000): [RID#2] No sub-attributes for [mail]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_process_message] (0x4000): [RID#2] Message type: [LDAP_RES_SEARCH_RESULT]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_op_finished] (0x0400): [RID#2] Search result: Success(0), no errmsg set
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_op_destructor] (0x2000): [RID#2] Operation 15 finished
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_search_user_process] (0x0400): [RID#2] Search for users, returned 1 results.
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_search_user_process] (0x2000): [RID#2] Retrieved total 1 users
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_save_user] (0x0400): [RID#2] Save user
(2021-07-26 18:26:37): [be[testidm.com]] [sss_domain_get_state] (0x1000): [RID#2] Domain testidm.c

[....]
(2021-07-26 18:26:37): [be[testidm.com]] [_dp_req_recv] (0x0400): [RID#2] DP Request [Account #2]: Receiving request data.
(2021-07-26 18:26:37): [be[testidm.com]] [dp_req_destructor] (0x0400): [RID#2] DP Request [Account #2]: Request removed.
(2021-07-26 18:26:37): [be[testidm.com]] [dp_req_destructor] (0x0400): [RID#2] Number of active DP request: 0
(2021-07-26 18:26:37): [be[testidm.com]] [dp_req_reply_std] (0x1000): [RID#2] DP Request [Account #2]: Returning [Success]: 0,0,Success
(2021-07-26 18:26:37): [be[testidm.com]] [dp_attach_req] (0x0400): [RID#3] DP Request [AccountDomain #3]: REQ_TRACE: New request. [sssd.nss CID #1] Flags [0x0001].
(2021-07-26 18:26:37): [be[testidm.com]] [dp_attach_req] (0x0400): [RID#3] Number of active DP request: 1
(2021-07-26 18:26:37): [be[testidm.com]] [dp_req_done] (0x0400): [RID#3] DP Request [AccountDomain #3]: Request handler finished [0]: Success
(2021-07-26 18:26:37): [be[testidm.com]] [_dp_req_recv] (0x0400): [RID#3] DP Request [AccountDomain #3]: Receiving request data.
(2021-07-26 18:26:37): [be[testidm.com]] [dp_req_destructor] (0x0400): [RID#3] DP Request [AccountDomain #3]: Request removed.
(2021-07-26 18:26:37): [be[testidm.com]] [dp_req_destructor] (0x0400): [RID#3] Number of active DP request: 0
(2021-07-26 18:26:37): [be[testidm.com]] [dp_req_reply_std] (0x1000): [RID#3] DP Request [AccountDomain #3]: Returning [Internal Error]: 3,1432158301,GetAccountDomain() not supported
(2021-07-26 18:26:37): [be[testidm.com]] [dp_attach_req] (0x0400): [RID#4] DP Request [Account #4]: REQ_TRACE: New request. [sssd.nss CID #1] Flags [0x0001].
(2021-07-26 18:26:37): [be[testidm.com]] [dp_attach_req] (0x0400): [RID#4] Number of active DP request: 1
(2021-07-26 18:26:37): [be[testidm.com]] [sss_domain_get_state] (0x1000): [RID#4] Domain testidm.com is Active
(2021-07-26 18:26:37): [be[testidm.com]] [sss_domain_get_state] (0x1000): [RID#4] Domain testidm.com is Active
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_id_op_connect_step] (0x4000): [RID#4] reusing cached connection
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_groups_next_base] (0x0400): [RID#4] Searching for groups with base [cn=accounts,dc=testidm,dc=com]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_print_server] (0x2000): [RID#4] Searching 192.168.122.3:389
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x0400): [RID#4] calling ldap_search_ext with [(&(gidNumber=1665400020)(|(objectClass=ipaUserGroup)(objectClass=posixGroup))(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][cn=accounts,dc=testidm,dc=com].
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#4] Requesting attrs: [objectClass]

[....]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_id_op_destroy] (0x4000): [RID#4] releasing operation connection
(2021-07-26 18:26:37): [be[testidm.com]] [dp_req_done] (0x0400): [RID#4] DP Request [Account #4]: Request handler finished [0]: Success
(2021-07-26 18:26:37): [be[testidm.com]] [_dp_req_recv] (0x0400): [RID#4] DP Request [Account #4]: Receiving request data.
(2021-07-26 18:26:37): [be[testidm.com]] [dp_req_destructor] (0x0400): [RID#4] DP Request [Account #4]: Request removed.
(2021-07-26 18:26:37): [be[testidm.com]] [dp_req_destructor] (0x0400): [RID#4] Number of active DP request: 0
(2021-07-26 18:26:37): [be[testidm.com]] [dp_req_reply_std] (0x1000): [RID#4] DP Request [Account #4]: Returning [Success]: 0,0,Success
(2021-07-26 18:26:37): [be[testidm.com]] [dp_attach_req] (0x0400): [RID#5] DP Request [Initgroups #5]: REQ_TRACE: New request. [sssd.nss CID #1] Flags [0x0001].
(2021-07-26 18:26:37): [be[testidm.com]] [dp_attach_req] (0x0400): [RID#5] Number of active DP request: 1
(2021-07-26 18:26:37): [be[testidm.com]] [sss_domain_get_state] (0x1000): [RID#5] Domain testidm.com is Active
(2021-07-26 18:26:37): [be[testidm.com]] [sss_domain_get_state] (0x1000): [RID#5] Domain testidm.com is Active
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_id_op_connect_step] (0x4000): [RID#5] reusing cached connection
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_initgr_send] (0x4000): [RID#5] Retrieving info for initgroups call
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_id_op_connect_step] (0x4000): [RID#5] reusing cached connection
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_initgr_next_base] (0x0400): [RID#5] Searching for users with base [cn=accounts,dc=testidm,dc=com]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_print_server] (0x2000): [RID#5] Searching 192.168.122.3:389
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x0400): [RID#5] calling ldap_search_ext with [(&(uid=iuser4)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=testidm,dc=com].
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5] Requesting attrs: [objectClass]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5] Requesting attrs: [uid]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5] Requesting attrs: [userPassword]
(2021-07-26 18:26:37): [be[testidm.com]] [sdap_get_generic_ext_step] (0x1000): [RID#5] Requesting attrs: [uidNumber]

[..END..]

There is a unique identifier added in the log for each request generated by backend.
Marking verified.
Comment 14 errata-xmlrpc 2021-11-09 19:47:29 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