On 1.8.2016 09:08, Jakub Hrozek wrote: > 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
Hostname == IP address will break Kerberos authentication in cases where client wants to connect using DNS name instead of IP address. E.g. it will break "ssh user@server" where server is the machine you installed using the command above. Petr^2 Spacek >> >> 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? >>> > -- Petr^2 Spacek -- 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
