Uploaded image for project: 'netconf'
  1. netconf
  2. NETCONF-681

Netconf Callhome SSH: drop connections

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Medium Medium
    • 3.0.6, 4.0.2
    • Neon, Neon SR1, Sodium, Neon SR2, Neon SR3, Magnesium, Sodium SR1, Sodium SR2
    • None

      1) Netconf Callhome SSH: drop connection after 10 min (600000ms) idle.

       [ERR]: Session 1: SSH channel poll error (Received SSH_MSG_DISCONNECT: 2:User session has timed out idling after 600000 ms.).

      That's mean SSH keepalive ( https://tools.ietf.org/html/rfc8071#section-4.1 poin S7) for call home connection with Netopeer2 not works. Guys from Netopeer2 thinking it's ODL problem, because libssh and openssl no have API for this functionality: https://github.com/CESNET/libnetconf2/issues/201.

       

      rovarga was wrote: 

      This is just the default Mina SSHD configuration, nothing specific. It
also is an inactivity delay, it does not strictly require keepalives.
Not sure how to change the config, though. Can you file an issue with
jira.opendaylight.org. 

      Ok, issue is here.

       

      2) Netconf Callhome SSH: drop connection after 1 hour force.

      Maybe dummy keepalive by Netconf notifications solve my problem? I was create model and subscribe it from Opendeylight. About hour (+3-5min) connection force closing and open again. In Netopeer log i see: 

      Sat May  2 14:20:46 2020 daemon.err netopeer2-server[2967]: [2020/05/02 14:20:46.467772, 1] ssh_packet_kexinit:  Other side initiating key re-exchange
