tls-debug.log
[NETCONF-854] mount with TLS fails on phosphorus-sr1 Created: 28/Jan/22 Updated: 11/Feb/22 Resolved: 11/Feb/22 |
|
| Status: | Resolved |
| Project: | netconf |
| Component/s: | netconf |
| Affects Version/s: | 2.0.11 |
| Fix Version/s: | 2.0.13 |
| Type: | Bug | Priority: | Medium |
| Reporter: | Michael Dürre | Assignee: | Robert Varga |
| Resolution: | Done | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Attachments: |
tls-debug.log
|
| Description |
|
This feature was working in silicon-sr1. How to reproduce: * mount device with TLS PUT /rests/data/network-topology:network-topology/topology=topology-netconf/node=tlstest <node xmlns="urn:TBD:params:xml:ns:yang:network-topology"> <node-id>tlstest</node-id> <key-based xmlns="urn:opendaylight:netconf-node-topology"> <key-id xmlns="urn:opendaylight:netconf-node-topology">ODL_private_key_0</key-id> <username xmlns="urn:opendaylight:netconf-node-topology">netconf</username> </key-based> <host xmlns="urn:opendaylight:netconf-node-topology">10.20.35.147</host> <port xmlns="urn:opendaylight:netconf-node-topology">31500</port> <tcp-only xmlns="urn:opendaylight:netconf-node-topology">false</tcp-only> <protocol xmlns="urn:opendaylight:netconf-node-topology"> <name xmlns="urn:opendaylight:netconf-node-topology">TLS</name> </protocol> <max-connection-attempts xmlns="urn:opendaylight:netconf-node-topology">2</max-connection-attempts> </node> * wait for connected state... will never happen
GET /rests/data/network-topology:network-topology/topology=topology-netconf
{
"network-topology:topology": [
{
"topology-id": "topology-netconf",
"node": [
{
"node-id": "tlstest",
"netconf-node-topology:connection-status": "unable-to-connect",
"netconf-node-topology:connected-message": "javax.net.ssl.SSLHandshakeException: Received fatal alert: decrypt_error",
"netconf-node-topology:max-connection-attempts": 2,
"netconf-node-topology:key-based": {
"username": "netconf",
"key-id": ""
},
"netconf-node-topology:host": "10.20.35.147",
"netconf-node-topology:port": 31500,
"netconf-node-topology:protocol": {
"name": "TLS"
},
"netconf-node-topology:tcp-only": false
}
]
}
]
}
The following exception is thrown in karaf.log 2022-01-28T03:51:09,695 | INFO | globalWorkerGroup-3-1 | AbstractNetconfSessionNegotiator | 352 - org.opendaylight.netconf.netty-util - 2.0.11 | Unexpected error during negotiation on channel [id: 0x50cee553, L:0.0.0.0/0.0.0.0:34890]2022-01-28T03:51:09,695 | INFO | globalWorkerGroup-3-1 | AbstractNetconfSessionNegotiator | 352 - org.opendaylight.netconf.netty-util - 2.0.11 | Unexpected error during negotiation on channel [id: 0x50cee553, L:0.0.0.0/0.0.0.0:34890]io.netty.handler.codec.DecoderException: javax.net.ssl.SSLHandshakeException: Received fatal alert: decrypt_error at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:477) ~[bundleFile:4.1.69.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) ~[bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [bundleFile:4.1.69.Final] at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) [bundleFile:4.1.69.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) [bundleFile:4.1.69.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) [bundleFile:4.1.69.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) [bundleFile:4.1.69.Final] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [bundleFile:4.1.69.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [bundleFile:4.1.69.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.69.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.69.Final] at java.lang.Thread.run(Unknown Source) [?:?]Caused by: javax.net.ssl.SSLHandshakeException: Received fatal alert: decrypt_error at sun.security.ssl.Alert.createSSLException(Unknown Source) ~[?:?] at sun.security.ssl.Alert.createSSLException(Unknown Source) ~[?:?] at sun.security.ssl.TransportContext.fatal(Unknown Source) ~[?:?] at sun.security.ssl.Alert$AlertConsumer.consume(Unknown Source) ~[?:?] at sun.security.ssl.TransportContext.dispatch(Unknown Source) ~[?:?] at sun.security.ssl.SSLTransport.decode(Unknown Source) ~[?:?] at sun.security.ssl.SSLEngineImpl.decode(Unknown Source) ~[?:?] at sun.security.ssl.SSLEngineImpl.readRecord(Unknown Source) ~[?:?] at sun.security.ssl.SSLEngineImpl.unwrap(Unknown Source) ~[?:?] at sun.security.ssl.SSLEngineImpl.unwrap(Unknown Source) ~[?:?] at javax.net.ssl.SSLEngine.unwrap(Unknown Source) ~[?:?] at io.netty.handler.ssl.SslHandler$SslEngineType$3.unwrap(SslHandler.java:296) ~[bundleFile:4.1.69.Final] at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1342) ~[bundleFile:4.1.69.Final] at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1235) ~[bundleFile:4.1.69.Final] at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1284) ~[bundleFile:4.1.69.Final] at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507) ~[bundleFile:4.1.69.Final] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446) ~[bundleFile:4.1.69.Final] ... 17 more2022-01-28T03:51:09,735 | INFO | opendaylight-cluster-data-notification-dispatcher-45 | NetconfNodeStateServiceImpl | 234 - org.onap.ccsdk.features.sdnr.wt.phosphorus.sr1.sdnr-wt-netconfnode-state-service-provider - 1.3.0.SNAPSHOT | L1 TreeChange enter changes:12022-01-28T03:51:09,735 | INFO | opendaylight-cluster-data-notification-dispatcher-41 | NetconfNodeStateServiceImpl | 234 - org.onap.ccsdk.features.sdnr.wt.phosphorus.sr1.sdnr-wt-netconfnode-state-service-provider - 1.3.0.SNAPSHOT | L2 TreeChange enter changes:12022-01-28T03:51:09,736 | INFO | opendaylight-cluster-data-notification-dispatcher-41 | NetconfNodeStateServiceImpl | 234 - org.onap.ccsdk.features.sdnr.wt.phosphorus.sr1.sdnr-wt-netconfnode-state-service-provider - 1.3.0.SNAPSHOT | L2 TreeChange leave2022-01-28T03:51:09,736 | INFO | opendaylight-cluster-data-notification-dispatcher-45 | NetconfNodeStateServiceImpl | 234 - org.onap.ccsdk.features.sdnr.wt.phosphorus.sr1.sdnr-wt-netconfnode-state-service-provider - 1.3.0.SNAPSHOT | L1 NETCONF id:Uri{_value=tlstest} t:WRITE created false before:false after:false akkaIsCluster:false cl stat:null2022-01-28T03:51:09,737 | INFO | opendaylight-cluster-data-notification-dispatcher-45 | DeviceManagerNetconfNotConnectHandler | 212 - org.onap.ccsdk.features.sdnr.wt.phosphorus.sr1.sdnr-wt-devicemanager-core-provider - 1.3.0.SNAPSHOT | onStateChange Uri{_value=tlstest}2022-01-28T03:51:09,721 | WARN | globalWorkerGroup-3-2 | ChannelInitializer | 66 - io.netty.common - 4.1.69.Final | Failed to initialize a channel. Closing: [id: 0xd0dc51df]io.netty.channel.ChannelPipelineException: org.opendaylight.netconf.nettyutil.ReconnectPromise$1 is not a @Sharable handler, so can't be added or removed multiple times. at io.netty.channel.DefaultChannelPipeline.checkMultiplicity(DefaultChannelPipeline.java:600) ~[bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline.addLast(DefaultChannelPipeline.java:202) ~[bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline.addLast(DefaultChannelPipeline.java:381) ~[bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline.addLast(DefaultChannelPipeline.java:370) ~[bundleFile:4.1.69.Final] at org.opendaylight.netconf.nettyutil.ReconnectPromise.lambda$lockedConnect$0(ReconnectPromise.java:114) ~[bundleFile:?] at org.opendaylight.netconf.nettyutil.AbstractNetconfDispatcher$3.initChannel(AbstractNetconfDispatcher.java:202) ~[bundleFile:?] at org.opendaylight.netconf.nettyutil.AbstractNetconfDispatcher$3.initChannel(AbstractNetconfDispatcher.java:199) ~[bundleFile:?] at io.netty.channel.ChannelInitializer.initChannel(ChannelInitializer.java:129) [bundleFile:4.1.69.Final] at io.netty.channel.ChannelInitializer.handlerAdded(ChannelInitializer.java:112) [bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannelHandlerContext.callHandlerAdded(AbstractChannelHandlerContext.java:938) [bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline.callHandlerAdded0(DefaultChannelPipeline.java:609) [bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline.access$100(DefaultChannelPipeline.java:46) [bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline$PendingHandlerAddedTask.execute(DefaultChannelPipeline.java:1463) [bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline.callHandlerAddedForAllHandlers(DefaultChannelPipeline.java:1115) [bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline.invokeHandlerAddedIfNeeded(DefaultChannelPipeline.java:650) [bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannel$AbstractUnsafe.register0(AbstractChannel.java:514) [bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannel$AbstractUnsafe.access$200(AbstractChannel.java:429) [bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannel$AbstractUnsafe$1.run(AbstractChannel.java:486) [bundleFile:4.1.69.Final] at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [bundleFile:4.1.69.Final] at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) [bundleFile:4.1.69.Final] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) [bundleFile:4.1.69.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [bundleFile:4.1.69.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.69.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.69.Final] at java.lang.Thread.run(Unknown Source) [?:?]2022-01-28T03:51:09,742 | INFO | opendaylight-cluster-data-notification-dispatcher-45 | Capabilities | 233 - org.onap.ccsdk.features.sdnr.wt.phosphorus.sr1.sdnr-wt-netconfnode-state-service-model - 1.3.0.SNAPSHOT | GetAvailableCapabilities for node2022-01-28T03:51:09,742 | INFO | opendaylight-cluster-data-notification-dispatcher-45 | Capabilities | 233 - org.onap.ccsdk.features.sdnr.wt.phosphorus.sr1.sdnr-wt-netconfnode-state-service-model - 1.3.0.SNAPSHOT | GetUnavailableCapabilities for node2022-01-28T03:51:09,743 | INFO | opendaylight-cluster-data-notification-dispatcher-45 | HtDatabaseEventsService | 210 - org.onap.ccsdk.features.sdnr.wt.phosphorus.sr1.sdnr-wt-data-provider-provider - 1.3.0.SNAPSHOT | update networkelement-connection for tlstest with data NetworkElementConnection{coreModelCapability=Unsupported, deviceType=Unknown, host=10.20.35.147, id=tlstest, isRequired=false, mountMethod=KeyAuth, nodeDetails=NodeDetails{availableCapabilities=[], unavailableCapabilities=[]}, nodeId=tlstest, port=31500, status=UnableToConnect, tlsKey=, username=netconf}2022-01-28T03:51:09,725 | ERROR | globalEventExecutor-1-1 | AbstractNetconfTopology | 362 - org.opendaylight.netconf.topology - 2.0.11 | Connector for tlstest failedio.netty.handler.codec.DecoderException: javax.net.ssl.SSLHandshakeException: Received fatal alert: decrypt_error at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:477) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) ~[?:?] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[bundleFile:4.1.69.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[bundleFile:4.1.69.Final] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[bundleFile:4.1.69.Final] at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) ~[bundleFile:4.1.69.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) ~[bundleFile:4.1.69.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) ~[bundleFile:4.1.69.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) ~[bundleFile:4.1.69.Final] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) ~[bundleFile:4.1.69.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) ~[bundleFile:4.1.69.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.69.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.69.Final] at java.lang.Thread.run(Unknown Source) [?:?]Caused by: javax.net.ssl.SSLHandshakeException: Received fatal alert: decrypt_error at sun.security.ssl.Alert.createSSLException(Unknown Source) ~[?:?] at sun.security.ssl.Alert.createSSLException(Unknown Source) ~[?:?] at sun.security.ssl.TransportContext.fatal(Unknown Source) ~[?:?] at sun.security.ssl.Alert$AlertConsumer.consume(Unknown Source) ~[?:?] at sun.security.ssl.TransportContext.dispatch(Unknown Source) ~[?:?] at sun.security.ssl.SSLTransport.decode(Unknown Source) ~[?:?] at sun.security.ssl.SSLEngineImpl.decode(Unknown Source) ~[?:?] at sun.security.ssl.SSLEngineImpl.readRecord(Unknown Source) ~[?:?] at sun.security.ssl.SSLEngineImpl.unwrap(Unknown Source) ~[?:?] at sun.security.ssl.SSLEngineImpl.unwrap(Unknown Source) ~[?:?] at javax.net.ssl.SSLEngine.unwrap(Unknown Source) ~[?:?] at io.netty.handler.ssl.SslHandler$SslEngineType$3.unwrap(SslHandler.java:296) ~[?:?] at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1342) ~[?:?] at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1235) ~[?:?] at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1284) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446) ~[?:?] ... 17 more |
| Comments |
| Comment by Michael Dürre [ 28/Jan/22 ] |
|
I have run the test again with the additional env JAVA_NON_DEBUG_OPTS=-Djavax.net.debug=all and attached the output to the ticket (tls-debug.log). I hope it helps. |
| Comment by Michael Dürre [ 02/Feb/22 ] |
|
So no idea? Since it sounds like a netty issue it is maybe caused by this? https://git.opendaylight.org/gerrit/gitweb?p=netconf.git;a=commit;h=966a5b2c53caf54af837d4d67ff25d31bef32277 |
| Comment by Robert Varga [ 02/Feb/22 ] |
|
The device is saying, as it has sent an alert message javax.net.ssl|DEBUG|03 3C|globalWorkerGroup-3-1|2022-01-28 05:15:23.278 GMT|null:-1|Received alert message (
"Alert": {
"level" : "fatal",
"description": "decrypt_error"
}
There is no provision in TLS1.2 to learn what the underlying cause, hence you need to diagnose this on the device side. |
| Comment by Michael Dürre [ 09/Feb/22 ] |
|
good news. I have found the issue. It is the order of the certificate chain of the private key. So workaround for now is to fill the whole netconf-keystore with the data of a silicon installation. Since we use the same script to install the certificates the order of the rpc calls do not differ to silicon.
But still investigating what exactly the problem is. I mean which step works differently from silicon to phosphorus |
| Comment by Michael Dürre [ 11/Feb/22 ] |
|
So it looks like it is a problem of the add-private-key rpc. I add a payload like this: {
"input": {
"private-key": {
"name": "ODL_private_key_0",
"data": "MIIEpAIBAAKC....",
"certificate-chain":[
"MIIECTCCAvGgAw...",
"MIID7TCCAtWgAw...."
]
}
}
}
but if I request the netconf keystore again I see the private key installed with a mixed up order of the certificate chain GET /rests/data/netconf-keystore:keystore/private-key=ODL_private_key_0 {
"netconf-keystore:private-key": [{
"name": "ODL_private_key_0",
"data": "MIIEpAIBAAKC...",
"certificate-chain": [
"MIID7TCCAtWgAw...",
"MIIECTCCAvGgAw..."
]
}]
}
|
| Comment by Michael Dürre [ 11/Feb/22 ] |
|
I now also tried to do this and it did not worked. I mean it mixed up the cert chain again. PUT /rests/data/netconf-keystore:keystore/private-key=ODL_private_key_0
{
"private-key": [{
"name": "ODL_private_key_0",
"data": "MIIEpAIBAAKC...",
"certificate-chain": [
"MIID7TCCAtWgAw...",
"MIIECTCCAvGgAw..."
]
}]
}
|
| Comment by Robert Varga [ 11/Feb/22 ] |
|
Thanks for the investigation. The problem is that certificate-chain is not marked as user-ordered. |