[v2,6/7] dts: refactor logging configuration

  Remove unused parts of the code and add useful features:
1. Add DTS execution stages such as execution and test suite to better
   identify where in the DTS lifecycle we are when investigating logs,
2. Logging to separate files in specific stages, which is mainly useful
   for having test suite logs in additional separate files.
3. Remove the dependence on the settings module which enhances the
   usefulness of the logger module, as it can now be imported in more
   modules.

The execution stages and the files to log to are the same for all DTS
loggers. To achieve this, we have one DTS root logger which should be
used for handling stage switching and all other loggers are children of
this DTS root logger. The DTS root logger is the one where we change the
behavior of all loggers (the stage and which files to log to) and the
child loggers just log messages under a different name.

Signed-off-by: Juraj Linkeš <juraj.linkes@pantheon.tech>
---
 dts/framework/logger.py                       | 235 +++++++++++-------
 dts/framework/remote_session/__init__.py      |   6 +-
 .../interactive_remote_session.py             |   6 +-
 .../remote_session/interactive_shell.py       |   6 +-
 .../remote_session/remote_session.py          |   8 +-
 dts/framework/runner.py                       |  19 +-
 dts/framework/test_result.py                  |   6 +-
 dts/framework/test_suite.py                   |   6 +-
 dts/framework/testbed_model/node.py           |  11 +-
 dts/framework/testbed_model/os_session.py     |   7 +-
 .../traffic_generator/traffic_generator.py    |   6 +-
 dts/main.py                                   |   1 -
 12 files changed, 183 insertions(+), 134 deletions(-)
  

On Tue, Feb 6, 2024 at 9:57 AM Juraj Linkeš <juraj.linkes@pantheon.tech> wrote:
>
> Remove unused parts of the code and add useful features:
> 1. Add DTS execution stages such as execution and test suite to better
>    identify where in the DTS lifecycle we are when investigating logs,
> 2. Logging to separate files in specific stages, which is mainly useful
>    for having test suite logs in additional separate files.
> 3. Remove the dependence on the settings module which enhances the
>    usefulness of the logger module, as it can now be imported in more
>    modules.
>
> The execution stages and the files to log to are the same for all DTS
> loggers. To achieve this, we have one DTS root logger which should be
> used for handling stage switching and all other loggers are children of
> this DTS root logger. The DTS root logger is the one where we change the
> behavior of all loggers (the stage and which files to log to) and the
> child loggers just log messages under a different name.
>
> Signed-off-by: Juraj Linkeš <juraj.linkes@pantheon.tech>
> ---
>  dts/framework/logger.py                       | 235 +++++++++++-------
>  dts/framework/remote_session/__init__.py      |   6 +-
>  .../interactive_remote_session.py             |   6 +-
>  .../remote_session/interactive_shell.py       |   6 +-
>  .../remote_session/remote_session.py          |   8 +-
>  dts/framework/runner.py                       |  19 +-
>  dts/framework/test_result.py                  |   6 +-
>  dts/framework/test_suite.py                   |   6 +-
>  dts/framework/testbed_model/node.py           |  11 +-
>  dts/framework/testbed_model/os_session.py     |   7 +-
>  .../traffic_generator/traffic_generator.py    |   6 +-
>  dts/main.py                                   |   1 -
>  12 files changed, 183 insertions(+), 134 deletions(-)
>
> diff --git a/dts/framework/logger.py b/dts/framework/logger.py
> index cfa6e8cd72..568edad82d 100644
> --- a/dts/framework/logger.py
> +++ b/dts/framework/logger.py
> @@ -5,141 +5,186 @@
>
>  """DTS logger module.
>
> -DTS framework and TestSuite logs are saved in different log files.
> +The module provides several additional features:
> +
> +    * The storage of DTS execution stages,
> +    * Logging to console, a human-readable log file and a machine-readable log file,
> +    * Optional log files for specific stages.
>  """
>
>  import logging
> -import os.path
> -from typing import TypedDict
> +from enum import auto
> +from logging import FileHandler, StreamHandler
> +from pathlib import Path
> +from typing import ClassVar
>
> -from .settings import SETTINGS
> +from .utils import StrEnum
>
>  date_fmt = "%Y/%m/%d %H:%M:%S"
> -stream_fmt = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
> +stream_fmt = "%(asctime)s - %(stage)s - %(name)s - %(levelname)s - %(message)s"
> +dts_root_logger_name = "dts"
> +
> +
> +class DtsStage(StrEnum):
> +    """The DTS execution stage."""
>
> +    #:
> +    pre_execution = auto()
> +    #:
> +    execution = auto()
> +    #:
> +    build_target = auto()
> +    #:
> +    suite = auto()
> +    #:
> +    post_execution = auto()
>
> -class DTSLOG(logging.LoggerAdapter):
> -    """DTS logger adapter class for framework and testsuites.
>
> -    The :option:`--verbose` command line argument and the :envvar:`DTS_VERBOSE` environment
> -    variable control the verbosity of output. If enabled, all messages will be emitted to the
> -    console.
> +class DTSLogger(logging.Logger):
> +    """The DTS logger class.
>
> -    The :option:`--output` command line argument and the :envvar:`DTS_OUTPUT_DIR` environment
> -    variable modify the directory where the logs will be stored.
> +    The class extends the :class:`~logging.Logger` class to add the DTS execution stage information
> +    to log records. The stage is common to all loggers, so it's stored in a class variable.
>
> -    Attributes:
> -        node: The additional identifier. Currently unused.
> -        sh: The handler which emits logs to console.
> -        fh: The handler which emits logs to a file.
> -        verbose_fh: Just as fh, but logs with a different, more verbose, format.
> +    Any time we switch to a new stage, we have the ability to log to an additional log file along
> +    with a supplementary log file with machine-readable format. These two log files are used until
> +    a new stage switch occurs. This is useful mainly for logging per test suite.
>      """
>
> -    _logger: logging.Logger
> -    node: str
> -    sh: logging.StreamHandler
> -    fh: logging.FileHandler
> -    verbose_fh: logging.FileHandler
> +    _stage: ClassVar[DtsStage] = DtsStage.pre_execution
> +    _extra_file_handlers: list[FileHandler] = []
>
> -    def __init__(self, logger: logging.Logger, node: str = "suite"):
> -        """Extend the constructor with additional handlers.
> +    def __init__(self, *args, **kwargs):
> +        """Extend the constructor with extra file handlers."""
> +        self._extra_file_handlers = []
> +        super().__init__(*args, **kwargs)
>
> -        One handler logs to the console, the other one to a file, with either a regular or verbose
> -        format.
> +    def makeRecord(self, *args, **kwargs):

Is the return type annotation here skipped because of the `:meta private:`?

