OUD12c - The “log-connection-details” Feature for Access Logger Throws NullPointerException When Enabled (Doc ID 2803504.1)

$ dsconfig -n -p ${ADMIN_PORT} -D "{DS_ADMIN}" -j ${PWD_FILE} -h ${INSTANCE_NAME}.${DOMAIN} --trustAll set-log-publisher-prop --publisher-name File-Based\ Access\ Logger --set log-controls:true

$ dsconfig -n -p ${ADMIN_PORT} -D "{DS_ADMIN}" -j ${PWD_FILE} -h ${INSTANCE_NAME}.${DOMAIN} --trustAll set-log-publisher-prop --publisher-name File-Based\ Access\ Logger --set log-connection-details:true

# condition 1 : BIND with wrong BINDDN (e.g. ou instead of user object due to misconfiguration of application):
 
$ grep "conn=221 " access
[01/Feb/2021:16:49:21 +0100] CONNECT conn=221 from={CLIENT_IP}:{CLIENT_RANDOM_PORT} to={SERVER_IP}:{SERVER_SSL_PORT} protocol=LDAPS
[01/Feb/2021:16:49:21 +0100] BIND REQ conn=221 op=0 msgID=1 client={CLIENT_IP}:{CLIENT_RANDOM_PORT} server={SERVER_IP}:{SERVER_SSL_PORT} protocol=LDAPS type=SIMPLE dn="{OU_BASE_DN}" version=3 controls=""
[01/Feb/2021:16:49:22 +0100] DISCONNECT conn=221 reason="Server Error" msg="Worker Thread 12 encountered an uncaught exception while processing operation BindOperation(connID=221, opID=0, protocol="LDAPS 3, {OU_BASE_DN}, authType=Simple): NullPointerException (AccessLogPublisher.java:1246 TextAccessLogPublisher.java:1328 TextAccessLogPublisher.java:735 AccessLogger.java:788 BindOperationBasis.java:1171 TraditionalWorkerThread.java:166)"
 
# condition 2 : BIND with not existing user dn (replaced real username by “xxx”):
 
access.20210202024433Z:[01/Feb/2021:16:47:14 +0100] BIND REQ conn=39 op=0 msgID=1 client={CLIENT_IP}:{CLIENT_RANDOM_PORT} server={SERVER_IP}:{SERVER_SSL_PORT} protocol=LDAPS type=SIMPLE dn="{cn=xxx},{OU_BASE_DN}" version=3 controls=""
access.20210202024433Z:[01/Feb/2021:16:47:14 +0100] DISCONNECT conn=39 reason="Server Error" msg="Worker Thread 15 encountered an uncaught exception while processing operation BindOperation(connID=39, opID=0, protocol="LDAPS 3, {cn=xxx},{OU_BASE_DN}, authType=Simple): NullPointerException (AccessLogPublisher.java:1246 TextAccessLogPublisher.java:1328 TextAccessLogPublisher.java:735 AccessLogger.java:788 BindOperationBasis.java:1171 TraditionalWorkerThread.java:166)"
 
# previous logs before activating this feature show that the BIND user doesn’t exist:
 
access.20210201163459Z:[01/Feb/2021:16:37:46 +0100] BIND REQ conn=1540897 op=0 msgID=1 type=SIMPLE dn="{cn=xxx},{OU_BASE_DN}" version=3
access.20210201163459Z:[01/Feb/2021:16:37:46 +0100] BIND RES conn=1540897 op=0 msgID=1 result=49 authFailureID=196826 authFailureReason="Unable to bind to the Directory Server as user {cn=xxx},{OU_BASE_DN} because no such user exists in the server" qtime=0 etime=0
 
# condition 3 : Unsuccessful BIND:
 
