#49995 Internal operation logging connection id can get corrupted
Closed: wontfix 5 years ago Opened 5 years ago by mreynolds.

Issue Description

Just enable internal logging in the access log and restart the server to see this behaviour The server's own internal operations Conn & Op ID get corrupted. The op count also stops incrementing

[26/Oct/2018:09:22:57.813333175 -0400] conn=2 (Internal) op=6(1) SRCH base="cn=config" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[26/Oct/2018:09:22:57.822230811 -0400] conn=2 (Internal) op=6(1) RESULT err=0 tag=48 nentries=1 etime=0.0008962387
...
...
[26/Oct/2018:09:23:21.188889915 -0400] conn=21638144 (Internal) op=256(2) SRCH base="cn=mapping tree,cn=config" scope=1 filter="(&(objectclass=nsMappingTree)(!(nsslapd-parent-suffix=*)))" attrs=ALL
[26/Oct/2018:09:23:21.189094520 -0400] conn=21668480 (Internal) op=256(2) RESULT err=0 tag=48 nentries=2 etime=0.0000223559
[26/Oct/2018:09:23:21.189124575 -0400] conn=21671440 (Internal) op=256(2) SRCH base="cn=mapping tree,cn=config" scope=1 filter="(&(objectclass=nsMappingTree)(|(nsslapd-parent-suffix="o=netscaperoot")(nsslapd-parent-suffix=o=netscaperoot)))" attrs=ALL

Metadata Update from @mreynolds:
- Custom field component adjusted to None
- Custom field origin adjusted to None
- Custom field reviewstatus adjusted to None
- Custom field type adjusted to None
- Custom field version adjusted to None

5 years ago

Metadata Update from @mreynolds:
- Issue assigned to mreynolds

5 years ago

Looks like this feature is actually quite broken since the local thread storage code was "cleaned up" via 49941. Continuing investigation...

It's not as bad as I thought. Looks like at startup the internal operations the server does are happening without the conn id and op id (internal op count) being set. So they are random values:

<starting up, this is the first logging line>

[26/Oct/2018:10:07:43.362667115 -0400] conn=21730488 (Internal) op=256(2) SRCH base="cn=mapping tree,cn=config" scope=1 filter="(&(objectclass=nsMappingTree)(!(nsslapd-parent-suffix=*)))" attrs=ALL
[26/Oct/2018:10:07:43.371287558 -0400] conn=21760888 (Internal) op=256(2) RESULT err=0 tag=48 nentries=2 etime=0.0008635295
[26/Oct/2018:10:07:43.373724757 -0400] conn=21763848 (Internal) op=256(3) SRCH base="cn=mapping tree,cn=config" scope=1 filter="(&(objectclass=nsMappingTree)(|(nsslapd-parent-suffix="o=netscaperoot")(nsslapd-parent-suffix=o=netscaperoot)))" attrs=ALL
[26/Oct/2018:10:07:43.376246024 -0400] conn=21785912 (Internal) op=256(3) RESULT err=0 tag=48 nentries=0 etime=0.0002534106
[26/Oct/2018:10:07:43.378614848 -0400] conn=21788960 (Internal) op=256(4) SRCH base="cn=mapping tree,cn=config" scope=1 filter="(&(objectclass=nsMappingTree)(|(nsslapd-parent-suffix="dc=example,dc=com")(nsslapd-parent-suffix=dc=example,dc=com)))" attrs=ALL
[26/Oct/2018:10:07:43.381252810 -0400] conn=21811024 (Internal) op=256(4) RESULT err=0 tag=48 nentries=0 etime=0.0002648307
[26/Oct/2018:10:07:43.383592960 -0400] conn=21814640 (Internal) op=256(5) ADD dn=""
[26/Oct/2018:10:07:43.386030423 -0400] conn=21820896 (Internal) op=256(5) RESULT err=68 tag=48 nentries=0 etime=0.0002446090
[26/Oct/2018:10:07:43.388421144 -0400] conn=21824328 (Internal) op=256(6) ADD dn="oid=2.16.840.1.113730.3.4.9,cn=features,cn=config"
[26/Oct/2018:10:07:43.390900129 -0400] conn=21833488 (Internal) op=256(6) RESULT err=68 tag=48 nentries=0 etime=0.0002487905
[26/Oct/2018:10:07:43.393364769 -0400] conn=21836320 (Internal) op=256(7) ADD dn="oid=2.16.840.1.113730.3.5.7,cn=features,cn=config"
[26/Oct/2018:10:07:43.395746144 -0400] conn=21845288 (Internal) op=256(7) RESULT err=68 tag=48 nentries=0 etime=0.0002389264
[26/Oct/2018:10:07:43.398184999 -0400] conn=21847712 (Internal) op=256(8) ADD dn="cn=options,cn=features,cn=config"

