(second try without the logs)
On Fri, Feb 15, 2019 at 09:26:08PM +0100, Sumit Bose wrote:
> On Fri, Feb 15, 2019 at 07:24:10PM +0000, D wrote:
> > I have increased krb5_auth_timeout to 30 and raised debug to level 9, Logs attached.
> >
> > The krb5_child_timeout has gone away, so we might be one step closer to finding the issue now.
> >
> > Eager to hear your thoughts on the logs.
Now timeouts occur when trying to connect to LDAP servers, see lines 81
and 139 in the log file. The name and the IP address can be found a few
line before. Is it expected that AD DCs respond very slowly or are there
some firewall between the IPA server and the AD DCs? In the former case
you can try to increase ldap_search_timeout, default is 6s as well.
bye,
Sumit
> >
> > Thanks,
> > D
> >
> > ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐
> > On Friday, 15 February 2019 13:23, Sumit Bose via FreeIPA-users <freeipa-users(a)lists.fedorahosted.org> wrote:
> >
> > > 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(a)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(a)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(a)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(a)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(a)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(a)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
