From 73bacf8bcb3e3ae6b68c6ec10fcfa1118986fdd0 Mon Sep 17 00:00:00 2001 From: "Mr. Walls" Date: Tue, 8 Apr 2025 19:57:58 -0700 Subject: [PATCH 01/12] [FEATURE] Initial implementation of module logging for debugging (- WIP #233 -) Changes in file .coveragerc: * updated related config Changes in file multicast/__init__.py: * added debug signposts via logging module Changes in file multicast/env.py: * added debug signposts via logging module Changes in file multicast/exceptions.py: * added debug signposts via logging module Changes in file multicast/hear.py: * added debug signposts via logging module * related work Changes in file multicast/recv.py: * added debug signposts via logging module Changes in file multicast/send.py: * added debug signposts via logging module * related work Changes in file multicast/skt.py: * added debug signpost via logging module Changes in file requirements.txt: * mention of loggin builtin Changes in file tests/__init__.py: * added debug signposts via logging module Changes in file tests/context.py: * related work Changes in file tests/run_selective.py: * related work def main() -> None: --- .coveragerc | 2 + multicast/__init__.py | 13 +++++ multicast/env.py | 40 ++++++++++++++- multicast/exceptions.py | 30 +++++++++-- multicast/hear.py | 110 +++++++++++++++++++++++++++++++++++----- multicast/recv.py | 22 ++++++-- multicast/send.py | 35 ++++++++++++- multicast/skt.py | 5 ++ requirements.txt | 1 + tests/__init__.py | 81 ++++++++++++++++++++++++++--- tests/context.py | 7 ++- tests/run_selective.py | 17 ++++--- 12 files changed, 321 insertions(+), 42 deletions(-) diff --git a/.coveragerc b/.coveragerc index 2a75abb1..190fa3bf 100644 --- a/.coveragerc +++ b/.coveragerc @@ -34,6 +34,7 @@ exclude_lines = if __name__ in u"__main__": if __name__ .. .__main__.: if __sys_path__ not in sys.path: + if __debug__ os.abort() exit @@ -52,6 +53,7 @@ partial_branches = if __name__ in u'__main__': if __name__ in u"__main__": if __name__ in '__main__': + if __debug__ if __sys_path__ not in sys.path: # don't complain about sys.modules sys.modules diff --git a/multicast/__init__.py b/multicast/__init__.py index 44695d06..c49a5923 100644 --- a/multicast/__init__.py +++ b/multicast/__init__.py @@ -22,6 +22,7 @@ import socket import struct import abc +import logging # skipcq __all__ = [ @@ -404,6 +405,10 @@ """ +if logging.__name__ is not None: # pragma: no branch + logging.getLogger(__module__).addHandler(logging.NullHandler()) + logging.getLogger(__module__).debug(f"Loading {__module__}") + if sys.__name__ is None: raise ModuleNotFoundError( "FAIL: we could not import sys. We're like in the matrix! ABORT." @@ -418,6 +423,7 @@ if socket.__name__ is None: raise ModuleNotFoundError("FAIL: we could not import socket. ABORT.") from None else: # pragma: no branch + logging.getLogger(__module__).debug(f"Setting default packet timeout to {_MCAST_DEFAULT_TTL}") socket.setdefaulttimeout(int(_MCAST_DEFAULT_TTL)) if struct.__name__ is None: @@ -460,6 +466,7 @@ if _config is None: raise ImportError("FAIL: we could not import environment. ABORT.") from None else: + logging.getLogger(__module__).debug("Configuring overrides and defaults.") _MCAST_DEFAULT_PORT = _config["port"] _MCAST_DEFAULT_GROUP = _config["group"] _MCAST_DEFAULT_TTL = _config["ttl"] @@ -468,6 +475,11 @@ _MCAST_DEFAULT_BIND_IP = _config["bind_addr"] global _MCAST_DEFAULT_GROUPS # skipcq: PYL-W0604 _MCAST_DEFAULT_GROUPS = _config["groups"] + if __debug__: # pragma: no branch + logging.getLogger(__module__).info("Overrides and defaults are configured.") + logging.getLogger(__module__).debug("Defaults:") + for key, value in _config.items(): + logging.getLogger(__module__).debug(f"\t{key}={str(value)}") del _config # skipcq - cleanup any bootstrap/setup leaks early @@ -543,6 +555,7 @@ def buildArgs(cls, calling_parser_group): """ if calling_parser_group is None: # pragma: no branch + logging.getLogger(__module__).debug(f"Building {__name__} arguments.") calling_parser_group = argparse.ArgumentParser( prog=str(cls.__name__ if cls.__proc__ is None else cls.__proc__), description=cls.__prologue__, diff --git a/multicast/env.py b/multicast/env.py index eab10d99..7e99c1e8 100644 --- a/multicast/env.py +++ b/multicast/env.py @@ -88,6 +88,7 @@ try: import os import warnings + from . import logging # skipcq: PLY-C0414 from . import socket # skipcq: PYL-C0414 import ipaddress except Exception as err: @@ -98,6 +99,11 @@ raise baton from err +module_logger = logging.getLogger(__module__) +module_logger.debug(f"loading {__module__}") +module_logger.debug(f"Initializing {__package__} environment.") + + def validate_buffer_size(size: int) -> bool: """ Validate if the buffer size is a positive integer. @@ -334,26 +340,31 @@ def load_buffer_size() -> int: """ # Import globals that we'll potentially update from multicast import _MCAST_DEFAULT_BUFFER_SIZE + module_logger.debug("Looking for MULTICAST_BUFFER_SIZE in environment.") try: buffer_size = int(os.getenv( "MULTICAST_BUFFER_SIZE", _MCAST_DEFAULT_BUFFER_SIZE # skipcq: PYL-W1508 )) + module_logger.debug("Done.") except ValueError: warnings.warn( f"Invalid MULTICAST_BUFFER_SIZE value, using default {_MCAST_DEFAULT_BUFFER_SIZE}", stacklevel=2 ) buffer_size = _MCAST_DEFAULT_BUFFER_SIZE # skipcq: PYL-W1508 - # Validate and potentially update port + # Validate and potentially update buffer-size + module_logger.debug("Validating MULTICAST_BUFFER_SIZE.") if validate_buffer_size(buffer_size): globals()["_MCAST_DEFAULT_BUFFER_SIZE"] = buffer_size + module_logger.debug("Valid.") else: warnings.warn( f"Invalid MULTICAST_BUFFER_SIZE {buffer_size}, using default {_MCAST_DEFAULT_BUFFER_SIZE}", stacklevel=2 ) buffer_size = _MCAST_DEFAULT_BUFFER_SIZE + module_logger.debug(f"Loaded {buffer_size} as internal multicast buffer size.") return buffer_size @@ -435,22 +446,27 @@ def load_port() -> int: """ # Import globals that we'll potentially update from multicast import _MCAST_DEFAULT_PORT + module_logger.debug("Looking for MULTICAST_PORT in environment.") try: port = int(os.getenv("MULTICAST_PORT", _MCAST_DEFAULT_PORT)) + module_logger.debug("Done.") except ValueError: warnings.warn( f"Invalid MULTICAST_PORT value, using default {_MCAST_DEFAULT_PORT}", stacklevel=2 ) port = _MCAST_DEFAULT_PORT # Validate and potentially update port + module_logger.debug("Validating MULTICAST_PORT.") if validate_port(port): globals()["_MCAST_DEFAULT_PORT"] = port + module_logger.debug("Valid.") else: warnings.warn( f"Port {port} is outside valid range (49152-65535), using default {_MCAST_DEFAULT_PORT}", stacklevel=2 ) port = _MCAST_DEFAULT_PORT + module_logger.debug(f"Loaded {port} as default multicast port.") return port @@ -555,15 +571,19 @@ def load_group() -> ipaddress.IPv4Address: """ # Import globals that we'll potentially update from multicast import _MCAST_DEFAULT_GROUP + module_logger.debug("Looking for any MULTICAST_GROUP in environment.") group = os.getenv("MULTICAST_GROUP", _MCAST_DEFAULT_GROUP) # Validate and potentially update group + module_logger.debug("Validating either MULTICAST_GROUP or default.") if validate_multicast_address(group): globals()["_MCAST_DEFAULT_GROUP"] = group + module_logger.debug("Valid.") else: warnings.warn( f"Invalid multicast group {group}, using default {_MCAST_DEFAULT_GROUP}", stacklevel=2 ) group = _MCAST_DEFAULT_GROUP + module_logger.debug(f"Loaded {group} as default multicast group.") return ipaddress.IPv4Address(group) @@ -638,24 +658,31 @@ def load_TTL() -> int: """ # Import globals that we'll potentially update from multicast import _MCAST_DEFAULT_TTL + module_logger.debug("Looking for MULTICAST_TTL in environment.") try: ttl = int(os.getenv("MULTICAST_TTL", _MCAST_DEFAULT_TTL)) + module_logger.debug("Done.") except ValueError: warnings.warn( f"Invalid MULTICAST_TTL value, using default {_MCAST_DEFAULT_TTL}", stacklevel=2 ) ttl = _MCAST_DEFAULT_TTL # Validate and potentially update TTL + module_logger.debug("Validating MULTICAST_TTL.") if validate_ttl(ttl): globals()["_MCAST_DEFAULT_TTL"] = ttl + module_logger.debug("Valid.") else: warnings.warn( f"TTL {ttl} is outside valid range (1-126), using default {_MCAST_DEFAULT_TTL}", stacklevel=2 ) ttl = _MCAST_DEFAULT_TTL + module_logger.debug(f"Loaded {ttl} as default multicast time-to-live.") # Update socket default timeout + module_logger.debug("Update socket default timeout.") socket.setdefaulttimeout(int(ttl)) + module_logger.debug("Updated.") return ttl @@ -857,13 +884,19 @@ def load_config() -> dict: """ # Load values from environment with defaults + module_logger.info("Loading multicast overrides from environment.") port = load_port() group = load_group() ttl = load_TTL() buffer_size = load_buffer_size() + module_logger.debug("Looking for MULTICAST_GROUPS in environment.") groups_str = os.getenv("MULTICAST_GROUPS", "") + module_logger.debug("Done.") + module_logger.debug("Looking for MULTICAST_BIND_ADDR in environment.") bind_addr = os.getenv("MULTICAST_BIND_ADDR", str(group)) # skipcq: PYL-W1508 + module_logger.debug("Done.") # Process and validate groups + module_logger.debug("Processing and validating groups.") groups = set() if groups_str: for addr in groups_str.split(): @@ -875,9 +908,14 @@ def load_config() -> dict: ) # Always include the primary group groups.add(str(group)) + module_logger.debug("Processed groups.") # Include bind_addr if it's a valid multicast address + module_logger.debug("Processing and validating bind-address.") if validate_multicast_address(bind_addr): + module_logger.debug("Adding multicast bind-address to groups.") groups.add(str(bind_addr)) + module_logger.debug("Processed bind-address.") + module_logger.debug("Overrides and defaults are ready to configure.") return { "port": port, "group": str(group), diff --git a/multicast/exceptions.py b/multicast/exceptions.py index 4400d34e..cc6e3971 100644 --- a/multicast/exceptions.py +++ b/multicast/exceptions.py @@ -193,8 +193,8 @@ """ try: - from . import sys # skipcq: PYL-C0414 from . import argparse # skipcq: PYL-C0414 + from . import logging # skipcq: PYL-C0414 import functools except Exception as err: baton = ImportError(err, str("[CWE-758] Module failed completely.")) @@ -204,6 +204,11 @@ raise baton from err +module_logger = logging.getLogger(__module__) +module_logger.debug(f"loading {__module__}") +module_logger.debug(f"Initializing {__package__} exceptions.") + + class CommandExecutionError(RuntimeError): """ Exception raised when a command execution fails. @@ -433,8 +438,11 @@ def __init__(self, *args, **kwargs) -> None: self.exit_code = 143 # Use SIGTERM exit code for graceful shutdown +module_logger.debug("Initialized exceptions.") +module_logger.debug("Initializing error message strings.") # Error message constants EXIT_CODE_RANGE_ERROR = "Exit code must be an integer between 0 and 255" +module_logger.debug("Initialized message strings.") def validate_exit_code(code) -> None: @@ -509,8 +517,13 @@ def validate_exit_code(code) -> None: >>> success True """ + module_logger.info("Validating possible exit code.") if not isinstance(code, int) or code < 0 or code > 255: raise ValueError(EXIT_CODE_RANGE_ERROR) + module_logger.info("Validated possible exit code.") + + +module_logger.debug("Initializing CEP-8 EXIT_CODES") EXIT_CODES = { @@ -555,6 +568,7 @@ def validate_exit_code(code) -> None: Usage Example: ```python + import sys from multicast.exceptions import EXIT_CODES from multicast.exceptions import get_exit_code_from_exception @@ -621,6 +635,9 @@ def validate_exit_code(code) -> None: """ +module_logger.debug("Initialized EXIT_CODES.") + + def get_exit_code_from_exception(exc: BaseException) -> int: """ Retrieve the exit code associated with a specific exception. @@ -733,25 +750,28 @@ def exit_on_exception(func: callable): @functools.wraps(func) def wrapper(*args, **kwargs): + _func_logger = module_logger try: + _func_logger = logging.getLogger(func.__name__) return func(*args, **kwargs) except SystemExit as exc: # Handle SystemExit exceptions, possibly from argparse exit_code = exc.code if isinstance(exc.code, int) else 2 - if (sys.stderr.isatty()): - print(f"{EXIT_CODES[exit_code][1]}: {exc}", file=sys.stderr) + _func_logger.warning(f"{EXIT_CODES[exit_code][1]}: {exc}") raise SystemExit(exit_code) from exc # otherwise sys.exit(exit_code) except BaseException as err: exit_code = get_exit_code_from_exception(err) - if (sys.stderr.isatty()): - print(f"{EXIT_CODES[exit_code][1]}: {err}", file=sys.stderr) + _func_logger.warning(f"{EXIT_CODES[exit_code][1]}: {err}") raise SystemExit(exit_code) from err # otherwise sys.exit(exit_code) return wrapper +module_logger.debug(f"loaded {__module__}") + + # skipcq __all__ = [ """__package__""", diff --git a/multicast/hear.py b/multicast/hear.py index 6ba6dcfa..5daac192 100644 --- a/multicast/hear.py +++ b/multicast/hear.py @@ -180,11 +180,11 @@ """ try: - import sys as _sys - if 'multicast' not in _sys.modules: + import sys + if 'multicast' not in sys.modules: from . import multicast as multicast # pylint: disable=cyclic-import - skipcq: PYL-C0414 else: # pragma: no branch - multicast = _sys.modules["multicast"] + multicast = sys.modules["multicast"] _BLANK = multicast._BLANK # skipcq: PYL-W0212 - module ok # skipcq from . import recv as recv # pylint: disable=useless-import-alias - skipcq: PYL-C0414 @@ -196,6 +196,7 @@ import multicast as multicast # pylint: disable=cyclic-import - skipcq: PYL-R0401, PYL-C0414 try: + import logging import threading import socketserver import warnings @@ -216,6 +217,10 @@ raise ImportError(err) from err +module_logger = logging.getLogger(__name__) +module_logger.debug(f"loading {__name__}") + + class McastServer(socketserver.UDPServer): """ Generic Subclasses socketserver.UDPServer for handling '--daemon' function. @@ -244,6 +249,47 @@ class McastServer(socketserver.UDPServer): """ + __name__ = """multicast.hear.McastServer""" # skipcq: PYL-W0622 + """Names this server + + Minimal Acceptance Testing: + + First set up test fixtures by importing multicast. + + Testcase 0: Multicast should be importable. + + >>> import multicast + >>> + + Testcase 1: McastServer should be automatically imported. + + >>> multicast.hear.McastServer.__name__ is not None + True + >>> + + """ + + def __init__(self, *args, **kwargs) -> None: + (logger_name, _) = kwargs.get("server_address", (None, None)) + if logger_name: # pragma: no branch + self.__logger = logging.getLogger(f"{McastServer.__name__}.{logger_name}") + else: + self.__logger = logging.getLogger(f"{McastServer.__name__}") + super().__init__(*args, **kwargs) + + def _sync_logger(self) -> None: + """Internal function to sync logger with bound socket address.""" + (logger_name, _) = self.socket.getsockname() + if logger_name: + self.__logger = logging.getLogger(f"{McastServer.__name__}.{logger_name}") + else: # pragma: no branch + self.__logger = logging.getLogger(f"{McastServer.__name__}") + + @property + def logger(self) -> logging.Logger: + """Getter for the logger attribute.""" + return self.__logger + def server_activate(self): """ Activate the server to begin handling requests. @@ -253,7 +299,7 @@ def server_activate(self): Returns: None """ - print(str("server_activate")) + self.logger.info("server_activate") with warnings.catch_warnings(): warnings.simplefilter("ignore", category=ResourceWarning) self.open_for_request() @@ -274,7 +320,7 @@ def open_for_request(self): Returns: None """ - print(str("open_request")) + self.logger.info("open_request") # enter critical section old_socket = self.socket (tmp_addr, tmp_prt) = old_socket.getsockname() @@ -292,10 +338,11 @@ def server_bind(self): Returns: None """ - print(str("server_bind")) + self.logger.info("server_bind") super(McastServer, self).server_bind() + self._sync_logger() # enter critical section - print(f"bound on: {str(self.socket.getsockname())}") + self.logger.info(f"bound on: {str(self.socket.getsockname())}") # exit critical section def close_request(self, request): @@ -311,7 +358,7 @@ def close_request(self, request): Returns: None """ - print(str("close_request")) + self.logger.info("close_request") with warnings.catch_warnings(): warnings.simplefilter("ignore", category=ResourceWarning) self.open_for_request() @@ -331,7 +378,7 @@ def handle_error(self, request, client_address): Returns: None """ - print(str("handle_error")) + self.logger.info("handle_error") if request is not None and request[0] is not None and "STOP" in str(request[0]): def kill_func(a_server): """ @@ -377,6 +424,27 @@ class HearUDPHandler(socketserver.BaseRequestHandler): >>> + """ + + __name__ = "multicast.hear.HearUDPHandler" # skipcq: PYL-W0622 + """Names this handler type. + + Minimal Acceptance Testing: + + First set up test fixtures by importing multicast. + + Testcase 0: Multicast should be importable. + + >>> import multicast + >>> + + Testcase 1: HearUDPHandler should be automatically imported. + + >>> multicast.hear.HearUDPHandler.__name__ is not None + True + >>> + + """ def handle(self): @@ -443,17 +511,22 @@ def handle(self): try: data = data.decode('utf8') if isinstance(data, bytes) else str(data) except UnicodeDecodeError: # pragma: no cover + if __debug__: + logging.getLogger(self.__name__).debug( + f"Received invalid UTF-8 data from {self.client_address[0]}" + ) return # silently ignore invalid UTF-8 data -- fail quickly. - if (_sys.stdout.isatty()): # pragma: no cover - print(f"{self.client_address[0]} SAYS: {data.strip()} to ALL") + _logger = logging.getLogger(self.__name__) + if __debug__: + _logger.info(f"{self.client_address[0]} SAYS: {data.strip()} to ALL") if data is not None: me = str(sock.getsockname()[0]) - if (_sys.stdout.isatty()): # pragma: no cover + if __debug__: # pragma: no cover _what = data.strip().replace("""\r""", str()).replace("""%""", """%%""") - print( + _logger.info( f"{me} HEAR: [{self.client_address} SAID {str(_what)}]" ) - print( + _logger.info( f"{me} SAYS [ HEAR [ {str(_what)} SAID {self.client_address} ] from {me} ]" # noqa ) send.McastSAY()._sayStep( # skipcq: PYL-W0212 - module ok @@ -539,11 +612,14 @@ def doStep(self, *args, **kwargs): Returns: tuple: A tuple containing a status indicator and an optional result message. """ + _logger = logging.getLogger(__name__) + _logger.debug(McastHEAR.__proc__) HOST = kwargs.get("group", multicast._MCAST_DEFAULT_GROUP) # skipcq: PYL-W0212 - module ok PORT = kwargs.get("port", multicast._MCAST_DEFAULT_PORT) # skipcq: PYL-W0212 - module ok server_initialized = False server = None try: + _logger.debug(f"Initializing server on port {PORT} as {HOST}.") with McastServer((HOST, PORT), HearUDPHandler) as server: server_initialized = True server.serve_forever() @@ -557,9 +633,15 @@ def doStep(self, *args, **kwargs): f"HEAR has stopped due to interruption signal (was previously listening on ({HOST}, {PORT}))." ) from userInterrupt finally: + _logger.debug(f"Finalizing server with port {PORT} from {HOST}.") if server: # pragma: no cover # deadlocks if not called by other thread end_it = threading.Thread(name="Kill_Thread", target=server.shutdown, args=[]) end_it.start() end_it.join(1) + if __debug__: + if server_initialized: + module_logger.debug(f"HEAR result was {server_initialized}. Reporting success.") + else: + module_logger.debug(f"HEAR result was {server_initialized}. Reporting failure.") return (server_initialized, None) diff --git a/multicast/recv.py b/multicast/recv.py index 5cdeb262..76e3f884 100644 --- a/multicast/recv.py +++ b/multicast/recv.py @@ -183,6 +183,7 @@ import multicast as multicast # pylint: disable=cyclic-import - skipcq: PYL-R0401, PYL-C0414 try: + from multicast import logging from multicast import argparse as _argparse from multicast import unicodedata as _unicodedata from multicast import socket as _socket @@ -203,6 +204,10 @@ raise baton from err +module_logger = logging.getLogger(__name__) +module_logger.debug(f"loading {__name__}") + + def joinstep(groups, port, iface=None, bind_group=None, isock=None): """ Join multicast groups to prepare for receiving messages. @@ -411,11 +416,9 @@ def recvstep(msgbuffer, chunk, sock): msgbuffer = tryrecv(msgbuffer, chunk, sock) except KeyboardInterrupt: # pragma: no branch if (sys.stdout.isatty()): # pragma: no cover - print(multicast._BLANK) # skipcq: PYL-W0212 - module ok - print("User Interrupted") + module_logger.warning("User Interrupted") except OSError: # pragma: no branch - if (sys.stdout.isatty()): # pragma: no cover - print(multicast._BLANK) # skipcq: PYL-W0212 - module ok + module_logger.debug("[CWE-440] Nothing happened. There seems to have been an OS error.") finally: sock = multicast.endSocket(sock) if not (chunk is None): # pragma: no branch @@ -541,12 +544,17 @@ def _hearstep(groups, port, iface=None, bind_group=None): """ + module_logger.debug(f"Joining {str(groups)} on port {port} using {iface} as {bind_group}") sock = joinstep(groups, port, iface, bind_group, None) + module_logger.debug(f"Opened {sock}") msgbuffer = str(multicast._BLANK) # skipcq: PYL-W0212 - module ok chunk = None + module_logger.debug("Ready.") msgbuffer = recvstep(msgbuffer, chunk, sock) # about 969 bytes in base64 encoded as chars + module_logger.debug("Closing.") multicast.endSocket(sock) + module_logger.debug("Done.") return msgbuffer def doStep(self, *args, **kwargs): @@ -563,6 +571,7 @@ def doStep(self, *args, **kwargs): Returns: tuple: A tuple containing received data and a status indicator. """ + module_logger.debug("RECV") response = self._hearstep( kwargs.get( "groups", @@ -574,8 +583,13 @@ def doStep(self, *args, **kwargs): ) _is_std = kwargs.get("is_std", False) if (sys.stdout.isatty() or _is_std) and (len(response) > 0): # pragma: no cover + module_logger.debug("Will Print to Console.") print(multicast._BLANK) # skipcq: PYL-W0212 - module ok print(str(response)) print(multicast._BLANK) # skipcq: PYL-W0212 - module ok _result = (len(response) > 0) is True + if _result: + module_logger.info("Success") + else: + module_logger.debug("Nothing Received.") return (_result, None if not _result else response) # skipcq: PTC-W0020 - intended diff --git a/multicast/send.py b/multicast/send.py index 3b30e096..7c479da5 100644 --- a/multicast/send.py +++ b/multicast/send.py @@ -146,6 +146,7 @@ import multicast as multicast # pylint: disable=cyclic-import - skipcq: PYL-R0401, PYL-C0414 try: + import logging from multicast import argparse as _argparse # skipcq: PYL-C0414 from multicast import unicodedata as _unicodedata # skipcq: PYL-C0414 from multicast import socket as _socket # skipcq: PYL-C0414 @@ -163,6 +164,10 @@ raise ImportError(baton) from baton +module_logger = logging.getLogger(__name__) +module_logger.debug(f"loading {__name__}") + + class McastSAY(multicast.mtool): """ Multicast Broacaster tool. @@ -276,6 +281,8 @@ def setupArgs(cls, parser): """ if parser is not None: # pragma: no branch + if __debug__: + module_logger.debug(f"Adding {__name__} arguments.") parser.add_argument( "--port", type=int, @@ -318,11 +325,26 @@ def _sayStep(group, port, data): """ _success = False sock = multicast.genSocket() + if __debug__: + module_logger.info(f"Preparing to send {len(data)}") try: - sock.sendto(data.encode('utf8'), (group, port)) + if __debug__ and module_logger.isEnabledFor(logging.DEBUG): # pragma: no branch + module_logger.debug("Encoding.") + _payload = data.encode('utf8') + module_logger.debug(f"Encoded {len(_payload)}.") + module_logger.debug(f"Sending {_payload} to ({group}, {port}).") + sock.sendto(data.encode('utf8'), (group, port)) + module_logger.debug(f"Sent {len(_payload)}.") + else: + sock.sendto(data.encode('utf8'), (group, port)) _success = True finally: multicast.endSocket(sock) + if __debug__: # pragma: no branch + if _success: + module_logger.info("Finished sending. Reporting success.") + else: # pragma: no branch + module_logger.warning("Failed to send. Reporting failure.") return _success def doStep(self, *args, **kwargs): @@ -342,6 +364,8 @@ def doStep(self, *args, **kwargs): Returns: tuple: A tuple containing a status indicator and optional error message. """ + _logger = logging.getLogger(McastSAY.__name__) + _logger.debug(McastSAY.__proc__) group = kwargs.get( "group", multicast._MCAST_DEFAULT_GROUP # skipcq: PYL-W0212 - module ok @@ -350,6 +374,7 @@ def doStep(self, *args, **kwargs): data = kwargs.get("data") _result = False if data == ["-"]: + _logger.debug("Reading from stdin") _result = True # Read from stdin in chunks while True: @@ -360,11 +385,12 @@ def doStep(self, *args, **kwargs): multicast._MCAST_DEFAULT_BUFFER_SIZE, # skipcq: PYL-W0212 - module ok ) except IOError as e: - print(f"Error reading from stdin: {e}", file=sys.stderr) + _logger.exception(f"[CWE-228] Error reading from stdin: {e}") break if not chunk: break _result = _result and self._sayStep(group, port, chunk) + _logger.debug("Finished reading stdin.") elif isinstance(data, list): # Join multiple arguments into a single string message = " ".join(data) @@ -372,4 +398,9 @@ def doStep(self, *args, **kwargs): else: message = data.decode('utf8') if isinstance(data, bytes) else str(data) _result = self._sayStep(group, port, message) + if __debug__: # pragma: no branch + if _result: + module_logger.debug(f"SEND result was {_result}. Reporting success.") + else: # pragma: no branch + module_logger.debug(f"SEND result was {_result}. Reporting failure.") return (_result, None) # skipcq: PTC-W0020 - intended diff --git a/multicast/skt.py b/multicast/skt.py index 6052887b..cb6513fc 100644 --- a/multicast/skt.py +++ b/multicast/skt.py @@ -137,6 +137,7 @@ """ try: + from . import logging from . import socket as _socket # skipcq: PYL-C0414 from . import struct as _struct # noqa from . import _MCAST_DEFAULT_TTL as _MCAST_DEFAULT_TTL # skipcq: PYL-C0414 @@ -148,6 +149,10 @@ raise baton from err +module_logger = logging.getLogger(__module__) +module_logger.debug(f"loading {__module__}") + + def genSocket() -> _socket.socket: """ Create and configure a multicast socket. diff --git a/requirements.txt b/requirements.txt index 233a363d..73dbc168 100644 --- a/requirements.txt +++ b/requirements.txt @@ -14,6 +14,7 @@ # See the License for the specific language governing permissions and # limitations under the License. #python +# logging - builtin - PSF license # time - builtin - PSF license # re - builtin - PSF license? # subprocess - PSF license diff --git a/tests/__init__.py b/tests/__init__.py index b200b742..262c5ac5 100644 --- a/tests/__init__.py +++ b/tests/__init__.py @@ -63,6 +63,71 @@ except ImportError as baton: # pragma: no branch raise ModuleNotFoundError("[CWE-440] Module failed to import.") from baton +try: + import logging + try: + class ANSIColors: + # Define ANSI color codes + BLACK = """\033[30m""" + RED = """\033[31m""" + GREEN = """\033[32m""" + YELLOW = """\033[33m""" + BLUE = """\033[34m""" + MAGENTA = """\033[35m""" + CYAN = """\033[36m""" + GREY = """\033[37m""" + AMBER = """\033[93m""" + REDBG = """\033[41m""" # Red background + ENDC = """\033[0m""" + + logging_color = { + 'debug': ANSIColors.BLUE, 'info': ANSIColors.GREY, + 'warning': ANSIColors.AMBER, + 'error': ANSIColors.RED, + 'critical': str(str(ANSIColors.BLACK) + str(ANSIColors.REDBG)) + } + + logging_level = { + 'debug': logging.DEBUG, + 'info': logging.INFO, + 'warning': logging.WARNING, + 'error': logging.ERROR, + 'critical': logging.CRITICAL + } + + class ColoredStreamHandler(logging.StreamHandler): + def emit(self, record): + # Get the log level as a string + loglevel = record.levelname.lower() + # Validate the log level + if not isinstance(loglevel, str): + raise ValueError("Invalid log level") + if loglevel not in logging_color.keys(): + raise ValueError("Invalid log level") + # Determine color based on whether the output is a terminal + if sys.stdout.isatty(): + colorPrefix = logging_color[loglevel] + endColor = ANSIColors.ENDC + else: + colorPrefix = str() + endColor = str() + # Format the message + msg = self.format(record) + formatted_msg = f"{colorPrefix}{msg}{endColor}" + # Write the formatted message to the stream + self.stream.write(formatted_msg + self.terminator) + self.flush() + + except Exception as _cause: + raise ImportError("[CWE-909] Could Not Initialize Test Logger") from _cause + # Setup logging for testing + root = logging.getLogger() + root.setLevel(logging.INFO) + handler = ColoredStreamHandler() + root.addHandler(handler) +except ImportError as baton: # pragma: no branch + raise ModuleNotFoundError("[CWE-440] Logging failed to initialize.") from baton + try: if 'multicast' not in sys.modules: import multicast # pylint: disable=cyclic-import - skipcq: PYL-R0401 @@ -72,6 +137,8 @@ raise ImportError("[CWE-440] multicast Failed to import.") from err try: + _LOGGER = logging.getLogger(__module__) + _LOGGER.debug("Initializing tests.") _DIR_NAME = str(".") _PARENT_DIR_NAME = str("..") _BASE_NAME = os.path.dirname(__file__) @@ -117,7 +184,7 @@ from tests import test_fuzz depends.insert(10, test_fuzz) except Exception as e: # pragma: no branch - print(f"Error loading optional Fuzzing tests: {e}") + _LOGGER.exception(f"Error loading optional Fuzzing tests: {e}") for unit_test in depends: try: @@ -128,11 +195,9 @@ except Exception as impErr: # pragma: no branch raise ImportError(str("[CWE-758] Test module failed completely.")) from impErr except Exception as badErr: # pragma: no branch - print(str('')) - print(str(type(badErr))) - print(str(badErr)) - print(str((badErr.args))) - print(str('')) + _LOGGER.debug(str(type(badErr))) + _LOGGER.exception(str(badErr)) + _LOGGER.debug(str((badErr.args))) badErr = None del badErr # skipcq - cleanup any error leaks early exit(0) # skipcq: PYL-R1722 - intentionally allow overwriteing exit for testing @@ -216,9 +281,9 @@ def loadDocstringsFromModule(module: types.ModuleType) -> TestSuite: doc_suite.addTests(doctest.DocTestSuite(module=module, test_finder=finder)) except ValueError as e: # ValueError is raised when no tests are found - print(f"No doctests found in {module.__name__}: {e}") + _LOGGER.warning(f"No doctests found in {module.__name__}: {e}") except Exception as e: - print(f"Error loading doctests from {module.__name__}: {e}") + _LOGGER.error(f"Error loading doctests from {module.__name__}: {e}") return doc_suite diff --git a/tests/context.py b/tests/context.py index aa611ff7..79f35786 100644 --- a/tests/context.py +++ b/tests/context.py @@ -91,6 +91,7 @@ raise ModuleNotFoundError("[CWE-440] string support is not available.") from None import secrets import unittest + import warnings except ImportError as err: # pragma: no branch raise ModuleNotFoundError("[CWE-440] Module Failed to import.") from err @@ -1001,9 +1002,11 @@ def managed_process(process): if process.is_alive(): process.kill() except Exception as e: - if (sys.stderr.isatty()): + if (__debug__ and sys.stderr.isatty()): # Log the error but don't re-raise as this is cleanup code - print(f"Error during process cleanup: {e}", file=sys.stderr) + warnings.warn( + f"Error during process cleanup: {e}", stacklevel=2 + ) class BasicUsageTestSuite(unittest.TestCase): diff --git a/tests/run_selective.py b/tests/run_selective.py index 35acfbf7..8237f812 100755 --- a/tests/run_selective.py +++ b/tests/run_selective.py @@ -33,6 +33,11 @@ import sys import argparse import unittest +import logging + +if __debug__ and __name__ == "__main__": + logging.getLogger(__module__).debug(f"Bootstrapping {__file__}") + from tests import get_test_suite from tests import TEST_GROUPS @@ -57,18 +62,18 @@ def main() -> None: args = parser.parse_args() try: _bar = str("-" * 20) - if (sys.stdout.isatty()): - print(f"{_bar}START{_bar}", file=sys.stdout) + logger = logging.getLogger(__module__) + logger.info(f"{_bar}GROUP{_bar}") + logger.info(f"{args.group}:{args.category}") + logger.info(f"{_bar}START{_bar}") suite = get_test_suite(args.group, args.category) runner = unittest.TextTestRunner(verbosity=2) result = runner.run(suite) - if (sys.stdout.isatty()): - print(f"{_bar} END {_bar}", file=sys.stdout) + logger.info(f"{_bar} END {_bar}") del _bar # skipcq - cleanup any object leaks early sys.exit(not result.wasSuccessful()) except ValueError as e: - if (sys.stderr.isatty()): - print(f"Error: {e}", file=sys.stderr) + logger.exception(f"Error: {e}") sys.exit(1) From f068db287ba4dfa07c1b01284b8b63777da2f744 Mon Sep 17 00:00:00 2001 From: "Mr. Walls" Date: Tue, 8 Apr 2025 20:05:24 -0700 Subject: [PATCH 02/12] [FEATURE] More implementation of logging style output and related work (- WIP #233 -) Changes in file Makefile: * related work (WIP) Changes in file setup.py: * Added some more debugging signposts (eg warnings) as part of #233 Changes in file tests/check_integration_coverage: * Related work (also WIP) --- Makefile | 17 ++++++++++++++--- setup.py | 5 ++++- tests/check_integration_coverage | 10 ++++++++-- 3 files changed, 26 insertions(+), 6 deletions(-) diff --git a/Makefile b/Makefile index f47b4345..e06781ea 100644 --- a/Makefile +++ b/Makefile @@ -214,6 +214,9 @@ legacy-purge: clean uninstall purge: legacy-purge $(QUIET)$(RM) ./test-reports/*.xml 2>$(ERROR_LOG_PATH) || : + $(QUIET)$(RM) ./coverage_* 2>$(ERROR_LOG_PATH) || : + $(QUIET)$(RM) ./.coverage.* 2>$(ERROR_LOG_PATH) || : + $(QUIET)$(RM) ./coverage_doctests.xml 2>$(ERROR_LOG_PATH) || : $(QUIET)$(RMDIR) ./test-reports/ 2>$(ERROR_LOG_PATH) || : $(QUIET)$(ECHO) "$@: Done." @@ -223,6 +226,12 @@ test: just-test $(QUIET)$(COVERAGE) report -m --include=* 2>$(ERROR_LOG_PATH) || : ; $(QUIET)$(ECHO) "$@: Done." +test-mod: test-mat + $(QUIET)$(DO_FAIL) ; + $(QUIET)$(COVERAGE) combine 2>$(ERROR_LOG_PATH) || : ; + $(QUIET)$(COVERAGE) report -m --include=* 2>$(ERROR_LOG_PATH) || : ; + $(QUIET)$(ECHO) "$@: Done." + test-tox: build $(QUIET)tox -v -- || tail -n 500 .tox/py*/log/py*.log 2>$(ERROR_LOG_PATH) $(QUIET)$(COVERAGE) combine 2>$(ERROR_LOG_PATH) || : ; @@ -253,7 +262,7 @@ just-test: cleanup MANIFEST.in ## Run all minimum acceptance tests $(QUIET)$(WAIT) ; $(QUIET)$(DO_FAIL) ; -test-mat: test-mat-build test-mat-bootstrap test-mat-basic test-mat-say test-mat-hear test-mat-usage test-mat-doctests ## Run all minimum acceptance tests +test-mat: cleanup MANIFEST.in test-mat-build test-mat-bootstrap test-mat-basic test-mat-say test-mat-hear test-mat-usage test-mat-doctests ## Run all minimum acceptance tests $(QUIET)$(WAIT) ; $(QUIET)$(DO_FAIL) ; @@ -263,8 +272,10 @@ test-mat-doctests: MANIFEST.in ## Run doctests MAT category (doctests are specia $(ECHO) "Try 'make test-mat-doctests' instead."; \ else \ $(COVERAGE) run -p --source=multicast -m tests.run_selective --group mat --category doctests || DO_FAIL="exit 2" ; \ - $(COVERAGE) combine 2>$(ERROR_LOG_PATH) || : ; \ - $(COVERAGE) xml --include=* 2>$(ERROR_LOG_PATH) || : ; \ + $(QUIET)$(WAIT) ; \ + $(COVERAGE) combine --keep --data-file=coverage_doctests ./.coverage.* 2>$(ERROR_LOG_PATH) || : ; \ + $(COVERAGE) report -m --include=* --data-file=coverage_doctests 2>$(ERROR_LOG_PATH) || : ; \ + $(COVERAGE) xml -o coverage_doctests.xml --include=* --data-file=coverage_doctests 2>$(ERROR_LOG_PATH) || : ; \ fi $(QUIET)$(WAIT) ; $(QUIET)$(DO_FAIL) ; diff --git a/setup.py b/setup.py index c2d725cc..8a82613d 100755 --- a/setup.py +++ b/setup.py @@ -154,7 +154,10 @@ def parse_requirements_for_install_requires(requirements_text): str("""Topic :: System :: Networking""") ] except Exception as e: - print(f"Warning: Error occurred while setting class_tags: {e}") + warnings.warn( + f"Warning: Error occurred while setting class_tags: {e}", + stacklevel=2, + ) class_tags = ["Development Status :: 5 - Production/Stable"] # finally the setup setup( diff --git a/tests/check_integration_coverage b/tests/check_integration_coverage index 127695bc..735fafd7 100755 --- a/tests/check_integration_coverage +++ b/tests/check_integration_coverage @@ -184,9 +184,15 @@ printf "%s\n\n" "End of Integration Test daemon" >> ./"${LOG_FILE}" ; wait ; # cleanup from test-suite -$(command -v python3) -m coverage combine 2>/dev/null || EXIT_CODE=2 ; -$(command -v python3) -m coverage xml --include=multicast/* -o ./test-reports/coverage_supplement.xml || EXIT_CODE=2 ; +COVERAGE_DATE_FILE="./coverage_integration" +$(command -v python3) -m coverage combine --data-file="${COVERAGE_DATE_FILE}" 2>/dev/null || EXIT_CODE=2 ; +if [[ -r "${COVERAGE_DATE_FILE}" ]] ; then + $(command -v python3) -m coverage report -m --data-file="${COVERAGE_DATE_FILE}" 2>/dev/null || EXIT_CODE=2 ; + $(command -v python3) -m coverage xml -o ./test-reports/coverage_supplement.xml --include=multicast/* --data-file="${COVERAGE_DATE_FILE}" || EXIT_CODE=2 ; +else + printf "%s\n" "Coverage collection FAILED!" 2>/dev/null || EXIT_CODE=2 ; +fi ; wait ; cp -f ./"${LOG_FILE}" ./test-reports/integration_data_log.log 2>/dev/null ; wait ; printf "%s\n" "" | tee -a ./test-reports/integration_data_log.log ; wait ; From a9777febeff8ae80e4474f212270550106a04a13 Mon Sep 17 00:00:00 2001 From: "Mr. Walls" Date: Wed, 9 Apr 2025 12:05:45 -0700 Subject: [PATCH 03/12] [STYLE] Refactored to avoid PYL-C0201 (- WIP #233 -) Changes in file tests/__init__.py: * avoid conditional with check of `keys()` to correct PYL-C0201 --- tests/__init__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/__init__.py b/tests/__init__.py index 262c5ac5..1547db17 100644 --- a/tests/__init__.py +++ b/tests/__init__.py @@ -102,7 +102,7 @@ def emit(self, record): # Validate the log level if not isinstance(loglevel, str): raise ValueError("Invalid log level") - if loglevel not in logging_color.keys(): + if loglevel not in logging_color: raise ValueError("Invalid log level") # Determine color based on whether the output is a terminal if sys.stdout.isatty(): From f2878d01f05aba65bb6d15042ca43cb6e14d6352 Mon Sep 17 00:00:00 2001 From: "Mr. Walls" Date: Wed, 9 Apr 2025 12:56:36 -0700 Subject: [PATCH 04/12] [STYLE] Refactored to use lazy formatting to avoid PYL-W1203 * Most of the changes were to simply swap-out f-strings for '%s' lazy style formatting * These changes are to appease the strict linter of app.deepsource.io Changes in file multicast/__init__.py: * refactored to lazy formatting to avoid PYL-W1203 Changes in file multicast/env.py: * refactored to lazy formatting to avoid PYL-W1203 Changes in file multicast/exceptions.py: * refactored to lazy formatting to avoid PYL-W1203 Changes in file multicast/hear.py: * refactored to lazy formatting to avoid PYL-W1203 Changes in file multicast/recv.py: * refactored to lazy formatting to avoid PYL-W1203 Changes in file multicast/send.py: * refactored to lazy formatting to avoid PYL-W1203 Changes in file multicast/skt.py: * refactored to lazy formatting to avoid PYL-W1203 Changes in file tests/run_selective.py: * refactored to lazy formatting to avoid PYL-W1203 --- multicast/__init__.py | 20 ++++++++++++++++---- multicast/env.py | 30 ++++++++++++++++++++++++------ multicast/exceptions.py | 15 ++++++++++++--- multicast/hear.py | 25 ++++++++++++++++++++----- multicast/recv.py | 12 +++++++++--- multicast/send.py | 37 +++++++++++++++++++++++++++++-------- multicast/skt.py | 5 ++++- tests/run_selective.py | 5 ++++- 8 files changed, 118 insertions(+), 31 deletions(-) diff --git a/multicast/__init__.py b/multicast/__init__.py index c49a5923..8ae9edd1 100644 --- a/multicast/__init__.py +++ b/multicast/__init__.py @@ -407,7 +407,10 @@ if logging.__name__ is not None: # pragma: no branch logging.getLogger(__module__).addHandler(logging.NullHandler()) - logging.getLogger(__module__).debug(f"Loading {__module__}") + logging.getLogger(__module__).debug( + "Loading %s", # lazy formatting to avoid PYL-W1203 + __module__, + ) if sys.__name__ is None: raise ModuleNotFoundError( @@ -423,7 +426,10 @@ if socket.__name__ is None: raise ModuleNotFoundError("FAIL: we could not import socket. ABORT.") from None else: # pragma: no branch - logging.getLogger(__module__).debug(f"Setting default packet timeout to {_MCAST_DEFAULT_TTL}") + logging.getLogger(__module__).debug( + "Setting default packet timeout to %n", # lazy formatting to avoid PYL-W1203 + _MCAST_DEFAULT_TTL, + ) socket.setdefaulttimeout(int(_MCAST_DEFAULT_TTL)) if struct.__name__ is None: @@ -479,7 +485,10 @@ logging.getLogger(__module__).info("Overrides and defaults are configured.") logging.getLogger(__module__).debug("Defaults:") for key, value in _config.items(): - logging.getLogger(__module__).debug(f"\t{key}={str(value)}") + logging.getLogger(__module__).debug( + "\t%s=%s", # lazy formatting to avoid PYL-W1203 + key, value, + ) del _config # skipcq - cleanup any bootstrap/setup leaks early @@ -555,7 +564,10 @@ def buildArgs(cls, calling_parser_group): """ if calling_parser_group is None: # pragma: no branch - logging.getLogger(__module__).debug(f"Building {__name__} arguments.") + logging.getLogger(__module__).debug( + "Building %s arguments.", # lazy formatting to avoid PYL-W1203 + __name__, + ) calling_parser_group = argparse.ArgumentParser( prog=str(cls.__name__ if cls.__proc__ is None else cls.__proc__), description=cls.__prologue__, diff --git a/multicast/env.py b/multicast/env.py index 7e99c1e8..088e45bd 100644 --- a/multicast/env.py +++ b/multicast/env.py @@ -100,8 +100,14 @@ module_logger = logging.getLogger(__module__) -module_logger.debug(f"loading {__module__}") -module_logger.debug(f"Initializing {__package__} environment.") +module_logger.debug( + "Loading %s", # lazy formatting to avoid PYL-W1203 + __module__, +) +module_logger.debug( + "Initializing %s environment.", # lazy formatting to avoid PYL-W1203 + __package__, +) def validate_buffer_size(size: int) -> bool: @@ -364,7 +370,10 @@ def load_buffer_size() -> int: stacklevel=2 ) buffer_size = _MCAST_DEFAULT_BUFFER_SIZE - module_logger.debug(f"Loaded {buffer_size} as internal multicast buffer size.") + module_logger.debug( + "Loaded %s as internal multicast buffer size.", # lazy formatting to avoid PYL-W1203 + str(buffer_size), + ) return buffer_size @@ -466,7 +475,10 @@ def load_port() -> int: stacklevel=2 ) port = _MCAST_DEFAULT_PORT - module_logger.debug(f"Loaded {port} as default multicast port.") + module_logger.debug( + "Loaded %s as default multicast port.", # lazy formatting to avoid PYL-W1203 + str(port), + ) return port @@ -583,7 +595,10 @@ def load_group() -> ipaddress.IPv4Address: f"Invalid multicast group {group}, using default {_MCAST_DEFAULT_GROUP}", stacklevel=2 ) group = _MCAST_DEFAULT_GROUP - module_logger.debug(f"Loaded {group} as default multicast group.") + module_logger.debug( + "Loaded %s as default multicast group.", # lazy formatting to avoid PYL-W1203 + group, + ) return ipaddress.IPv4Address(group) @@ -678,7 +693,10 @@ def load_TTL() -> int: stacklevel=2 ) ttl = _MCAST_DEFAULT_TTL - module_logger.debug(f"Loaded {ttl} as default multicast time-to-live.") + module_logger.debug( + "Loaded %d as default multicast time-to-live.", # lazy formatting to avoid PYL-W1203 + ttl, + ) # Update socket default timeout module_logger.debug("Update socket default timeout.") socket.setdefaulttimeout(int(ttl)) diff --git a/multicast/exceptions.py b/multicast/exceptions.py index cc6e3971..7c33ae49 100644 --- a/multicast/exceptions.py +++ b/multicast/exceptions.py @@ -205,8 +205,14 @@ module_logger = logging.getLogger(__module__) -module_logger.debug(f"loading {__module__}") -module_logger.debug(f"Initializing {__package__} exceptions.") +module_logger.debug( + "Loading %s", # lazy formatting to avoid PYL-W1203 + __module__, +) +module_logger.debug( + "Initializing %s exceptions.", # lazy formatting to avoid PYL-W1203 + __package__, +) class CommandExecutionError(RuntimeError): @@ -769,7 +775,10 @@ def wrapper(*args, **kwargs): return wrapper -module_logger.debug(f"loaded {__module__}") +module_logger.debug( + "Loaded %s", # lazy formatting to avoid PYL-W1203 + __module__, +) # skipcq diff --git a/multicast/hear.py b/multicast/hear.py index 5daac192..b75c9bb7 100644 --- a/multicast/hear.py +++ b/multicast/hear.py @@ -218,7 +218,10 @@ module_logger = logging.getLogger(__name__) -module_logger.debug(f"loading {__name__}") +module_logger.debug( + "Loading %s", # lazy formatting to avoid PYL-W1203 + __name__, +) class McastServer(socketserver.UDPServer): @@ -619,7 +622,10 @@ def doStep(self, *args, **kwargs): server_initialized = False server = None try: - _logger.debug(f"Initializing server on port {PORT} as {HOST}.") + _logger.debug( + "Initializing server on port %d as %s.", # lazy formatting to avoid PYL-W1203 + PORT, HOST, + ) with McastServer((HOST, PORT), HearUDPHandler) as server: server_initialized = True server.serve_forever() @@ -633,7 +639,10 @@ def doStep(self, *args, **kwargs): f"HEAR has stopped due to interruption signal (was previously listening on ({HOST}, {PORT}))." ) from userInterrupt finally: - _logger.debug(f"Finalizing server with port {PORT} from {HOST}.") + _logger.debug( + "Finalizing server with port %d from %s.", # lazy formatting to avoid PYL-W1203 + PORT, HOST, + ) if server: # pragma: no cover # deadlocks if not called by other thread end_it = threading.Thread(name="Kill_Thread", target=server.shutdown, args=[]) @@ -641,7 +650,13 @@ def doStep(self, *args, **kwargs): end_it.join(1) if __debug__: if server_initialized: - module_logger.debug(f"HEAR result was {server_initialized}. Reporting success.") + module_logger.debug( + "HEAR result was %s. Reporting success.", # lazy formatting to avoid PYL-W1203 + server_initialized, + ) else: - module_logger.debug(f"HEAR result was {server_initialized}. Reporting failure.") + module_logger.debug( + "HEAR result was %s. Reporting failure.", # lazy formatting to avoid PYL-W1203 + server_initialized, + ) return (server_initialized, None) diff --git a/multicast/recv.py b/multicast/recv.py index 76e3f884..462b85f2 100644 --- a/multicast/recv.py +++ b/multicast/recv.py @@ -205,7 +205,10 @@ module_logger = logging.getLogger(__name__) -module_logger.debug(f"loading {__name__}") +module_logger.debug( + "Loading %s", # lazy formatting to avoid PYL-W1203 + __name__, +) def joinstep(groups, port, iface=None, bind_group=None, isock=None): @@ -544,9 +547,12 @@ def _hearstep(groups, port, iface=None, bind_group=None): """ - module_logger.debug(f"Joining {str(groups)} on port {port} using {iface} as {bind_group}") + module_logger.debug( + "Joining %s on port %d using %s as %s", # lazy formatting to avoid PYL-W1203 + str(groups), port, str(iface), bind_group, + ) sock = joinstep(groups, port, iface, bind_group, None) - module_logger.debug(f"Opened {sock}") + module_logger.debug("Opened %s", sock) # lazy formatting to avoid PYL-W1203 msgbuffer = str(multicast._BLANK) # skipcq: PYL-W0212 - module ok chunk = None module_logger.debug("Ready.") diff --git a/multicast/send.py b/multicast/send.py index 7c479da5..9e48f787 100644 --- a/multicast/send.py +++ b/multicast/send.py @@ -165,7 +165,10 @@ module_logger = logging.getLogger(__name__) -module_logger.debug(f"loading {__name__}") +module_logger.debug( + "Loading %s", # lazy formatting to avoid PYL-W1203 + __name__, +) class McastSAY(multicast.mtool): @@ -282,7 +285,10 @@ def setupArgs(cls, parser): """ if parser is not None: # pragma: no branch if __debug__: - module_logger.debug(f"Adding {__name__} arguments.") + module_logger.debug( + "Adding %s arguments.", # lazy formatting to avoid PYL-W1203 + __name__, + ) parser.add_argument( "--port", type=int, @@ -331,10 +337,19 @@ def _sayStep(group, port, data): if __debug__ and module_logger.isEnabledFor(logging.DEBUG): # pragma: no branch module_logger.debug("Encoding.") _payload = data.encode('utf8') - module_logger.debug(f"Encoded {len(_payload)}.") - module_logger.debug(f"Sending {_payload} to ({group}, {port}).") + module_logger.debug( + "Encoded %d.", # lazy formatting to avoid PYL-W1203 + len(_payload), + ) + module_logger.debug( + "Sending %s to (%s, %d).", # lazy formatting to avoid PYL-W1203 + _payload, group, port, + ) sock.sendto(data.encode('utf8'), (group, port)) - module_logger.debug(f"Sent {len(_payload)}.") + module_logger.debug( + "Sent %d.", # lazy formatting to avoid PYL-W1203 + len(_payload), + ) else: sock.sendto(data.encode('utf8'), (group, port)) _success = True @@ -400,7 +415,13 @@ def doStep(self, *args, **kwargs): _result = self._sayStep(group, port, message) if __debug__: # pragma: no branch if _result: - module_logger.debug(f"SEND result was {_result}. Reporting success.") - else: # pragma: no branch - module_logger.debug(f"SEND result was {_result}. Reporting failure.") + module_logger.debug( + "SEND result was %s. Reporting success.", # lazy formatting to avoid PYL-W1203 + _result, + ) + else: + module_logger.debug( + "SEND result was %s. Reporting failure.", # lazy formatting to avoid PYL-W1203 + _result, + ) return (_result, None) # skipcq: PTC-W0020 - intended diff --git a/multicast/skt.py b/multicast/skt.py index cb6513fc..4a0ca766 100644 --- a/multicast/skt.py +++ b/multicast/skt.py @@ -150,7 +150,10 @@ module_logger = logging.getLogger(__module__) -module_logger.debug(f"loading {__module__}") +module_logger.debug( + "Loading %s", # lazy formatting to avoid PYL-W1203 + __module__, +) def genSocket() -> _socket.socket: diff --git a/tests/run_selective.py b/tests/run_selective.py index 8237f812..a13f836b 100755 --- a/tests/run_selective.py +++ b/tests/run_selective.py @@ -36,7 +36,10 @@ import logging if __debug__ and __name__ == "__main__": - logging.getLogger(__module__).debug(f"Bootstrapping {__file__}") + logging.getLogger(__module__).debug( + "Bootstrapping %s", # lazy formatting to avoid PYL-W1203 + __file__, + ) from tests import get_test_suite from tests import TEST_GROUPS From e333f56daeb064f6334720146c473f05549156ac Mon Sep 17 00:00:00 2001 From: "Mr. Walls" Date: Wed, 9 Apr 2025 15:09:09 -0700 Subject: [PATCH 05/12] [STYLE] More work related to refactoring to use lazy formatting to avoid PLY-1203 Changes in file multicast/hear.py: * follow-up for logger.info formatting Changes in file multicast/send.py: * follow-up for logger.info formatting Changes in file tests/run_selective.py: * related work for supressing linter in test-code --- multicast/hear.py | 10 ++++++++-- multicast/send.py | 5 ++++- tests/run_selective.py | 8 ++++---- 3 files changed, 16 insertions(+), 7 deletions(-) diff --git a/multicast/hear.py b/multicast/hear.py index b75c9bb7..0a411684 100644 --- a/multicast/hear.py +++ b/multicast/hear.py @@ -345,7 +345,10 @@ def server_bind(self): super(McastServer, self).server_bind() self._sync_logger() # enter critical section - self.logger.info(f"bound on: {str(self.socket.getsockname())}") + self.logger.info( + "bound on: %s", # lazy formatting to avoid PYL-W1203 + str(self.socket.getsockname()), + ) # exit critical section def close_request(self, request): @@ -521,7 +524,10 @@ def handle(self): return # silently ignore invalid UTF-8 data -- fail quickly. _logger = logging.getLogger(self.__name__) if __debug__: - _logger.info(f"{self.client_address[0]} SAYS: {data.strip()} to ALL") + _logger.info( + "%s SAYS: %s to ALL", # lazy formatting to avoid PYL-W1203 + str(self.client_address[0]), data.strip(), + ) if data is not None: me = str(sock.getsockname()[0]) if __debug__: # pragma: no cover diff --git a/multicast/send.py b/multicast/send.py index 9e48f787..9079fe66 100644 --- a/multicast/send.py +++ b/multicast/send.py @@ -332,7 +332,10 @@ def _sayStep(group, port, data): _success = False sock = multicast.genSocket() if __debug__: - module_logger.info(f"Preparing to send {len(data)}") + module_logger.info( + "Preparing to send %d", # lazy formatting to avoid PYL-W1203 + len(data), + ) try: if __debug__ and module_logger.isEnabledFor(logging.DEBUG): # pragma: no branch module_logger.debug("Encoding.") diff --git a/tests/run_selective.py b/tests/run_selective.py index a13f836b..ecbcaa78 100755 --- a/tests/run_selective.py +++ b/tests/run_selective.py @@ -66,13 +66,13 @@ def main() -> None: try: _bar = str("-" * 20) logger = logging.getLogger(__module__) - logger.info(f"{_bar}GROUP{_bar}") - logger.info(f"{args.group}:{args.category}") - logger.info(f"{_bar}START{_bar}") + logger.info(f"{_bar}GROUP{_bar}") # skipcq PYL-W1203 - test code ok + logger.info(f"{args.group}:{args.category}") # skipcq PYL-W1203 - test code ok + logger.info(f"{_bar}START{_bar}") # skipcq PYL-W1203 - test code ok suite = get_test_suite(args.group, args.category) runner = unittest.TextTestRunner(verbosity=2) result = runner.run(suite) - logger.info(f"{_bar} END {_bar}") + logger.info(f"{_bar} END {_bar}") # skipcq PYL-W1203 - test code ok del _bar # skipcq - cleanup any object leaks early sys.exit(not result.wasSuccessful()) except ValueError as e: From 56468ce2f0ef05cbf105bb146993d470143b3c4c Mon Sep 17 00:00:00 2001 From: "Mr. Walls" Date: Wed, 9 Apr 2025 16:46:15 -0700 Subject: [PATCH 06/12] [DOCUMENTATION] Added initial docstring and corrected method def as found in review (- WIP PR #354 -) * this is related work to implementing #233 Changes in file multicast/hear.py: * added some more docs for class McastServer(socketserver.UDPServer) --- multicast/hear.py | 58 ++++++++++++++++++++++++++++++++++++++++------- 1 file changed, 50 insertions(+), 8 deletions(-) diff --git a/multicast/hear.py b/multicast/hear.py index 0a411684..56803055 100644 --- a/multicast/hear.py +++ b/multicast/hear.py @@ -272,13 +272,53 @@ class McastServer(socketserver.UDPServer): """ - def __init__(self, *args, **kwargs) -> None: - (logger_name, _) = kwargs.get("server_address", (None, None)) + def __init__(self, server_address, RequestHandlerClass, bind_and_activate=True) -> None: + """ + Initialize a new instance of the McastServer. + + Creates a new UDP server for multicast communication and sets up an appropriate logger + based on the server address provided. May be extended, do not override. + + Returns: + None + + Minimal Acceptance Testing: + + First set up test fixtures by importing multicast. + + Testcase 0: Basic initialization of McastServer. + A: Test that McastServer can be initialized with minimal arguments. + B: Test that the resulting instance is of the correct type. + + >>> import multicast + >>> from multicast.hear import McastServer + >>> server = McastServer(('224.0.0.1', 12345), None) + >>> isinstance(server, McastServer) + True + >>> isinstance(server, multicast.hear.socketserver.UDPServer) + True + >>> + + Testcase 1: Server initialization with logger name extraction. + A: Test that the server extracts the logger name from server_address. + B: Test that the logger is properly initialized. + + >>> from multicast.hear import McastServer + >>> test_addr = ('227.0.0.1', 23456) + >>> server = McastServer(test_addr, None) + >>> server.logger is not None + True + >>> server.logger.name.endswith('227.0.0.1') + True + >>> + + """ + logger_name = server_address[0] if server_address and len(server_address) > 0 else None if logger_name: # pragma: no branch self.__logger = logging.getLogger(f"{McastServer.__name__}.{logger_name}") else: self.__logger = logging.getLogger(f"{McastServer.__name__}") - super().__init__(*args, **kwargs) + super().__init__(server_address, RequestHandlerClass, bind_and_activate) def _sync_logger(self) -> None: """Internal function to sync logger with bound socket address.""" @@ -525,18 +565,20 @@ def handle(self): _logger = logging.getLogger(self.__name__) if __debug__: _logger.info( - "%s SAYS: %s to ALL", # lazy formatting to avoid PYL-W1203 - str(self.client_address[0]), data.strip(), - ) + "%s SAYS: %s to ALL", # lazy formatting to avoid PYL-W1203 + str(self.client_address[0]), data.strip(), + ) if data is not None: me = str(sock.getsockname()[0]) if __debug__: # pragma: no cover _what = data.strip().replace("""\r""", str()).replace("""%""", """%%""") _logger.info( - f"{me} HEAR: [{self.client_address} SAID {str(_what)}]" + "%s HEAR: [%s SAID %s]", # lazy formatting to avoid PYL-W1203 + str(me), str(self.client_address), str(_what), ) _logger.info( - f"{me} SAYS [ HEAR [ {str(_what)} SAID {self.client_address} ] from {me} ]" # noqa + "%s SAYS [ HEAR [ {%s SAID %s ] from %s ]", # lazy formatting to avoid PYL-W1203 + str(me), str(_what), str(self.client_address), str(me), ) send.McastSAY()._sayStep( # skipcq: PYL-W0212 - module ok self.client_address[0], self.client_address[1], From 979d5fb43355a33f16edf8f2bbc4c2cb4781c5a7 Mon Sep 17 00:00:00 2001 From: "Mr. Walls" Date: Wed, 9 Apr 2025 19:53:15 -0700 Subject: [PATCH 07/12] [DOCUMENTATION] Applied improvements found in review (- WIP PR #354 -) * This work is related to implementing #233 Changes in file multicast/hear.py: class McastServer(socketserver.UDPServer): * improved logging name logic * added docstrings from review --- multicast/hear.py | 185 +++++++++++++++++++++++++++++++++++++++++----- 1 file changed, 167 insertions(+), 18 deletions(-) diff --git a/multicast/hear.py b/multicast/hear.py index 56803055..44bf1233 100644 --- a/multicast/hear.py +++ b/multicast/hear.py @@ -252,10 +252,12 @@ class McastServer(socketserver.UDPServer): """ - __name__ = """multicast.hear.McastServer""" # skipcq: PYL-W0622 - """Names this server + __log_handle__ = """multicast.hear.McastServer""" # skipcq: PYL-W0622 + """Names this server's Logger. - Minimal Acceptance Testing: + Basically just the prefix of the logger's name. Subclasses should override. + + Minimal Acceptance Testing: First set up test fixtures by importing multicast. @@ -268,6 +270,8 @@ class McastServer(socketserver.UDPServer): >>> multicast.hear.McastServer.__name__ is not None True + >>> multicast.hear.McastServer.__log_handle__ is not None + True >>> """ @@ -286,51 +290,196 @@ def __init__(self, server_address, RequestHandlerClass, bind_and_activate=True) First set up test fixtures by importing multicast. + Testcase 0: Multicast should be importable. + + >>> import socketserver + >>> import multicast + >>> + Testcase 0: Basic initialization of McastServer. A: Test that McastServer can be initialized with minimal arguments. B: Test that the resulting instance is of the correct type. - >>> import multicast - >>> from multicast.hear import McastServer - >>> server = McastServer(('224.0.0.1', 12345), None) - >>> isinstance(server, McastServer) + >>> server = multicast.hear.McastServer(('224.0.0.1', 12345), None) + >>> isinstance(server, multicast.hear.McastServer) True - >>> isinstance(server, multicast.hear.socketserver.UDPServer) + >>> isinstance(server, socketserver.UDPServer) True + >>> server.server_close() # Clean up >>> Testcase 1: Server initialization with logger name extraction. A: Test that the server extracts the logger name from server_address. B: Test that the logger is properly initialized. - >>> from multicast.hear import McastServer - >>> test_addr = ('227.0.0.1', 23456) - >>> server = McastServer(test_addr, None) + >>> test_addr = ('239.0.0.9', 23456) + >>> server = multicast.hear.McastServer(test_addr, None) >>> server.logger is not None True - >>> server.logger.name.endswith('227.0.0.1') + >>> server.logger.name.endswith('239.0.0.9') True + >>> server.server_close() # Clean up >>> """ logger_name = server_address[0] if server_address and len(server_address) > 0 else None if logger_name: # pragma: no branch - self.__logger = logging.getLogger(f"{McastServer.__name__}.{logger_name}") + self.__logger = logging.getLogger(f"{self.__log_handle__}.{logger_name}") else: - self.__logger = logging.getLogger(f"{McastServer.__name__}") + self.__logger = logging.getLogger(f"{self.__log_handle__}") super().__init__(server_address, RequestHandlerClass, bind_and_activate) def _sync_logger(self) -> None: - """Internal function to sync logger with bound socket address.""" + """Synchronize the logger instance with the bound socket address. + + This internal method updates the instance's logger attribute based on the current + socket address. It extracts the address component from the socket's bound address + and uses it to create a hierarchical logger name in the format + 'multicast.hear.McastServer.[address]'. + + If no valid address is found, it falls back to the base McastServer logger. + This method is typically called after server_bind() to ensure the logger + reflects the actual bound socket address. + + Note: + This is an internal method and should not be called directly from outside + the class. + + Args: + None + + Returns: + None + + Minimal Acceptance Testing: + + First set up test fixtures by importing multicast. + + Testcase 0: Multicast should be importable. + + >>> import types + >>> import logging + >>> import multicast + >>> + + Testcase 1: Method exists and takes expected arguments. + A: Test method exists in McastServer class. + B: Test method signature does not accept arguments. + + >>> from multicast.hear import McastServer + >>> hasattr(McastServer, '_sync_logger') + True + >>> import inspect + >>> len(inspect.signature(McastServer._sync_logger).parameters) - 1 # Remove 'self' + 0 + >>> + + Testcase 2: Method handles case where socket has a valid address. + A: Use a mock socket with a valid address. + B: Verify logger name is properly formatted. + + >>> # Setup a server instance with mock socket + >>> server = multicast.hear.McastServer(('239.0.0.9', 51234), None) + >>> # Create mock socket with valid address + >>> mock_socket = types.SimpleNamespace() + >>> mock_socket.getsockname = lambda: ('239.0.0.9', 51234) + >>> server.socket = mock_socket + >>> # Call method and verify logger name + >>> server._sync_logger() + >>> server.logger.name + 'multicast.hear.McastServer.239.0.0.9' + >>> + + Testcase 3: Method handles case where socket address name component is None. + A: Use a mock socket with None as the address component. + B: Verify logger falls back to base logger name. + + >>> # Setup a server instance + >>> server = multicast.hear.McastServer(('239.0.0.9', 51234), None) + >>> # Create mock socket with None as the address + >>> mock_socket = types.SimpleNamespace() + >>> mock_socket.getsockname = lambda: (None, 5678) + >>> server.socket = mock_socket + >>> # Call method and verify logger name + >>> server._sync_logger() + >>> server.logger.name + 'multicast.hear.McastServer' + >>> + + Testcase 4: Method handles case where socket address has special formatting. + A: Use a mock socket with an IPv6 address. + B: Verify logger name incorporates the address correctly. + + >>> import multicast + >>> from multicast.hear import McastServer + >>> import types + >>> import logging + >>> # Setup a server instance + >>> server = McastServer(('239.0.0.9', 51234), None) + >>> # Create mock socket with IPv6 address format + >>> mock_socket = types.SimpleNamespace() + >>> mock_socket.getsockname = lambda: ('2001:db8::1', 5678) + >>> server.socket = mock_socket + >>> # Call method and verify logger name + >>> server._sync_logger() + >>> server.logger.name + 'multicast.hear.McastServer.2001:db8::1' + >>> + """ (logger_name, _) = self.socket.getsockname() if logger_name: - self.__logger = logging.getLogger(f"{McastServer.__name__}.{logger_name}") + self.__logger = logging.getLogger(f"{self.__log_handle__}.{logger_name}") else: # pragma: no branch - self.__logger = logging.getLogger(f"{McastServer.__name__}") + self.__logger = logging.getLogger(f"{self.__log_handle__}") @property def logger(self) -> logging.Logger: - """Getter for the logger attribute.""" + """Getter for the logger attribute of McastServer. + + This property provides access to the server's internal logger instance. The logger name + is determined during initialization and may be updated by calling _sync_logger when the + server's socket address changes. + + Returns: + logging.Logger -- The logger instance associated with this server. + + Minimal Acceptance Testing: + + First set up test fixtures by importing multicast. + + >>> import multicast + >>> import logging + >>> + + Testcase 0: Verify logger accessibility. + A: Test that the logger property exists. + B: Test that it's accessible from an McastServer instance. + + >>> server = multicast.hear.McastServer(("239.0.0.9", 0), multicast.hear.HearUDPHandler) + >>> hasattr(server, 'logger') + True + >>> server.server_close() # Clean up + >>> + + Testcase 1: Verify logger type. + A: Test that the logger property returns a logging.Logger instance. + + >>> server = multicast.hear.McastServer(("239.0.0.9", 0), multicast.hear.HearUDPHandler) + >>> isinstance(server.logger, logging.Logger) + True + >>> server.server_close() # Clean up + >>> + + Testcase 2: Verify logger name. + A: Test that the logger name includes the server class name. + B: Test that it's properly formatted. + + >>> server = multicast.hear.McastServer(("239.0.0.9", 0), multicast.hear.HearUDPHandler) + >>> server.logger.name.startswith('multicast.hear.McastServer') + True + >>> server.server_close() # Clean up + >>> + """ return self.__logger def server_activate(self): From fd193f5e322b99e5cb4a7a2ac5bc4bb68daa460b Mon Sep 17 00:00:00 2001 From: "Mr. Walls" Date: Wed, 9 Apr 2025 19:58:47 -0700 Subject: [PATCH 08/12] [HOTFIX] Fix for regression found in review (- WIP PR #354 -) * This should fix GHA makefile linting. Changes in file Makefile: * refactored to pass linting by breaking up too-large 'purge' rule. --- Makefile | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/Makefile b/Makefile index e06781ea..6e61c428 100644 --- a/Makefile +++ b/Makefile @@ -212,12 +212,17 @@ legacy-purge: clean uninstall $(QUIET)$(RMDIR) ./dist/ 2>$(ERROR_LOG_PATH) || : $(QUIET)$(RMDIR) ./.eggs/ 2>$(ERROR_LOG_PATH) || : -purge: legacy-purge +purge-test-reports:: $(QUIET)$(RM) ./test-reports/*.xml 2>$(ERROR_LOG_PATH) || : + $(QUIET)$(RMDIR) ./test-reports/ 2>$(ERROR_LOG_PATH) || : + +purge-coverage-artifacts: legacy-purge $(QUIET)$(RM) ./coverage_* 2>$(ERROR_LOG_PATH) || : $(QUIET)$(RM) ./.coverage.* 2>$(ERROR_LOG_PATH) || : $(QUIET)$(RM) ./coverage_doctests.xml 2>$(ERROR_LOG_PATH) || : - $(QUIET)$(RMDIR) ./test-reports/ 2>$(ERROR_LOG_PATH) || : + +purge: purge-coverage-artifacts purge-test-reports + $(QUIET)$(WAIT) $(QUIET)$(ECHO) "$@: Done." test: just-test From b3a633abe944e8b19113131c2e680c1d749ebfe3 Mon Sep 17 00:00:00 2001 From: "Mr. Walls" Date: Fri, 11 Apr 2025 18:34:46 -0700 Subject: [PATCH 09/12] [PATCH] Apply suggestions from code review (- WIP #354 -) Co-authored-by: coderabbitai[bot] <136622811+coderabbitai[bot]@users.noreply.github.com> --- multicast/exceptions.py | 4 ++-- multicast/hear.py | 2 +- multicast/send.py | 2 +- tests/__init__.py | 2 +- tests/run_selective.py | 2 +- 5 files changed, 6 insertions(+), 6 deletions(-) diff --git a/multicast/exceptions.py b/multicast/exceptions.py index 7c33ae49..884776bf 100644 --- a/multicast/exceptions.py +++ b/multicast/exceptions.py @@ -523,10 +523,10 @@ def validate_exit_code(code) -> None: >>> success True """ - module_logger.info("Validating possible exit code.") + module_logger.debug("Validating possible exit code.") if not isinstance(code, int) or code < 0 or code > 255: raise ValueError(EXIT_CODE_RANGE_ERROR) - module_logger.info("Validated possible exit code.") + module_logger.debug("Validated possible exit code.") module_logger.debug("Initializing CEP-8 EXIT_CODES") diff --git a/multicast/hear.py b/multicast/hear.py index 44bf1233..f4a80e6c 100644 --- a/multicast/hear.py +++ b/multicast/hear.py @@ -276,7 +276,7 @@ class McastServer(socketserver.UDPServer): """ - def __init__(self, server_address, RequestHandlerClass, bind_and_activate=True) -> None: + def __init__(self, server_address: tuple, RequestHandlerClass: type, bind_and_activate: bool = True) -> None: """ Initialize a new instance of the McastServer. diff --git a/multicast/send.py b/multicast/send.py index 9079fe66..7f47b258 100644 --- a/multicast/send.py +++ b/multicast/send.py @@ -403,7 +403,7 @@ def doStep(self, *args, **kwargs): multicast._MCAST_DEFAULT_BUFFER_SIZE, # skipcq: PYL-W0212 - module ok ) except IOError as e: - _logger.exception(f"[CWE-228] Error reading from stdin: {e}") + _logger.exception("[CWE-228] Error reading from stdin.") break if not chunk: break diff --git a/tests/__init__.py b/tests/__init__.py index 1547db17..467391e4 100644 --- a/tests/__init__.py +++ b/tests/__init__.py @@ -184,7 +184,7 @@ def emit(self, record): from tests import test_fuzz depends.insert(10, test_fuzz) except Exception as e: # pragma: no branch - _LOGGER.exception(f"Error loading optional Fuzzing tests: {e}") + _LOGGER.exception("Error loading optional Fuzzing tests") for unit_test in depends: try: diff --git a/tests/run_selective.py b/tests/run_selective.py index ecbcaa78..0a61cac3 100755 --- a/tests/run_selective.py +++ b/tests/run_selective.py @@ -76,7 +76,7 @@ def main() -> None: del _bar # skipcq - cleanup any object leaks early sys.exit(not result.wasSuccessful()) except ValueError as e: - logger.exception(f"Error: {e}") + logger.exception("Error occurred") sys.exit(1) From 9e75b77abf6738d9d194e76c950b8de1faa2ef33 Mon Sep 17 00:00:00 2001 From: "Mr. Walls" Date: Fri, 11 Apr 2025 19:54:55 -0700 Subject: [PATCH 10/12] [PATCH] Apply fixes as found in review (- WIP PR #354 -) --- multicast/hear.py | 13 ++++++++----- multicast/send.py | 2 +- tests/__init__.py | 20 ++++++++++++++------ tests/run_selective.py | 2 +- 4 files changed, 24 insertions(+), 13 deletions(-) diff --git a/multicast/hear.py b/multicast/hear.py index f4a80e6c..3c32ff00 100644 --- a/multicast/hear.py +++ b/multicast/hear.py @@ -276,7 +276,9 @@ class McastServer(socketserver.UDPServer): """ - def __init__(self, server_address: tuple, RequestHandlerClass: type, bind_and_activate: bool = True) -> None: + def __init__( + self, server_address: tuple, RequestHandlerClass: type, bind_and_activate: bool = True + ) -> None: """ Initialize a new instance of the McastServer. @@ -707,11 +709,12 @@ def handle(self): data = data.decode('utf8') if isinstance(data, bytes) else str(data) except UnicodeDecodeError: # pragma: no cover if __debug__: - logging.getLogger(self.__name__).debug( - f"Received invalid UTF-8 data from {self.client_address[0]}" + module_logger.debug( + "Received invalid UTF-8 data from %s", # lazy formatting to avoid PYL-W1203 + self.client_address[0], ) return # silently ignore invalid UTF-8 data -- fail quickly. - _logger = logging.getLogger(self.__name__) + _logger = logging.getLogger(f"{type(self).__module__}.{type(self).__qualname__}") if __debug__: _logger.info( "%s SAYS: %s to ALL", # lazy formatting to avoid PYL-W1203 @@ -812,7 +815,7 @@ def doStep(self, *args, **kwargs): Returns: tuple: A tuple containing a status indicator and an optional result message. """ - _logger = logging.getLogger(__name__) + _logger = logging.getLogger(f"{type(self).__module__}.{type(self).__qualname__}") _logger.debug(McastHEAR.__proc__) HOST = kwargs.get("group", multicast._MCAST_DEFAULT_GROUP) # skipcq: PYL-W0212 - module ok PORT = kwargs.get("port", multicast._MCAST_DEFAULT_PORT) # skipcq: PYL-W0212 - module ok diff --git a/multicast/send.py b/multicast/send.py index 7f47b258..8538de6e 100644 --- a/multicast/send.py +++ b/multicast/send.py @@ -402,7 +402,7 @@ def doStep(self, *args, **kwargs): chunk = sys.stdin.read( multicast._MCAST_DEFAULT_BUFFER_SIZE, # skipcq: PYL-W0212 - module ok ) - except IOError as e: + except IOError: _logger.exception("[CWE-228] Error reading from stdin.") break if not chunk: diff --git a/tests/__init__.py b/tests/__init__.py index 467391e4..3296ed1d 100644 --- a/tests/__init__.py +++ b/tests/__init__.py @@ -109,8 +109,8 @@ def emit(self, record): colorPrefix = logging_color[loglevel] endColor = ANSIColors.ENDC else: - colorPrefix = str() - endColor = str() + colorPrefix = "" + endColor = "" # Format the message msg = self.format(record) formatted_msg = f"{colorPrefix}{msg}{endColor}" @@ -183,7 +183,7 @@ def emit(self, record): try: from tests import test_fuzz depends.insert(10, test_fuzz) - except Exception as e: # pragma: no branch + except Exception: # pragma: no branch _LOGGER.exception("Error loading optional Fuzzing tests") for unit_test in depends: @@ -281,9 +281,17 @@ def loadDocstringsFromModule(module: types.ModuleType) -> TestSuite: doc_suite.addTests(doctest.DocTestSuite(module=module, test_finder=finder)) except ValueError as e: # ValueError is raised when no tests are found - _LOGGER.warning(f"No doctests found in {module.__name__}: {e}") - except Exception as e: - _LOGGER.error(f"Error loading doctests from {module.__name__}: {e}") + _LOGGER.warning( + "No doctests found in %s: %s", # lazy formatting to avoid PYL-W1203 + module.__name__, + e, # log as just warning level, instead of exception (error), but still detailed. + exec_info=True, + ) + except Exception: + _LOGGER.exception( + "Error loading doctests from %s", # lazy formatting to avoid PYL-W1203 + module.__name__, + ) return doc_suite diff --git a/tests/run_selective.py b/tests/run_selective.py index 0a61cac3..58679a23 100755 --- a/tests/run_selective.py +++ b/tests/run_selective.py @@ -75,7 +75,7 @@ def main() -> None: logger.info(f"{_bar} END {_bar}") # skipcq PYL-W1203 - test code ok del _bar # skipcq - cleanup any object leaks early sys.exit(not result.wasSuccessful()) - except ValueError as e: + except ValueError: logger.exception("Error occurred") sys.exit(1) From 475dda45ea0dfdfaee8e8f5ce7a14e01f2821ae2 Mon Sep 17 00:00:00 2001 From: "coderabbitai[bot]" <136622811+coderabbitai[bot]@users.noreply.github.com> Date: Sat, 12 Apr 2025 00:42:08 +0000 Subject: [PATCH 11/12] ### ChangeLog: Additions with file tests/test_recv.py: Unknown Additions --- tests/test_recv.py | 177 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 177 insertions(+) create mode 100644 tests/test_recv.py diff --git a/tests/test_recv.py b/tests/test_recv.py new file mode 100644 index 00000000..8801054e --- /dev/null +++ b/tests/test_recv.py @@ -0,0 +1,177 @@ +#! /usr/bin/env python3 +# -*- coding: utf-8 -*- + +# Multicast Python Test Module +# .................................. +# Copyright (c) 2017-2025, Mr. Walls +# .................................. +# Licensed under MIT (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# .......................................... +# https://www.github.com/reactive-firewall/multicast/LICENSE.md +# .......................................... +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Test module for multicast.recv functionality. + +This module provides test cases for the recv module, focusing on the +McastRECV.doStep method's branching logic for success/failure logging. +""" + +import unittest +from unittest import mock +import sys +import io + +from multicast import recv + +# Import necessary modules to avoid cyclic dependency +try: + import multicast +except ImportError: # pragma: no cover + import sys + import os + sys.path.insert(0, os.path.abspath(os.path.join(os.path.dirname(__file__), '..'))) + import multicast + + +class TestMcastRECV(unittest.TestCase): + """Test cases for McastRECV class doStep method.""" + + def setUp(self): + """Set up test fixtures.""" + self.recv_tool = recv.McastRECV() + # Store original stdout for later restoration + self.original_stdout = sys.stdout + + def tearDown(self): + """Tear down test fixtures.""" + # Restore original stdout + sys.stdout = self.original_stdout + + @mock.patch('multicast.recv.module_logger') + def test_doStep_with_response(self, mock_logger): + """Test case 1: Test doStep with successful response.""" + # Mock _hearstep to return a non-empty response + with mock.patch.object( + recv.McastRECV, '_hearstep', return_value='Test response' + ) as mock_hear: + result, response = self.recv_tool.doStep(is_std=False) + + # Verify results + self.assertTrue(result) + self.assertEqual(response, 'Test response') + + # Verify logger called with success message + mock_logger.info.assert_called_once_with("Success") + + # Verify _hearstep was called with expected defaults + mock_hear.assert_called_once() + + @mock.patch('multicast.recv.module_logger') + def test_doStep_with_empty_response(self, mock_logger): + """Test case 2: Test doStep with empty response.""" + # Mock _hearstep to return an empty response + with mock.patch.object( + recv.McastRECV, '_hearstep', return_value='' + ) as mock_hear: + result, response = self.recv_tool.doStep(is_std=False) + + # Verify results: expect a failure (False) and no response (None) + self.assertFalse(result) + self.assertIsNone(response) + + # Verify logger called with nothing received message + mock_logger.debug.assert_any_call("Nothing Received.") + + # Verify _hearstep was called with expected defaults + mock_hear.assert_called_once() + + @mock.patch('multicast.recv.module_logger') + def test_doStep_logging_sequence_success(self, mock_logger): + """Test case 3: Verify logging sequence for successful response.""" + # Mock _hearstep to return a non-empty response + with mock.patch.object( + recv.McastRECV, '_hearstep', return_value='Test response' + ): + self.recv_tool.doStep(is_std=False) + + # Verify initial debug log and success log + mock_logger.debug.assert_any_call("RECV") + mock_logger.info.assert_called_once_with("Success") + + # Ensure that "Nothing Received" is not logged + for call in mock_logger.debug.call_args_list: + self.assertNotEqual(call[0][0], "Nothing Received.") + + @mock.patch('multicast.recv.module_logger') + def test_doStep_logging_sequence_empty(self, mock_logger): + """Test case 4: Verify logging sequence for empty response.""" + # Mock _hearstep to return an empty response + with mock.patch.object( + recv.McastRECV, '_hearstep', return_value='' + ): + self.recv_tool.doStep(is_std=False) + + # Verify initial debug log and nothing received log + mock_logger.debug.assert_any_call("RECV") + mock_logger.debug.assert_any_call("Nothing Received.") + + # Verify that no success log was called + mock_logger.info.assert_not_called() + + @mock.patch('multicast.recv.module_logger') + def test_doStep_console_output(self, mock_logger): + """Test case 5: Test console output when is_std is True with data.""" + # Capture printed output by redirecting stdout + mock_stdout = io.StringIO() + sys.stdout = mock_stdout + + # Mock _hearstep to return a non-empty response + with mock.patch.object( + recv.McastRECV, '_hearstep', return_value='Test response' + ): + self.recv_tool.doStep(is_std=True) + + # Verify that the response is printed to console + output = mock_stdout.getvalue() + self.assertIn('Test response', output) + + # Verify that the logger recorded the intended debug message + mock_logger.debug.assert_any_call("Will Print to Console.") + + @mock.patch('multicast.recv.module_logger') + def test_doStep_with_custom_parameters(self, mock_logger): + """Test case 6: Test doStep with custom parameters.""" + # Mock _hearstep to capture and return custom test output + with mock.patch.object( + recv.McastRECV, '_hearstep', return_value='Custom test' + ) as mock_hear: + custom_group = "224.0.0.2" + custom_port = 12345 + custom_iface = "lo" + + self.recv_tool.doStep( + groups=[custom_group], + port=custom_port, + iface=custom_iface, + group=custom_group, + is_std=False + ) + + # Verify _hearstep is called with custom parameters + mock_hear.assert_called_once_with( + [custom_group], custom_port, custom_iface, custom_group + ) + + # Verify that a success log is recorded for the custom parameters + mock_logger.info.assert_called_once_with("Success") + + +if __name__ == '__main__': + unittest.main() \ No newline at end of file From b2840c2c5d0a8341f32f90db9623d341d0cab1a2 Mon Sep 17 00:00:00 2001 From: "Mr. Walls" Date: Fri, 11 Apr 2025 21:13:03 -0700 Subject: [PATCH 12/12] [TESTING] Fixing up the implementation for new extra tests (- WIP PR #359 -) * this work is part of implementing #357 Changes in file tests/__init__.py: * related work. Changes in file tests/test_recv.py: * Implementing GHI #357 --- tests/__init__.py | 9 +- tests/test_recv.py | 289 ++++++++++++++++++++++----------------------- 2 files changed, 150 insertions(+), 148 deletions(-) diff --git a/tests/__init__.py b/tests/__init__.py index 3296ed1d..22d7e7f9 100644 --- a/tests/__init__.py +++ b/tests/__init__.py @@ -285,7 +285,7 @@ def loadDocstringsFromModule(module: types.ModuleType) -> TestSuite: "No doctests found in %s: %s", # lazy formatting to avoid PYL-W1203 module.__name__, e, # log as just warning level, instead of exception (error), but still detailed. - exec_info=True, + exc_info=True, ) except Exception: _LOGGER.exception( @@ -350,6 +350,13 @@ def loadDocstringsFromModule(module: types.ModuleType) -> TestSuite: "security": [], # To be implemented } +try: + from tests import test_recv + depends.insert(11, test_recv) + EXTRA_TESTS["coverage"].append(test_recv.McastRECVTestSuite) +except Exception: # pragma: no branch + _LOGGER.warning("Error loading optional debug tests", exc_info=True) + try: FUZZING_TESTS = { "slow": [ diff --git a/tests/test_recv.py b/tests/test_recv.py index 8801054e..cd4b0bef 100644 --- a/tests/test_recv.py +++ b/tests/test_recv.py @@ -1,7 +1,7 @@ #! /usr/bin/env python3 # -*- coding: utf-8 -*- -# Multicast Python Test Module +# Multicast Python Module (Testing) # .................................. # Copyright (c) 2017-2025, Mr. Walls # .................................. @@ -23,155 +23,150 @@ McastRECV.doStep method's branching logic for success/failure logging. """ -import unittest -from unittest import mock -import sys -import io -from multicast import recv +__module__ = "tests" + -# Import necessary modules to avoid cyclic dependency try: - import multicast -except ImportError: # pragma: no cover - import sys - import os - sys.path.insert(0, os.path.abspath(os.path.join(os.path.dirname(__file__), '..'))) - import multicast - - -class TestMcastRECV(unittest.TestCase): - """Test cases for McastRECV class doStep method.""" - - def setUp(self): - """Set up test fixtures.""" - self.recv_tool = recv.McastRECV() - # Store original stdout for later restoration - self.original_stdout = sys.stdout - - def tearDown(self): - """Tear down test fixtures.""" - # Restore original stdout - sys.stdout = self.original_stdout - - @mock.patch('multicast.recv.module_logger') - def test_doStep_with_response(self, mock_logger): - """Test case 1: Test doStep with successful response.""" - # Mock _hearstep to return a non-empty response - with mock.patch.object( - recv.McastRECV, '_hearstep', return_value='Test response' - ) as mock_hear: - result, response = self.recv_tool.doStep(is_std=False) - - # Verify results - self.assertTrue(result) - self.assertEqual(response, 'Test response') - - # Verify logger called with success message - mock_logger.info.assert_called_once_with("Success") - - # Verify _hearstep was called with expected defaults - mock_hear.assert_called_once() - - @mock.patch('multicast.recv.module_logger') - def test_doStep_with_empty_response(self, mock_logger): - """Test case 2: Test doStep with empty response.""" - # Mock _hearstep to return an empty response - with mock.patch.object( - recv.McastRECV, '_hearstep', return_value='' - ) as mock_hear: - result, response = self.recv_tool.doStep(is_std=False) - - # Verify results: expect a failure (False) and no response (None) - self.assertFalse(result) - self.assertIsNone(response) - - # Verify logger called with nothing received message - mock_logger.debug.assert_any_call("Nothing Received.") - - # Verify _hearstep was called with expected defaults - mock_hear.assert_called_once() - - @mock.patch('multicast.recv.module_logger') - def test_doStep_logging_sequence_success(self, mock_logger): - """Test case 3: Verify logging sequence for successful response.""" - # Mock _hearstep to return a non-empty response - with mock.patch.object( - recv.McastRECV, '_hearstep', return_value='Test response' - ): - self.recv_tool.doStep(is_std=False) - - # Verify initial debug log and success log - mock_logger.debug.assert_any_call("RECV") - mock_logger.info.assert_called_once_with("Success") - - # Ensure that "Nothing Received" is not logged - for call in mock_logger.debug.call_args_list: - self.assertNotEqual(call[0][0], "Nothing Received.") - - @mock.patch('multicast.recv.module_logger') - def test_doStep_logging_sequence_empty(self, mock_logger): - """Test case 4: Verify logging sequence for empty response.""" - # Mock _hearstep to return an empty response - with mock.patch.object( - recv.McastRECV, '_hearstep', return_value='' - ): - self.recv_tool.doStep(is_std=False) - - # Verify initial debug log and nothing received log - mock_logger.debug.assert_any_call("RECV") - mock_logger.debug.assert_any_call("Nothing Received.") - - # Verify that no success log was called - mock_logger.info.assert_not_called() - - @mock.patch('multicast.recv.module_logger') - def test_doStep_console_output(self, mock_logger): - """Test case 5: Test console output when is_std is True with data.""" - # Capture printed output by redirecting stdout - mock_stdout = io.StringIO() - sys.stdout = mock_stdout - - # Mock _hearstep to return a non-empty response - with mock.patch.object( - recv.McastRECV, '_hearstep', return_value='Test response' - ): - self.recv_tool.doStep(is_std=True) - - # Verify that the response is printed to console - output = mock_stdout.getvalue() - self.assertIn('Test response', output) - - # Verify that the logger recorded the intended debug message - mock_logger.debug.assert_any_call("Will Print to Console.") - - @mock.patch('multicast.recv.module_logger') - def test_doStep_with_custom_parameters(self, mock_logger): - """Test case 6: Test doStep with custom parameters.""" - # Mock _hearstep to capture and return custom test output - with mock.patch.object( - recv.McastRECV, '_hearstep', return_value='Custom test' - ) as mock_hear: - custom_group = "224.0.0.2" - custom_port = 12345 - custom_iface = "lo" - - self.recv_tool.doStep( - groups=[custom_group], - port=custom_port, - iface=custom_iface, - group=custom_group, - is_std=False - ) - - # Verify _hearstep is called with custom parameters - mock_hear.assert_called_once_with( - [custom_group], custom_port, custom_iface, custom_group - ) - - # Verify that a success log is recorded for the custom parameters - mock_logger.info.assert_called_once_with("Success") + try: + import context + except Exception as _: # pragma: no branch + del _ # skipcq - cleanup any error vars early + from . import context + if context.__name__ is None: + raise ModuleNotFoundError("[CWE-758] Failed to import context") from None + else: + from context import sys + from context import multicast # pylint: disable=cyclic-import - skipcq: PYL-R0401 + from context import unittest + from unittest import mock + import io +except Exception as err: + raise ImportError("[CWE-758] Failed to import test context") from err + + +@context.markWithMetaTag("extra", "coverage") +class McastRECVTestSuite(context.BasicUsageTestSuite): + """Test cases for McastRECV class doStep method.""" + + __module__ = "tests.test_recv" + + def setUp(self): + """Set up test fixtures.""" + super(McastRECVTestSuite, self).setUp() + self.recv_tool = multicast.recv.McastRECV() + # Store original stdout for later restoration + self.original_stdout = sys.stdout + + def tearDown(self): + """Tear down test fixtures.""" + # Restore original stdout + sys.stdout = self.original_stdout + super(McastRECVTestSuite, self).tearDown() + + @mock.patch('multicast.recv.module_logger') + def test_doStep_with_response(self, mock_logger): + """Test case 1: Test doStep with successful response.""" + # Mock _hearstep to return a non-empty response + with mock.patch.object( + multicast.recv.McastRECV, '_hearstep', return_value='Test response' + ) as mock_hear: + result, response = self.recv_tool.doStep(is_std=False) + # Verify results + self.assertTrue(result) + self.assertEqual(response, 'Test response') + # Verify logger called with success message + mock_logger.info.assert_called_once_with("Success") + # Verify _hearstep was called with expected defaults + mock_hear.assert_called_once() + + @mock.patch('multicast.recv.module_logger') + def test_doStep_with_empty_response(self, mock_logger): + """Test case 2: Test doStep with empty response.""" + # Mock _hearstep to return an empty response + with mock.patch.object( + multicast.recv.McastRECV, '_hearstep', return_value='' + ) as mock_hear: + result, response = self.recv_tool.doStep(is_std=False) + # Verify results: expect a failure (False) and no response (None) + self.assertFalse(result) + self.assertIsNone(response) + # Verify logger called with nothing received message + mock_logger.debug.assert_any_call("Nothing Received.") + # Verify _hearstep was called with expected defaults + mock_hear.assert_called_once() + + @mock.patch('multicast.recv.module_logger') + def test_doStep_logging_sequence_success(self, mock_logger): + """Test case 3: Verify logging sequence for successful response.""" + # Mock _hearstep to return a non-empty response + with mock.patch.object( + multicast.recv.McastRECV, '_hearstep', return_value='Test response' + ): + self.recv_tool.doStep(is_std=False) + # Verify initial debug log and success log + mock_logger.debug.assert_any_call("RECV") + mock_logger.info.assert_called_once_with("Success") + # Ensure that "Nothing Received" is not logged + for call in mock_logger.debug.call_args_list: + self.assertNotEqual(call[0][0], "Nothing Received.") + + @mock.patch('multicast.recv.module_logger') + def test_doStep_logging_sequence_empty(self, mock_logger): + """Test case 4: Verify logging sequence for empty response.""" + # Mock _hearstep to return an empty response + with mock.patch.object( + multicast.recv.McastRECV, '_hearstep', return_value='' + ): + self.recv_tool.doStep(is_std=False) + # Verify initial debug log and nothing received log + mock_logger.debug.assert_any_call("RECV") + mock_logger.debug.assert_any_call("Nothing Received.") + # Verify that no success log was called + mock_logger.info.assert_not_called() + + @mock.patch('multicast.recv.module_logger') + def test_doStep_console_output(self, mock_logger): + """Test case 5: Test console output when is_std is True with data.""" + # Capture printed output by redirecting stdout + mock_stdout = io.StringIO() + sys.stdout = mock_stdout + # Mock _hearstep to return a non-empty response + with mock.patch.object( + multicast.recv.McastRECV, '_hearstep', return_value='Test response' + ): + self.recv_tool.doStep(is_std=True) + # Verify that the response is printed to console + output = mock_stdout.getvalue() + self.assertIn('Test response', output) + # Verify that the logger recorded the intended debug message + mock_logger.debug.assert_any_call("Will Print to Console.") + + @mock.patch('multicast.recv.module_logger') + def test_doStep_with_custom_parameters(self, mock_logger): + """Test case 6: Test doStep with custom parameters.""" + # Mock _hearstep to capture and return custom test output + with mock.patch.object( + multicast.recv.McastRECV, '_hearstep', return_value='Custom test' + ) as mock_hear: + custom_group = "224.0.0.2" + custom_port = 12345 + custom_iface = "lo" + + self.recv_tool.doStep( + groups=[custom_group], + port=custom_port, + iface=custom_iface, + group=custom_group, + is_std=False + ) + # Verify _hearstep is called with custom parameters + mock_hear.assert_called_once_with( + [custom_group], custom_port, custom_iface, custom_group + ) + # Verify that a success log is recorded for the custom parameters + mock_logger.info.assert_called_once_with("Success") if __name__ == '__main__': - unittest.main() \ No newline at end of file + unittest.main()