stuck with ticket #3465
by Jakub Hrozek
Hi,
I'm afraid I got a little stuck looking into upstream ticket
https://pagure.io/SSSD/sssd/issue/3465
The reporter is seeing sssd memory usage increasing on RHEL-6 and
RHEL-7. There is a valgrind log from RHEL-6 attached to the ticket which
does show some leaks, the three biggest ones are:
==14913== 4,715,355 (74,383 direct, 4,640,972 indirect) bytes in 599 blocks are definitely lost in loss record 1,113 of 1,115
==14913== at 0x4C28A2E: malloc (vg_replace_malloc.c:270)
==14913== by 0x8D76DCA: _talloc_array (talloc.c:668)
==14913== by 0x56D0A48: ldb_val_dup (ldb_msg.c:106)
==14913== by 0x52668B4: sysdb_attrs_add_val_int (sysdb.c:555)
==14913== by 0x1264C964: sdap_parse_entry (sdap.c:576)
==14913== by 0x1261C702: sdap_get_and_parse_generic_parse_entry (sdap_async.c:1749)
==14913== by 0x1261FEB3: sdap_get_generic_op_finished (sdap_async.c:1487)
==14913== by 0x1262155E: sdap_process_result (sdap_async.c:352)
==14913== by 0x8B6DEA5: epoll_event_loop_once (tevent_epoll.c:728)
==14913== by 0x8B6C2D5: std_event_loop_once (tevent_standard.c:114)
==14913== by 0x8B67C3C: _tevent_loop_once (tevent.c:533)
==14913== by 0x8B67CBA: tevent_common_loop_wait (tevent.c:637)
==14913==
==14913== 7,998,231 bytes in 64,275 blocks are indirectly lost in loss record 1,114 of 1,115
==14913== at 0x4C28A2E: malloc (vg_replace_malloc.c:270)
==14913== by 0x8D76DCA: _talloc_array (talloc.c:668)
==14913== by 0x56D0A48: ldb_val_dup (ldb_msg.c:106)
==14913== by 0x52668B4: sysdb_attrs_add_val_int (sysdb.c:555)
==14913== by 0x1264C964: sdap_parse_entry (sdap.c:576)
==14913== by 0x1261C702: sdap_get_and_parse_generic_parse_entry (sdap_async.c:1749)
==14913== by 0x1261FEB3: sdap_get_generic_op_finished (sdap_async.c:1487)
==14913== by 0x1262155E: sdap_process_result (sdap_async.c:352)
==14913== by 0x8B6DEA5: epoll_event_loop_once (tevent_epoll.c:728)
==14913== by 0x8B6C2D5: std_event_loop_once (tevent_standard.c:114)
==14913== by 0x8B67C3C: _tevent_loop_once (tevent.c:533)
==14913== by 0x8B67CBA: tevent_common_loop_wait (tevent.c:637)
==14913==
==14913== 33,554,430 bytes in 2 blocks are still reachable in loss record 1,115 of 1,115
==14913== at 0x4C28A2E: malloc (vg_replace_malloc.c:270)
==14913== by 0x9FA4CCD: _plug_decode (plugin_common.c:666)
==14913== by 0x1453036A: gssapi_decode (gssapi.c:497)
==14913== by 0x9F9B783: sasl_decode (common.c:621)
==14913== by 0x69AC69C: sb_sasl_cyrus_decode (cyrus.c:188)
==14913== by 0x69AEF2F: sb_sasl_generic_read (sasl.c:711)
==14913== by 0x6790AEB: sb_debug_read (sockbuf.c:829)
==14913== by 0x67906AE: ber_int_sb_read (sockbuf.c:423)
==14913== by 0x678D789: ber_get_next (io.c:532)
==14913== by 0x69A6D4D: wait4msg (result.c:491)
==14913== by 0x12620EB4: sdap_process_result (sdap_async.c:165)
==14913== by 0x8B6DEA5: epoll_event_loop_once (tevent_epoll.c:728)
The biggest one almost looks like a leak in libldap, because this line:
==14913== by 0x12620EB4: sdap_process_result (sdap_async.c:165)
is a call to ldap_result().
But even the other leaks make little sense to me, like this one:
==14913== 7,998,231 bytes in 64,275 blocks are indirectly lost in loss record 1,114 of 1,115
==14913== at 0x4C28A2E: malloc (vg_replace_malloc.c:270)
==14913== by 0x8D76DCA: _talloc_array (talloc.c:668)
==14913== by 0x56D0A48: ldb_val_dup (ldb_msg.c:106)
==14913== by 0x52668B4: sysdb_attrs_add_val_int (sysdb.c:555)
==14913== by 0x1264C964: sdap_parse_entry (sdap.c:576)
==14913== by 0x1261C702: sdap_get_and_parse_generic_parse_entry (sdap_async.c:1749)
==14913== by 0x1261FEB3: sdap_get_generic_op_finished (sdap_async.c:1487)
==14913== by 0x1262155E: sdap_process_result (sdap_async.c:352)
==14913== by 0x8B6DEA5: epoll_event_loop_once (tevent_epoll.c:728)
==14913== by 0x8B6C2D5: std_event_loop_once (tevent_standard.c:114)
==14913== by 0x8B67C3C: _tevent_loop_once (tevent.c:533)
==14913== by 0x8B67CBA: tevent_common_loop_wait (tevent.c:637)
In sdap_parse_entry, we allocate sysdb_attrs on state and all the internal
ldb structures hang off sysdb_attrs. The context is stolen to caller's
provided context which is typically state of a tevent request which is
passed upwards. So the only idea I have is that somewhere, we steal the
request to NULL.. But I don't know where or how to look for this.
Also, it seems odd that with so many people running sssd, this is the
only user (so far?) who reported this issue.
Does anyone have an idea how to continue?
6 years, 8 months
[sssd PR#347][opened] Fixes related to negative cache and "root" user/group
by fidencio
URL: https://github.com/SSSD/sssd/pull/347
Author: fidencio
Title: #347: Fixes related to negative cache and "root" user/group
Action: opened
PR body:
"""
This patch set contains a bunch of fixes in the negative cache code.
The patches were tested in an AD-trust environment and more specific instructions/details can be found below:
- **NEGCACHE: Add some comments about each step of sss_ncache_prepopulate()**
Just verified the comments make sense.
- **NEGCACHE: Always add "root" to the negative cache**:
- Add `filter_users = foo` and `filter_groups = foo` under `[nss]` section;
- Restart SSSD (`systemctl restart sssd`) and run `id root`;
- Inspect sssd_nss.log, checking for the second time the users and groups are added to the negative cache;
- Without this patch:
```
(Mon Aug 14 17:09:50 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'foo' matched without domain, user is foo
(Mon Aug 14 17:09:50 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/indirect.ipa.ff/foo(a)indirect.ipa.ff] to negative cache permanently
(Mon Aug 14 17:09:50 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'bar' matched without domain, user is bar
(Mon Aug 14 17:09:50 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/GROUP/indirect.ipa.ff/bar(a)indirect.ipa.ff] to negative cache permanently
```
- With this patch:
```
(Mon Aug 14 17:13:31 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'foo' matched without domain, user is foo
(Mon Aug 14 17:13:31 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/indirect.ipa.ff/foo(a)indirect.ipa.ff] to negative cache permanently
(Mon Aug 14 17:13:31 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'bar' matched without domain, user is bar
(Mon Aug 14 17:13:31 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/GROUP/indirect.ipa.ff/bar(a)indirect.ipa.ff] to negative cache permanently
(Mon Aug 14 17:13:31 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/indirect.ipa.ff/root(a)indirect.ipa.ff] to negative cache permanently
(Mon Aug 14 17:13:31 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/GROUP/indirect.ipa.ff/root(a)indirect.ipa.ff] to negative cache permanently
(Mon Aug 14 17:13:31 2017) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain indirect.ad.ff is Active
(Mon Aug 14 17:13:31 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/indirect.ad.ff/root(a)indirect.ad.ff] to negative cache permanently
(Mon Aug 14 17:13:31 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/GROUP/indirect.ad.ff/root(a)indirect.ad.ff] to negative cache permanently
```
- **NEGCACHE: Add "0" to the negative cache**:
- Considering the very same environment where the previous patch was applied, do:
- `id 0`;
- Inspect sssd_nss.log, checking for the cache req call triggered by the command above;
- Without this patch:
```
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [nss_getby_name] (0x0400): Input name: 0
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #0: Setting "User by name" plugin
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_send] (0x0400): CR #0: New request 'User by name'
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_process_input] (0x0400): CR #0: Parsing input name [0]
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name '0' matched without domain, user is 0
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_set_name] (0x0400): CR #0: Setting name [0]
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #0: Performing a multi-domain search
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #0: Search will check the cache and check the data provider
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain indirect.ipa.ff type POSIX is valid
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #0: Using domain [indirect.ipa.ff]
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #0: Preparing input data for domain [indirect.ipa.ff] rules
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_search_send] (0x0400): CR #0: Looking up 0(a)indirect.ipa.ff
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #0: Checking negative cache for [0(a)indirect.ipa.ff]
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/indirect.ipa.ff/0(a)indirect.ipa.ff]
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #0: [0(a)indirect.ipa.ff] is not present in negative cache
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #0: Looking up [0(a)indirect.ipa.ff] in cache
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x669120
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x6691e0
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x669120 "ltdb_callback"
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x6691e0 "ltdb_timeout"
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x669120 "ltdb_callback"
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #0: Object [0(a)indirect.ipa.ff] was not found in cache
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #0: Looking up [0(a)indirect.ipa.ff] in data provider
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x416010:1:0@indirect.ipa.ff@indirect.ipa.ff]
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [indirect.ipa.ff][0x1][BE_REQ_USER][name=0@indirect.ipa.ff:-]
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x65db60
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x416010:1:0@indirect.ipa.ff@indirect.ipa.ff]
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x65db60
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x65c8c0
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching.
(Mon Aug 14 17:19:52 2017) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success
```
- With this patch:
```
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [nss_getby_name] (0x0400): Input name: 0
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #0: Setting "User by name" plugin
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_send] (0x0400): CR #0: New request 'User by name'
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_process_input] (0x0400): CR #0: Parsing input name [0]
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name '0' matched without domain, user is 0
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_set_name] (0x0400): CR #0: Setting name [0]
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #0: Performing a multi-domain search
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #0: Search will check the cache and check the data provider
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain indirect.ipa.ff type POSIX is valid
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #0: Using domain [indirect.ipa.ff]
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_prepare_domain_data] (0x0400): CR #0: Preparing input data for domain [indirect.ipa.ff] rules
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_search_send] (0x0400): CR #0: Looking up 0(a)indirect.ipa.ff
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #0: Checking negative cache for [0(a)indirect.ipa.ff]
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/USER/indirect.ipa.ff/0(a)indirect.ipa.ff]
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #0: [0(a)indirect.ipa.ff] does not exist (negative cache)
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain indirect.ad.ff type POSIX is valid
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [cache_req_process_result] (0x0400): CR #0: Finished: Not found
```
- **NEGCACHE: Descend to subdomains when adding user/groups**:
- Considering the very same environment where the previous patch was applied, do:
- `id root`;
- Inspect sssd_nss.log, looking for when the user `foo` and group `bar` are added to the negative cache;
- Without this patch:
```
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'foo' matched without domain, user is foo
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/indirect.ipa.ff/foo(a)indirect.ipa.ff] to negative cache permanently
(Mon Aug 14 17:26:17 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'bar' matched without domain, user is bar
```
- With this patch:
```
(Mon Aug 14 17:31:54 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'foo' matched without domain, user is foo
(Mon Aug 14 17:31:54 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/indirect.ipa.ff/foo(a)indirect.ipa.ff] to negative cache permanently
(Mon Aug 14 17:31:54 2017) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain indirect.ad.ff is Active
(Mon Aug 14 17:31:54 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/USER/indirect.ad.ff/foo(a)indirect.ad.ff] to negative cache permanently
(Mon Aug 14 17:31:54 2017) [sssd[nss]] [sss_parse_name_for_domains] (0x0200): name 'bar' matched without domain, user is bar
(Mon Aug 14 17:31:54 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/GROUP/indirect.ipa.ff/bar(a)indirect.ipa.ff] to negative cache permanently
(Mon Aug 14 17:31:54 2017) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain indirect.ad.ff is Active
(Mon Aug 14 17:31:54 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/GROUP/indirect.ad.ff/bar(a)indirect.ad.ff] to negative cache permanently
```
- **CACHE_REQ: Don't error out when searching by id = 0**:
- With the very same environment, just do:
- `id root`;
- Inspect the sssd_nss.log, taking a look after the first cache req request;
- Without this patch:
```
(Mon Aug 14 19:21:59 2017) [sssd[nss]] [sss_domain_get_state] (0x1000): Domain indirect.ad.ff is Active
(Mon Aug 14 19:21:59 2017) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found
(Mon Aug 14 19:21:59 2017) [sssd[nss]] [nss_getby_id] (0x0400): Input ID: 0
(Mon Aug 14 19:21:59 2017) [sssd[nss]] [cache_req_data_create] (0x0020): Bug: id cannot be 0!
(Mon Aug 14 19:21:59 2017) [sssd[nss]] [cache_req_data_create] (0x0020): Unable to create cache_req data [1432158209]: Internal Error
(Mon Aug 14 19:21:59 2017) [sssd[nss]] [nss_getby_id] (0x0020): Unable to set cache request data!
(Mon Aug 14 19:21:59 2017) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: error [12]: Cannot allocate memory
```
- With this patch:
```
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [nss_getby_id] (0x0400): Input ID: 0
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #1: Setting "User by ID" plugin
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_send] (0x0400): CR #1: New request 'User by ID'
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #1: Performing a multi-domain search
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #1: Search will check the cache and check the data provider
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain indirect.ipa.ff type POSIX is valid
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #1: Using domain [indirect.ipa.ff]
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_send] (0x0400): CR #1: Looking up UID:0@indirect.ipa.ff
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #1: Checking negative cache for [UID:0@indirect.ipa.ff]
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/UID/0]
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #1: [UID:0@indirect.ipa.ff] is not present in negative cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #1: Looking up [UID:0@indirect.ipa.ff] in cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x252fa20
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x2532bc0
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x252fa20 "ltdb_callback"
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x2532bc0 "ltdb_timeout"
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x252fa20 "ltdb_callback"
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #1: Object [UID:0@indirect.ipa.ff] was not found in cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #1: Looking up [UID:0@indirect.ipa.ff] in data provider
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x416030:1:*@indirect.ipa.ff]
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [indirect.ipa.ff][0x1][BE_REQ_USER][*:-]
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x252a330
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x416030:1:*@indirect.ipa.ff]
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x252a330
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x25238c0
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching.
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #1: Looking up [UID:0@indirect.ad.ff] in cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x252f960
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x2534150
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x252f960 "ltdb_callback"
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x2534150 "ltdb_timeout"
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x252f960 "ltdb_callback"
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #1: Object [UID:0@indirect.ad.ff] was not found in cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_ncache_add] (0x2000): CR #1: This request type does not support negative cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_global_ncache_add] (0x0400): CR #1: Adding [UID:0@indirect.ad.ff] to global negative cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/UID/0] to negative cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_process_result] (0x0400): CR #1: Finished: Not found
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [memcache_delete_entry] (0x0040): Bug: invalid input!
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found
```
- **NSS: Don't error out when deleting an entry which has id = 0 from the memcache**:
- Considering the very same environment, just do:
- `id root`;
- Inspect sssd_nss.log, looking for "Bug: invalid input!" from memcache_delete_entry;
- Without this patch:
```
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #1: Object [UID:0@indirect.ad.ff] was not found in cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_search_ncache_add] (0x2000): CR #1: This request type does not support negative cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_global_ncache_add] (0x0400): CR #1: Adding [UID:0@indirect.ad.ff] to global negative cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/UID/0] to negative cache
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [cache_req_process_result] (0x0400): CR #1: Finished: Not found
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [memcache_delete_entry] (0x0040): Bug: invalid input!
(Mon Aug 14 19:26:11 2017) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found
```
- With this patch:
```
(Mon Aug 14 19:34:08 2017) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #1: Object [UID:0@indirect.ad.ff] was not found in cache
(Mon Aug 14 19:34:08 2017) [sssd[nss]] [cache_req_search_ncache_add] (0x2000): CR #1: This request type does not support negative cache
(Mon Aug 14 19:34:08 2017) [sssd[nss]] [cache_req_global_ncache_add] (0x0400): CR #1: Adding [UID:0@indirect.ad.ff] to global negative cache
(Mon Aug 14 19:34:08 2017) [sssd[nss]] [sss_ncache_set_str] (0x0400): Adding [NCE/UID/0] to negative cache
(Mon Aug 14 19:34:08 2017) [sssd[nss]] [cache_req_process_result] (0x0400): CR #1: Finished: Not found
(Mon Aug 14 19:34:08 2017) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found
```
- **NEGCACHE: Add root's uid/gid to ncache**:
- Considering the very same environment, just do:
- `id root`;
- Inspect sssd_nss.log, looking for a lookup in the data provider;
- Without this patch:
```
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [nss_getby_id] (0x0400): Input ID: 0
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #1: Setting "User by ID" plugin
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_send] (0x0400): CR #1: New request 'User by ID'
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #1: Performing a multi-domain search
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #1: Search will check the cache and check the data provider
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain indirect.ipa.ff type POSIX is valid
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #1: Using domain [indirect.ipa.ff]
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_search_send] (0x0400): CR #1: Looking up UID:0@indirect.ipa.ff
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #1: Checking negative cache for [UID:0@indirect.ipa.ff]
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/UID/0]
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #1: [UID:0@indirect.ipa.ff] is not present in negative cache
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #1: Looking up [UID:0@indirect.ipa.ff] in cache
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_callback": 0x82b230
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [ldb] (0x4000): Added timed event "ltdb_timeout": 0x825100
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [ldb] (0x4000): Running timer event 0x82b230 "ltdb_callback"
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [ldb] (0x4000): Destroying timer event 0x825100 "ltdb_timeout"
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [ldb] (0x4000): Ending timer event 0x82b230 "ltdb_callback"
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_search_cache] (0x0400): CR #1: Object [UID:0@indirect.ipa.ff] was not found in cache
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [cache_req_search_dp] (0x0400): CR #1: Looking up [UID:0@indirect.ipa.ff] in data provider
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [sss_dp_issue_request] (0x0400): Issuing request for [0x415ff0:1:*@indirect.ipa.ff]
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [sss_dp_get_account_msg] (0x0400): Creating request for [indirect.ipa.ff][0x1][BE_REQ_USER][*:-]
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [sbus_add_timeout] (0x2000): 0x825330
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [sss_dp_internal_get_send] (0x0400): Entering request [0x415ff0:1:*@indirect.ipa.ff]
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [sbus_remove_timeout] (0x2000): 0x825330
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [sbus_dispatch] (0x4000): dbus conn: 0x81e8c0
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [sbus_dispatch] (0x4000): Dispatching.
(Mon Aug 14 19:39:17 2017) [sssd[nss]] [sss_dp_get_reply] (0x1000): Got reply from Data Provider - DP error code: 0 errno: 0 error message: Success
```
- With this patch:
```
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [nss_getby_id] (0x0400): Input ID: 0
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_set_plugin] (0x2000): CR #1: Setting "User by ID" plugin
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_send] (0x0400): CR #1: New request 'User by ID'
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_select_domains] (0x0400): CR #1: Performing a multi-domain search
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_search_domains] (0x0400): CR #1: Search will check the cache and check the data provider
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain indirect.ipa.ff type POSIX is valid
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #1: Using domain [indirect.ipa.ff]
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_search_send] (0x0400): CR #1: Looking up UID:0@indirect.ipa.ff
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #1: Checking negative cache for [UID:0@indirect.ipa.ff]
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/UID/0]
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #1: [UID:0@indirect.ipa.ff] does not exist (negative cache)
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_validate_domain_type] (0x2000): Request type POSIX-only for domain indirect.ad.ff type POSIX is valid
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_set_domain] (0x0400): CR #1: Using domain [indirect.ad.ff]
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_search_send] (0x0400): CR #1: Looking up UID:0@indirect.ad.ff
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #1: Checking negative cache for [UID:0@indirect.ad.ff]
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [sss_ncache_check_str] (0x2000): Checking negative cache for [NCE/UID/0]
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_search_ncache] (0x0400): CR #1: [UID:0@indirect.ad.ff] does not exist (negative cache)
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [cache_req_process_result] (0x0400): CR #1: Finished: Not found
(Mon Aug 14 19:41:29 2017) [sssd[nss]] [nss_protocol_done] (0x4000): Sending reply: not found
```
"""
To pull the PR as Git branch:
git remote add ghsssd https://github.com/SSSD/sssd
git fetch ghsssd pull/347/head:pr347
git checkout pr347
6 years, 8 months