Cloned from Pagure issue: https://pagure.io/SSSD/sssd/issue/3886

Created at 2018-11-19 22:13:27 by paulds
Assigned to nobody
Associated bugzillas
- https://bugzilla.redhat.com/show_bug.cgi?id=1730377

We are noticing what appears to be widespread silent corruption of (at a minimum) group membership data in the sssd cache, across dozens of machines running CentOS 7, and apparently going back several years.

We make widespread use of posix groups for filesystem access controls. The groups reside in an OpenLDAP server, and clients use sssd for lookups and resolution.

We first noticed this when a user reported not having access to a directory that they should have been able to access based on membership in a supplemental group. During troubleshooting we realized that "getent group [groupname]" was only returning a subset of the group's members on the affected machine. The group resolves as expected on other systems. Playing around with ldbsearch we noted that the affected group entry had "dataExpireTimestamp: 1" in /var/lib/sss/db/cache_default.ldb, which we assume means the data is expired and should be refreshed (or removed) on the next lookup. Running "sss_cache -G" did not cause the entry to be refreshed, nor removed from the cache. The only solution we have found to get the data to refresh was to stop sssd, delete cache_default.ldb, and restart sssd. After this the group resolved correctly again.

During subsequent investigations we have found dozens of systems that have (in some cases hundreds) of cache entries showing "dataExpireTimestamp: 1". It is unclear to us whether this is normal and expected, or if it's an indication of a problem. But spot checks of some of those entries for other posix groups has shown that in almost every case the results are missing group members.

Some of the affected cache entries have createTimestamp fields that go back several years, so it's unclear how long this issue has been going on.

Given the silent nature of the error, this is very concerning. We would also like to understand what is happening here in order to reassure ourselves that other old data is not lingering in local caches and continuing to be returned to system queries, such as user accounts that have been removed from the LDAP server.

Please let us know if there is any additional information or debugging steps that it would be helpful for us to provide.

Comments

Comment from sbose at 2018-11-21 11:15:16

"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

Comment from praines at 2018-11-29 20:28:28

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.

Comment from praines at 2018-11-29 21:12:40

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.

Comment from praines at 2018-11-29 21:23:36

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.

Comment from sbose at 2018-11-30 16:44:18

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

Comment from praines at 2018-11-30 17:23:47

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

Comment from paulds at 2019-01-08 19:10:10

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.

Comment from tobyblake at 2019-05-14 12:12:09

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

Comment from praines at 2019-07-16 16:24:01

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

Comment from atikhonov at 2019-07-18 13:23:31

Metadata Update from @atikhonov:

Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1730377

Comment from pbrezina at 2020-03-13 14:56:50

Metadata Update from @pbrezina:

Issue tagged with: bugzilla

I'm seeing the same issue here, including on 2.3.0, and I can reliably reproduce it as follows:

delete cache, restart SSSD
getent group foo
(a full member list is produced).
id bar # any member in group foo - always returns complete info
sleep $CACHE_TTL
getent group foo (now the list returned does NOT include the user bar)

Below is the (redacted) full debug logs in that corrupt state after "sss_cache -g foo" and "SSS_NSS_USE_MEMCACHE=NO getent group foo"

Let me know if I can provide any further info that will help repro and fix this!

