[NETCONF-552] Controller can not establish netconf connection with testtool Created: 01/Aug/18  Updated: 20/Nov/18  Resolved: 20/Nov/18

Status: Resolved
Project: netconf
Component/s: netconf
Affects Version/s: Fluorine
Fix Version/s: Fluorine

Type: Bug Priority: Medium
Reporter: wang senxiao Assignee: wang senxiao
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified


 Description   

I built the netconf connection in this way as before, but it suddenly failed:

PUT    http://10.10.19.15:8181/restconf/config/network-topology:network-topology/topology/topology-netconf/node/node1

<node xmlns="urn:TBD:params:xml:ns:yang:network-topology">
<node-id>node1</node-id>
<host xmlns="urn:opendaylight:netconf-node-topology">10.10.19.15</host>
<port xmlns="urn:opendaylight:netconf-node-topology">17830</port>
<username xmlns="urn:opendaylight:netconf-node-topology">admin</username>
<password xmlns="urn:opendaylight:netconf-node-topology">admin</password>
<tcp-only xmlns="urn:opendaylight:netconf-node-topology">false</tcp-only>
<keepalive-delay xmlns="urn:opendaylight:netconf-node-topology">0</keepalive-delay>
</node>

I think it is a bug. I use the testtool with version 1.4.3-SNAPSHOT in Netconf master branch and controller with feature odl-netconf-console 1.5.0-SNAPSHOT, the karaf log shows:

