Merge pull request #1155 from Emantor/topic/logging_work

 Rework Step information to use logging infrastructure #1106

CHANGES.rst

@@ -3,7 +3,13 @@ Release 23.1 (unreleased)
 
 New Features in 23.1
 ~~~~~~~~~~~~~~~~~~~~
-
+- When invoking tests with pytest, the ``--log-(cli|file)-(level|format)``
+  command line arguments and their corresponding pytest.ini configure options
+  are now respected (making it possible to have different format and logging
+  levels in the log file than then console).
+- A new log level called ``CONSOLE`` has been added between the default
+  ``INFO`` and ``DEBUG`` levels. This level will show all reads and writes made
+  to the serial console during testing.
 
 Bug fixes in 23.1
 ~~~~~~~~~~~~~~~~~
@@ -24,6 +30,30 @@ Breaking changes in 23.1
   `coordinator container <https://hub.docker.com/r/labgrid/coordinator>`_ or
   install it into a separate local venv as desribed in the
   `documentation <https://labgrid.readthedocs.io/en/latest/getting_started.html#coordinator>`_.
+- The `StepReporter` API has been changed. To start step reporting, you must
+  now call ``StepReporter.start()`` instead of ``StepReporter()``
+- Logging output when running pytest is no longer sent to stderr by default,
+  since this is both chatty and also unnecessary with the improved logging
+  flexibility. It it recommended to use the ``--log-cli-level=INFO`` command
+  line option, or ``log_cli_level = INFO`` option in pytest.ini, but if you
+  want to restore the old behavior add the following to your ``conftest.py``
+  file (note that doing so may affect the ability to use some more advanced
+  logging features)::
+
+     def pytest_configure(config):
+         import logging
+         import sys
+
+         logging.basicConfig(
+             level=logging.INFO,
+             format='%(levelname)8s: %(message)s',
+             stream=sys.stderr,
+         )
+
+- The interpretation of the ``-v`` command line argument to pytest has changed
+  slightly. ``-vv`` is now an alias for ``--log-cli-level=INFO`` (effectively
+  unchanged), ``-vvv`` is an alias for ``--log-cli-level=CONSOLE``, and
+  ``-vvvv`` is an alias for ``--log-cli-level=DEBUG``.
 
 Known issues in 23.1
 ~~~~~~~~~~~~~~~~~~~~
@@ -172,7 +202,7 @@ New Features in 0.4.0
 - With ``--lg-colored-steps``, two new ``dark`` and ``light`` color schemes
   which only use the standard 8 ANSI colors can be set in ``LG_COLOR_SCHEME``.
   The existing color schemes have been renamed to ``dark-256color`` and ``light-256color``.
-  Also, the `ColoredStepReporter` now tries to autodetect whether the terminal
+  Also, the ``ColoredStepReporter`` now tries to autodetect whether the terminal
   supports 8 or 256 colors, and defaults to the respective dark variant.
   The 256-color schemes now use purple instead of green for the ``run`` lines to
   make them easier distinguishable from pytest's "PASSED" output.

doc/configuration.rst

@@ -3023,10 +3023,6 @@ The Reporter can be stopped with a call to the stop function:
 Stopping the StepReporter if it has not been started will raise an
 AssertionError, as will starting an already started StepReporter.
 
-ColoredStepReporter
-~~~~~~~~~~~~~~~~~~~
-The ColoredStepReporter inherits from the StepReporter.
-The output is colored using ANSI color code sequences.
 
 ConsoleLoggingReporter
 ~~~~~~~~~~~~~~~~~~~~~~

labgrid/consoleloggingreporter.py

@@ -83,7 +83,7 @@ def notify(self, event):
         """This is the callback function for steps"""
         step = event.step
         if step.tag == 'console':
-            if str(step) == 'read':
+            if step.title == 'read':
                 if event.data.get('state') == 'stop':
                     if step.result and step.source:
                         log = self.get_logfile(event)

labgrid/driver/bareboxdriver.py

@@ -1,5 +1,4 @@
 import logging
-import re
 import shlex
 
 import attr
@@ -8,7 +7,7 @@
 from ..factory import target_factory
 from ..protocol import CommandProtocol, ConsoleProtocol, LinuxBootProtocol
 from ..step import step
-from ..util import gen_marker, Timeout
+from ..util import gen_marker, Timeout, re_vt100
 from .common import Driver
 from .commandmixin import CommandMixin
 
@@ -41,9 +40,6 @@ class BareboxDriver(CommandMixin, Driver, CommandProtocol, LinuxBootProtocol):
 
     def __attrs_post_init__(self):
         super().__attrs_post_init__()
-        self.re_vt100 = re.compile(
-            r'(\x1b\[|\x9b)[^@-_a-z]*[@-_a-z]|\x1b[@-_a-z]'
-        )
         self.logger = logging.getLogger(f"{self}:{self.target}")
         self._status = 0
 
