"dataExpireTimestamp: 1" is used to indicate that a cached entry is expired and should be refreshed. The sss_cache utility sets this value to expire the selected entries, it will never remove entries.

Please note that the timestamps in /var/lib/sss/db/cache_default.ldb might not be up-to-date, please check /var/lib/sss/db/timestamps_default.ldb as well. The second cache file was introduced to reduce the I/O load because due to internals of libldb used by SSSD to manage the cache, changing a single attribute, e.g. dataExpireTimestamp after refreshing an otherwise unchanged entry would require the whole entry to be written again.

One reason entries are not refreshed might be that SSSD is offline. You can check this with 'sssctl domain-status ...'.

If you have an entry with "dataExpireTimestamp: 1" in the timestamp cache which is not updated if SSSD is online please call

sssctl debug-level 9

and

SSS_NSS_USE_MEMCACHE=NO getent group groupname

The 'SSS_NSS_USE_MEMCACHE=NO' variable will make sure SSSD's memory cache is not used and the request is send to SSSD for processing.

Please attache at least the sssd_nss.log and sssd_default.log which cover the request.

HTH

bye,
Sumit

I am experiencing a similar issue on CentOS7 (sssd-1.16.0-19) where some updates to LDAP server are not showing up on specific clients. I updated a group with a new user and on two of of 300+ of my identically configured sssd C7 clients the change is not taking effect. I actually see the new user in the group when I dump /var/lib/sss/db/cache_default.ldb but not when I run 'getent group' or when I dump /var/lib/sss/mc/group. Restarting sssd or running 'sss_cache -E' does not fix the issue.

One commonality between the two clients showing the problem that I don't see on clients that work is that in /var/lib/sss/mc/group the personal group record of the user affected is located immediately after the affected group record. In other words if you run

  strings -a /var/lib/sss/mc/group | grep -A10

on the affected machines you would see

  affectedgroup
  user1
  user2
  user3
  affecteduser  <- this is actually a group, the users personal group
  affecteduser
  randomgroup
  userX
  userY
  ...

while on working clients you would see something like

  affectedgroup
  user1
  affecteduser
  user2
  user3
  randomgroup
  userX
  userY
  ...

However, stopping sssd, removing /var/lib/sss/mc/group, then starting sssd again did not fix it so it is probably a red herring.

Stopping sssd, removing everything in /var/lib/sss/db, then starting sssd DID fix it so I guess it is a cache problem but I am stumped as to how. And to why 'sss_cache -E' did not fix it then.

On the second client still showing the problem I did the following test. I added another user to the affected group in LDAP. I ran 'sss_cache -E'. Now 'getent group affectedgroup' shows the new user but still does not show the original affected user.

There must be something about the way affected user is stored in the cache for this group that makes the sss services ignore it and sss_cache not clear it. There has to be a corruption only cleared by a true file delete of everything in /var/lib/sss/db with sssd stopped.

BTW, I don't think SSS_NSS_USE_MEMCACHE=NO works on the sssd version in CentOS7. It seems to have no affect.

Also, I might be reading the dump of cache_default.ldb wrong. Looks like the affected user is missing from the memberuid field and ghost field of the record but is present as member which is not used. On working clients the affected user is always there as memberuid or ghost.

Using ldbdel on "name=affectedgroup@default,cn=groups,cn=default,cn=sysdb" on both timestamps_default.ldb and cache_default.ldb followed by a sss_cache -E does work.

Hi,

thank you for the detailed description. But I still have some question which might help me to reproduce the issue.

Which LDAP schema are you using on the LDAP server rfc2307 or rfc2307bis (are group members stored as usernames or DNs of the related user object)?

When looking at the user object in the SSSD disk cache, is there memberOf attribute with the DN of the affected group?

Can you attach the cache file and SSSD debug logs with debug_level=9 especially sssd_nss.log and the domain log?

About 'SSS_NSS_USE_MEMCACHE=NO', how did you check that it has no effect?

bye,
Sumit

Just plain RFC2307.

From the cache dump I did before fixing the problem, the "dn: name=affecteduser@default,..." entry has no memberOf attribute for the affectedgroup. On a dump from a client without the issue it is there. Other users properly showing up do have that attribute

With 'SSS_NSS_USE_MEMCACHE=NO' I would still see the message "Looking up [affectedgroup@default] in cache" in the log so that is why I feel it had no effect.

I think the log files are too revealing to post on a public site. But here are some snippets with names changed to hide them. The first file shows the LDIF dump directly from the LDAP server for the affectedgroup followed by the two relevant records from the sss cache dump

Hi Sumit. Sorry for the delay in following up.

Our group members are stored as plain usernames, so I guess that's rfc2307.

Running "sssctl domain-status default" on an affected host confirms "Online status: Online".

I ran the debug 9 test you requested. The log files contain thousands of lines of output, so redacting all of the private data would be difficult. If there's a way for me to send the full logs to you privately, I'd be willing to do that, but I don't really want to post them publicly. But here are the redacted/obfuscated results that I suspect are most relevant:

Correct results from a non-affected machine, showing all 8 members defined in LDAP:
$ getent group foo
foo:*:1103:gol,ric,kzh,soh,afa,ein,nad,czq

Before the test, /var/lib/sss/db/cache_default.ldb contains this entry:

record 429

