RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1954630 - [RFE] Improve debug messages by adding a unique tag for each request the backend is handling
Summary: [RFE] Improve debug messages by adding a unique tag for each request the back...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: sssd
Version: 8.4
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: beta
: ---
Assignee: Pavel Březina
QA Contact: shridhar
URL:
Whiteboard: sync-to-jira
Depends On: 1967137 1980346
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-04-28 13:40 UTC by Pavel Březina
Modified: 2021-11-10 09:11 UTC (History)
9 users (show)

Fixed In Version: sssd-2.5.2-1.el8
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2021-11-09 19:47:29 UTC
Type: Bug
Target Upstream Version:
Embargoed:
pm-rhel: mirror+

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2021:4435 0 None None None 2021-11-09 19:47:44 UTC

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
Note You need to log in before you can comment on or make changes to this bug.