#342 better error message when cache overflows
Closed: wontfix None Opened 11 years ago by rmeggins.

ticket3 gives the ability to increase the acl cache to avoid overflows - but when you do get an overflow, all you get is this cryptic error message:

[17/Apr/2012:17:38:20 -0600] acl__TestRights - cache overflown

Not only that, but you get hundreds of these, clogging up your errors log. We need to do two things

  • print a message like this:

Your ACL cache of %d slots has overflowed. This can happen when you have many ACIs. This ACI evaluation requires %d slots to cache. You can increase your max value by setting the attribute nsslapd-aclpb-max-selected-acls in cn=ACL Plugin,cn=plugins,cn=config to a value higher. A server restart is required.

  • print the error message only once per ACI evaluation instead of hundreds of times

set default ticket origin to Community

Added initial screened field value.

Bug description: ACL cache overflow error message is not very clear
and repeated too many times.

Fix description:
1) print a message like this:
Your ACL cache of %d slots has overflowed. This can happen
when you have many ACIs. This ACI evaluation requires %d
slots to cache. You can increase your max value by setting
the attribute nsslapd-aclpb-max-selected-acls in cn=ACL
Plugin,cn=plugins,cn=config to a value higher. A server
restart is required.
2) print the error message only once per ACI evaluation instead
of hundreds of times

Reviewed by Mark (Thank you!!)

Pushed to master: commit 892bf12

there are two places where the "cache overflow" message logged, but only one is fixed

Replying to [comment:13 lkrispen]:

there are two places where the "cache overflow" message logged, but only one is fixed

Hi Ludwig, could you put some more details about the second "cache overflow" which is not yet fixed? I'm having a hard time to find it...

All "cache overflow(n)" strings look in comments.
'''master:'''
{{{
find . -name ".[ch]" | xargs egrep --color -i "cache overflow"
./ldap/servers/plugins/acl/acl.c: } else { /
cache overflow /
./ldap/servers/plugins/acl/acl.c: } else { /
cache overflow /
./ldap/servers/slapd/back-ldbm/import.c: * without the test for cache overflow?
/
}}}

'''389-ds-base-1.3.2:'''
{{{
find . -name ".[ch]" | xargs egrep --color -i "cache overflow"
./ldap/servers/plugins/acl/acl.c: } else { /
cache overflow /
./ldap/servers/plugins/acl/acl.c: } else { /
cache overflow /
./ldap/servers/slapd/back-ldbm/import.c: * without the test for cache overflow?
/
}}}

'''389-ds-base-1.3.1:'''
{{{
find . -name ".[ch]" | xargs egrep --color -i "cache overflow"
./ldap/servers/plugins/acl/acl.c: } else { /
cache overflow /
./ldap/servers/plugins/acl/acl.c: } else { /
cache overflow /
./ldap/servers/slapd/back-ldbm/import.c: * without the test for cache overflow?
/
}}}

Are you suggesting to log the cache overflow error here? It seems nothing is currently logged here.
{{{
2735 static int
2736 acl__TestRights(Acl_PBlock aclpb,int access, const char right, const char map_gene ric,
2737 aclResultReason_t
result_reason)
[...]
2929 } else { / cache overflow /
2930 if ( rights_rv == ACL_RES_DENY) {
2931 result_reason->deciding_aci = aci;
2932 result_reason->reason = ACL_REASON_EVALUATED_DENY;
2933 TNF_PROBE_1_DEBUG(acl__TestRights_end,"ACL","",
2934 tnf_string,evaled_deny,"");
2935 return ACL_RES_DENY;
2936 } else {
2937 continue;
2938 }
2939 }
}}}

I wonder if you might have opened this bug due to the report from a community member:
[389-users] acl__TestRights - cache overflown
Unfortunately, the fix was not backported to 1.2.11. He is running 1.2.11.
389-ds-base-1.2.11.25-1.el6.x86_64

This ticket's milestone is 1.3.1.

you're right, I was referring to line 2929 and following, yes maybe we could log the same message here

Description: commit 892bf12 only
logs detailed cache overflow message on the allow ACIs. This patch
logs the same message when the cache overflow occurs on the deny
ACIs.

Thanks to Ludwig for finding out the missing piece.

Reviewed by Rich (Thank you!!)

Pushed to master:
f67e638..24d1817 master -> master
commit 24d1817

Pushed to 389-ds-base-1.3.2:
df5a061..3c6e0d0 389-ds-base-1.3.2 -> 389-ds-base-1.3.2
commit 3c6e0d0

Pushed to 389-ds-base-1.3.1:
457cd16..8e40fa9 389-ds-base-1.3.1 -> 389-ds-base-1.3.1
commit 8e40fa9

