From 770ed3e6ab51b9c51e27933055215be6d927d687 Mon Sep 17 00:00:00 2001 From: Einar Nilsen-Nygaard Date: Fri, 17 Aug 2018 21:58:57 +0100 Subject: [PATCH 1/7] First draft of improved netconf:base:1.1 parsing --- ncclient/transport/session.py | 10 +- ncclient/transport/ssh.py | 242 +++++++++++++------------------- test/unit/transport/test_ssh.py | 7 +- 3 files changed, 112 insertions(+), 147 deletions(-) diff --git a/ncclient/transport/session.py b/ncclient/transport/session.py index e8f58a4e..62cf88c5 100644 --- a/ncclient/transport/session.py +++ b/ncclient/transport/session.py @@ -30,6 +30,12 @@ logger = logging.getLogger('ncclient.transport.session') +class NetconfBase(object): + '''Netconf Base protocol version''' + BASE_10 = 1 + BASE_11 = 2 + + class Session(Thread): "Base class for use by transport protocol implementations." @@ -44,7 +50,7 @@ def __init__(self, capabilities): self._notification_q = Queue() self._client_capabilities = capabilities self._server_capabilities = None # yet - self._base = "1.0" + self._base = NetconfBase.BASE_10 self._id = None # session-id self._connected = False # to be set/cleared by subclass implementation logger.debug('%r created: client_capabilities=%r' % @@ -110,7 +116,7 @@ def err_cb(err): # raise MissingCapabilityError(':base:1.0') if 'urn:ietf:params:netconf:base:1.1' in self._server_capabilities and 'urn:ietf:params:netconf:base:1.1' in self._client_capabilities: logger.debug("After 'hello' message selecting netconf:base:1.1 for encoding") - self._base = "1.1" + self._base = NetconfBase.BASE_11 logger.info('initialized: session-id=%s | server_capabilities=%s' % (self._id, self._server_capabilities)) diff --git a/ncclient/transport/ssh.py b/ncclient/transport/ssh.py index c4dd0528..9d7ea356 100644 --- a/ncclient/transport/ssh.py +++ b/ncclient/transport/ssh.py @@ -17,6 +17,7 @@ import sys import socket import getpass +import re import threading from binascii import hexlify from lxml import etree @@ -32,6 +33,7 @@ from ncclient.transport.errors import AuthenticationError, SessionCloseError, SSHError, SSHUnknownHostError from ncclient.transport.session import Session +from ncclient.transport.session import NetconfBase from ncclient.xml_ import * import logging @@ -46,6 +48,18 @@ TICK = 0.1 +# +# Define delimiters for chunks and messages for netconf 1.1 chunk enoding. +# When matched: +# +# * result.group(0) will contain whole matched string +# * result.group(1) will contain the '#[0-9]+' +# * result.group(2) will contain the digit string for a chunk +# * result.group(3) will be defined if '##' found +# +RE_NC11_DELIM = re.compile('\n(#([0-9]+)|(##))\n') + + def default_unknown_host_cb(host, fingerprint): """An unknown host callback returns `True` if it finds the key acceptable, and `False` if not. @@ -149,149 +163,85 @@ def _parse10(self): self._parsing_pos10 = 0 def _parse11(self): - logger.debug("parsing netconf v1.1") - expchunksize = self._expchunksize - curchunksize = self._curchunksize - idle, instart, inmsg, inbetween, inend = range(5) - state = self._parsing_state11 - inendpos = self._inendpos - num_list = self._size_num_list - MAX_STARTCHUNK_SIZE = 12 # \#+4294967295+\n - pre = 'invalid base:1:1 frame' - buf = self._buffer - buf.seek(self._parsing_pos11) - message_list = self._message_list # a message is a list of chunks - chunk_list = [] # a chunk is a list of characters - - should_recurse = False - + + """Messages are split into chunks. Chunks and messages are delimited + by the regex #RE_NC11_DELIM defined earlier in this file. Each time we + get called here either a chunk delimiter or an end-of-message delimiter + should be found. If it's not, a framing error will be raised.""" + + logger.debug("_parse11: starting") + + # suck in whole string that we have (this is what we will work on in + # this function) and initialize a couple of useful values + self._buffer.seek(0, os.SEEK_SET) + data = self._buffer.getvalue() + data_len = len(data) + start = 0 + logger.debug('_parse11: working with buffer of {0} bytes'.format(data_len)) + logger.debug('_parse11: data= {0}'.format(data)) while True: - x = buf.read(1) - if not x: - logger.debug('No more data to read') - # Store the current chunk to the message list - chunk = b''.join(chunk_list) - message_list.append(textify(chunk)) - break # done reading - if state == idle: - if x == b'\n': - state = instart - inendpos = 1 - else: - logger.debug('%s (%s: expect newline)'%(pre, state)) - raise Exception - elif state == instart: - if inendpos == 1: - if x == b'#': - inendpos += 1 - else: - logger.debug('%s (%s: expect "#")'%(pre, state)) - raise Exception - elif inendpos == 2: - if x.isdigit(): - inendpos += 1 # == 3 now # - num_list.append(x) - else: - logger.debug('%s (%s: expect digit)'%(pre, state)) - raise Exception + # match to see if we found at least some kind of delimiter + logger.debug('_parse11: matching from {0} bytes from start of buffer'.format(start)) + re_result = RE_NC11_DELIM.match(data[start:].decode('utf-8')) + if not re_result: + + # not found any kind of delimiter just break; this should only + # ever happen if we just have the first few characters of a + # message such that we don't yet have a full delimiter + logger.debug('_parse11: no delimiter found, buffer={0}'.format(data[start:])) + break + + # save useful variables for reuse + re_start = re_result.start() + re_end = re_result.end() + logger.debug('_parse11: regular expression start={0}, end={1}'.format(re_start, re_end)) + + # If the regex doesn't start at the beginning of the buffer, + # we're in trouble, so throw an error + if re_start != 0: + raise NetconfFramingError('_parse11: delimiter not at start of match buffer', data[start:]) + + if re_result.group(3): + # we've found the end of the message, need to form up + # whole message, save back remainder (if any) to buffer + # and dispatch the message + start += re_end + message = ''.join(self._message_list) + self._message_list = [] + logger.debug('_parse11: found end of message delimiter') + self._dispatch_message(message) + break + + elif re_result.group(2): + # we've found a chunk delimiter, and group(2) is the digit + # string that will tell us how many bytes past the end of + # where it was found that we need to have available to + # save the next chunk off + logger.debug('_parse11: found chunk delimiter') + digits = int(re_result.group(2)) + logger.debug('_parse11: chunk size {0} bytes'.format(digits)) + if (data_len-start) >= (re_end + digits): + # we have enough data for the chunk + fragment = textify(data[start+re_end:start+re_end+digits]) + self._message_list.append(fragment) + start += re_end + digits + logger.debug('_parse11: appending {0} bytes'.format(digits)) + logger.debug('_parse11: fragment = "{0}"'.format(fragment)) else: - if inendpos == MAX_STARTCHUNK_SIZE: - logger.debug('%s (%s: no. too long)'%(pre, state)) - raise Exception - elif x == b'\n': - num = b''.join(num_list) - num_list = [] # Reset num_list - try: num = int(num) - except: - logger.debug('%s (%s: invalid no.)'%(pre, state)) - raise Exception - else: - state = inmsg - expchunksize = num - logger.debug('response length: %d'%expchunksize) - curchunksize = 0 - inendpos += 1 - elif x.isdigit(): - inendpos += 1 # > 3 now # - num_list.append(x) - else: - logger.debug('%s (%s: expect digit)'%(pre, state)) - raise Exception - elif state == inmsg: - chunk_list.append(x) - curchunksize += 1 - chunkleft = expchunksize - curchunksize - if chunkleft == 0: - inendpos = 0 - state = inbetween - chunk = b''.join(chunk_list) - message_list.append(textify(chunk)) - chunk_list = [] # Reset chunk_list - logger.debug('parsed new chunk: %s'%(chunk)) - elif state == inbetween: - if inendpos == 0: - if x == b'\n': inendpos += 1 - else: - logger.debug('%s (%s: expect newline)'%(pre, state)) - raise Exception - elif inendpos == 1: - if x == b'#': inendpos += 1 - else: - logger.debug('%s (%s: expect "#")'%(pre, state)) - raise Exception - else: - inendpos += 1 # == 3 now # - if x == b'#': - state = inend - elif x.isdigit(): - # More trunks - state = instart - num_list = [] - num_list.append(x) - else: - logger.debug('%s (%s: expect "#")'%(pre, state)) - raise Exception - elif state == inend: - if inendpos == 3: - if x == b'\n': - inendpos = 0 - state = idle - logger.debug('dispatching message') - self._dispatch_message(''.join(message_list)) - # reset - rest = buf.read() - buf = BytesIO() - buf.write(rest) - buf.seek(0) - message_list = [] - self._message_list = message_list - chunk_list = [] - expchunksize = chunksize = 0 - parsing_state11 = idle - inendpos = parsing_pos11 = 0 - # There could be another entire message in the - # buffer, so we should try to parse again. - should_recurse = True - break - else: - logger.debug('%s (%s: expect newline)'%(pre, state)) - raise Exception - else: - logger.debug('%s (%s invalid state)'%(pre, state)) - raise Exception - - self._expchunksize = expchunksize - self._curchunksize = curchunksize - self._parsing_state11 = state - self._inendpos = inendpos - self._size_num_list = num_list - self._buffer = buf - self._parsing_pos11 = self._buffer.tell() - logger.debug('parse11 ending ...') - - if should_recurse: - logger.debug('Trying another round of parsing since there is still data') + # we don't have enough bytes, just break out for now + # after updating start pointer to start of new chunk + start += re_start + logger.debug('_parse11: not enough data for chunk yet') + logger.debug('_parse11: setting start to {0}'.format(start)) + break + + # Now out of the loop, need to see if we need to save back any content + if start > 0: + logger.debug('_parse11: saving back rest of message after {0} bytes, original size {1}'.format(start, data_len)) + self._buffer = StringIO(data[start:]) + logger.debug('_parse11: still have data, may have another full message!') self._parse11() + logger.debug('_parse11: ending') def load_known_hosts(self, filename=None): @@ -556,8 +506,11 @@ def start_delim(data_len): return '\n#%s\n'%(data_len) # Log what netconf:base version we are using this time # round the loop; _base is updated when we receive the # server's capabilities. - logger.debug('Currently selected netconf:base:%s', self._base) - + if self._base == NetconfBase.BASE_11: + logger.debug('Currently selected netconf:base:1.1') + else: + logger.debug('Currently selected netconf:base:1.1') + # Will wakeup evey TICK seconds to check if something # to send, more quickly if something to read (due to # select returning chan in readable list). @@ -565,8 +518,9 @@ def start_delim(data_len): return '\n#%s\n'%(data_len) if events: data = chan.recv(BUF_SIZE) if data: + self._buffer.seek(0, os.SEEK_END) self._buffer.write(data) - if self._base == "1.1": + if self._base == NetconfBase.BASE_11: self._parse11() else: self._parse10() @@ -575,7 +529,7 @@ def start_delim(data_len): return '\n#%s\n'%(data_len) if not q.empty() and chan.send_ready(): logger.debug("Sending message") data = q.get() - if self._base == "1.1": + if self._base == NetconfBase.BASE_11: data = "%s%s%s" % (start_delim(len(data)), data, END_DELIM) else: data = "%s%s" % (data, MSG_DELIM) diff --git a/test/unit/transport/test_ssh.py b/test/unit/transport/test_ssh.py index e771e395..f36702e2 100644 --- a/test/unit/transport/test_ssh.py +++ b/test/unit/transport/test_ssh.py @@ -36,7 +36,10 @@ reply_ok_chunk = "\n#%d\n%s\n##\n" % (len(reply_ok), reply_ok) -reply_ok_partial_chunk = "\n#%d\n%s\n" % (len(reply_ok), reply_ok) +# einarnn: this test message had to be reduced in size as the improved +# 1.1 parsing finds a whole fragment in it, so needed to have less +# data in it than the terminating '>' +reply_ok_partial_chunk = "\n#%d\n%s" % (len(reply_ok), reply_ok[:-1]) # A buffer of data with two complete messages and an incomplete message rpc_reply11 = "\n#%d\n%s\n#%d\n%s\n##\n%s%s" % ( @@ -80,6 +83,8 @@ def _test_parsemethod(self, mock_dispatch, parsemethod, reply, ok_chunk, remainder = ok_chunk parsemethod(obj) + import pprint + pprint.pprint(mock_dispatch.call_args_list) for i in range(0, len(expected_messages)): call = mock_dispatch.call_args_list[i][0][0] self.assertEqual(call, expected_messages[i]) From 649dece57dda830800a6db34c75e330bc7ae3927 Mon Sep 17 00:00:00 2001 From: Einar Nilsen-Nygaard Date: Fri, 17 Aug 2018 22:03:11 +0100 Subject: [PATCH 2/7] removed pprint detritus --- test/unit/transport/test_ssh.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/test/unit/transport/test_ssh.py b/test/unit/transport/test_ssh.py index f36702e2..2e88eeb9 100644 --- a/test/unit/transport/test_ssh.py +++ b/test/unit/transport/test_ssh.py @@ -83,8 +83,6 @@ def _test_parsemethod(self, mock_dispatch, parsemethod, reply, ok_chunk, remainder = ok_chunk parsemethod(obj) - import pprint - pprint.pprint(mock_dispatch.call_args_list) for i in range(0, len(expected_messages)): call = mock_dispatch.call_args_list[i][0][0] self.assertEqual(call, expected_messages[i]) From 31a6acb52bcc46125dde90881922e6fa5a57209e Mon Sep 17 00:00:00 2001 From: Einar Nilsen-Nygaard Date: Fri, 17 Aug 2018 22:07:38 +0100 Subject: [PATCH 3/7] removed unnecessary logging --- ncclient/transport/ssh.py | 1 - 1 file changed, 1 deletion(-) diff --git a/ncclient/transport/ssh.py b/ncclient/transport/ssh.py index 9d7ea356..5d9fcab2 100644 --- a/ncclient/transport/ssh.py +++ b/ncclient/transport/ssh.py @@ -178,7 +178,6 @@ def _parse11(self): data_len = len(data) start = 0 logger.debug('_parse11: working with buffer of {0} bytes'.format(data_len)) - logger.debug('_parse11: data= {0}'.format(data)) while True: # match to see if we found at least some kind of delimiter logger.debug('_parse11: matching from {0} bytes from start of buffer'.format(start)) From 5d7c2ffdcd587406dc10c0cf9e3ae2b9031a3317 Mon Sep 17 00:00:00 2001 From: Einar Nilsen-Nygaard Date: Fri, 17 Aug 2018 22:10:22 +0100 Subject: [PATCH 4/7] added NetconfFramingError exception --- ncclient/transport/errors.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/ncclient/transport/errors.py b/ncclient/transport/errors.py index 5aefe1ce..7bbec731 100644 --- a/ncclient/transport/errors.py +++ b/ncclient/transport/errors.py @@ -46,3 +46,6 @@ def __init__(self, host, fingerprint): SSHError.__init__(self, 'Unknown host key [%s] for [%s]' % (fingerprint, host)) self.host = host self.fingerprint = fingerprint + +class NetconfFramingError(TransportError): + pass From dbedee7c48377958e4019f57c2eda3c852495c13 Mon Sep 17 00:00:00 2001 From: Einar Nilsen-Nygaard Date: Sat, 18 Aug 2018 13:55:15 +0100 Subject: [PATCH 5/7] removed unnecessarily verbose logging --- ncclient/transport/ssh.py | 8 -------- 1 file changed, 8 deletions(-) diff --git a/ncclient/transport/ssh.py b/ncclient/transport/ssh.py index 5d9fcab2..c4663286 100644 --- a/ncclient/transport/ssh.py +++ b/ncclient/transport/ssh.py @@ -501,14 +501,6 @@ def start_delim(data_len): return '\n#%s\n'%(data_len) s.register(chan, selectors.EVENT_READ) logger.debug('selector type = %s', s.__class__.__name__) while True: - - # Log what netconf:base version we are using this time - # round the loop; _base is updated when we receive the - # server's capabilities. - if self._base == NetconfBase.BASE_11: - logger.debug('Currently selected netconf:base:1.1') - else: - logger.debug('Currently selected netconf:base:1.1') # Will wakeup evey TICK seconds to check if something # to send, more quickly if something to read (due to From 852ec63c6edd1dfda83c62df3e46f60681fe43e5 Mon Sep 17 00:00:00 2001 From: Einar Nilsen-Nygaard Date: Mon, 20 Aug 2018 16:51:20 +0100 Subject: [PATCH 6/7] updates from code review --- ncclient/transport/ssh.py | 27 +++++++++++++++------------ 1 file changed, 15 insertions(+), 12 deletions(-) diff --git a/ncclient/transport/ssh.py b/ncclient/transport/ssh.py index c4663286..812cd083 100644 --- a/ncclient/transport/ssh.py +++ b/ncclient/transport/ssh.py @@ -53,11 +53,10 @@ # When matched: # # * result.group(0) will contain whole matched string -# * result.group(1) will contain the '#[0-9]+' -# * result.group(2) will contain the digit string for a chunk -# * result.group(3) will be defined if '##' found +# * result.group(1) will contain the digit string for a chunk +# * result.group(2) will be defined if '##' found # -RE_NC11_DELIM = re.compile('\n(#([0-9]+)|(##))\n') +RE_NC11_DELIM = re.compile(r'\n(?:#([0-9]+)|(##))\n') def default_unknown_host_cb(host, fingerprint): @@ -165,9 +164,12 @@ def _parse10(self): def _parse11(self): """Messages are split into chunks. Chunks and messages are delimited - by the regex #RE_NC11_DELIM defined earlier in this file. Each time we - get called here either a chunk delimiter or an end-of-message delimiter - should be found. If it's not, a framing error will be raised.""" + by the regex #RE_NC11_DELIM defined earlier in this file. Each + time we get called here either a chunk delimiter or an + end-of-message delimiter should be found iff there is enough + data. If there is not enough data, we will wait for more. If a + delimiter is found in the wrong place, a #NetconfFramingError + will be raised.""" logger.debug("_parse11: starting") @@ -200,7 +202,7 @@ def _parse11(self): if re_start != 0: raise NetconfFramingError('_parse11: delimiter not at start of match buffer', data[start:]) - if re_result.group(3): + if re_result.group(2): # we've found the end of the message, need to form up # whole message, save back remainder (if any) to buffer # and dispatch the message @@ -211,13 +213,13 @@ def _parse11(self): self._dispatch_message(message) break - elif re_result.group(2): + elif re_result.group(1): # we've found a chunk delimiter, and group(2) is the digit # string that will tell us how many bytes past the end of # where it was found that we need to have available to # save the next chunk off logger.debug('_parse11: found chunk delimiter') - digits = int(re_result.group(2)) + digits = int(re_result.group(1)) logger.debug('_parse11: chunk size {0} bytes'.format(digits)) if (data_len-start) >= (re_end + digits): # we have enough data for the chunk @@ -238,8 +240,9 @@ def _parse11(self): if start > 0: logger.debug('_parse11: saving back rest of message after {0} bytes, original size {1}'.format(start, data_len)) self._buffer = StringIO(data[start:]) - logger.debug('_parse11: still have data, may have another full message!') - self._parse11() + if start < data_len: + logger.debug('_parse11: still have data, may have another full message!') + self._parse11() logger.debug('_parse11: ending') From 21df7cac452eca69d1a162632cd4bd08676bd047 Mon Sep 17 00:00:00 2001 From: Einar Nilsen-Nygaard Date: Mon, 20 Aug 2018 16:59:07 +0100 Subject: [PATCH 7/7] modified logger.debug statements to not use .format(...) for efficiency gain --- ncclient/transport/ssh.py | 20 +++++++++++--------- 1 file changed, 11 insertions(+), 9 deletions(-) diff --git a/ncclient/transport/ssh.py b/ncclient/transport/ssh.py index 812cd083..448dba03 100644 --- a/ncclient/transport/ssh.py +++ b/ncclient/transport/ssh.py @@ -179,23 +179,23 @@ def _parse11(self): data = self._buffer.getvalue() data_len = len(data) start = 0 - logger.debug('_parse11: working with buffer of {0} bytes'.format(data_len)) + logger.debug('_parse11: working with buffer of %d bytes', data_len) while True: # match to see if we found at least some kind of delimiter - logger.debug('_parse11: matching from {0} bytes from start of buffer'.format(start)) + logger.debug('_parse11: matching from %d bytes from start of buffer', start) re_result = RE_NC11_DELIM.match(data[start:].decode('utf-8')) if not re_result: # not found any kind of delimiter just break; this should only # ever happen if we just have the first few characters of a # message such that we don't yet have a full delimiter - logger.debug('_parse11: no delimiter found, buffer={0}'.format(data[start:])) + logger.debug('_parse11: no delimiter found, buffer="%s"', data[start:].encode()) break # save useful variables for reuse re_start = re_result.start() re_end = re_result.end() - logger.debug('_parse11: regular expression start={0}, end={1}'.format(re_start, re_end)) + logger.debug('_parse11: regular expression start=%d, end=%d', re_start, re_end) # If the regex doesn't start at the beginning of the buffer, # we're in trouble, so throw an error @@ -220,25 +220,27 @@ def _parse11(self): # save the next chunk off logger.debug('_parse11: found chunk delimiter') digits = int(re_result.group(1)) - logger.debug('_parse11: chunk size {0} bytes'.format(digits)) + logger.debug('_parse11: chunk size %d bytes', digits) if (data_len-start) >= (re_end + digits): # we have enough data for the chunk fragment = textify(data[start+re_end:start+re_end+digits]) self._message_list.append(fragment) start += re_end + digits - logger.debug('_parse11: appending {0} bytes'.format(digits)) - logger.debug('_parse11: fragment = "{0}"'.format(fragment)) + logger.debug('_parse11: appending %d bytes', digits) + logger.debug('_parse11: fragment = "%s"', fragment) else: # we don't have enough bytes, just break out for now # after updating start pointer to start of new chunk start += re_start logger.debug('_parse11: not enough data for chunk yet') - logger.debug('_parse11: setting start to {0}'.format(start)) + logger.debug('_parse11: setting start to %d', start) break # Now out of the loop, need to see if we need to save back any content if start > 0: - logger.debug('_parse11: saving back rest of message after {0} bytes, original size {1}'.format(start, data_len)) + logger.debug( + '_parse11: saving back rest of message after %d bytes, original size %d', + start, data_len) self._buffer = StringIO(data[start:]) if start < data_len: logger.debug('_parse11: still have data, may have another full message!')