(2020-06-24  6:18:28): [be[company.com.domain1]] [sbus_dispatch] (0x4000): Dispatching.
(2020-06-24  6:18:28): [be[company.com.domain1]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.getAccountInfo on /sssd
(2020-06-24  6:18:28): [be[company.com.domain1]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_get_account_info_send] (0x0200): Got request for [0x2][BE_REQ_GROUP][name=foo@company.com.domain1]
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_attach_req] (0x0400): DP Request [Account #196]: New request. Flags [0x0001].
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_attach_req] (0x0400): Number of active DP request: 1
(2020-06-24  6:18:28): [be[company.com.domain1]] [sss_domain_get_state] (0x1000): Domain company.com.domain1 is Active
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_connect_step] (0x4000): releasing expired cached connection
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_handle_release] (0x2000): Trace: sh[0x562963011f20], connected[0], ops[(nil)], ldap[(nil)], destructor_lock[0], release_memory[0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_connect_step] (0x4000): beginning to connect
(2020-06-24  6:18:28): [be[company.com.domain1]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP'
(2020-06-24  6:18:28): [be[company.com.domain1]] [get_server_status] (0x1000): Status of server 'ldap.company.com' is 'working'
(2020-06-24  6:18:28): [be[company.com.domain1]] [get_server_status] (0x0100): Hostname resolution expired, resetting the server status of 'ldap.company.com'
(2020-06-24  6:18:28): [be[company.com.domain1]] [set_server_common_status] (0x0100): Marking server 'ldap.company.com' as 'name not resolved'
(2020-06-24  6:18:28): [be[company.com.domain1]] [get_port_status] (0x1000): Port status of port 636 for server 'ldap.company.com' is 'working'
(2020-06-24  6:18:28): [be[company.com.domain1]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
(2020-06-24  6:18:28): [be[company.com.domain1]] [get_server_status] (0x1000): Status of server 'ldap.company.com' is 'name not resolved'
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_is_address] (0x4000): [ldap.company.com] does not look like an IP address
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_step] (0x2000): Querying files
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'ldap.company.com' in files
(2020-06-24  6:18:28): [be[company.com.domain1]] [set_server_common_status] (0x0100): Marking server 'ldap.company.com' as 'resolving name'
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_step] (0x2000): Querying files
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'ldap.company.com' in files
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_next] (0x0200): No more address families to retry
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_step] (0x2000): Querying DNS
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'ldap.company.com' in DNS
(2020-06-24  6:18:28): [be[company.com.domain1]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 3 seconds
(2020-06-24  6:18:28): [be[company.com.domain1]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
(2020-06-24  6:18:28): [be[company.com.domain1]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply
(2020-06-24  6:18:28): [be[company.com.domain1]] [request_watch_destructor] (0x0400): Deleting request watch
(2020-06-24  6:18:28): [be[company.com.domain1]] [set_server_common_status] (0x0100): Marking server 'ldap.company.com' as 'name resolved'
(2020-06-24  6:18:28): [be[company.com.domain1]] [be_resolve_server_process] (0x1000): Saving the first resolved server
(2020-06-24  6:18:28): [be[company.com.domain1]] [be_resolve_server_process] (0x0200): Found address for server ldap.company.com: [10.59.17.14] TTL 300
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_uri_callback] (0x0400): Constructed uri 'ldaps://ldap.company.com:636'
(2020-06-24  6:18:28): [be[company.com.domain1]] [sssd_async_socket_init_send] (0x4000): Using file descriptor [23] for the connection.
(2020-06-24  6:18:28): [be[company.com.domain1]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldaps://ldap.company.com:636/??base] with fd [23].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_rootdse_send] (0x4000): Getting rootdse
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_print_server] (0x2000): Searching 10.59.17.14:636
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_add] (0x2000): New operation 1 timeout 6
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x5629630117e0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_entry] (0x1000): OriginalDN: [].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [namingContexts]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedControl]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedFeatures]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedSASLMechanisms]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x5629630117e0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_destructor] (0x2000): Operation 1 finished
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_rootdse_done] (0x2000): Got rootdse
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_server_opts_from_rootdse] (0x0200): No known USN scheme is supported by this server!
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_cli_auth_step] (0x0100): expire timeout is 900
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1592980408
(2020-06-24  6:18:28): [be[company.com.domain1]] [simple_bind_send] (0x0100): Executing simple bind as: uid=root,cn=users,dc=company,dc=com
(2020-06-24  6:18:28): [be[company.com.domain1]] [simple_bind_send] (0x2000): ldap simple bind sent, msgid = 2
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_add] (0x2000): New operation 2 timeout 8
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x5629630110f0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x5629630110f0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_BIND]
(2020-06-24  6:18:28): [be[company.com.domain1]] [simple_bind_done] (0x1000): Server returned no controls.
(2020-06-24  6:18:28): [be[company.com.domain1]] [simple_bind_done] (0x0400): Bind result: Success(0), no errmsg set
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_destructor] (0x2000): Operation 2 finished
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_cli_connect_recv] (0x0400): Connection established.
(2020-06-24  6:18:28): [be[company.com.domain1]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_recv: 2114
(2020-06-24  6:18:28): [be[company.com.domain1]] [fo_set_port_status] (0x0100): Marking port 636 of server 'ldap.company.com' as 'working'
(2020-06-24  6:18:28): [be[company.com.domain1]] [set_server_common_status] (0x0100): Marking server 'ldap.company.com' as 'working'
(2020-06-24  6:18:28): [be[company.com.domain1]] [fo_set_port_status] (0x0400): Marking port 636 of duplicate server 'ldap.company.com' as 'working'
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_connect_done] (0x2000): Old USN: 0, New USN: 0
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_groups_next_base] (0x0400): Searching for groups with base [cn=groups,dc=company,dc=com]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_print_server] (0x2000): Searching 10.59.17.14:636
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=foo)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][cn=groups,dc=company,dc=com].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberuid]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 3
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_add] (0x2000): New operation 3 timeout 6
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies
(2020-06-24  6:18:28): [be[company.com.domain1]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do.
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x562963011de0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x562963011de0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=foo,cn=groups,dc=company,dc=com].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [gidNumber]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [memberUid]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [modifyTimestamp]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x562963011de0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_destructor] (0x2000): Operation 3 finished
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_groups_process] (0x0400): Search for groups, returned 1 results.
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #0 (user1@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user1@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #1 (user2@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user2@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #2 (user3@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user3@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #3 (user4@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user4@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #4 (user5@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user5@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #5 (user6@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user6@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #6 (user7@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user7@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #7 (user8@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user8@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #8 (user8-staging@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user8-staging@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #9 (user10@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user10@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #10 (user11@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user11@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #11 (attribution-service@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=attribution-service@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #12 (macaw-wtf@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=macaw-wtf@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #13 (adshard@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=adshard@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #14 (audiences@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=audiences@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #15 (ads-prediction@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=ads-prediction@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #16 (macawexchange@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=macawexchange@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #17 (user10-testing@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user10-testing@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #18 (ads@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=ads@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #19 (hadoop-exchange-data-service@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=hadoop-exchange-data-service@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #20 (conversionattribution@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=conversionattribution@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #21 (octain-sa@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=octain-sa@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #22 (ads-brand-surveys@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=ads-brand-surveys@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #23 (onboarding-task-service@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=onboarding-task-service@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #24 (user10-staging@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user10-staging@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #25 (ads-attribution@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=ads-attribution@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #26 (mapred@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=mapred@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #27 (gb-gdpr@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=gb-gdpr@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #28 (mholzner@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=mholzner@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_send] (0x1000): All group members processed
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_groups_done] (0x4000): Groups remaining: 0
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_groups_done] (0x4000): All groups processed
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_attrs_get_sid_str] (0x1000): No [objectSID] attribute. [0][Success]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_group] (0x4000): objectSID: not available for group [(null)].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_group] (0x4000): Failed to retrieve UUID [2][No such file or directory].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_primary_name] (0x0400): Processing object foo
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_group] (0x0400): Processing group foo@company.com.domain1
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_group] (0x2000): This is a posix group
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [cn=foo,cn=groups,dc=company,dc=com] to attributes of [id-bridges-anonymization-key@company.com.domain1].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20200522230044Z] to attributes of [foo@company.com.domain1].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_ghost_members] (0x0400): Group has 29 members
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_group] (0x0400): Storing info for group foo@company.com.domain1
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_store_group] (0x1000): The group record of foo@company.com.domain1 did not change, only updated the timestamp cache
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_groups] (0x4000): Group 0 processed!
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_groups_done] (0x4000): Saving 1 Groups - Done
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_done] (0x4000): releasing operation connection
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_req_done] (0x0400): DP Request [Account #196]: Request handler finished [0]: Success
(2020-06-24  6:18:28): [be[company.com.domain1]] [_dp_req_recv] (0x0400): DP Request [Account #196]: Receiving request data.
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_req_destructor] (0x0400): DP Request [Account #196]: Request removed.
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_req_destructor] (0x0400): Number of active DP request: 0
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_req_reply_std] (0x1000): DP Request [Account #196]: Returning [Success]: 0,0,Success
(2020-06-24  6:18:28): [be[company.com.domain1]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.getAccountInfo: Success
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[(nil)], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2020-06-24  6:18:28): [be[company.com.domain1]] [sbus_dispatch] (0x4000): Dispatching.(2020-06-24  6:18:28): [be[company.com.domain1]] [sbus_dispatch] (0x4000): Dispatching.
(2020-06-24  6:18:28): [be[company.com.domain1]] [sbus_dispatch] (0x4000): Dispatching.
(2020-06-24  6:18:28): [be[company.com.domain1]] [sbus_method_handler] (0x2000): Received D-Bus method sssd.dataprovider.getAccountInfo on /sssd
(2020-06-24  6:18:28): [be[company.com.domain1]] [sbus_senders_lookup] (0x2000): Looking for identity of sender [sssd.nss]
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_get_account_info_send] (0x0200): Got request for [0x2][BE_REQ_GROUP][name=foo@company.com.domain1]
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_attach_req] (0x0400): DP Request [Account #196]: New request. Flags [0x0001].
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_attach_req] (0x0400): Number of active DP request: 1
(2020-06-24  6:18:28): [be[company.com.domain1]] [sss_domain_get_state] (0x1000): Domain company.com.domain1 is Active
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_connect_step] (0x4000): releasing expired cached connection
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_handle_release] (0x2000): Trace: sh[0x562963011f20], connected[0], ops[(nil)], ldap[(nil)], destructor_lock[0], release_memory[0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_connect_step] (0x4000): beginning to connect
(2020-06-24  6:18:28): [be[company.com.domain1]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP'
(2020-06-24  6:18:28): [be[company.com.domain1]] [get_server_status] (0x1000): Status of server 'ldap.company.com' is 'working'
(2020-06-24  6:18:28): [be[company.com.domain1]] [get_server_status] (0x0100): Hostname resolution expired, resetting the server status of 'ldap.company.com'
(2020-06-24  6:18:28): [be[company.com.domain1]] [set_server_common_status] (0x0100): Marking server 'ldap.company.com' as 'name not resolved'
(2020-06-24  6:18:28): [be[company.com.domain1]] [get_port_status] (0x1000): Port status of port 636 for server 'ldap.company.com' is 'working'
(2020-06-24  6:18:28): [be[company.com.domain1]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
(2020-06-24  6:18:28): [be[company.com.domain1]] [get_server_status] (0x1000): Status of server 'ldap.company.com' is 'name not resolved'
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_is_address] (0x4000): [ldap.company.com] does not look like an IP address
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_step] (0x2000): Querying files
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record of 'ldap.company.com' in files
(2020-06-24  6:18:28): [be[company.com.domain1]] [set_server_common_status] (0x0100): Marking server 'ldap.company.com' as 'resolving name'
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_step] (0x2000): Querying files
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_files_send] (0x0100): Trying to resolve AAAA record of 'ldap.company.com' in files
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_next] (0x0200): No more address families to retry
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_step] (0x2000): Querying DNS
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_dns_query] (0x0100): Trying to resolve A record of 'ldap.company.com' in DNS
(2020-06-24  6:18:28): [be[company.com.domain1]] [schedule_request_timeout] (0x2000): Scheduling a timeout of 3 seconds
(2020-06-24  6:18:28): [be[company.com.domain1]] [schedule_timeout_watcher] (0x2000): Scheduling DNS timeout watcher
(2020-06-24  6:18:28): [be[company.com.domain1]] [unschedule_timeout_watcher] (0x4000): Unscheduling DNS timeout watcher
(2020-06-24  6:18:28): [be[company.com.domain1]] [resolv_gethostbyname_dns_parse] (0x1000): Parsing an A reply
(2020-06-24  6:18:28): [be[company.com.domain1]] [request_watch_destructor] (0x0400): Deleting request watch
(2020-06-24  6:18:28): [be[company.com.domain1]] [set_server_common_status] (0x0100): Marking server 'ldap.company.com' as 'name resolved'
(2020-06-24  6:18:28): [be[company.com.domain1]] [be_resolve_server_process] (0x1000): Saving the first resolved server
(2020-06-24  6:18:28): [be[company.com.domain1]] [be_resolve_server_process] (0x0200): Found address for server ldap.company.com: [10.59.17.14] TTL 300
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_uri_callback] (0x0400): Constructed uri 'ldaps://ldap.company.com:636'
(2020-06-24  6:18:28): [be[company.com.domain1]] [sssd_async_socket_init_send] (0x4000): Using file descriptor [23] for the connection.
(2020-06-24  6:18:28): [be[company.com.domain1]] [sssd_async_socket_init_send] (0x0400): Setting 6 seconds timeout for connecting
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldaps://ldap.company.com:636/??base] with fd [23].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_rootdse_send] (0x4000): Getting rootdse
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_print_server] (0x2000): Searching 10.59.17.14:636
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_add] (0x2000): New operation 1 timeout 6
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x5629630117e0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_entry] (0x1000): OriginalDN: [].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [namingContexts]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedControl]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedFeatures]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedSASLMechanisms]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x5629630117e0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_destructor] (0x2000): Operation 1 finished
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_rootdse_done] (0x2000): Got rootdse
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_rootdse_done] (0x2000): Skipping auto-detection of match rule
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_server_opts_from_rootdse] (0x0200): No known USN scheme is supported by this server!
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_cli_auth_step] (0x0100): expire timeout is 900
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_cli_auth_step] (0x1000): the connection will expire at 1592980408
(2020-06-24  6:18:28): [be[company.com.domain1]] [simple_bind_send] (0x0100): Executing simple bind as: uid=root,cn=users,dc=company,dc=com
(2020-06-24  6:18:28): [be[company.com.domain1]] [simple_bind_send] (0x2000): ldap simple bind sent, msgid = 2
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_add] (0x2000): New operation 2 timeout 8
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x5629630110f0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x5629630110f0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_BIND]
(2020-06-24  6:18:28): [be[company.com.domain1]] [simple_bind_done] (0x1000): Server returned no controls.
(2020-06-24  6:18:28): [be[company.com.domain1]] [simple_bind_done] (0x0400): Bind result: Success(0), no errmsg set
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_destructor] (0x2000): Operation 2 finished
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_cli_connect_recv] (0x0400): Connection established.
(2020-06-24  6:18:28): [be[company.com.domain1]] [_be_fo_set_port_status] (0x8000): Setting status: PORT_WORKING. Called from: src/providers/ldap/sdap_async_connection.c: sdap_cli_connect_recv: 2114
(2020-06-24  6:18:28): [be[company.com.domain1]] [fo_set_port_status] (0x0100): Marking port 636 of server 'ldap.company.com' as 'working'
(2020-06-24  6:18:28): [be[company.com.domain1]] [set_server_common_status] (0x0100): Marking server 'ldap.company.com' as 'working'
(2020-06-24  6:18:28): [be[company.com.domain1]] [fo_set_port_status] (0x0400): Marking port 636 of duplicate server 'ldap.company.com' as 'working'
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_connect_done] (0x2000): Old USN: 0, New USN: 0
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_connect_done] (0x4000): notify connected to op #1
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_groups_next_base] (0x0400): Searching for groups with base [cn=groups,dc=company,dc=com]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_print_server] (0x2000): Searching 10.59.17.14:636
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(cn=foo)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][cn=groups,dc=company,dc=com].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberuid]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 3
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_add] (0x2000): New operation 3 timeout 6
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_connect_done] (0x4000): caching successful connection after 1 notifies
(2020-06-24  6:18:28): [be[company.com.domain1]] [be_run_unconditional_online_cb] (0x4000): List of unconditional online callbacks is empty, nothing to do.
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x562963011de0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x562963011de0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_entry] (0x1000): OriginalDN: [cn=foo,cn=groups,dc=company,dc=com].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [gidNumber]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [memberUid]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_parse_range] (0x2000): No sub-attributes for [modifyTimestamp]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[0x562963011de0], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_generic_op_finished] (0x0400): Search result: Success(0), no errmsg set
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_op_destructor] (0x2000): Operation 3 finished
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_groups_process] (0x0400): Search for groups, returned 1 results.
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #0 (user1@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user1@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #1 (user2@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user2@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #2 (user3@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user3@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_members_2307] (0x1000): member #3 (user4@company.com.domain1): not found in sysdb
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): Search users with filter: (&(objectCategory=user)(nameAlias=user4@company.com.domain1))
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_cache_search_users] (0x2000): No such entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_missing_member_2307] (0x0400): Adding a ghost entry
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_search_by_name] (0x0400): No such entry