https://pagure.io/389-ds-base/pull-request/49996

Example of new logging (with added nesting level)

[26/Oct/2018:15:16:00.327125046 -0400] conn=2 op=11 MOD dn="cn=group,dc=example,dc=com"
[26/Oct/2018:15:16:00.339311572 -0400] conn=2 (Internal) op=11(1)(1) SRCH base="cn=group,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[26/Oct/2018:15:16:00.345373360 -0400] conn=2 (Internal) op=11(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0006122703
[26/Oct/2018:15:16:00.348355417 -0400] conn=2 (Internal) op=11(2)(1) SRCH base="cn=group,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[26/Oct/2018:15:16:00.354388180 -0400] conn=2 (Internal) op=11(2)(1) RESULT err=0 tag=48 nentries=1 etime=0.0006067696
[26/Oct/2018:15:16:00.361683625 -0400] conn=2 (Internal) op=11(3)(1) SRCH base="uid=mreynolds,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="uniquemember"
[26/Oct/2018:15:16:00.368099305 -0400] conn=2 (Internal) op=11(3)(1) RESULT err=0 tag=48 nentries=1 etime=0.0006458572
[26/Oct/2018:15:16:00.370868571 -0400] conn=2 (Internal) op=11(4)(1) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=uid=mreynolds,dc=example,dc=com)" attrs=ALL
[26/Oct/2018:15:16:00.373756050 -0400] conn=2 (Internal) op=11(4)(2) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=cn=group,dc=example,dc=com)" attrs=ALL
[26/Oct/2018:15:16:00.376501472 -0400] conn=2 (Internal) op=11(4)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002767202
[26/Oct/2018:15:16:00.379086446 -0400] conn=2 (Internal) op=11(4)(1) RESULT err=0 tag=48 nentries=1 etime=0.0008405816
[26/Oct/2018:15:16:00.381822284 -0400] conn=2 (Internal) op=11(5)(1) MOD dn="uid=mreynolds,dc=example,dc=com"
[26/Oct/2018:15:16:00.384744820 -0400] conn=2 (Internal) op=11(5)(2) SRCH base="uid=mreynolds,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[26/Oct/2018:15:16:00.387374272 -0400] conn=2 (Internal) op=11(5)(2) RESULT err=0 tag=48 nentries=1 etime=0.0002652571
[26/Oct/2018:15:16:00.391259149 -0400] conn=2 (Internal) op=11(5)(1) RESULT err=0 tag=48 nentries=0 etime=0.0009456253 pr_idx=0 pr_cookie=0 
[26/Oct/2018:15:16:00.397613995 -0400] conn=2 op=11 RESULT err=0 tag=103 nentries=0 etime=0.0070811682



