diff --git a/nsfarm/board/_board.py b/nsfarm/board/_board.py
index 3944042d345a89cb97cf0fbe3071bbafdc551d6f..f3375b39277448ed493fa5e492e5e9b56393fedb 100644
--- a/nsfarm/board/_board.py
+++ b/nsfarm/board/_board.py
@@ -2,6 +2,7 @@
"""
import sys
import time
+import logging
import serial
import serial.tools.miniterm
from pexpect import fdpexpect
@@ -24,9 +25,8 @@ class Board:
self.config = target_config
# Open serial console to board
self._serial = serial.Serial(self.config['serial'], 115200)
- # TODO better and configurable logging
- self.logfile = open("./{}.log".format(target), "wb")
- self._pexpect = fdpexpect.fdspawn(self._serial, logfile=self.logfile)
+ self._pexpect = fdpexpect.fdspawn(self._serial)
+ self._pexpect.logfile_read = cli.PexpectLogging(logging.getLogger('{}[{}]'.format(__package__, target)))
# Set board to some known state
self.reset(True) # Hold in reset state
diff --git a/nsfarm/cli.py b/nsfarm/cli.py
index ce27f2e05839b7f8dffdbb248a3aa79d72753c91..80534a985d48b1d08269ec11a7ac570adc992309 100644
--- a/nsfarm/cli.py
+++ b/nsfarm/cli.py
@@ -3,7 +3,7 @@
This ensures systematic logging and access to terminals. We implement two special terminal types at the moment. We have
support for shell and u-boot. They differ in a way how they handle prompt and methods they provide to user.
"""
-import pexpect
+import logging
import base64
@@ -162,6 +162,41 @@ class Uboot(Cli):
return self._output
+class PexpectLogging:
+ """Logging for pexpect.
+
+ This emulates file object and is intended to be used with pexpect handler as logger.
+ """
+ _EXPECTED_EOL = b'\n\r'
+
+ def __init__(self, logger):
+ self._level = logging.INFO
+ self.logger = logger
+ self.linebuf = b''
+
+ def __del__(self):
+ if self.linebuf:
+ self._log(self.linebuf)
+
+ def _log(self, line):
+ self.logger.log(self._level, repr(line.rstrip(self._EXPECTED_EOL).expandtabs())[2:-1])
+
+ def write(self, buf):
+ """Standard-like file write function.
+ """
+ jbuf = self.linebuf + buf
+ lines = jbuf.splitlines(keepends=True)
+ if lines[-1] or lines[-1][-1] not in self._EXPECTED_EOL:
+ # The last line is not terminated (no new line character) so just preserve it
+ self.linebuf = lines.pop()
+ for line in lines:
+ self._log(line)
+
+ def flush(self):
+ """Standard-like flush function.
+ """
+ # Just ignore flush
+
# Notest on some of the hacks in this file
#
# There are new line character matches in regular expressions. Correct one is \r\n but some serial controlles for some
diff --git a/nsfarm/lxd/_lxd.py b/nsfarm/lxd/_lxd.py
index 21263b8fae5218681b287b4c57538308c7a5136d..38e0a826e898b2df087983541a419b914ef0ba94 100644
--- a/nsfarm/lxd/_lxd.py
+++ b/nsfarm/lxd/_lxd.py
@@ -1,5 +1,6 @@
"""Internal global LXD handle
"""
+import logging
import pylxd
IMAGES_SOURCE = "https://images.linuxcontainers.org"
@@ -16,9 +17,14 @@ def _profile_device(profile, checkfunc):
def connect():
"""Make sure that we are connected to LXD.
"""
+ # Suppress logging of pylxd components
+ logging.getLogger('ws4py').setLevel(logging.ERROR)
+ logging.getLogger('urllib3').setLevel(logging.ERROR)
+ # Initialize LXD connection to linuximages.org
global IMAGES
if IMAGES is None:
IMAGES = pylxd.Client(IMAGES_SOURCE)
+ # Initialize LXD connection to local server
global LOCAL
if LOCAL is None:
LOCAL = pylxd.Client()
diff --git a/nsfarm/lxd/container.py b/nsfarm/lxd/container.py
index 535c5255ece1e602236dcccfd4adb2c73d588cfd..7a6194c38b66245d77129fa7a33dc59b07640f46 100644
--- a/nsfarm/lxd/container.py
+++ b/nsfarm/lxd/container.py
@@ -6,23 +6,27 @@ import itertools
import hashlib
import logging
import pexpect
+from .. import cli
from . import _lxd
IMAGE_INIT_PATH = "/nsfarm-init.sh" # Where we deploy initialization script for image
IMGS_DIR = os.path.join(os.path.dirname(os.path.dirname(os.path.dirname(__file__))), "imgs")
+LOGGER = logging.getLogger(__package__)
class Container():
"""Generic container handle.
"""
+ # TODO log syslog somehow
- def __init__(self, img_name, devices=[], internet=True):
+ def __init__(self, img_name, devices=(), internet=True):
self._name = img_name
self._internet = internet
self._devices = tuple(devices)
self._dpath = os.path.join(IMGS_DIR, img_name)
self._fpath = self._dpath + ".sh"
+ self._logger = logging.getLogger("{}[{}]".format(__package__, img_name))
# Verify existence of image definition
if not os.path.isfile(self._fpath):
raise Exception("There seems to be no file describing image: {}".format(self._fpath))
@@ -102,7 +106,7 @@ class Container():
self._lxd_image = _lxd.LOCAL.images.get_by_alias(self._image_alias)
return
# We do not have appropriate image so prepare it
- logging.info("Bootstrapping image: %s", self._image_alias)
+ LOGGER.warning("Bootstrapping image: %s", self._image_alias)
image_source = {
'type': 'image',
}
@@ -126,13 +130,14 @@ class Container():
# TODO found other way to match reason
if not str(elxd).endswith("This container already exists"):
raise
- logging.warning("Other instance is already bootsrapping image probably. "
+ LOGGER.warning("Other instance is already bootsrapping image probably. "
"Waiting for following container to go away: %s", container_name)
while _lxd.LOCAL.containers.exists(container_name):
time.sleep(1)
self.prepare_image() # possibly get created image or try again
return
try:
+ # TODO log boostrap process
# Copy script and files to container
with open(self._fpath) as file:
container.files.put(IMAGE_INIT_PATH, file.read(), mode=700)
@@ -180,6 +185,7 @@ class Container():
},
}, wait=True)
self._lxd_container.start(wait=True)
+ self._logger.debug("Container prepared: %s", self._lxd_container.name)
# TODO we could somehow just let it create it and return from this method and wait later on when we realy need
# container.
@@ -190,6 +196,7 @@ class Container():
"""
if self._lxd_container is None:
return # No cleanup is required
+ self._logger.debug("Removing container: %s", self._lxd_container.name)
# First freeze and remove devices
self._lxd_container.freeze(wait=True)
self._lxd_container.devices = dict()
@@ -200,12 +207,14 @@ class Container():
self._lxd_container.stop()
self._lxd_container = None
- def pexpect(self, shell="/bin/sh"):
- """Returns pexpect handle for shell in container.
+ def pexpect(self, command=["/bin/sh"]):
+ """Returns pexpect handle for command running in container.
"""
- # TODO some logging of this session
assert self._lxd_container is not None
- return pexpect.spawn('lxc', ["exec", self._lxd_container.name, shell])
+ self._logger.debug("Running command: %s", command)
+ pexp = pexpect.spawn('lxc', ["exec", self._lxd_container.name] + command)
+ pexp.logfile_read = cli.PexpectLogging(logging.getLogger(self._logger.name + str(command)))
+ return pexp
def __enter__(self):
self.prepare()
diff --git a/pytest.ini b/pytest.ini
index a7c66248cf4af9294650a259822b6eb1f96715e2..b509f12500db3a4199778517fe6b43c585624305 100644
--- a/pytest.ini
+++ b/pytest.ini
@@ -1,5 +1,8 @@
[pytest]
addopts = --strict-markers
+log_level = DEBUG
+log_format = %(levelname)s[%(relativeCreated)d]%(name)s %(message)s
+log_cli_format = %(levelname)s %(name)s %(message)s
markers =
deploy: quick tests to be run as part of deployment process
board(boards): mark test to run only on specified board