@@ -89,7 +85,7 @@ def _run(self, cmd: str, *, timeout: int = 30, codec: str = "utf-8", decodeerror
                 rf'{marker}(.*){marker}\s+(\d+)\s+.*{self.prompt}',
                 timeout=timeout)
             # Remove VT100 Codes and split by newline
-            data = self.re_vt100.sub('', match.group(1).decode('utf-8')).split('\r\n')[1:-1]
+            data = re_vt100.sub('', match.group(1).decode('utf-8')).split('\r\n')[1:-1]
             self.logger.debug("Received Data: %s", data)
             # Get exit code
             exitcode = int(match.group(2))

labgrid/driver/qemudriver.py

@@ -310,6 +310,8 @@ def _read(self, size=1, timeout=10, max_size=None):
             raise TIMEOUT(f"Timeout of {timeout:.2f} seconds exceeded")
         return res
 
-    @step(args=['data'])
     def _write(self, data):
         return self._clientsocket.send(data)
+
+    def __str__(self):
+        return f"QemuDriver({self.target.name})"

labgrid/driver/serialdriver.py

@@ -114,3 +114,6 @@ def close(self):
         if self.status:
             self.serial.close()
             self.status = 0
+
+    def __str__(self):
+        return f"SerialDriver({self.target.name})"

labgrid/driver/shelldriver.py

@@ -14,7 +14,7 @@
 from ..factory import target_factory
 from ..protocol import CommandProtocol, ConsoleProtocol, FileTransferProtocol
 from ..step import step
-from ..util import gen_marker, Timeout
+from ..util import gen_marker, Timeout, re_vt100
 from .commandmixin import CommandMixin
 from .common import Driver
 from .exception import ExecutionError
@@ -58,9 +58,6 @@ class ShellDriver(CommandMixin, Driver, CommandProtocol, FileTransferProtocol):
 
     def __attrs_post_init__(self):
         super().__attrs_post_init__()
-        self.re_vt100 = re.compile(
-            r'(\x1b\[|\x9b)[^@-_a-z]*[@-_a-z]|\x1b[@-_a-z]'
-        )
         self.logger = logging.getLogger(f"{self}:{self.target}")
         self._status = 0
 
@@ -100,7 +97,7 @@ def _run(self, cmd, *, timeout=30.0, codec="utf-8", decodeerrors="strict"):
             timeout=timeout
         )
         # Remove VT100 Codes, split by newline and remove surrounding newline
-        data = self.re_vt100.sub('', match.group(1).decode(codec, decodeerrors)).split('\r\n')
+        data = re_vt100.sub('', match.group(1).decode(codec, decodeerrors)).split('\r\n')
         if data and not data[-1]:
             del data[-1]
         self.logger.debug("Received Data: %s", data)

labgrid/driver/smallubootdriver.py

@@ -6,6 +6,7 @@
 from .common import Driver
 
 from .ubootdriver import UBootDriver
+from ..util import re_vt100
 
 @target_factory.reg_driver
 @attr.s(eq=False)
@@ -97,7 +98,7 @@ def _run(self, cmd: str, *, timeout: int = 30, codec: str = "utf-8", decodeerror
         self.console.sendline(cmp_command)
         _, before, _, _ = self.console.expect(self.prompt, timeout=timeout)
 
-        data = self.re_vt100.sub(
+        data = re_vt100.sub(
             '', before.decode('utf-8'), count=1000000
         ).replace("\r", "").split("\n")
         data = data[1:]

labgrid/driver/ubootdriver.py

@@ -1,13 +1,12 @@
 """The U-Boot Module contains the UBootDriver"""
 import logging
-import re
 
 import attr
 from pexpect import TIMEOUT
 
 from ..factory import target_factory
 from ..protocol import CommandProtocol, ConsoleProtocol, LinuxBootProtocol
-from ..util import gen_marker, Timeout
+from ..util import gen_marker, Timeout, re_vt100
 from ..step import step
 from .common import Driver
 from .commandmixin import CommandMixin
@@ -49,9 +48,6 @@ class UBootDriver(CommandMixin, Driver, CommandProtocol, LinuxBootProtocol):
 
     def __attrs_post_init__(self):
         super().__attrs_post_init__()
-        self.re_vt100 = re.compile(
-            r'(\x1b\[|\x9b)[^@-_a-z]*[@-_a-z]|\x1b[@-_a-z]'
-        )
         self.logger = logging.getLogger(f"{self}:{self.target}")
         self._status = 0
 
@@ -83,7 +79,7 @@ def _run(self, cmd: str, *, timeout: int = 30, codec: str = "utf-8", decodeerror
             self.console.sendline(cmp_command)
             _, before, _, _ = self.console.expect(self.prompt, timeout=timeout)
             # Remove VT100 Codes and split by newline
-            data = self.re_vt100.sub(
+            data = re_vt100.sub(
                 '', before.decode('utf-8'), count=1000000
             ).replace("\r", "").split("\n")
             self.logger.debug("Received Data: %s", data)