2018-08-01T09:34:49,377 | DEBUG | nioEventLoopGroupCloseable-4-1 | AsyncSshHandler | 281 - org.opendaylight.netconf.netty-util - 1.5.0.SNAPSHOT | Starting SSH to /10.96.33.30:17830 on channel: [id: 0x7024df42]
2018-08-01T09:34:49,377 | DEBUG | nioEventLoopGroupCloseable-4-1 | DefaultConfigFileHostEntryResolver | 54 - org.apache.sshd.core - 1.6.0 | resolveEffectiveHost(admin@10.96.33.30:17830) => null
2018-08-01T09:34:49,378 | DEBUG | nioEventLoopGroupCloseable-4-1 | SshClient | 54 - org.apache.sshd.core - 1.6.0 | connect(admin@10.96.33.30:17830) no overrides
2018-08-01T09:34:49,381 | DEBUG | nioEventLoopGroupCloseable-4-1 | Nio2Connector | 54 - org.apache.sshd.core - 1.6.0 | Connecting to /10.96.33.30:17830
2018-08-01T09:34:49,385 | DEBUG | nioEventLoopGroupCloseable-4-1 | Nio2Connector | 54 - org.apache.sshd.core - 1.6.0 | setOption(SO_REUSEADDR)[true] from property=socket-reuseaddr
2018-08-01T09:34:49,397 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | Nio2Session | 54 - org.apache.sshd.core - 1.6.0 | Creating IoSession on /172.20.68.20:49994 from /10.96.33.30:17830
2018-08-01T09:34:49,430 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | ClientSessionImpl | 54 - org.apache.sshd.core - 1.6.0 | Client session created: Nio2Session[local=/172.20.68.20:49994, remote=/10.96.33.30:17830]
2018-08-01T09:34:49,434 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | ClientUserAuthService | 54 - org.apache.sshd.core - 1.6.0 | ClientUserAuthService(ClientSessionImpl[null@/10.96.33.30:17830]) client methods: [publickey, keyboard-interactive, password]
2018-08-01T09:34:49,454 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | ClientSessionImpl | 54 - org.apache.sshd.core - 1.6.0 | sendIdentification(ClientSessionImpl[null@/10.96.33.30:17830]): SSH-2.0-SSHD-CORE-1.6.0
2018-08-01T09:34:49,454 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | Nio2Session | 54 - org.apache.sshd.core - 1.6.0 | Writing 25 bytes
2018-08-01T09:34:49,457 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | Nio2Session | 54 - org.apache.sshd.core - 1.6.0 | handleCompletedWriteCycle(Nio2Session[local=/172.20.68.20:49994, remote=/10.96.33.30:17830]) finished writing len=25
2018-08-01T09:34:49,458 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | ClientSessionImpl | 54 - org.apache.sshd.core - 1.6.0 | sendKexInit(ClientSessionImpl[null@/10.96.33.30:17830]) Send SSH_MSG_KEXINIT
2018-08-01T09:34:49,459 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | Nio2Session | 54 - org.apache.sshd.core - 1.6.0 | Writing 592 bytes
2018-08-01T09:34:49,460 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | Nio2Session | 54 - org.apache.sshd.core - 1.6.0 | handleCompletedWriteCycle(Nio2Session[local=/172.20.68.20:49994, remote=/10.96.33.30:17830]) finished writing len=592
2018-08-01T09:34:49,484 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | ClientSessionImpl | 54 - org.apache.sshd.core - 1.6.0 | addPasswordIdentity(ClientSessionImpl[admin@/10.96.33.30:17830]) SHA256:jGl25bVBBBW96Qi9Te4V37Fnqchz/Eu4qB9vKrRIqRg
2018-08-01T09:34:49,486 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | ClientUserAuthService | 54 - org.apache.sshd.core - 1.6.0 | auth(ClientSessionImpl[admin@/10.96.33.30:17830])[ssh-connection] send SSH_MSG_USERAUTH_REQUEST for 'none'
2018-08-01T09:34:49,496 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | ClientSessionImpl | 54 - org.apache.sshd.core - 1.6.0 | writePacket(ClientSessionImpl[admin@/10.96.33.30:17830])[SSH_MSG_USERAUTH_REQUEST] Start flagging packets as pending until key exchange is done
2018-08-01T09:34:49,502 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | Nio2Session | 54 - org.apache.sshd.core - 1.6.0 | handleReadCycleCompletion(Nio2Session[local=/172.20.68.20:49994, remote=/10.96.33.30:17830]) read 25 bytes
2018-08-01T09:34:49,502 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | ClientSessionImpl | 54 - org.apache.sshd.core - 1.6.0 | doReadIdentification(ClientSessionImpl[admin@/10.96.33.30:17830]) line='SSH-2.0-SSHD-CORE-1.6.0'
2018-08-01T09:34:49,503 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-1 | ClientSessionImpl | 54 - org.apache.sshd.core - 1.6.0 | readIdentification(ClientSessionImpl[admin@/10.96.33.30:17830]) Server version string: SSH-2.0-SSHD-CORE-1.6.0
2018-08-01T09:34:49,902 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-2 | Nio2Session | 54 - org.apache.sshd.core - 1.6.0 | handleReadCycleCompletion(Nio2Session[local=/172.20.68.20:49994, remote=/10.96.33.30:17830]) read 552 bytes
2018-08-01T09:34:49,902 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-2 | ClientSessionImpl | 54 - org.apache.sshd.core - 1.6.0 | handleKexInit(ClientSessionImpl[admin@/10.96.33.30:17830]) SSH_MSG_KEXINIT
2018-08-01T09:34:49,905 | DEBUG | sshd-SshClient[675d4333]nio2-thread-2 | ClientSessionImpl | 54 - org.apache.sshd.core - 1.6.0 | setNegotiationResult(ClientSessionImpl[admin@/10.96.33.30:17830]) Kex: server>client aes128-ctr hmac-md5 none
2018-08-01T09:34:49,905 | DEBUG | sshd-SshClient[675d4333]nio2-thread-2 | ClientSessionImpl | 54 - org.apache.sshd.core - 1.6.0 | setNegotiationResult(ClientSessionImpl[admin@/10.96.33.30:17830]) Kex: client>server aes128-ctr hmac-md5 none
2018-08-01T09:34:50,775 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-2 | DHGClient | 54 - org.apache.sshd.core - 1.6.0 | init(DHGClient[ecdh-sha2-nistp521])[ClientSessionImpl[admin@/10.96.33.30:17830]] Send SSH_MSG_KEXDH_INIT
2018-08-01T09:34:50,777 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-2 | Nio2Session | 54 - org.apache.sshd.core - 1.6.0 | Writing 152 bytes
2018-08-01T09:34:50,777 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-2 | Nio2Session | 54 - org.apache.sshd.core - 1.6.0 | handleCompletedWriteCycle(Nio2Session[local=/172.20.68.20:49994, remote=/10.96.33.30:17830]) finished writing len=152
2018-08-01T09:34:50,779 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-2 | Nio2Session | 54 - org.apache.sshd.core - 1.6.0 | handleReadCycleCompletion(Nio2Session[local=/172.20.68.20:49994, remote=/10.96.33.30:17830]) Socket has been disconnected (result=-1), closing IoSession now
2018-08-01T09:34:50,779 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-2 | Nio2Session | 54 - org.apache.sshd.core - 1.6.0 | close(Nio2Session[local=/172.20.68.20:49994, remote=/10.96.33.30:17830]) Closing immediately
2018-08-01T09:34:50,780 | DEBUG | sshd-SshClient[675d4333]-nio2-thread-2 | ClientSessionImpl | 54 - org.apache.sshd.core - 1.6.0 | close(ClientSessionImpl[admin@/10.96.33.30:17830]) Closing immediately
2018-08-01T09:34:50,780 | WARN | sshd-SshClient[675d4333]-nio2-thread-2 | AsyncSshHandler | 281 - org.opendaylight.netconf.netty-util - 1.5.0.SNAPSHOT | Unable to setup SSH connection on channel: [id: 0x7024df42]
org.apache.sshd.common.SshException: Session is being closed
at org.apache.sshd.client.session.ClientSessionImpl.preClose(ClientSessionImpl.java:126) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:80) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.sessionClosed(AbstractSessionIoHandler.java:48) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.io.nio2.Nio2Session.doCloseImmediately(Nio2Session.java:216) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:81) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.io.nio2.Nio2Session.handleReadCycleCompletion(Nio2Session.java:298) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:264) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:261) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38) ~[54:org.apache.sshd.core:1.6.0]
at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37) ~[54:org.apache.sshd.core:1.6.0]
at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126) ~[?:?]
at sun.nio.ch.Invoker.invokeDirect(Invoker.java:157) ~[?:?]
at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implRead(UnixAsynchronousSocketChannelImpl.java:553) ~[?:?]
at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:276) ~[?:?]
at sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297) ~[?:?]
at org.apache.sshd.common.io.nio2.Nio2Session.doReadCycle(Nio2Session.java:312) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.io.nio2.Nio2Session.handleReadCycleCompletion(Nio2Session.java:288) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:264) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:261) ~[54:org.apache.sshd.core:1.6.0]
at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38) ~[54:org.apache.sshd.core:1.6.0]
at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37) [54:org.apache.sshd.core:1.6.0]
at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126) [?:?]
at sun.nio.ch.Invoker$2.run(Invoker.java:218) [?:?]
at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]

 Comments   
