From e1a30f2297ec939ad8225c041eeed7a305699cc3 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Karel=20Ko=C4=8D=C3=AD?= <karel.koci@nic.cz>
Date: Thu, 16 Jul 2020 11:00:12 +0200
Subject: [PATCH] Replace logging trough pexpect with realtime logging
Problem with logging trough pexpect is that we log output only when we
expect it. That is when we access it trough pexpect. This means that
time and synchronization when logs arrive from multiple sources can't be
archived and only one source logs at the time (the one that is used
currently by pexpect). This is not ideal as we are interested in
situation such as restarting network interfaces that produce some logs
not only on router but also in container at the same time.
Synchronization on time bases in such cases is important and we can't
wait for code to call pexpect to print it to logs later on.
This instead utilizes sockets and by reading source immediately and just
passing it to socket.
---
nsfarm/cli.py | 94 +++++++++++++++++++++++++++++++++++++++++++++++++--
1 file changed, 92 insertions(+), 2 deletions(-)
diff --git a/nsfarm/cli.py b/nsfarm/cli.py
index e21b13c..b9f2c47 100644
--- a/nsfarm/cli.py
+++ b/nsfarm/cli.py
@@ -8,9 +8,14 @@ support for shell and u-boot. They differ in a way how they handle prompt and m
# There are new line character matches in regular expressions. Correct one is \r\n but some serial controlles for some
# reason also use \n\r so we match both alternatives.
#
+import os
+import io
import abc
import logging
import base64
+import fcntl
+import socket
+import threading
import typing
_FLUSH_BUFFLEN = 2048
@@ -52,7 +57,8 @@ class Cli(abc.ABC):
All keyword arguments are passed to pexpect's expect call.
"""
- @abc.abstractproperty
+ @property
+ @abc.abstractmethod
def output(self):
"""All output before latest prompt.
@@ -190,6 +196,90 @@ class Uboot(Cli):
return self._output
+class FDLogging:
+ """Live logging with data passtrough.
+
+ This is stream logging that logs communication comming from and to file descript trough socket. This intended use is
+ for direct output to be visible live in logs.
+
+ This has one primary limitation and that is output only in lines. Log is created only when new line character is
+ located not before that.
+ """
+ _EXPECTED_EOL = b'\n\r'
+
+ def __init__(self, fd, logger, in_level=logging.INFO, out_level=logging.DEBUG):
+ self.logger = logger
+ self.in_level = in_level
+ self.out_level = out_level
+ self.fileno = fd.fileno()
+ self.our_sock, self.user_sock = socket.socketpair()
+
+ # Input
+ self.inputthread = threading.Thread(target=self._input, daemon=True)
+ self.inputthread.start()
+ # Output
+ self.outputthread = threading.Thread(target=self._output, daemon=True)
+ self.outputthread.start()
+
+ def socket(self):
+ """Returns socket for user to use to communicate trough this logged passtrough.
+ """
+ return self.user_sock
+
+ def close(self):
+ """Close socket and stop logging.
+ """
+ if self.our_sock is not None:
+ # Terminates and cleans _input
+ _orig_filestatus = fcntl.fcntl(self.fileno, fcntl.F_GETFL)
+ fcntl.fcntl(self.fileno, fcntl.F_SETFL, _orig_filestatus | os.O_NONBLOCK)
+ self.inputthread.join()
+ fcntl.fcntl(self.fileno, fcntl.F_SETFL, _orig_filestatus)
+ # Terminates and cleans _output
+ self.our_sock.close()
+ self.outputthread.join()
+ self.our_sock = None
+
+ def __del__(self):
+ self.close()
+
+ def _log_line(self, line, level):
+ self.logger.log(level, repr(line.rstrip(self._EXPECTED_EOL).expandtabs())[2:-1])
+
+ def _log(self, prev_data, new_data, level):
+ data = prev_data + new_data
+ lines = data.splitlines(keepends=True)
+ if not lines:
+ return
+ # The last line does not have to be terminated (no new line character) so just preserve it
+ reminder = lines.pop() if lines[-1] or lines[-1][-1] not in self._EXPECTED_EOL else b''
+ for line in lines:
+ self._log_line(line, level)
+ return reminder
+
+ def _input(self):
+ data = b''
+ while True:
+ try:
+ new_data = os.read(self.fileno, io.DEFAULT_BUFFER_SIZE)
+ except io.BlockingIOError:
+ self._log_line(data, self.in_level)
+ return
+ self.our_sock.sendall(new_data)
+ data = self._log(data, new_data, self.in_level)
+
+ def _output(self):
+ data = b''
+ while True:
+ try:
+ new_data = self.our_sock.recv(io.DEFAULT_BUFFER_SIZE)
+ except io.BlockingIOError:
+ self._log_line(data, self.out_level)
+ return
+ os.write(self.fileno, new_data)
+ data = self._log(data, new_data, self.out_level)
+
+
class PexpectLogging:
"""Logging for pexpect.
@@ -198,7 +288,7 @@ class PexpectLogging:
_EXPECTED_EOL = b'\n\r'
def __init__(self, logger):
- self._level = logging.INFO
+ self._level = logging.DEBUG
self.logger = logger
self.linebuf = b''
--
GitLab