Categories
DevOps

How to debug ZooKeeper SSL connection issues

Debug ZooKeeper SSL connection issues.

Ensure that -Djavax.net.debug=ssl option is defined.

$ sudo -u zookeeper -i cat zookeeper/conf/zookeeper-env.sh
JVMFLAGS="-Djavax.net.debug=ssl"

Restart service.

$ sudo systemctl restart zookeeper.service

Inspect log file to identify an issue.

$ tail -f /opt/zookeeper/zookeeper/logs/zookeeper-zookeeper-server-zookeeper1.example.org.out 

Expired certificate.

[...]
2040-01-01 00:00:32,390 [myid:1] - ERROR [nioEventLoopGroup-4-1:NettyServerCnxnFactory$CertificateVerifier@457] - Unsuccessful handshake with session 0x0          
javax.net.ssl|WARNING|2D|nioEventLoopGroup-4-1|2040-01-01 24:00:32.391 UTC|SSLEngineOutputRecord.java:168|outbound has closed, ignore outbound application data
2040-01-01 00:00:32,392 [myid:1] - WARN  [nioEventLoopGroup-4-1:NettyServerCnxnFactory$CnxnChannelHandler@293] - Exception caught
io.netty.handler.codec.DecoderException: javax.net.ssl.SSLHandshakeException: PKIX path validation failed: java.security.cert.CertPathValidatorException: validity 
check failed                                                                                                                                                       
        at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:478)                  
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)                 
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)    
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)       
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)                              
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: javax.net.ssl.SSLHandshakeException: PKIX path validation failed: java.security.cert.CertPathValidatorException: validity check failed
        at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:131)
        at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:349)
        at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:292)
        at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:287)
        at java.base/sun.security.ssl.CertificateMessage$T12CertificateConsumer.checkClientCerts(CertificateMessage.java:700)
        at java.base/sun.security.ssl.CertificateMessage$T12CertificateConsumer.onCertificate(CertificateMessage.java:411)
        at java.base/sun.security.ssl.CertificateMessage$T12CertificateConsumer.consume(CertificateMessage.java:375)
        at java.base/sun.security.ssl.SSLHandshake.consume(SSLHandshake.java:392) 
        at java.base/sun.security.ssl.HandshakeContext.dispatch(HandshakeContext.java:443)
        at java.base/sun.security.ssl.SSLEngineImpl$DelegatedTask$DelegatedAction.run(SSLEngineImpl.java:1074)
        at java.base/sun.security.ssl.SSLEngineImpl$DelegatedTask$DelegatedAction.run(SSLEngineImpl.java:1061)
        at java.base/java.security.AccessController.doPrivileged(Native Method)
        at java.base/sun.security.ssl.SSLEngineImpl$DelegatedTask.run(SSLEngineImpl.java:1008)
        at io.netty.handler.ssl.SslHandler.runAllDelegatedTasks(SslHandler.java:1557)
        at io.netty.handler.ssl.SslHandler.runDelegatedTasks(SslHandler.java:1571)
        at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1455)
        at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1282)
        at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1329)
        at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:508)
        at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:447)
        ... 17 more
Caused by: sun.security.validator.ValidatorException: PKIX path validation failed: java.security.cert.CertPathValidatorException: validity check failed
        at java.base/sun.security.validator.PKIXValidator.doValidate(PKIXValidator.java:369)
        at java.base/sun.security.validator.PKIXValidator.engineValidate(PKIXValidator.java:263)
        at java.base/sun.security.validator.Validator.validate(Validator.java:264)
        at java.base/sun.security.ssl.X509TrustManagerImpl.validate(X509TrustManagerImpl.java:313)
        at java.base/sun.security.ssl.X509TrustManagerImpl.checkTrusted(X509TrustManagerImpl.java:276)
        at java.base/sun.security.ssl.X509TrustManagerImpl.checkClientTrusted(X509TrustManagerImpl.java:135)
        at org.apache.zookeeper.common.ZKTrustManager.checkClientTrusted(ZKTrustManager.java:99)
        at java.base/sun.security.ssl.CertificateMessage$T12CertificateConsumer.checkClientCerts(CertificateMessage.java:682)
        ... 32 more
Caused by: java.security.cert.CertPathValidatorException: validity check failed
        at java.base/sun.security.provider.certpath.PKIXMasterCertPathValidator.validate(PKIXMasterCertPathValidator.java:135)
        at java.base/sun.security.provider.certpath.PKIXCertPathValidator.validate(PKIXCertPathValidator.java:224)
        at java.base/sun.security.provider.certpath.PKIXCertPathValidator.validate(PKIXCertPathValidator.java:144)
        at java.base/sun.security.provider.certpath.PKIXCertPathValidator.engineValidate(PKIXCertPathValidator.java:83)
        at java.base/java.security.cert.CertPathValidator.validate(CertPathValidator.java:309)
        at java.base/sun.security.validator.PKIXValidator.doValidate(PKIXValidator.java:364)
        ... 39 more