[26/Oct/2018:15:16:54.795787969 -0400] conn=2 op=15 DEL dn="uid=mreynolds,dc=example,dc=com"
[26/Oct/2018:15:16:54.798707351 -0400] conn=2 (Internal) op=15(1)(1) SRCH base="uid=mreynolds,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[26/Oct/2018:15:16:54.801632753 -0400] conn=2 (Internal) op=15(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0002976284
[26/Oct/2018:15:16:54.815894621 -0400] conn=2 (Internal) op=15(2)(1) MOD dn="cn=group,dc=example,dc=com"
[26/Oct/2018:15:16:54.818652476 -0400] conn=2 (Internal) op=15(2)(2) SRCH base="cn=group,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[26/Oct/2018:15:16:54.821194976 -0400] conn=2 (Internal) op=15(2)(2) RESULT err=0 tag=48 nentries=1 etime=0.0002570200
[26/Oct/2018:15:16:54.826052349 -0400] conn=2 (Internal) op=15(2)(2) SRCH base="uid=mreynolds,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="uniquemember"
[26/Oct/2018:15:16:54.828700892 -0400] conn=2 (Internal) op=15(2)(2) RESULT err=32 tag=48 nentries=0 etime=0.0002709035
[26/Oct/2018:15:16:54.831223477 -0400] conn=2 (Internal) op=15(2)(2) SRCH base="dc=example,dc=com" scope=2 filter="(memberOf=uid=mreynolds,dc=example,dc=com)" attrs=ALL
[26/Oct/2018:15:16:54.833740058 -0400] conn=2 (Internal) op=15(2)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002532687
[26/Oct/2018:15:16:54.837021267 -0400] conn=2 (Internal) op=15(2)(1) RESULT err=0 tag=48 nentries=0 etime=0.0021152815
[26/Oct/2018:15:16:54.842157226 -0400] conn=2 (Internal) op=15(3)(1) SRCH base="dc=example,dc=com" scope=2 filter="(owner=uid=mreynolds,dc=example,dc=com)" attrs="owner"
[26/Oct/2018:15:16:54.845005986 -0400] conn=2 (Internal) op=15(3)(1) RESULT err=0 tag=48 nentries=0 etime=0.0002897103
[26/Oct/2018:15:16:54.847488905 -0400] conn=2 (Internal) op=15(4)(1) SRCH base="dc=example,dc=com" scope=2 filter="(seeAlso=uid=mreynolds,dc=example,dc=com)" attrs="seeAlso"
[26/Oct/2018:15:16:54.850111031 -0400] conn=2 (Internal) op=15(4)(1) RESULT err=0 tag=48 nentries=0 etime=0.0002635809
[26/Oct/2018:15:16:54.880137443 -0400] conn=2 op=15 RESULT err=0 tag=107 nentries=0 etime=0.0084534436

Metadata Update from @mreynolds:
- Custom field reviewstatus adjusted to review (was: None)

5 years ago

Thanks Mark for working on this. Few questions -
1. Is this the new format - conn=ORIGNAL CONN ID (Internal) op=ORIGINAL_OP_ID(INTERNAL OP COUNT)(level) ?

[26/Oct/2018:15:16:00.327125046 -0400] conn=2 op=11 MOD dn="cn=group,dc=example,dc=com"
[26/Oct/2018:15:16:00.339311572 -0400] conn=2 (Internal) op=11(1)(1) SRCH base="cn=group,dc=example,dc=com" scope=0 filter="(|(objectclass=)(objectclass=ldapsubentry))" attrs=ALL
[26/Oct/2018:15:16:00.345373360 -0400] conn=2 (Internal) op=11(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0006122703
[26/Oct/2018:15:16:00.348355417 -0400] conn=2 (Internal) op=11(2)(1) SRCH base="cn=group,dc=example,dc=com" scope=0 filter="(|(objectclass=
)(objectclass=ldapsubentry))" attrs=ALL
2. WHy this same operation got executed twice?

[26/Oct/2018:15:16:00.354388180 -0400] conn=2 (Internal) op=11(2)(1) RESULT err=0 tag=48 nentries=1 etime=0.0006067696
[26/Oct/2018:15:16:00.361683625 -0400] conn=2 (Internal) op=11(3)(1) SRCH base="uid=mreynolds,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="uniquemember"
[26/Oct/2018:15:16:00.368099305 -0400] conn=2 (Internal) op=11(3)(1) RESULT err=0 tag=48 nentries=1 etime=0.0006458572
[26/Oct/2018:15:16:00.370868571 -0400] conn=2 (Internal) op=11(4)(1) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=uid=mreynolds,dc=example,dc=com)" attrs=ALL
[26/Oct/2018:15:16:00.373756050 -0400] conn=2 (Internal) op=11(4)(2) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=cn=group,dc=example,dc=com)" attrs=ALL
[26/Oct/2018:15:16:00.376501472 -0400] conn=2 (Internal) op=11(4)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002767202
3. SO this is level2 operation initiated by "conn=2 (Internal) op=11(4)(1)" ? and it is the nested operation here?

[26/Oct/2018:15:16:00.379086446 -0400] conn=2 (Internal) op=11(4)(1) RESULT err=0 tag=48 nentries=1 etime=0.0008405816
[26/Oct/2018:15:16:00.381822284 -0400] conn=2 (Internal) op=11(5)(1) MOD dn="uid=mreynolds,dc=example,dc=com"
[26/Oct/2018:15:16:00.384744820 -0400] conn=2 (Internal) op=11(5)(2) SRCH base="uid=mreynolds,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
4. Again this is nested internal operation at level2 initiated by modify internal operation?

