Ticket was cloned from Red Hat Bugzilla (product Red Hat Enterprise Linux 7): Bug 1358706
Please note that this Bug is private and may not be accessible as it contains confidential Red Hat customer information.
Description of problem: when we enable internal operations to troubleshoot customer issues, by doing: nsslapd-accesslog-level: 4 + (former log level) nsslapd-plugin-logging: on we can see the internal operations but we cannot match request with result. [20/Jul/2016:15:42:53 -0500] conn=Internal op=-1 SRCH base="uid=xxxx,cn=users,cn=accounts,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL [20/Jul/2016:15:42:53 -0500] conn=Internal op=-1 RESULT err=0 tag=48 nentries=1 etime=0 We need, at least, to be able to match the request with the result and, if possible, to which connection the operation belongs to. Top of the top will be to have the plugin that has done it as well. Version-Release number of selected component (if applicable): N/A How reproducible: N/A
attachment 0001-improve-logging-of-internal-operations-POC.patch
Metadata Update from @lkrispen: - Issue set to the milestone: 1.3.6.0
Metadata Update from @mreynolds: - Issue close_status updated to: None - Issue set to the milestone: 1.3.7.0 (was: 1.3.6.0)
Metadata Update from @mreynolds: - Custom field reviewstatus adjusted to None - Custom field version adjusted to None - Issue tagged with: RFE
So the current patch changes:
conn=Internal op=-1
to
conn=1 op=2
But this losses the the information about it being an internal operation though.
Perhaps we can change it to something like this where we keep the "Internal" word and add the conn id to it. Here are a few examples:
conn=Internal-connid=7 op=2 conn=Internal(connid=7) op=2 conn=Internal-7 op=2 conn=Internal(7) op=2
you are right we should not loose the fact that it is internal.
From your suggestions I like conn=Internal(7) op=2 best what about conn=7 op=2(Internal)
as it is about internal ops, not conns
you are right we should not loose the fact that it is internal. From your suggestions I like conn=Internal(7) op=2 best what about conn=7 op=2(Internal) as it is about internal ops, not conns
That would work, but it would very different from before (moving "Internal" from conn to op). Hard to say if anyone is actually parsing Internal access logging as this would break any existing scripts (its probably unlikely) It will also impact logconv.pl no matter what approach we take. Anyway I am fine with your suggestion!
Our logging format is not a supported part of our interface, and thus we should feel free to change this.
A future improvement could be structured log output (ie json), and then we support that behaviour.
the attached patch is really a proof of concept, not ready yet. It does not cleanly apply to master (done before clang code formatting) and after doing it manually it works, but has strong limitations.
It uses the wrapper conn_id and op_id only in SRCH logging, not even in the RESULT of searches. It is not used in ADD/DEL/MODRDN ops It logs a strange connid for real internal ops It sets the thread local data in connection threadmain, need to verify that it still is corect related to changes in turbo mode, more data and nuncstans
It sets the thread local data in connection threadmain, need to verify that it still is corect related to changes in turbo mode, more data and nuncstans
It should be find with NS. NS will use one thread for the IO event as it arrives, and a different thread for the actual operation itself. However that would only affect the external connection ID, not an internal ops. Internal ops don't start or use new threads (due to potential for deadlock etc).
I would assume that whatever identifier you can create for internal ops and how they relate to the conn_id and op_id, that would suffice.
Perhaps we could have a "nested" conn_id/op_id idea, that when we trigger the internal operation via do_*, we can push in a "parent_conn_id" and "parent_op_id", then we would have:
[timestame] conn=X op=Y internal_op=Z
Where X/Y are from parent ID's in the pb, and the internal_op is the current internal op id.
-- Sincerely,
William
Actually I wasn't sure if you were working on it Ludwig, but I did the feature. Here is what a del looks like with RI plugin (and nsslapd-plugin-logging enabled). This takes into account a separate op id count for the internal ops:
conn=Internal(ORIGNAL CONN ID) op=ORIGINAL_OP_ID(INTERNAL OP COUNT)
[08/Aug/2018:20:57:32.612774938 -0400] conn=2 op=57 DEL dn="uid=zzzzz,dc=example,dc=com" [08/Aug/2018:20:57:32.624102102 -0400] conn=Internal(2) op=57(1) SRCH base="uid=zzzzz,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL [08/Aug/2018:20:57:32.624252642 -0400] conn=Internal(2) op=57(1) RESULT err=0 tag=48 nentries=1 etime=0.0011273218 [08/Aug/2018:20:57:32.629996876 -0400] conn=Internal(2) op=57(2) SRCH base="dc=example,dc=com" scope=2 filter="(member=uid=zzzzz,dc=example,dc=com)" attrs="member" [08/Aug/2018:20:57:32.630228231 -0400] conn=Internal(2) op=57(2) RESULT err=0 tag=48 nentries=0 etime=0.0005139582 [08/Aug/2018:20:57:32.635206553 -0400] conn=Internal(2) op=57(3) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=uid=zzzzz,dc=example,dc=com)" attrs="uniquemember" [08/Aug/2018:20:57:32.635439964 -0400] conn=Internal(2) op=57(3) RESULT err=0 tag=48 nentries=1 etime=0.0005186672 [08/Aug/2018:20:57:32.643740893 -0400] conn=Internal(2) op=57(4) MOD dn="cn=TESTER,dc=example,dc=com" [08/Aug/2018:20:57:32.655572565 -0400] conn=Internal(2) op=57(5) SRCH base="cn=TESTER,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL [08/Aug/2018:20:57:32.655682783 -0400] conn=Internal(2) op=57(5) RESULT err=0 tag=48 nentries=1 etime=0.0011723128 [08/Aug/2018:20:57:32.661628249 -0400] conn=Internal(2) op=57(5) RESULT err=0 tag=48 nentries=0 etime=0.0026172211 [08/Aug/2018:20:57:32.668906829 -0400] conn=Internal(2) op=57(6) SRCH base="dc=example,dc=com" scope=2 filter="(owner=uid=zzzzz,dc=example,dc=com)" attrs="owner" [08/Aug/2018:20:57:32.669099084 -0400] conn=Internal(2) op=57(6) RESULT err=0 tag=48 nentries=0 etime=0.1994932407 [08/Aug/2018:20:57:32.673976008 -0400] conn=Internal(2) op=57(7) SRCH base="dc=example,dc=com" scope=2 filter="(seeAlso=uid=zzzzz,dc=example,dc=com)" attrs="seeAlso" [08/Aug/2018:20:57:32.674139924 -0400] conn=Internal(2) op=57(7) RESULT err=0 tag=48 nentries=0 etime=0.0005018344 [08/Aug/2018:20:57:32.679242542 -0400] conn=Internal(2) op=57(8) SRCH base="o=netscaperoot" scope=2 filter="(member=uid=zzzzz,dc=example,dc=com)" attrs="member" [08/Aug/2018:20:57:32.679385057 -0400] conn=Internal(2) op=57(8) RESULT err=0 tag=48 nentries=0 etime=0.0005225074 [08/Aug/2018:20:57:32.684240991 -0400] conn=Internal(2) op=57(9) SRCH base="o=netscaperoot" scope=2 filter="(uniquemember=uid=zzzzz,dc=example,dc=com)" attrs="uniquemember" [08/Aug/2018:20:57:32.684395748 -0400] conn=Internal(2) op=57(9) RESULT err=0 tag=48 nentries=0 etime=0.0004991839 [08/Aug/2018:20:57:32.689305736 -0400] conn=Internal(2) op=57(10) SRCH base="o=netscaperoot" scope=2 filter="(owner=uid=zzzzz,dc=example,dc=com)" attrs="owner" [08/Aug/2018:20:57:32.689373711 -0400] conn=Internal(2) op=57(10) RESULT err=0 tag=48 nentries=0 etime=0.0004963038 [08/Aug/2018:20:57:32.694235078 -0400] conn=Internal(2) op=57(11) SRCH base="o=netscaperoot" scope=2 filter="(seeAlso=uid=zzzzz,dc=example,dc=com)" attrs="seeAlso" [08/Aug/2018:20:57:32.694464492 -0400] conn=Internal(2) op=57(11) RESULT err=0 tag=48 nentries=0 etime=0.0005075262
I'll be filing a PR shortly...
And I just noticed this problem:
[08/Aug/2018:20:57:32.643740893 -0400] conn=Internal(2) op=57(4) MOD dn="cn=TESTER,dc=example,dc=com" [08/Aug/2018:20:57:32.655572565 -0400] conn=Internal(2) op=57(5) SRCH base="cn=TESTER,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL [08/Aug/2018:20:57:32.655682783 -0400] conn=Internal(2) op=57(5) RESULT err=0 tag=48 nentries=1 etime=0.0011723128 [08/Aug/2018:20:57:32.661628249 -0400] conn=Internal(2) op=57(5) RESULT err=0 tag=48 nentries=0 etime=0.0026172211
These ops have internal op id of 5 (the one is supposed to be 4), investigating...
And I just noticed this problem: [08/Aug/2018:20:57:32.643740893 -0400] conn=Internal(2) op=57(4) MOD dn="cn=TESTER,dc=example,dc=com" [08/Aug/2018:20:57:32.655572565 -0400] conn=Internal(2) op=57(5) SRCH base="cn=TESTER,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL [08/Aug/2018:20:57:32.655682783 -0400] conn=Internal(2) op=57(5) RESULT err=0 tag=48 nentries=1 etime=0.0011723128 [08/Aug/2018:20:57:32.661628249 -0400] conn=Internal(2) op=57(5) RESULT err=0 tag=48 nentries=0 etime=0.0026172211 These ops have internal op id of 5 (the one is supposed to be 4), investigating...
And I just noticed this problem: [08/Aug/2018:20:57:32.643740893 -0400] conn=Internal(2) op=57(4) MOD dn="cn=TESTER,dc=example,dc=com" [08/Aug/2018:20:57:32.655572565 -0400] conn=Internal(2) op=57(5) SRCH base="cn=TESTER,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL [08/Aug/2018:20:57:32.655682783 -0400] conn=Internal(2) op=57(5) RESULT err=0 tag=48 nentries=1 etime=0.0011723128 [08/Aug/2018:20:57:32.661628249 -0400] conn=Internal(2) op=57(5) RESULT err=0 tag=48 nentries=0 etime=0.0026172211
Ugh, this made it more complex than I wanted, but it's working correctly:
https://pagure.io/389-ds-base/pull-request/49895
Please review. Note devel freeze is Monday and this is expected to be in the next build.
Metadata Update from @mreynolds: - Custom field reviewstatus adjusted to review (was: None)
For completeness this is the access log showing the RI plugin removing an entry, and MEP plugin getting called to do a search (conn=Internal(3) op=13(5)) in the middle of it:
[09/Aug/2018:00:49:14.186756480 -0400] conn=3 op=13 DEL dn="uid=dd,dc=example,dc=com" [09/Aug/2018:00:49:14.202184860 -0400] conn=Internal(3) op=13(1) SRCH base="uid=dd,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL [09/Aug/2018:00:49:14.203947657 -0400] conn=Internal(3) op=13(1) RESULT err=0 tag=48 nentries=1 etime=0.0002218665 [09/Aug/2018:00:49:14.248005180 -0400] conn=Internal(3) op=13(2) SRCH base="dc=example,dc=com" scope=2 filter="(member=uid=dd,dc=example,dc=com)" attrs="member" [09/Aug/2018:00:49:14.252756638 -0400] conn=Internal(3) op=13(2) RESULT err=0 tag=48 nentries=0 etime=0.0005104199 [09/Aug/2018:00:49:14.253479791 -0400] conn=Internal(3) op=13(3) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=uid=dd,dc=example,dc=com)" attrs="uniquemember" [09/Aug/2018:00:49:14.256435834 -0400] conn=Internal(3) op=13(3) RESULT err=0 tag=48 nentries=1 etime=0.0003124065 [09/Aug/2018:00:49:14.259183011 -0400] conn=Internal(3) op=13(4) MOD dn="cn=TESTER,dc=example,dc=com" [09/Aug/2018:00:49:14.265634430 -0400] conn=Internal(3) op=13(5) SRCH base="cn=TESTER,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL [09/Aug/2018:00:49:14.266976666 -0400] conn=Internal(3) op=13(5) RESULT err=0 tag=48 nentries=1 etime=0.0002023556 [09/Aug/2018:00:49:14.281974702 -0400] conn=Internal(3) op=13(4) RESULT err=0 tag=48 nentries=0 etime=0.0023903659 [09/Aug/2018:00:49:14.288482292 -0400] conn=Internal(3) op=13(6) SRCH base="dc=example,dc=com" scope=2 filter="(owner=uid=dd,dc=example,dc=com)" attrs="owner" [09/Aug/2018:00:49:14.292931132 -0400] conn=Internal(3) op=13(6) RESULT err=0 tag=48 nentries=0 etime=0.0005271225 [09/Aug/2018:00:49:14.293645239 -0400] conn=Internal(3) op=13(7) SRCH base="dc=example,dc=com" scope=2 filter="(seeAlso=uid=dd,dc=example,dc=com)" attrs="seeAlso" [09/Aug/2018:00:49:14.297945512 -0400] conn=Internal(3) op=13(7) RESULT err=0 tag=48 nentries=0 etime=0.0004579159 [09/Aug/2018:00:49:14.299849955 -0400] conn=Internal(3) op=13(8) SRCH base="o=netscaperoot" scope=2 filter="(member=uid=dd,dc=example,dc=com)" attrs="member" [09/Aug/2018:00:49:14.303916584 -0400] conn=Internal(3) op=13(8) RESULT err=0 tag=48 nentries=0 etime=0.0004899536 [09/Aug/2018:00:49:14.304512791 -0400] conn=Internal(3) op=13(9) SRCH base="o=netscaperoot" scope=2 filter="(uniquemember=uid=dd,dc=example,dc=com)" attrs="uniquemember" [09/Aug/2018:00:49:14.307271160 -0400] conn=Internal(3) op=13(9) RESULT err=0 tag=48 nentries=0 etime=0.0003010558 [09/Aug/2018:00:49:14.307872094 -0400] conn=Internal(3) op=13(10) SRCH base="o=netscaperoot" scope=2 filter="(owner=uid=dd,dc=example,dc=com)" attrs="owner" [09/Aug/2018:00:49:14.309913992 -0400] conn=Internal(3) op=13(10) RESULT err=0 tag=48 nentries=0 etime=0.0002315302 [09/Aug/2018:00:49:14.310434137 -0400] conn=Internal(3) op=13(11) SRCH base="o=netscaperoot" scope=2 filter="(seeAlso=uid=dd,dc=example,dc=com)" attrs="seeAlso" [09/Aug/2018:00:49:14.312513099 -0400] conn=Internal(3) op=13(11) RESULT err=0 tag=48 nentries=0 etime=0.0002300869 [09/Aug/2018:00:49:14.324977311 -0400] conn=3 op=13 RESULT err=0 tag=107 nentries=0 etime=0.0144184295
Great work, especially the addition of counters for the internal ops.
Now I have a bit of concern about the logging format, we have real internal operations and internal operations triggered by external ops.
The first type is logged as:
[09/Aug/2018:10:00:17.338833180 +0200] conn=Internal(0) op=0(0) MOD dn="dc=example,dc=com" [09/Aug/2018:10:00:17.399340302 +0200] conn=Internal(0) op=0(0) RESULT err=0 tag=48 nentries=0 etime=0.0060519613
this is just fine, but for the other type we now have something like:
[09/Aug/2018:10:00:14.161315539 +0200] conn=3 op=64 RESULT err=0 tag=120 nentries=0 etime=0.0212800859 [09/Aug/2018:10:00:14.337451411 +0200] conn=3 op=65 EXT oid="2.16.840.1.113730.3.5.5" name="replication-multimaster-extop" [09/Aug/2018:10:00:14.349471049 +0200] conn=Internal(3) op=65(1) MOD dn="dc=example,dc=com" [09/Aug/2018:10:00:14.364397609 +0200] conn=Internal(3) op=65(1) RESULT err=0 tag=48 nentries=0 etime=0.0014946418 [09/Aug/2018:10:00:14.385534999 +0200] conn=3 op=65 RESULT err=0 tag=120 nentries=0 etime=0.0200702411 [09/Aug/2018:10:00:14.583265235 +0200] conn=3 op=66 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop" [09/Aug/2018:10:00:14.647613997 +0200] conn=Internal(3) op=66(1) SRCH base="cn=dc\3Dexample\2Cdc\3Dcom,cn=mapping tree,cn=config" scope=0 filter="objectclass=*" attrs="nsslapd-backend nsslapd-distribution-plugin nsslapd-distribution-funct" [09/Aug/2018:10:00:14.647734524 +0200] conn=Internal(3) op=66(1) RESULT err=0 tag=48 nentries=1 etime=0.0000165786 [09/Aug/2018:10:00:14.647766916 +0200] conn=Internal(3) op=66(2) SRCH base="cn=dc\3Dexample\2Cdc\3Dcom,cn=mapping tree,cn=config" scope=0 filter="objectclass=nsMappingTree" attrs="nsslapd-referral" [09/Aug/2018:10:00:14.647821505 +0200] conn=Internal(3) op=66(2) RESULT err=0 tag=48 nentries=1 etime=0.0000061188 [09/Aug/2018:10:00:14.647839722 +0200] conn=Internal(3) op=66(3) SRCH base="cn=dc\3Dexample\2Cdc\3Dcom,cn=mapping tree,cn=config" scope=0 filter="objectclass=nsMappingTree" attrs="nsslapd-state" [09/Aug/2018:10:00:14.647887314 +0200] conn=Internal(3) op=66(3) RESULT err=0 tag=48 nentries=1 etime=0.0000052207 [09/Aug/2018:10:00:14.659797605 +0200] conn=3 op=66 RESULT err=0 tag=120 nentries=0 etime=0.1737607111
this does not allow to simly grep for conn=3 to get all interanl and externalö ops for this connection and it also logs "conn=Internal(3)", but it is not an internal connection, 3 is a real one
I would prefer soemething like this:
[09/Aug/2018:11:51:51.799499056 +0200] conn=3 op=28 EXT oid="2.16.840.1.113730.3.5.5" name="replication-multimaster-extop" [09/Aug/2018:11:51:51.805995365 +0200] conn=3 (Internal) op=28(1) MOD dn="dc=example,dc=com" [09/Aug/2018:11:51:51.815918713 +0200] conn=3 (Internal) op=28(1) RESULT err=0 tag=48 nentries=0 etime=0.0009947557 [09/Aug/2018:11:51:51.828688077 +0200] conn=3 op=28 RESULT err=0 tag=120 nentries=0 etime=0.0176385905
I have a patch almost ready to reviwew this format
I'm fine changing the format, that's the easy part :-)
but I want to keep the format for the real internals :-) its done
<img alt="0001-ticket-49029-modification-of-logging-format-for-inte.patch" src="/389-ds-base/issue/raw/files/1096ca4b2aae8bec55281882756bf8ae685d77707797f0c306102b9e9c0b2244-0001-ticket-49029-modification-of-logging-format-for-inte.patch" />
based on the patch from the PR
214 @@ -2141,7 +2146,9 @@ log_referral(Operation *op) 215 int32_t op_id; 216 int32_t op_internal_id; 217 get_internal_conn_op(&connid, &op_id, &op_internal_id); 218 - slapi_log_access(LDAP_DEBUG_ARGS, "conn=Internal(%" PRIu64 ") op=%d(%d) REFERRAL\n", 219 + slapi_log_access(LDAP_DEBUG_ARGS, 220 + connid == 0 ? "conn=Internal(%" PRIu64 ") op=%d(%d) REFERRAL\n" : 221 + "conn=%" PRIu64 " (Internal) op=%d(%d) ENTRY\n",
This this is supposed to be REFERRAL twice?
219 + slapi_log_access(LDAP_DEBUG_ARGS, 220 + connid == 0 ? "conn=Internal(%" PRIu64 ") op=%d(%d) REFERRAL\n" : 221 + "conn=%" PRIu64 " (Internal) op=%d(%d) ENTRY\n", This this is supposed to be REFERRAL twice?
219 + slapi_log_access(LDAP_DEBUG_ARGS, 220 + connid == 0 ? "conn=Internal(%" PRIu64 ") op=%d(%d) REFERRAL\n" : 221 + "conn=%" PRIu64 " (Internal) op=%d(%d) ENTRY\n",
yes, copy/pasted and not correctly edited, sorry
There were some other issues I found, you accidentally remove the trailing "%s" for the proxy string in delete.c and modify.c. No problem, added back, and PR has been updated. Going to look into logconv.pl next...
Metadata Update from @mreynolds: - Issue assigned to mreynolds
Metadata Update from @mreynolds: - Issue close_status updated to: fixed - Issue set to the milestone: 1.4.0 (was: 1.3.7.0)
do we need a doc update as well ?
Yes we should, but we never documented it before :-) I'll open a doc bug ;-)
Doc bug:
https://bugzilla.redhat.com/show_bug.cgi?id=1615904
Instance creation with ASan build fails with the following stack trace:
================================================================= ==10224==ERROR: AddressSanitizer: stack-use-after-scope on address 0x7ffd86292bf0 at pc 0x7fd2e8c43132 bp 0x7ffd8628a680 sp 0x7ffd8628a670 READ of size 4 at 0x7ffd86292bf0 thread T0 #0 0x7fd2e8c43131 in slapi_td_internal_op_finish (/usr/lib64/dirsrv/libslapd.so.0+0x23e131) #0 0x7fd2e8bca36e in slapi_seq_internal_callback_pb ??:? #1 0x7fd2e8bcaa76 in slapi_search_internal_callback ??:? #3 0x7fd2e8bcb064 in slapi_search_internal (/usr/lib64/dirsrv/libslapd.so.0+0x1c6064) #2 0x5573e5c2698f in read_root_dse /usr/src/debug/389-ds-base-1.4.0.14-2.1asan.fc29.x86_64/ldap/servers/slapd/rootdse.c:288 #3 0x7fd2e8afc059 in slapi_sdn_common_ancestor ??:? #6 0x7fd2e8b00301 in dse_search (/usr/lib64/dirsrv/libslapd.so.0+0xfb301) #7 0x7fd2e8b943fc in op_shared_search (/usr/lib64/dirsrv/libslapd.so.0+0x18f3fc) #4 0x7fd2e8bca369 in slapi_seq_internal_callback_pb ??:? #5 0x7fd2e8bcaa76 in slapi_search_internal_callback ??:? #10 0x7fd2e8bcb064 in slapi_search_internal (/usr/lib64/dirsrv/libslapd.so.0+0x1c6064) #6 0x7fd2e4d1320d in cos_cache_build_definition_list ldap/servers/plugins/cos/cos_cache.c:636 #12 0x7fd2e4d1546c in cos_cache_getref (/usr/lib64/dirsrv/plugins/libcos-plugin.so+0x1346c) #13 0x7fd2e4d1639f in cos_cache_change_notify (/usr/lib64/dirsrv/plugins/libcos-plugin.so+0x1439f) #14 0x7fd2e4d0a0f1 in cos_post_op (/usr/lib64/dirsrv/plugins/libcos-plugin.so+0x80f1) #7 0x7fd2e8bbd393 in slapi_plugin_op_finished ??:? #16 0x7fd2e8bbd70d in plugin_call_plugins (/usr/lib64/dirsrv/libslapd.so.0+0x1b870d) #8 0x7fd2e8ac637a in ?? ??:0 #9 0x7fd2e8ac7152 in ?? ??:0 #19 0x7fd2e8ac933c in slapi_add_internal_pb (/usr/lib64/dirsrv/libslapd.so.0+0xc433c) #20 0x7fd2e8c3ca4a in slapi_plugin_task_register_handler (/usr/lib64/dirsrv/libslapd.so.0+0x237a4a) #21 0x7fd2e8c3e52f in task_init (/usr/lib64/dirsrv/libslapd.so.0+0x23952f) #10 0x5573e5be488f in main /usr/src/debug/389-ds-base-1.4.0.14-2.1asan.fc29.x86_64/ldap/servers/slapd/main.c:1168 #23 0x7fd2e8305412 in __libc_start_main (/lib64/libc.so.6+0x24412) #11 0x5573e5be6f8d in ?? ??:0 Address 0x7ffd86292bf0 is located in stack of thread T0 at offset 32 in frame #0 0x5573e5be10bf in main /usr/src/debug/389-ds-base-1.4.0.14-2.1asan.fc29.x86_64/ldap/servers/slapd/main.c:638 This frame has 31 object(s): [32, 36) 'init_val' <== Memory access at offset 32 is inside this variable [96, 100) 'task_flags' [160, 164) 'task_flags' [224, 228) 'is_running' [288, 292) 'task_flags' [352, 356) 'task_flags' [416, 420) 'task_flags' [480, 484) 'task_flags' [544, 548) 'seq_type' [608, 612) 'task_flags' [672, 676) 'task_flags' [736, 744) 'tp' [800, 808) 'endp' [864, 872) 'listenhost' [928, 936) 'securelistenhost' [992, 1000) 'rundir' [1056, 1064) 'versionstring' [1120, 1128) 'buildnum' [1184, 1192) 'sdn' [1248, 1256) 'msg' [1312, 1320) 'instances' [1376, 1384) 'my_ldiffile' [1440, 1448) 'instances' [1504, 1512) 'plugin_list' [1568, 1576) 'instances' [1632, 1640) 'instances' [1696, 1704) 'suffixes' [1760, 1824) 'ports_info' [1856, 1944) 'tp_config' [1984, 2160) 'mcfg' [2208, 2720) 'errorbuf' HINT: this may be a false positive if your program uses some custom stack unwind mechanism or swapcontext (longjmp and C++ exceptions *are* supported) SUMMARY: AddressSanitizer: stack-use-after-scope (/usr/lib64/dirsrv/libslapd.so.0+0x23e131) in slapi_td_internal_op_finish Shadow bytes around the buggy address: 0x100030c4a520: f2 f2 f2 f2 f2 f2 00 f2 f2 f2 f2 f2 f2 f2 00 f2 0x100030c4a530: f2 f2 f2 f2 f2 f2 00 00 f2 f2 f2 f2 f2 f2 00 00 0x100030c4a540: 00 f2 f2 f2 f2 f2 00 00 00 f2 f2 f2 f2 f2 00 00 0x100030c4a550: 00 00 00 00 00 00 00 f2 f2 f2 00 00 00 00 00 00 0x100030c4a560: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 =>0x100030c4a570: 00 00 00 00 00 00 00 00 00 00 f1 f1 f1 f1[f8]f2 0x100030c4a580: f2 f2 f2 f2 f2 f2 04 f2 f2 f2 f2 f2 f2 f2 04 f2 0x100030c4a590: f2 f2 f2 f2 f2 f2 04 f2 f2 f2 f2 f2 f2 f2 04 f2 0x100030c4a5a0: f2 f2 f2 f2 f2 f2 04 f2 f2 f2 f2 f2 f2 f2 04 f2 0x100030c4a5b0: f2 f2 f2 f2 f2 f2 04 f2 f2 f2 f2 f2 f2 f2 04 f2 0x100030c4a5c0: f2 f2 f2 f2 f2 f2 04 f2 f2 f2 f2 f2 f2 f2 04 f2 Shadow byte legend (one shadow byte represents 8 application bytes): Addressable: 00 Partially addressable: 01 02 03 04 05 06 07 Heap left redzone: fa Freed heap region: fd Stack left redzone: f1 Stack mid redzone: f2 Stack right redzone: f3 Stack after return: f5 Stack use after scope: f8 Global redzone: f9 Global init order: f6 Poisoned by user: f7 Container overflow: fc Array cookie: ac Intra object redzone: bb ASan internal: fe Left alloca redzone: ca Right alloca redzone: cb ==10224==ABORTING
Edit: replaced the output with symbolized output.
I need to allocate the integer pointers that are used for the id's, flags, etc. Valgrind did not complain about this, so I guess it's time to finally start drinking the ASAN kool-aid :-)
@mreynolds It's delicious. To put it simply, it improved the quality of code I was putting out, has stopped tiny-niggle issues coming out of my machine, and just makes us all more confident in out work.
Get drinking!
@mreynolds It's delicious. To put it simply, it improved the quality of code I was putting out, has stopped tiny-niggle issues coming out of my machine, and just makes us all more confident in out work. Get drinking!
:beers:
To fix the integer allocation and hopefully the freeipa crash:
https://pagure.io/389-ds-base/pull-request/49910
Fixed upstream
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/2088
If you want to receive further updates on the issue, please navigate to the github issue and click on subscribe button.
subscribe
Thank you for understanding. We apologize for all inconvenience.
Metadata Update from @spichugi: - Issue close_status updated to: wontfix (was: fixed)
Login to comment on this ticket.