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.