Caused by: java.security.cert.CertificateExpiredException: NotAfter: Sun Aug 28 08:05:27 UTC 2012
        at java.base/sun.security.x509.CertificateValidity.valid(CertificateValidity.java:277)
        at java.base/sun.security.x509.X509CertImpl.checkValidity(X509CertImpl.java:675)
        at java.base/sun.security.provider.certpath.BasicChecker.verifyValidity(BasicChecker.java:190)
        at java.base/sun.security.provider.certpath.BasicChecker.check(BasicChecker.java:144)
        at java.base/sun.security.provider.certpath.PKIXMasterCertPathValidator.validate(PKIXMasterCertPathValidator.java:125)
        ... 44 more
[...]

Mismatched certificates.

[...]
2021-08-28 00:00:05,752 [myid:1] - ERROR [nioEventLoopGroup-4-4:NettyServerCnxnFactory$CertificateVerifier@457] - Unsuccessful handshake with session 0x0                  2021-08-28 00:00:05,753 [myid:1] - WARN  [nioEventLoopGroup-4-4:NettyServerCnxnFactory$CnxnChannelHandler@293] - Exception caught                                          io.netty.handler.codec.DecoderException: javax.net.ssl.SSLHandshakeException: Received fatal alert: decrypt_error                                                                  at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:478)                                                                                   at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)                                                                                  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)                                                                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)                                                                at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)                                                                  at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)                                                                       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)                                                                at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)                                                                at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)                                                                        
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)                                                              
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)                                                                                             at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)                                                                                   at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)                                                                                    
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)              
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)                                                                            at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)                                                                                               at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)                                                                           
        at java.base/java.lang.Thread.run(Thread.java:829)                           
Caused by: javax.net.ssl.SSLHandshakeException: Received fatal alert: decrypt_error                                                                                        
        at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:131)       
        at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:117)       
        at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:336)                                                                                            at java.base/sun.security.ssl.Alert$AlertConsumer.consume(Alert.java:293)                                                                                                  at java.base/sun.security.ssl.TransportContext.dispatch(TransportContext.java:185)                                                                                 
        at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:172)     
        at java.base/sun.security.ssl.SSLEngineImpl.decode(SSLEngineImpl.java:681)                                                                                                 at java.base/sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:636)                                                                                             at java.base/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:454)                                                                                                 at java.base/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:433)                                                                                         
        at java.base/javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:637)              
        at io.netty.handler.ssl.SslHandler$SslEngineType$3.unwrap(SslHandler.java:282)                                                                                     
        at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1387)              
        at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1282)                                                                                       
        at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1329)              
        at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:508)                                                               at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:447)                                                                           
        ... 17 more                       
javax.net.ssl|ALL|2B|nioEventLoopGroup-4-1|2021-08-28 24:00:05.882 UTC|X509Authentication.java:301|No X.509 cert selected for EC                                           javax.net.ssl|DEBUG|2B|nioEventLoopGroup-4-1|2021-08-28 24:00:05.890 UTC|Alert.java:238|Received alert message (                                                           
"Alert": {                                
  "level"      : "fatal",                 
  "description": "decrypt_error"          
}                                         
)                                  
javax.net.ssl|ERROR|2B|nioEventLoopGroup-4-1|2021-08-28 24:00:05.891 UTC|TransportContext.java:341|Fatal (DECRYPT_ERROR): Received fatal alert: decrypt_error (            
"throwable" : {                           
  javax.net.ssl.SSLHandshakeException: Received fatal alert: decrypt_error           
        at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:131)       
        at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:117)       
        at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:336)                                                                                    
        at java.base/sun.security.ssl.Alert$AlertConsumer.consume(Alert.java:293)                                                                                          
        at java.base/sun.security.ssl.TransportContext.dispatch(TransportContext.java:185)                                                                                 
        at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:172)     
        at java.base/sun.security.ssl.SSLEngineImpl.decode(SSLEngineImpl.java:681)                                                                                         
        at java.base/sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:636)                                                                                     
        at java.base/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:454)                                                                                         
        at java.base/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:433)                                                                                         
        at java.base/javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:637)              
        at io.netty.handler.ssl.SslHandler$SslEngineType$3.unwrap(SslHandler.java:282)                                                                                     
        at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1387)              
        at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1282)                                                                                       
        at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1329)              
        at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:508)                                                       
        at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:447)                                                                           
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)                                                                          
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)                                                        
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)                                                        
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)                                                          
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)                                                               
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)                                                        
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)                                                        
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)                                                                        
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)                                                                 
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)                                                                                     
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)                                                                           
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)                                                                                    
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)              
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)                                                                    
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)                                                                                       
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)                                                                           
        at java.base/java.lang.Thread.run(Thread.java:829)}                          

)
[...]

It is easier to debug SSL issues now.