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(a)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..