On Thu, Aug 22, 2019 at 01:11:28PM -0000, Martijn Bakkes via FreeIPA-users wrote:
> On Wed, Aug 21, 2019 at 07:10:50PM -0000, Martijn Bakkes via
FreeIPA-users wrote:
> ...
>
> Hi,
>
> here everything happened in 14:08:28, so there is no visible delay in the
> logs. Did you see a delay on the client for this attempt?
>
> Can you try again and send new logs which "hopefully" show some delay?
>
> bye,
> Sumit
>
> > (Wed Aug 21 14:08:43 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle
timer
> re-set for client [0x559f771f0e20][21]
> > (Wed Aug 21 14:08:58 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle
timer
> re-set for client [0x559f771e45f0][22]
> > (Wed Aug 21 14:09:13 2019) [sssd[nss]] [client_idle_handler] (0x2000):
Terminating
> idle client [0x559f771f0e20][21]
> > (Wed Aug 21 14:09:13 2019) [sssd[nss]] [client_close_fn] (0x2000): Terminated
client
> [0x559f771f0e20][21]
> > (Wed Aug 21 14:09:28 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle
timer
> re-set for client [0x559f771e45f0][22]
> > (Wed Aug 21 14:09:58 2019) [sssd[nss]] [client_idle_handler] (0x2000):
Terminating
> idle client [0x559f771e45f0][22]
> > (Wed Aug 21 14:09:58 2019) [sssd[nss]] [client_close_fn] (0x2000): Terminated
client
> [0x559f771e45f0][22]
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [get_client_cred] (0x4000): Client
creds:
> euid[0] egid[0] pid[18338].
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle
timer
> re-set for client [0x559f771f0e20][21]
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [accept_fd_handler] (0x0400): Client
> connected!
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200):
Received
> client version [1].
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [sss_cmd_get_version] (0x0200): Offered
> version [1].
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name:
root
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR
#27:
> Setting "Initgroups by name" plugin
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #27: New
request
> 'Initgroups by name'
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR
#27:
> Parsing input name [root]
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200):
name
> 'root' matched without domain, user is root
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #27:
Setting
> name [root]
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR
#27:
> Performing a multi-domain search
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR
#27:
> Search will check the cache and check the data provider
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_validate_domain_type]
(0x2000):
> Request type POSIX-only for domain <IPA DOMAIN> type POSIX is valid
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #27:
Using
> domain [<IPA DOMAIN>]
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_prepare_domain_data]
(0x0400): CR
> #27: Preparing input data for domain [<IPA DOMAIN>] rules
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR
#27:
> Looking up root@<IPA DOMAIN>
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR
#27:
> Checking negative cache for [root@<IPA DOMAIN>]
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000):
Checking
> negative cache for [NCE/USER/<IPA DOMAIN>/root@<IPA DOMAIN>]
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR
#27:
> [root@<IPA DOMAIN>] does not exist (negative cache)
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_validate_domain_type]
(0x2000):
> Request type POSIX-only for domain <AD DOMAIN> type POSIX is valid
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [cache_req_process_result] (0x0400): CR
#27:
> Finished: Not found
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain
<AD
> DOMAIN> is Active
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending
reply:
> not found
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [client_recv] (0x0200): Client
disconnected!
> > (Wed Aug 21 14:10:01 2019) [sssd[nss]] [client_close_fn] (0x2000): Terminated
client
> [0x559f771f0e20][21]
> > _______________________________________________
> > FreeIPA-users mailing list --
freeipa-users(a)lists.fedorahosted.org
> > To unsubscribe send an email to
freeipa-users-leave(a)lists.fedorahosted.org
> > Fedora Code of Conduct:
>
https://docs.fedoraproject.org/en-US/project/code-of-conduct/
> > List Guidelines:
https://fedoraproject.org/wiki/Mailing_list_guidelines
> > List Archives:
>
https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedoraho...
So when I'm currently testing the NSS process starts and finishes right away after
entering username at the prompt.
Then it just sits there without a password prompt.
At this time the client will ask the server for the user data ...
Meanwhile on the server:
(Thu Aug 22 09:05:34 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #69: Finished:
Success
(Thu Aug 22 09:05:34 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply:
success
... but this seems to be fast this time.
(Thu Aug 22 09:06:04 2019) [sssd[nss]] [setup_client_idle_timer]
(0x4000): Idle timer re-set for client [0x5628cf451730][21]
(Thu Aug 22 09:06:34 2019) [sssd[nss]] [setup_client_idle_timer] (0x4000): Idle timer
re-set for client [0x5628cf451730][21]
(Thu Aug 22 09:07:04 2019) [sssd[nss]] [client_idle_handler] (0x2000): Terminating idle
client [0x5628cf451730][21]
(Thu Aug 22 09:07:04 2019) [sssd[nss]] [client_close_fn] (0x2000): Terminated client
[0x5628cf451730][21]
Sometimes the network connection gets reset, and you get an idle timeout like above.
Sometimes the password prompt appears in time for me to enter a password, in which case
/var/log/secure shows:
6 (Permission denied)
The slowness before the password prompt appearing happens only when using an AD account,
but it happens on the server as well. However, on the server once the passw prompt appears
you're able to successfully login with AD credentials...
Additionally SSSD tries to figure out which authentication methods are
available for the user trying to log in (password, 2FA, Smartcard). For
this the client will try to connect to the IPA server or the AD DCs for
AD users directly (as long as you do not have a KDC proxy configured).
Maybe this is causing the delay here. To identify this the SSSD domain
logs and the krb5_child.log from the IPA client are needed.
bye,
Sumit
> _______________________________________________
> FreeIPA-users mailing list -- freeipa-users(a)lists.fedorahosted.org
> To unsubscribe send an email to freeipa-users-leave(a)lists.fedorahosted.org
> Fedora Code of Conduct:
https://docs.fedoraproject.org/en-US/project/code-of-conduct/
> List Guidelines:
https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives:
https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedoraho...