On (22/08/17 10:23), Lukas Slebodnik wrote:
>On (22/08/17 14:48), Lachlan Musicman wrote:
>>On 22 August 2017 at 08:33, Lachlan Musicman <datakid(a)gmail.com> wrote:
>>
>>> On 22 August 2017 at 00:46, Jakub Hrozek <jhrozek(a)redhat.com> wrote:
>>>
>>>> On Mon, Aug 21, 2017 at 10:24:50AM +1000, Lachlan Musicman wrote:
>>>> > On 18 August 2017 at 17:33, Jakub Hrozek <jhrozek(a)redhat.com>
wrote:
>>>> >
>>>> > Hmmm. Weird. We are still seeing the "AD group not reflected in
cache"
>>>> > problem and am not seeing evidence of SSSD updating from the IPA
server
>>>> on
>>>> > request (via login from other machine, via id command).
>>>>
>>>
>>
>>Just to follow up on this, I've done a comparative test.
>>
>>On a machine in which <user> comes up correctly (all groups, properly
>>over-written by ipa's idview) and one in which the same <user> does
not.
>>Note that both machines are on the same network, run the same OS and SSSD
>>versions.
>>
>>When I run the following on both servers:
>>
>>sss_cache -u <user>
>>'id <user>’
>>
>>On the sssd client that returns the correct data, sssd_<domain>.log shows:
>>
>>....
>>(Tue Aug 22 13:13:17 2017) [sssd[be[sub.domain.com]]]
>>[sss_domain_get_state] (0x1000): Domain
sub.domain.com is Active
>>(Tue Aug 22 13:13:17 2017) [sssd[be[sub.domain.com]]]
>>[sss_domain_get_state] (0x1000): Domain
sub.domain.com is Active
>>(Tue Aug 22 13:13:17 2017) [sssd[be[sub.domain.com]]]
>>[sysdb_set_entry_attr] (0x0200): Entry
>>[name=<user>,cn=users,cn=domain.com,cn=sysdb]
>>has set [ts_cache] attrs.
>>(Tue Aug 22 13:13:17 2017) [sssd[be[sub.domain.com]]] [dp_req_done]
>>(0x0400): DP Request [Account #5760]: Request handler finished [0]: Success
>>(Tue Aug 22 13:13:17 2017) [sssd[be[sub.domain.com]]] [_dp_req_recv]
>>(0x0400): DP Request [Account #5760]: Receiving request data.
>>....
>>
>>
>>On the sssd client which does *not* return the correct data,
>>sssd_<domain>.log shows:
>>
>>....
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]]
>>[sss_domain_get_state] (0x1000): Domain
sub.domain.com is Active
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]]
>>[sss_domain_get_state] (0x1000): Domain
sub.domain.com is Active
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]]
>>[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such
>>object](32)[ldb_wait: No such object (32)]
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]]
>>[sysdb_set_cache_entry_attr] (0x0400): No such entry
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]]
>>[sysdb_set_entry_attr] (0x0080): Cannot set attrs for
>>name=<user>,cn=users,cn=domain.com,cn=sysdb, 2 [No such file or directory]
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]] [sysdb_store_user]
>>(0x0040): Cache update failed: 2
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]] [sysdb_store_user]
>>(0x0400): Error: 2 (No such file or directory)
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]]
>>[ipa_s2n_save_objects] (0x0040): sysdb_store_user failed [2]: No such file
>>or directory
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]]
>>[ipa_s2n_get_user_done] (0x0040): ipa_s2n_save_objects failed.
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]] [dp_req_done]
>>(0x0400): DP Request [Account #400]: Request handler finished [0]: Success
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]] [_dp_req_recv]
>>(0x0400): DP Request [Account #400]: Receiving request data.
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]]
>>[dp_req_reply_list_success] (0x0400): DP Request [Account #400]: Finished.
>>Success.
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]] [dp_req_reply_std]
>>(0x1000): DP Request [Account #400]: Returning [Success]: 0,0,Success
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]]
>>[dp_table_value_destructor] (0x0400): Removing
>>[0:1:0x0001:1::domain.com:name=<user>]
>>from reply table
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]] [dp_req_destructor]
>>(0x0400): DP Request [Account #400]: Request removed.
>>(Tue Aug 22 12:54:25 2017) [sssd[be[sub.domain.com]]] [dp_req_destructor]
>>(0x0400): Number of active DP request: 0
>>....
>>
>>
>>The difference is
>>
>>[sysdb_set_cache_entry_attr] (0x0080): ldb_modify failed: [No such
>>object](32)[ldb_wait: No such object (32)]
>>
>
>It is a bug in processing group hierarchy in sssd.
>
>It would be good if you could provide a minimal reproducer
>because I expect you cannot dump whole directory server for us :-) :-) :-)
>
Another possible solution would be to enable debugging for ldb functions.
So we might see also action and not only result.
curl -O /usr/local/lib64/sss_ldb_debug.so
https://lslebodn.fedorapeople.org/sss_ldb_debug/sss_ldb_debug.so ^^
Sorry for typo. It need to be -o
curl -o /usr/local/lib64/sss_ldb_debug.so
echo "LD_PRELOAD=/usr/local/lib64/sss_ldb_debug.so" >>
/etc/sysconfig/sssd
* clear sssd cache and old sssd log files; rm -f /var/lib/sssd/db/* /var/log/sssd/*
* increase debug_level in domain section
* restart sssd
* reproduce problem
An provide sanitized log files. Feel free to send them privately
if you do not want to send them to mailing list.