Add debug stuff to show the telnet console death issue.

pull/2345/head
John Fleming 4 months ago
parent 9774fe9468
commit b759d31482

@ -62,6 +62,7 @@ READ_SIZE = 1024
class TelnetConnection(object): class TelnetConnection(object):
"""Default implementation of telnet connection which may but may not be used.""" """Default implementation of telnet connection which may but may not be used."""
def __init__(self, reader, writer, window_size_changed_callback=None): def __init__(self, reader, writer, window_size_changed_callback=None):
log.debug(f"Start TelnetConnection init")
self.is_closing = False self.is_closing = False
self._reader = reader self._reader = reader
self._writer = writer self._writer = writer
@ -69,6 +70,7 @@ class TelnetConnection(object):
@property @property
def reader(self): def reader(self):
log.debug(f"Start TelnetConnection reader")
return self._reader return self._reader
@property @property
@ -77,15 +79,18 @@ class TelnetConnection(object):
async def connected(self): async def connected(self):
"""Method called when client is connected""" """Method called when client is connected"""
log.debug(f"Start TelnetConnection connected")
pass pass
async def disconnected(self): async def disconnected(self):
"""Method called when client is disconnecting""" """Method called when client is disconnecting"""
log.debug(f"Start TelnetConnection disconnected")
pass pass
async def window_size_changed(self, columns, rows): async def window_size_changed(self, columns, rows):
"""Method called when window size changed, only can occur when """Method called when window size changed, only can occur when
`naws` flag is enable in server configuration.""" `naws` flag is enable in server configuration."""
log.debug(f"Start TelnetConnection window_size_changed")
if self._window_size_changed_callback: if self._window_size_changed_callback:
await self._window_size_changed_callback(columns, rows) await self._window_size_changed_callback(columns, rows)
@ -95,12 +100,14 @@ class TelnetConnection(object):
Handles incoming data Handles incoming data
:return: :return:
""" """
log.debug(f"Start TelnetConnection feed")
def send(self, data): def send(self, data):
""" """
Sending data back to client Sending data back to client
:return: :return:
""" """
log.debug(f"Start TelnetConnection send")
data = data.decode().replace("\n", "\r\n") data = data.decode().replace("\n", "\r\n")
self.writer.write(data.encode()) self.writer.write(data.encode())
@ -109,6 +116,7 @@ class TelnetConnection(object):
Closes current connection Closes current connection
:return: :return:
""" """
log.debug(f"Start TelnetConnection close")
self.is_closing = True self.is_closing = True
@ -116,6 +124,7 @@ class AsyncioTelnetServer:
MAX_NEGOTIATION_READ = 10 MAX_NEGOTIATION_READ = 10
def __init__(self, reader=None, writer=None, binary=True, echo=False, naws=False, window_size_changed_callback=None, connection_factory=None): def __init__(self, reader=None, writer=None, binary=True, echo=False, naws=False, window_size_changed_callback=None, connection_factory=None):
log.debug(f"Start AsyncioTelnetServer init")
""" """
Initializes telnet server Initializes telnet server
:param naws when True make a window size negotiation :param naws when True make a window size negotiation
@ -140,6 +149,7 @@ class AsyncioTelnetServer:
self._naws = naws self._naws = naws
def default_connection_factory(reader, writer, window_size_changed_callback): def default_connection_factory(reader, writer, window_size_changed_callback):
log.debug(f"Start connection factory")
return TelnetConnection(reader, writer, window_size_changed_callback) return TelnetConnection(reader, writer, window_size_changed_callback)
if connection_factory is None: if connection_factory is None:
@ -149,6 +159,7 @@ class AsyncioTelnetServer:
@staticmethod @staticmethod
async def write_client_intro(writer, echo=False): async def write_client_intro(writer, echo=False):
log.debug(f"Start async write_clien_intro")
# Send initial telnet session opening # Send initial telnet session opening
if echo: if echo:
writer.write(bytes([IAC, WILL, ECHO])) writer.write(bytes([IAC, WILL, ECHO]))
@ -159,6 +170,7 @@ class AsyncioTelnetServer:
await writer.drain() await writer.drain()
async def _write_intro(self, writer, binary=False, echo=False, naws=False): async def _write_intro(self, writer, binary=False, echo=False, naws=False):
log.debug(f"Start async _write_intro")
# Send initial telnet session opening # Send initial telnet session opening
if echo: if echo:
writer.write(bytes([IAC, WILL, ECHO])) writer.write(bytes([IAC, WILL, ECHO]))
@ -187,14 +199,10 @@ class AsyncioTelnetServer:
async def run(self, network_reader, network_writer): async def run(self, network_reader, network_writer):
log.debug(f"Start async run")
sock = network_writer.get_extra_info("socket") sock = network_writer.get_extra_info("socket")
sock.setsockopt(socket.SOL_SOCKET, socket.SO_KEEPALIVE, 1) sock.setsockopt(socket.SOL_SOCKET, socket.SO_KEEPALIVE, 1)
sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)
# 60 sec keep alives, close tcp session after 4 missed
# Will keep a firewall from aging out telnet console.
sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPIDLE, 60)
sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPINTVL, 10)
sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPCNT, 4)
#log.debug("New connection from {}".format(sock.getpeername())) #log.debug("New connection from {}".format(sock.getpeername()))
# Keep track of connected clients # Keep track of connected clients
@ -206,9 +214,12 @@ class AsyncioTelnetServer:
await connection.connected() await connection.connected()
await self._process(network_reader, network_writer, connection) await self._process(network_reader, network_writer, connection)
except ConnectionError: except ConnectionError:
log.info("Async ConnectionError")
async with self._lock: async with self._lock:
network_writer.close() network_writer.close()
# await network_writer.wait_closed() # this doesn't work in Python 3.6 # await network_writer.wait_closed() # this doesn't work in Python 3.6
log.debug(f"self._reader_process == network_reader")
log.debug(f"{self._reader_process} == {network_reader}")
if self._reader_process == network_reader: if self._reader_process == network_reader:
self._reader_process = None self._reader_process = None
# Cancel current read from this reader # Cancel current read from this reader
@ -219,6 +230,7 @@ class AsyncioTelnetServer:
del self._connections[network_writer] del self._connections[network_writer]
async def close(self): async def close(self):
log.debug(f"Start async close")
for writer, connection in self._connections.items(): for writer, connection in self._connections.items():
try: try:
writer.write_eof() writer.write_eof()
@ -229,29 +241,40 @@ class AsyncioTelnetServer:
continue continue
async def client_connected_hook(self): async def client_connected_hook(self):
log.debug(f"Start async client_connected_hook")
pass pass
async def _get_reader(self, network_reader): async def _get_reader(self, network_reader):
""" """
Get a reader or None if another reader is already reading. Get a reader or None if another reader is already reading.
""" """
log.debug(f"Start async _get_reader")
async with self._lock: async with self._lock:
if self._reader_process is None: if self._reader_process is None:
self._reader_process = network_reader self._reader_process = network_reader
if self._reader: if self._reader:
log.debug(f"self._reader_process == network_reader")
log.debug(f"{self._reader_process} == {network_reader}")
if self._reader_process == network_reader: if self._reader_process == network_reader:
self._current_read = asyncio.ensure_future(self._reader.read(READ_SIZE)) self._current_read = asyncio.ensure_future(self._reader.read(READ_SIZE))
return self._current_read return self._current_read
log.debug(f"_get_reader Returning None")
return None return None
async def _process(self, network_reader, network_writer, connection): async def _process(self, network_reader, network_writer, connection):
log.debug(f"Start async _process")
network_read = asyncio.ensure_future(network_reader.read(READ_SIZE)) network_read = asyncio.ensure_future(network_reader.read(READ_SIZE))
reader_read = await self._get_reader(network_reader) reader_read = await self._get_reader(network_reader)
while True: while True:
log.debug(f"__process True loop")
if reader_read is None: if reader_read is None:
log.debug(f"__process reader_read is None")
reader_read = await self._get_reader(network_reader) reader_read = await self._get_reader(network_reader)
log.debug(f"__process reader_read is still 2nd None")
if reader_read is None: if reader_read is None:
log.debug(f"__process reader_read is still 3rd None")
done, pending = await asyncio.wait( done, pending = await asyncio.wait(
[ [
network_read, network_read,
@ -259,13 +282,19 @@ class AsyncioTelnetServer:
timeout=1, timeout=1,
return_when=asyncio.FIRST_COMPLETED) return_when=asyncio.FIRST_COMPLETED)
else: else:
log.debug(f"__process reader_read else")
done, pending = await asyncio.wait( done, pending = await asyncio.wait(
[ [
network_read, network_read,
reader_read reader_read
], ],
return_when=asyncio.FIRST_COMPLETED) return_when=asyncio.FIRST_COMPLETED)
log.debug(f"__process just before coro done check")
log.debug(f"")
log.debug(f"")
log.debug(f"")
for coro in done: for coro in done:
log.debug(f"__process coro can has done?")
data = coro.result() data = coro.result()
if coro == network_read: if coro == network_read:
if network_reader.at_eof(): if network_reader.at_eof():
@ -303,6 +332,7 @@ class AsyncioTelnetServer:
async def _read(self, cmd, buffer, location, reader): async def _read(self, cmd, buffer, location, reader):
""" Reads next op from the buffer or reader""" """ Reads next op from the buffer or reader"""
log.debug(f"Start async _read")
try: try:
op = buffer[location] op = buffer[location]
cmd.append(op) cmd.append(op)
@ -315,6 +345,7 @@ class AsyncioTelnetServer:
async def _negotiate(self, data, connection): async def _negotiate(self, data, connection):
""" Performs negotiation commands""" """ Performs negotiation commands"""
log.debug(f"Start async _negotiate")
command, payload = data[0], data[1:] command, payload = data[0], data[1:]
if command == NAWS: if command == NAWS:
@ -327,6 +358,7 @@ class AsyncioTelnetServer:
log.debug("Not supported negotiation sequence, received {} bytes", len(data)) log.debug("Not supported negotiation sequence, received {} bytes", len(data))
async def _IAC_parser(self, buf, network_reader, network_writer, connection): async def _IAC_parser(self, buf, network_reader, network_writer, connection):
log.debug(f"Start async _IAC_parser")
""" """
Processes and removes any Telnet commands from the buffer. Processes and removes any Telnet commands from the buffer.

Loading…
Cancel
Save