2.9.{2,4} test failure on armhf: responder_cache_req-tests and pam-srv-tests

[Andreas Hasenack]

Hi,

I'm troubleshooting a set of test failures[1][2] in sssd 2.9.2 and
2.9.4. They are only failing in armhf, so the usual culprits are
32bits, slowness of the arch/infrastructure, and now we also have a
time_t change[3] to a 64bit type. I don't know yet which, if any, are
related to the failures.

The current failures are:

[ RUN      ] test_user_by_recent_filter_valid
[  ERROR   ] --- 0x2 != 0x1
[   LINE   ] --- ../src/tests/cmocka/test_responder_cache_req.c:2505:
error: Failure!
[  FAILED  ] test_user_by_recent_filter_valid
[ RUN      ] test_users_by_recent_filter_valid
[       OK ] test_users_by_recent_filter_valid
[ RUN      ] test_group_by_recent_filter_valid
[  ERROR   ] --- 0x2 != 0x1
[   LINE   ] --- ../src/tests/cmocka/test_responder_cache_req.c:2868:
error: Failure!
[  FAILED  ] test_group_by_recent_filter_valid
[ RUN      ] test_groups_by_recent_filter_valid
[       OK ] test_groups_by_recent_filter_valid
[ RUN      ] test_users_by_filter_filter_old
[  ERROR   ] --- 0x2 != 0x1
[   LINE   ] --- ../src/tests/cmocka/test_responder_cache_req.c:2613:
error: Failure!
[  FAILED  ] test_users_by_filter_filter_old

And

[  ERROR   ] --- No entries for symbol sss_dp_get_account_recv.
../src/tests/cmocka/common_mock_resp_dp.c:52: error: Could not get
value to mock function sss_dp_get_account_recv
../src/tests/cmocka/test_pam_srv.c:802: note: Previously returned mock
value was declared here

[  FAILED  ] test_pam_preauth_expired_crl_file
...
[  ERROR   ] --- No entries for symbol sss_dp_get_account_recv.
../src/tests/cmocka/common_mock_resp_dp.c:52: error: Could not get
value to mock function sss_dp_get_account_recv
../src/tests/cmocka/test_pam_srv.c:802: note: Previously returned mock
value was declared here

[  FAILED  ] test_pam_preauth_crl_another_ca_crl_invalid_files
[ RUN      ] test_pam_preauth_crl_invalid_crl_another_ca_files
[  ERROR   ] --- No entries for symbol sss_dp_get_account_recv.
../src/tests/cmocka/common_mock_resp_dp.c:52: error: Could not get
value to mock function sss_dp_get_account_recv
../src/tests/cmocka/test_pam_srv.c:802: note: Previously returned mock
value was declared here

[  FAILED  ] test_pam_preauth_crl_invalid_crl_another_ca_files

At first, I've been trying to understand
test_user_by_recent_filter_valid()[4], and it seems to be the reason
for all 3 failures in that test group.

The failure is that it expects just one user to be returned, but in
the end there are two. The test seems to prepare two users, but in the
end only one should be returned by the filter. I have not yet
understood what is being expected here. What's "recent" in this
context? Is it related to the "one second ago" (time(NULL) -1) in
prepare_user()?



1. https://bugs.launchpad.net/ubuntu/+source/sssd/+bug/2058576
2. https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1068063
3. https://wiki.debian.org/ReleaseGoals/64bit-time
4.
https://github.com/SSSD/sssd/blob/1c2aa825062dcf2da2e886c3211be90c22db175...

[Alexey Tikhonov]

On Thu, Apr 4, 2024 at 6:26 PM Andreas Hasenack <andreas(a)canonical.com&gt; wrote:
>  Hi,
>
>  I'm troubleshooting a set of test failures[1][2] in sssd 2.9.2 and
>  2.9.4. They are only failing in armhf, so the usual culprits are
>  32bits, slowness of the arch/infrastructure, and now we also have a
>  time_t change[3] to a 64bit type. 
+ unaligned mem access, but hardly the case here.