Sat May  2 14:20:46 2020 daemon.err netopeer2-server[2967]: [2020/05/02 14:20:46.469413, 2] ssh_kex_select_methods:  Negotiated ecdh-sha2-nistp521,ssh-rsa,aes128-ctr,aes128-ctr,hmac-sha1,hmac-sha1,none,none,,
Sat May  2 14:20:47 2020 daemon.err netopeer2-server[2967]: [2020/05/02 14:20:47.191284, 2] ssh_server_ecdh_init:  SSH_MSG_KEXDH_REPLY sent
Sat May  2 14:20:47 2020 daemon.err netopeer2-server[2967]: [2020/05/02 14:20:47.194856, 2] ssh_server_ecdh_init:  SSH_MSG_NEWKEYS sent
Sat May  2 14:20:47 2020 daemon.err netopeer2-server[2967]: Session 46: SSH channel poll error (Received SSH_MSG_DISCONNECT: 9:Server key did not validate).
Sat May  2 14:20:47 2020 daemon.info netopeer2-server[2967]: Session 46: thread 4 event session terminated.
Sat May  2 14:20:47 2020 daemon.err netopeer2-server[2967]: [2020/05/02 14:20:47.208409, 1] ssh_packet_disconnect_callback:  Received SSH_MSG_DISCONNECT: 9:Server key did not validate
Sat May  2 14:20:47 2020 daemon.err netopeer2-server[2967]: [ERR]: LN: Session 46: SSH channel poll error (Received SSH_MSG_DISCONNECT: 9:Server key did not validate).
Sat May  2 14:20:47 2020 daemon.err netopeer2-server[2967]: [INF]: NP: Session 46: thread 4 event session terminated.
Sat May  2 14:20:47 2020 daemon.info netopeer2-server[2967]: There are no subscribers for "ietf-netconf-notifications" notifications.
Sat May  2 14:20:47 2020 daemon.info netopeer2-server[2967]: Generated new event (netconf-session-end).

       Opendaylight error:

      14:24:24.335 INFO [nioEventLoopGroup-4-6] Incoming session ClientSessionImpl[netconf@/2a02:17d0:8102:600:c0f1:9fff:fef0:ba16:58038] was rejected. Session with same name db56ed8d0d1dce57f505da9ac603c957 is already active. 14:24:24.337 INFO [nioEventLoopGroup-4-7] Removing Uri{_value=db56ed8d0d1dce57f505da9ac603c957} from Netconf Topology. 14:24:24.338 WARN [nioEventLoopGroup-4-7] RemoteDevice{db56ed8d0d1dce57f505da9ac603c957}: Session terminated Session closed 14:24:24.339 INFO [nioEventLoopGroup-4-7] Removing Uri{_value=db56ed8d0d1dce57f505da9ac603c957} from Netconf Topology. 14:24:24.339 INFO [opendaylight-cluster-data-notification-dispatcher-206534] Setting failed status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}. 14:24:24.340 INFO [opendaylight-cluster-data-notification-dispatcher-206534] Setting failed status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}. 14:24:24.343 INFO [opendaylight-cluster-data-notification-dispatcher-206568] Setting disconnected status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}. 14:24:24.344 INFO [opendaylight-cluster-data-notification-dispatcher-206533] Setting failed status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}. 14:24:24.345 INFO [opendaylight-cluster-data-notification-dispatcher-206570] Setting disconnected status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}. 14:24:24.345 INFO [opendaylight-cluster-data-notification-dispatcher-206533] Setting disconnected status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}. 14:24:24.348 WARN [nioEventLoopGroup-4-7] RemoteDevice{db56ed8d0d1dce57f505da9ac603c957}: Session went down java.io.IOException: End of input detected. Close the session. at org.opendaylight.netconf.nettyutil.AbstractNetconfSession.endOfInput(AbstractNetconfSession.java:94) [293:org.opendaylight.netconf.netty-util:1.7.1] at org.opendaylight.netconf.nettyutil.AbstractNetconfSession.channelInactive(AbstractNetconfSession.java:174) [293:org.opendaylight.netconf.netty-util:1.7.1] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:257) [64:io.netty.transport:4.1.39.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:243) [64:io.netty.transport:4.1.39.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:236) [64:io.netty.transport:4.1.39.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:393) [59:io.netty.codec:4.1.39.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:358) [59:io.netty.codec:4.1.39.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:257) [64:io.netty.transport:4.1.39.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:243) [64:io.netty.transport:4.1.39.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:236) [64:io.netty.transport:4.1.39.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:393) [59:io.netty.codec:4.1.39.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:358) [59:io.netty.codec:4.1.39.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:257) [64:io.netty.transport:4.1.39.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:243) [64:io.netty.transport:4.1.39.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:236) [64:io.netty.transport:4.1.39.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1416) [64:io.netty.transport:4.1.39.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:257) [64:io.netty.transport:4.1.39.Final] at io.netty.channel.AbstractChannelHandlerContext.access$300(AbstractChannelHandlerContext.java:56) [64:io.netty.transport:4.1.39.Final] at io.netty.channel.AbstractChannelHandlerContext$4.run(AbstractChannelHandlerContext.java:248) [64:io.netty.transport:4.1.39.Final] at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) [61:io.netty.common:4.1.39.Final] at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:416) [61:io.netty.common:4.1.39.Final] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:515) [64:io.netty.transport:4.1.39.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918) [61:io.netty.common:4.1.39.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [61:io.netty.common:4.1.39.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [61:io.netty.common:4.1.39.Final] at java.lang.Thread.run(Thread.java:748) [?:?] 14:24:24.408 INFO [nioEventLoopGroup-4-1] [id: 0x8b2649ce, L:/0:0:0:0:0:0:0:0:6666] READ: [id: 0xaaab3ab6, L:/2a02:17d0:8102:600:c0f1:9fff:fef0:ba16:6666 - R:/2a02:17d0:8102:600:c0f1:9fff:fef0:ba16:59626] 14:24:24.409 INFO [nioEventLoopGroup-4-1] [id: 0x8b2649ce, L:/0:0:0:0:0:0:0:0:6666] READ COMPLETE 14:24:24.873 INFO [nioEventLoopGroup-4-2] Provisioning fake config Node{_nodeId=Uri{_value=db56ed8d0d1dce57f505da9ac603c957}, augmentation=[NetconfNode{_credentials=LoginPassword{_password=ommited, _username=ommited, augmentation=[]}, _host=Host{_ipAddress=IpAddress{_ipv6Address=Ipv6Address{_value=2a02:17d0:8102:600:c0f1:9fff:fef0:ba16}}}, _port=PortNumber{_value=59626}, _schemaless=false, _tcpOnly=false}]} 14:24:24.874 INFO [nioEventLoopGroup-4-2] Connecting RemoteDevice{Uri{_value=db56ed8d0d1dce57f505da9ac603c957}} , with config Node{_nodeId=Uri{_value=db56ed8d0d1dce57f505da9ac603c957}, augmentation=[NetconfNode{_credentials=***, _host=Host{_ipAddress=IpAddress{_ipv6Address=Ipv6Address{_value=2a02:17d0:8102:600:c0f1:9fff:fef0:ba16}}}, _port=PortNumber{_value=59626}, _schemaless=false, _tcpOnly=false}]} 14:24:24.875 WARN [nioEventLoopGroup-4-2] schema-cache-directory for db56ed8d0d1dce57f505da9ac603c957 is null or empty; using the default cache/schema 14:24:24.876 INFO [nioEventLoopGroup-4-2] Concurrent rpc limit is smaller than 1, no limit will be enforced for device RemoteDevice{db56ed8d0d1dce57f505da9ac603c957} 14:24:24.876 INFO [opendaylight-cluster-data-notification-dispatcher-206516] Setting failed status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}. 14:24:24.875 INFO [opendaylight-cluster-data-notification-dispatcher-206569] Setting failed status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}. 14:24:24.875 INFO [opendaylight-cluster-data-notification-dispatcher-206570] Setting failed status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}. 14:24:24.876 INFO [nioEventLoopGroup-4-2] Activating NETCONF channel for ip /2a02:17d0:8102:600:c0f1:9fff:fef0:ba16:59626 device context org.opendaylight.netconf.callhome.mount.CallHomeMountSessionContext@79472d56 14:24:24.878 INFO [nioEventLoopGroup-4-2] Activating Netconf channel for /2a02:17d0:8102:600:c0f1:9fff:fef0:ba16:59626 with org.opendaylight.netconf.callhome.mount.CallHomeMountSessionContext$1@45b1745c 14:24:25.153 WARN [remote-connector-processing-executor-745] RemoteDevice{db56ed8d0d1dce57f505da9ac603c957}: Netconf device provides additional yang models not reported in hello message capabilities: [(urn:itmh:cpe:firmware?revision=2019-09-06)itmh-cpe-firmware, (urn:ietf:params:xml:ns:yang:ietf-keystore?revision=2016-10-31)ietf-keystore, (urn:itmh:cpe:netconf?revision=2020-02-28)itmh-cpe-netconf, (urn:itmh:cpe:info?revision=2019-09-06)itmh-cpe-info, (urn:itmh:cpe:firewall?revision=2019-08-29)itmh-cpe-firewall, (urn:itmh:yang:types?revision=2019-07-15)itmh-yang-types, (urn:ietf:params:xml:ns:yang:ietf-ssh-server?revision=2016-11-02)ietf-ssh-server, (urn:itmh:cpe:dhcp?revision=2019-08-23)itmh-cpe-dhcp, (urn:itmh:cpe:wireless?revision=2019-09-06)itmh-cpe-wireless, (urn:ietf:params:xml:ns:yang:ietf-yang-library?revision=2018-01-17)ietf-yang-library, (urn:ietf:params:xml:ns:yang:ietf-tls-server?revision=2016-11-02)ietf-tls-server, (urn:ietf:params:xml:ns:yang:ietf-netconf-server?revision=2016-11-02)ietf-netconf-server, (urn:itmh:cpe:debug?revision=2019-09-06)itmh-cpe-debug, (urn:ietf:params:xml:ns:yang:ietf-datastores?revision=2017-08-17)ietf-datastores] 14:24:25.154 WARN [remote-connector-processing-executor-745] RemoteDevice{db56ed8d0d1dce57f505da9ac603c957}: Adding provided but not required sources as required to prevent failures 14:24:25.158 INFO [remote-connector-processing-executor-745] RemoteDevice{db56ed8d0d1dce57f505da9ac603c957}: Netconf connector initialized successfully 14:24:25.159 INFO [opendaylight-cluster-data-notification-dispatcher-206536] Setting successful status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}. 14:24:25.159 INFO [opendaylight-cluster-data-notification-dispatcher-206571] Setting successful status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}. 14:24:25.159 INFO [opendaylight-cluster-data-notification-dispatcher-206533] Setting successful status for callhome device id:Uri{_value=db56ed8d0d1dce57f505da9ac603c957}.

        1. [NETCONF-681] Steps to reproduce.odt
          24 kB
        2. files681.zip
          70 kB

            ivanm1996 Ivan Martiniak
            artsnz art snz
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: