389-ds-base

Clone
Source Code
GIT

#49029 [RFE] improve internal operations logging
Closed: fixed a year ago Opened 3 years ago by mreynolds.

Closed: fixed
Reopen Issue

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

Metadata Update from @lkrispen:
- Issue set to the milestone: 1.3.6.0
2 years ago

Metadata Update from @mreynolds:
- Issue close_status updated to: None
- Issue set to the milestone: 1.3.7.0 (was: 1.3.6.0)
2 years ago

Metadata Update from @mreynolds:
- Custom field reviewstatus adjusted to None
- Custom field version adjusted to None
- Issue tagged with: RFE
2 years ago

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...

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)
a year ago

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
Edited a year ago by lkrispen

I'm fine changing the format, that's the easy part :-)

I'm fine changing the format, that's the easy part :-)

but I want to keep the format for the real internals :-) its done

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?

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
a year ago

Metadata Update from @mreynolds:
- Issue close_status updated to: fixed
- Issue set to the milestone: 1.4.0 (was: 1.3.7.0)
a year ago

do we need a doc update as well ?

do we need a doc update as well ?

Yes we should, but we never documented it before :-) I'll open a doc bug ;-)

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.

Edited a year ago by vashirov

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

Login to comment on this ticket.

Metadata

RFE

None
None
major
review
Community
Attachments 1
0001-ticket-49029-modification-of-logging-format-f...
Attached a year ago View Comment
Powered by Pagure 5.8.1
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© 2014-2019 Red Hat, Inc. and others.