[26/Oct/2018:15:16:00.387374272 -0400] conn=2 (Internal) op=11(5)(2) RESULT err=0 tag=48 nentries=1 etime=0.0002652571
[26/Oct/2018:15:16:00.391259149 -0400] conn=2 (Internal) op=11(5)(1) RESULT err=0 tag=48 nentries=0 etime=0.0009456253 pr_idx=0 pr_cookie=0
[26/Oct/2018:15:16:00.397613995 -0400] conn=2 op=11 RESULT err=0 tag=103 nentries=0 etime=0.0070811682

Also here -
[26/Oct/2018:15:16:54.815894621 -0400] conn=2 (Internal) op=15(2)(1) MOD dn="cn=group,dc=example,dc=com"
[26/Oct/2018:15:16:54.818652476 -0400] conn=2 (Internal) op=15(2)(2) SRCH base="cn=group,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[26/Oct/2018:15:16:54.821194976 -0400] conn=2 (Internal) op=15(2)(2) RESULT err=0 tag=48 nentries=1 etime=0.0002570200
[26/Oct/2018:15:16:54.826052349 -0400] conn=2 (Internal) op=15(2)(2) MOD base="uid=mreynolds,dc=example,dc=com"

Search and modify are two different internal operation but we are neither increasing count of the internal operation nor level?

Thanks Mark for working on this. Few questions -
1. Is this the new format - conn=ORIGNAL CONN ID (Internal) op=ORIGINAL_OP_ID(INTERNAL OP COUNT)(level) ?

Correct

  1. Why this same operation got executed twice?

Sorry the example was "constructed" I was just trying to show what it would look like.

  1. SO this is level2 operation initiated by "conn=2 (Internal) op=11(4)(1)" ? and it is the nested operation here?

Correct. op=11(4) triggered another plugin to be called which performed a operation, which means its nested so the nesting level increased.

  1. Again this is nested internal operation at level2 initiated by modify internal operation?

So another way to look at this is that each nesting levels lists its operations sequentially. Once we get nested we can no longer use a counter because its impossible to maintain a "correct" operation counter once we get nested/nested. But we don't need a counter - we are just trying to match operations to their result.

[26/Oct/2018:15:16:54.815894621 -0400] conn=2 (Internal) op=15(2)(1) MOD dn="cn=group,dc=example,dc=com"

-->  This mod triggers another plugin which does 3 searches.  These are all nesting level 2 operations.  If one of those search operation triggered another plugin then those "nested nested" operations would be nesting level 3 and so on.

[26/Oct/2018:15:16:54.818652476 -0400] conn=2 (Internal) op=15(2)(2) SRCH base="cn=group,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[26/Oct/2018:15:16:54.821194976 -0400] conn=2 (Internal) op=15(2)(2) RESULT err=0 tag=48 nentries=1 etime=0.0002570200
[26/Oct/2018:15:16:54.826052349 -0400] conn=2 (Internal) op=15(2)(2) SRCH base="uid=mreynolds,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="uniquemember"
[26/Oct/2018:15:16:54.828700892 -0400] conn=2 (Internal) op=15(2)(2) RESULT err=32 tag=48 nentries=0 etime=0.0002709035
[26/Oct/2018:15:16:54.831223477 -0400] conn=2 (Internal) op=15(2)(2) SRCH base="dc=example,dc=com" scope=2 filter="(memberOf=uid=mreynolds,dc=example,dc=com)" attrs=ALL
[26/Oct/2018:15:16:54.833740058 -0400] conn=2 (Internal) op=15(2)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002532687

^^^ The result of the third (last) search from that plugin.  Now we are back to nested level 1 below:

[26/Oct/2018:15:16:54.837021267 -0400] conn=2 (Internal) op=15(2)(1) RESULT err=0 tag=48 nentries=0 etime=0.0021152815

Then your last comment:

[26/Oct/2018:15:16:54.815894621 -0400] conn=2 (Internal) op=15(2)(1) MOD dn="cn=group,dc=example,dc=com"
[26/Oct/2018:15:16:54.818652476 -0400] conn=2 (Internal) op=15(2)(2) SRCH base="cn=group,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[26/Oct/2018:15:16:54.821194976 -0400] conn=2 (Internal) op=15(2)(2) RESULT err=0 tag=48 nentries=1 etime=0.0002570200
[26/Oct/2018:15:16:54.826052349 -0400] conn=2 (Internal) op=15(2)(2) MOD base="uid=mreynolds,dc=example,dc=com"

