From 99e9290b169dabfff860453647748b30f9a10a70 Mon Sep 17 00:00:00 2001 From: Nicholas Wiltsie Date: Thu, 31 Aug 2023 15:20:39 -0700 Subject: [PATCH 1/6] Simplify the logging setup --- nftest/common.py | 40 ++++++++++++++++------------------------ 1 file changed, 16 insertions(+), 24 deletions(-) diff --git a/nftest/common.py b/nftest/common.py index 245893c..57653ae 100644 --- a/nftest/common.py +++ b/nftest/common.py @@ -53,39 +53,31 @@ def print_version_and_exist(): print(__version__, file=sys.stdout) sys.exit() + def setup_loggers(): """ Initialize loggers for both init and run """ - _ = generate_logger('NFTest') - _ = generate_logger('NFTestInit') + # Always log times in UTC + logging.Formatter.converter = time.gmtime -# pylint: disable=W0212 -def generate_logger(logger_name:str): - """ Generate program-specific logger """ _env = NFTestENV() - try: - log_level = logging._checkLevel(_env.NFT_LOG_LEVEL) - except ValueError: - log_level = logging._checkLevel('INFO') - - logger = logging.getLogger(logger_name) - logger.setLevel(log_level) - - formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s') - logging.Formatter.converter = time.gmtime + # Make a file handler that accepts all logs try: file_handler = logging.FileHandler(_env.NFT_LOG) + file_handler.setLevel(logging.DEBUG) except (FileNotFoundError, PermissionError) as file_error: raise Exception(f'Unable to create log file: {_env.NFT_LOG}') from file_error - file_handler.setLevel(log_level) + # Make a stream handler with the requested verbosity stream_handler = logging.StreamHandler(sys.stdout) - stream_handler.setLevel(log_level) - - file_handler.setFormatter(formatter) - stream_handler.setFormatter(formatter) - - logger.addHandler(file_handler) - logger.addHandler(stream_handler) + # stream_handler.setFormatter(formatter) + try: + stream_handler.setLevel(logging._checkLevel(_env.NFT_LOG_LEVEL)) + except ValueError: + stream_handler.setLevel(logging.INFO) - return logger + logging.basicConfig( + level=logging.DEBUG, + format='%(asctime)s - %(name)s - %(levelname)s - %(message)s', + handlers=(file_handler, stream_handler) + ) From 073691bfbadcc28812e343008ee5e9e54bc65a6f Mon Sep 17 00:00:00 2001 From: Nicholas Wiltsie Date: Thu, 31 Aug 2023 15:21:46 -0700 Subject: [PATCH 2/6] Stream NextFlow output to logs --- nftest/NFTestCase.py | 54 +++++++++++++++++++++++++++++++------------- 1 file changed, 38 insertions(+), 16 deletions(-) diff --git a/nftest/NFTestCase.py b/nftest/NFTestCase.py index c121ef5..f0d2dd9 100644 --- a/nftest/NFTestCase.py +++ b/nftest/NFTestCase.py @@ -1,9 +1,12 @@ """ NF Test case """ from __future__ import annotations +import os import shutil import re +import logging from pathlib import Path from shlex import quote +import selectors import subprocess as sp from subprocess import PIPE from logging import getLogger @@ -29,6 +32,7 @@ def __init__(self, name:str=None, message:str=None, nf_script:str=None, """ Constructor """ self._env = NFTestENV() self._logger = getLogger('NFTest') + self._nflogger = getLogger("NextFlow") self.name = name self.name_for_output = re.sub(r'[^a-zA-Z0-9_\-.]', '', self.name.replace(' ', '-')) self.message = message @@ -107,22 +111,40 @@ def submit(self) -> sp.CompletedProcess: """ self._logger.info(' '.join(cmd.split())) - res = sp.run(cmd, - shell=True, - stdout=PIPE, - stderr=PIPE, - check=False, - universal_newlines=True, - capture_output=(not self.verbose)) - - self._logger.info(res.stdout) - if res.stderr.strip(): - self._logger.error(res.stderr) - - return res - - - def combine_global(self, _global:NFTestGlobal) -> None: + with sp.Popen(cmd, + shell=True, + stdout=PIPE, + stderr=PIPE, + universal_newlines=True) as process: + + # Route stdout to INFO and stderr to ERROR in real-time + with selectors.DefaultSelector() as selector: + selector.register( + fileobj=process.stdout, + events=selectors.EVENT_READ, + data=logging.INFO + ) + selector.register( + fileobj=process.stderr, + events=selectors.EVENT_READ, + data=logging.ERROR + ) + + while process.poll() is None: + events = selector.select() + for key, _ in events: + line = key.fileobj.readline() + if line: + # The only case in which this won't be true is when + # the pipe is closed + self._nflogger.log( + level=key.data, + msg=line.rstrip() + ) + + return process + + def combine_global(self, _global: NFTestGlobal) -> None: """ Combine test case configs with the global configs. """ if _global.nf_config: self.nf_configs.insert(0, _global.nf_config) From 3542b96f8a3b6f78e72ae4181b7794bfbd46a0f7 Mon Sep 17 00:00:00 2001 From: Nicholas Wiltsie Date: Thu, 31 Aug 2023 15:22:08 -0700 Subject: [PATCH 3/6] Add debug statements about asserts --- nftest/NFTestAssert.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/nftest/NFTestAssert.py b/nftest/NFTestAssert.py index cf6b74e..5c14b22 100644 --- a/nftest/NFTestAssert.py +++ b/nftest/NFTestAssert.py @@ -35,6 +35,7 @@ def assert_expected(self): assert_method = self.get_assert_method() try: assert assert_method(self.actual, self.expect) + self._logger.debug('Assertion passed') except AssertionError as error: self._logger.error('Assertion failed') self._logger.error('Actual: %s', self.actual) @@ -47,11 +48,13 @@ def get_assert_method(self) -> Callable: if self.script is not None: def func(actual, expect): cmd = f"{self.script} {actual} {expect}" + self._logger.debug(cmd) process_out = sp.run(cmd, shell=True, check=False) return process_out.returncode == 0 return func if self.method == 'md5': def func(actual, expect): + self._logger.debug(f"md5 {actual} {expect}") actual_value = calculate_checksum(actual) expect_value = calculate_checksum(expect) return actual_value == expect_value From 1b4ca72a582768dd6f50f7d41e2c339399ffda31 Mon Sep 17 00:00:00 2001 From: Nicholas Wiltsie Date: Thu, 31 Aug 2023 15:51:27 -0700 Subject: [PATCH 4/6] Update CHANGELOG --- CHANGELOG.md | 3 +++ 1 file changed, 3 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index ac1389b..da28ca5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,9 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm --- ## [Unreleased] +### Changed +- Wrap all NextFlow output with real-time line-by-line log statements +- Add DEBUG lines about specific asserts --- From b6c268af8fce3e00f67a5972ab1196d5a71c9012 Mon Sep 17 00:00:00 2001 From: Nicholas Wiltsie Date: Thu, 31 Aug 2023 15:54:11 -0700 Subject: [PATCH 5/6] Remove commented line --- nftest/common.py | 1 - 1 file changed, 1 deletion(-) diff --git a/nftest/common.py b/nftest/common.py index 57653ae..43384be 100644 --- a/nftest/common.py +++ b/nftest/common.py @@ -70,7 +70,6 @@ def setup_loggers(): # Make a stream handler with the requested verbosity stream_handler = logging.StreamHandler(sys.stdout) - # stream_handler.setFormatter(formatter) try: stream_handler.setLevel(logging._checkLevel(_env.NFT_LOG_LEVEL)) except ValueError: From 666e9c63c46dea4b4957b1f04c9da989c28c0dba Mon Sep 17 00:00:00 2001 From: Nicholas Wiltsie Date: Thu, 31 Aug 2023 16:02:47 -0700 Subject: [PATCH 6/6] Address pylint warnings --- nftest/NFTestAssert.py | 2 +- nftest/NFTestCase.py | 17 +++++++++-------- nftest/common.py | 2 +- 3 files changed, 11 insertions(+), 10 deletions(-) diff --git a/nftest/NFTestAssert.py b/nftest/NFTestAssert.py index 5c14b22..b51f60b 100644 --- a/nftest/NFTestAssert.py +++ b/nftest/NFTestAssert.py @@ -54,7 +54,7 @@ def func(actual, expect): return func if self.method == 'md5': def func(actual, expect): - self._logger.debug(f"md5 {actual} {expect}") + self._logger.debug("md5 %s %s", actual, expect) actual_value = calculate_checksum(actual) expect_value = calculate_checksum(expect) return actual_value == expect_value diff --git a/nftest/NFTestCase.py b/nftest/NFTestCase.py index f0d2dd9..86114d3 100644 --- a/nftest/NFTestCase.py +++ b/nftest/NFTestCase.py @@ -1,16 +1,17 @@ """ NF Test case """ from __future__ import annotations -import os -import shutil + import re -import logging -from pathlib import Path -from shlex import quote import selectors +import shutil import subprocess as sp + +from logging import getLogger, INFO, ERROR +from pathlib import Path +from shlex import quote from subprocess import PIPE -from logging import getLogger from typing import Callable, List, TYPE_CHECKING + from nftest.common import remove_nextflow_logs from nftest.NFTestENV import NFTestENV @@ -122,12 +123,12 @@ def submit(self) -> sp.CompletedProcess: selector.register( fileobj=process.stdout, events=selectors.EVENT_READ, - data=logging.INFO + data=INFO ) selector.register( fileobj=process.stderr, events=selectors.EVENT_READ, - data=logging.ERROR + data=ERROR ) while process.poll() is None: diff --git a/nftest/common.py b/nftest/common.py index 43384be..f5dddb0 100644 --- a/nftest/common.py +++ b/nftest/common.py @@ -71,7 +71,7 @@ def setup_loggers(): # Make a stream handler with the requested verbosity stream_handler = logging.StreamHandler(sys.stdout) try: - stream_handler.setLevel(logging._checkLevel(_env.NFT_LOG_LEVEL)) + stream_handler.setLevel(logging._checkLevel(_env.NFT_LOG_LEVEL)) # pylint: disable=W0212 except ValueError: stream_handler.setLevel(logging.INFO)