According to ldapsearch, yes the AD servers do exhibit intermittent slowness.
ldap_search_timeout has now been increased to 30. I believe that we are now seeing a new error, do you mind analysing this new log? Many Thanks, D ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ On Friday, 15 February 2019 15:46, Sumit Bose via FreeIPA-users <freeipa-users@lists.fedorahosted.org> wrote: > (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@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@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.u...@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 > > FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org > To unsubscribe send an email to freeipa-users-le...@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.fedorahosted.org
==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7fadf253c4a0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_dispatch] (0x4000): Dispatching. (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_message_handler] (0x2000): Received SBUS method org.freedesktop.sssd.dataprovider.pamHandler on path /org/freedesktop/sssd/dataprovider (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_handler] (0x0100): Got request with the following data (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): command: SSS_PAM_PREAUTH (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): domain: splat.acme.com (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): user: myu...@splat.acme.com (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): service: sshd (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): tty: ssh (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): ruser: (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): rhost: va-admin.splat.acme.com (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): authtok type: 0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): newauthtok type: 0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): priv: 1 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): cli_pid: 17707 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [pam_print_data] (0x0100): logon name: not set (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): DP Request [PAM Preauth #78]: New request. Flags [0000]. (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [dp_attach_req] (0x0400): Number of active DP request: 1 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain ipa.splat.acme.com is Active (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain splat.acme.com is Inactive (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain ipa.splat.acme.com is Active (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain splat.acme.com is Inactive (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_queue_send] (0x1000): Wait queue of user [myu...@splat.acme.com] is empty, running request [0x7fadf254e780] immediately. (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain ipa.splat.acme.com is Active (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain splat.acme.com is Inactive (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_setup] (0x4000): No mapping for: myu...@splat.acme.com (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fadf2540fa0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fadf255be80 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Running timer event 0x7fadf2540fa0 "ltdb_callback" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Destroying timer event 0x7fadf255be80 "ltdb_timeout" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Ending timer event 0x7fadf2540fa0 "ltdb_callback" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fadf254c770 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fadf255a1e0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Running timer event 0x7fadf254c770 "ltdb_callback" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Destroying timer event 0x7fadf255a1e0 "ltdb_timeout" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Ending timer event 0x7fadf254c770 "ltdb_callback" (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [get_server_status] (0x1000): Status of server 'va-prod-ipa01.ipa.splat.acme.com' is 'working' (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [get_port_status] (0x1000): Port status of port 0 for server 'va-prod-ipa01.ipa.splat.acme.com' is 'working' (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [get_server_status] (0x1000): Status of server 'va-prod-ipa01.ipa.splat.acme.com' is 'working' (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [be_resolve_server_process] (0x1000): Saving the first resolved server (Tue Feb 19 19:04:52 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 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://va-prod-ipa01.ipa.splat.acme.com' (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [unique_filename_destructor] (0x2000): Unlinking [/var/lib/sss/pubconf/.krb5info_dummy_TjcBSc] (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [unlink_dbg] (0x2000): File already removed: [/var/lib/sss/pubconf/.krb5info_dummy_TjcBSc] (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sss_domain_get_state] (0x1000): Domain splat.acme.com is Inactive (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_resolve_done] (0x2000): Subdomain splat.acme.com is inactive, will proceed offline (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [17708] (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [child_handler_setup] (0x2000): Signal handler set up for pid [17708] (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_dispatch] (0x4000): dbus conn: 0x7fadf25326a0 (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [sbus_dispatch] (0x4000): Dispatching. (Tue Feb 19 19:04:52 2019) [sssd[be[ipa.splat.acme.com]]] [write_pipe_handler] (0x0400): All data has been sent! ==> /var/log/sssd/krb5_child.log <== (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [main] (0x0400): krb5_child started. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [unpack_buffer] (0x1000): total buffer size: [147] (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [unpack_buffer] (0x0100): cmd [249] uid [612329111] gid [612329111] validate [true] enterprise principal [false] offline [true] UPN [myu...@splat.acme.com] (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:612329111] old_ccname: [KEYRING:persistent:612329111] keytab: [/etc/krb5.keytab] (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [become_user] (0x0200): Trying to become user [612329111][612329111]. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [main] (0x2000): Running as [612329111][612329111]. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [become_user] (0x0200): Trying to become user [612329111][612329111]. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [become_user] (0x0200): Already user [612329111]. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [k5c_setup] (0x2000): Running as [612329111][612329111]. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [set_lifetime_options] (0x0100): No specific lifetime requested. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [main] (0x0400): Will perform pre-auth (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [tgt_req_child] (0x1000): Attempting to get a TGT (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [SPLAT.acme.COM] (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107670: Getting initial credentials for myu...@splat.acme.com (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107672: Sending request (174 bytes) to SPLAT.acme.COM (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107673: Resolving hostname SV-DC-01.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107674: Resolving hostname EQ-PROD-AD02.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107675: Resolving hostname VA-PROD-AD02.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107676: Resolving hostname FR-PROD-AD01.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107677: Resolving hostname SV-PROD-AD02.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107678: Resolving hostname FR-PROD-AD02.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107679: Resolving hostname VA-PROD-AD01.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107680: Resolving hostname EQ-PROD-AD01.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107681: Resolving hostname SV-DC-01.splat.acme.com. (Tue Feb 19 19:04:52 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603092.107682: Initiating TCP connection to stream 172.18.171.35:88 ==> /var/log/sssd/sssd_pam.log <== (Tue Feb 19 19:04:52 2019) [sssd[pam]] [pam_initgr_cache_remove] (0x2000): [myu...@splat.acme.com] removed from PAM initgroup cache ==> /var/log/sssd/krb5_child.log <== (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436765: Resolving hostname EQ-PROD-AD02.splat.acme.com. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436766: Initiating TCP connection to stream 10.25.172.49:88 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436767: Sending TCP request to stream 10.25.172.49:88 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436768: Received answer (185 bytes) from stream 10.25.172.49:88 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436769: Terminating TCP connection to stream 172.18.171.35:88 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436770: Terminating TCP connection to stream 10.25.172.49:88 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436771: Response was not from master KDC (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436772: Received error from KDC: -1765328359/Additional pre-authentication required (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436775: Processing preauth types: 16, 15, 19, 2 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436776: Selected etype info: etype aes256-cts, salt "SPLAT.acme.COMmyuser", params "" (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436777: PKINIT client has no configured identity; giving up (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_krb5_responder] (0x4000): Got question [password]. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436778: PKINIT client has no configured identity; giving up (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436779: Preauth module pkinit (16) (real) returned: 22/Invalid argument (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436780: PKINIT client has no configured identity; giving up (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436781: Preauth module pkinit (14) (real) returned: 22/Invalid argument (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_krb5_prompter] (0x4000): sss_krb5_prompter name [(null)] banner [(null)] num_prompts [1] EINVAL. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_krb5_prompter] (0x4000): Prompt [0][Password for myu...@splat.acme.com]. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_krb5_prompter] (0x0020): Cannot handle password prompts. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436782: Preauth module encrypted_timestamp (2) (real) returned: -1765328254/Cannot read password (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436783: Retrying AS request with master KDC (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436784: Getting initial credentials for myu...@splat.acme.com (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [sss_child_krb5_trace_cb] (0x4000): [17708] 1550603093.436786: Sending request (174 bytes) to SPLAT.acme.COM (master) (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [get_and_save_tgt] (0x0400): krb5_get_init_creds_password returned [-1765328174] during pre-auth. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [k5c_send_data] (0x0200): Received error code 0 (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [pack_response_packet] (0x2000): response packet size: [12] (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [k5c_send_data] (0x4000): Response sent. (Tue Feb 19 19:04:53 2019) [[sssd[krb5_child[17708]]]] [main] (0x0400): krb5_child completed successfully ==> /var/log/sssd/sssd_ipa.splat.acme.com.log <== (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x1000): Waiting for child [17708]. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [child_sig_handler] (0x0100): child [17708] finished successfully. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [read_pipe_handler] (0x0400): EOF received, client finished (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [parse_krb5_child_response] (0x1000): child response [0][11][0]. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: src/providers/krb5/krb5_auth.c: krb5_auth_done: 1093 (Tue Feb 19 19:04:53 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' (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [set_server_common_status] (0x0100): Marking server 'va-prod-ipa01.ipa.splat.acme.com' as 'working' (Tue Feb 19 19:04:53 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' (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_mod_ccname] (0x4000): Save ccname [KEYRING:persistent:612329111] for user [myu...@splat.acme.com]. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): start ldb transaction (nesting: 0) (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7fadf255a9e0 (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7fadf255aaa0 (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Running timer event 0x7fadf255a9e0 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Destroying timer event 0x7fadf255aaa0 "ltdb_timeout" (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): Ending timer event 0x7fadf255a9e0 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [sysdb_set_entry_attr] (0x0200): Entry [name=myu...@splat.acme.com,cn=users,cn=splat.acme.com,cn=sysdb] has set [ts_cache] attrs. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [ldb] (0x4000): commit ldb transaction (nesting: 0) (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_cache_creds] (0x0080): Delayed authentication is only available for password authentication (single factor). (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [check_wait_queue] (0x1000): Wait queue for user [myu...@splat.acme.com] is empty. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [krb5_auth_queue_done] (0x1000): krb5_auth_queue request [0x7fadf254e780] done. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_done] (0x0400): DP Request [PAM Preauth #78]: Request handler finished [0]: Success (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [_dp_req_recv] (0x0400): DP Request [PAM Preauth #78]: Receiving request data. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): DP Request [PAM Preauth #78]: Request removed. (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [dp_req_destructor] (0x0400): Number of active DP request: 0 (Tue Feb 19 19:04:53 2019) [sssd[be[ipa.splat.acme.com]]] [dp_pam_reply] (0x1000): DP Request [PAM Preauth #78]: Sending result [4][splat.acme.com] ==> /var/log/sssd/sssd_pam.log <== (Tue Feb 19 19:04:53 2019) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x7f2ccb506110 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 0x7f2ccb5026e0 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching. (Tue Feb 19 19:04:53 2019) [sssd[pam]] [pam_dp_process_reply] (0x0200): received: [4 (System error)][splat.acme.com] (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2ccb525510 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2ccb503700 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7f2ccb503700 "ltdb_timeout" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [pam_reply] (0x0200): pam_reply called with result [4]: System error. (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2ccb525510 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2ccb514620 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7f2ccb514620 "ltdb_timeout" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x7f2ccb525510 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x7f2ccb503700 (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Running timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Destroying timer event 0x7f2ccb503700 "ltdb_timeout" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [ldb] (0x4000): Ending timer event 0x7f2ccb525510 "ltdb_callback" (Tue Feb 19 19:04:53 2019) [sssd[pam]] [filter_responses] (0x0100): [pam_response_filter] not available, not fatal. (Tue Feb 19 19:04:53 2019) [sssd[pam]] [pam_reply] (0x0200): blen: 37 ^C
_______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-le...@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.fedorahosted.org
