search

vt-middleware / ldaptive

A simple, extensible Java API for interacting with LDAP servers
56 stars 26 forks source link

SyncRepl problems handling with SyncIdSetUuids message #221

Closed fmartelli closed 2 years ago

fmartelli commented 2 years ago

It seems there are some SyncRepl messages resulting into SyncInfoMessage instances providing entryUuids field as null. Null entryUuids field generate NullPointerExceptions into SyncIdSetUuidsHandler.handle method. Although I cannot figure out how it is possible to have entryUuids null, I would suggest to provide stronger code into SyncIdSetUuidsHandler.handle. Maybe something like the following

        public void handle(final DERParser parser, final DERBuffer encoded) {
            try {
                if (getObject().getEntryUuids()==null) {
                    // ignore and log the skipping
                } else {
                    getObject().addEntryUuids(UuidType.decode(encoded));
                }
            } catch (Exception ignore) {
                // ignore and log the exception
            }
        }
dfish3r commented 2 years ago

That should only be possible if some piece of code invoked #setEntryUuids with null. I can certainly add a guard there as that's clearly going to cause problems. Can you provide a stacktrace so I can investigate further?

fmartelli commented 2 years ago

Thanks for your prompt reaction. Please see below for the stack trace (please note, no custom code calling setEntryUuids).

23:58:18.175 WARN  org.ldaptive.transport.netty.NettyConnection - Inbound handler caught exception for org.ldaptive.transport.netty.NettyConnection@1950420241::ldapUrl=[org.ldaptive.LdapURL@-2145590971::scheme=ldap, hostname=ldap1-prod.unifi.local, port=389, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null], isOpen=true, connectTime=2022-09-18T21:58:18.165189Z, connectionConfig=[org.ldaptive.ConnectionConfig@811788665::ldapUrl=ldap://ldap1-prod.unifi.local:389, connectTimeout=PT1M, responseTimeout=PT0S, reconnectTimeout=PT2M, autoReconnect=true, autoReconnectCondition=org.apache.syncope.core.logic.SyncReplLogic$$Lambda$1291/0x00000001011fd440@4ff5b362, autoReplay=true, sslConfig=null, useStartTLS=false, connectionInitializers=[org.ldaptive.BindConnectionInitializer@256138317::bindDn=orclApplicationCommonName=IdentityUnifi,ou=services,dc=unifi,dc=it, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.ActivePassiveConnectionStrategy@750e4d81, connectionValidator=null, transportOptions={}], channel=[id: 0x0624adc1, L:/192.168.108.116:50052 - R:ldap1-prod.unifi.local/192.168.104.16:389]
io.netty.handler.codec.DecoderException: java.lang.NullPointerException
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:477) ~[netty-codec-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) ~[netty-codec-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) ~[netty-codec-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) ~[netty-codec-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:271) ~[netty-handler-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:795) ~[netty-transport-native-epoll-4.1.65.Final-linux-x86_64.jar:4.1.65.Final]
    at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:480) ~[netty-transport-native-epoll-4.1.65.Final-linux-x86_64.jar:4.1.65.Final]
    at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378) ~[netty-transport-native-epoll-4.1.65.Final-linux-x86_64.jar:4.1.65.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) ~[netty-common-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.65.Final.jar:4.1.65.Final]
    at java.lang.Thread.run(Thread.java:829) ~[?:?]
Caused by: java.lang.NullPointerException
    at org.ldaptive.extended.SyncInfoMessage$SyncIdSetUuidsHandler.handle(SyncInfoMessage.java:606) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTag(DERParser.java:172) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTags(DERParser.java:147) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTag(DERParser.java:177) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTags(DERParser.java:147) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTag(DERParser.java:177) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTags(DERParser.java:147) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parse(DERParser.java:53) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.extended.SyncInfoMessage.lambda$getResponseValueParseHandler$0(SyncInfoMessage.java:157) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTag(DERParser.java:172) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTags(DERParser.java:147) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTag(DERParser.java:177) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTags(DERParser.java:147) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTag(DERParser.java:177) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTags(DERParser.java:147) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parse(DERParser.java:53) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.extended.IntermediateResponse.<init>(IntermediateResponse.java:65) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.extended.SyncInfoMessage.<init>(SyncInfoMessage.java:132) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.transport.ResponseParser.lambda$new$10(ResponseParser.java:126) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTag(DERParser.java:172) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTags(DERParser.java:147) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTag(DERParser.java:177) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parseTags(DERParser.java:147) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.asn1.DERParser.parse(DERParser.java:53) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.transport.ResponseParser.parse(ResponseParser.java:143) ~[ldaptive-2.1.0.jar:?]
    at org.ldaptive.transport.netty.NettyConnection$MessageDecoder.decode(NettyConnection.java:1451) ~[ldaptive-2.1.0.jar:?]
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507) ~[netty-codec-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446) ~[netty-codec-4.1.65.Final.jar:4.1.65.Final]
dfish3r commented 2 years ago