==21238== Thread 32:
==21238== Invalid read of size 2
==21238== at 0xEBB5053: acl__TestRights (acl.c:3150)
==21238== by 0xEBB0B6B: acl_access_allowed (acl.c:592)
==21238== by 0xEBCCD66: acl_access_allowed_main (aclplugin.c:393)
==21238== by 0x4CC6CF3: plugin_call_acl_plugin (plugin_acl.c:90)
==21238== by 0x4C885A4: test_filter_access (filterentry.c:1014)
==21238== by 0x4C881A2: slapi_vattr_filter_test_ext_internal (filterentry.c:929)
==21238== by 0x4C87DB7: slapi_vattr_filter_test_ext (filterentry.c:842)
==21238== by 0x4C87CEE: slapi_vattr_filter_test (filterentry.c:790)
==21238== by 0x1030DA99: ldbm_back_next_search_entry_ext (ldbm_search.c:1646)
==21238== by 0x1030CF3B: ldbm_back_next_search_entry (ldbm_search.c:1362)
==21238== by 0x4CB6CB7: iterate (opshared.c:1281)
==21238== by 0x4CB75CF: send_results_ext (opshared.c:1678)
==21238== by 0x4CB6307: op_shared_search (opshared.c:853)
==21238== by 0x13D619: do_search (search.c:376)
==21238== by 0x120982: connection_dispatch_operation (connection.c:684)
==21238== by 0x12291F: connection_threadmain (connection.c:2534)
==21238== by 0x690FC75: _pt_root (ptthread.c:204)
==21238== by 0x6F4CD14: start_thread (pthread_create.c:308)
==21238== by 0x746A53C: clone (clone.S:114)
==21238== Address 0x13d4ee96 is 6 bytes after a block of size 1,600 alloc'd
==21238== at 0x4A06B6F: calloc (vg_replace_malloc.c:593)
==21238== by 0x4C61C9F: slapi_ch_calloc (ch_malloc.c:243)
==21238== by 0xEBB8282: acl__malloc_aclpb (acl_ext.c:745)
==21238== by 0xEBB7AC9: acl_create_aclpb_pool (acl_ext.c:506)
==21238== by 0xEBBD2F2: aclinit_main (aclinit.c:130)
==21238== by 0xEBCC9FE: aclplugin_init (aclplugin.c:293)
==21238== by 0x4CC334B: plugin_call_func (plugin.c:1474)
==21238== by 0x4CC3238: plugin_call_one (plugin.c:1442)
==21238== by 0x4CC2A49: plugin_dependency_startall (plugin.c:1214)
==21238== by 0x4CC316A: plugin_startall (plugin.c:1404)
==21238== by 0x12F3CA: main (main.c:1187)

==21238== Invalid write of size 2
==21238== at 0xEBB50C9: acl__TestRights (acl.c:3160)
==21238== by 0xEBB0B6B: acl_access_allowed (acl.c:592)
==21238== by 0xEBCCD66: acl_access_allowed_main (aclplugin.c:393)
==21238== by 0x4CC6CF3: plugin_call_acl_plugin (plugin_acl.c:90)
==21238== by 0x4C885A4: test_filter_access (filterentry.c:1014)
==21238== by 0x4C881A2: slapi_vattr_filter_test_ext_internal (filterentry.c:929)
==21238== by 0x4C87DB7: slapi_vattr_filter_test_ext (filterentry.c:842)
==21238== by 0x4C87CEE: slapi_vattr_filter_test (filterentry.c:790)
==21238== by 0x1030DA99: ldbm_back_next_search_entry_ext (ldbm_search.c:1646)
==21238== by 0x1030CF3B: ldbm_back_next_search_entry (ldbm_search.c:1362)
==21238== by 0x4CB6CB7: iterate (opshared.c:1281)
==21238== by 0x4CB75CF: send_results_ext (opshared.c:1678)
==21238== by 0x4CB6307: op_shared_search (opshared.c:853)
==21238== by 0x13D619: do_search (search.c:376)
==21238== by 0x120982: connection_dispatch_operation (connection.c:684)
==21238== by 0x12291F: connection_threadmain (connection.c:2534)
==21238== by 0x690FC75: _pt_root (ptthread.c:204)
==21238== by 0x6F4CD14: start_thread (pthread_create.c:308)
==21238== by 0x746A53C: clone (clone.S:114)
==21238== Address 0x13d4ee96 is 6 bytes after a block of size 1,600 alloc'd
==21238== at 0x4A06B6F: calloc (vg_replace_malloc.c:593)
==21238== by 0x4C61C9F: slapi_ch_calloc (ch_malloc.c:243)
==21238== by 0xEBB8282: acl__malloc_aclpb (acl_ext.c:745)
==21238== by 0xEBB7AC9: acl_create_aclpb_pool (acl_ext.c:506)
==21238== by 0xEBBD2F2: aclinit_main (aclinit.c:130)
==21238== by 0xEBCC9FE: aclplugin_init (aclplugin.c:293)
==21238== by 0x4CC334B: plugin_call_func (plugin.c:1474)
==21238== by 0x4CC3238: plugin_call_one (plugin.c:1442)
==21238== by 0x4CC2A49: plugin_dependency_startall (plugin.c:1214)
==21238== by 0x4CC316A: plugin_startall (plugin.c:1404)
==21238== by 0x12F3CA: main (main.c:1187)

Description: commit 892bf12
introduced an invalid memory read/write. This patch prepares one
extra aclpblock for the acl cache overflow.

git patch file (master) -- fixing invalid read/write on the acl cache overflow
0001-Ticket-342-better-error-message-when-cache-overflows.3.patch

Reviewed by Rich (Thank you!!)

Pushed to master:
9f2b104..3fee1fc master -> master
commit 3fee1fc

Pushed to 389-ds-base-1.3.2:
a6ec074..fe75b11 389-ds-base-1.3.2 -> 389-ds-base-1.3.2
commit fe75b11

Pushed to 389-ds-base-1.3.1:
51c1b2a..aec2050 389-ds-base-1.3.1 -> 389-ds-base-1.3.1
commit aec2050

Metadata Update from @nkinder:
- Issue assigned to nhosoi
- Issue set to the milestone: 1.3.1

7 years ago

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

This issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/342

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

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix (was: Fixed)

3 years ago

Login to comment on this ticket.

Metadata