This was never documented before, but it should be.  Here is an  example of access log with internal logging level set ( level 4 - Logging for internal access operations )

There are two foramts for internal operation logging

[1]  Server initiated internal operation.  This is an internal operation not triggers by a client operation.  This logging looks like:


[14/Aug/2018:09:45:25.814158882 -0400] conn=Internal(0) op=0(0) MOD dn="cn=uniqueid generator,cn=config"
[14/Aug/2018:09:45:25.822103183 -0400] conn=Internal(0) op=0(0) RESULT err=0 tag=48 nentries=0 etime=0.0007968796

Note that all values inside the parenthesis are zero, and the "conn=" is "Internal"

[2]  For internal operations triggered by client operations the logging looks like this below.  This tells us that operation 15(op=15) triggered the following internal operations: 

[14/Aug/2018:09:45:14.382918693 -0400] conn=5 (Internal) op=15(1) SRCH base="cn=config,cn=userroot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/Aug/2018:09:45:14.383191380 -0400] conn=5 (Internal) op=15(1) RESULT err=0 tag=48 nentries=0 etime=0.0000295419
[14/Aug/2018:09:45:14.383216269 -0400] conn=5 (Internal) op=15(2) SRCH base="cn=config,cn=NetscapeRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/Aug/2018:09:45:14.383449419 -0400] conn=5 (Internal) op=15(2) RESULT err=0 

 Note the "conn=" value is still the original client connection ID following by "(Internal)".  Then next to the operation number we now have a internal op counter/id inside parenthesis so that the internal ops can be correctly matched up.


Here is an example with nsslapd-plugin-logging is enabled, showing the full operation stack involving plugins, and nested internal operations.  In this case the logging shows what happens when a user is deleted, and the Referential Integrity Plugin removes that user from a group:


[14/Aug/2018:09:55:51.187449076 -0400] conn=2 op=37 DEL dn="uid=my_user,dc=example,dc=com"
[14/Aug/2018:09:55:51.187629505 -0400] conn=2 (Internal) op=37(1) SRCH base="uid=my_user,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[14/Aug/2018:09:55:51.187737801 -0400] conn=2 (Internal) op=37(1) RESULT err=0 tag=48 nentries=1 etime=0.0000129148
[14/Aug/2018:09:55:51.188416283 -0400] conn=2 (Internal) op=37(2) SRCH base="dc=example,dc=com" scope=2 filter="(member=uid=my_user,dc=example,dc=com)" attrs="member"
[14/Aug/2018:09:55:51.188526266 -0400] conn=2 (Internal) op=37(2) RESULT err=0 tag=48 nentries=0 etime=0.0000123162
[14/Aug/2018:09:55:51.188549089 -0400] conn=2 (Internal) op=37(3) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=uid=my_user,dc=example,dc=com)" attrs="uniquemember"
[14/Aug/2018:09:55:51.188669549 -0400] conn=2 (Internal) op=37(3) RESULT err=0 tag=48 nentries=1 etime=0.0000128104
[14/Aug/2018:09:55:51.188688734 -0400] conn=2 (Internal) op=37(4) MOD dn="cn=my_group,dc=example,dc=com"
[14/Aug/2018:09:55:51.188899569 -0400] conn=2 (Internal) op=37(5) SRCH base="cn=my_group,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[14/Aug/2018:09:55:51.189002552 -0400] conn=2 (Internal) op=37(5) RESULT err=0 tag=48 nentries=1 etime=0.0000130685
[14/Aug/2018:09:55:51.193901336 -0400] conn=2 (Internal) op=37(4) RESULT err=0 tag=48 nentries=0 etime=0.0005217545
[14/Aug/2018:09:55:51.196443038 -0400] conn=2 (Internal) op=37(6) SRCH base="dc=example,dc=com" scope=2 filter="(owner=uid=my_user,dc=example,dc=com)" attrs="owner"
[14/Aug/2018:09:55:51.196566896 -0400] conn=2 (Internal) op=37(6) RESULT err=0 tag=48 nentries=0 etime=0.0000137656
[14/Aug/2018:09:55:51.196583851 -0400] conn=2 (Internal) op=37(7) SRCH base="dc=example,dc=com" scope=2 filter="(seeAlso=uid=my_user,dc=example,dc=com)" attrs="seeAlso"
[14/Aug/2018:09:55:51.196644622 -0400] conn=2 (Internal) op=37(7) RESULT err=0 tag=48 nentries=0 etime=0.0000066978
[14/Aug/2018:09:55:51.196661636 -0400] conn=2 (Internal) op=37(8) SRCH base="o=netscaperoot" scope=2 filter="(member=uid=my_user,dc=example,dc=com)" attrs="member"
[14/Aug/2018:09:55:51.196717581 -0400] conn=2 (Internal) op=37(8) RESULT err=0 tag=48 nentries=0 etime=0.0000063316
[14/Aug/2018:09:55:51.196730167 -0400] conn=2 (Internal) op=37(9) SRCH base="o=netscaperoot" scope=2 filter="(uniquemember=uid=my_user,dc=example,dc=com)" attrs="uniquemember"
[14/Aug/2018:09:55:51.196774033 -0400] conn=2 (Internal) op=37(9) RESULT err=0 tag=48 nentries=0 etime=0.0000048634
[14/Aug/2018:09:55:51.196785642 -0400] conn=2 (Internal) op=37(10) SRCH base="o=netscaperoot" scope=2 filter="(owner=uid=my_user,dc=example,dc=com)" attrs="owner"
[14/Aug/2018:09:55:51.196830223 -0400] conn=2 (Internal) op=37(10) RESULT err=0 tag=48 nentries=0 etime=0.0000048854
[14/Aug/2018:09:55:51.196841640 -0400] conn=2 (Internal) op=37(11) SRCH base="o=netscaperoot" scope=2 filter="(seeAlso=uid=my_user,dc=example,dc=com)" attrs="seeAlso"
[14/Aug/2018:09:55:51.196884075 -0400] conn=2 (Internal) op=37(11) RESULT err=0 tag=48 nentries=0 etime=0.0000046522
[14/Aug/2018:09:55:51.197669445 -0400] conn=2 op=37 RESULT err=0 tag=107 nentries=0 etime=0.0010297858