On (10/06/16 12:07), Sumit Bose wrote: >On Fri, Jun 10, 2016 at 11:09:49AM +0200, Lukas Slebodnik wrote: >> On (10/06/16 09:54), Sumit Bose wrote: >> >On Fri, Jun 10, 2016 at 09:26:38AM +0200, Lukas Slebodnik wrote: >> >> ehlo, >> >> >> >> I took some time to find out why pam-srv-tests fails so often. >> >> https://fedorahosted.org/sssd/ticket/2994 >> >> >> >> It is caused by slow execution of function sysdb_cache_password_ex. >> >> >> >> (Thu Jun 9 22:13:36:771048 2016) [sssd] [sysdb_cache_password_ex] >> >> (0x0100): start. >> >> (Thu Jun 9 22:13:36:771317 2016) [sssd] [sysdb_cache_password_ex] >> >> (0x0100): Before s3crypt_gen_salt >> >> (Thu Jun 9 22:13:36:771678 2016) [sssd] [sysdb_cache_password_ex] >> >> (0x0100): Before s3crypt_sha512 >> >> (Thu Jun 9 22:13:38:022470 2016) [sssd] [sysdb_cache_password_ex] >> >> (0x0100): Before sysdb_new_attrs >> >> (Thu Jun 9 22:13:38:023115 2016) [sssd] [sysdb_cache_password_ex] >> >> (0x0100): Before sysdb_attrs_add_string >> >> (Thu Jun 9 22:13:38:023431 2016) [sssd] [sysdb_cache_password_ex] >> >> (0x0100): Before sysdb_attrs_add_long >> >> (Thu Jun 9 22:13:38:023829 2016) [sssd] [sysdb_cache_password_ex] >> >> (0x0100): Before sysdb_attrs_add_long v2 >> >> (Thu Jun 9 22:13:38:024156 2016) [sssd] [sysdb_cache_password_ex] >> >> (0x0100): Before sysdb_attrs_add_long v3 >> >> (Thu Jun 9 22:13:38:024482 2016) [sssd] [sysdb_cache_password_ex] >> >> (0x0100): Before sysdb_attrs_add_uint32 >> >> (Thu Jun 9 22:13:38:024816 2016) [sssd] [sysdb_cache_password_ex] >> >> (0x0100): Before sysdb_set_user_attr >> >> (Thu Jun 9 22:13:38:035319 2016) [sssd] [sysdb_cache_password_ex] >> >> (0x0100): return eok >> >> >> >> As you can see, the execution of function s3crypt_sha512 >> >> took almost two seconds. >> >> >> >> Is it caused by valgrind all low entropy? >> > >> >The random data for the salt is already collected in s3crypt_gen_salt(). >> >sha512_crypt_r() basically mingles and password and the salt and does >> >hash operations. >> > >> >From a short inspection I can see nothing obvious which might cause such >> >delay. Maybe nspr_nss_init() if we really have to init NSS at this >> >point. The main operations in sha512_crypt_r() are heavily CPU bound, so >> >maybe some scheduler decides that its time for a different process to get >> >some CPU time? >> > >> >On the other hand can you give some details why the test fails because >> >of this delay? It looks a bit like we depend on a specific execution >> >time either in the test or the main code. If this is the case I think we >> >would make the code more robust by removing this dependency. >> > >> >> There are two possitive tests for pam authentication. >> test_pam_cached_auth_success and >> test_pam_cached_auth_success_combined_pw_with_cached_2fa >> >> The test case is: >> * simulate authenticate in pam responder -> common_test_pam_cached_auth >> * back-end should be contacted >> * store cached password (here is slow function sysdb_cache_password_ex) >> // we need to explicitely cache password because it is usually done in >> // back-end >> * simulate authenticate in pam responder -> common_test_pam_cached_auth >> * back-end should *NOT* be contacted >> >> However, the value of cached_auth_timeout is set to 2 seconds in tests. >> and therefore back-end is sometimes contected in second authentication. >> >> I tried to increase value of cached_auth_timeout 2 -> 4. >> It helped a little bit but after this change >> I can still see failures in pam-srv-tests but in differetn tests :-) >> >> [ FAILED ] test_pam_preauth_cert_nomatch >> [ FAILED ] test_pam_preauth_cert_match >> [ FAILED ] test_pam_preauth_cert_match_wrong_user >> [ FAILED ] test_pam_preauth_cert_no_logon_name >> >> and it does not make sense to me >> because it failes due to slow p11_child (30 seconds shoudl be enough >> for p11_child) > >yes, 30s should be enough. Even in the cases where p11_child returns >without a timeout it needs at least 10s to run trough an area of code >where among other things NSS is initialized. Does the error only happen >on RHEL6 or on other CI platforms as well? > hmm, I cannot reproduce anymore.
Attached is a patch which increases a cached_auth_timeout. As Sumit already wrote: sha512_crypt_r() are heavily CPU bound So it might happen that it will slow with valgrind. I used just essential test-suit because I was interested only in valgrind test which caused problems. http://sssd-ci.duckdns.org/logs-test/job/0/88/summary.html http://sssd-ci.duckdns.org/logs-test/job/0/89/summary.html http://sssd-ci.duckdns.org/logs-test/job/0/90/summary.html http://sssd-ci.duckdns.org/logs-test/job/0/91/summary.html http://sssd-ci.duckdns.org/logs-test/job/0/92/summary.html http://sssd-ci.duckdns.org/logs-test/job/0/93/summary.html http://sssd-ci.duckdns.org/logs-test/job/0/94/summary.html http://sssd-ci.duckdns.org/logs-test/job/0/95/summary.html http://sssd-ci.duckdns.org/logs-test/job/0/96/summary.html http://sssd-ci.duckdns.org/logs-test/job/0/97/summary.html LS
>From 7db9205d20244e810e4b497a7604696d956f790f Mon Sep 17 00:00:00 2001 From: Lukas Slebodnik <[email protected]> Date: Fri, 10 Jun 2016 09:28:37 +0200 Subject: [PATCH] pam-srv-tests: Increase cached_auth_timeout The execution sysdb_cache_password_ex can be slow due to function s3crypt_sha512 and valgrind slowdown. Therefore 2 seconds timeout can be reached in possitive tests test_pam_cached_auth_success and test_pam_cached_auth_success_combined_pw_with_cached_2fa Resolves: https://fedorahosted.org/sssd/ticket/2994 --- src/tests/cmocka/test_pam_srv.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/tests/cmocka/test_pam_srv.c b/src/tests/cmocka/test_pam_srv.c index 2d4677e340b72c11aeb3ea93af01499010c6436a..85127704ffd90f149fa1c1d7ae4ba101fb2779cc 100644 --- a/src/tests/cmocka/test_pam_srv.c +++ b/src/tests/cmocka/test_pam_srv.c @@ -71,8 +71,8 @@ "zotpoBIZmdH+ipYsu58HohHVlM9Wi5H4QmiiXl+Soldkq7eXYlafcmT7wv8+cKwz" \ "Nz0Tm3+eYpFqRo3skr6QzXi525Jkg3r6r+kkhxU=" \ -static char CACHED_AUTH_TIMEOUT_STR[] = "2"; -static const int CACHED_AUTH_TIMEOUT = 2; +static char CACHED_AUTH_TIMEOUT_STR[] = "4"; +static const int CACHED_AUTH_TIMEOUT = 4; struct pam_test_ctx { struct sss_test_ctx *tctx; -- 2.7.4
_______________________________________________ sssd-devel mailing list [email protected] https://lists.fedorahosted.org/admin/lists/[email protected]
