On Sat, Jul 30, 2016 at 02:02:56PM +0530, Rakesh Rajasekharan wrote: > 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@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 > > > 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 wonder if this works only by accident. Even if you run ipa-client-install --hostname then you'll see in the help this is supposed to be FQDN. Kerberos got less picky about hostnames in the recent releases, but still.. > > 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 <jhro...@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@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[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? > > -- Manage your subscription for the Freeipa-users mailing list: https://www.redhat.com/mailman/listinfo/freeipa-users Go to http://freeipa.org for more info on the project
