<div dir="ltr"><div><div><div><div><div><div><div>Thanks Jakub for the detailed analysis... with those inputs , I was able to nail down the issue. </div>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... </div>So, I stopped nslcd and now logins have improved drastically to around 5s date;ssh testuser@localhost Sat Jul 30 08:09:13 UTC 2016 testuser@localhost's password: Last login: Sat Jul 30 08:08:55 2016 from 127.0.0.1 [p-rakeshpillai@prod1-admintools-1c :~] date Sat Jul 30 08:09:18 UTC 2016 </div>For the ipa_hostname entry in sssd.conf, that gets auto populated entered everytime I run ipa-client-install . </div><div>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 </div><div>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. </div> </div>I had earlier tried with servername.domain ( <a href="http://qa-test1.yyz.com">qa-test1.yyz.com</a> as the hostname ) and my servers hostname would get changed to <a href="http://qa-test1.yyz.com">qa-test1.yyz.com</a> . 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. </div>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 </div><div>Thanks, </div><div>Rakesh </div><div> </div> <div><div><div><div><div><div><div><div><div> <div><div> </div></div></div></div></div></div></div></div></div></div></div></div><div class="gmail_extra"> <div class="gmail_quote">On Fri, Jul 29, 2016 at 5:10 PM, Jakub Hrozek <<a href="mailto:jhrozek@redhat.com" target="_blank">jhrozek@redhat.com</a>> wrote: <blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">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/<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] > selinux_provider=none > krb5_auth_timeout = 20 > cache_credentials = True > krb5_store_password_if_offline = True > ipa_domain = <a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a> > 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. <div><div class="h5"> > chpass_provider = ipa > ipa_server = <a href="http://ipa-master-in.xyz.com" rel="noreferrer" target="_blank">ipa-master-in.xyz.com</a> > dns_discovery_domain = <a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a> > ignore_group_members=True > ldap_purge_cache_timeout = 0 > debug_level=8 > [sssd] > services = nss, sudo, pam, ssh > config_file_version = 2 > > domains = <a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a> > [nss] > homedir_substring = /home > > [pam] > pam_id_timeout = 3 > > [sudo] > > [autofs] > > [ssh] > > [pac] > > [ifp] > > > > And here is the login times and logs > > [root@ipa-client-1 :~] date;ssh testuser@localhost > Tue Jul 26 12:06:37 UTC 2016 > testuser@localhost's password: > Last login: Tue Jul 26 12:03:53 2016 from 127.0.0.1 > [testuser@ipa-client-1 :~] date > Tue Jul 26 12:06:55 UTC 2016 > > > sssd_domain logs > > (Tue Jul 26 12:06:40 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [sbus_get_sender_id_send] > (0x2000): Not a sysbus message, quit > (Tue Jul 26 12:06:40 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_get_account_info] > (0x0200): Got request for [0x3][1][name=testuser] > (Tue Jul 26 12:06:40 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_req_set_domain] > (0x0400): Changing request domain from [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] to [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] > (Tue Jul 26 12:06:40 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] > [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse > domain SID from [(null)] > (Tue Jul 26 12:06:40 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] > [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse > domain SID from [(null)] > (Tue Jul 26 12:06:40 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [sdap_get_initgr_next_base] > (0x0400): Searching for users with base [cn=accounts,dc=xyz,dc=com] </div></div>--> A request for user's groups arrived. > (Tue Jul 26 12:06:40 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [sdap_print_server] > (0x2000): Searching 10.65.16.4 > (Tue Jul 26 12:06:40 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [sdap_get_generic_ext_step] > (0x1000): Requesting attrs: [objectClass] [...] > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [sbus_get_sender_id_send] > (0x2000): Not a sysbus message, quit > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_req_set_domain] > (0x0400): Changing request domain from [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] to [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler] (0x0100): > Got request with the following data > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [pam_print_data] (0x0100): > command: SSS_PAM_PREAUTH Preauthentication checks for available login methods... > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler_callback] > (0x0100): Backend returned: (0, 0, <NULL>) [Success (Success)] > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler_callback] > (0x0100): Sending result [0][<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler_callback] > (0x0100): Sent result [0][<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] ---> Here the preauth request finished, within a second. > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [sbus_get_sender_id_send] > (0x2000): Not a sysbus message, quit > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_req_set_domain] > (0x0400): Changing request domain from [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] to [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler] (0x0100): > Got request with the following data > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [pam_print_data] (0x0100): > command: PAM_AUTHENTICATE ---> Authentication request is recieved. > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [krb5_auth_queue_done] > (0x1000): krb5_auth_queue request [0x7f88d1142ab0] done. > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler_callback] > (0x0100): Backend returned: (0, 0, <NULL>) [Success (Success)] > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler_callback] > (0x0100): Sending result [0][<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] > (Tue Jul 26 12:06:41 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler_callback] > (0x0100): Sent result [0][<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] Here the authentication finished successfully, again within a second.. > (Tue Jul 26 12:06:42 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [sbus_get_sender_id_send] > (0x2000): Not a sysbus message, quit > (Tue Jul 26 12:06:42 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [sbus_get_sender_id_send] > (0x2000): Not a sysbus message, quit > (Tue Jul 26 12:06:42 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_req_set_domain] > (0x0400): Changing request domain from [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] to [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] > (Tue Jul 26 12:06:42 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler] (0x0100): > Got request with the following data > (Tue Jul 26 12:06:42 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [pam_print_data] (0x0100): > command: PAM_ACCT_MGMT ---> Access control request is received > (Tue Jul 26 12:06:42 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [ipa_hbac_evaluate_rules] > (0x0080): Access granted by HBAC rule [allow_all] > (Tue Jul 26 12:06:42 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler_callback] > (0x0100): Sending result [0][<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] > (Tue Jul 26 12:06:42 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler_callback] > (0x0100): Sent result [0][<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] --> The selinux provider is disabled and quits immediately. > (Tue Jul 26 12:06:42 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [pam_print_data] (0x0100): > command: PAM_SETCRED > (Tue Jul 26 12:06:42 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler] (0x0100): > Sending result [0][<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] --> 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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [sbus_get_sender_id_send] > (0x2000): Not a sysbus message, quit > (Tue Jul 26 12:06:52 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [sbus_get_sender_id_send] > (0x2000): Not a sysbus message, quit > (Tue Jul 26 12:06:52 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_get_account_info] > (0x0200): Got request for [0x3][1][name=testuser] > (Tue Jul 26 12:06:52 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_req_set_domain] > (0x0400): Changing request domain from [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] to [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] > (Tue Jul 26 12:06:52 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] > [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse > domain SID from [(null)] > (Tue Jul 26 12:06:52 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] > [sdap_idmap_domain_has_algorithmic_mapping] (0x0080): Could not parse > domain SID from [(null)] > (Tue Jul 26 12:06:52 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [acctinfo_callback] > (0x0100): Request processed. Returned 0,0,Success (Success) ---> Is processed here. > (Tue Jul 26 12:06:53 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [sbus_get_sender_id_send] > (0x2000): Not a sysbus message, quit > (Tue Jul 26 12:06:53 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_req_set_domain] > (0x0400): Changing request domain from [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] to [<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>] > (Tue Jul 26 12:06:53 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [be_pam_handler] (0x0100): > Got request with the following data > (Tue Jul 26 12:06:53 2016) [sssd[be[<a href="http://xyz.com" rel="noreferrer" target="_blank">xyz.com</a>]]] [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? </blockquote></div> </div>