>  I don't know yet which, if any, are
>  related to the failures.
>
>  The current failures are:
>
>  [ RUN      ] test_user_by_recent_filter_valid
>  [  ERROR   ] --- 0x2 != 0x1
>  [   LINE   ] --- ../src/tests/cmocka/test_responder_cache_req.c:2505:
>  error: Failure!
>  [  FAILED  ] test_user_by_recent_filter_valid
>  [ RUN      ] test_users_by_recent_filter_valid
>  [       OK ] test_users_by_recent_filter_valid
>  [ RUN      ] test_group_by_recent_filter_valid
>  [  ERROR   ] --- 0x2 != 0x1
>  [   LINE   ] --- ../src/tests/cmocka/test_responder_cache_req.c:2868:
>  error: Failure!
>  [  FAILED  ] test_group_by_recent_filter_valid
>  [ RUN      ] test_groups_by_recent_filter_valid
>  [       OK ] test_groups_by_recent_filter_valid
>  [ RUN      ] test_users_by_filter_filter_old
>  [  ERROR   ] --- 0x2 != 0x1
>  [   LINE   ] --- ../src/tests/cmocka/test_responder_cache_req.c:2613:
>  error: Failure!
>  [  FAILED  ] test_users_by_filter_filter_old
>
>  And
>
>  [  ERROR   ] --- No entries for symbol sss_dp_get_account_recv.
>  ../src/tests/cmocka/common_mock_resp_dp.c:52: error: Could not get
>  value to mock function sss_dp_get_account_recv
>  ../src/tests/cmocka/test_pam_srv.c:802: note: Previously returned mock
>  value was declared here
>
>  [  FAILED  ] test_pam_preauth_expired_crl_file
>  ...
>  [  ERROR   ] --- No entries for symbol sss_dp_get_account_recv.
>  ../src/tests/cmocka/common_mock_resp_dp.c:52: error: Could not get
>  value to mock function sss_dp_get_account_recv
>  ../src/tests/cmocka/test_pam_srv.c:802: note: Previously returned mock
>  value was declared here
>
>  [  FAILED  ] test_pam_preauth_crl_another_ca_crl_invalid_files
>  [ RUN      ] test_pam_preauth_crl_invalid_crl_another_ca_files
>  [  ERROR   ] --- No entries for symbol sss_dp_get_account_recv.
>  ../src/tests/cmocka/common_mock_resp_dp.c:52: error: Could not get
>  value to mock function sss_dp_get_account_recv
>  ../src/tests/cmocka/test_pam_srv.c:802: note: Previously returned mock
>  value was declared here
>
>  [  FAILED  ] test_pam_preauth_crl_invalid_crl_another_ca_files
>
>  At first, I've been trying to understand
>  test_user_by_recent_filter_valid()[4], and it seems to be the reason
>  for all 3 failures in that test group.
>
>  The failure is that it expects just one user to be returned, but in
>  the end there are two. 
I would print the content of `test_ctx->result` at this point just to
debug / see what's there...

>  The test seems to prepare two users, 
Why?
```
    test_ctx->create_user1 = true;
    test_ctx->create_user2 = false;
```

>  but in the
>  end only one should be returned by the filter. I have not yet
>  understood what is being expected here. What's "recent" in this
>  context? Is it related to the "one second ago" (time(NULL) -1) in
>  prepare_user()?
>
>
>
>  1. https://bugs.launchpad.net/ubuntu/+source/sssd/+bug/2058576
>  2. https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1068063
>  3. https://wiki.debian.org/ReleaseGoals/64bit-time
>  4.
> https://github.com/SSSD/sssd/blob/1c2aa825062dcf2da2e886c3211be90c22db175...
>  --
>  _______________________________________________
>  sssd-devel mailing list -- sssd-devel(a)lists.fedorahosted.org
>  To unsubscribe send an email to sssd-devel-leave(a)lists.fedorahosted.org
>  Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/
>  List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
>  List Archives:
> https://lists.fedorahosted.org/archives/list/[e-mail]...
>  Do not reply to spam, report it: https://pagure.io/fedora-infrastructure/new_issue

[Alexey Tikhonov]

Btw, about a patch
https://code.launchpad.net/~ahasenack/ubuntu/+source/sssd/+git/sssd/+merg...
that I've found browsing links list:

wouldn't it be better to use `SPRItime` (defined in
'util/sss_format.h') instead of replacing `%lu` with `%lld`?

And I think you could upstream this.