grep conn=1716812 access
[01/Feb/2021:16:38:42 +0100] CONNECT conn=1716812 from={CLIENT_IP}:{CLIENT_RANDOM_PORT} to={SERVER_IP}:{SERVER_PORT} protocol=LDAP
[01/Feb/2021:16:38:42 +0100] EXTENDED REQ conn=1716812 op=0 msgID=1 client={CLIENT_IP}:{CLIENT_RANDOM_PORT} server={SERVER_IP}:{SERVER_PORT} protocol=LDAP name="StartTLS" oid="1.3.6.1.4.1.1466.20037"
[01/Feb/2021:16:38:42 +0100] EXTENDED RES conn=1716812 op=0 msgID=1 client={CLIENT_IP}:{CLIENT_RANDOM_PORT} server={SERVER_IP}:{SERVER_PORT} protocol=LDAP name="StartTLS" oid="1.3.6.1.4.1.1466.20037" result=0 etime=0
[01/Feb/2021:16:38:42 +0100] SEARCH REQ conn=1716812 op=1 msgID=2 client={CLIENT_IP}:{CLIENT_RANDOM_PORT} server={SERVER_IP}:{SERVER_PORT} protocol=LDAP base="" scope=base filter="(objectclass=*)" attrs="*,altServer,namingContexts,supportedControl,supportedExtension,supportedFeatures,supportedLDAPVersion,supportedSASLMechanisms,domainControllerFunctionality,defaultNamingContext,lastUSN,highestCommittedUSN" controls=""
[01/Feb/2021:16:38:42 +0100] SEARCH RES conn=1716812 op=1 msgID=2 client={CLIENT_IP}:{CLIENT_RANDOM_PORT} server={SERVER_IP}:{SERVER_PORT} protocol=LDAP result=0 nentries=1 controls="" qtime=0 etime=1
[01/Feb/2021:16:38:42 +0100] BIND REQ conn=1716812 op=2 msgID=3 client={CLIENT_IP}:{CLIENT_RANDOM_PORT} server={SERVER_IP}:{SERVER_PORT} protocol=LDAP type=SIMPLE dn="{cn=XXX},{OU_BASE_DN}" version=3 controls="1.3.6.1.4.1.42.2.27.8.5.1"
[01/Feb/2021:16:38:42 +0100] DISCONNECT conn=1716812 reason="Server Error" msg="Worker Thread 21 encountered an uncaught exception while processing operation BindOperation(connID=1716812, opID=2, protocol="LDAP 3, dn={cn=XXX},{OU_BASE_DN}, authType=Simple): NullPointerException (AccessLogPublisher.java:1246 TextAccessLogPublisher.java:1328 TextAccessLogPublisher.java:735 AccessLogger.java:788 BindOperationBasis.java:1171 TraditionalWorkerThread.java:166)"
 
# previous logs (before activating this feature on the other cluster node) show the unsuccessful BIND due to misconfiguration on the client:
 
$ grep 1759290 access.20210201221502Z
[01/Feb/2021:16:37:13 +0100] CONNECT conn=1759290 from={CLIENT_IP}:{CLIENT_RANDOM_PORT} to={SERVER_IP}:{SERVER_PORT} protocol=LDAP
[01/Feb/2021:16:37:13 +0100] EXTENDED REQ conn=1759290 op=0 msgID=1 name="StartTLS" oid="1.3.6.1.4.1.1466.20037"
[01/Feb/2021:16:37:13 +0100] EXTENDED RES conn=1759290 op=0 msgID=1 name="StartTLS" oid="1.3.6.1.4.1.1466.20037" result=0 etime=0
[01/Feb/2021:16:37:13 +0100] SEARCH REQ conn=1759290 op=1 msgID=2 base="" scope=base filter="(objectclass=*)" attrs="*,altServer,namingContexts,supportedControl,supportedExtension,supportedFeatures,supportedLDAPVersion,supportedSASLMechanisms,domainControllerFunctionality,defaultNamingContext,lastUSN,highestCommittedUSN"
[01/Feb/2021:16:37:13 +0100] SEARCH RES conn=1759290 op=1 msgID=2 result=0 nentries=1 qtime=0 etime=1
[01/Feb/2021:16:37:13 +0100] BIND REQ conn=1759290 op=2 msgID=3 type=SIMPLE dn=""{cn=XXX},{OU_BASE_DN}" version=3
[01/Feb/2021:16:37:13 +0100] BIND RES conn=1759290 op=2 msgID=3 result=49 authFailureID=196887 authFailureReason="The password provided by the user did not match any password(s) stored in the user's entry" qtime=0 etime=1
[01/Feb/2021:16:37:13 +0100] UNBIND REQ conn=1759290 op=3 msgID=4
[01/Feb/2021:16:37:13 +0100] DISCONNECT conn=1759290 reason="Client Disconnect"