Search and modify are two different internal operation but we are neither increasing count of the internal operation nor level?

The third number is the nesting level (2) - this does not increase unless we goto a new nesting level. All the operations on nesting level 2 use the same identifiers, but they are sequential so can just follow them normally - the result will always follow the operation (unless that operation triggers another plugin and a new nesting level).

So we use the nesting level to keep track of things. Everything in the same nesting level is correctly sequential. So matching the result to the operation is easy. Remember the point of all of this is so we can match internal operations to their results.

Anyway I'm going to work on a new example were many plugins get called in a nested fashion.

Perhaps it would be clearer if I changed the format to this?

conn=2 (Internal) op=15(2)(level: 2)

or

conn=2 (Internal) op=15(2)(nested: 2)

I was not able to get 3 levels deep in nested operations, but is areal example. I first setup automember plugin to add users to "cn=autogroup,ou=groups,dc=example,dc=com". Then I setup MEP plugin to created managed entries under ou=groups,dc=example,dc=com, and finally I also setup RI plugin. Here is the resulting logging when I delete "uid=mark". I will break down each section of the logging next:

[30/Oct/2018:10:58:29.283327032 -0400] conn=3 op=66 DEL dn="uid=mark,ou=People,dc=example,dc=com"
[30/Oct/2018:10:58:29.286261556 -0400] conn=3 (Internal) op=66(1)(1) SRCH base="uid=mark,ou=People,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[30/Oct/2018:10:58:29.289013868 -0400] conn=3 (Internal) op=66(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0002773781
[30/Oct/2018:10:58:29.292636465 -0400] conn=3 (Internal) op=66(2)(1) SRCH base="dc=example,dc=com" scope=2 filter="(member=uid=mark,ou=People,dc=example,dc=com)" attrs="member"
[30/Oct/2018:10:58:29.295540964 -0400] conn=3 (Internal) op=66(2)(1) RESULT err=0 tag=48 nentries=1 etime=0.0002917562
[30/Oct/2018:10:58:29.298895827 -0400] conn=3 (Internal) op=66(3)(1) MOD dn="cn=autogroup,ou=Groups,dc=example,dc=com"
[30/Oct/2018:10:58:29.301951990 -0400] conn=3 (Internal) op=66(3)(2) SRCH base="cn=autogroup,ou=Groups,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[30/Oct/2018:10:58:29.305670431 -0400] conn=3 (Internal) op=66(3)(2) RESULT err=0 tag=48 nentries=1 etime=0.0003743947
[30/Oct/2018:10:58:29.309164255 -0400] conn=3 (Internal) op=66(3)(1) RESULT err=0 tag=48 nentries=0 etime=0.0010333278
[30/Oct/2018:10:58:29.314195789 -0400] conn=3 (Internal) op=66(4)(1) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=uid=mark,ou=People,dc=example,dc=com)" attrs="uniquemember"
[30/Oct/2018:10:58:29.316765619 -0400] conn=3 (Internal) op=66(4)(1) RESULT err=0 tag=48 nentries=1 etime=0.0002586319
[30/Oct/2018:10:58:29.319295746 -0400] conn=3 (Internal) op=66(5)(1) MOD dn="cn=group,dc=example,dc=com"

This modify operation above it triggering a plugin which does three searches.  This is nested because it is inside of this MOD operation:  op=66(5)(1) MOD

[30/Oct/2018:10:58:29.321899777 -0400] conn=3 (Internal) op=66(5)(2) SRCH base="cn=group,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[30/Oct/2018:10:58:29.324361927 -0400] conn=3 (Internal) op=66(5)(2) RESULT err=0 tag=48 nentries=1 etime=0.0002472293
[30/Oct/2018:10:58:29.327113918 -0400] conn=3 (Internal) op=66(5)(2) SRCH base="uid=mark,ou=People,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="uniquemember"
[30/Oct/2018:10:58:29.329935563 -0400] conn=3 (Internal) op=66(5)(2) RESULT err=32 tag=48 nentries=0 etime=0.0002840753
[30/Oct/2018:10:58:29.333805947 -0400] conn=3 (Internal) op=66(5)(2) SRCH base="dc=example,dc=com" scope=2 filter="(memberOf=uid=mark,ou=people,dc=example,dc=com)" attrs=ALL
[30/Oct/2018:10:58:29.336442707 -0400] conn=3 (Internal) op=66(5)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002656295
[30/Oct/2018:10:58:29.339708235 -0400] conn=3 (Internal) op=66(5)(1) RESULT err=0 tag=48 nentries=0 etime=0.0020427749

