[NETCONF-942] Callhome session is closed after allowing device to connect Created: 11/Jan/23  Updated: 01/Feb/23  Resolved: 24/Jan/23

Status: Resolved
Project: netconf
Component/s: netconf
Affects Version/s: 5.0.0
Fix Version/s: 5.0.1

Type: Bug Priority: Highest
Reporter: Peter Suna Assignee: Ivan Hrasko
Resolution: Done Votes: 0
Labels: pt
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Blocks
blocks NETCONF-887 Netconf callhome failed for devices w... Resolved
blocks NETCONF-699 Eliminate use of AsyncSshHandlerReade... Resolved
blocks NETCONF-710 Add session-id to the operational dat... Resolved

 Description   

Netconf Callhome session is closed after adding device to allowed-devices container. Device will not be connected and callhome-status is staying in state DISCONNECTED.

ODL Logs will stay in cycle with reconnecting device:

17:21:52.119 INFO [qtp1390078279-811] Authentication is now enabled
17:21:52.119 INFO [qtp1390078279-811] Authentication Manager activated
17:21:52.169 INFO [qtp1390078279-811] Consecutive slashes in REST URLs will be rejected
17:22:15.187 INFO [opendaylight-cluster-data-notification-dispatcher-42] Using lazy population for maps larger than 1 element(s)
17:23:25.853 INFO [nioEventLoopGroup-4-3] Instantiated factory for class org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.inet.types.rev130715.Ipv4AddressNoZone
17:23:25.853 INFO [nioEventLoopGroup-4-3] Instantiated factory for class org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.inet.types.rev130715.Ipv4Prefix
17:23:25.854 INFO [nioEventLoopGroup-4-3] Instantiated factory for class org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.inet.types.rev130715.Ipv6AddressNoZone
17:23:25.855 INFO [nioEventLoopGroup-4-3] Instantiated factory for class org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.inet.types.rev130715.Ipv6Prefix
17:23:25.861 INFO [nioEventLoopGroup-4-3] Provisioning fake config Node{nodeId=Uri{value=netopeer}, augmentation=[NetconfNode{actorResponseWaitTime=5, betweenAttemptsTimeoutMillis=2000, concurrentRpcLimit=0, connectionTimeoutMillis=20000, credentials=LoginPassword{password=omitted, username=omitted}, defaultRequestTimeoutMillis=60000, host=Host{ipAddress=IpAddress{ipv4Address=Ipv4Address{value=172.17.0.2}}}, keepaliveDelay=120, maxConnectionAttempts=0, port=PortNumber{value=45740}, protocol=Protocol{name=SSH}, reconnectOnChangedSchema=false, schemaless=false, sleepFactor=1.5, tcpOnly=false}]}
17:23:25.862 INFO [nioEventLoopGroup-4-3] Connecting RemoteDevice{Uri{value=netopeer}} , with config Node{nodeId=Uri{value=netopeer}, augmentation=[NetconfNode{actorResponseWaitTime=5, betweenAttemptsTimeoutMillis=2000, concurrentRpcLimit=0, connectionTimeoutMillis=20000, credentials=***, defaultRequestTimeoutMillis=60000, host=Host{ipAddress=IpAddress{ipv4Address=Ipv4Address{value=172.17.0.2}}}, keepaliveDelay=120, maxConnectionAttempts=0, port=PortNumber{value=45740}, protocol=Protocol{name=SSH}, reconnectOnChangedSchema=false, schemaless=false, sleepFactor=1.5, tcpOnly=false}]}
17:23:25.865 WARN [nioEventLoopGroup-4-3] notifyListener(DefaultOpenFuture[id=ChannelSubsystem[id=0, recipient=-1]-ClientSessionImpl[netconf@/172.17.0.2:45740][netconf]][value=true]) failed (NoSuchElementException) to invoke org.opendaylight.netconf.callhome.protocol.CallHomeSessionContext$$Lambda$2749/0x00000007c1161b18@3fbb462a: Value of lockdatastore is not present
17:24:26.910 ERROR [nioEventLoopGroup-4-4] Server Host Key/Certificate RSA Public Key [16:9b:98:7b:59:3b:95:67:57:2b:86:a2:0a:2c:e9:fe:56:40:67:be],[56:66:d1:a4]
        modulus: c6d1bd28fcc7b3605326b0aaf41ee5da08ad2969d0f002da3bd9f06d601734b625a1cd9988db6eaea985efc3da436c75fe9a0510bd790c79f0eabcb5b03ac4992429f872ae6f8f9acf478ee68503b767819e6bd308e294b9508d6da1c04c4d083ed0c644cefad809faf38857fa94a8b70a25587717b930eec6c7d05f525a05c24b5a3edebc2be4f89f47fad1d13ca7b4358fff324ea82f16c318ff792b3545ade0c69762c7bd5716ada0d673719ef8babfd2a8a6cbcaf2db2fcce99a57bff85116e59c06e2783f3e75e2fba0a53b55c9285ab110ff7ed8065103f861c3a3e85ca4d117040b9f40f2fe201b9c279970301d9679424c4d6ac19be9fb9f994dfc99
