URL:
https://github.com/SSSD/sssd/pull/203
Author: justin-stephenson
Title: #203: IPA: Enhance debug logging for ipa s2n operations
Action: opened
PR body:
"""
Troubleshooting IPA client issues during AD Trust user and group resolution can be a
difficult task requiring review of IPA client and IPA server SSSD logs during the full
timeframe of a lookup request. If groups go missing on the client or client operations
timeout with no obvious error then it is difficult to understand which requests to the IPA
server are failing. Often times, client-side ipa_s2n functions will fail with a generic
`s2n exop request failed` and the SSSD server-side logs are very busy for large AD
environments.
This PR is intended to help assist in log analysis and troubleshooting efforts by adding
more useful information in the IPA client logs to help narrow down the focus for searching
SSSD failures on the server.
- Before patch:
```
[root@ipa-client-f25 ~]# id sssduser(a)ad.jstephen
[root@ipa-client-f25 ~]# grep 'ipa_s2n' /var/log/sssd/sssd_idm.jstephen.log
(Thu Mar 16 15:49:43 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x0400):
Executing extended operation
(Thu Mar 16 15:49:43 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 17
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_done] (0x0400):
ldap_extended_operation result: Success(0), (null).
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x0400):
Executing extended operation
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 18
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_done] (0x0400):
ldap_extended_operation result: Success(0), (null).
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x4000): Found
original AD upn [sssduser(a)AD.JSTEPHEN].
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x2000):
Updating memberships for sssduser(a)ad.jstephen
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x0400):
Executing extended operation
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 19
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_done] (0x0400):
ldap_extended_operation result: Success(0), (null).
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x0400):
Processing group secondarygroup(a)ad.jstephen
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x0400):
Executing extended operation
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 20
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_done] (0x0400):
ldap_extended_operation result: Success(0), (null).
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x0400):
Processing group domain users(a)ad.jstephen
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x0400):
Executing extended operation
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 21
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_done] (0x0400):
ldap_extended_operation result: Success(0), (null).
(Thu Mar 16 15:49:44 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x0400):
Processing group parentofprimarygroup(a)ad.jstephen
(Thu Mar 16 15:49:45 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x4000): Found
original AD upn [sssduser(a)AD.JSTEPHEN].
(Thu Mar 16 15:49:45 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x2000):
Updating memberships for sssduser(a)ad.jstephen
```
- After patch
```
[root@ipa-client-f25 ~]# id sssduser(a)ad.jstephen
[root@ipa-client-f25 ~]# grep 'ipa_s2n' /var/log/sssd/sssd_idm.jstephen.log
(Thu Mar 16 15:59:39 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_acct_info_send] (0x0400):
Sending request_type: [3] for trust user [sssduser] to IPA server
(Thu Mar 16 15:59:39 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x0400):
Executing extended operation
(Thu Mar 16 15:59:39 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 17
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_done] (0x0400):
ldap_extended_operation result: Success(0), (null).
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_user_done] (0x0400):
Received [4] groups in group list from IPA Server
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_user_done] (0x0400):
[sssduser(a)ad.jstephen].
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_user_done] (0x0400):
[secondarygroup(a)ad.jstephen].
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_user_done] (0x0400):
[domain users(a)ad.jstephen].
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_user_done] (0x0400):
[parentofprimarygroup(a)ad.jstephen].
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_list_step] (0x0400):
Sending request_type: [3] for group [sssduser(a)ad.jstephen].
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x0400):
Executing extended operation
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 18
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_done] (0x0400):
ldap_extended_operation result: Success(0), (null).
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_list_next] (0x0400):
Received [sssduser(a)ad.jstephen] attributes from IPA server.
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x4000): Found
original AD upn [sssduser(a)AD.JSTEPHEN].
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x2000):
Updating memberships for sssduser(a)ad.jstephen
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_list_step] (0x0400):
Sending request_type: [3] for group [secondarygroup(a)ad.jstephen].
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x0400):
Executing extended operation
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 19
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_done] (0x0400):
ldap_extended_operation result: Success(0), (null).
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_list_next] (0x0400):
Received [secondarygroup(a)ad.jstephen] attributes from IPA server.
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x0400):
Processing group secondarygroup(a)ad.jstephen
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_list_step] (0x0400):
Sending request_type: [3] for group [domain users(a)ad.jstephen].
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x0400):
Executing extended operation
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 20
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_done] (0x0400):
ldap_extended_operation result: Success(0), (null).
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_list_next] (0x0400):
Received [domain users(a)ad.jstephen] attributes from IPA server.
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x0400):
Processing group domain users(a)ad.jstephen
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_list_step] (0x0400):
Sending request_type: [3] for group [parentofprimarygroup(a)ad.jstephen].
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x0400):
Executing extended operation
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_send] (0x2000):
ldap_extended_operation sent, msgid = 21
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_exop_done] (0x0400):
ldap_extended_operation result: Success(0), (null).
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_get_list_next] (0x0400):
Received [parentofprimarygroup(a)ad.jstephen] attributes from IPA server.
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x0400):
Processing group parentofprimarygroup(a)ad.jstephen
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x4000): Found
original AD upn [sssduser(a)AD.JSTEPHEN].
(Thu Mar 16 15:59:40 2017) [sssd[be[idm.jstephen]]] [ipa_s2n_save_objects] (0x2000):
Updating memberships for sssduser(a)ad.jstephen
```
"""
To pull the PR as Git branch:
git remote add ghsssd
https://github.com/SSSD/sssd
git fetch ghsssd pull/203/head:pr203
git checkout pr203