[Freeipa-users] slow login with freeipa 4.2.0

Sat Jul 30 08:32:56 UTC 2016

Thanks Jakub for the detailed analysis... with those inputs , I was able to
nail down the issue.

I had migrated this host from openldap to freeipa.. However, nslcd daemon
was still running and the sylog pointed me to the error "unable to contact
the earlier openldap server" and it spent some time there...

So, I stopped nslcd and now logins have improved drastically to around 5s

date;ssh testuser at localhost
Sat Jul 30 08:09:13 UTC 2016
testuser at localhost's password:
Last login: Sat Jul 30 08:08:55 2016 from 127.0.0.1
[p-rakeshpillai at prod1-admintools-1c :~] date
Sat Jul 30 08:09:18 UTC 2016

For the ipa_hostname entry in sssd.conf, that gets auto populated entered
everytime I run ipa-client-install .

I run the below command to setup ipa client

ipa-client-install --domain=xyz.xom --server=ipa-master-int.xyz.xom
--realm=xyz.xom -p admin --password=mypass--mkhomedir --hostname=10.65.16.4
--no-ssh --no-sshd -N -f -U

Notice that, In the hostname argument, I am passing the IP address. Hope
thats fine, its actually working fine on around 2000+ servers in my
environment.

I had earlier tried with servername.domain ( qa-test1.yyz.com as the
hostname ) and my servers hostname would get changed to  qa-test1.yyz.com .
However, we do our deployments on glassfish and glassfish somehow started
having issue everytime we restart glassfish ( not an expert with glassfish
) so not sure whats wrong there.

With this approach , my hostname is now my ipaddress and  things are
working fine both at galssfish and IPA side.
But just want to confirm its ok to do that

Thanks,
Rakesh

On Fri, Jul 29, 2016 at 5:10 PM, Jakub Hrozek <jhrozek at redhat.com> wrote:

> On Tue, Jul 26, 2016 at 06:07:10PM +0530, Rakesh Rajasekharan wrote:
> > > Any change that it's running on a VM? If so, check your entropy:
> >
> > > cat /proc/sys/kernel/random/entropy_avail
> >
> > > If it's low (like < 1k), install haveged.
> >
> > this indeed is vm , am running it on azure . However, I have a similar
> set
> > up running on aws which works completely fine
>
> Sorry about the delay in replying..
>
> >
> > The entropy was low, around 180, I installed haveged and now its above 3k
> > cat /proc/sys/kernel/random/entropy_avail
> > 3178
> >
> > The timing though is still the same around 19s
>
> I have some comments inline about the config and logs.
>
> >
> > @jakub, i am reattaching the logs.
> >
> > The dns resoltion seems fast when I check using dig
> >
> > below is my sssd.conf
> > [domain/xyz.com]
> > selinux_provider=none
> > krb5_auth_timeout = 20
> > cache_credentials = True
> > krb5_store_password_if_offline = True
> > ipa_domain = xyz.com
> > id_provider = ipa
> > auth_provider = ipa
> > access_provider = ipa
> > ldap_tls_cacert = /etc/ipa/ca.crt
> > ipa_hostname = 10.65.16.4
>
> The ipa_hostname value is wrong. It's meant for systems where hostname
> reports a different name that what is the name the host is registered as
> in IPA. Including an IP address there doesn't make much sense.
>
> > chpass_provider = ipa
> > ipa_server = ipa-master-in.xyz.com
> > dns_discovery_domain = xyz.com
> > ignore_group_members=True
> > ldap_purge_cache_timeout = 0
> > debug_level=8
> > [sssd]
> > services = nss, sudo, pam, ssh
> > config_file_version = 2
> >
> > domains = xyz.com
> > [nss]
> > homedir_substring = /home
> >
> > [pam]
> > pam_id_timeout = 3
> >
> > [sudo]
> >
> > [autofs]
> >
> > [ssh]
> >
> > [pac]
> >
> > [ifp]
> >
> >
> >
> > And here is the login times and logs
> >
> > [root at ipa-client-1 :~] date;ssh testuser at localhost
> > Tue Jul 26 12:06:37 UTC 2016
> > testuser at localhost's password:
> > Last login: Tue Jul 26 12:03:53 2016 from 127.0.0.1
> > [testuser at ipa-client-1 :~] date
> > Tue Jul 26 12:06:55 UTC 2016
> >
> >
> > sssd_domain logs
> >
> > (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> > (0x2000): Received SBUS method
> > org.freedesktop.sssd.dataprovider.getAccountInfo on path
> > /org/freedesktop/sssd/dataprovider
> > (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> > (0x2000): Not a sysbus message, quit
> > (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [be_get_account_info]
> > (0x0200): Got request for [0x3][1][name=testuser]
> > (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> > (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> > (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]]
> > [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
> > domain SID from [(null)]
> > (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]]
> > [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
> > domain SID from [(null)]
> > (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]]
> [sdap_get_initgr_next_base]
> > (0x0400): Searching for users with base [cn=accounts,dc=xyz,dc=com]
>
> --> A request for user's groups arrived.
>
> > (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]] [sdap_print_server]
> > (0x2000): Searching 10.65.16.4
> > (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]]
> [sdap_get_generic_ext_step]
> > (0x0400): calling ldap_search_ext with
> >
> [(&(uid=testuser)(objectclass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))][cn=accounts,dc=xyz,dc=com].
> > (Tue Jul 26 12:06:40 2016) [sssd[be[xyz.com]]]
> [sdap_get_generic_ext_step]
> > (0x1000): Requesting attrs: [objectClass]
>
> [...]
>
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [acctinfo_callback]
> > (0x0100): Request processed. Returned 0,0,Success (Success)
>
> ---> Here the request for user's groups finished. It took about a second
> in total.
>
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> > (0x2000): Received SBUS method
> org.freedesktop.sssd.dataprovider.pamHandler
> > on path /org/freedesktop/sssd/dataprovider
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> > (0x2000): Not a sysbus message, quit
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> > (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler]
> (0x0100):
> > Got request with the following data
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [pam_print_data]
> (0x0100):
> > command: SSS_PAM_PREAUTH
>
> Preauthentication checks for available login methods...
>
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> > (0x0100): Backend returned: (0, 0, <NULL>) [Success (Success)]
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> > (0x0100): Sending result [0][xyz.com]
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> > (0x0100): Sent result [0][xyz.com]
>
> ---> Here the preauth request finished, within a second.
>
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> > (0x2000): Received SBUS method
> org.freedesktop.sssd.dataprovider.pamHandler
> > on path /org/freedesktop/sssd/dataprovider
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> > (0x2000): Not a sysbus message, quit
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> > (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler]
> (0x0100):
> > Got request with the following data
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [pam_print_data]
> (0x0100):
> > command: PAM_AUTHENTICATE
>
> ---> Authentication request is recieved.
>
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [krb5_auth_queue_done]
> > (0x1000): krb5_auth_queue request [0x7f88d1142ab0] done.
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> > (0x0100): Backend returned: (0, 0, <NULL>) [Success (Success)]
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> > (0x0100): Sending result [0][xyz.com]
> > (Tue Jul 26 12:06:41 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> > (0x0100): Sent result [0][xyz.com]
>
> Here the authentication finished successfully, again within a second..
>
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> > (0x2000): Received SBUS method org.freedesktop.sssd.service.ping on path
> > /org/freedesktop/sssd/service
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> > (0x2000): Not a sysbus message, quit
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> > (0x2000): Received SBUS method
> org.freedesktop.sssd.dataprovider.pamHandler
> > on path /org/freedesktop/sssd/dataprovider
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> > (0x2000): Not a sysbus message, quit
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> > (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler]
> (0x0100):
> > Got request with the following data
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [pam_print_data]
> (0x0100):
> > command: PAM_ACCT_MGMT
>
> ---> Access control request is received
>
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [ipa_hbac_evaluate_rules]
> > (0x0080): Access granted by HBAC rule [allow_all]
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> > (0x0100): Backend returned: (0, 0, <NULL>) [Success (Success)]
>
> --> User is granted access, we're within two seconds from the first
> request, still.
>
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> > (0x0400): SELinux provider doesn't exist, not sending the request to it.
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> > (0x0100): Sending result [0][xyz.com]
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler_callback]
> > (0x0100): Sent result [0][xyz.com]
>
> --> The selinux provider is disabled and quits immediately.
>
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [pam_print_data]
> (0x0100):
> > command: PAM_SETCRED
> > (Tue Jul 26 12:06:42 2016) [sssd[be[xyz.com]]] [be_pam_handler]
> (0x0100):
> > Sending result [0][xyz.com]
>
> --> The setred PAM target does nothing, just returns success.
>
> ...And there nothing happens for 10 seconds, at least not in this log.
> Is there any activity in the other SSSD logs in the meantime?
>
> > (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> > (0x2000): Received SBUS method org.freedesktop.sssd.service.ping on path
> > /org/freedesktop/sssd/service
> > (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> > (0x2000): Not a sysbus message, quit
> > (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> > (0x2000): Received SBUS method
> > org.freedesktop.sssd.dataprovider.getAccountInfo on path
> > /org/freedesktop/sssd/dataprovider
> > (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> > (0x2000): Not a sysbus message, quit
> > (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [be_get_account_info]
> > (0x0200): Got request for [0x3][1][name=testuser]
> > (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> > (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> > (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]]
> > [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
> > domain SID from [(null)]
> > (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]]
> > [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse
> > domain SID from [(null)]
> > (Tue Jul 26 12:06:52 2016) [sssd[be[xyz.com]]]
> [sdap_get_initgr_next_base]
> > (0x0400): Searching for users with base [cn=accounts,dc=xyz,dc=com]
>
> ...Until a request for user groups arrives here..
>
> > (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [acctinfo_callback]
> > (0x0100): Request processed. Returned 0,0,Success (Success)
>
> ---> Is processed here.
>
> > (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [sbus_message_handler]
> > (0x2000): Received SBUS method
> org.freedesktop.sssd.dataprovider.pamHandler
> > on path /org/freedesktop/sssd/dataprovider
> > (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [sbus_get_sender_id_send]
> > (0x2000): Not a sysbus message, quit
> > (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [be_req_set_domain]
> > (0x0400): Changing request domain from [xyz.com] to [xyz.com]
> > (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [be_pam_handler]
> (0x0100):
> > Got request with the following data
> > (Tue Jul 26 12:06:53 2016) [sssd[be[xyz.com]]] [pam_print_data]
> (0x0100):
> > command: PAM_OPEN_SESSION
>
> And the session for the user is opened here.
>
> So my conclusion from the logs is that the delay is not within SSSD. The
> next things I would check are:
>     - are there any other NSS modules in nsswitch.conf except sss and
>       files?
>     - is there any other PAM module in the PAM stack except pam_sss.so
>       and pam_unix and those that you would expect after IPA client
>       installation?
>     - is there anything in syslog/journal?
>     - if you increase the SSHD debug level, is there anything of
>       interest in the SSHD log?
>     - if you strace sshd (make sure to strace the child processes also
>       and include the -tt flag to see the timestamps with a high
>       resultion), do you see any delay there?
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20160730/3e65eccf/attachment.htm>