Xrootd TLS handshake failed: not an SSL/TLS record

[ageorget]

trafficstars

Hi,

For the last days, we observed more and more SSL/TLS errors on the CMS XRootD doors like this without any changes on dCache side (9.2.22 on doors, Java openjdk version "17.0.10") :

Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]: 31 Jul 2024 14:10:40 (xrootd-ccdcacli501) [] Server: TLS handshake failed: io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record.
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]: 31 Jul 2024 14:10:40 (xrootd-ccdcacli501) [door:xrootd-ccdcacli501@xrootd-ccdcacli501Domain:AAYeifuYzUA] TLS handshake failed: io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record.
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]: 31 Jul 2024 14:10:40 (xrootd-ccdcacli501) [door:xrootd-ccdcacli501@xrootd-ccdcacli501Domain:AAYeifuYzUA] Uncaught exception in thread xrootd-net-2
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]: io.netty.handler.codec.DecoderException: io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:499)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at org.dcache.util.CDCThreadFactory.lambda$newThread$0(CDCThreadFactory.java:42)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at java.base/java.lang.Thread.run(Thread.java:840)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]: Caused by: io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1189)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1426)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1469)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.handler.ssl.SslHandler$SslEngineType$1.unwrap(SslHandler.java:223)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1353)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.handler.ssl.SslHandler.decodeNonJdkCompatible(SslHandler.java:1257)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1297)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468)
Jul 31 14:10:40 ccdcacli501 dcache@xrootd-ccdcacli501Domain[15154]:         ... 17 common frames omitted

The strange thing is that access log reports the transaction as OK and nothing else:

level=INFO ts=2024-07-31T14:10:40.712+0200 event=org.dcache.xrootd.connection.start session=door:xrootd-ccdcacli501@xrootd-ccdcacli501Domain:AAYeifuYzUA socket.remote=128.142.196.239:15788 socket.local=134.158.209.241:1094
level=INFO ts=2024-07-31T14:10:40.714+0200 event=org.dcache.xrootd.request session=door:xrootd-ccdcacli501@xrootd-ccdcacli501Domain:AAYeifuYzUA request=protocol response=ok
level=INFO ts=2024-07-31T14:10:40.719+0200 event=org.dcache.xrootd.connection.end session=door:xrootd-ccdcacli501@xrootd-ccdcacli501Domain:AAYeifuYzUA

Adrien