public exponent: 10001
 is associated with existing session CallHomeMountSessionContext{address=/172.17.0.2:45740, hostKey=RSA Public Key [16:9b:98:7b:59:3b:95:67:57:2b:86:a2:0a:2c:e9:fe:56:40:67:be],[56:66:d1:a4]
        modulus: c6d1bd28fcc7b3605326b0aaf41ee5da08ad2969d0f002da3bd9f06d601734b625a1cd9988db6eaea985efc3da436c75fe9a0510bd790c79f0eabcb5b03ac4992429f872ae6f8f9acf478ee68503b767819e6bd308e294b9508d6da1c04c4d083ed0c644cefad809faf38857fa94a8b70a25587717b930eec6c7d05f525a05c24b5a3edebc2be4f89f47fad1d13ca7b4358fff324ea82f16c318ff792b3545ade0c69762c7bd5716ada0d673719ef8babfd2a8a6cbcaf2db2fcce99a57bff85116e59c06e2783f3e75e2fba0a53b55c9285ab110ff7ed8065103f861c3a3e85ca4d117040b9f40f2fe201b9c279970301d9679424c4d6ac19be9fb9f994dfc99
public exponent: 10001
}, closing session org.opendaylight.netconf.callhome.protocol.CallHomeSessionContext@7c6e5436
17:24:27.938 ERROR [nioEventLoopGroup-4-5] Server Host Key/Certificate RSA Public Key [16:9b:98:7b:59:3b:95:67:57:2b:86:a2:0a:2c:e9:fe:56:40:67:be],[56:66:d1:a4]
        modulus: c6d1bd28fcc7b3605326b0aaf41ee5da08ad2969d0f002da3bd9f06d601734b625a1cd9988db6eaea985efc3da436c75fe9a0510bd790c79f0eabcb5b03ac4992429f872ae6f8f9acf478ee68503b767819e6bd308e294b9508d6da1c04c4d083ed0c644cefad809faf38857fa94a8b70a25587717b930eec6c7d05f525a05c24b5a3edebc2be4f89f47fad1d13ca7b4358fff324ea82f16c318ff792b3545ade0c69762c7bd5716ada0d673719ef8babfd2a8a6cbcaf2db2fcce99a57bff85116e59c06e2783f3e75e2fba0a53b55c9285ab110ff7ed8065103f861c3a3e85ca4d117040b9f40f2fe201b9c279970301d9679424c4d6ac19be9fb9f994dfc99
