Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
Am 08.04.2015 um 10:27 schrieb Jakub Hrozek: Can you run: KRB5_TRACE=/dev/stderr kinit yourprinc@YOUR.REALM So that we can compare with the krb5_child.log you sent earlier? I wonder if SSSD talks to a KDC that is slower or far away from your client.. This is my trace from kinit: [2422] 1428482081.62208: AS key obtained for encrypted timestamp: aes256-cts/61D1 [2422] 1428482081.62288: Encrypted timestamp (for 1428482081.868994): plain ***, encrypted *** [2422] 1428482081.62328: Preauth module encrypted_timestamp (2) (real) returned: 0/Success [2422] 1428482081.62342: Produced preauth for next request: 133, 2 [2422] 1428482081.62379: Sending request (265 bytes) to MITTELERDE.DE [2422] 1428482081.62484: Sending initial UDP request to dgram 1.2.3.4:88 [2422] 1428482081.201814: Received answer (740 bytes) from dgram 1.2.3.4:88 [2422] 1428482081.201872: Response was from master KDC [2422] 1428482081.201905: Processing preauth types: 19 [2422] 1428482081.201914: Selected etype info: etype aes256-cts, salt ***, params [2422] 1428482081.201920: Produced preauth for next request: (empty) [2422] 1428482081.201929: AS key determined by preauth: aes256-cts/61D1 [2422] 1428482081.201973: Decrypted AS reply; session key is: aes256-cts/C464 [2422] 1428482081.201991: FAST negotiation: available [2422] 1428482081.202014: Initializing KEYRING:persistent:0:0 with default princ fr...@mittelerde.de [2422] 1428482081.202058: Removing fr...@mittelerde.de - krbtgt/mittelerde...@mittelerde.de from KEYRING:persistent:0:0 [2422] 1428482081.202065: Storing fr...@mittelerde.de - krbtgt/mittelerde...@mittelerde.de in KEYRING:persistent:0:0 [2422] 1428482081.202110: Storing config in KEYRING:persistent:0:0 for krbtgt/mittelerde...@mittelerde.de: fast_avail: yes [2422] 1428482081.202126: Removing fr...@mittelerde.de - krb5_ccache_conf_data/fast_avail/krbtgt\/MITTELERDE.DE\@MITTELERDE.DE@X-CACHECONF: from KEYRING:persistent:0:0 [2422] 1428482081.202133: Storing fr...@mittelerde.de - krb5_ccache_conf_data/fast_avail/krbtgt\/MITTELERDE.DE\@MITTELERDE.DE@X-CACHECONF: in KEYRING:persistent:0:0 [2422] 1428482081.202166: Storing config in KEYRING:persistent:0:0 for krbtgt/mittelerde...@mittelerde.de: pa_type: 2 [2422] 1428482081.202177: Removing fr...@mittelerde.de - krb5_ccache_conf_data/pa_type/krbtgt\/MITTELERDE.DE\@MITTELERDE.DE@X-CACHECONF: from KEYRING:persistent:0:0 [2422] 1428482081.202184: Storing fr...@mittelerde.de - krb5_ccache_conf_data/pa_type/krbtgt\/MITTELERDE.DE\@MITTELERDE.DE@X-CACHECONF: in KEYRING:persistent:0:0 Most of the host can only communicate in the local net, which has not that much hosts (10). The wired ones are connected via GBit Network, wireless it is up to 150MBit. Server is a Xeon E3-1225 with 8GB Mem. All Systems have Fedora 21 installed Martin. -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
On Wed, Apr 08, 2015 at 10:11:01AM +0200, Martin (Lists) wrote: Am 07.04.2015 um 18:27 schrieb Simo Sorce: On Tue, 2015-04-07 at 17:57 +0200, Martin (Lists) wrote: Hallo attached you can find the data from krb_child.log. As far as I can see it, the three seconds are due to the communication with the kerberos server. (1.2.3.4 is my server). Do you experience the same latency if you kinit manually ? Simo. No, kinit completes almost instantly after entering the password. Martin Can you run: KRB5_TRACE=/dev/stderr kinit yourprinc@YOUR.REALM So that we can compare with the krb5_child.log you sent earlier? I wonder if SSSD talks to a KDC that is slower or far away from your client.. -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
Am 08.04.2015 um 10:57 schrieb Jakub Hrozek: Most of the host can only communicate in the local net, which has not that much hosts (10). The wired ones are connected via GBit Network, wireless it is up to 150MBit. Server is a Xeon E3-1225 with 8GB Mem. All Systems have Fedora 21 installed Does it communicate with the same KDC as krb5_child? Yep, same host, same port number. Currently I have only one IPA server running. Replication is on my todo list though. Martin -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
On Wed, Apr 08, 2015 at 10:43:10AM +0200, Martin (Lists) wrote: Am 08.04.2015 um 10:27 schrieb Jakub Hrozek: Can you run: KRB5_TRACE=/dev/stderr kinit yourprinc@YOUR.REALM So that we can compare with the krb5_child.log you sent earlier? I wonder if SSSD talks to a KDC that is slower or far away from your client.. This is my trace from kinit: [2422] 1428482081.62208: AS key obtained for encrypted timestamp: aes256-cts/61D1 [2422] 1428482081.62288: Encrypted timestamp (for 1428482081.868994): plain ***, encrypted *** [2422] 1428482081.62328: Preauth module encrypted_timestamp (2) (real) returned: 0/Success [2422] 1428482081.62342: Produced preauth for next request: 133, 2 [2422] 1428482081.62379: Sending request (265 bytes) to MITTELERDE.DE [2422] 1428482081.62484: Sending initial UDP request to dgram 1.2.3.4:88 [2422] 1428482081.201814: Received answer (740 bytes) from dgram 1.2.3.4:88 [2422] 1428482081.201872: Response was from master KDC [2422] 1428482081.201905: Processing preauth types: 19 [2422] 1428482081.201914: Selected etype info: etype aes256-cts, salt ***, params [2422] 1428482081.201920: Produced preauth for next request: (empty) [2422] 1428482081.201929: AS key determined by preauth: aes256-cts/61D1 [2422] 1428482081.201973: Decrypted AS reply; session key is: aes256-cts/C464 [2422] 1428482081.201991: FAST negotiation: available [2422] 1428482081.202014: Initializing KEYRING:persistent:0:0 with default princ fr...@mittelerde.de [2422] 1428482081.202058: Removing fr...@mittelerde.de - krbtgt/mittelerde...@mittelerde.de from KEYRING:persistent:0:0 [2422] 1428482081.202065: Storing fr...@mittelerde.de - krbtgt/mittelerde...@mittelerde.de in KEYRING:persistent:0:0 [2422] 1428482081.202110: Storing config in KEYRING:persistent:0:0 for krbtgt/mittelerde...@mittelerde.de: fast_avail: yes [2422] 1428482081.202126: Removing fr...@mittelerde.de - krb5_ccache_conf_data/fast_avail/krbtgt\/MITTELERDE.DE\@MITTELERDE.DE@X-CACHECONF: from KEYRING:persistent:0:0 [2422] 1428482081.202133: Storing fr...@mittelerde.de - krb5_ccache_conf_data/fast_avail/krbtgt\/MITTELERDE.DE\@MITTELERDE.DE@X-CACHECONF: in KEYRING:persistent:0:0 [2422] 1428482081.202166: Storing config in KEYRING:persistent:0:0 for krbtgt/mittelerde...@mittelerde.de: pa_type: 2 [2422] 1428482081.202177: Removing fr...@mittelerde.de - krb5_ccache_conf_data/pa_type/krbtgt\/MITTELERDE.DE\@MITTELERDE.DE@X-CACHECONF: from KEYRING:persistent:0:0 [2422] 1428482081.202184: Storing fr...@mittelerde.de - krb5_ccache_conf_data/pa_type/krbtgt\/MITTELERDE.DE\@MITTELERDE.DE@X-CACHECONF: in KEYRING:persistent:0:0 Most of the host can only communicate in the local net, which has not that much hosts (10). The wired ones are connected via GBit Network, wireless it is up to 150MBit. Server is a Xeon E3-1225 with 8GB Mem. All Systems have Fedora 21 installed Does it communicate with the same KDC as krb5_child? -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
Am 07.04.2015 um 18:27 schrieb Simo Sorce: On Tue, 2015-04-07 at 17:57 +0200, Martin (Lists) wrote: Hallo attached you can find the data from krb_child.log. As far as I can see it, the three seconds are due to the communication with the kerberos server. (1.2.3.4 is my server). Do you experience the same latency if you kinit manually ? Simo. No, kinit completes almost instantly after entering the password. Martin -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
On Mon, Apr 06, 2015 at 08:01:46PM -0500, Dan Mossor wrote: On 04/05/2015 12:51 PM, Dmitri Pal wrote: On 04/05/2015 12:10 AM, Dan Mossor wrote: I've recently deployed a new domain based on 4.1.2 in F21. We've noticed an issue and can't quite seem to nail it down. The problem is that logins are taking an inordinate amount of time to complete - the fastest logon we can get using LDAP credentials is 8 seconds. During our testing, even logons to the IPA server itself took over 30 seconds to complete. I've narrowed this down to sssd, but that is as far as I can get. When cranking up debugging for sshd and PAM, I see a minimum 2 second delay between ssh handing off the authentication request to sssd and the reply back. The only troubleshooting I've done is with ssh, but the area that causes the most grief is Apache logins. We configured Apache to use PAM for auth through IPA, vice directly calling IPA itself. Logging in to our Redmine site takes users a minimum of 34 seconds to complete. Following this, a simple webpage containing two hyperlinks and two small thumbnail images takes over a minute to load on a gigabit network. The *only* thing changed in this environment was the IPA server. We moved the Redmine from our old network that was using IPA 3.x (F20 branch) to the new one. My initial reaction was that it was the VM that was hosting Redmine, but we've run these tests against bare metal machines in the same network and have the same issue. It appears that sssd is taking a very, very long time to talk to FreeIPA - even on the IPA server itself. However, Kerberos logins into the IPA web GUI are near instantaneous, while Username/Password logins take more than a few seconds. I need to get this solved. My developers don't appreciate the glory days of XP taking 5 minutes to log into an IIS 2.1 web server on the local network. I don't have the budget to keep them at the coffee pot waiting on the network. So, what further information do you need from me to track this one down? Dan Several tips. Please check your DNS configuration. Such delay is usually caused by the DNS lookups timing out. That means that the servers probably trying to resolve names against an old DNS server that is not around. Look at resolve.conf and make sure only valid DNS servers are there and they are in the proper order. If this does not help please turn on SSSD debug_level to 10, sanitize and send the SSSD domain logs and sssd.conf to the list. More hints can be found here: https://fedorahosted.org/sssd/wiki/Troubleshooting DNS lookups are good - 'dig' and 'dig -x' return instantaneous forward and reverse lookups on the IPA server, the target server, and the client. The only DNS server configured is the IPA server. I did catch some sssd logs. I set logging to 0x0450 instead of 10, and I didn't have time to compare if any different information was caught. If you still need me to specify log level 10 or some other setting, let me know. The login that these logs are for took 15.371 seconds (checked via 'time ssh danofs...@yoda.example.lcl exit' selinux_child.log: http://fpaste.org/207805/ sssd_sudo.log: http://fpaste.org/207806/ sssd_pac.log: http://fpaste.org/207807/ sssd_pam.log: http://fpaste.org/207808/67775142/ sssd_nss.log: http://fpaste.org/207809/ sssd.log: http://fpaste.org/207810/ sssd_example.lcl.log: http://fpaste.org/207811/36832514/ We've recently found a performance problem in the SELinux code. Can you check if setting: selinux_provider = none improves the performance anyhow? -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
On Tue, Apr 07, 2015 at 11:12:40AM +0200, Martin (Lists) wrote: Am 05.04.2015 um 11:51 schrieb Martin (Lists): Hallo I have a similar issue. On login (graphic systems and ssh) and on the screen saver I have a delay from about 2 secons to 10 seconds. According to my logfile i have the following timeline at login: 0 pam_unix (auth) 3 pam_sss (auth) 3 pam_kwallet (sddm:auth) 4 pam_kwallet (sddm:setcred) 5 pam_unix (session) First collum is the number of seconds after the first action. On myl old server I had a pure kerberos (handmade) system, which reacted almost instandly. Regards Martin Hallo I enabled debugging (set to level 6). selinux provider is set to none. During a login I got data accorting to my attachment. Regards Martin If that's all the data, then the login seems quite fast (3 seconds). The slowdown seems to happen when the krb5 provider is initializing the krb5 ccache for the user. krb5_child.log with a high debug level would show what's happening in particular. (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [be_req_set_domain] (0x0400): Changing request domain from [mittelerde.de] to [mittelerde.de] (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [be_pam_handler] (0x0100): Got request with the following data (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): domain: mittelerde.de (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): user: frodo (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): service: sddm (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): tty: (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): ruser: (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): rhost: (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): authtok type: 1 (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): newauthtok type: 0 (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): priv: 1 (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): cli_pid: 6409 (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): logon name: not set (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [be_resolve_server_process] (0x0200): Found address for server gandalf.mittelerde.de: [10.2.33.5] TTL 1200 (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://gandalf.mittelerde.de' (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [write_pipe_handler] (0x0400): All data has been sent! Here we sent data to krb5_child (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [child_sig_handler] (0x0100): child [6410] finished successfully. Here the krb5_child process finished (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [read_pipe_handler] (0x0400): EOF received, client finished (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'gandalf.mittelerde.de' as 'working' (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [set_server_common_status] (0x0100): Marking server 'gandalf.mittelerde.de' as 'working' (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'gandalf.mittelerde.de' as 'working' (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, NULL) [Success] (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler_callback] (0x0100): Sending result [0][mittelerde.de] (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler_callback] (0x0100): Sent result [0][mittelerde.de] (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_req_set_domain] (0x0400): Changing request domain from [mittelerde.de] to [mittelerde.de] (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler] (0x0100): Got request with the following data (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): domain: mittelerde.de (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): user: frodo (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): service: sddm (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): tty: (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]]
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
Am 05.04.2015 um 11:51 schrieb Martin (Lists): Hallo I have a similar issue. On login (graphic systems and ssh) and on the screen saver I have a delay from about 2 secons to 10 seconds. According to my logfile i have the following timeline at login: 0 pam_unix (auth) 3 pam_sss (auth) 3 pam_kwallet (sddm:auth) 4 pam_kwallet (sddm:setcred) 5 pam_unix (session) First collum is the number of seconds after the first action. On myl old server I had a pure kerberos (handmade) system, which reacted almost instandly. Regards Martin Hallo I enabled debugging (set to level 6). selinux provider is set to none. During a login I got data accorting to my attachment. Regards Martin (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [be_req_set_domain] (0x0400): Changing request domain from [mittelerde.de] to [mittelerde.de] (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [be_pam_handler] (0x0100): Got request with the following data (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): domain: mittelerde.de (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): user: frodo (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): service: sddm (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): tty: (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): ruser: (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): rhost: (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): authtok type: 1 (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): newauthtok type: 0 (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): priv: 1 (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): cli_pid: 6409 (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): logon name: not set (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'IPA' (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [be_resolve_server_process] (0x0200): Found address for server gandalf.mittelerde.de: [10.2.33.5] TTL 1200 (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [ipa_resolve_callback] (0x0400): Constructed uri 'ldap://gandalf.mittelerde.de' (Tue Apr 7 10:52:38 2015) [sssd[be[mittelerde.de]]] [write_pipe_handler] (0x0400): All data has been sent! (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [child_sig_handler] (0x0100): child [6410] finished successfully. (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [read_pipe_handler] (0x0400): EOF received, client finished (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [fo_set_port_status] (0x0100): Marking port 0 of server 'gandalf.mittelerde.de' as 'working' (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [set_server_common_status] (0x0100): Marking server 'gandalf.mittelerde.de' as 'working' (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [fo_set_port_status] (0x0400): Marking port 0 of duplicate server 'gandalf.mittelerde.de' as 'working' (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, NULL) [Success] (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler_callback] (0x0100): Sending result [0][mittelerde.de] (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler_callback] (0x0100): Sent result [0][mittelerde.de] (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_req_set_domain] (0x0400): Changing request domain from [mittelerde.de] to [mittelerde.de] (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [be_pam_handler] (0x0100): Got request with the following data (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): command: PAM_ACCT_MGMT (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): domain: mittelerde.de (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): user: frodo (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): service: sddm (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): tty: (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): ruser: (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): rhost: (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): authtok type: 0 (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): newauthtok type: 0 (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): priv: 1 (Tue Apr 7 10:52:41 2015) [sssd[be[mittelerde.de]]] [pam_print_data] (0x0100): cli_pid: 6409 (Tue Apr 7
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
On Tue, Apr 07, 2015 at 05:57:49PM +0200, Martin (Lists) wrote: Hallo attached you can find the data from krb_child.log. As far as I can see it, the three seconds are due to the communication with the kerberos server. (1.2.3.4 is my server). regards Martin Yes. It looks like kinit takes two seconds and validation one second. You might be interested in: https://fedorahosted.org/sssd/ticket/1807 -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
On Tue, 2015-04-07 at 17:57 +0200, Martin (Lists) wrote: Hallo attached you can find the data from krb_child.log. As far as I can see it, the three seconds are due to the communication with the kerberos server. (1.2.3.4 is my server). Do you experience the same latency if you kinit manually ? Simo. -- Simo Sorce * Red Hat, Inc * New York -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
On 04/07/2015 03:05 AM, Jakub Hrozek wrote: On Mon, Apr 06, 2015 at 08:01:46PM -0500, Dan Mossor wrote: On 04/05/2015 12:51 PM, Dmitri Pal wrote: Several tips. Please check your DNS configuration. Such delay is usually caused by the DNS lookups timing out. That means that the servers probably trying to resolve names against an old DNS server that is not around. Look at resolve.conf and make sure only valid DNS servers are there and they are in the proper order. If this does not help please turn on SSSD debug_level to 10, sanitize and send the SSSD domain logs and sssd.conf to the list. More hints can be found here: https://fedorahosted.org/sssd/wiki/Troubleshooting DNS lookups are good - 'dig' and 'dig -x' return instantaneous forward and reverse lookups on the IPA server, the target server, and the client. The only DNS server configured is the IPA server. I did catch some sssd logs. I set logging to 0x0450 instead of 10, and I didn't have time to compare if any different information was caught. If you still need me to specify log level 10 or some other setting, let me know. The login that these logs are for took 15.371 seconds (checked via 'time ssh danofs...@yoda.example.lcl exit' selinux_child.log: http://fpaste.org/207805/ sssd_sudo.log: http://fpaste.org/207806/ sssd_pac.log: http://fpaste.org/207807/ sssd_pam.log: http://fpaste.org/207808/67775142/ sssd_nss.log: http://fpaste.org/207809/ sssd.log: http://fpaste.org/207810/ sssd_example.lcl.log: http://fpaste.org/207811/36832514/ We've recently found a performance problem in the SELinux code. Can you check if setting: selinux_provider = none improves the performance anyhow? Adding selinux_provider = none to the domain section of /etc/sssd/sssd.conf seems to have drastically improved ssh logins. The Apache authentications are faster, but we're still hitting a performance issue somewhere in that chain. It may be with Apache itself, so stand by...but otherwise, I'm calling this fixed. Thanks! -- Dan Mossor Systems Engineer at Large Fedora KDE WG | Fedora QA Team | Fedora Server SIG Fedora Infrastructure Apprentice FAS: dmossor IRC: danofsatx San Antonio, Texas, USA -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
On Tue, Apr 07, 2015 at 01:15:46PM -0500, Dan Mossor wrote: On 04/07/2015 03:05 AM, Jakub Hrozek wrote: On Mon, Apr 06, 2015 at 08:01:46PM -0500, Dan Mossor wrote: On 04/05/2015 12:51 PM, Dmitri Pal wrote: Several tips. Please check your DNS configuration. Such delay is usually caused by the DNS lookups timing out. That means that the servers probably trying to resolve names against an old DNS server that is not around. Look at resolve.conf and make sure only valid DNS servers are there and they are in the proper order. If this does not help please turn on SSSD debug_level to 10, sanitize and send the SSSD domain logs and sssd.conf to the list. More hints can be found here: https://fedorahosted.org/sssd/wiki/Troubleshooting DNS lookups are good - 'dig' and 'dig -x' return instantaneous forward and reverse lookups on the IPA server, the target server, and the client. The only DNS server configured is the IPA server. I did catch some sssd logs. I set logging to 0x0450 instead of 10, and I didn't have time to compare if any different information was caught. If you still need me to specify log level 10 or some other setting, let me know. The login that these logs are for took 15.371 seconds (checked via 'time ssh danofs...@yoda.example.lcl exit' selinux_child.log: http://fpaste.org/207805/ sssd_sudo.log: http://fpaste.org/207806/ sssd_pac.log: http://fpaste.org/207807/ sssd_pam.log: http://fpaste.org/207808/67775142/ sssd_nss.log: http://fpaste.org/207809/ sssd.log: http://fpaste.org/207810/ sssd_example.lcl.log: http://fpaste.org/207811/36832514/ We've recently found a performance problem in the SELinux code. Can you check if setting: selinux_provider = none improves the performance anyhow? Adding selinux_provider = none to the domain section of /etc/sssd/sssd.conf seems to have drastically improved ssh logins. The Apache authentications are faster, but we're still hitting a performance issue somewhere in that chain. It may be with Apache itself, so stand by...but otherwise, I'm calling this fixed. Not fixed, merely worked around. Thanks! Thank you for confirming the problem and the workaround. I do have a WIP patch, I just need to finish testing it. -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
On 04/05/2015 12:51 PM, Dmitri Pal wrote: On 04/05/2015 12:10 AM, Dan Mossor wrote: I've recently deployed a new domain based on 4.1.2 in F21. We've noticed an issue and can't quite seem to nail it down. The problem is that logins are taking an inordinate amount of time to complete - the fastest logon we can get using LDAP credentials is 8 seconds. During our testing, even logons to the IPA server itself took over 30 seconds to complete. I've narrowed this down to sssd, but that is as far as I can get. When cranking up debugging for sshd and PAM, I see a minimum 2 second delay between ssh handing off the authentication request to sssd and the reply back. The only troubleshooting I've done is with ssh, but the area that causes the most grief is Apache logins. We configured Apache to use PAM for auth through IPA, vice directly calling IPA itself. Logging in to our Redmine site takes users a minimum of 34 seconds to complete. Following this, a simple webpage containing two hyperlinks and two small thumbnail images takes over a minute to load on a gigabit network. The *only* thing changed in this environment was the IPA server. We moved the Redmine from our old network that was using IPA 3.x (F20 branch) to the new one. My initial reaction was that it was the VM that was hosting Redmine, but we've run these tests against bare metal machines in the same network and have the same issue. It appears that sssd is taking a very, very long time to talk to FreeIPA - even on the IPA server itself. However, Kerberos logins into the IPA web GUI are near instantaneous, while Username/Password logins take more than a few seconds. I need to get this solved. My developers don't appreciate the glory days of XP taking 5 minutes to log into an IIS 2.1 web server on the local network. I don't have the budget to keep them at the coffee pot waiting on the network. So, what further information do you need from me to track this one down? Dan Several tips. Please check your DNS configuration. Such delay is usually caused by the DNS lookups timing out. That means that the servers probably trying to resolve names against an old DNS server that is not around. Look at resolve.conf and make sure only valid DNS servers are there and they are in the proper order. If this does not help please turn on SSSD debug_level to 10, sanitize and send the SSSD domain logs and sssd.conf to the list. More hints can be found here: https://fedorahosted.org/sssd/wiki/Troubleshooting DNS lookups are good - 'dig' and 'dig -x' return instantaneous forward and reverse lookups on the IPA server, the target server, and the client. The only DNS server configured is the IPA server. I did catch some sssd logs. I set logging to 0x0450 instead of 10, and I didn't have time to compare if any different information was caught. If you still need me to specify log level 10 or some other setting, let me know. The login that these logs are for took 15.371 seconds (checked via 'time ssh danofs...@yoda.example.lcl exit' selinux_child.log: http://fpaste.org/207805/ sssd_sudo.log: http://fpaste.org/207806/ sssd_pac.log: http://fpaste.org/207807/ sssd_pam.log: http://fpaste.org/207808/67775142/ sssd_nss.log: http://fpaste.org/207809/ sssd.log: http://fpaste.org/207810/ sssd_example.lcl.log: http://fpaste.org/207811/36832514/ -- Dan Mossor Systems Engineer at Large Fedora KDE WG | Fedora QA Team | Fedora Server SIG Fedora Infrastructure Apprentice FAS: dmossor IRC: danofsatx San Antonio, Texas, USA -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
Hi Dan, I had a problem that login time increased by ~ 15 seconds from F20 - F21. That was worked around by adding selinux_provider = none to the domain section in /etc/sssd/sssd.conf Have you checked that dns lookups + reverse lookups work on the ipa server? Is id -G the_user_name and is the user_name_name slow or fast? Did you check https://fedorahosted.org/sssd/wiki/Troubleshooting + -- john 2015-04-05 6:10 GMT+02:00 Dan Mossor danofs...@gmail.com: I've recently deployed a new domain based on 4.1.2 in F21. We've noticed an issue and can't quite seem to nail it down. The problem is that logins are taking an inordinate amount of time to complete - the fastest logon we can get using LDAP credentials is 8 seconds. During our testing, even logons to the IPA server itself took over 30 seconds to complete. I've narrowed this down to sssd, but that is as far as I can get. When cranking up debugging for sshd and PAM, I see a minimum 2 second delay between ssh handing off the authentication request to sssd and the reply back. The only troubleshooting I've done is with ssh, but the area that causes the most grief is Apache logins. We configured Apache to use PAM for auth through IPA, vice directly calling IPA itself. Logging in to our Redmine site takes users a minimum of 34 seconds to complete. Following this, a simple webpage containing two hyperlinks and two small thumbnail images takes over a minute to load on a gigabit network. The *only* thing changed in this environment was the IPA server. We moved the Redmine from our old network that was using IPA 3.x (F20 branch) to the new one. My initial reaction was that it was the VM that was hosting Redmine, but we've run these tests against bare metal machines in the same network and have the same issue. It appears that sssd is taking a very, very long time to talk to FreeIPA - even on the IPA server itself. However, Kerberos logins into the IPA web GUI are near instantaneous, while Username/Password logins take more than a few seconds. I need to get this solved. My developers don't appreciate the glory days of XP taking 5 minutes to log into an IIS 2.1 web server on the local network. I don't have the budget to keep them at the coffee pot waiting on the network. So, what further information do you need from me to track this one down? Dan -- Dan Mossor Systems Engineer at Large Fedora KDE WG | Fedora QA Team | Fedora Server SIG Fedora Infrastructure Apprentice FAS: dmossor IRC: danofsatx San Antonio, Texas, USA -- 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 -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
Am 05.04.2015 um 06:10 schrieb Dan Mossor: I've recently deployed a new domain based on 4.1.2 in F21. We've noticed an issue and can't quite seem to nail it down. The problem is that logins are taking an inordinate amount of time to complete - the fastest logon we can get using LDAP credentials is 8 seconds. During our testing, even logons to the IPA server itself took over 30 seconds to complete. I've narrowed this down to sssd, but that is as far as I can get. When cranking up debugging for sshd and PAM, I see a minimum 2 second delay between ssh handing off the authentication request to sssd and the reply back. The only troubleshooting I've done is with ssh, but the area that causes the most grief is Apache logins. We configured Apache to use PAM for auth through IPA, vice directly calling IPA itself. Logging in to our Redmine site takes users a minimum of 34 seconds to complete. Following this, a simple webpage containing two hyperlinks and two small thumbnail images takes over a minute to load on a gigabit network. The *only* thing changed in this environment was the IPA server. We moved the Redmine from our old network that was using IPA 3.x (F20 branch) to the new one. My initial reaction was that it was the VM that was hosting Redmine, but we've run these tests against bare metal machines in the same network and have the same issue. It appears that sssd is taking a very, very long time to talk to FreeIPA - even on the IPA server itself. However, Kerberos logins into the IPA web GUI are near instantaneous, while Username/Password logins take more than a few seconds. I need to get this solved. My developers don't appreciate the glory days of XP taking 5 minutes to log into an IIS 2.1 web server on the local network. I don't have the budget to keep them at the coffee pot waiting on the network. So, what further information do you need from me to track this one down? Dan Hallo I have a similar issue. On login (graphic systems and ssh) and on the screen saver I have a delay from about 2 secons to 10 seconds. According to my logfile i have the following timeline at login: 0 pam_unix (auth) 3 pam_sss (auth) 3 pam_kwallet (sddm:auth) 4 pam_kwallet (sddm:setcred) 5 pam_unix (session) First collum is the number of seconds after the first action. On myl old server I had a pure kerberos (handmade) system, which reacted almost instandly. Regards Martin -- 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
Re: [Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
On 04/05/2015 12:10 AM, Dan Mossor wrote: I've recently deployed a new domain based on 4.1.2 in F21. We've noticed an issue and can't quite seem to nail it down. The problem is that logins are taking an inordinate amount of time to complete - the fastest logon we can get using LDAP credentials is 8 seconds. During our testing, even logons to the IPA server itself took over 30 seconds to complete. I've narrowed this down to sssd, but that is as far as I can get. When cranking up debugging for sshd and PAM, I see a minimum 2 second delay between ssh handing off the authentication request to sssd and the reply back. The only troubleshooting I've done is with ssh, but the area that causes the most grief is Apache logins. We configured Apache to use PAM for auth through IPA, vice directly calling IPA itself. Logging in to our Redmine site takes users a minimum of 34 seconds to complete. Following this, a simple webpage containing two hyperlinks and two small thumbnail images takes over a minute to load on a gigabit network. The *only* thing changed in this environment was the IPA server. We moved the Redmine from our old network that was using IPA 3.x (F20 branch) to the new one. My initial reaction was that it was the VM that was hosting Redmine, but we've run these tests against bare metal machines in the same network and have the same issue. It appears that sssd is taking a very, very long time to talk to FreeIPA - even on the IPA server itself. However, Kerberos logins into the IPA web GUI are near instantaneous, while Username/Password logins take more than a few seconds. I need to get this solved. My developers don't appreciate the glory days of XP taking 5 minutes to log into an IIS 2.1 web server on the local network. I don't have the budget to keep them at the coffee pot waiting on the network. So, what further information do you need from me to track this one down? Dan Several tips. Please check your DNS configuration. Such delay is usually caused by the DNS lookups timing out. That means that the servers probably trying to resolve names against an old DNS server that is not around. Look at resolve.conf and make sure only valid DNS servers are there and they are in the proper order. If this does not help please turn on SSSD debug_level to 10, sanitize and send the SSSD domain logs and sssd.conf to the list. More hints can be found here: https://fedorahosted.org/sssd/wiki/Troubleshooting -- Thank you, Dmitri Pal Sr. Engineering Manager IdM portfolio Red Hat, Inc. -- 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
[Freeipa-users] Slow logins on FreeIPA 4.1.2 (F21)
I've recently deployed a new domain based on 4.1.2 in F21. We've noticed an issue and can't quite seem to nail it down. The problem is that logins are taking an inordinate amount of time to complete - the fastest logon we can get using LDAP credentials is 8 seconds. During our testing, even logons to the IPA server itself took over 30 seconds to complete. I've narrowed this down to sssd, but that is as far as I can get. When cranking up debugging for sshd and PAM, I see a minimum 2 second delay between ssh handing off the authentication request to sssd and the reply back. The only troubleshooting I've done is with ssh, but the area that causes the most grief is Apache logins. We configured Apache to use PAM for auth through IPA, vice directly calling IPA itself. Logging in to our Redmine site takes users a minimum of 34 seconds to complete. Following this, a simple webpage containing two hyperlinks and two small thumbnail images takes over a minute to load on a gigabit network. The *only* thing changed in this environment was the IPA server. We moved the Redmine from our old network that was using IPA 3.x (F20 branch) to the new one. My initial reaction was that it was the VM that was hosting Redmine, but we've run these tests against bare metal machines in the same network and have the same issue. It appears that sssd is taking a very, very long time to talk to FreeIPA - even on the IPA server itself. However, Kerberos logins into the IPA web GUI are near instantaneous, while Username/Password logins take more than a few seconds. I need to get this solved. My developers don't appreciate the glory days of XP taking 5 minutes to log into an IIS 2.1 web server on the local network. I don't have the budget to keep them at the coffee pot waiting on the network. So, what further information do you need from me to track this one down? Dan -- Dan Mossor Systems Engineer at Large Fedora KDE WG | Fedora QA Team | Fedora Server SIG Fedora Infrastructure Apprentice FAS: dmossor IRC: danofsatx San Antonio, Texas, USA -- 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
