Hello,
Would anyone mind helping me troubleshoot a problem?
1. Running a two-way trust between AD2016 and ipa-server 4.5.4-10.el7. 2. Unable to log into an IPA client with an AD account via ssh. The client has no trouble with “kinit $ad_user” and “getent passwd $ad_user”. 3. The AD user appears to properly exist in the correct groups for IPA/ad internal/external mapping as described in the docs.
I think the problem occurs here, with the PAC fetch: ==> /var/log/sssd/sssd_pac.log <== (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0020): Search with filter [(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))] returned more than one object. (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0040): Error: 22 (Invalid argument) (Mon Feb 11 05:24:36 2019) [sssd[pac]] [cache_req_search_cache] (0x0020): CR #5: Unable to lookup [<MY SID>@ad.domain.com] in cache [22]: Invalid argument
==> /var/log/sssd/krb5_child.log-20190210 <== (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][22]. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name]
==> /var/log/sssd/sssd_ipa.domain.com.log <== (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [child_sig_handler] (0x0100): child [26961] finished successfully. (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information
Addtl. Details:
# ipa service-show ldap/prod-ipa01.ipa.domain.com@IPA.DOMAIN.COM| grep PAC PAC type: MS-PAC
Thanks, D
I think the issue is outlined in the PAC error you got.
On 11 Feb 2019, at 16:51, D via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct.
It seems to indicate that the PAC in the ticket doesn’t match with the User+Group membership combo that was expected.
John
Thanks for confirming. Sounds like a failure to follow the docs. Here is what I have for groups:
1. AD user is a member of "AD Group". 2. There is an ipa group called ad_users_external. It has been mapped to "AD Group", and you can see the correct SID of this "AD group" listed under External Members. 3. There is an ipa group called ad_users. It is internal, and ad_users_external is a member of this group.
Is additional configuration required?
Thanks for your time :)
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Monday, February 11, 2019 11:34 AM, John Keates via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
I think the issue is outlined in the PAC error you got.
On 11 Feb 2019, at 16:51, D via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct.
It seems to indicate that the PAC in the ticket doesn’t match with the User+Group membership combo that was expected.
John
On Mon, Feb 11, 2019 at 03:51:07PM +0000, D via FreeIPA-users wrote:
Hello,
Would anyone mind helping me troubleshoot a problem?
- Running a two-way trust between AD2016 and ipa-server 4.5.4-10.el7.
- Unable to log into an IPA client with an AD account via ssh. The client has no trouble with “kinit $ad_user” and “getent passwd $ad_user”.
- The AD user appears to properly exist in the correct groups for IPA/ad internal/external mapping as described in the docs.
I think the problem occurs here, with the PAC fetch: ==> /var/log/sssd/sssd_pac.log <== (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0020): Search with filter [(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))] returned more than one object.
SIDs should be unique and it looks that currently in SSSD's cache are more than one object with the given SID. You can check the results yourself by calling:
ldbsearch -H /var/lib/sss/db/cache_DOMAIN.NAME.ldb '(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))'
(ldbsearch is in the ldb-tools package). Maybe this already explains what has happened but feel free to send the (sanitized) output.
(Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0040): Error: 22 (Invalid argument) (Mon Feb 11 05:24:36 2019) [sssd[pac]] [cache_req_search_cache] (0x0020): CR #5: Unable to lookup [<MY SID>@ad.domain.com] in cache [22]: Invalid argument
==> /var/log/sssd/krb5_child.log-20190210 <== (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][22]. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name]
That's odd. At the start of the log messages for 'krb5_child[26961]' there should be a line like:
[unpack_buffer] (0x0100): ccname: [KEYRING:persistent:.....
Can you send the full line which the complete name of the ccache?
bye, Sumit
==> /var/log/sssd/sssd_ipa.domain.com.log <== (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [child_sig_handler] (0x0100): child [26961] finished successfully. (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information
Addtl. Details:
# ipa service-show ldap/prod-ipa01.ipa.domain.com@IPA.DOMAIN.COM| grep PAC PAC type: MS-PAC
Thanks, D
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
Sumit,
The ldbsearch on the ipa client revealed two records with the SID in question, and the krb5 ccname is [KEYRING:persistent:$posix_uid_attribute] which matches the default ccname format in krb5.conf.
One of them appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
The ldbsearch command on the ipa server returns only the user record.
Do you have any idea where this odd group record might be coming from?
Thank you for your hard work, D
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, 12 February 2019 02:19, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Mon, Feb 11, 2019 at 03:51:07PM +0000, D via FreeIPA-users wrote:
Hello, Would anyone mind helping me troubleshoot a problem?
- Running a two-way trust between AD2016 and ipa-server 4.5.4-10.el7.
- Unable to log into an IPA client with an AD account via ssh. The client has no trouble with “kinit $ad_user” and “getent passwd $ad_user”.
- The AD user appears to properly exist in the correct groups for IPA/ad internal/external mapping as described in the docs.
I think the problem occurs here, with the PAC fetch: ==> /var/log/sssd/sssd_pac.log <== (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0020): Search with filter [(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))] returned more than one object.
SIDs should be unique and it looks that currently in SSSD's cache are more than one object with the given SID. You can check the results yourself by calling:
ldbsearch -H /var/lib/sss/db/cache_DOMAIN.NAME.ldb '(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))'
(ldbsearch is in the ldb-tools package). Maybe this already explains what has happened but feel free to send the (sanitized) output.
(Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0040): Error: 22 (Invalid argument) (Mon Feb 11 05:24:36 2019) [sssd[pac]] [cache_req_search_cache] (0x0020): CR #5: Unable to lookup [<MY SID>@ad.domain.com] in cache [22]: Invalid argument ==> /var/log/sssd/krb5_child.log-20190210 <== (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][22]. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name]
That's odd. At the start of the log messages for 'krb5_child[26961]' there should be a line like:
[unpack_buffer] (0x0100): ccname: [KEYRING:persistent:.....
Can you send the full line which the complete name of the ccache?
bye, Sumit
==> /var/log/sssd/sssd_ipa.domain.com.log <== (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [child_sig_handler] (0x0100): child [26961] finished successfully. (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information Addtl. Details:
ipa service-show ldap/prod-ipa01.ipa.domain.com@IPA.DOMAIN.COM| grep PAC
=========================================================================
PAC type: MS-PAC Thanks, D
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
On Tue, Feb 12, 2019 at 08:37:44PM +0000, D wrote:
Sumit,
The ldbsearch on the ipa client revealed two records with the SID in question, and the krb5 ccname is [KEYRING:persistent:$posix_uid_attribute] which matches the default ccname format in krb5.conf.
And is $posix_uid_attribute the same UID as the one from the log message two lines above:
[unpack_buffer] (0x0100): cmd [...] uid [...] gid [...] validate ...
Later on in the logs there should be
[become_user] (0x0200): Trying to become user ... (0x2000): Running as ....
is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
One of them appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
The ldbsearch command on the ipa server returns only the user record.
Do you have any idea where this odd group record might be coming from?
It would be best to have full logs to understand what is happening.
But since you say that the group memberships of the user are looking correct I guess this is not the primary issue why the login failed. Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better?
HTH
bye, Sumit
Thank you for your hard work, D
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, 12 February 2019 02:19, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Mon, Feb 11, 2019 at 03:51:07PM +0000, D via FreeIPA-users wrote:
Hello, Would anyone mind helping me troubleshoot a problem?
- Running a two-way trust between AD2016 and ipa-server 4.5.4-10.el7.
- Unable to log into an IPA client with an AD account via ssh. The client has no trouble with “kinit $ad_user” and “getent passwd $ad_user”.
- The AD user appears to properly exist in the correct groups for IPA/ad internal/external mapping as described in the docs.
I think the problem occurs here, with the PAC fetch: ==> /var/log/sssd/sssd_pac.log <== (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0020): Search with filter [(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))] returned more than one object.
SIDs should be unique and it looks that currently in SSSD's cache are more than one object with the given SID. You can check the results yourself by calling:
ldbsearch -H /var/lib/sss/db/cache_DOMAIN.NAME.ldb '(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))'
(ldbsearch is in the ldb-tools package). Maybe this already explains what has happened but feel free to send the (sanitized) output.
(Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0040): Error: 22 (Invalid argument) (Mon Feb 11 05:24:36 2019) [sssd[pac]] [cache_req_search_cache] (0x0020): CR #5: Unable to lookup [<MY SID>@ad.domain.com] in cache [22]: Invalid argument ==> /var/log/sssd/krb5_child.log-20190210 <== (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][22]. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name]
That's odd. At the start of the log messages for 'krb5_child[26961]' there should be a line like:
[unpack_buffer] (0x0100): ccname: [KEYRING:persistent:.....
Can you send the full line which the complete name of the ccache?
bye, Sumit
==> /var/log/sssd/sssd_ipa.domain.com.log <== (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [child_sig_handler] (0x0100): child [26961] finished successfully. (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information Addtl. Details:
ipa service-show ldap/prod-ipa01.ipa.domain.com@IPA.DOMAIN.COM| grep PAC
=========================================================================
PAC type: MS-PAC Thanks, D
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
Apologies for the delay Sumit.
I've attached full sanitized logs this time. This should answer a few of the questions you asked.
is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
I don't see a line involving a switch from that UID - the results when running ssh user@ad.domain.com@client as root vs. user@ad.domain.com seem to be the same.
One of the (ldbsearch records returned) appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
Yes it does, GID is the same.
Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better?
I can switch this in the kerberos config on the client right, sure
D
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, February 12, 2019 4:00 PM, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Tue, Feb 12, 2019 at 08:37:44PM +0000, D wrote:
Sumit, The ldbsearch on the ipa client revealed two records with the SID in question, and the krb5 ccname is [KEYRING:persistent:$posix_uid_attribute] which matches the default ccname format in krb5.conf.
And is $posix_uid_attribute the same UID as the one from the log message two lines above:
[unpack_buffer] (0x0100): cmd [...] uid [...] gid [...] validate ...
Later on in the logs there should be
[become_user] (0x0200): Trying to become user ... (0x2000): Running as ....
is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
One of them appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
The ldbsearch command on the ipa server returns only the user record. Do you have any idea where this odd group record might be coming from?
It would be best to have full logs to understand what is happening.
But since you say that the group memberships of the user are looking correct I guess this is not the primary issue why the login failed. Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better?
HTH
bye, Sumit
Thank you for your hard work, D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, 12 February 2019 02:19, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Mon, Feb 11, 2019 at 03:51:07PM +0000, D via FreeIPA-users wrote:
Hello, Would anyone mind helping me troubleshoot a problem?
- Running a two-way trust between AD2016 and ipa-server 4.5.4-10.el7.
- Unable to log into an IPA client with an AD account via ssh. The client has no trouble with “kinit $ad_user” and “getent passwd $ad_user”.
- The AD user appears to properly exist in the correct groups for IPA/ad internal/external mapping as described in the docs.
I think the problem occurs here, with the PAC fetch: ==> /var/log/sssd/sssd_pac.log <== (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0020): Search with filter [(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))] returned more than one object.
SIDs should be unique and it looks that currently in SSSD's cache are more than one object with the given SID. You can check the results yourself by calling: ldbsearch -H /var/lib/sss/db/cache_DOMAIN.NAME.ldb '(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))' (ldbsearch is in the ldb-tools package). Maybe this already explains what has happened but feel free to send the (sanitized) output.
(Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0040): Error: 22 (Invalid argument) (Mon Feb 11 05:24:36 2019) [sssd[pac]] [cache_req_search_cache] (0x0020): CR #5: Unable to lookup [<MY SID>@ad.domain.com] in cache [22]: Invalid argument ==> /var/log/sssd/krb5_child.log-20190210 <== (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][22]. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name]
That's odd. At the start of the log messages for 'krb5_child[26961]' there should be a line like: [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:..... Can you send the full line which the complete name of the ccache? bye, Sumit
==> /var/log/sssd/sssd_ipa.domain.com.log <== (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [child_sig_handler] (0x0100): child [26961] finished successfully. (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information Addtl. Details: ipa service-show ldap/prod-ipa01.ipa.domain.com@IPA.DOMAIN.COM| grep PAC ========================================================================= PAC type: MS-PAC Thanks, D
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
Update on this.
The strange ldb record being returned was due to the user being added to the external AD connector group as an external group. Removing that and cleaning caches has fixed the problem.
The larger issue with SSHD not working on a fresh install is not resolved, Sumit would you prefer a new thread or to continue here?
Thanks again for everything, D
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Wednesday, 13 February 2019 11:03, D via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
Apologies for the delay Sumit.
I've attached full sanitized logs this time. This should answer a few of the questions you asked.
is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
I don't see a line involving a switch from that UID - the results when running ssh user@ad.domain.com@client as root vs.user@ad.domain.com seem to be the same.
One of the (ldbsearch records returned) appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
Yes it does, GID is the same.
Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better?
I can switch this in the kerberos config on the client right, sure
D
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, February 12, 2019 4:00 PM, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Tue, Feb 12, 2019 at 08:37:44PM +0000, D wrote:
Sumit, The ldbsearch on the ipa client revealed two records with the SID in question, and the krb5 ccname is [KEYRING:persistent:$posix_uid_attribute] which matches the default ccname format in krb5.conf.
And is $posix_uid_attribute the same UID as the one from the log message two lines above: [unpack_buffer] (0x0100): cmd [...] uid [...] gid [...] validate ... Later on in the logs there should be [become_user] (0x0200): Trying to become user ... (0x2000): Running as .... is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
One of them appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
The ldbsearch command on the ipa server returns only the user record. Do you have any idea where this odd group record might be coming from?
It would be best to have full logs to understand what is happening. But since you say that the group memberships of the user are looking correct I guess this is not the primary issue why the login failed. Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better? HTH bye, Sumit
Thank you for your hard work, D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, 12 February 2019 02:19, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Mon, Feb 11, 2019 at 03:51:07PM +0000, D via FreeIPA-users wrote:
Hello, Would anyone mind helping me troubleshoot a problem?
- Running a two-way trust between AD2016 and ipa-server 4.5.4-10.el7.
- Unable to log into an IPA client with an AD account via ssh. The client has no trouble with “kinit $ad_user” and “getent passwd $ad_user”.
- The AD user appears to properly exist in the correct groups for IPA/ad internal/external mapping as described in the docs.
I think the problem occurs here, with the PAC fetch: ==> /var/log/sssd/sssd_pac.log <== (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0020): Search with filter [(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))] returned more than one object.
SIDs should be unique and it looks that currently in SSSD's cache are more than one object with the given SID. You can check the results yourself by calling: ldbsearch -H /var/lib/sss/db/cache_DOMAIN.NAME.ldb '(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))' (ldbsearch is in the ldb-tools package). Maybe this already explains what has happened but feel free to send the (sanitized) output.
(Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0040): Error: 22 (Invalid argument) (Mon Feb 11 05:24:36 2019) [sssd[pac]] [cache_req_search_cache] (0x0020): CR #5: Unable to lookup [<MY SID>@ad.domain.com] in cache [22]: Invalid argument ==> /var/log/sssd/krb5_child.log-20190210 <== (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][22]. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name]
That's odd. At the start of the log messages for 'krb5_child[26961]' there should be a line like: [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:..... Can you send the full line which the complete name of the ccache? bye, Sumit
==> /var/log/sssd/sssd_ipa.domain.com.log <== (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [child_sig_handler] (0x0100): child [26961] finished successfully. (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information Addtl. Details: ipa service-show ldap/prod-ipa01.ipa.domain.com@IPA.DOMAIN.COM| grep PAC
======================================================================================================================================================================================================================================================================================================================================================================================================================================================================
PAC type: MS-PAC Thanks, D
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
On Wed, Feb 13, 2019 at 08:18:10PM +0000, D wrote:
Update on this.
The strange ldb record being returned was due to the user being added to the external AD connector group as an external group. Removing that and cleaning caches has fixed the problem.
The larger issue with SSHD not working on a fresh install is not resolved, Sumit would you prefer a new thread or to continue here?
We can continue here.
The logs you have send only contains the SSS_PAM_PREAUTH step, I guess the error happens during SSS_PAM_AUTHENTICATE. Can you also increase the debug_level in the [domain/...] section to 9 and restart SSSD before running the test? I do not need all the logs, krb5_child.log would be sufficient for a start.
bye, Sumit
Thanks again for everything, D
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Wednesday, 13 February 2019 11:03, D via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
Apologies for the delay Sumit.
I've attached full sanitized logs this time. This should answer a few of the questions you asked.
is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
I don't see a line involving a switch from that UID - the results when running ssh user@ad.domain.com@client as root vs.user@ad.domain.com seem to be the same.
One of the (ldbsearch records returned) appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
Yes it does, GID is the same.
Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better?
I can switch this in the kerberos config on the client right, sure
D
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, February 12, 2019 4:00 PM, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Tue, Feb 12, 2019 at 08:37:44PM +0000, D wrote:
Sumit, The ldbsearch on the ipa client revealed two records with the SID in question, and the krb5 ccname is [KEYRING:persistent:$posix_uid_attribute] which matches the default ccname format in krb5.conf.
And is $posix_uid_attribute the same UID as the one from the log message two lines above: [unpack_buffer] (0x0100): cmd [...] uid [...] gid [...] validate ... Later on in the logs there should be [become_user] (0x0200): Trying to become user ... (0x2000): Running as .... is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
One of them appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
The ldbsearch command on the ipa server returns only the user record. Do you have any idea where this odd group record might be coming from?
It would be best to have full logs to understand what is happening. But since you say that the group memberships of the user are looking correct I guess this is not the primary issue why the login failed. Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better? HTH bye, Sumit
Thank you for your hard work, D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, 12 February 2019 02:19, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Mon, Feb 11, 2019 at 03:51:07PM +0000, D via FreeIPA-users wrote:
Hello, Would anyone mind helping me troubleshoot a problem?
- Running a two-way trust between AD2016 and ipa-server 4.5.4-10.el7.
- Unable to log into an IPA client with an AD account via ssh. The client has no trouble with “kinit $ad_user” and “getent passwd $ad_user”.
- The AD user appears to properly exist in the correct groups for IPA/ad internal/external mapping as described in the docs.
I think the problem occurs here, with the PAC fetch: ==> /var/log/sssd/sssd_pac.log <== (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0020): Search with filter [(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))] returned more than one object.
SIDs should be unique and it looks that currently in SSSD's cache are more than one object with the given SID. You can check the results yourself by calling: ldbsearch -H /var/lib/sss/db/cache_DOMAIN.NAME.ldb '(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))' (ldbsearch is in the ldb-tools package). Maybe this already explains what has happened but feel free to send the (sanitized) output.
(Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0040): Error: 22 (Invalid argument) (Mon Feb 11 05:24:36 2019) [sssd[pac]] [cache_req_search_cache] (0x0020): CR #5: Unable to lookup [<MY SID>@ad.domain.com] in cache [22]: Invalid argument ==> /var/log/sssd/krb5_child.log-20190210 <== (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][22]. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct. (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name]
That's odd. At the start of the log messages for 'krb5_child[26961]' there should be a line like: [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:..... Can you send the full line which the complete name of the ccache? bye, Sumit
==> /var/log/sssd/sssd_ipa.domain.com.log <== (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [child_sig_handler] (0x0100): child [26961] finished successfully. (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information Addtl. Details: ipa service-show ldap/prod-ipa01.ipa.domain.com@IPA.DOMAIN.COM| grep PAC
======================================================================================================================================================================================================================================================================================================================================================================================================================================================================
PAC type: MS-PAC Thanks, D
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
New logs are attached. They are from attempts to ssh into the IPA server as one of the AD users.
I think this is the problem now, but the full logs are attached in case I'm mistaken.
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_child_timeout] (0x0040): Timeout for child [11388] reached. In case KDC is distant or network is slow you may consider increasing value of krb5_auth_timeout. (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_done] (0x0020): child timed out!
Happy Friday :-)
D
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Thursday, February 14, 2019 4:34 AM, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Wed, Feb 13, 2019 at 08:18:10PM +0000, D wrote:
Update on this. The strange ldb record being returned was due to the user being added to the external AD connector group as an external group. Removing that and cleaning caches has fixed the problem. The larger issue with SSHD not working on a fresh install is not resolved, Sumit would you prefer a new thread or to continue here?
We can continue here.
The logs you have send only contains the SSS_PAM_PREAUTH step, I guess the error happens during SSS_PAM_AUTHENTICATE. Can you also increase the debug_level in the [domain/...] section to 9 and restart SSSD before running the test? I do not need all the logs, krb5_child.log would be sufficient for a start.
bye, Sumit
Thanks again for everything, D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Wednesday, 13 February 2019 11:03, D via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
Apologies for the delay Sumit. I've attached full sanitized logs this time. This should answer a few of the questions you asked.
is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
I don't see a line involving a switch from that UID - the results when running ssh user@ad.domain.com@client as root vs.user@ad.domain.com seem to be the same.
One of the (ldbsearch records returned) appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
Yes it does, GID is the same.
Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better?
I can switch this in the kerberos config on the client right, sure D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, February 12, 2019 4:00 PM, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Tue, Feb 12, 2019 at 08:37:44PM +0000, D wrote:
Sumit, The ldbsearch on the ipa client revealed two records with the SID in question, and the krb5 ccname is [KEYRING:persistent:$posix_uid_attribute] which matches the default ccname format in krb5.conf.
And is $posix_uid_attribute the same UID as the one from the log message two lines above: [unpack_buffer] (0x0100): cmd [...] uid [...] gid [...] validate ... Later on in the logs there should be [become_user] (0x0200): Trying to become user ... (0x2000): Running as .... is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
One of them appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
The ldbsearch command on the ipa server returns only the user record. Do you have any idea where this odd group record might be coming from?
It would be best to have full logs to understand what is happening. But since you say that the group memberships of the user are looking correct I guess this is not the primary issue why the login failed. Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better? HTH bye, Sumit
Thank you for your hard work, D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, 12 February 2019 02:19, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Mon, Feb 11, 2019 at 03:51:07PM +0000, D via FreeIPA-users wrote:
> Hello, > Would anyone mind helping me troubleshoot a problem? > > 1. Running a two-way trust between AD2016 and ipa-server 4.5.4-10.el7. > 2. Unable to log into an IPA client with an AD account via ssh. The client has no trouble with “kinit $ad_user” and “getent passwd $ad_user”. > 3. The AD user appears to properly exist in the correct groups for IPA/ad internal/external mapping as described in the docs. > > I think the problem occurs here, with the PAC fetch: > ==> /var/log/sssd/sssd_pac.log <== > (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0020): Search with filter [(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))] returned more than one object.
SIDs should be unique and it looks that currently in SSSD's cache are more than one object with the given SID. You can check the results yourself by calling: ldbsearch -H /var/lib/sss/db/cache_DOMAIN.NAME.ldb '(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))' (ldbsearch is in the ldb-tools package). Maybe this already explains what has happened but feel free to send the (sanitized) output.
> (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0040): Error: 22 (Invalid argument) > (Mon Feb 11 05:24:36 2019) [sssd[pac]] [cache_req_search_cache] (0x0020): CR #5: Unable to lookup [<MY SID>@ad.domain.com] in cache [22]: Invalid argument > ==> /var/log/sssd/krb5_child.log-20190210 <== > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][22]. > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct. > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name]
That's odd. At the start of the log messages for 'krb5_child[26961]' there should be a line like: [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:..... Can you send the full line which the complete name of the ccache? bye, Sumit
> ==> /var/log/sssd/sssd_ipa.domain.com.log <== > (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [child_sig_handler] (0x0100): child [26961] finished successfully. > (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information > Addtl. Details: > ipa service-show ldap/prod-ipa01.ipa.domain.com@IPA.DOMAIN.COM| grep PAC > ====================================================================================================================================================================================================================================================================================================================================================================================================================================================================== > PAC type: MS-PAC > Thanks, > D
> FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org > To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org > Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html > List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines > List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
Apologies, forgot to attach.
D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Friday, February 15, 2019 11:19 AM, D via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
New logs are attached. They are from attempts to ssh into the IPA server as one of the AD users.
I think this is the problem now, but the full logs are attached in case I'm mistaken.
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_child_timeout] (0x0040): Timeout for child [11388] reached. In case KDC is distant or network is slow you may consider increasing value of krb5_auth_timeout. (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_done] (0x0020): child timed out!
Happy Friday :-)
D
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Thursday, February 14, 2019 4:34 AM, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Wed, Feb 13, 2019 at 08:18:10PM +0000, D wrote:
Update on this. The strange ldb record being returned was due to the user being added to the external AD connector group as an external group. Removing that and cleaning caches has fixed the problem. The larger issue with SSHD not working on a fresh install is not resolved, Sumit would you prefer a new thread or to continue here?
We can continue here. The logs you have send only contains the SSS_PAM_PREAUTH step, I guess the error happens during SSS_PAM_AUTHENTICATE. Can you also increase the debug_level in the [domain/...] section to 9 and restart SSSD before running the test? I do not need all the logs, krb5_child.log would be sufficient for a start. bye, Sumit
Thanks again for everything, D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Wednesday, 13 February 2019 11:03, D via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
Apologies for the delay Sumit. I've attached full sanitized logs this time. This should answer a few of the questions you asked.
is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
I don't see a line involving a switch from that UID - the results when running ssh user@ad.domain.com@client as root vs.user@ad.domain.com seem to be the same.
One of the (ldbsearch records returned) appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
Yes it does, GID is the same.
Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better?
I can switch this in the kerberos config on the client right, sure D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, February 12, 2019 4:00 PM, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Tue, Feb 12, 2019 at 08:37:44PM +0000, D wrote:
Sumit, The ldbsearch on the ipa client revealed two records with the SID in question, and the krb5 ccname is [KEYRING:persistent:$posix_uid_attribute] which matches the default ccname format in krb5.conf.
And is $posix_uid_attribute the same UID as the one from the log message two lines above: [unpack_buffer] (0x0100): cmd [...] uid [...] gid [...] validate ... Later on in the logs there should be [become_user] (0x0200): Trying to become user ... (0x2000): Running as .... is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
One of them appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
The ldbsearch command on the ipa server returns only the user record. Do you have any idea where this odd group record might be coming from?
It would be best to have full logs to understand what is happening. But since you say that the group memberships of the user are looking correct I guess this is not the primary issue why the login failed. Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better? HTH bye, Sumit
Thank you for your hard work, D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, 12 February 2019 02:19, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
> On Mon, Feb 11, 2019 at 03:51:07PM +0000, D via FreeIPA-users wrote: > > > Hello, > > Would anyone mind helping me troubleshoot a problem? > > > > 1. Running a two-way trust between AD2016 and ipa-server 4.5.4-10.el7. > > 2. Unable to log into an IPA client with an AD account via ssh. The client has no trouble with “kinit $ad_user” and “getent passwd $ad_user”. > > 3. The AD user appears to properly exist in the correct groups for IPA/ad internal/external mapping as described in the docs. > > > > I think the problem occurs here, with the PAC fetch: > > ==> /var/log/sssd/sssd_pac.log <== > > (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0020): Search with filter [(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))] returned more than one object. > > SIDs should be unique and it looks that currently in SSSD's cache are > more than one object with the given SID. You can check the results > yourself by calling: > ldbsearch -H /var/lib/sss/db/cache_DOMAIN.NAME.ldb '(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))' > (ldbsearch is in the ldb-tools package). Maybe this already explains > what has happened but feel free to send the (sanitized) output. > > > (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0040): Error: 22 (Invalid argument) > > (Mon Feb 11 05:24:36 2019) [sssd[pac]] [cache_req_search_cache] (0x0020): CR #5: Unable to lookup [<MY SID>@ad.domain.com] in cache [22]: Invalid argument > > ==> /var/log/sssd/krb5_child.log-20190210 <== > > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][22]. > > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct. > > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] > > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name] > > That's odd. At the start of the log messages for 'krb5_child[26961]' > there should be a line like: > [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:..... > Can you send the full line which the complete name of the ccache? > bye, > Sumit > > > ==> /var/log/sssd/sssd_ipa.domain.com.log <== > > (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [child_sig_handler] (0x0100): child [26961] finished successfully. > > (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information > > Addtl. Details: > > ipa service-show ldap/prod-ipa01.ipa.domain.com@IPA.DOMAIN.COM| grep PAC > > > > ====================================================================================================================================================================================================================================================================================================================================================================================================================================================================== > > > > PAC type: MS-PAC > > Thanks, > > D > > > FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org > > To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org > > Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html > > List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines > > List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste... > > FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org > To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org > Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html > List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines > List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
On Fri, Feb 15, 2019 at 04:22:33PM +0000, D wrote:
Apologies, forgot to attach.
D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Friday, February 15, 2019 11:19 AM, D via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
New logs are attached. They are from attempts to ssh into the IPA server as one of the AD users.
I think this is the problem now, but the full logs are attached in case I'm mistaken.
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_child_timeout] (0x0040): Timeout for child [11388] reached. In case KDC is distant or network is slow you may consider increasing value of krb5_auth_timeout.
Ok, the timeout is happening already during pre-auth setting the backend into offline-mode. Maybe the keyring error is related to the offline mode, although I do not see it in my setup when offline.
Have you tried the suggestion from the debug message and increased krb5_auth_timeout in the [domain/....] section of sssd.conf? The default is 6 (seconds), I would suggest to try 30 for a start. And please set debug_level=9 in the [domain/...] section as well. I extra output might help to identify where the delay is coming from.
bye, Sumit
(Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_done] (0x0020): child timed out!
Happy Friday :-)
D
‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Thursday, February 14, 2019 4:34 AM, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Wed, Feb 13, 2019 at 08:18:10PM +0000, D wrote:
Update on this. The strange ldb record being returned was due to the user being added to the external AD connector group as an external group. Removing that and cleaning caches has fixed the problem. The larger issue with SSHD not working on a fresh install is not resolved, Sumit would you prefer a new thread or to continue here?
We can continue here. The logs you have send only contains the SSS_PAM_PREAUTH step, I guess the error happens during SSS_PAM_AUTHENTICATE. Can you also increase the debug_level in the [domain/...] section to 9 and restart SSSD before running the test? I do not need all the logs, krb5_child.log would be sufficient for a start. bye, Sumit
Thanks again for everything, D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Wednesday, 13 February 2019 11:03, D via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
Apologies for the delay Sumit. I've attached full sanitized logs this time. This should answer a few of the questions you asked.
is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
I don't see a line involving a switch from that UID - the results when running ssh user@ad.domain.com@client as root vs.user@ad.domain.com seem to be the same.
> One of the (ldbsearch records returned) appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
Yes it does, GID is the same.
Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better?
I can switch this in the kerberos config on the client right, sure D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Tuesday, February 12, 2019 4:00 PM, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote:
On Tue, Feb 12, 2019 at 08:37:44PM +0000, D wrote:
> Sumit, > The ldbsearch on the ipa client revealed two records with the SID in question, and the krb5 ccname is [KEYRING:persistent:$posix_uid_attribute] which matches the default ccname format in krb5.conf.
And is $posix_uid_attribute the same UID as the one from the log message two lines above: [unpack_buffer] (0x0100): cmd [...] uid [...] gid [...] validate ... Later on in the logs there should be [become_user] (0x0200): Trying to become user ... (0x2000): Running as .... is there a line before '[-1750600185][Invalid UID in persistent keyring name]' error where krb5_child tries to switch to this UID or is it always running as root?
> One of them appears to be a user, and the other, incorrect one, is a group record. Cleaning cache and deleting database files does not seem to fix this.
Does the group record share some properties of the user record like same name or GID==UID?
> The ldbsearch command on the ipa server returns only the user record. > Do you have any idea where this odd group record might be coming from?
It would be best to have full logs to understand what is happening. But since you say that the group memberships of the user are looking correct I guess this is not the primary issue why the login failed. Besides trying to figure out what is wrong with the KEYRING ccache you might also want to try if a different ccache type, e.g. FILE:...., works any better? HTH bye, Sumit
> Thank you for your hard work, > D > ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ > On Tuesday, 12 February 2019 02:19, Sumit Bose via FreeIPA-users freeipa-users@lists.fedorahosted.org wrote: > > > On Mon, Feb 11, 2019 at 03:51:07PM +0000, D via FreeIPA-users wrote: > > > > > Hello, > > > Would anyone mind helping me troubleshoot a problem? > > > > > > 1. Running a two-way trust between AD2016 and ipa-server 4.5.4-10.el7. > > > 2. Unable to log into an IPA client with an AD account via ssh. The client has no trouble with “kinit $ad_user” and “getent passwd $ad_user”. > > > 3. The AD user appears to properly exist in the correct groups for IPA/ad internal/external mapping as described in the docs. > > > > > > I think the problem occurs here, with the PAC fetch: > > > ==> /var/log/sssd/sssd_pac.log <== > > > (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0020): Search with filter [(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))] returned more than one object. > > > > SIDs should be unique and it looks that currently in SSSD's cache are > > more than one object with the given SID. You can check the results > > yourself by calling: > > ldbsearch -H /var/lib/sss/db/cache_DOMAIN.NAME.ldb '(&(|(objectCategory=user)(objectCategory=group))(objectSIDString= < MY SID HERE >))' > > (ldbsearch is in the ldb-tools package). Maybe this already explains > > what has happened but feel free to send the (sanitized) output. > > > > > (Mon Feb 11 05:24:36 2019) [sssd[pac]] [sysdb_search_object_attr] (0x0040): Error: 22 (Invalid argument) > > > (Mon Feb 11 05:24:36 2019) [sssd[pac]] [cache_req_search_cache] (0x0020): CR #5: Unable to lookup [<MY SID>@ad.domain.com] in cache [22]: Invalid argument > > > ==> /var/log/sssd/krb5_child.log-20190210 <== > > > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [sss_send_pac] (0x0040): sss_pac_make_request failed [-1][22]. > > > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [validate_tgt] (0x0040): sss_send_pac failed, group membership for user with principal [<my username>@AD.DOMAIN.COM] might not be correct. > > > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] > > > (Mon Feb 11 05:24:36 2019) [[sssd[krb5_child[26961]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name] > > > > That's odd. At the start of the log messages for 'krb5_child[26961]' > > there should be a line like: > > [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:..... > > Can you send the full line which the complete name of the ccache? > > bye, > > Sumit > > > > > ==> /var/log/sssd/sssd_ipa.domain.com.log <== > > > (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [child_sig_handler] (0x0100): child [26961] finished successfully. > > > (Mon Feb 11 05:24:36 2019) [sssd[be[ipa.domain.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information > > > Addtl. Details: > > > ipa service-show ldap/prod-ipa01.ipa.domain.com@IPA.DOMAIN.COM| grep PAC > > > > > > ====================================================================================================================================================================================================================================================================================================================================================================================================================================================================== > > > > > > PAC type: MS-PAC > > > Thanks, > > > D > > > > > FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org > > > To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org > > > Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html > > > List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines > > > List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste... > > > > FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org > > To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org > > Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html > > List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines > > List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahoste...
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:56:48 2019) [sssd[nss]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:56:48 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Fri Feb 15 15:56:48 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #287: New request 'User by name' (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #287: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #287: Setting name [myuser] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #287: Performing a single domain search (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #287: Search will check the cache and check the data provider (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #287: Using domain [splat.acme.com] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #287: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #287: Looking up myuser@splat.acme.com (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #287: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #287: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #287: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #287: Object found, but needs to be refreshed. (Fri Feb 15 15:56:48 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #287: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:56:48 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #100]: New request. Flags [0x0001]. (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_splat.acme.com' (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain splat.acme.com and site VA (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'VA._sites.splat.acme.com' (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.VA._sites.splat.acme.com' (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing... (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [fo_discover_srv_done] (0x0400): Got 2 servers (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [ad_get_dc_servers_done] (0x0400): Found 2 domain controllers in domain VA._sites.splat.acme.com (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [ad_srv_plugin_dcs_done] (0x0400): About to locate suitable site (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_send] (0x0400): Resolving host VA-PROD-AD02.splat.acme.com (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'VA-PROD-AD02.splat.acme.com' in files (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'VA-PROD-AD02.splat.acme.com' in files (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'VA-PROD-AD02.splat.acme.com' in DNS (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_resolv_done] (0x0400): Connecting to ldap://VA-PROD-AD02.splat.acme.com:389 (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_done] (0x0400): Successful connection to ldap://VA-PROD-AD02.splat.acme.com:389 (Fri Feb 15 15:56:48 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(DnsDomain=splat.acme.com)(NtVer=\14\00\00\00))][]. (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_timeout] (0x0080): Service resolving timeout reached (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'sd_splat.acme.com' (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolve_srv_send] (0x0200): The status of SRV lookup is neutral (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ad_srv_plugin_send] (0x0400): About to find domain controllers (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ad_get_dc_servers_send] (0x0400): Looking up domain controllers in domain splat.acme.com and site VA (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_discover_srv_next_domain] (0x0400): SRV resolution of service 'ldap'. Will use DNS discovery domain 'VA._sites.splat.acme.com' (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_getsrv_send] (0x0100): Trying to resolve SRV record of '_ldap._tcp.VA._sites.splat.acme.com' (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [fo_discover_srv_done] (0x0400): Got answer. Processing... (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [fo_discover_srv_done] (0x0400): Got 2 servers (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ad_get_dc_servers_done] (0x0400): Found 2 domain controllers in domain VA._sites.splat.acme.com (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [ad_srv_plugin_dcs_done] (0x0400): About to locate suitable site (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_send] (0x0400): Resolving host VA-PROD-AD02.splat.acme.com (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'VA-PROD-AD02.splat.acme.com' in files (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'VA-PROD-AD02.splat.acme.com' in files (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_next] (0x0200): No more address families to retry (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'VA-PROD-AD02.splat.acme.com' in DNS (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [request_watch_destructor] (0x0400): Deleting request watch (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_resolv_done] (0x0400): Connecting to ldap://VA-PROD-AD02.splat.acme.com:389 (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_connect_host_done] (0x0400): Successful connection to ldap://VA-PROD-AD02.splat.acme.com:389 (Fri Feb 15 15:56:54 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(DnsDomain=splat.acme.com)(NtVer=\14\00\00\00))][]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_timeout] (0x0080): Service resolving timeout reached (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_id_op_connect_done] (0x0400): Failed to connect to server, but ignore mark offline is enabled. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #100]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #100]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #100]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #100]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0040): CR #287: Data Provider Error: 3, 1432158271, Subdomain is inactive (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_common_dp_recv] (0x0400): CR #287: Due to an error we will return cached data (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #287: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #287: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #287: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #287: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #287: Finished: Success (Fri Feb 15 15:57:00 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: nobody (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #288: New request 'Initgroups by name' (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #288: Parsing input name [nobody] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'nobody' matched without domain, user is nobody (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #288: Setting name [nobody] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #288: Performing a multi-domain search (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #288: Search will check the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #288: Using domain [ipa.splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #288: Preparing input data for domain [ipa.splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #288: Looking up nobody@ipa.splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #288: Checking negative cache for [nobody@ipa.splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #288: [nobody@ipa.splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #288: Looking up [nobody@ipa.splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #288: Object [nobody@ipa.splat.acme.com] was not found in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #288: Looking up [nobody@ipa.splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:3:nobody@ipa.splat.acme.com@ipa.splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [ipa.splat.acme.com][0x3][BE_REQ_INITGROUPS][name=nobody@ipa.splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:3:nobody@ipa.splat.acme.com@ipa.splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=nobody@ipa.splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #101]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_initgr_next_base] (0x0400): Searching for users with base [cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(uid=nobody)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_search_user_by_upn] (0x0400): No entry with upn [nobody@ipa.splat.acme.com] found. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_search_entry_by_sid_str] (0x0400): No such entry (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_search_object_attr] (0x0400): No such entry. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_get_real_name] (0x0040): Cannot find user [nobody@ipa.splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_search_by_name] (0x0400): No such entry (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_delete_user] (0x0400): Error: 2 (No such file or directory) (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_search_by_name] (0x0400): No such entry (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_id_get_account_info_orig_done] (0x0080): Object not found, ending request (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #101]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #101]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #101]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::ipa.splat.acme.com:name=nobody@ipa.splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #101]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #288: Looking up [nobody@ipa.splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #288: Object [nobody@ipa.splat.acme.com] was not found in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache_add_to_domain] (0x0400): CR #288: Adding [nobody@ipa.splat.acme.com] to negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/ipa.splat.acme.com/nobody@ipa.splat.acme.com] to negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR #288: Finished: Not found (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:3:nobody@ipa.splat.acme.com@ipa.splat.acme.com]
==> /var/log/sssd/sssd_ssh.log <== (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [accept_fd_handler] (0x0400): Client connected! (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Received client version [0]. (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_cmd_get_version] (0x0200): Offered version [0]. (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [ssh_protocol_parse_request] (0x0400): Requested domain [<ALL>] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [ssh_cmd_get_user_pubkeys] (0x0400): Requesting SSH user public keys for [myuser@splat.acme.com] from [<ALL>] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_send] (0x0400): CR #1: New request 'User by name' (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_process_input] (0x0400): CR #1: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_set_name] (0x0400): CR #1: Setting name [myuser] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_select_domains] (0x0400): CR #1: Performing a single domain search (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_domains] (0x0400): CR #1: Search will check the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_set_domain] (0x0400): CR #1: Using domain [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_prepare_domain_data] (0x0400): CR #1: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_send] (0x0400): CR #1: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_ncache] (0x0400): CR #1: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_ncache] (0x0400): CR #1: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_cache] (0x0400): CR #1: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_send] (0x0400): CR #1: Object found, but needs to be refreshed. (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_dp] (0x0400): CR #1: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7fed9b6f0160:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7fed9b6f0160:1:myuser@splat.acme.com@splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #102]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #102]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #102]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #102]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #102]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_ssh.log <== (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_cache] (0x0400): CR #1: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_ncache_filter] (0x0400): CR #1: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_search_done] (0x0400): CR #1: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_create_and_add_result] (0x0400): CR #1: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7fed9b6f0160:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [cache_req_done] (0x0400): CR #1: Finished: Success (Fri Feb 15 15:57:00 2019) [sssd[ssh]] [client_recv] (0x0200): Client disconnected!
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #289: New request 'User by name' (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #289: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #289: Setting name [myuser] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #289: Performing a single domain search (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #289: Search will check the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #289: Using domain [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #289: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #289: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #289: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #289: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #289: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #289: Object found, but needs to be refreshed. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #289: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #103]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #103]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #103]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #103]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #103]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #289: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #289: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #289: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #289: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #289: Finished: Success (Fri Feb 15 15:57:00 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #290: New request 'User by name' (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #290: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #290: Setting name [myuser] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #290: Performing a single domain search (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #290: Search will check the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #290: Using domain [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #290: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #290: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #290: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #290: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #290: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #290: Object found, but needs to be refreshed. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #290: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #104]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #104]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #104]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #104]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #104]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #290: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #290: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #290: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #290: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #290: Finished: Success (Fri Feb 15 15:57:00 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #291: New request 'User by name' (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #291: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #291: Setting name [myuser] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #291: Performing a single domain search (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #291: Search will check the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #291: Using domain [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #291: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #291: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #291: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #291: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #291: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #291: Object found, but needs to be refreshed. (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #291: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #105]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #105]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #105]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #105]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #105]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #291: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #291: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #291: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #291: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #291: Finished: Success
==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:00 2019) [sssd[pam]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:00 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe! (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3]. (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3]. (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_send] (0x0400): CR #1: New request 'Initgroups by name' (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_process_input] (0x0400): CR #1: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_set_name] (0x0400): CR #1: Setting name [myuser] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #1: Performing a single domain search (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #1: Search will bypass the cache and check the data provider (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #1: Using domain [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #1: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #1: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #1: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #1: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #1: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #106]: New request. Flags [0x0001]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #106]: Request handler finished [0]: Success (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #106]: Receiving request data. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #106]: Finished. Success. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #106]: Request removed. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #1: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #1: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_search_done] (0x0400): CR #1: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #1: Found 12 entries in domain splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:00 2019) [sssd[pam]] [cache_req_done] (0x0400): CR #1: Finished: Success (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): ruser: (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): logon name: not set (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [PAM Preauth #107]: New request. Flags [0000]. (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [be_resolve_server_process] (0x0200): Found address for server va-prod-ipa01.ipa.splat.acme.com: [172.18.181.132] TTL 7200 (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://va-prod-ipa01.ipa.splat.acme.com' (Fri Feb 15 15:57:00 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent!
==> /var/log/sssd/krb5_child.log <== (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [main] (0x0400): krb5_child started. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [unpack_buffer] (0x0100): cmd [249] uid [612329895] gid [612329895] validate [true] enterprise principal [false] offline [true] UPN [myuser@SPLAT.acme.com] (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:612329895] old_ccname: [not set] keytab: [/etc/krb5.keytab] (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [become_user] (0x0200): Already user [612329895]. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [main] (0x0400): Will perform pre-auth (Fri Feb 15 15:57:00 2019) [[sssd[krb5_child[11388]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SPLAT.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_child_timeout] (0x0040): Timeout for child [11388] reached. In case KDC is distant or network is slow you may consider increasing value of krb5_auth_timeout. (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_done] (0x0020): child timed out! (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Preauth #107]: Request handler finished [0]: Success (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Preauth #107]: Receiving request data. (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Preauth #107]: Request removed. (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:06 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [15 (Authentication service cannot retrieve user credentials)][splat.acme.com] (Fri Feb 15 15:57:06 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [15]: Authentication service cannot retrieve user credentials. (Fri Feb 15 15:57:06 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Fri Feb 15 15:57:06 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 29
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:06 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0020): child [11388] was terminated by signal [9].
==> /var/log/sssd/sssd_pac.log <== (Fri Feb 15 15:57:07 2019) [sssd[pac]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:07 2019) [sssd[pac]] [accept_fd_handler] (0x0020): Access denied for uid [389].
==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_cmd_authenticate] (0x0100): entering pam_cmd_authenticate (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_send] (0x0400): CR #2: New request 'Initgroups by name' (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_process_input] (0x0400): CR #2: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_set_name] (0x0400): CR #2: Setting name [myuser] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #2: Performing a single domain search (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #2: Search will bypass the cache and check the data provider (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #2: Using domain [splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #2: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #2: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #2: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #2: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #2: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #108]: New request. Flags [0x0001]. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #108]: Request handler finished [0]: Success (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #108]: Receiving request data. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #108]: Finished. Success. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #108]: Request removed. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #2: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #2: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_search_done] (0x0400): CR #2: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #2: Found 12 entries in domain splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [cache_req_done] (0x0400): CR #2: Finished: Success (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 1 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): command: SSS_PAM_AUTHENTICATE (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): ruser: (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): authtok type: 1 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): cli_pid: 11387 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): logon name: not set (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [PAM Authenticate #109]: New request. Flags [0000]. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [be_resolve_server_process] (0x0200): Found address for server va-prod-ipa01.ipa.splat.acme.com: [172.18.181.132] TTL 7200 (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent!
==> /var/log/sssd/krb5_child.log <== (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [main] (0x0400): krb5_child started. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [unpack_buffer] (0x0100): cmd [241] uid [612329895] gid [612329895] validate [true] enterprise principal [false] offline [true] UPN [myuser@SPLAT.acme.com] (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:612329895] old_ccname: [not set] keytab: [/etc/krb5.keytab] (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [become_user] (0x0200): Already user [612329895]. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [main] (0x0400): Will perform offline auth (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [create_ccache] (0x0020): 973: [-1750600185][Invalid UID in persistent keyring name] (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [map_krb5_error] (0x0020): 1657: [-1750600185][Invalid UID in persistent keyring name] (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [k5c_send_data] (0x0200): Received error code 1432158209 (Fri Feb 15 15:57:09 2019) [[sssd[krb5_child[11396]]]] [main] (0x0400): krb5_child completed successfully
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0100): child [11396] finished successfully. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_done] (0x0040): The krb5_child process returned an error. Please inspect the krb5_child.log file or the journal for more information (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Authenticate #109]: Request handler finished [0]: Success (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Authenticate #109]: Receiving request data. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Authenticate #109]: Request removed. (Fri Feb 15 15:57:09 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [4 (System error)][splat.acme.com] (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [4]: System error. (Fri Feb 15 15:57:09 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Fri Feb 15 15:57:09 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 29
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:11 2019) [sssd[nss]] [client_recv] (0x0200): Client disconnected!
==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:11 2019) [sssd[pam]] [client_recv] (0x0200): Client disconnected!
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:11 2019) [sssd[nss]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client connected! (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Received client version [1]. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered version [1]. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #292: New request 'User by name' (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #292: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #292: Setting name [myuser] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #292: Performing a single domain search (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #292: Search will check the cache and check the data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #292: Using domain [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #292: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #292: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #292: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #292: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #292: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #292: Object found, but needs to be refreshed. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #292: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #110]: New request. Flags [0x0001]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #110]: Request handler finished [0]: Success (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #110]: Receiving request data. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #110]: Finished. Success. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #110]: Request removed. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #292: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #292: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #292: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #292: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #292: Finished: Success (Fri Feb 15 15:57:11 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #293: New request 'User by name' (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #293: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #293: Setting name [myuser] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #293: Performing a single domain search (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #293: Search will check the cache and check the data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #293: Using domain [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #293: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #293: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #293: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #293: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #293: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #293: Object found, but needs to be refreshed. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #293: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #111]: New request. Flags [0x0001]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #111]: Request handler finished [0]: Success (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #111]: Receiving request data. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #111]: Finished. Success. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #111]: Request removed. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #293: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #293: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #293: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #293: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #293: Finished: Success (Fri Feb 15 15:57:11 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #294: New request 'User by name' (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #294: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #294: Setting name [myuser] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #294: Performing a single domain search (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #294: Search will check the cache and check the data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #294: Using domain [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #294: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #294: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #294: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #294: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #294: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #294: Object found, but needs to be refreshed. (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #294: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x1][BE_REQ_USER][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x1][BE_REQ_USER][name=myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Account #112]: New request. Flags [0x0001]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Account #112]: Request handler finished [0]: Success (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Account #112]: Receiving request data. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Account #112]: Finished. Success. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:1::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Account #112]: Request removed. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_nss.log <== (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #294: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #294: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_search_done] (0x0400): CR #294: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #294: Found 1 entries in domain splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[nss]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f017cb1cb90:1:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #294: Finished: Success
==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:11 2019) [sssd[pam]] [get_client_cred] (0x0080): The following failure is expected to happen in case SELinux is disabled: SELINUX_getpeercon failed [92][Protocol not available]. Please, consider enabling SELinux in your system. (Fri Feb 15 15:57:11 2019) [sssd[pam]] [accept_fd_handler] (0x0400): Client connected to privileged pipe! (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Received client version [3]. (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_cmd_get_version] (0x0200): Offered version [3]. (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_cmd_preauth] (0x0100): entering pam_cmd_preauth (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11399 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_send] (0x0400): CR #3: New request 'Initgroups by name' (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_process_input] (0x0400): CR #3: Parsing input name [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_parse_name_for_domains] (0x0200): name 'myuser@splat.acme.com' matched expression for domain 'splat.acme.com', user is myuser (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_set_name] (0x0400): CR #3: Setting name [myuser] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_select_domains] (0x0400): CR #3: Performing a single domain search (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_domains] (0x0400): CR #3: Search will check the cache and check the data provider (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_set_domain] (0x0400): CR #3: Using domain [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_prepare_domain_data] (0x0400): CR #3: Preparing input data for domain [splat.acme.com] rules (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #3: Looking up myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #3: Checking negative cache for [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_ncache] (0x0400): CR #3: [myuser@splat.acme.com] is not present in negative cache (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #3: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_send] (0x0400): CR #3: Object found, but needs to be refreshed. (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_dp] (0x0400): CR #3: Looking up [myuser@splat.acme.com] in data provider (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_dp_issue_request] (0x0400): Issuing request for [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_dp_get_account_msg] (0x0400): Creating request for [splat.acme.com][0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com:-] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_dp_internal_get_send] (0x0400): Entering request [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com]
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_get_account_info_handler] (0x0200): Got request for [0x3][BE_REQ_INITGROUPS][name=myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [Initgroups #113]: New request. Flags [0x0001]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaUserOverride)(uid=myuser))][cn=Default Trust View,cn=views,cn=accounts,dc=ipa,dc=splat,dc=bt,dc=com]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0080): Sudomain lookup failed, will try to reset sudomain.. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_retried] (0x0400): Sudomain re-set, will retry lookup (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [be_fo_reset_svc] (0x0080): Cannot retrieve service [splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_step] (0x0400): Looking up AD account (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_srv_ad_acct_lookup_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_subdomain_account_done] (0x0040): ipa_get_*_acct request failed: [1432158271]: Subdomain is inactive. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_reply_std_set] (0x0080): DP Error is OK on failed request? (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [Initgroups #113]: Request handler finished [0]: Success (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [Initgroups #113]: Receiving request data. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_initgr_pp_nss_notify] (0x0400): Ordering NSS responder to update memory cache (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_reply_list_success] (0x0400): DP Request [Initgroups #113]: Finished. Success. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_table_value_destructor] (0x0400): Removing [0:1:0x0001:3::splat.acme.com:name=myuser@splat.acme.com] from reply table (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [Initgroups #113]: Request removed. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_cache] (0x0400): CR #3: Looking up [myuser@splat.acme.com] in cache (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_ncache_filter] (0x0400): CR #3: This request type does not support filtering result by negative cache (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_search_done] (0x0400): CR #3: Returning updated object [myuser@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_create_and_add_result] (0x0400): CR #3: Found 12 entries in domain splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x7f916280d4c0:3:myuser@splat.acme.com@splat.acme.com] (Fri Feb 15 15:57:11 2019) [sssd[pam]] [cache_req_done] (0x0400): CR #3: Finished: Success (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pd_set_primary_name] (0x0400): User's primary name is myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_dp_send_req] (0x0100): Sending request with the following data: (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): ruser: not set (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): cli_pid: 11399 (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_print_data] (0x0100): logon name: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[pam]] [pam_dom_forwarder] (0x0100): pam_dp_send_req returned 0
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): domain: splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): user: myuser@splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): service: sshd (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): tty: ssh (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): ruser: (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): authtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): priv: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): cli_pid: 11399 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): logon name: not set (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [PAM Preauth #114]: New request. Flags [0000]. (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [be_resolve_server_process] (0x0200): Found address for server va-prod-ipa01.ipa.splat.acme.com: [172.18.181.132] TTL 7200 (Fri Feb 15 15:57:11 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent!
==> /var/log/sssd/krb5_child.log <== (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [main] (0x0400): krb5_child started. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [unpack_buffer] (0x0100): cmd [249] uid [612329895] gid [612329895] validate [true] enterprise principal [false] offline [true] UPN [myuser@SPLAT.acme.com] (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:612329895] old_ccname: [not set] keytab: [/etc/krb5.keytab] (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [become_user] (0x0200): Trying to become user [612329895][612329895]. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [become_user] (0x0200): Already user [612329895]. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [main] (0x0400): Will perform pre-auth (Fri Feb 15 15:57:11 2019) [[sssd[krb5_child[11400]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SPLAT.acme.com] (Fri Feb 15 15:57:12 2019) [[sssd[krb5_child[11400]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts. (Fri Feb 15 15:57:12 2019) [[sssd[krb5_child[11400]]]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth. (Fri Feb 15 15:57:12 2019) [[sssd[krb5_child[11400]]]] [k5c_send_data] (0x0200): Received error code 0 (Fri Feb 15 15:57:12 2019) [[sssd[krb5_child[11400]]]] [main] (0x0400): krb5_child completed successfully
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0100): child [11400] finished successfully. (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [set_server_common_status] (0x0100): Marking server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=myuser@splat.acme.com,cn=users,cn=splat.acme.com,cn=sysdb] has set [cache, ts_cache] attrs. (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_cache_creds] (0x0080): Delayed authentication is only available for password authentication (single factor). (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Preauth #114]: Request handler finished [0]: Success (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Preauth #114]: Receiving request data. (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Preauth #114]: Request removed. (Fri Feb 15 15:57:12 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0
==> /var/log/sssd/sssd_pam.log <== (Fri Feb 15 15:57:12 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [4 (System error)][splat.acme.com] (Fri Feb 15 15:57:12 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [4]: System error. (Fri Feb 15 15:57:12 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Fri Feb 15 15:57:12 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 37 ^C
[root@va-prod-ipa01 ~]# getent passwd myuser@splat.acme.com myuser@splat.acme.com:*:612329895:612329895:myuser:/home/splat.acme.com/myuser:
[root@va-prod-ipa01 ~]# kinit myuser@splat.acme.com Password for myuser@splat.acme.com:
[root@va-prod-ipa01 ~]#
freeipa-users@lists.fedorahosted.org
-
D -
John Keates -
Sumit Bose