dn: name=foo@default,cn=groups,cn=default,cn=sysdb
createTimestamp: 1526384007
gidNumber: 1103
name: foo@default
objectCategory: group
isPosix: TRUE
originalDN: cn=foo,ou=groups,dc=example,dc=com
memberuid: nad@default
originalModifyTimestamp: 20181009112632Z
entryUSN: 20181009112632Z
member: name=ric@default,cn=users,cn=default,cn=sysdb
member: name=czq@default,cn=users,cn=default,cn=sysdb
member: name=kzh@default,cn=users,cn=default,cn=sysdb
member: name=ein@default,cn=users,cn=default,cn=sysdb
member: name=nad@default,cn=users,cn=default,cn=sysdb
ghost: soh@default
ghost: afa@default
ghost: gol@default
nameAlias: foo@default
lastUpdate: 1546966725
dataExpireTimestamp: 1546972125
distinguishedName: name=foo@default,cn=groups,cn=default,cn=sysdb

Note that all 8 members appear, although some of them appear as "member:" attributes, and some as "ghost:". I'm not sure what ghost means in this context. Note also that getent is returning only the last "member" entry and all of the "ghost" entries.

Before the test, /var/lib/sss/db/timestamps_default.ldb contains this entry:

record 30

dn: name=foo@default,cn=groups,cn=default,cn=sysdb
lastUpdate: 1526384007
objectCategory: group
dataExpireTimestamp: 1
distinguishedName: name=foo@default,cn=groups,cn=default,cn=sysdb

So then I ran:

$ sudo sssctl debug-level 9
$ sudo SSS_NSS_USE_MEMCACHE=NO getent group foo
foo:*:1103:nad,soh,afa,gol
$ sudo sssctl debug-level 0

At this point, the entry in cache_default.ldb remains unchanged, but the entry in timestamps_default.ldb has changed to the following:

record 30

dn: name=foo@default,cn=groups,cn=default,cn=sysdb
objectCategory: group
originalModifyTimestamp: 20181009112632Z
entryUSN: 20181009112632Z
lastUpdate: 1546967314
dataExpireTimestamp: 1546972714
distinguishedName: name=foo@default,cn=groups,cn=default,cn=sysdb

Of the log files you mentioned, I don't see much of interest in sssd_default.log that appears to be related to the lookup I performed of the affected group; but here are some interesting lines from sssd_nss.log:

(Tue Jan 8 12:11:14 2019) [sssd[nss]] [nss_getby_name] (0x0400): Input name: foo
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #230978: Setting "Group by name" plugin
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_send] (0x0400): CR #230978: New request 'Group by name'
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_process_input] (0x0400): CR #230978: Parsing input name [foo]
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'foo' matched without domain, user is foo
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_set_name] (0x0400): CR #230978: Setting name [foo]
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #230978: Performing a multi-domain search
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #230978: Search will check the cache and check the data provider
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain default type POSIX is valid
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #230978: Using domain [default]
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #230978: Preparing input data for domain [default] rules
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #230978: Looking up foo@default
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #230978: Checking negative cache for [foo@default]
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/GROUP/default/foo@default]
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #230978: [foo@default] is not present in negative cache
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #230978: Looking up [foo@default] in cache
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [merge_msg_ts_attrs] (0x2000): No such DN in the timestamp cache: name=nad@default,cn=users,cn=default,cn=sysdb
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sysdb_merge_res_ts_attrs] (0x2000): TS cache doesn't contain this DN, skipping
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): No override name available.
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sysdb_add_group_member_overrides] (0x4000): Added [nad@default] to [overridememberUid].
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_search_send] (0x0400): CR #230978: Returning [foo@default] from cache
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_search_ncache_filter] (0x0400): CR #230978: This request type does not support filtering result by negative cache
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_create_and_add_result] (0x0400): CR #230978: Found 1 entries in domain default
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [cache_req_done] (0x0400): CR #230978: Finished: Success
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/default/nad@default]
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain default is Active
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/default/soh@default]
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain default is Active
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/default/afa@default]
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain default is Active
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/default/gol@default]
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain default is Active
(Tue Jan 8 12:11:14 2019) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: success

Note the line regarding user "nad", which as mentioned above was the only user with the "member" attribute that was returned. Is the lack of existing entries for some group members in the timestamp cache, combined with the inconsistent way of listing the group's members in cache_default.ldb somehow interacting in an unexpected way?

If there are specific things you were looking for in either of the log files that I haven't included here, please let me know and I'll try to redact/obfuscate them enough to post here.

Hi there,

I've just commented in https://pagure.io/SSSD/sssd/issue/3869 to say that we're seeing the same problem, and it seems this is the same bug, so I'll bump this one too.

Cheers
Toby

Here is another example that just happened:

[root@hound db]# getent group stroke
stroke:*:1021:judith
[root@hound db]# grep ldap4 /etc/sssd/sssd.conf
ldap_uri = ldap://ldap4.mydomain.org, ldap://ldap5.mydomain.org
[root@hound db]# ldapsearch -h ldap4 -x -b 'ou=Group,dc=mydomain,dc=org' "(cn=st
roke)" | grep memberUid
memberUid: judith
memberUid: marco
memberUid: bgh12
[root@hound db]# sss_cache -G
[root@hound db]# sss_cache -E
[root@hound db]# getent group stroke
stroke:*:1021:judith
[root@hound db]# systemctl stop sssd
[root@hound db]# \rm cache_default.ldb timestamps_default.ldb
[root@hound db]# systemctl start sssd
[root@hound db]# getent group stroke
stroke:*:1021:judith,marco,bgh12
[root@hound db]# rpm -q sssd
sssd-1.16.2-13.el7_6.8.x86_64

SSSD is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in SSSD's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/SSSD/sssd/issues/4872

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.