> +        """Generates a record with additional stage information.
>
> -        Args:
> -            logger: The logger from which to create the logger adapter.
> -            node: An additional identifier. Currently unused.
> +        This is the default method for the :class:`~logging.Logger` class. We extend it
> +        to add stage information to the record.
> +
> +        :meta private:
> +
> +        Returns:
> +            record: The generated record with the stage information.
>          """
> -        self._logger = logger
> -        # 1 means log everything, this will be used by file handlers if their level
> -        # is not set
> -        self._logger.setLevel(1)
> +        record = super().makeRecord(*args, **kwargs)
> +        record.stage = DTSLogger._stage
> +        return record
> +
> +    def add_dts_root_logger_handlers(self, verbose: bool, output_dir: str) -> None:
> +        """Add logger handlers to the DTS root logger.
> +
> +        This method should be called only on the DTS root logger.
> +        The log records from child loggers will propagate to these handlers.
> +
> +        Three handlers are added:
>
> -        self.node = node
> +            * A console handler,
> +            * A file handler,
> +            * A supplementary file handler with machine-readable logs
> +              containing more debug information.
>
> -        # add handler to emit to stdout
> -        sh = logging.StreamHandler()
> +        All log messages will be logged to files. The log level of the console handler
> +        is configurable with `verbose`.
> +
> +        Args:
> +            verbose: If :data:`True`, log all messages to the console.
> +                If :data:`False`, log to console with the :data:`logging.INFO` level.
> +            output_dir: The directory where the log files will be located.
> +                The names of the log files correspond to the name of the logger instance.
> +        """
> +        self.setLevel(1)
> +
> +        sh = StreamHandler()
>          sh.setFormatter(logging.Formatter(stream_fmt, date_fmt))
> -        sh.setLevel(logging.INFO)  # console handler default level
> +        if not verbose:
> +            sh.setLevel(logging.INFO)
> +        self.addHandler(sh)
>
> -        if SETTINGS.verbose is True:
> -            sh.setLevel(logging.DEBUG)
> +        self._add_file_handlers(Path(output_dir, self.name))
>
> -        self._logger.addHandler(sh)
> -        self.sh = sh
> +    def set_stage(self, stage: DtsStage, log_file_path: Path | None = None) -> None:
> +        """Set the DTS execution stage and optionally log to files.
>
> -        # prepare the output folder
> -        if not os.path.exists(SETTINGS.output_dir):
> -            os.mkdir(SETTINGS.output_dir)
> +        Set the DTS execution stage of the DTSLog class and optionally add
> +        file handlers to the instance if the log file name is provided.
>
> -        logging_path_prefix = os.path.join(SETTINGS.output_dir, node)
> +        The file handlers log all messages. One is a regular human-readable log file and
> +        the other one is a machine-readable log file with extra debug information.
>
> -        fh = logging.FileHandler(f"{logging_path_prefix}.log")
> -        fh.setFormatter(
> -            logging.Formatter(
> -                fmt="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
> -                datefmt=date_fmt,
> -            )
> -        )
> +        Args:
> +            stage: The DTS stage to set.
> +            log_file_path: An optional path of the log file to use. This should be a full path
> +                (either relative or absolute) without suffix (which will be appended).
> +        """
> +        self._remove_extra_file_handlers()
> +
> +        if DTSLogger._stage != stage:
> +            self.info(f"Moving from stage '{DTSLogger._stage}' to stage '{stage}'.")
> +            DTSLogger._stage = stage
> +
> +        if log_file_path:
> +            self._extra_file_handlers.extend(self._add_file_handlers(log_file_path))
> +
> +    def _add_file_handlers(self, log_file_path: Path) -> list[FileHandler]:
> +        """Add file handlers to the DTS root logger.
> +
> +        Add two type of file handlers:
> +
> +            * A regular file handler with suffix ".log",
> +            * A machine-readable file handler with suffix ".verbose.log".
> +              This format provides extensive information for debugging and detailed analysis.
> +
> +        Args:
> +            log_file_path: The full path to the log file without suffix.
> +
> +        Returns:
> +            The newly created file handlers.
>
> -        self._logger.addHandler(fh)
> -        self.fh = fh
> +        """
> +        fh = FileHandler(f"{log_file_path}.log")
> +        fh.setFormatter(logging.Formatter(stream_fmt, date_fmt))
> +        self.addHandler(fh)
>
> -        # This outputs EVERYTHING, intended for post-mortem debugging
> -        # Also optimized for processing via AWK (awk -F '|' ...)
> -        verbose_fh = logging.FileHandler(f"{logging_path_prefix}.verbose.log")
> +        verbose_fh = FileHandler(f"{log_file_path}.verbose.log")
>          verbose_fh.setFormatter(
>              logging.Formatter(
> -                fmt="%(asctime)s|%(name)s|%(levelname)s|%(pathname)s|%(lineno)d|"
> +                "%(asctime)s|%(stage)s|%(name)s|%(levelname)s|%(pathname)s|%(lineno)d|"
>                  "%(funcName)s|%(process)d|%(thread)d|%(threadName)s|%(message)s",
>                  datefmt=date_fmt,
>              )
>          )
> +        self.addHandler(verbose_fh)
>
> -        self._logger.addHandler(verbose_fh)
> -        self.verbose_fh = verbose_fh
> -
> -        super(DTSLOG, self).__init__(self._logger, dict(node=self.node))
> -
> -    def logger_exit(self) -> None:
> -        """Remove the stream handler and the logfile handler."""
> -        for handler in (self.sh, self.fh, self.verbose_fh):
> -            handler.flush()
> -            self._logger.removeHandler(handler)
> -
> -
> -class _LoggerDictType(TypedDict):
> -    logger: DTSLOG
> -    name: str
> -    node: str
> -
> +        return [fh, verbose_fh]
>
> -# List for saving all loggers in use
> -_Loggers: list[_LoggerDictType] = []
> +    def _remove_extra_file_handlers(self) -> None:
> +        """Remove any extra file handlers that have been added to the logger."""
> +        if self._extra_file_handlers:
> +            for extra_file_handler in self._extra_file_handlers:
> +                self.removeHandler(extra_file_handler)
>
> +            self._extra_file_handlers = []
>
> -def getLogger(name: str, node: str = "suite") -> DTSLOG:
> -    """Get DTS logger adapter identified by name and node.
>
> -    An existing logger will be returned if one with the exact name and node already exists.
> -    A new one will be created and stored otherwise.
> +def get_dts_logger(name: str = None) -> DTSLogger:
> +    """Return a DTS logger instance identified by `name`.
>
>      Args:
> -        name: The name of the logger.
> -        node: An additional identifier for the logger.
> +        name: If :data:`None`, return the DTS root logger.
> +            If specified, return a child of the DTS root logger.
>
>      Returns:
> -        A logger uniquely identified by both name and node.
> +         The DTS root logger or a child logger identified by `name`.
>      """
> -    global _Loggers
> -    # return saved logger
> -    logger: _LoggerDictType
> -    for logger in _Loggers:
> -        if logger["name"] == name and logger["node"] == node:
> -            return logger["logger"]
> -
> -    # return new logger
> -    dts_logger: DTSLOG = DTSLOG(logging.getLogger(name), node)
> -    _Loggers.append({"logger": dts_logger, "name": name, "node": node})
> -    return dts_logger
> +    logging.setLoggerClass(DTSLogger)
> +    if name:
> +        name = f"{dts_root_logger_name}.{name}"
> +    else:
> +        name = dts_root_logger_name
> +    logger = logging.getLogger(name)
> +    logging.setLoggerClass(logging.Logger)

What's the benefit of setting the logger class back to logging.Logger
here? Is the idea basically that if someone wanted to use the logging
module we shouldn't implicitly make them use our DTSLogger?

> +    return logger  # type: ignore[return-value]
> diff --git a/dts/framework/remote_session/__init__.py b/dts/framework/remote_session/__init__.py
> index 51a01d6b5e..1910c81c3c 100644
> --- a/dts/framework/remote_session/__init__.py
> +++ b/dts/framework/remote_session/__init__.py
> @@ -15,7 +15,7 @@
>  # pylama:ignore=W0611
>
>  from framework.config import NodeConfiguration
> -from framework.logger import DTSLOG
> +from framework.logger import DTSLogger
>
>  from .interactive_remote_session import InteractiveRemoteSession
>  from .interactive_shell import InteractiveShell
> @@ -26,7 +26,7 @@
>
>
>  def create_remote_session(
> -    node_config: NodeConfiguration, name: str, logger: DTSLOG
> +    node_config: NodeConfiguration, name: str, logger: DTSLogger
>  ) -> RemoteSession:
>      """Factory for non-interactive remote sessions.
>
> @@ -45,7 +45,7 @@ def create_remote_session(
>
>
>  def create_interactive_session(
> -    node_config: NodeConfiguration, logger: DTSLOG
> +    node_config: NodeConfiguration, logger: DTSLogger
>  ) -> InteractiveRemoteSession:
>      """Factory for interactive remote sessions.
>
> diff --git a/dts/framework/remote_session/interactive_remote_session.py b/dts/framework/remote_session/interactive_remote_session.py
> index 1cc82e3377..c50790db79 100644
> --- a/dts/framework/remote_session/interactive_remote_session.py
> +++ b/dts/framework/remote_session/interactive_remote_session.py
> @@ -16,7 +16,7 @@
>
>  from framework.config import NodeConfiguration
>  from framework.exception import SSHConnectionError
> -from framework.logger import DTSLOG
> +from framework.logger import DTSLogger
>
>
>  class InteractiveRemoteSession:
> @@ -50,11 +50,11 @@ class InteractiveRemoteSession:
>      username: str
>      password: str
>      session: SSHClient
> -    _logger: DTSLOG
> +    _logger: DTSLogger
>      _node_config: NodeConfiguration
>      _transport: Transport | None
>
> -    def __init__(self, node_config: NodeConfiguration, logger: DTSLOG) -> None:
> +    def __init__(self, node_config: NodeConfiguration, logger: DTSLogger) -> None:
>          """Connect to the node during initialization.
>
>          Args:
> diff --git a/dts/framework/remote_session/interactive_shell.py b/dts/framework/remote_session/interactive_shell.py
> index b158f963b6..5cfe202e15 100644
> --- a/dts/framework/remote_session/interactive_shell.py
> +++ b/dts/framework/remote_session/interactive_shell.py
> @@ -20,7 +20,7 @@
>
>  from paramiko import Channel, SSHClient, channel  # type: ignore[import]
>
> -from framework.logger import DTSLOG
> +from framework.logger import DTSLogger
>  from framework.settings import SETTINGS
>
>
> @@ -38,7 +38,7 @@ class InteractiveShell(ABC):
>      _stdin: channel.ChannelStdinFile
>      _stdout: channel.ChannelFile
>      _ssh_channel: Channel
> -    _logger: DTSLOG
> +    _logger: DTSLogger
>      _timeout: float
>      _app_args: str
>
> @@ -61,7 +61,7 @@ class InteractiveShell(ABC):
>      def __init__(
>          self,
>          interactive_session: SSHClient,
> -        logger: DTSLOG,
> +        logger: DTSLogger,
>          get_privileged_command: Callable[[str], str] | None,
>          app_args: str = "",
>          timeout: float = SETTINGS.timeout,
> diff --git a/dts/framework/remote_session/remote_session.py b/dts/framework/remote_session/remote_session.py
> index 2059f9a981..a69dc99400 100644
> --- a/dts/framework/remote_session/remote_session.py
> +++ b/dts/framework/remote_session/remote_session.py
> @@ -9,14 +9,13 @@
>  the structure of the result of a command execution.
>  """
>
> -
>  import dataclasses
>  from abc import ABC, abstractmethod
>  from pathlib import PurePath
>
>  from framework.config import NodeConfiguration
>  from framework.exception import RemoteCommandExecutionError
> -from framework.logger import DTSLOG
> +from framework.logger import DTSLogger
>  from framework.settings import SETTINGS
>
>
> @@ -75,14 +74,14 @@ class RemoteSession(ABC):
>      username: str
>      password: str
>      history: list[CommandResult]
> -    _logger: DTSLOG
> +    _logger: DTSLogger
>      _node_config: NodeConfiguration
>
>      def __init__(
>          self,
>          node_config: NodeConfiguration,
>          session_name: str,
> -        logger: DTSLOG,
> +        logger: DTSLogger,
>      ):
>          """Connect to the node during initialization.
>
> @@ -181,7 +180,6 @@ def close(self, force: bool = False) -> None:
>          Args:
>              force: Force the closure of the connection. This may not clean up all resources.
>          """
> -        self._logger.logger_exit()
>          self._close(force)
>
>      @abstractmethod
> diff --git a/dts/framework/runner.py b/dts/framework/runner.py
> index f58b0adc13..035e3368ef 100644
> --- a/dts/framework/runner.py
> +++ b/dts/framework/runner.py
> @@ -19,9 +19,10 @@
>
>  import importlib
>  import inspect
> -import logging
> +import os
>  import re
>  import sys
> +from pathlib import Path
>  from types import MethodType
>  from typing import Iterable
>
> @@ -38,7 +39,7 @@
>      SSHTimeoutError,
>      TestCaseVerifyError,
>  )
> -from .logger import DTSLOG, getLogger
> +from .logger import DTSLogger, DtsStage, get_dts_logger
>  from .settings import SETTINGS
>  from .test_result import (
>      BuildTargetResult,
> @@ -73,7 +74,7 @@ class DTSRunner:
>      """
>
>      _configuration: Configuration
> -    _logger: DTSLOG
> +    _logger: DTSLogger
>      _result: DTSResult
>      _test_suite_class_prefix: str
>      _test_suite_module_prefix: str
> @@ -83,7 +84,10 @@ class DTSRunner:
>      def __init__(self):
>          """Initialize the instance with configuration, logger, result and string constants."""
>          self._configuration = load_config()
> -        self._logger = getLogger("DTSRunner")
> +        self._logger = get_dts_logger()
> +        if not os.path.exists(SETTINGS.output_dir):
> +            os.makedirs(SETTINGS.output_dir)
> +        self._logger.add_dts_root_logger_handlers(SETTINGS.verbose, SETTINGS.output_dir)
>          self._result = DTSResult(self._logger)
>          self._test_suite_class_prefix = "Test"
>          self._test_suite_module_prefix = "tests.TestSuite_"
> @@ -137,6 +141,7 @@ def run(self):
>
>              # for all Execution sections
>              for execution in self._configuration.executions:
> +                self._logger.set_stage(DtsStage.execution)

This ends up getting set twice in short succession which of course
doesn't functionally cause a problem, but I don't exactly see the
point of setting it twice. We could either set it here or set it in
the _run_execution, but i think it makes more sense to set it in the
_run_execution method as that is the method where we are doing the
setup, here we are only initializing the nodes which is still in a
sense "pre execution."


>                  self._logger.info(
>                      f"Running execution with SUT '{execution.system_under_test_node.name}'."
>                  )
> @@ -164,6 +169,7 @@ def run(self):
>
>          finally:
>              try:
> +                self._logger.set_stage(DtsStage.post_execution)
>                  for node in (sut_nodes | tg_nodes).values():
>                      node.close()
>                  self._result.update_teardown(Result.PASS)
> @@ -419,6 +425,7 @@ def _run_execution(
>
>          finally:
>              try:
> +                self._logger.set_stage(DtsStage.execution)
>                  sut_node.tear_down_execution()
>                  execution_result.update_teardown(Result.PASS)
>              except Exception as e:
> @@ -447,6 +454,7 @@ def _run_build_target(
>                  with the current build target.
>              test_suites_with_cases: The test suites with test cases to run.
>          """
> +        self._logger.set_stage(DtsStage.build_target)
>          self._logger.info(f"Running build target '{build_target.name}'.")
>
>          try:
> @@ -463,6 +471,7 @@ def _run_build_target(
>
>          finally:
>              try:
> +                self._logger.set_stage(DtsStage.build_target)
>                  sut_node.tear_down_build_target()
>                  build_target_result.update_teardown(Result.PASS)
>              except Exception as e:
> @@ -535,6 +544,7 @@ def _run_test_suite(
>              BlockingTestSuiteError: If a blocking test suite fails.
>          """
>          test_suite_name = test_suite_with_cases.test_suite_class.__name__
> +        self._logger.set_stage(DtsStage.suite, Path(SETTINGS.output_dir, test_suite_name))
>          test_suite = test_suite_with_cases.test_suite_class(sut_node, tg_node)
>          try:
>              self._logger.info(f"Starting test suite setup: {test_suite_name}")
> @@ -683,5 +693,4 @@ def _exit_dts(self) -> None:
>          if self._logger:
>              self._logger.info("DTS execution has ended.")
>
> -        logging.shutdown()
>          sys.exit(self._result.get_return_code())
> diff --git a/dts/framework/test_result.py b/dts/framework/test_result.py
> index eedb2d20ee..28f84fd793 100644
> --- a/dts/framework/test_result.py
> +++ b/dts/framework/test_result.py
> @@ -42,7 +42,7 @@
>      TestSuiteConfig,
>  )
>  from .exception import DTSError, ErrorSeverity
> -from .logger import DTSLOG
> +from .logger import DTSLogger
>  from .settings import SETTINGS
>  from .test_suite import TestSuite
>
> @@ -237,13 +237,13 @@ class DTSResult(BaseResult):
>      """
>
>      dpdk_version: str | None
> -    _logger: DTSLOG
> +    _logger: DTSLogger
>      _errors: list[Exception]
>      _return_code: ErrorSeverity
>      _stats_result: Union["Statistics", None]
>      _stats_filename: str
>
> -    def __init__(self, logger: DTSLOG):
> +    def __init__(self, logger: DTSLogger):
>          """Extend the constructor with top-level specifics.
>
>          Args:
> diff --git a/dts/framework/test_suite.py b/dts/framework/test_suite.py
> index f9fe88093e..365f80e21a 100644
> --- a/dts/framework/test_suite.py
> +++ b/dts/framework/test_suite.py
> @@ -21,7 +21,7 @@
>  from scapy.packet import Packet, Padding  # type: ignore[import]
>
>  from .exception import TestCaseVerifyError
> -from .logger import DTSLOG, getLogger
> +from .logger import DTSLogger, get_dts_logger
>  from .testbed_model import Port, PortLink, SutNode, TGNode
>  from .utils import get_packet_summaries
>
> @@ -61,7 +61,7 @@ class TestSuite(object):
>      #: Whether the test suite is blocking. A failure of a blocking test suite
>      #: will block the execution of all subsequent test suites in the current build target.
>      is_blocking: ClassVar[bool] = False
> -    _logger: DTSLOG
> +    _logger: DTSLogger
>      _port_links: list[PortLink]
>      _sut_port_ingress: Port
>      _sut_port_egress: Port
> @@ -88,7 +88,7 @@ def __init__(
>          """
>          self.sut_node = sut_node
>          self.tg_node = tg_node
> -        self._logger = getLogger(self.__class__.__name__)
> +        self._logger = get_dts_logger(self.__class__.__name__)
>          self._port_links = []
>          self._process_links()
>          self._sut_port_ingress, self._tg_port_egress = (
> diff --git a/dts/framework/testbed_model/node.py b/dts/framework/testbed_model/node.py
> index 1a55fadf78..74061f6262 100644
> --- a/dts/framework/testbed_model/node.py
> +++ b/dts/framework/testbed_model/node.py
> @@ -23,7 +23,7 @@
>      NodeConfiguration,
>  )
>  from framework.exception import ConfigurationError
> -from framework.logger import DTSLOG, getLogger
> +from framework.logger import DTSLogger, get_dts_logger
>  from framework.settings import SETTINGS
>
>  from .cpu import (
> @@ -63,7 +63,7 @@ class Node(ABC):
>      name: str
>      lcores: list[LogicalCore]
>      ports: list[Port]
> -    _logger: DTSLOG
> +    _logger: DTSLogger
>      _other_sessions: list[OSSession]
>      _execution_config: ExecutionConfiguration
>      virtual_devices: list[VirtualDevice]
> @@ -82,7 +82,7 @@ def __init__(self, node_config: NodeConfiguration):
>          """
>          self.config = node_config
>          self.name = node_config.name
> -        self._logger = getLogger(self.name)
> +        self._logger = get_dts_logger(self.name)
>          self.main_session = create_session(self.config, self.name, self._logger)
>
>          self._logger.info(f"Connected to node: {self.name}")
> @@ -189,7 +189,7 @@ def create_session(self, name: str) -> OSSession:
>          connection = create_session(
>              self.config,
>              session_name,
> -            getLogger(session_name, node=self.name),
> +            get_dts_logger(session_name),
>          )
>          self._other_sessions.append(connection)
>          return connection
> @@ -299,7 +299,6 @@ def close(self) -> None:
>              self.main_session.close()
>          for session in self._other_sessions:
>              session.close()
> -        self._logger.logger_exit()
>
>      @staticmethod
>      def skip_setup(func: Callable[..., Any]) -> Callable[..., Any]:
> @@ -314,7 +313,7 @@ def skip_setup(func: Callable[..., Any]) -> Callable[..., Any]:
>              return func
>
>
> -def create_session(node_config: NodeConfiguration, name: str, logger: DTSLOG) -> OSSession:
> +def create_session(node_config: NodeConfiguration, name: str, logger: DTSLogger) -> OSSession:
>      """Factory for OS-aware sessions.
>
>      Args:
> diff --git a/dts/framework/testbed_model/os_session.py b/dts/framework/testbed_model/os_session.py
> index ac6bb5e112..6983aa4a77 100644
> --- a/dts/framework/testbed_model/os_session.py
> +++ b/dts/framework/testbed_model/os_session.py
> @@ -21,7 +21,6 @@
>      the :attr:`~.node.Node.main_session` translates that to ``rm -rf`` if the node's OS is Linux
>      and other commands for other OSs. It also translates the path to match the underlying OS.
>  """
> -
>  from abc import ABC, abstractmethod
>  from collections.abc import Iterable
>  from ipaddress import IPv4Interface, IPv6Interface
> @@ -29,7 +28,7 @@
>  from typing import Type, TypeVar, Union
>
>  from framework.config import Architecture, NodeConfiguration, NodeInfo
> -from framework.logger import DTSLOG
> +from framework.logger import DTSLogger
>  from framework.remote_session import (
>      CommandResult,
>      InteractiveRemoteSession,
> @@ -62,7 +61,7 @@ class OSSession(ABC):
>
>      _config: NodeConfiguration
>      name: str
> -    _logger: DTSLOG
> +    _logger: DTSLogger
>      remote_session: RemoteSession
>      interactive_session: InteractiveRemoteSession
>
> @@ -70,7 +69,7 @@ def __init__(
>          self,
>          node_config: NodeConfiguration,
>          name: str,
> -        logger: DTSLOG,
> +        logger: DTSLogger,
>      ):
>          """Initialize the OS-aware session.
>
> diff --git a/dts/framework/testbed_model/traffic_generator/traffic_generator.py b/dts/framework/testbed_model/traffic_generator/traffic_generator.py
> index c49fbff488..d86d7fb532 100644
> --- a/dts/framework/testbed_model/traffic_generator/traffic_generator.py
> +++ b/dts/framework/testbed_model/traffic_generator/traffic_generator.py
> @@ -13,7 +13,7 @@
>  from scapy.packet import Packet  # type: ignore[import]
>
>  from framework.config import TrafficGeneratorConfig
> -from framework.logger import DTSLOG, getLogger
> +from framework.logger import DTSLogger, get_dts_logger
>  from framework.testbed_model.node import Node
>  from framework.testbed_model.port import Port
>  from framework.utils import get_packet_summaries
> @@ -28,7 +28,7 @@ class TrafficGenerator(ABC):
>
>      _config: TrafficGeneratorConfig
>      _tg_node: Node
> -    _logger: DTSLOG
> +    _logger: DTSLogger
>
>      def __init__(self, tg_node: Node, config: TrafficGeneratorConfig):
>          """Initialize the traffic generator.
> @@ -39,7 +39,7 @@ def __init__(self, tg_node: Node, config: TrafficGeneratorConfig):
>          """
>          self._config = config
>          self._tg_node = tg_node
> -        self._logger = getLogger(f"{self._tg_node.name} {self._config.traffic_generator_type}")
> +        self._logger = get_dts_logger(f"{self._tg_node.name} {self._config.traffic_generator_type}")
>
>      def send_packet(self, packet: Packet, port: Port) -> None:
>          """Send `packet` and block until it is fully sent.
> diff --git a/dts/main.py b/dts/main.py
> index 1ffe8ff81f..d30c164b95 100755
> --- a/dts/main.py
> +++ b/dts/main.py
> @@ -30,5 +30,4 @@ def main() -> None:
>
>  # Main program begins here
>  if __name__ == "__main__":
> -    logging.raiseExceptions = True
>      main()
> --
> 2.34.1
>
  

Hi Jeremy,

Just a reminder, please strip the parts you're not commenting on.

On Mon, Feb 12, 2024 at 5:45 PM Jeremy Spewock <jspewock@iol.unh.edu> wrote:
>
> On Tue, Feb 6, 2024 at 9:57 AM Juraj Linkeš <juraj.linkes@pantheon.tech> wrote:
> >
> > Remove unused parts of the code and add useful features:
> > 1. Add DTS execution stages such as execution and test suite to better
> >    identify where in the DTS lifecycle we are when investigating logs,
> > 2. Logging to separate files in specific stages, which is mainly useful
> >    for having test suite logs in additional separate files.
> > 3. Remove the dependence on the settings module which enhances the
> >    usefulness of the logger module, as it can now be imported in more
> >    modules.
> >
> > The execution stages and the files to log to are the same for all DTS
> > loggers. To achieve this, we have one DTS root logger which should be
> > used for handling stage switching and all other loggers are children of
> > this DTS root logger. The DTS root logger is the one where we change the
> > behavior of all loggers (the stage and which files to log to) and the
> > child loggers just log messages under a different name.
> >
> > Signed-off-by: Juraj Linkeš <juraj.linkes@pantheon.tech>
> > ---
> >  dts/framework/logger.py                       | 235 +++++++++++-------
> >  dts/framework/remote_session/__init__.py      |   6 +-
> >  .../interactive_remote_session.py             |   6 +-
> >  .../remote_session/interactive_shell.py       |   6 +-
> >  .../remote_session/remote_session.py          |   8 +-
> >  dts/framework/runner.py                       |  19 +-
> >  dts/framework/test_result.py                  |   6 +-
> >  dts/framework/test_suite.py                   |   6 +-
> >  dts/framework/testbed_model/node.py           |  11 +-
> >  dts/framework/testbed_model/os_session.py     |   7 +-
> >  .../traffic_generator/traffic_generator.py    |   6 +-
> >  dts/main.py                                   |   1 -
> >  12 files changed, 183 insertions(+), 134 deletions(-)
> >
> > diff --git a/dts/framework/logger.py b/dts/framework/logger.py
> > index cfa6e8cd72..568edad82d 100644
> > --- a/dts/framework/logger.py
> > +++ b/dts/framework/logger.py
> > @@ -5,141 +5,186 @@
> >
> >  """DTS logger module.
> >
> > -DTS framework and TestSuite logs are saved in different log files.
> > +The module provides several additional features:
> > +
> > +    * The storage of DTS execution stages,
> > +    * Logging to console, a human-readable log file and a machine-readable log file,
> > +    * Optional log files for specific stages.
> >  """
> >
> >  import logging
> > -import os.path
> > -from typing import TypedDict
> > +from enum import auto
> > +from logging import FileHandler, StreamHandler
> > +from pathlib import Path
> > +from typing import ClassVar
> >
> > -from .settings import SETTINGS
> > +from .utils import StrEnum
> >
> >  date_fmt = "%Y/%m/%d %H:%M:%S"
> > -stream_fmt = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
> > +stream_fmt = "%(asctime)s - %(stage)s - %(name)s - %(levelname)s - %(message)s"
> > +dts_root_logger_name = "dts"
> > +
> > +
> > +class DtsStage(StrEnum):
> > +    """The DTS execution stage."""
> >
> > +    #:
> > +    pre_execution = auto()
> > +    #:
> > +    execution = auto()
> > +    #:
> > +    build_target = auto()
> > +    #:
> > +    suite = auto()
> > +    #:
> > +    post_execution = auto()
> >
> > -class DTSLOG(logging.LoggerAdapter):
> > -    """DTS logger adapter class for framework and testsuites.
> >
> > -    The :option:`--verbose` command line argument and the :envvar:`DTS_VERBOSE` environment
> > -    variable control the verbosity of output. If enabled, all messages will be emitted to the
> > -    console.
> > +class DTSLogger(logging.Logger):
> > +    """The DTS logger class.
> >
> > -    The :option:`--output` command line argument and the :envvar:`DTS_OUTPUT_DIR` environment
> > -    variable modify the directory where the logs will be stored.
> > +    The class extends the :class:`~logging.Logger` class to add the DTS execution stage information
> > +    to log records. The stage is common to all loggers, so it's stored in a class variable.
> >
> > -    Attributes:
> > -        node: The additional identifier. Currently unused.
> > -        sh: The handler which emits logs to console.
> > -        fh: The handler which emits logs to a file.
> > -        verbose_fh: Just as fh, but logs with a different, more verbose, format.
> > +    Any time we switch to a new stage, we have the ability to log to an additional log file along
> > +    with a supplementary log file with machine-readable format. These two log files are used until
> > +    a new stage switch occurs. This is useful mainly for logging per test suite.
> >      """
> >
> > -    _logger: logging.Logger
> > -    node: str
> > -    sh: logging.StreamHandler
> > -    fh: logging.FileHandler
> > -    verbose_fh: logging.FileHandler
> > +    _stage: ClassVar[DtsStage] = DtsStage.pre_execution
> > +    _extra_file_handlers: list[FileHandler] = []
> >
> > -    def __init__(self, logger: logging.Logger, node: str = "suite"):
> > -        """Extend the constructor with additional handlers.
> > +    def __init__(self, *args, **kwargs):
> > +        """Extend the constructor with extra file handlers."""
> > +        self._extra_file_handlers = []
> > +        super().__init__(*args, **kwargs)
> >
> > -        One handler logs to the console, the other one to a file, with either a regular or verbose
> > -        format.
> > +    def makeRecord(self, *args, **kwargs):
>
> Is the return type annotation here skipped because of the `:meta private:`?
>

Basically. We're modifying a method defined elsewhere, but there's no
harm in adding the return type.

> > +        """Generates a record with additional stage information.
> >
> > -        Args:
> > -            logger: The logger from which to create the logger adapter.
> > -            node: An additional identifier. Currently unused.
> > +        This is the default method for the :class:`~logging.Logger` class. We extend it
> > +        to add stage information to the record.
> > +
> > +        :meta private:
> > +
> > +        Returns:
> > +            record: The generated record with the stage information.
> >          """
> > -        self._logger = logger
> > -        # 1 means log everything, this will be used by file handlers if their level
> > -        # is not set
> > -        self._logger.setLevel(1)
> > +        record = super().makeRecord(*args, **kwargs)
> > +        record.stage = DTSLogger._stage
> > +        return record
> > +
> > +    def add_dts_root_logger_handlers(self, verbose: bool, output_dir: str) -> None:
> > +        """Add logger handlers to the DTS root logger.
> > +
> > +        This method should be called only on the DTS root logger.
> > +        The log records from child loggers will propagate to these handlers.
> > +
> > +        Three handlers are added:
> >
> > -        self.node = node
> > +            * A console handler,
> > +            * A file handler,
> > +            * A supplementary file handler with machine-readable logs
> > +              containing more debug information.
> >
> > -        # add handler to emit to stdout
> > -        sh = logging.StreamHandler()
> > +        All log messages will be logged to files. The log level of the console handler
> > +        is configurable with `verbose`.
> > +
> > +        Args:
> > +            verbose: If :data:`True`, log all messages to the console.
> > +                If :data:`False`, log to console with the :data:`logging.INFO` level.
> > +            output_dir: The directory where the log files will be located.
> > +                The names of the log files correspond to the name of the logger instance.
> > +        """
> > +        self.setLevel(1)
> > +
> > +        sh = StreamHandler()
> >          sh.setFormatter(logging.Formatter(stream_fmt, date_fmt))
> > -        sh.setLevel(logging.INFO)  # console handler default level
> > +        if not verbose:
> > +            sh.setLevel(logging.INFO)
> > +        self.addHandler(sh)
> >
> > -        if SETTINGS.verbose is True:
> > -            sh.setLevel(logging.DEBUG)
> > +        self._add_file_handlers(Path(output_dir, self.name))
> >
> > -        self._logger.addHandler(sh)
> > -        self.sh = sh
> > +    def set_stage(self, stage: DtsStage, log_file_path: Path | None = None) -> None:
> > +        """Set the DTS execution stage and optionally log to files.
> >
> > -        # prepare the output folder
> > -        if not os.path.exists(SETTINGS.output_dir):
> > -            os.mkdir(SETTINGS.output_dir)
> > +        Set the DTS execution stage of the DTSLog class and optionally add
> > +        file handlers to the instance if the log file name is provided.
> >
> > -        logging_path_prefix = os.path.join(SETTINGS.output_dir, node)
> > +        The file handlers log all messages. One is a regular human-readable log file and
> > +        the other one is a machine-readable log file with extra debug information.
> >
> > -        fh = logging.FileHandler(f"{logging_path_prefix}.log")
> > -        fh.setFormatter(
> > -            logging.Formatter(
> > -                fmt="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
> > -                datefmt=date_fmt,
> > -            )
> > -        )
> > +        Args:
> > +            stage: The DTS stage to set.
> > +            log_file_path: An optional path of the log file to use. This should be a full path
> > +                (either relative or absolute) without suffix (which will be appended).
> > +        """
> > +        self._remove_extra_file_handlers()
> > +
> > +        if DTSLogger._stage != stage:
> > +            self.info(f"Moving from stage '{DTSLogger._stage}' to stage '{stage}'.")
> > +            DTSLogger._stage = stage
> > +
> > +        if log_file_path:
> > +            self._extra_file_handlers.extend(self._add_file_handlers(log_file_path))
> > +
> > +    def _add_file_handlers(self, log_file_path: Path) -> list[FileHandler]:
> > +        """Add file handlers to the DTS root logger.
> > +
> > +        Add two type of file handlers:
> > +
> > +            * A regular file handler with suffix ".log",
> > +            * A machine-readable file handler with suffix ".verbose.log".
> > +              This format provides extensive information for debugging and detailed analysis.
> > +
> > +        Args:
> > +            log_file_path: The full path to the log file without suffix.
> > +
> > +        Returns:
> > +            The newly created file handlers.
> >
> > -        self._logger.addHandler(fh)
> > -        self.fh = fh
> > +        """
> > +        fh = FileHandler(f"{log_file_path}.log")
> > +        fh.setFormatter(logging.Formatter(stream_fmt, date_fmt))
> > +        self.addHandler(fh)
> >
> > -        # This outputs EVERYTHING, intended for post-mortem debugging
> > -        # Also optimized for processing via AWK (awk -F '|' ...)
> > -        verbose_fh = logging.FileHandler(f"{logging_path_prefix}.verbose.log")
> > +        verbose_fh = FileHandler(f"{log_file_path}.verbose.log")
> >          verbose_fh.setFormatter(
> >              logging.Formatter(
> > -                fmt="%(asctime)s|%(name)s|%(levelname)s|%(pathname)s|%(lineno)d|"
> > +                "%(asctime)s|%(stage)s|%(name)s|%(levelname)s|%(pathname)s|%(lineno)d|"
> >                  "%(funcName)s|%(process)d|%(thread)d|%(threadName)s|%(message)s",
> >                  datefmt=date_fmt,
> >              )
> >          )
> > +        self.addHandler(verbose_fh)
> >
> > -        self._logger.addHandler(verbose_fh)
> > -        self.verbose_fh = verbose_fh
> > -
> > -        super(DTSLOG, self).__init__(self._logger, dict(node=self.node))
> > -
> > -    def logger_exit(self) -> None:
> > -        """Remove the stream handler and the logfile handler."""
> > -        for handler in (self.sh, self.fh, self.verbose_fh):
> > -            handler.flush()
> > -            self._logger.removeHandler(handler)
> > -
> > -
> > -class _LoggerDictType(TypedDict):
> > -    logger: DTSLOG
> > -    name: str
> > -    node: str
> > -
> > +        return [fh, verbose_fh]
> >
> > -# List for saving all loggers in use
> > -_Loggers: list[_LoggerDictType] = []
> > +    def _remove_extra_file_handlers(self) -> None:
> > +        """Remove any extra file handlers that have been added to the logger."""
> > +        if self._extra_file_handlers:
> > +            for extra_file_handler in self._extra_file_handlers:
> > +                self.removeHandler(extra_file_handler)
> >
> > +            self._extra_file_handlers = []
> >
> > -def getLogger(name: str, node: str = "suite") -> DTSLOG:
> > -    """Get DTS logger adapter identified by name and node.
> >
> > -    An existing logger will be returned if one with the exact name and node already exists.
> > -    A new one will be created and stored otherwise.
> > +def get_dts_logger(name: str = None) -> DTSLogger:
> > +    """Return a DTS logger instance identified by `name`.
> >
> >      Args:
> > -        name: The name of the logger.
> > -        node: An additional identifier for the logger.
> > +        name: If :data:`None`, return the DTS root logger.
> > +            If specified, return a child of the DTS root logger.
> >
> >      Returns:
> > -        A logger uniquely identified by both name and node.
> > +         The DTS root logger or a child logger identified by `name`.
> >      """
> > -    global _Loggers
> > -    # return saved logger
> > -    logger: _LoggerDictType
> > -    for logger in _Loggers:
> > -        if logger["name"] == name and logger["node"] == node:
> > -            return logger["logger"]
> > -
> > -    # return new logger
> > -    dts_logger: DTSLOG = DTSLOG(logging.getLogger(name), node)
> > -    _Loggers.append({"logger": dts_logger, "name": name, "node": node})
> > -    return dts_logger
> > +    logging.setLoggerClass(DTSLogger)
> > +    if name:
> > +        name = f"{dts_root_logger_name}.{name}"
> > +    else:
> > +        name = dts_root_logger_name
> > +    logger = logging.getLogger(name)
> > +    logging.setLoggerClass(logging.Logger)
>
> What's the benefit of setting the logger class back to logging.Logger
> here? Is the idea basically that if someone wanted to use the logging
> module we shouldn't implicitly make them use our DTSLogger?
>

Yes. We should actually set it to whatever was there before (it may
not be logging.Logger), so I'll change that.+


> > +    return logger  # type: ignore[return-value]
> > diff --git a/dts/framework/remote_session/__init__.py b/dts/framework/remote_session/__init__.py
> > index 51a01d6b5e..1910c81c3c 100644
> > --- a/dts/framework/remote_session/__init__.py
> > +++ b/dts/framework/remote_session/__init__.py
> > @@ -15,7 +15,7 @@
> >  # pylama:ignore=W0611
> >
> >  from framework.config import NodeConfiguration
> > -from framework.logger import DTSLOG
> > +from framework.logger import DTSLogger
> >
> >  from .interactive_remote_session import InteractiveRemoteSession
> >  from .interactive_shell import InteractiveShell
> > @@ -26,7 +26,7 @@
> >
> >
> >  def create_remote_session(
> > -    node_config: NodeConfiguration, name: str, logger: DTSLOG
> > +    node_config: NodeConfiguration, name: str, logger: DTSLogger
> >  ) -> RemoteSession:
> >      """Factory for non-interactive remote sessions.
> >
> > @@ -45,7 +45,7 @@ def create_remote_session(
> >
> >
> >  def create_interactive_session(
> > -    node_config: NodeConfiguration, logger: DTSLOG
> > +    node_config: NodeConfiguration, logger: DTSLogger
> >  ) -> InteractiveRemoteSession:
> >      """Factory for interactive remote sessions.
> >
> > diff --git a/dts/framework/remote_session/interactive_remote_session.py b/dts/framework/remote_session/interactive_remote_session.py
> > index 1cc82e3377..c50790db79 100644
> > --- a/dts/framework/remote_session/interactive_remote_session.py
> > +++ b/dts/framework/remote_session/interactive_remote_session.py
> > @@ -16,7 +16,7 @@
> >
> >  from framework.config import NodeConfiguration
> >  from framework.exception import SSHConnectionError
> > -from framework.logger import DTSLOG
> > +from framework.logger import DTSLogger
> >
> >
> >  class InteractiveRemoteSession:
> > @@ -50,11 +50,11 @@ class InteractiveRemoteSession:
> >      username: str
> >      password: str
> >      session: SSHClient
> > -    _logger: DTSLOG
> > +    _logger: DTSLogger
> >      _node_config: NodeConfiguration
> >      _transport: Transport | None
> >
> > -    def __init__(self, node_config: NodeConfiguration, logger: DTSLOG) -> None:
> > +    def __init__(self, node_config: NodeConfiguration, logger: DTSLogger) -> None:
> >          """Connect to the node during initialization.
> >
> >          Args:
> > diff --git a/dts/framework/remote_session/interactive_shell.py b/dts/framework/remote_session/interactive_shell.py
> > index b158f963b6..5cfe202e15 100644
> > --- a/dts/framework/remote_session/interactive_shell.py
> > +++ b/dts/framework/remote_session/interactive_shell.py
> > @@ -20,7 +20,7 @@
> >
> >  from paramiko import Channel, SSHClient, channel  # type: ignore[import]
> >
> > -from framework.logger import DTSLOG
> > +from framework.logger import DTSLogger
> >  from framework.settings import SETTINGS
> >
> >
> > @@ -38,7 +38,7 @@ class InteractiveShell(ABC):
> >      _stdin: channel.ChannelStdinFile
> >      _stdout: channel.ChannelFile
> >      _ssh_channel: Channel
> > -    _logger: DTSLOG
> > +    _logger: DTSLogger
> >      _timeout: float
> >      _app_args: str
> >
> > @@ -61,7 +61,7 @@ class InteractiveShell(ABC):
> >      def __init__(
> >          self,
> >          interactive_session: SSHClient,
> > -        logger: DTSLOG,
> > +        logger: DTSLogger,
> >          get_privileged_command: Callable[[str], str] | None,
> >          app_args: str = "",
> >          timeout: float = SETTINGS.timeout,
> > diff --git a/dts/framework/remote_session/remote_session.py b/dts/framework/remote_session/remote_session.py
> > index 2059f9a981..a69dc99400 100644
> > --- a/dts/framework/remote_session/remote_session.py
> > +++ b/dts/framework/remote_session/remote_session.py
> > @@ -9,14 +9,13 @@
> >  the structure of the result of a command execution.
> >  """
> >
> > -
> >  import dataclasses
> >  from abc import ABC, abstractmethod
> >  from pathlib import PurePath
> >
> >  from framework.config import NodeConfiguration
> >  from framework.exception import RemoteCommandExecutionError
> > -from framework.logger import DTSLOG
> > +from framework.logger import DTSLogger
> >  from framework.settings import SETTINGS
> >
> >
> > @@ -75,14 +74,14 @@ class RemoteSession(ABC):
> >      username: str
> >      password: str
> >      history: list[CommandResult]
> > -    _logger: DTSLOG
> > +    _logger: DTSLogger
> >      _node_config: NodeConfiguration
> >
> >      def __init__(
> >          self,
> >          node_config: NodeConfiguration,
> >          session_name: str,
> > -        logger: DTSLOG,
> > +        logger: DTSLogger,
> >      ):
> >          """Connect to the node during initialization.
> >
> > @@ -181,7 +180,6 @@ def close(self, force: bool = False) -> None:
> >          Args:
> >              force: Force the closure of the connection. This may not clean up all resources.
> >          """
> > -        self._logger.logger_exit()
> >          self._close(force)
> >
> >      @abstractmethod
> > diff --git a/dts/framework/runner.py b/dts/framework/runner.py
> > index f58b0adc13..035e3368ef 100644
> > --- a/dts/framework/runner.py
> > +++ b/dts/framework/runner.py
> > @@ -19,9 +19,10 @@
> >
> >  import importlib
> >  import inspect
> > -import logging
> > +import os
> >  import re
> >  import sys
> > +from pathlib import Path
> >  from types import MethodType
> >  from typing import Iterable
> >
> > @@ -38,7 +39,7 @@
> >      SSHTimeoutError,
> >      TestCaseVerifyError,
> >  )
> > -from .logger import DTSLOG, getLogger
> > +from .logger import DTSLogger, DtsStage, get_dts_logger
> >  from .settings import SETTINGS
> >  from .test_result import (
> >      BuildTargetResult,
> > @@ -73,7 +74,7 @@ class DTSRunner:
> >      """
> >
> >      _configuration: Configuration
> > -    _logger: DTSLOG
> > +    _logger: DTSLogger
> >      _result: DTSResult
> >      _test_suite_class_prefix: str
> >      _test_suite_module_prefix: str
> > @@ -83,7 +84,10 @@ class DTSRunner:
> >      def __init__(self):
> >          """Initialize the instance with configuration, logger, result and string constants."""
> >          self._configuration = load_config()
> > -        self._logger = getLogger("DTSRunner")
> > +        self._logger = get_dts_logger()
> > +        if not os.path.exists(SETTINGS.output_dir):
> > +            os.makedirs(SETTINGS.output_dir)
> > +        self._logger.add_dts_root_logger_handlers(SETTINGS.verbose, SETTINGS.output_dir)
> >          self._result = DTSResult(self._logger)
> >          self._test_suite_class_prefix = "Test"
> >          self._test_suite_module_prefix = "tests.TestSuite_"
> > @@ -137,6 +141,7 @@ def run(self):
> >
> >              # for all Execution sections
> >              for execution in self._configuration.executions:
> > +                self._logger.set_stage(DtsStage.execution)
>
> This ends up getting set twice in short succession which of course
> doesn't functionally cause a problem, but I don't exactly see the
> point of setting it twice.

I'm not sure what you're referring to. The stage is only set once at
the start of each execution (and more generally, at the start of each
stage). It's also set in each finally block to properly mark the
cleanup of that stage. There are two finally blocks in the execution
stage where that could happen, but otherwise it should be set exactly
once.

>  We could either set it here or set it in
> the _run_execution, but i think it makes more sense to set it in the
> _run_execution method as that is the method where we are doing the
> setup, here we are only initializing the nodes which is still in a
> sense "pre execution."

Init nodes was pre-execution before the patch. I've moved it to
execution because of two reasons:
1. The nodes are actually defined per-execution. It just made more
sense to move them to execution. Also, if an error happens while
connecting to a node, we don't want to abort the whole DTS run, just
the execution, as the next execution could be connecting to a
different node.
2. We're not just doing node init here, we're also discovering which
test cases to run. This is essential to do as soon as possible (before
anything else happens in the execution, such as connecting the nodes)
so that we can mark blocked test cases in case of an error. Test case
discovery is definitely part of each execution and putting node init
after that was a natural consequence. There's an argument for
discovering test cases of all executions before actually running any
of the executions. It's certainly doable, but the code doesn't look
that good (when not modifying the original execution config (which we
shouldn't do) - I've tried) and there's actually not much of a point
to do it this way, the result is almost the same. Where it makes a
difference is when there's an error in test suite configuration and
later executions - the user would have to wait for the previous
execution to fully run to discover the error).

>
>
> >                  self._logger.info(
> >                      f"Running execution with SUT '{execution.system_under_test_node.name}'."
> >                  )
> > @@ -164,6 +169,7 @@ def run(self):
> >
> >          finally:
> >              try:
> > +                self._logger.set_stage(DtsStage.post_execution)
> >                  for node in (sut_nodes | tg_nodes).values():
> >                      node.close()
> >                  self._result.update_teardown(Result.PASS)
> > @@ -419,6 +425,7 @@ def _run_execution(
> >
> >          finally:
> >              try:
> > +                self._logger.set_stage(DtsStage.execution)
> >                  sut_node.tear_down_execution()
> >                  execution_result.update_teardown(Result.PASS)
> >              except Exception as e:
> > @@ -447,6 +454,7 @@ def _run_build_target(
> >                  with the current build target.
> >              test_suites_with_cases: The test suites with test cases to run.
> >          """
> > +        self._logger.set_stage(DtsStage.build_target)
> >          self._logger.info(f"Running build target '{build_target.name}'.")
> >
> >          try:
> > @@ -463,6 +471,7 @@ def _run_build_target(
> >
> >          finally:
> >              try:
> > +                self._logger.set_stage(DtsStage.build_target)
> >                  sut_node.tear_down_build_target()
> >                  build_target_result.update_teardown(Result.PASS)
> >              except Exception as e:
> > @@ -535,6 +544,7 @@ def _run_test_suite(
> >              BlockingTestSuiteError: If a blocking test suite fails.
> >          """
> >          test_suite_name = test_suite_with_cases.test_suite_class.__name__
> > +        self._logger.set_stage(DtsStage.suite, Path(SETTINGS.output_dir, test_suite_name))
> >          test_suite = test_suite_with_cases.test_suite_class(sut_node, tg_node)
> >          try:
> >              self._logger.info(f"Starting test suite setup: {test_suite_name}")
> > @@ -683,5 +693,4 @@ def _exit_dts(self) -> None:
> >          if self._logger:
> >              self._logger.info("DTS execution has ended.")
> >
> > -        logging.shutdown()
> >          sys.exit(self._result.get_return_code())
> > diff --git a/dts/framework/test_result.py b/dts/framework/test_result.py
> > index eedb2d20ee..28f84fd793 100644
> > --- a/dts/framework/test_result.py
> > +++ b/dts/framework/test_result.py
> > @@ -42,7 +42,7 @@
> >      TestSuiteConfig,
> >  )
> >  from .exception import DTSError, ErrorSeverity
> > -from .logger import DTSLOG
> > +from .logger import DTSLogger
> >  from .settings import SETTINGS
> >  from .test_suite import TestSuite
> >
> > @@ -237,13 +237,13 @@ class DTSResult(BaseResult):
> >      """
> >
> >      dpdk_version: str | None
> > -    _logger: DTSLOG
> > +    _logger: DTSLogger
> >      _errors: list[Exception]
> >      _return_code: ErrorSeverity
> >      _stats_result: Union["Statistics", None]
> >      _stats_filename: str
> >
> > -    def __init__(self, logger: DTSLOG):
> > +    def __init__(self, logger: DTSLogger):
> >          """Extend the constructor with top-level specifics.
> >
> >          Args:
> > diff --git a/dts/framework/test_suite.py b/dts/framework/test_suite.py
> > index f9fe88093e..365f80e21a 100644
> > --- a/dts/framework/test_suite.py
> > +++ b/dts/framework/test_suite.py
> > @@ -21,7 +21,7 @@
> >  from scapy.packet import Packet, Padding  # type: ignore[import]
> >
> >  from .exception import TestCaseVerifyError
> > -from .logger import DTSLOG, getLogger
> > +from .logger import DTSLogger, get_dts_logger
> >  from .testbed_model import Port, PortLink, SutNode, TGNode
> >  from .utils import get_packet_summaries
> >
> > @@ -61,7 +61,7 @@ class TestSuite(object):
> >      #: Whether the test suite is blocking. A failure of a blocking test suite
> >      #: will block the execution of all subsequent test suites in the current build target.
> >      is_blocking: ClassVar[bool] = False
> > -    _logger: DTSLOG
> > +    _logger: DTSLogger
> >      _port_links: list[PortLink]
> >      _sut_port_ingress: Port
> >      _sut_port_egress: Port
> > @@ -88,7 +88,7 @@ def __init__(
> >          """
> >          self.sut_node = sut_node
> >          self.tg_node = tg_node
> > -        self._logger = getLogger(self.__class__.__name__)
> > +        self._logger = get_dts_logger(self.__class__.__name__)
> >          self._port_links = []
> >          self._process_links()
> >          self._sut_port_ingress, self._tg_port_egress = (
> > diff --git a/dts/framework/testbed_model/node.py b/dts/framework/testbed_model/node.py
> > index 1a55fadf78..74061f6262 100644
> > --- a/dts/framework/testbed_model/node.py
> > +++ b/dts/framework/testbed_model/node.py
> > @@ -23,7 +23,7 @@
> >      NodeConfiguration,
> >  )
> >  from framework.exception import ConfigurationError
> > -from framework.logger import DTSLOG, getLogger
> > +from framework.logger import DTSLogger, get_dts_logger
> >  from framework.settings import SETTINGS
> >
> >  from .cpu import (
> > @@ -63,7 +63,7 @@ class Node(ABC):
> >      name: str
> >      lcores: list[LogicalCore]
> >      ports: list[Port]
> > -    _logger: DTSLOG
> > +    _logger: DTSLogger
> >      _other_sessions: list[OSSession]
> >      _execution_config: ExecutionConfiguration
> >      virtual_devices: list[VirtualDevice]
> > @@ -82,7 +82,7 @@ def __init__(self, node_config: NodeConfiguration):
> >          """
> >          self.config = node_config
> >          self.name = node_config.name
> > -        self._logger = getLogger(self.name)
> > +        self._logger = get_dts_logger(self.name)
> >          self.main_session = create_session(self.config, self.name, self._logger)
> >
> >          self._logger.info(f"Connected to node: {self.name}")
> > @@ -189,7 +189,7 @@ def create_session(self, name: str) -> OSSession:
> >          connection = create_session(
> >              self.config,
> >              session_name,
> > -            getLogger(session_name, node=self.name),
> > +            get_dts_logger(session_name),
> >          )
> >          self._other_sessions.append(connection)
> >          return connection
> > @@ -299,7 +299,6 @@ def close(self) -> None:
> >              self.main_session.close()
> >          for session in self._other_sessions:
> >              session.close()
> > -        self._logger.logger_exit()
> >
> >      @staticmethod
> >      def skip_setup(func: Callable[..., Any]) -> Callable[..., Any]:
> > @@ -314,7 +313,7 @@ def skip_setup(func: Callable[..., Any]) -> Callable[..., Any]:
> >              return func
> >
> >
> > -def create_session(node_config: NodeConfiguration, name: str, logger: DTSLOG) -> OSSession:
> > +def create_session(node_config: NodeConfiguration, name: str, logger: DTSLogger) -> OSSession:
> >      """Factory for OS-aware sessions.
> >
> >      Args:
> > diff --git a/dts/framework/testbed_model/os_session.py b/dts/framework/testbed_model/os_session.py
> > index ac6bb5e112..6983aa4a77 100644
> > --- a/dts/framework/testbed_model/os_session.py
> > +++ b/dts/framework/testbed_model/os_session.py
> > @@ -21,7 +21,6 @@
> >      the :attr:`~.node.Node.main_session` translates that to ``rm -rf`` if the node's OS is Linux
> >      and other commands for other OSs. It also translates the path to match the underlying OS.
> >  """
> > -
> >  from abc import ABC, abstractmethod
> >  from collections.abc import Iterable
> >  from ipaddress import IPv4Interface, IPv6Interface
> > @@ -29,7 +28,7 @@
> >  from typing import Type, TypeVar, Union
> >
> >  from framework.config import Architecture, NodeConfiguration, NodeInfo
> > -from framework.logger import DTSLOG
> > +from framework.logger import DTSLogger
> >  from framework.remote_session import (
> >      CommandResult,
> >      InteractiveRemoteSession,
> > @@ -62,7 +61,7 @@ class OSSession(ABC):
> >
> >      _config: NodeConfiguration
> >      name: str
> > -    _logger: DTSLOG
> > +    _logger: DTSLogger
> >      remote_session: RemoteSession
> >      interactive_session: InteractiveRemoteSession
> >
> > @@ -70,7 +69,7 @@ def __init__(
> >          self,
> >          node_config: NodeConfiguration,
> >          name: str,
> > -        logger: DTSLOG,
> > +        logger: DTSLogger,
> >      ):
> >          """Initialize the OS-aware session.
> >
> > diff --git a/dts/framework/testbed_model/traffic_generator/traffic_generator.py b/dts/framework/testbed_model/traffic_generator/traffic_generator.py
> > index c49fbff488..d86d7fb532 100644
> > --- a/dts/framework/testbed_model/traffic_generator/traffic_generator.py
> > +++ b/dts/framework/testbed_model/traffic_generator/traffic_generator.py
> > @@ -13,7 +13,7 @@
> >  from scapy.packet import Packet  # type: ignore[import]
> >
> >  from framework.config import TrafficGeneratorConfig
> > -from framework.logger import DTSLOG, getLogger
> > +from framework.logger import DTSLogger, get_dts_logger
> >  from framework.testbed_model.node import Node
> >  from framework.testbed_model.port import Port
> >  from framework.utils import get_packet_summaries
> > @@ -28,7 +28,7 @@ class TrafficGenerator(ABC):
> >
> >      _config: TrafficGeneratorConfig
> >      _tg_node: Node
> > -    _logger: DTSLOG
> > +    _logger: DTSLogger
> >
> >      def __init__(self, tg_node: Node, config: TrafficGeneratorConfig):
> >          """Initialize the traffic generator.
> > @@ -39,7 +39,7 @@ def __init__(self, tg_node: Node, config: TrafficGeneratorConfig):
> >          """
> >          self._config = config
> >          self._tg_node = tg_node
> > -        self._logger = getLogger(f"{self._tg_node.name} {self._config.traffic_generator_type}")
> > +        self._logger = get_dts_logger(f"{self._tg_node.name} {self._config.traffic_generator_type}")
> >
> >      def send_packet(self, packet: Packet, port: Port) -> None:
> >          """Send `packet` and block until it is fully sent.
> > diff --git a/dts/main.py b/dts/main.py
> > index 1ffe8ff81f..d30c164b95 100755
> > --- a/dts/main.py
> > +++ b/dts/main.py
> > @@ -30,5 +30,4 @@ def main() -> None:
> >
> >  # Main program begins here
> >  if __name__ == "__main__":
> > -    logging.raiseExceptions = True
> >      main()
> > --
> > 2.34.1
> >
  

On Wed, Feb 14, 2024 at 2:49 AM Juraj Linkeš <juraj.linkes@pantheon.tech> wrote:
>
> Hi Jeremy,
>
> Just a reminder, please strip the parts you're not commenting on.
>
<snip>
> > > +    def __init__(self, *args, **kwargs):
> > > +        """Extend the constructor with extra file handlers."""
> > > +        self._extra_file_handlers = []
> > > +        super().__init__(*args, **kwargs)
> > >
> > > -        One handler logs to the console, the other one to a file, with either a regular or verbose
> > > -        format.
> > > +    def makeRecord(self, *args, **kwargs):
> >
> > Is the return type annotation here skipped because of the `:meta private:`?
> >
>
> Basically. We're modifying a method defined elsewhere, but there's no
> harm in adding the return type.
>
<snip>
> > > +    logging.setLoggerClass(DTSLogger)
> > > +    if name:
> > > +        name = f"{dts_root_logger_name}.{name}"
> > > +    else:
> > > +        name = dts_root_logger_name
> > > +    logger = logging.getLogger(name)
> > > +    logging.setLoggerClass(logging.Logger)
> >
> > What's the benefit of setting the logger class back to logging.Logger
> > here? Is the idea basically that if someone wanted to use the logging
> > module we shouldn't implicitly make them use our DTSLogger?
> >
>
> Yes. We should actually set it to whatever was there before (it may
> not be logging.Logger), so I'll change that.+
>
>
<snip>
> > > @@ -137,6 +141,7 @@ def run(self):
> > >
> > >              # for all Execution sections
> > >              for execution in self._configuration.executions:
> > > +                self._logger.set_stage(DtsStage.execution)
> >
> > This ends up getting set twice in short succession which of course
> > doesn't functionally cause a problem, but I don't exactly see the
> > point of setting it twice.
>
> I'm not sure what you're referring to. The stage is only set once at
> the start of each execution (and more generally, at the start of each
> stage). It's also set in each finally block to properly mark the
> cleanup of that stage. There are two finally blocks in the execution
> stage where that could happen, but otherwise it should be set exactly
> once.

You're right, I misread where it was being set the second time in the
code when I was reading this and thought there was a way where it
could get set twice but it cannot. Apologies, it makes sense that you
weren't sure what I was referring to because what I was referring to
doesn't exist.

>
> >  We could either set it here or set it in
> > the _run_execution, but i think it makes more sense to set it in the
> > _run_execution method as that is the method where we are doing the
> > setup, here we are only initializing the nodes which is still in a
> > sense "pre execution."
>
> Init nodes was pre-execution before the patch. I've moved it to
> execution because of two reasons:
> 1. The nodes are actually defined per-execution. It just made more
> sense to move them to execution. Also, if an error happens while
> connecting to a node, we don't want to abort the whole DTS run, just
> the execution, as the next execution could be connecting to a
> different node.
> 2. We're not just doing node init here, we're also discovering which
> test cases to run. This is essential to do as soon as possible (before
> anything else happens in the execution, such as connecting the nodes)
> so that we can mark blocked test cases in case of an error. Test case
> discovery is definitely part of each execution and putting node init
> after that was a natural consequence. There's an argument for
> discovering test cases of all executions before actually running any
> of the executions. It's certainly doable, but the code doesn't look
> that good (when not modifying the original execution config (which we
> shouldn't do) - I've tried) and there's actually not much of a point
> to do it this way, the result is almost the same. Where it makes a
> difference is when there's an error in test suite configuration and
> later executions - the user would have to wait for the previous
> execution to fully run to discover the error).
>

These are very good points. I was still thinking of these
initializations as part of the pre-execution but I agree with you that
the things we are doing are actually part of the execution. Thank you
for elaborating!

> >
> >
<snip>