^^^ Now the MOD op has finished:  op=66(5)(1) 

Next we see a bunch of operations the MEP plugin is doing...

[30/Oct/2018:10:58:29.344670322 -0400] conn=3 (Internal) op=66(6)(1) SRCH base="dc=example,dc=com" scope=2 filter="(owner=uid=mark,ou=People,dc=example,dc=com)" attrs="owner"
[30/Oct/2018:10:58:29.347160872 -0400] conn=3 (Internal) op=66(6)(1) RESULT err=0 tag=48 nentries=0 etime=0.0002507431
[30/Oct/2018:10:58:29.349571965 -0400] conn=3 (Internal) op=66(7)(1) SRCH base="dc=example,dc=com" scope=2 filter="(seeAlso=uid=mark,ou=People,dc=example,dc=com)" attrs="seeAlso"
[30/Oct/2018:10:58:29.352045668 -0400] conn=3 (Internal) op=66(7)(1) RESULT err=0 tag=48 nentries=0 etime=0.0002495150
[30/Oct/2018:10:58:29.354608984 -0400] conn=3 (Internal) op=66(8)(1) SRCH base="o=netscaperoot" scope=2 filter="(member=uid=mark,ou=People,dc=example,dc=com)" attrs="member"
[30/Oct/2018:10:58:29.357202505 -0400] conn=3 (Internal) op=66(8)(1) RESULT err=0 tag=48 nentries=0 etime=0.0002611295
[30/Oct/2018:10:58:29.359616851 -0400] conn=3 (Internal) op=66(9)(1) SRCH base="o=netscaperoot" scope=2 filter="(uniquemember=uid=mark,ou=People,dc=example,dc=com)" attrs="uniquemember"
[30/Oct/2018:10:58:29.362091585 -0400] conn=3 (Internal) op=66(9)(1) RESULT err=0 tag=48 nentries=0 etime=0.0002488057
[30/Oct/2018:10:58:29.364447126 -0400] conn=3 (Internal) op=66(10)(1) SRCH base="o=netscaperoot" scope=2 filter="(owner=uid=mark,ou=People,dc=example,dc=com)" attrs="owner"
[30/Oct/2018:10:58:29.367105114 -0400] conn=3 (Internal) op=66(10)(1) RESULT err=0 tag=48 nentries=0 etime=0.0002671884
[30/Oct/2018:10:58:29.369691618 -0400] conn=3 (Internal) op=66(11)(1) SRCH base="o=netscaperoot" scope=2 filter="(seeAlso=uid=mark,ou=People,dc=example,dc=com)" attrs="seeAlso"
[30/Oct/2018:10:58:29.372359380 -0400] conn=3 (Internal) op=66(11)(1) RESULT err=0 tag=48 nentries=0 etime=0.0002685501

Next we delete the MEP entry, in turn triggers the RI plugin to do a bunch of searches (nested)