***SNIP - repeats for the rest of the 29 users***

(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_group_send] (0x1000): All group members processed
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_groups_done] (0x4000): Groups remaining: 0
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_groups_done] (0x4000): All groups processed
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_attrs_get_sid_str] (0x1000): No [objectSID] attribute. [0][Success]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_group] (0x4000): objectSID: not available for group [(null)].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_group] (0x4000): Failed to retrieve UUID [2][No such file or directory].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_primary_name] (0x0400): Processing object foo
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_group] (0x0400): Processing group foo@company.com.domain1
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_group] (0x2000): This is a posix group
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original DN [cn=foo,cn=groups,dc=company,dc=com] to attributes of [foo@company.com.domain1].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_attrs_add_ldap_attr] (0x2000): Adding original mod-Timestamp [20200522230044Z] to attributes of [foo@company.com.domain1].
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_ghost_members] (0x0400): Group has 29 members
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_group] (0x0400): Storing info for group foo@company.com.domain1
(2020-06-24  6:18:28): [be[company.com.domain1]] [sysdb_store_group] (0x1000): The group record of foo@company.com.domain1 did not change, only updated the timestamp cache
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_save_groups] (0x4000): Group 0 processed!
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_get_groups_done] (0x4000): Saving 1 Groups - Done
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_id_op_done] (0x4000): releasing operation connection
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_req_done] (0x0400): DP Request [Account #196]: Request handler finished [0]: Success
(2020-06-24  6:18:28): [be[company.com.domain1]] [_dp_req_recv] (0x0400): DP Request [Account #196]: Receiving request data.
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_req_destructor] (0x0400): DP Request [Account #196]: Request removed.
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_req_destructor] (0x0400): Number of active DP request: 0
(2020-06-24  6:18:28): [be[company.com.domain1]] [dp_req_reply_std] (0x1000): DP Request [Account #196]: Returning [Success]: 0,0,Success
(2020-06-24  6:18:28): [be[company.com.domain1]] [sbus_issue_request_done] (0x0400): sssd.dataprovider.getAccountInfo: Success
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: sh[0x562963082ea0], connected[1], ops[(nil)], ldap[0x562963088af0]
(2020-06-24  6:18:28): [be[company.com.domain1]] [sdap_process_result] (0x2000): Trace: end of ldap_result list
(2020-06-24  6:18:28): [be[company.com.domain1]] [sbus_dispatch] (0x4000): Dispatching.

@sumit-bose this looks like a pretty bad bug, was any investigation done ?

@sumit-bose this looks like a pretty bad bug, was any investigation done ?

Hi,

yes, but so far I was not able to reproduce this issue with various setup. Also with the steps recently posted.

bye, Sumit

Hi @var1abl3,

thanks for the steps and the related part of the logs. As said I was not able to reproduce the issue. I wonder if you can safe the data and timestamp cache between every of your steps and send them to me, by private email if you prefer.

bye, Sumit

@simo5 thank you for the followup! @sumit-bose Happy to provide any data that will help. I do need to email you privately since it'll contain sensitive information. How do I get your email address?

@simo5 thank you for the followup! @sumit-bose Happy to provide any data that will help. I do need to email you privately since it'll contain sensitive information. How do I get your email address?

Hi,

I work for redhat.com and my name there is sbose .

bye, Sumit

~~I'm having the same issue ...~~

I thought I was seeing the same issue, but after digging deeper, it turns out that I had some users that were in more than 500 groups. The default OpenLDAP sizelimit is 500, so the (&(memberUid=bar)(objectClass=posixGroup)(cn=*)) lookup results were being truncated. This resulted in:

rm -f /var/lib/sss/db/* ; systemctl restart sssd
getent group foo  # Includes "bar"
id bar  # Missing "foo"
getent group foo  # Missing "bar"

To add to the confusion, my LDAP servers were sometimes returning groups in different orders, so the behavior varied depending on which LDAP server I was hitting and which order the LDAP lookups were performed in.

The following log messages in sss_default.log identify this problem:

[sssd[be[default]]] [sdap_get_generic_op_finished] (0x0400): Search result: Size limit exceeded(4), no errmsg set
[sssd[be[default]]] [sdap_get_generic_op_finished] (0x0080): LDAP sizelimit was exceeded, returning incomplete data

~I'm having the same issue ...~

I thought I was seeing the same issue, but after digging deeper, it turns out that I had some users that were in more than 500 groups. The default OpenLDAP sizelimit is 500, so the (&(memberUid=bar)(objectClass=posixGroup)(cn=*)) lookup results were being truncated. This resulted in:
rm -f /var/lib/sss/db/* ; systemctl restart sssd
getent group foo  # Includes "bar"
id bar  # Missing "foo"
getent group foo  # Missing "bar"
To add to the confusion, my LDAP servers were sometimes returning groups in different orders, so the behavior varied depending on which LDAP server I was hitting and which order the LDAP lookups were performed in.

The following log messages in sss_default.log identify this problem:
[sssd[be[default]]] [sdap_get_generic_op_finished] (0x0400): Search result: Size limit exceeded(4), no errmsg set
[sssd[be[default]]] [sdap_get_generic_op_finished] (0x0080): LDAP sizelimit was exceeded, returning incomplete data

Hi @PaulSD,

by default SSSD should have paging enabled for this kind of request. I wonder if you mind to open a new ticket for this issue and add the full logs to the new ticket?

bye, Sumit

@simo5 thank you for the followup! @sumit-bose Happy to provide any data that will help. I do need to email you privately since it'll contain sensitive information. How do I get your email address?

Hi,

I work for redhat.com and my name there is sbose .

bye, Sumit

Hi @var1abl3,

did you already had the chance to collect the data?

bye, Sumit

Hey @sumit-bose, I have something better. I've emailed you.

Hello,

We seem to have the exact same issue on RHEL 7 where after some time (we don't know what or how to trigger the bug), users lose both their primary and secondary groups. Primary group name cannot be resolved and no secondary groups are found.

When that happens, the output of id for my account (I'm supposed to be a member of at least 10 groups) is as follow: % id uid=1001525(myuseraccount) gid=20399 groups=20399

So if we can provide logs or whatever to help, feel free to let us know. We have a RH case open as well for that issue.

Cheers, Matt

Hi there, We are seeing (potentially) the same issue.

The only thing we have been able to reproduce is that a certain user does not belong to a group around 5 minutes after cleaning the sssd cache (sss_cache -E), in case that helps.

Happy to provide logs as well!

Cheers, Dan.

I think I may be experiencing the same bug - initially all users are associated with their groups, then after a while sssd "forgets" who belongs to which group. Since we use groups to permit users to login, people at this point aren't able to log into the systems. Clearing the cache via sss_cache -E will not solve the issue, but sssctl cache-remove -ops does resolve it for a while, until after a bit of time the same problem appears again. Every other LDAP client using the same server seems to work fine, but I can't completely rule out some odd configuration quirk. So far I haven't found any clue as to what is causing this issue.

Hi @ximion,

I wonder if you can share the data and the timestamp cache (/var/lib/sss/db/cache_DOMAIN.NAME.ldb and /var/lib/sss/db/timestamps_DOMAIN.NAME.ldb, respectively) from the time the issue occurs?

In recent versions of SSSD #5596 is fixed and with this using sss_cache -E should be sufficient and a complete removal should not be necessary anymore.

bye, Sumit

Hi @ximion,

I wonder if you can share the data and the timestamp cache (/var/lib/sss/db/cache_DOMAIN.NAME.ldb and /var/lib/sss/db/timestamps_DOMAIN.NAME.ldb, respectively) from the time the issue occurs?

I think I can, but I don't feel comfortable with throwing it out in public - I could send the files in a private mail though. If I could make the cache's contents completely anonymous that would also be fine, but that's probably be very difficult.

In recent versions of SSSD #5596 is fixed and with this using sss_cache -E should be sufficient and a complete removal should not be necessary anymore.

Ah! I am using SSSD 2.4.1 (as shipped with Debian 11), which does not have this patch, so at least that mystery is solved :-) Thank you for the fix!

Hi @ximion, I wonder if you can share the data and the timestamp cache (/var/lib/sss/db/cache_DOMAIN.NAME.ldb and /var/lib/sss/db/timestamps_DOMAIN.NAME.ldb, respectively) from the time the issue occurs?

I think I can, but I don't feel comfortable with throwing it out in public - I could send the files in a private mail though.

Hi,

sure feel free to use sbose@redhat.com.

If I could make the cache's contents completely anonymous that would also be fine, but that's probably be very difficult.

You can check the content with ldbsearch -H /var/lib/sss/db/cache_DOMAIN.NAME.ldb, ldbsearch is part of the ldb-tools package. But you will see that the names are part of the DN and I need those to related the cached object to each other and find the ones which have issues. So it would be easier to check the unmodified files.

bye, Sumit

In recent versions of SSSD #5596 is fixed and with this using sss_cache -E should be sufficient and a complete removal should not be necessary anymore.

Ah! I am using SSSD 2.4.1 (as shipped with Debian 11), which does not have this patch, so at least that mystery is solved :-) Thank you for the fix!

@sumit-bose

sure feel free to use sbose@redhat.com.

Done, you should have it as email now. I included a good version of the cache and a bad version of it. The configuration has enumerate=True, but fortunately the directory is very small.

I also just diff'ed the text output of ldbsearch for the two caches and indeed for the "bad" cache most groups associated with most users had simply vanished from the listing, which is odd. Could still be some odd configuration where a second request to the LDAP server is wrong and yields no groups while the first one is good and fetches all data...

If you need any more logs or configuration details, let me know!

We seem to be hitting the same bug

I have a cronjob which deletes the cache and restarts sssd every 15min (because sssd forgets which groups users belong too pretty much every 15min like a clockwork). That works, but is an extremely dumb workaround :-/

I observed a new thing, which makes me believe that this is no cache corruption on my side at least: The issue can be reproduced immediately on my clients just by running sss_cache -G - the groups are expired, but sssd never fetches new ones, so the groups are just lost. If the sssd.conf domain section has

entry_cache_timeout = 30
enum_cache_timeout = 30
ldap_enumeration_refresh_timeout = 30

then the entries a renwed sometimes after 30 seconds, but that's not a guarantee (I've seen it work 20 times in a row, just to fail constantly afterwards). So, apparently group information gets expired in the cache and sssd fails to renew group information unless the cache is completely deleted (I run sssctl cache-remove -ops > /dev/null in a cronjob every 15min, which works but also sucks a lot as a workaround).

Sooo... Really odd thing: I've updated the FreeIPA server container that we use for LDAP (and LDAP only...) to quay.io/freeipa/freeipa-server:centos-9-stream and that completely fixed the issue, no changes on the clients were needed. So, there was definitely something with the server that sssd wasn't happy with before and caused it to drop the previously valid cache.

Almost... The issue is back again with another FreeIPA update, but it's clear now that the problem lies there, not in SSSD (which is annoying, but progress at least :-D).

Thanks for the feedback, @ximion, I'll share this with FreeIPA team. Meanwhile, do you mind opening an issue there (I tried to search, but I didn't find it) or sharing the details here (so I can forward it to them)?

Thanks for the feedback, @ximion, I'll share this with FreeIPA team. Meanwhile, do you mind opening an issue there (I tried to search, but I didn't find it) or sharing the details here (so I can forward it to them)?

Thank you so much for the reply, and sorry for my slow response! I was distracted with some emergencies, and our workaround kept users happy most of the time (except for the unlucky ones which log in when sssd is restarting or had just forgotten about user groups).

I finally filed this issue against FreeIPA: https://pagure.io/freeipa/issue/9457 I also tried to reproduce it locally somehow, to provide something testable with the bug report, but didn't manage to do so yet. We also stopped upgrading the CentOS 9 Stream FreeIPA container immediately after the issue showed up again, but I could upgrade it to a more recent version if needed.

Thanks @ximion

@abbra pinged us about this, and it seems the problem isn't in FreeIPA. The suspicion is that the issue is between LDAP provider in SSSD and 389-ds as LDAP server.

I know we are talking about something ancient, with a lot of comments since 2018, but, if you don't mind providing the basic information, such as the configuration and versions you are using, set debug level 9 and remove the workaround to see what the logs show us (we have been trying to improve that area as well, hopefully it is easier to follow the stack trace), it would be helpful!

If we don't reproduce the issue, it will be hard to identify this tricky bug, it is why I am asking those things (again).

I will also ask someone more skilled than I (@sumit-bose @pbrezina or @alexey-tikhonov ) to jump in here and ask for the right/specific things (if I didn't yet).

As a matter of curiosity, are you running containerized IPA on Debian?

Thanks in advance for the help and willing to solve this :) we do really appreciate it

if you don't mind providing the basic information, such as the configuration and versions you are using, set debug level 9 and remove the workaround to see what the logs show us (we have been trying to improve that area as well, hopefully it is easier to follow the stack trace), it would be helpful!

Absolutely, I can quite easily do that! Thank you so much for asking! :-) I was about to write to the freeipa mailinglist, as requested in the FreeIPA bug report ^^

As a matter of curiosity, are you running containerized IPA on Debian?

Yes, so the configuration is one LDAP server running FreeIPA (centos-9-stream) in a Podman container on Debian 12, multiple webservices (like Nextcloud) connecting to it, and a bunch of storage and compute servers where people run calculations also connecting to it. The latter run sssd and are the only ones having issues, we never encountered this bug with any of the webservices. All systems run Debian 12 at the moment (hopefully that's not an issue...). Sssd on the affected clients is not containerized in any way.

IPA component versions in the container:

ipa-server-4.10.2-1.el9.x86_64
ipa-client-4.10.2-1.el9.x86_64
389-ds-base-2.3.4-2.el9.x86_64
package pki-ca is not installed
krb5-server-1.20.1-8.el9.x86_64

Sssd version on the clients: 2.8.2-4 (Debian version)

Is there any specific log you need? I'll try to collect some now :-)

Annoyingly, the reports list pretty much every user in the directory and disclose its structure. I think it's still okay to share that if I anonymize some of the more important parts (except usernames) though.

Still, I'll probably just temporarily upload the logs so you can fetch them, and then remove them so they aren't on this issue report forever.

Here are the logs, I had to change them a lot to strip out personal information from people and devices: https://drive.google.com/file/d/1whPaBwof7ZRiATeu5dwHrEMV6ux9srx4/view?usp=sharing - hopefully though, everything was either replaced with a hash, a stable human-readable name or a placeholder like <<token>>.

Some context: syslog-01-success.log contains a login attempt from me at client hostpc141 that was successful. My anonymized user-ID is user57 in this case. Then, syslog-02-fail.log contains the exact same login attempt an hour later when sssd has forgotten about user groups, which is denied because it forgot that I am in an allowed group. (See the checks at (2023-09-30 2:57:54) in sssd_default.anon.log.

I hope that helps with analyzing this issue!

Hi, the FreeIPA ticket seems to be the first one that actually mentions sssd.conf. So I must ask first - why do you need enumeration? Why do you use ldap provider instead of ipa provider?

Can you check if the issue happens if you set enumerate=false or if you use ipa provider?

why do you need enumeration?

It's not actually needed, that was added in an attempt to try to work around the vanishing group problem, but the groups vanish regardless of whether this setting is enabled or not.

Why do you use ldap provider instead of ipa provider?

We don't use any of IPA's "advanced" features, but also, how would ldap_default_bind_dn etc. work? The man page mentions:

The IPA provider accepts the same options used by the sssd-ldap(5) identity provider and the sssd-krb5(5) authentication provider with some exceptions

So I guess I can just replace "ldap" with "ipa" and it will work? I don't think I tried that yet, I can give it a go...

Can you check if the issue happens if you set enumerate=false

That definitely doesn't change anything, unfortunately.

or if you use ipa provider

If the IPA provider works in this restricted configuration, then I can try it. I'll have a look!

The recommended way to join to IPA domain is with realmd or ipa-client-install and I would say that you certainly wants to use the IPA provider instead of ldap when talking to IPA now. It is not just only about additional features, but the coded is completely different, taking advantage of internal IPA ldap schema to handle even the basic things in a better way.

I think the configuration should work with the following changes (mostly reduction) to the domain section:

...
[domain/default]
cache_credentials = true
override_shell = /bin/bash

id_provider = ipa
ipa_server = $ipaserveraddress
ldap_tls_cacert = /etc/sssd/ca.crt

access_provider = simple
simple_allow_groups = allowed_access_group1,allowed_access_group2,allowed_access_group3

ldap_default_bind_dn = uid=sys_search,cn=sysaccounts,cn=etc,dc=blah,dc=test-domain,dc=com
ldap_default_authtok_type = obfuscated_password
ldap_default_authtok = <token>

But honestly, I'm not sure from the top of my head if ldap binddn and password is supported with IPA, since it should use Kerberos.

I looked into the logs, but so far, I am not much smarter. One differents between using the ldap and ipa provider is that ldap provider relies on compat tree in ipa. Since it looks like the issue is related to ipa upgrade, maybe the compat tree is misbehaving.

The recommended way to join to IPA domain is with realmd or ipa-client-install and I would say that you certainly wants to use the IPA provider instead of ldap when talking to IPA now. It is not just only about additional features, but the coded is completely different, taking advantage of internal IPA ldap schema to handle even the basic things in a better way.

So, using the ipaprovider with the LDAP settings and without Kerberos in our custom-crafted sssd.conf file did not work at all, so I bit the bullet and used ipa-client-install. TBH, the simple LDAP setup existed before, to combine login for a bunch of web services, and FreeIPA was added so non-technical admins have a nice GUI to manage the directory. So Kerberos was seen as additional thing to maintain, which wasn't needed in this very trusted environment and would have needed configuring.

I don't know if it was ever tried to enroll the clients properly, but I now did that on my test client, and using ipa-client-install was an incredibly easy and painless process! Also, the described issue hasn't happened for at least 5 hours, normally it should have shown itself by now.

So, switching to the ipa-client-install-generated configuration and the IPA provider seems to have solved the issues.

I looked into the logs, but so far, I am not much smarter. One differents between using the ldap and ipa provider is that ldap provider relies on compat tree in ipa. Since it looks like the issue is related to ipa upgrade, maybe the compat tree is misbehaving.

That would definitely explain it... That would also explain why switching to the IPA provider solves the issue. Looks like doing things properly is good for something! I do wonder whether the underlying original issue would hit regular LDAP users, or whether it is specific to the unusual FreeIPA configurtion we have (and as it looks like will migrate away from to ipa-client-install, which fortunately works really well on Debian).

Both ipa-client-install and realmd are really easy and do everything for you. Realmd can also enroll you into an AD domain if you ever need it.

Since we didn't have any such reports for ldap provider and ldap provider is in terms of user and group look up pretty stable now (as is ipa), I really believe it is something in the compat tree or in combination of your configuration and compat tree. The compat tree is there for legacy clients and can be disabled by ipa-compat-manage. SSSD itself should not use it nowadays and ipa provider is definitely the recommended way to go.

One thing I do wonder about now: There is a bunch of webservices (Nextcloud, Matrix, Wiki.js, etc) that connect to FreeIPA via just LDAP, where I entered the exact same credentials as used on the sssd clients. Those never had any issues at all - are they not using the compat tree? Would I have to worry about them experiencing the same issue at some point?

I've been subscribed to this issue for years now (I reported having the issue with RHEL 7) and we're been tracking the same issue described by the OP with RHEL 8.4, 8.6 and 8.8. We first noticed the issue with RHEL 8 when a user or group was renamed: on certain clients, we'd never see the new names.

Testing showed dataExpireTimestamp when set to 1 isn't refreshed and entries which should expire don't.

We do use an OpenLDAP infrastructure, replicated with slarpd, clients connect to it using id_provider=ldap / ldap_schema=rfc2307bis and no enumeration.

To reproduce it:

do a getent passwd someuser
get a proper result
do a ldbsearch in the cache to get dataExpireTimestamp
see there's a proper value
expire the entry manually with sss_cache -u someuser
do a ldbsearch again to see dataExpireTimestamp is set to 1
do a getent passwd someuser (note using SSS_NSS_USE_MEMCACHE=NO makes no difference whatsoever)
check with ldbsearch dataExpireTimestamp is still 1 (instead of a proper record)

And when that happens sss_cache -E doesn't do anything. The only way to solve the issue is to stop sssd, rm the db files, restart sssd until the next occurence.

I can provide logs if needed.

One thing I do wonder about now: There is a bunch of webservices (Nextcloud, Matrix, Wiki.js, etc) that connect to FreeIPA via just LDAP, where I entered the exact same credentials as used on the sssd clients. Those never had any issues at all - are they not using the compat tree? Would I have to worry about them experiencing the same issue at some point?

I don't konw how they are configured, but if these services do not use SSSD, then it is likely that they use compat tree.

@mchouque please attach logs, I will look at it. Also, if you are able to reproduce it at will, it would be good to have precise steps to reproduce, including affected users and groups.

I was not able to reproduce it locally from given information. Keeping dataExpireTimestamp=1 in cache_$domain.ldb is in my opinion a bug, but not an issue. We actually separated this attribute into its own cache timestamps_$domain.ldb for performance improvement. ssscache seems to keep updating both databases, but the value in `cache$domain.ldbis not actually used by SSSD when looking up expired records. You can check that this attribute is updated intimestamps_$domain.ldb`.

@mchouque This actually sounds exactly like our issue, before switching to using ipa-client-install - if I have a new client, I'll maybe try your steps to see if I can reproduce the problem the same way.

I am facing similar issue on debian, can someone please help me in reading .ldb file, I tried clearing cache_default.ldb file and the issue was fixed however, I need to view this file. Can anyone please let me know how can I view it?

Hi,

you can use the ldbsearch command which should be available in the ldb-tools package to read the cache files.

HTH

bye, Sumit

Hi, I have similar issue of corrupt data on RHEL 7 OS:

[root~]# cat /etc/redhat-release 
Red Hat Enterprise Linux Server release 7.9 (Maipo)
[root@pgcludba2 ~]# rpm -qa | grep sssd
sssd-krb5-common-1.16.5-10.el7_9.16.x86_64
sssd-ldap-1.16.5-10.el7_9.16.x86_64
sssd-tools-1.16.5-10.el7_9.16.x86_64
python-sssdconfig-1.16.5-10.el7_9.16.noarch
sssd-common-1.16.5-10.el7_9.16.x86_64
sssd-common-pac-1.16.5-10.el7_9.16.x86_64
sssd-ad-1.16.5-10.el7_9.16.x86_64
sssd-krb5-1.16.5-10.el7_9.16.x86_64
sssd-1.16.5-10.el7_9.16.x86_64
sssd-client-1.16.5-10.el7_9.16.x86_64
sssd-ipa-1.16.5-10.el7_9.16.x86_64
sssd-proxy-1.16.5-10.el7_9.16.x86_64
sssd-dbus-1.16.5-10.el7_9.16.x86_64

Looking sssd db I have memberuid attribut on a group which contains only nested groups, so user should be defined as ghost entry:

name: sandbox-finops-dbaas-rw@ipa.maskeddomain
objectCategory: group
....
ghost: cpaun@ipa.maskeddomain
ghost: shaverkort@ipa.maskeddomain
ghost: plutterman@ipa.maskeddomain
overrideDN: name=sandbox-finops-dbaas-rw@ipa.maskeddomain,cn=groups,cn=ipa.maskeddomain,cn=sysdb
dataExpireTimestamp: 1
memberuid: bgrzesiak@ipa.maskeddomain
distinguishedName: name=sandbox-finops-dbaas-rw@ipa.maskeddomain,cn=groups,cn=ipa.maskeddomain,cn=sysdb

After that:

[root~]# systemctl stop sssd
[root~]# rm -f /var/lib/sss/db/*
[root~]# systemctl start sssd

Bad entry is resolved, I have ghost entry for bgrzesiak and getent group on the group give correct result Before I have try to unvalidate cache entry by sss_cache -g on all related group to this user and user itself.

if you can help, we have arround 20 thousand hosts and we detect it on 6 hosts RHEL7, nor on some others.... for this case but we don not check all host ;) And some time we detect thes kind of problems.

If you can help about this. Regards Bertrand

SSSD / sssd

Silent cache corruption and entries not refreshing #4872

Comments

record 429

record 30

record 30