On Fri, Apr 5, 2024 at 12:24 PM Alexey Tikhonov <atikhono(a)redhat.com&gt; wrote:
>  On Thu, Apr 4, 2024 at 6:26 PM Andreas Hasenack <andreas(a)canonical.com&gt; wrote:
>  >
>  > Hi,
>  >
>  > I'm troubleshooting a set of test failures[1][2] in sssd 2.9.2 and
>  > 2.9.4. They are only failing in armhf, so the usual culprits are
>  > 32bits, slowness of the arch/infrastructure, and now we also have a
>  > time_t change[3] to a 64bit type.
>
>  + unaligned mem access, but hardly the case here.
>
>  > I don't know yet which, if any, are
>  > related to the failures.
>  >
>  > The current failures are:
>  >
>  > [ RUN      ] test_user_by_recent_filter_valid
>  > [  ERROR   ] --- 0x2 != 0x1
>  > [   LINE   ] --- ../src/tests/cmocka/test_responder_cache_req.c:2505:
>  > error: Failure!
>  > [  FAILED  ] test_user_by_recent_filter_valid
>  > [ RUN      ] test_users_by_recent_filter_valid
>  > [       OK ] test_users_by_recent_filter_valid
>  > [ RUN      ] test_group_by_recent_filter_valid
>  > [  ERROR   ] --- 0x2 != 0x1
>  > [   LINE   ] --- ../src/tests/cmocka/test_responder_cache_req.c:2868:
>  > error: Failure!
>  > [  FAILED  ] test_group_by_recent_filter_valid
>  > [ RUN      ] test_groups_by_recent_filter_valid
>  > [       OK ] test_groups_by_recent_filter_valid
>  > [ RUN      ] test_users_by_filter_filter_old
>  > [  ERROR   ] --- 0x2 != 0x1
>  > [   LINE   ] --- ../src/tests/cmocka/test_responder_cache_req.c:2613:
>  > error: Failure!
>  > [  FAILED  ] test_users_by_filter_filter_old
>  >
>  > And
>  >
>  > [  ERROR   ] --- No entries for symbol sss_dp_get_account_recv.
>  > ../src/tests/cmocka/common_mock_resp_dp.c:52: error: Could not get
>  > value to mock function sss_dp_get_account_recv
>  > ../src/tests/cmocka/test_pam_srv.c:802: note: Previously returned mock
>  > value was declared here
>  >
>  > [  FAILED  ] test_pam_preauth_expired_crl_file
>  > ...
>  > [  ERROR   ] --- No entries for symbol sss_dp_get_account_recv.
>  > ../src/tests/cmocka/common_mock_resp_dp.c:52: error: Could not get
>  > value to mock function sss_dp_get_account_recv
>  > ../src/tests/cmocka/test_pam_srv.c:802: note: Previously returned mock
>  > value was declared here
>  >
>  > [  FAILED  ] test_pam_preauth_crl_another_ca_crl_invalid_files
>  > [ RUN      ] test_pam_preauth_crl_invalid_crl_another_ca_files
>  > [  ERROR   ] --- No entries for symbol sss_dp_get_account_recv.
>  > ../src/tests/cmocka/common_mock_resp_dp.c:52: error: Could not get
>  > value to mock function sss_dp_get_account_recv
>  > ../src/tests/cmocka/test_pam_srv.c:802: note: Previously returned mock
>  > value was declared here
>  >
>  > [  FAILED  ] test_pam_preauth_crl_invalid_crl_another_ca_files
>  >
>  > At first, I've been trying to understand
>  > test_user_by_recent_filter_valid()[4], and it seems to be the reason
>  > for all 3 failures in that test group.
>  >
>  > The failure is that it expects just one user to be returned, but in
>  > the end there are two.
>
>  I would print the content of `test_ctx->result` at this point just to
>  debug / see what's there...
>
>  > The test seems to prepare two users,
>
>  Why?
>  ```
>      test_ctx->create_user1 = true;
>      test_ctx->create_user2 = false;
>  ```
>
>  > but in the
>  > end only one should be returned by the filter. I have not yet
>  > understood what is being expected here. What's "recent" in this
>  > context? Is it related to the "one second ago" (time(NULL) -1) in
>  > prepare_user()?
>  >
>  >
>  >
>  > 1. https://bugs.launchpad.net/ubuntu/+source/sssd/+bug/2058576
>  > 2. https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1068063
>  > 3. https://wiki.debian.org/ReleaseGoals/64bit-time
>  > 4.
> https://github.com/SSSD/sssd/blob/1c2aa825062dcf2da2e886c3211be90c22db175...
>  > --
>  > _______________________________________________
>  > sssd-devel mailing list -- sssd-devel(a)lists.fedorahosted.org
>  > To unsubscribe send an email to sssd-devel-leave(a)lists.fedorahosted.org
>  > Fedora Code of Conduct:
> https://docs.fedoraproject.org/en-US/project/code-of-conduct/
>  > List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
>  > List Archives:
> https://lists.fedorahosted.org/archives/list/[e-mail]...
>  > Do not reply to spam, report it: https://pagure.io/fedora-infrastructure/new_issue

[Andreas Hasenack]

Hi,

On Fri, Apr 5, 2024 at 7:39 AM Alexey Tikhonov <atikhono(a)redhat.com&gt; wrote:
>  Btw, about a patch
>
> https://code.launchpad.net/~ahasenack/ubuntu/+source/sssd/+git/sssd/+merg...
>  that I've found browsing links list: 
Yep, that's mine, after a long troubleshooting session :)

>  wouldn't it be better to use `SPRItime` (defined in
>  'util/sss_format.h') instead of replacing `%lu` with `%lld`? 
Probably, I'll check, thanks for the tip. I need to get this into
ubuntu today, so I may just do something else like #ifdef on
_TIME_BITS=64. armhf takes a long time to build this...

>  And I think you could upstream this. 
Definitely.

[Andreas Hasenack]

Hi,

On Fri, Apr 5, 2024 at 7:24 AM Alexey Tikhonov <atikhono(a)redhat.com&gt; wrote:
>  On Thu, Apr 4, 2024 at 6:26 PM Andreas Hasenack <andreas(a)canonical.com&gt; wrote:
>  >
>  > Hi,
>  > The failure is that it expects just one user to be returned, but in
>  > the end there are two.
>
>  I would print the content of `test_ctx->result` at this point just to
>  debug / see what's there... 
Two users

>  > The test seems to prepare two users,
>
>  Why?
>  ```
>      test_ctx->create_user1 = true;
>      test_ctx->create_user2 = false;
>  ``` 
There is a prepare_user() call right after for user2.

In the end, I had to breakpoint on ldb_search() to catch the search
filter that was related to the "recentness" of the user creation, and
then I saw it was looking for lastUpdate>=0. Turns out this is related
to time_t being 64bits now in this armhf build, after all.