[30/Oct/2018:10:58:29.374844622 -0400] conn=3 (Internal) op=66(12)(1) DEL dn="cn=mark,ou=groups,dc=example,dc=com"
[30/Oct/2018:10:58:29.377513053 -0400] conn=3 (Internal) op=66(12)(2) SRCH base="dc=example,dc=com" scope=2 filter="(member=cn=mark,ou=groups,dc=example,dc=com)" attrs="member"
[30/Oct/2018:10:58:29.379934239 -0400] conn=3 (Internal) op=66(12)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002427148
[30/Oct/2018:10:58:29.382482246 -0400] conn=3 (Internal) op=66(12)(2) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=cn=mark,ou=groups,dc=example,dc=com)" attrs="uniquemember"
[30/Oct/2018:10:58:29.385143391 -0400] conn=3 (Internal) op=66(12)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002681538
[30/Oct/2018:10:58:29.387575771 -0400] conn=3 (Internal) op=66(12)(2) SRCH base="dc=example,dc=com" scope=2 filter="(owner=cn=mark,ou=groups,dc=example,dc=com)" attrs="owner"
[30/Oct/2018:10:58:29.389975292 -0400] conn=3 (Internal) op=66(12)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002408779
[30/Oct/2018:10:58:29.392548795 -0400] conn=3 (Internal) op=66(12)(2) SRCH base="dc=example,dc=com" scope=2 filter="(seeAlso=cn=mark,ou=groups,dc=example,dc=com)" attrs="seeAlso"
[30/Oct/2018:10:58:29.394987008 -0400] conn=3 (Internal) op=66(12)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002446992
[30/Oct/2018:10:58:29.397419953 -0400] conn=3 (Internal) op=66(12)(2) SRCH base="o=netscaperoot" scope=2 filter="(member=cn=mark,ou=groups,dc=example,dc=com)" attrs="member"
[30/Oct/2018:10:58:29.400053064 -0400] conn=3 (Internal) op=66(12)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002648656
[30/Oct/2018:10:58:29.402628096 -0400] conn=3 (Internal) op=66(12)(2) SRCH base="o=netscaperoot" scope=2 filter="(uniquemember=cn=mark,ou=groups,dc=example,dc=com)" attrs="uniquemember"
[30/Oct/2018:10:58:29.405297607 -0400] conn=3 (Internal) op=66(12)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002683618
[30/Oct/2018:10:58:29.407645428 -0400] conn=3 (Internal) op=66(12)(2) SRCH base="o=netscaperoot" scope=2 filter="(owner=cn=mark,ou=groups,dc=example,dc=com)" attrs="owner"
[30/Oct/2018:10:58:29.410074865 -0400] conn=3 (Internal) op=66(12)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002442397
[30/Oct/2018:10:58:29.412449867 -0400] conn=3 (Internal) op=66(12)(2) SRCH base="o=netscaperoot" scope=2 filter="(seeAlso=cn=mark,ou=groups,dc=example,dc=com)" attrs="seeAlso"
[30/Oct/2018:10:58:29.414949139 -0400] conn=3 (Internal) op=66(12)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002505068
[30/Oct/2018:10:58:29.417477149 -0400] conn=3 (Internal) op=66(12)(2) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=cn=mark,ou=groups,dc=example,dc=com)" attrs=ALL
[30/Oct/2018:10:58:29.419890225 -0400] conn=3 (Internal) op=66(12)(2) RESULT err=0 tag=48 nentries=0 etime=0.0002423475

^^^ RI plugin is now done

[30/Oct/2018:10:58:29.422987651 -0400] conn=3 (Internal) op=66(12)(1) RESULT err=0 tag=48 nentries=0 etime=0.0048154005

^^^ Delete of MEP entry is now finished

[30/Oct/2018:10:58:29.428036898 -0400] conn=3 (Internal) op=66(13)(1) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=uid=mark,ou=People,dc=example,dc=com)" attrs=ALL
[30/Oct/2018:10:58:29.430652255 -0400] conn=3 (Internal) op=66(13)(1) RESULT err=0 tag=48 nentries=0 etime=0.0002623869
[30/Oct/2018:10:58:29.433911647 -0400] conn=3 op=66 RESULT err=0 tag=107 nentries=0 etime=0.0150715462 

^^^ Delete of uid=mark is now done

So we see that 3 times we got into nested level 2 state. I was hoping it would trigger 3 levels but it didn't happen, but it other scenarios with more plugins it could potentially go deeper.

Here is a very simple example.

  • Enable memberOf plugin
  • Create group
  • Create user (add extensibleObject objectclass for simplifying testcase)
  • Add user to group

Below we see the memberOf plugin doing some searches and the one search triggers a nested search (via a callback function), then MemberOf Plugin adds "memberOf" attribute to user "uid=dave"