public exponent: 10001
 is associated with existing session CallHomeMountSessionContext{address=/172.17.0.2:45740, hostKey=RSA Public Key [16:9b:98:7b:59:3b:95:67:57:2b:86:a2:0a:2c:e9:fe:56:40:67:be],[56:66:d1:a4]
        modulus: c6d1bd28fcc7b3605326b0aaf41ee5da08ad2969d0f002da3bd9f06d601734b625a1cd9988db6eaea985efc3da436c75fe9a0510bd790c79f0eabcb5b03ac4992429f872ae6f8f9acf478ee68503b767819e6bd308e294b9508d6da1c04c4d083ed0c644cefad809faf38857fa94a8b70a25587717b930eec6c7d05f525a05c24b5a3edebc2be4f89f47fad1d13ca7b4358fff324ea82f16c318ff792b3545ade0c69762c7bd5716ada0d673719ef8babfd2a8a6cbcaf2db2fcce99a57bff85116e59c06e2783f3e75e2fba0a53b55c9285ab110ff7ed8065103f861c3a3e85ca4d117040b9f40f2fe201b9c279970301d9679424c4d6ac19be9fb9f994dfc99
public exponent: 10001
}, closing session org.opendaylight.netconf.callhome.protocol.CallHomeSessionContext@7be53726

 

Steps to reproduce:

1) Install Karaf feature:
feature:install odl-netconf-callhome-ssh odl-restconf-nb
2) Add Netopeer2 device to allowed-devices:

curl --request POST 'http://127.0.0.1:8181/rests/data/odl-netconf-callhome-server:netconf-callhome-server/allowed-devices' \
--header 'Authorization: Basic YWRtaW46YWRtaW4=' \
--data-raw '{
  "device": {
    "unique-id": "netopeer",
    "ssh-client-params": {
      "host-key": "AAAAB3NzaC1yc2EAAAADAQABAAABAQDG0b0o/MezYFMmsKr0HuXaCK0padDwAto72fBtYBc0tiWhzZmI226uqYXvw9pDbHX+mgUQvXkMefDqvLWwOsSZJCn4cq5vj5rPR47mhQO3Z4Gea9MI4pS5UI1tocBMTQg+0MZEzvrYCfrziFf6lKi3CiVYdxe5MO7Gx9BfUloFwktaPt68K+T4n0f60dE8p7Q1j/8yTqgvFsMY/3krNUWt4MaXYse9VxatoNZzcZ74ur/SqKbLyvLbL8zpmle/+FEW5ZwG4ng/PnXi+6ClO1XJKFqxEP9+2AZRA/hhw6PoXKTRFwQLn0Dy/iAbnCeZcDAdlnlCTE1qwZvp+5+ZTfyZ",
      "credentials" : {
        "username": "netconf",
        "passwords": [
           "netconf" 
           ]
      }
    }
  }
}'

3) Start Netopeer2 device with Netconf Callhome configuration

 Comments   
Comment by Peter Suna [ 11/Jan/23 ]

This bug is introduced with this patch:
https://git.opendaylight.org/gerrit/c/netconf/+/103844

Comment by Ivan Hrasko [ 18/Jan/23 ]

Something similar has been solved here: https://git.opendaylight.org/gerrit/c/netconf/+/94248

Now, probably, the reason is:

17:23:25.865 WARN [nioEventLoopGroup-4-3] notifyListener(DefaultOpenFuture[id=ChannelSubsystem[id=0, recipient=-1]-ClientSessionImpl[netconf@/172.17.0.2:45740][netconf]][value=true]) failed (NoSuchElementException) to invoke org.opendaylight.netconf.callhome.protocol.CallHomeSessionContext$$Lambda$2749/0x00000007c1161b18@3fbb462a: Value of lockdatastore is not present

It means we have to implement this lock when callhome topology node is created in `CallHomeMountSessionContext`.

Comment by Ivan Hrasko [ 18/Jan/23 ]

By default it should be `true`. Maybe `AbstractNetconfDataTreeService` should initialize the value as true?

Comment by Ivan Hrasko [ 19/Jan/23 ]

Datastore lock is set to true by default according to YANG model `odl-netconf-device.yang`. The problem is that callhome logic fails to obey any default values in datastore. We have to set correct value manually.

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