On (12/08/15 17:57), Petr Cech wrote:
> Hi,
>
> I have explored in detail why the test responder_cache_req-tests failed so
> often. I created a new VM with RHEL 6.7.
>
>
> OBSERVATION:
>
> How we know, CI machines are under pressure, so I wrote simple cpu_braker,
> see [1]. I ran the tests 50 times with cpu_braker (average load > 2.60, only
> 1 CPU).
> Results:
>
> [ RUN ] test_users_by_filter_multiple_domains_valid
> 0x2 != 0
> src/tests/cmocka/test_responder_cache_req.c:1875: error: Failure!
>
> [ RUN ] test_users_by_filter_multiple_domains_valid
> 0x1 != 0x2
> src/tests/cmocka/test_responder_cache_req.c:1879: error: Failure!
>
> [ RUN ] test_groups_by_filter_valid
> 0x1 != 0x2
> src/tests/cmocka/test_responder_cache_req.c:1972: error: Failure!
>
> [ RUN ] test_groups_by_filter_multiple_domains_valid
> 0x2 != 0
> src/tests/cmocka/test_responder_cache_req.c:2051: error: Failure!
>
> [ RUN ] test_groups_by_filter_multiple_domains_valid
> 0x1 != 0x2
> src/tests/cmocka/test_responder_cache_req.c:2055: error: Failure!
>
> These errors say they failed to retrieve data from the cache. Tests inserts
> two test values into the cache at the beginning of their run, and then tries
> to pull it back. And sometime if they are under pressure, they fail.
>
> For a more detailed explanation, I added some printf(). I ran the test 25
> times.
> The results:
>
> [ RUN ] test_users_by_filter_valid
> >>> ... sysdb_store_user at [1439384336] (src/db/sysdb_ops.c:1882)
> >>> ... cache_req_input_create at [1439384337]
> (src/responder/common/responder_cache_req.c:122)
> >>> ... recent_filter = [(lastUpdate>=1439384337)]
> (src/responder/common/responder_cache_req.c:44)
> >>> ... sysdb_store_user at [1439384337] (src/db/sysdb_ops.c:1882)
> >>> ... recent_filter = [(lastUpdate>=1439384337)]
> (src/responder/common/responder_cache_req.c:44)
> 0x1 != 0x2
> src/tests/cmocka/test_responder_cache_req.c:1748: error: Failure!
>
> [ RUN ] test_users_by_filter_multiple_domains_valid
> >>> ... sysdb_store_user at [1439384174] (src/db/sysdb_ops.c:1882)
> >>> ... sysdb_store_user at [1439384174] (src/db/sysdb_ops.c:1882)
> >>> ... cache_req_input_create at [1439384175]
> (src/responder/common/responder_cache_req.c:122)
> >>> ... recent_filter = [(lastUpdate>=1439384175)]
> (src/responder/common/responder_cache_req.c:44)
> >>> ... recent_filter = [(lastUpdate>=1439384175)]
> (src/responder/common/responder_cache_req.c:44)
> 0x2 != 0
> src/tests/cmocka/test_responder_cache_req.c:1874: error: Failure!
>
> [ RUN ] test_groups_by_filter_valid
> >>> ... sysdb_store_group at [1439385276] (src/db/sysdb_ops.c:2042)
> >>> ... cache_req_input_create at [1439385277]
> (src/responder/common/responder_cache_req.c:122)
> >>> ... recent_filter = [(lastUpdate>=1439385277)]
> (src/responder/common/responder_cache_req.c:67)
> >>> ... sysdb_store_group at [1439385277] (src/db/sysdb_ops.c:2042)
> >>> ... recent_filter = [(lastUpdate>=1439385277)]
> (src/responder/common/responder_cache_req.c:67)
> 0x1 != 0x2
> src/tests/cmocka/test_responder_cache_req.c:1971: error: Failure!
>
> [ RUN ] test_groups_by_filter_multiple_domains_valid
> >>> ... sysdb_store_group at [1439385286] (src/db/sysdb_ops.c:2042)
> >>> ... sysdb_store_group at [1439385287] (src/db/sysdb_ops.c:2042)
> >>> ... cache_req_input_create at [1439385287]
> (src/responder/common/responder_cache_req.c:122)
> >>> ... recent_filter = [(lastUpdate>=1439385287)]
> (src/responder/common/responder_cache_req.c:67)
> >>> ... recent_filter = [(lastUpdate>=1439385287)]
> (src/responder/common/responder_cache_req.c:67)
> 0x1 != 0x2
> src/tests/cmocka/test_responder_cache_req.c:2054: error: Failure!
>
> As we can see, we have discovered a new failing test
> test_users_by_filter_valid.
>
> REPRODUCER:
>
> Use cpu_braker [1] and observation patch [2] and try some iterations...
> # for i in {1..50} ; do ./responder_cache_req-tests ; done
>
>
> SOLUTION?
>
> The problem is caused by trying to retrieve records from the cache, with the
> time filter set. A time filter we have set by the time of the request
> creation. However, we create the request in our tests after inserting records
> into the cache. Therefore, it may vary the data records time and the time
> filter.
>
> So, solution is create the request and then insert records or create request
> and set:
> # req.req_start = req.req_start - 1.
>
> Please, can you help me? For example see function:
> test_users_by_filter_multiple_domains_valid()
> in src/tests/cmocka/test_responder_cache_req.c:1834
>
> Regards
>
> Petr
>
>
> ATTACHMENTS:
>
> [1] cpu_braker.c
> [2] 0001-TEST-Observation-patch.patch
>From b58608eaadca863b28b0cc80b0588fa536d508b8 Mon Sep 17 00:00:00 2001
> From: Petr Cech <pcech(a)redhat.com>
> Date: Wed, 12 Aug 2015 15:41:03 +0200
> Subject: [PATCH] [TEST]: Observation patch
>
> This patch is part of reproducer, nothing more.
>
> Resolves:
>
https://fedorahosted.org/sssd/ticket/2730
> ---
> src/db/sysdb_ops.c | 6 ++++++
> src/responder/common/responder_cache_req.c | 11 +++++++++++
> 2 files changed, 17 insertions(+), 0 deletions(-)
>
> diff --git a/src/db/sysdb_ops.c b/src/db/sysdb_ops.c
> index
d1d43ebe6c71611f3371b2f4ccf5f7911909c9de..341380c2ed5d30ea1f63b25bdf2a860a1296a979 100644
> --- a/src/db/sysdb_ops.c
> +++ b/src/db/sysdb_ops.c
> @@ -1878,6 +1878,9 @@ int sysdb_store_user(struct sss_domain_info *domain,
> errno_t sret = EOK;
> bool in_transaction = false;
>
> + printf(">>> ... sysdb_store_user at [%lld] (%s:%i)\n",
> + (long long) now, __FILE__, __LINE__);
> +
FYI:
You can use debug macros as well for trouble shooting issues.
Debugging in most of test can be enabled with command line argument
--debug-level=9 becasue test contais macro SSSD_DEBUG_OPTS in
struct poptOption array and dubuggin is initialized with another macro
"DEBUG_CLI_INIT(debug_level);"
I often use a trick to overrride default debug_level and to avoid
using command line arguments.
debug_level = 0xFFF0;
DEBUG_CLI_INIT(debug_level);
HTH
LS
Thanks.
_______________________________________________
sssd-devel mailing list
sssd-devel(a)lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-devel