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?
I can try to go deeper and find out which part of function sha512_crypt_r is very slow. But it's faster to write to mailing list rather than wait for results from CI.
LS
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.
bye, Sumit
I can try to go deeper and find out which part of function sha512_crypt_r is very slow. But it's faster to write to mailing list rather than wait for results from CI.
LS _______________________________________________ sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/admin/lists/sssd-devel@lists.fedorahosted.org
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)
http://sssd-ci.duckdns.org/logs-test/job/0/73/rhel6/ci-build-debug/pam-srv-t...
I will try with disabled debuging.
LS
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?
bye, Sumit
http://sssd-ci.duckdns.org/logs-test/job/0/73/rhel6/ci-build-debug/pam-srv-t...
I will try with disabled debuging.
LS _______________________________________________ sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/admin/lists/sssd-devel@lists.fedorahosted.org
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
On Fri, Jun 10, 2016 at 04:42:51PM +0200, Lukas Slebodnik wrote:
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 lslebodn@redhat.com 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(-)
If this patch helped in your testing, then I say we should push it..
On (10/06/16 17:30), Jakub Hrozek wrote:
On Fri, Jun 10, 2016 at 04:42:51PM +0200, Lukas Slebodnik wrote:
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 lslebodn@redhat.com 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(-)
If this patch helped in your testing, then I say we should push it..
master: * 6574e41a8d1c2af293df2f57916628344eaa3560
LS
sssd-devel@lists.fedorahosted.org
-
Jakub Hrozek -
Lukas Slebodnik -
Sumit Bose