[30/Oct/2018:11:24:32.733031048 -0400] conn=2 op=30 MOD dn="cn=group,dc=example,dc=com"
[30/Oct/2018:11:24:32.741632059 -0400] conn=2 (Internal) op=30(1)(1) SRCH base="cn=group,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[30/Oct/2018:11:24:32.744418984 -0400] conn=2 (Internal) op=30(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0002822177
[30/Oct/2018:11:24:32.748331582 -0400] conn=2 (Internal) op=30(2)(1) SRCH base="uid=dave,ou=People,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="uniquemember"
[30/Oct/2018:11:24:32.751367046 -0400] conn=2 (Internal) op=30(2)(1) RESULT err=0 tag=48 nentries=1 etime=0.0003070513
[30/Oct/2018:11:24:32.754114208 -0400] conn=2 (Internal) op=30(3)(1) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=uid=dave,ou=People,dc=example,dc=com)" attrs=ALL
[30/Oct/2018:11:24:32.756985209 -0400] conn=2 (Internal) op=30(3)(2) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=cn=group,dc=example,dc=com)" attrs=ALL
[30/Oct/2018:11:24:32.760017553 -0400] conn=2 (Internal) op=30(3)(2) RESULT err=0 tag=48 nentries=0 etime=0.0003047684
[30/Oct/2018:11:24:32.762659735 -0400] conn=2 (Internal) op=30(3)(1) RESULT err=0 tag=48 nentries=1 etime=0.0008563977
[30/Oct/2018:11:24:32.765336861 -0400] conn=2 (Internal) op=30(4)(1) MOD dn="uid=dave,ou=People,dc=example,dc=com"
[30/Oct/2018:11:24:32.770089216 -0400] conn=2 (Internal) op=30(4)(1) RESULT err=0 tag=48 nentries=0 etime=0.0004764162 pr_idx=0 pr_cookie=0 
[30/Oct/2018:11:24:32.776825834 -0400] conn=2 op=30 RESULT err=0 tag=103 nentries=0 etime=0.0044004048

Perhaps it would be clearer if I changed the format to this?
conn=2 (Internal) op=15(2)(level: 2)
or
conn=2 (Internal) op=15(2)(nested: 2)

I don;t think that we should label anything like this(level or nested), as we are not labeling anything else too in the logs. Let's make sure to document the format correctly like this -

conn=ORIGNAL CONN ID (Internal) op=ORIGINAL_OP_ID(INTERNAL OP COUNT)(level)

to represent what is the exact log format. Thoughts?

Here is a very simple example.

Enable memberOf plugin
Create group
Create user (add extensibleObject objectclass for simplifying testcase)
Add user to group

Below we see the memberOf plugin doing some searches and the one search triggers a nested search (via a callback function), then MemberOf Plugin adds "memberOf" attribute to user "uid=dave"
[30/Oct/2018:11:24:32.733031048 -0400] conn=2 op=30 MOD dn="cn=group,dc=example,dc=com"
[30/Oct/2018:11:24:32.741632059 -0400] conn=2 (Internal) op=30(1)(1) SRCH base="cn=group,dc=example,dc=com" scope=0 filter="(|(objectclass=)(objectclass=ldapsubentry))" attrs=ALL
[30/Oct/2018:11:24:32.744418984 -0400] conn=2 (Internal) op=30(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0002822177
[30/Oct/2018:11:24:32.748331582 -0400] conn=2 (Internal) op=30(2)(1) SRCH base="uid=dave,ou=People,dc=example,dc=com" scope=0 filter="(|(objectclass=
)(objectclass=ldapsubentry))" attrs="uniquemember"
[30/Oct/2018:11:24:32.751367046 -0400] conn=2 (Internal) op=30(2)(1) RESULT err=0 tag=48 nentries=1 etime=0.0003070513
[30/Oct/2018:11:24:32.754114208 -0400] conn=2 (Internal) op=30(3)(1) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=uid=dave,ou=People,dc=example,dc=com)" attrs=ALL
[30/Oct/2018:11:24:32.756985209 -0400] conn=2 (Internal) op=30(3)(2) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=cn=group,dc=example,dc=com)" attrs=ALL
[30/Oct/2018:11:24:32.760017553 -0400] conn=2 (Internal) op=30(3)(2) RESULT err=0 tag=48 nentries=0 etime=0.0003047684
[30/Oct/2018:11:24:32.762659735 -0400] conn=2 (Internal) op=30(3)(1) RESULT err=0 tag=48 nentries=1 etime=0.0008563977
[30/Oct/2018:11:24:32.765336861 -0400] conn=2 (Internal) op=30(4)(1) MOD dn="uid=dave,ou=People,dc=example,dc=com"
[30/Oct/2018:11:24:32.770089216 -0400] conn=2 (Internal) op=30(4)(1) RESULT err=0 tag=48 nentries=0 etime=0.0004764162 pr_idx=0 pr_cookie=0
[30/Oct/2018:11:24:32.776825834 -0400] conn=2 op=30 RESULT err=0 tag=103 nentries=0 etime=0.0044004048

Perfect, thanks ::100:

Metadata Update from @mreynolds:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

5 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/3054

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