@@ -5,141 +5,187 @@
"""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) -> logging.LogRecord:
+ """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 # type: ignore[attr-defined]
+ 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
+ original_logger_class = logging.getLoggerClass()
+ logging.setLoggerClass(DTSLogger)
+ if name:
+ name = f"{dts_root_logger_name}.{name}"
+ else:
+ name = dts_root_logger_name
+ logger = logging.getLogger(name)
+ logging.setLoggerClass(original_logger_class)
+ return logger # type: ignore[return-value]
@@ -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.
@@ -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:
@@ -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,
@@ -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
@@ -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)
self._logger.info(
f"Running execution with SUT '{execution.system_under_test_node.name}'."
)
@@ -168,6 +173,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)
@@ -425,6 +431,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:
@@ -453,6 +460,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:
@@ -469,6 +477,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:
@@ -541,6 +550,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}")
@@ -689,5 +699,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())
@@ -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:
@@ -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 = (
@@ -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:
@@ -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.
@@ -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.
@@ -6,8 +6,6 @@
"""The DTS executable."""
-import logging
-
from framework import settings
@@ -30,5 +28,4 @@ def main() -> None:
# Main program begins here
if __name__ == "__main__":
- logging.raiseExceptions = True
main()