[sssd PR#203][opened] IPA: Enhance debug logging for ipa s2n operations
by justin-stephenson
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
6 years