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 <pc...@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__);
+
tmp_ctx = talloc_new(NULL);
if (!tmp_ctx) {
return ENOMEM;
@@ -2035,6 +2038,9 @@ int sysdb_store_group(struct sss_domain_info *domain,
uint64_t cache_timeout,
time_t now)
{
+ printf(">>> ... sysdb_store_group at [%lld] (%s:%i)\n",
+ (long long) now, __FILE__, __LINE__);
+
TALLOC_CTX *tmp_ctx;
static const char *src_attrs[] = { SYSDB_NAME, SYSDB_GIDNUM,
SYSDB_ORIG_MODSTAMP, NULL };
diff --git a/src/responder/common/responder_cache_req.c b/src/responder/common/responder_cache_req.c
index d0a90d2c94b7f990a46af488a08dd386854384e0..e7202612590b0f4a525f1b0045f4ff907504b3dd 100644
--- a/src/responder/common/responder_cache_req.c
+++ b/src/responder/common/responder_cache_req.c
@@ -39,6 +39,10 @@ static errno_t updated_users_by_filter(TALLOC_CTX *mem_ctx,
recent_filter = talloc_asprintf(mem_ctx, "(%s>=%lu)",
SYSDB_LAST_UPDATE, since);
+
+ printf(">>> ... recent_filter = [%s] (%s:%i)\n",
+ recent_filter, __FILE__, __LINE__);
+
ret = sysdb_enumpwent_filter_with_views(mem_ctx, domain,
name_filter, recent_filter,
_res);
@@ -58,6 +62,10 @@ static errno_t updated_groups_by_filter(TALLOC_CTX *mem_ctx,
recent_filter = talloc_asprintf(mem_ctx, "(%s>=%lu)",
SYSDB_LAST_UPDATE, since);
+
+ printf(">>> ... recent_filter = [%s] (%s:%i)\n",
+ recent_filter, __FILE__, __LINE__);
+
ret = sysdb_enumgrent_filter_with_views(mem_ctx, domain,
name_filter, recent_filter,
_res);
@@ -110,6 +118,9 @@ cache_req_input_create(TALLOC_CTX *mem_ctx,
input->type = type;
input->req_start = time(NULL);
+ printf(">>> ... cache_req_input_create at [%i] (%s:%i)\n",
+ (long long) input->req_start, __FILE__, __LINE__);
+
/* Check that input parameters match selected type. */
switch (input->type) {
case CACHE_REQ_USER_BY_NAME:
--
1.7.1
/*
* gcc cpu_braker.c -o cpu_braker.x
*/
#include <unistd.h>
int main(int argv, char *argc[]) {
for (int i = 0; ; ++i) {
i++;
if (i / 10000 == 0) {
usleep(100);
}
}
return 0;
}
_______________________________________________
sssd-devel mailing list
sssd-devel@lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
