ncclient.transport.errors.SessionCloseError: Unexpected session close directly after sending a <close-session/> RPC

[hjensas]

I'm using Cisco nexus device type, and intermittently see SessionCloseError: Unexpected session close raised directly after sending a <close-session/> RPC. This happens on app initialization, I'm just connecting and gathering capabilities of the device.

ncclient version:

>>> ncclient.__version__
'0.6.12'

My App class is simply calling this get_capabilities method.

def get_capabilities(netconf_device):
    capabilities = set()
    args = get_client_args(netconf_device)
    with manager.connect(**args) as nc_client:
        server_capabilities = nc_client.server_capabilities

    for capability in server_capabilities:
        for k, v in IANA_NETCONF_CAPABILITIES.items():
            if v in capability:
                capabilities.add(k)

    return capabilities

app[$PID]: INFO ncclient.transport.ssh [-] Connected (version 2.0, client OpenSSH_8.0)
app[$PID]: INFO ncclient.transport.ssh [-] Auth banner: b'User Access Verification\n'
app[$PID]: INFO ncclient.transport.ssh [-] Authentication (publickey) successful!
app[$PID]: INFO ncclient.transport.ssh [-] [host 192.168.24.21 session 0x7f6b0dc7c2e0] Sending:
app[$PID]: b'<?xml version="1.0" encoding="UTF-8"?><hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0"><capabilities><capability>urn:ietf:params:xml:ns:netconf:base:1.0</capability><capability>urn:ietf:params:netconf:base:1.1</capability><capability>urn:ietf:params:netconf:capability:writable-running:1.0</capability><capability>urn:ietf:params:netconf:capability:candidate:1.0</capability><capability>urn:ietf:params:netconf:capability:confirmed-commit:1.0</capability><capability>urn:ietf:params:netconf:capability:rollback-on-error:1.0</capability><capability>urn:ietf:params:netconf:capability:startup:1.0</capability><capability>urn:ietf:params:netconf:capability:url:1.0?scheme=http,ftp,file,https,sftp</capability><capability>urn:ietf:params:netconf:capability:validate:1.0</capability><capability>urn:ietf:params:netconf:capability:xpath:1.0</capability><capability>urn:ietf:params:netconf:capability:notification:1.0</capability><capability>urn:liberouter:params:netconf:capability:power-control:1.0</capability><capability>urn:ietf:params:netconf:capability:interleave:1.0</capability><capability>urn:ietf:params:netconf:capability:with-defaults:1.0</capability></capabilities></hello>]]>]]>'
app[$PID]: INFO ncclient.transport.ssh [-] [host 192.168.24.21 session 0x7f6b0dc7c2e0] Received message from host
app[$PID]: INFO ncclient.transport.ssh [-] [host 192.168.24.21 session-id 1399353056] initialized: session-id=1399353056 | server_capabilities=<dict_keyiterator object at 0x7f6b0ebb1c20>
app[$PID]: INFO ncclient.operations.rpc [-] [host 192.168.24.21 session-id 1399353056] Requesting 'CloseSession'
app[$PID]: INFO ncclient.transport.ssh [-] [host 192.168.24.21 session-id 1399353056] Sending:
app[$PID]: b'\n#381\n<?xml version="1.0" encoding="UTF-8"?><rpc xmlns:nxos="http://www.cisco.com/nxos:1.0" xmlns:if="http://www.cisco.com/nxos:1.0:if_manager" xmlns:nfcli="http://www.cisco.com/nxos:1.0:nfcli" xmlns:vlan_mgr_cli="http://www.cisco.com/nxos:1.0:vlan_mgr_cli" xmlns="urn:ietf:params:xml:ns:netconf:base:1.0" message-id="urn:uuid:d2e0a808-9651-4044-b6cc-d3a260fb66d9"><close-session/></rpc>\n##\n'
app[$PID]: CRITICAL 'Unexpected session close'.: ncclient.transport.errors.SessionCloseError: Unexpected session close

Traceback:

Traceback (most recent call last):
  File "/opt/app/foo/netconf_client.py", line 93, in get_capabilities
    server_capabilities = nc_client.server_capabilities
  File "/usr/local/lib/python3.8/dist-packages/ncclient/manager.py", line 232, in __exit__
    self.close_session()
  File "/usr/local/lib/python3.8/dist-packages/ncclient/manager.py", line 246, in execute
    return cls(self._session,
  File "/usr/local/lib/python3.8/dist-packages/ncclient/operations/session.py", line 27, in request
    ret = self._request(new_ele("close-session"))
  File "/usr/local/lib/python3.8/dist-packages/ncclient/operations/rpc.py", line 364, in _request
    raise self._error
  File "/usr/local/lib/python3.8/dist-packages/ncclient/transport/ssh.py", line 500, in run
    raise SessionCloseError(self._buffer.getvalue())
ncclient.transport.errors.SessionCloseError: Unexpected session close

[einarnn]

@hjensas, this sounds more like a problem with Cisco Nexus devices.Have you any more debugs that point to a problem with the ncclient library?

[nkitchen]

I've seen this exact same failure pattern with devices that are not Nexus nor any others from Cisco. It looks to me like it's a possible race with closing sessions: The server can close the connection before CloseSession.request() has a chance to call self._event.set(), and then when the loop in SSHSession.run() gets zero data, it misses the # End of session, expected case and raises SessionCloseError instead.

[einarnn]

At this point it looks like we are seeing netconf servers closing their sessions without necessarily sending the required <ok/> and gracefully terminating the connection. From RFC 6241:

7.8.  <close-session>

   Description:  Request graceful termination of a NETCONF session.

      When a NETCONF server receives a <close-session> request, it will
      gracefully close the session.  The server will release any locks
      and resources associated with the session and gracefully close any
      associated connections.  Any NETCONF requests received after a
      <close-session> request will be ignored.

   Positive Response:  If the device was able to satisfy the request, an
      <rpc-reply> is sent that includes an <ok> element.

   Negative Response:  An <rpc-error> element is included in the
      <rpc-reply> if the request cannot be completed for any reason.

   Example:

     <rpc message-id="101"
          xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
       <close-session/>
     </rpc>

     <rpc-reply message-id="101"
          xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
       <ok/>
     </rpc-reply>

The server should send the <ok/> and after that gracefully terminate the transport session. If we see ncclient.transport.errors.SessionCloseError: Unexpected session close with no <ok/>, then I don't think we are seeing the netconf server gracefully close the session.

As far as I can tell we don not have any issue with ncclient. Closing issue for now.