That's a head scratcher. I've got a few ideas, but seeing the BER data would help.

Can you turn on the following logging:

  <logger name="org.ldaptive.transport.netty.NettyConnection" level="DEBUG" />
  <logger name="io.netty.handler.logging.LoggingHandler" level="DEBUG" />

And report back the output from io.netty.handler.logging.LoggingHandler prior to this exception. (Note that this will produce a lot of log data.) That will allow me to create a unit test and dive a little deeper.

fmartelli commented 2 years ago

Hi. please find below org.ldaptive logs to TRACE. Still cannot provide logs for io.netty.handler.logging.LoggingHandler because I'm not able to reproduce the error systematically. I've configure the logger and I'll provide related statement as soon as the error occurs again.

23:58:18.331 TRACE org.ldaptive.transport.netty.NettyConnection$BindOperationHandle - await received result org.ldaptive.BindResponse@1758678506::messageID=20287605, controls=[], resultCode=SUCCESS, matchedDN=, diagnosticMessage=, referralURLs=[] for handle org.ldaptive.transport.netty.NettyConnection$BindOperationHandle@779501277::messageID=20287605, request=org.ldaptive.SimpleBindRequest@940709779::controls=null, dn=............., connection=null, responseTimeout=PT0S, creationTime=2022-09-18T21:58:18.327898Z, sentTime=2022-09-18T21:58:18.328735Z, receivedTime=2022-09-18T21:58:18.331377Z, consumedMessage=false, result=org.ldaptive.BindResponse@1758678506::messageID=20287605, controls=[], resultCode=SUCCESS, matchedDN=, diagnosticMessage=, referralURLs=[], exception=null
23:58:18.331 DEBUG org.ldaptive.transport.netty.NettyConnection - Netty opened connection org.ldaptive.transport.netty.NettyConnection@1950420241::ldapUrl=[org.ldaptive.LdapURL@-2145590971::scheme=ldap, hostname=............, port=389, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null], isOpen=true, connectTime=2022-09-18T21:58:18.331603Z, connectionConfig=[org.ldaptive.ConnectionConfig@811788665::ldapUrl=ldap://......:389, connectTimeout=PT1M, responseTimeout=PT0S, reconnectTimeout=PT2M, autoReconnect=true, autoReconnectCondition=org.apache.syncope.core.logic.SyncReplLogic$$Lambda$1291/0x00000001011fd440@4ff5b362, autoReplay=true, sslConfig=null, useStartTLS=false, connectionInitializers=[org.ldaptive.BindConnectionInitializer@256138317::bindDn=.............., bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.ActivePassiveConnectionStrategy@750e4d81, connectionValidator=null, transportOptions={}], channel=[id: 0x2d8ef931, L:/...... - R:......]
23:58:18.331 DEBUG org.ldaptive.transport.TransportConnection - Finished reopen for connection org.ldaptive.transport.netty.NettyConnection@1950420241::ldapUrl=[org.ldaptive.LdapURL@-2145590971::scheme=ldap, hostname=........., port=389, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null], isOpen=true, connectTime=2022-09-18T21:58:18.331603Z, connectionConfig=[org.ldaptive.ConnectionConfig@811788665::ldapUrl=ldap://.........:389, connectTimeout=PT1M, responseTimeout=PT0S, reconnectTimeout=PT2M, autoReconnect=true, autoReconnectCondition=org.apache.syncope.core.logic.SyncReplLogic$$Lambda$1291/0x00000001011fd440@4ff5b362, autoReplay=true, sslConfig=null, useStartTLS=false, connectionInitializers=[org.ldaptive.BindConnectionInitializer@256138317::bindDn=............., bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.ActivePassiveConnectionStrategy@750e4d81, connectionValidator=null, transportOptions={}], channel=[id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389] using strategy org.ldaptive.ActivePassiveConnectionStrategy@750e4d81
23:58:18.332 INFO  org.ldaptive.transport.netty.NettyConnection - auto reconnect finished for connection org.ldaptive.transport.netty.NettyConnection@1950420241::ldapUrl=[org.ldaptive.LdapURL@-2145590971::scheme=ldap, hostname=........., port=389, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null], isOpen=true, connectTime=2022-09-18T21:58:18.331603Z, connectionConfig=[org.ldaptive.ConnectionConfig@811788665::ldapUrl=ldap://.........:389, connectTimeout=PT1M, responseTimeout=PT0S, reconnectTimeout=PT2M, autoReconnect=true, autoReconnectCondition=org.apache.syncope.core.logic.SyncReplLogic$$Lambda$1291/0x00000001011fd440@4ff5b362, autoReplay=true, sslConfig=null, useStartTLS=false, connectionInitializers=[org.ldaptive.BindConnectionInitializer@256138317::bindDn=............., bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.ActivePassiveConnectionStrategy@750e4d81, connectionValidator=null, transportOptions={}], channel=[id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389]
23:58:18.332 TRACE org.ldaptive.transport.netty.NettyConnection - Write handle org.ldaptive.transport.DefaultSearchOperationHandle@266441628::messageID=20287604, request=org.ldaptive.SearchRequest@-689468308::controls=[[org.ldaptive.control.SyncRequestControl@1561007543::criticality=true, requestMode=REFRESH_AND_PERSIST, cookie=cmlkPTAwMCxjc249MjAyMjA5MTcwMTI4NDQuMzUyMjgwWiMwMDAwMDAjMDAwIzAwMDAwMA==, reloadHint=false]], dn=ou=personale,ou=people,dc=unifi,dc=it, scope=SUBTREE, aliases=NEVER, sizeLimit=0, timeLimit=PT0S, typesOnly=false, filter=org.ldaptive.filter.AndFilter@1335171252::filterComponents=[org.ldaptive.filter.AndFilter@1986454771::filterComponents=[org.ldaptive.filter.OrFilter@1985323754::filterComponents=[org.ldaptive.filter.EqualityFilter@-761589465::filterType=EQUALITY, attributeDesc=uid, assertionValue=D099162, org.ldaptive.filter.AndFilter@-774597180::filterComponents=[org.ldaptive.filter.PresenceFilter@132b6d, org.ldaptive.filter.ExtensibleFilter@-388492249::matchingRuleID=null, attributeDesc=ou, assertionValue=docenti, dnAttributes=true]]], org.ldaptive.filter.AndFilter@-326207268::filterComponents=[org.ldaptive.filter.EqualityFilter@-327338285::filterType=EQUALITY, attributeDesc=objectclass, assertionValue=unifiPersonale]], returnAttributes=[*], binaryAttributes=null, connection=org.ldaptive.transport.netty.NettyConnection@1950420241::ldapUrl=[org.ldaptive.LdapURL@-2145590971::scheme=ldap, hostname=........., port=389, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null], isOpen=true, connectTime=2022-09-18T21:58:18.331603Z, connectionConfig=[org.ldaptive.ConnectionConfig@811788665::ldapUrl=ldap://.........:389, connectTimeout=PT1M, responseTimeout=PT0S, reconnectTimeout=PT2M, autoReconnect=true, autoReconnectCondition=org.apache.syncope.core.logic.SyncReplLogic$$Lambda$1291/0x00000001011fd440@4ff5b362, autoReplay=true, sslConfig=null, useStartTLS=false, connectionInitializers=[org.ldaptive.BindConnectionInitializer@256138317::bindDn=............., bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.ActivePassiveConnectionStrategy@750e4d81, connectionValidator=null, transportOptions={}], channel=[id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389], responseTimeout=PT0S, creationTime=2022-09-17T03:40:45.411638Z, sentTime=2022-09-18T21:58:18.316571Z, receivedTime=null, consumedMessage=false, result=null, exception=null, onEntry=[org.ldaptive.control.util.SyncReplClient$$Lambda$1325/0x0000000101291440@24983c71], onReference=null, onSearchResult=null with pending responses org.ldaptive.transport.netty.HandleMap@1980287999::open=true, throttle=null, handles={}
23:58:18.333 TRACE org.ldaptive.transport.netty.NettyConnection$RequestEncoder - encoding message org.ldaptive.transport.netty.EncodedRequest@2043709702::messageID=20287606, encoded=3084000000F802040135907663840000008B04256F753D706572736F6E616C652C6F753D70656F706C652C64633D756E6966692C64633D69740A01020A0100020100020100010100A04EA02BA129A30E0403756964040744303939313632A0178703756964A91082026F758307646F63656E74698401FFA01FA31D040B6F626A656374636C617373040E756E696669506572736F6E616C65300304012AA05F305D0418312E332E362E312E342E312E343230332E312E392E312E310101FF043E303C02010304347269643D3030302C63736E3D32303232303931373031323834342E3335323238305A233030303030302330303023303030303030010100 on ChannelHandlerContext(request_encoder, [id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389])
23:58:18.333 TRACE org.ldaptive.transport.netty.NettyConnection - event loop group io.netty.channel.epoll.EpollEventLoopGroup@322ef75 has 1 pending tasks for org.ldaptive.transport.netty.NettyConnection@1950420241::ldapUrl=[org.ldaptive.LdapURL@-2145590971::scheme=ldap, hostname=........., port=389, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null], isOpen=true, connectTime=2022-09-18T21:58:18.331603Z, connectionConfig=[org.ldaptive.ConnectionConfig@811788665::ldapUrl=ldap://.........:389, connectTimeout=PT1M, responseTimeout=PT0S, reconnectTimeout=PT2M, autoReconnect=true, autoReconnectCondition=org.apache.syncope.core.logic.SyncReplLogic$$Lambda$1291/0x00000001011fd440@4ff5b362, autoReplay=true, sslConfig=null, useStartTLS=false, connectionInitializers=[org.ldaptive.BindConnectionInitializer@256138317::bindDn=............., bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.ActivePassiveConnectionStrategy@750e4d81, connectionValidator=null, transportOptions={}], channel=[id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389]
23:58:18.333 DEBUG org.ldaptive.transport.netty.NettyConnection - Reconnect for connection org.ldaptive.transport.netty.NettyConnection@1950420241::ldapUrl=[org.ldaptive.LdapURL@-2145590971::scheme=ldap, hostname=........., port=389, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null], isOpen=true, connectTime=2022-09-18T21:58:18.331603Z, connectionConfig=[org.ldaptive.ConnectionConfig@811788665::ldapUrl=ldap://.........:389, connectTimeout=PT1M, responseTimeout=PT0S, reconnectTimeout=PT2M, autoReconnect=true, autoReconnectCondition=org.apache.syncope.core.logic.SyncReplLogic$$Lambda$1291/0x00000001011fd440@4ff5b362, autoReplay=true, sslConfig=null, useStartTLS=false, connectionInitializers=[org.ldaptive.BindConnectionInitializer@256138317::bindDn=............., bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.ActivePassiveConnectionStrategy@750e4d81, connectionValidator=null, transportOptions={}], channel=[id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389] finished
23:58:18.335 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - decoding 2048 bytes from PooledUnsafeDirectByteBuf(ridx: 0, widx: 2048, cap: 2048) on ChannelHandlerContext(frame_decoder, [id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389])
23:58:18.336 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - could not read entire message of length 4656 with buffer org.ldaptive.transport.netty.NettyDERBuffer@1234687560::pos=4, lim=2048, cap=2048
23:58:18.336 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - decoded message length of -1 for PooledUnsafeDirectByteBuf(ridx: 2048, widx: 2048, cap: 2048) on ChannelHandlerContext(frame_decoder, [id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389])
23:58:18.336 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - could not read enough bytes from PooledUnsafeDirectByteBuf(ridx: 0, widx: 2048, cap: 2048) to decode message on ChannelHandlerContext(frame_decoder, [id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389])
23:58:18.336 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - decoding 4660 bytes from PooledUnsafeDirectByteBuf(ridx: 0, widx: 4660, cap: 8192) on ChannelHandlerContext(frame_decoder, [id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389])
23:58:18.336 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - read entire message of length 4656 with buffer org.ldaptive.transport.netty.NettyDERBuffer@674592978::pos=4, lim=4660, cap=4660
23:58:18.337 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - decoded message length of 4660 for PooledUnsafeDirectByteBuf(ridx: 4660, widx: 4660, cap: 8192) on ChannelHandlerContext(frame_decoder, [id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389])
23:58:18.337 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - read enough bytes from PooledUnsafeDirectByteBuf(ridx: 4660, widx: 4660, cap: 8192) to decode message PooledSlicedByteBuf(ridx: 0, widx: 4660, cap: 4660/4660, unwrapped: PooledUnsafeDirectByteBuf(ridx: 4660, widx: 4660, cap: 8192)) on ChannelHandlerContext(frame_decoder, [id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389])
23:58:18.337 TRACE org.ldaptive.transport.netty.NettyConnection - received 4660 bytes on ChannelHandlerContext(response_decoder, [id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389])
23:58:18.338 WARN  org.ldaptive.transport.netty.NettyConnection - Inbound handler caught exception for org.ldaptive.transport.netty.NettyConnection@1950420241::ldapUrl=[org.ldaptive.LdapURL@-2145590971::scheme=ldap, hostname=........., port=389, baseDn=null, attributes=null, scope=null, filter=null, inetAddress=null], isOpen=true, connectTime=2022-09-18T21:58:18.331603Z, connectionConfig=[org.ldaptive.ConnectionConfig@811788665::ldapUrl=ldap://.........:389, connectTimeout=PT1M, responseTimeout=PT0S, reconnectTimeout=PT2M, autoReconnect=true, autoReconnectCondition=org.apache.syncope.core.logic.SyncReplLogic$$Lambda$1291/0x00000001011fd440@4ff5b362, autoReplay=true, sslConfig=null, useStartTLS=false, connectionInitializers=[org.ldaptive.BindConnectionInitializer@256138317::bindDn=............., bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.ActivePassiveConnectionStrategy@750e4d81, connectionValidator=null, transportOptions={}], channel=[id: 0x2d8ef931, L:/192.168.108.116:50122 - R:........./192.168.104.16:389]
io.netty.handler.codec.DecoderException: java.lang.NullPointerException
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:477) ~[netty-codec-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) ~[netty-codec-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.65.Final.jar:4.1.65.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.65.Final.ja
dfish3r commented 2 years ago

I pushed a potential fix that makes the underlying set final. I published a new snapshot if you want to try it out.

I'd still like to get a capture of the BER data if you happen to reproduce this.

fmartelli commented 2 years ago

Thank for the new snapshot. I'll try it out within today for sure. In the mean while, is this what you are waiting for?

04:20:32.612 DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xe200acdf, L:/192.168.108.116:33516 - R:ldap1-prod.unifi.local/192.168.104.16:389] WRITE: 299B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 30 84 00 00 01 25 02 01 04 63 84 00 00 00 bb 04 |0....%...c......|
|00000010| 25 6f 75 3d 70 65 72 73 6f 6e 61 6c 65 2c 6f 75 |%ou=personale,ou|
|00000020| 3d 70 65 6f 70 6c 65 2c 64 63 3d 75 6e 69 66 69 |=people,dc=unifi|
|00000030| 2c 64 63 3d 69 74 0a 01 02 0a 01 00 02 01 00 02 |,dc=it..........|
|00000040| 01 00 01 01 00 a0 7e a0 5b a1 59 a3 0e 04 03 75 |......~.[.Y....u|
|00000050| 69 64 04 07 44 30 39 39 31 36 32 a3 0e 04 03 75 |id..D099162....u|
|00000060| 69 64 04 07 44 32 31 30 31 31 36 a3 0e 04 03 75 |id..D210116....u|
|00000070| 69 64 04 07 44 30 39 38 38 35 37 a3 0e 04 03 75 |id..D098857....u|
|00000080| 69 64 04 07 44 31 37 30 34 39 39 a0 17 87 03 75 |id..D170499....u|
|00000090| 69 64 a9 10 82 02 6f 75 83 07 64 6f 63 65 6e 74 |id....ou..docent|
|000000a0| 69 84 01 ff a0 1f a3 1d 04 0b 6f 62 6a 65 63 74 |i.........object|
|000000b0| 63 6c 61 73 73 04 0e 75 6e 69 66 69 50 65 72 73 |class..unifiPers|
|000000c0| 6f 6e 61 6c 65 30 03 04 01 2a a0 5f 30 5d 04 18 |onale0...*._0]..|
|000000d0| 31 2e 33 2e 36 2e 31 2e 34 2e 31 2e 34 32 30 33 |1.3.6.1.4.1.4203|
|000000e0| 2e 31 2e 39 2e 31 2e 31 01 01 ff 04 3e 30 3c 02 |.1.9.1.1....>0<.|
|000000f0| 01 03 04 34 72 69 64 3d 30 30 30 2c 63 73 6e 3d |...4rid=000,csn=|
|00000100| 32 30 32 32 30 39 32 31 30 30 30 38 30 30 2e 34 |20220921000800.4|
|00000110| 30 37 32 39 35 5a 23 30 30 30 30 30 30 23 30 30 |07295Z#000000#00|
|00000120| 30 23 30 30 30 30 30 30 01 01 00                |0#000000...     |
+--------+-------------------------------------------------+----------------+
04:20:32.612 DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xe200acdf, L:/192.168.108.116:33516 - R:ldap1-prod.unifi.local/192.168.104.16:389] FLUSH
04:20:32.637 DEBUG io.netty.handler.logging.LoggingHandler - [id: 0xe200acdf, L:/192.168.108.116:33516 - R:ldap1-prod.unifi.local/192.168.104.16:389] READ: 60B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 30 3a 02 01 04 79 35 80 18 31 2e 33 2e 36 2e 31 |0:...y5..1.3.6.1|
|00000010| 2e 34 2e 31 2e 34 32 30 33 2e 31 2e 39 2e 31 2e |.4.1.4203.1.9.1.|
|00000020| 34 81 19 a3 17 01 01 ff 31 12 04 10 a1 40 71 14 |4.......1....@q.|
|00000030| b5 1f 10 3c 80 93 83 ef 8d 93 05 09             |...<........    |
+--------+-------------------------------------------------+----------------+
04:20:32.637 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - decoding 60 bytes from PooledUnsafeDirectByteBuf(ridx: 0, widx: 60, cap: 2048) on ChannelHandlerContext(frame_decoder, [id: 0xe200acdf, L:/192.168.108.116:33516 - R:ldap1-prod.unifi.local/192.168.104.16:389])
04:20:32.637 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - read entire message of length 58 with buffer org.ldaptive.transport.netty.NettyDERBuffer@2023932765::pos=2, lim=60, cap=60
04:20:32.637 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - decoded message length of 60 for PooledUnsafeDirectByteBuf(ridx: 60, widx: 60, cap: 2048) on ChannelHandlerContext(frame_decoder, [id: 0xe200acdf, L:/192.168.108.116:33516 - R:ldap1-prod.unifi.local/192.168.104.16:389])
04:20:32.637 TRACE org.ldaptive.transport.netty.MessageFrameDecoder - read enough bytes from PooledUnsafeDirectByteBuf(ridx: 60, widx: 60, cap: 2048) to decode message PooledSlicedByteBuf(ridx: 0, widx: 60, cap: 60/60, unwrapped: PooledUnsafeDirectByteBuf(ridx: 60, widx: 60, cap: 2048)) on ChannelHandlerContext(frame_decoder, [id: 0xe200acdf, L:/192.168.108.116:33516 - R:ldap1-prod.unifi.local/192.168.104.16:389])
04:20:32.637 TRACE org.ldaptive.transport.netty.NettyConnection - received 60 bytes on ChannelHandlerContext(response_decoder, [id: 0xe200acdf, L:/192.168.108.116:33516 - R:ldap1-prod.unifi.local/192.168.104.16:389])
fmartelli commented 2 years ago

I applied related changes done into the snap. It seems that setEntryUuids is never called. I mean, occurring the error, no message about setEntryUuids is provided. Still running, anyway ...

dfish3r commented 2 years ago

Thank you for the BER data, I see the problem now. Should have a patch later today.

dfish3r commented 2 years ago

Fix has been merged and I published a new snapshot. Please reopen if that doesn't fix the problem.

fmartelli commented 2 years ago

I'm going to check the fix. I'll let you know.