Comment by Jakub Morvay [ 06/Aug/18 ]

Hi Wang,

Can you be please more specific about your setting? How do you start a netconf test-tool, how exactly do you mount it afterwards, if you can create ssh connection to it manually etc.

Also please try to use master (Fluorine) version of the test-tool as there are currently interoperability issues between Oxygen test-tool and master (fluorine) netconf southbound plugin.

Comment by Jakub Morvay [ 06/Sep/18 ]

wsx25289 any update on this issue?

Comment by wang senxiao [ 07/Sep/18 ]

Hi Jakub
Sorry for the late reply. I tried with the master version of test-tool(1.6.0), it also failed. By the way I start test-tool with command:java -jar netconf-testtool-1.2.2-SNAPSHOT-executable.jar --device-count 3 --debug true --schemas-dir ${filepath}.

Comment by Jakub Morvay [ 02/Oct/18 ]

Sorry for late reply,

Can you please provide us with karaf log and testtool logs?

Comment by Jakub Morvay [ 20/Nov/18 ]

Resolving this as "Cannot Reproduce". There is not enough reported information to be able for us to reproduce the issue.

wsx25289 Once you can provide us with additional karaf.log, setup and enviroment information, please feel free to reopen this issue again.

Generated at Wed Feb 07 20:15:19 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.