Merge pull request #444 from crim-ca/adjust-log-tests

adjust fixme in tests stdout/stderr

CHANGES.rst

@@ -16,7 +16,8 @@ Changes:
 
 Fixes:
 ------
-- No change.
+- Move ``WpsPackage`` properties to instance level to avoid potential referencing of attributes across same class
+  used by distinct running `Process`.
 
 .. _changes_4.18.0:
 

Makefile

@@ -365,6 +365,15 @@ clean-dist: clean	## remove *all* files that are not controlled by 'git' except
 # -v:  list of test names with PASS/FAIL/SKIP/ERROR/etc. next to it
 # -vv: extended collection of stdout/stderr on top of test results
 TEST_VERBOSITY ?= -v
+override TEST_VERBOSE_FLAG := $(shell echo $(TEST_VERBOSITY) | tr ' ' '\n' | grep -E "^\-v+" || echo "")
+override TEST_VERBOSE_CAPTURE := $(shell \
+	test $$(echo "$(TEST_VERBOSE_FLAG)" | tr -cd 'v' | wc -c) -gt 1 && echo 1 || echo 0 \
+)
+ifeq ($(filter $(TEST_VERBOSITY),"--capture"),)
+  ifeq ($(TEST_VERBOSE_CAPTURE),1)
+    TEST_VERBOSITY := $(TEST_VERBOSITY) --capture tee-sys
+  endif
+endif
 
 # autogen tests variants with pre-install of dependencies using the '-only' target references
 TESTS := unit func cli workflow online offline no-tb14 spec coverage
@@ -431,7 +440,7 @@ test-spec-only:	mkdir-reports  ## run tests with custom specification (pytest fo
 	@echo "Running custom tests from input specification..."
 	@[ "${SPEC}" ] || ( echo ">> 'SPEC' is not set"; exit 1 )
 	@bash -c '$(CONDA_CMD) pytest tests $(TEST_VERBOSITY) \
-		-m "${SPEC}" --junitxml "$(REPORTS_DIR)/test-results.xml"'
+		-k "${SPEC}" --junitxml "$(REPORTS_DIR)/test-results.xml"'
 
 .PHONY: test-smoke
 test-smoke: docker-test     ## alias to 'docker-test' executing smoke test of built docker images

setup.cfg

@@ -5,23 +5,23 @@ tag = True
 tag_name = {new_version}
 
 [bumpversion:file:CHANGES.rst]
-search = 
+search =
 	`Unreleased <https://github.com/crim-ca/weaver/tree/master>`_ (latest)
 	========================================================================
-replace = 
+replace =
 	`Unreleased <https://github.com/crim-ca/weaver/tree/master>`_ (latest)
 	========================================================================
-	
+
 	Changes:
 	--------
 	- No change.
-	
+
 	Fixes:
 	------
 	- No change.
-	
+
 	.. _changes_{new_version}:
-	
+
 	`{new_version} <https://github.com/crim-ca/weaver/tree/{new_version}>`_ ({now:%%Y-%%m-%%d})
 	========================================================================
 
@@ -42,17 +42,20 @@ search = LABEL version="{current_version}"
 replace = LABEL version="{new_version}"
 
 [tool:pytest]
-addopts = 
+# avoid using '--capture tee-sys' explicitly in 'addopts'
+# instead add it dynamically in Makefile based on 'TEST_VERBOSITY'
+addopts =
 	--strict-markers
 	--tb=native
 	weaver/
-capture = tee-sys
 log_cli = false
 log_level = DEBUG
-log_format = [%%(asctime)s] %%(levelname)-8.8s [%%(threadName)s][%%(name)s] %%(message)s
-log_date_format = %%Y-%%m-%%d %%H:%%M:%%S
+# FIXME: format specifiers incorrectly escaped (https://github.com/pytest-dev/pytest/issues/10019)
+#        fails our tests if provided since name and message are required to validate functionalities
+#log_format = [%%(asctime)s] %%(levelname)-8.8s [%%(threadName)s][%%(name)s] %%(message)s
+#log_date_format = %%Y-%%m-%%d %%H:%%M:%%S
 python_files = test_*.py
-markers = 
+markers =
 	cli: mark test as related to CLI operations
 	testbed14: mark test as 'testbed14' validation
 	functional: mark test as functionality validation
@@ -83,7 +86,7 @@ targets = .
 [flake8]
 ignore = E126,E226,E402,F401,W503,W504
 max-line-length = 120
-exclude = 
+exclude =
 	src,
 	.git,
 	__pycache__,
@@ -108,14 +111,14 @@ add_select = D201,D213
 branch = true
 source = ./
 include = weaver/*
-omit = 
+omit =
 	setup.py
 	docs/*
 	tests/*
 	*_mako
 
 [coverage:report]
-exclude_lines = 
+exclude_lines =
 	pragma: no cover
 	raise AssertionError
 	raise NotImplementedError

tests/processes/test_wps_package.py

@@ -5,7 +5,10 @@
     - :mod:`tests.functional.wps_package`.
 """
 import contextlib
+import io
+import logging
 import os
+import re
 import shutil
 import sys
 import tempfile
@@ -62,7 +65,9 @@ class MockWpsPackage(WpsPackage):
     """
     Mock of WPS package definition that ignores real status location updates and returns the mock for test validation.
     """
-    mock_status_location = None
+    def __init__(self, *_, **__):
+        super(MockWpsPackage, self).__init__(*_, **__)
+        self.mock_status_location = None
 
     @property
     def status_location(self):
@@ -74,12 +79,12 @@ def status_location(self, value):
 
 
 class MockWpsRequest(WPSRequest):
-    def __init__(self, process_id=None):
+    def __init__(self, process_id=None, with_message_input=True):
         if not process_id:
             raise ValueError("must provide mock process identifier")
         super(MockWpsRequest, self).__init__()
         self.identifier = process_id
-        self.json = {
+        data = {
             "identifier": process_id,
             "operation": "execute",
             "version": "1.0.0",
@@ -89,97 +94,183 @@ def __init__(self, process_id=None):
             "status": "true",
             "lineage": "true",
             "raw": "false",
-            "inputs": {
-                "message": [
-                    {
-                        "identifier": "message",
-                        "title": "A dummy message",
-                        "type": "literal",
-                        "data_type": "string",
-                        "data": "Dummy message",
-                        "allowed_values": [],
-                    }
-                ]
-            },
+            "inputs": {},
             "outputs": {}
         }
+        if with_message_input:
+            data["inputs"]["message"] = [
+                {
+                    "identifier": "message",
+                    "title": "A dummy message",
+                    "type": "literal",
+                    "data_type": "string",
+                    "data": "Dummy message",
+                    "allowed_values": [],
+                }
+            ]
+        self.json = data
 
 
 class MockProcess(Process):
-    def __init__(self, shell_command=None):
+    def __init__(self, shell_command, arguments=None, with_message_input=True):
         if not shell_command:
             raise ValueError("must provide mock process shell command")
         # fix for Windows, need to tell explicitly the path to shell command
         # since cwltool sets subprocess.Popen with shell=False
         if sys.platform == "win32":
             shell_command = [shutil.which("cmd.exe"), "/c", shell_command]
+        cwl = {
+            "cwlVersion": "v1.0",
+            "class": "CommandLineTool",
+            "baseCommand": shell_command,
+            "inputs": {},
+            "outputs": {}
+        }
+        if isinstance(arguments, list) and arguments:
+            cwl["arguments"] = arguments
+        if with_message_input:
+            cwl["inputs"]["message"] = {
+                "type": "string",
+                "inputBinding": {
+                    "position": 1
+                }
+            }
         body = {
             "title": "mock-process",
             "id": "mock-process",
-            "package": {
-                "cwlVersion": "v1.0",
-                "class": "CommandLineTool",
-                "baseCommand": shell_command,
-                "inputs": {
-                    "message": {
-                        "type": "string",
-                        "inputBinding": {
-                            "position": 1
-                        }
-                    }
-                },
-                "outputs": {}
-            }
+            "package": cwl
         }
         super(MockProcess, self).__init__(body)
 
 
-def test_stdout_stderr_logging_for_commandline_tool_success():
+def test_stdout_stderr_logging_for_commandline_tool_success(caplog):
     """
     Execute a process and assert that stdout is correctly logged to log file upon successful process execution.
     """
+    caplog.set_level(logging.INFO, logger="cwltool")
+    caplog.set_level(logging.INFO, logger="weaver")
+
     with contextlib.ExitStack() as stack:
         xml_file = stack.enter_context(tempfile.NamedTemporaryFile(suffix=".xml"))  # noqa
         workdir = stack.enter_context(tempfile.TemporaryDirectory())
         process = MockProcess(shell_command="echo")
         wps_package_instance = MockWpsPackage(identifier=process["id"], title=process["title"],
                                               payload=process, package=process["package"])
+        wps_package_instance.settings = {}
         wps_package_instance.mock_status_location = xml_file.name
         wps_package_instance.set_workdir(workdir)
+        expect_log = os.path.splitext(wps_package_instance.mock_status_location)[0] + ".log"
 
         # ExecuteResponse mock
         wps_request = MockWpsRequest(process_id=process.id)
         wps_response = type("", (object,), {"_update_status": lambda *_, **__: 1})()
-        wps_package_instance._handler(wps_request, wps_response)
 
-        # log assertions
-        expect_log = os.path.splitext(wps_package_instance.mock_status_location)[0] + ".log"
+        # depending on debug/command-line & pytest config, captured logs can be 'hijacked' or not, use any active one
+        stdout = io.StringIO()
+        with contextlib.redirect_stdout(stdout):
+            wps_package_instance._handler(wps_request, wps_response)
         with open(expect_log, mode="r", encoding="utf-8") as file:
-            log_data = file.read()
-            # FIXME: add more specific asserts... validate CWL command called and sub-operations logged
-            assert "Dummy message" in log_data
+            job_log = file.read()
+        log_data = stdout.getvalue() + "\n" + caplog.text + "\n" + job_log
+
+        # captured log portion added by the injected stdout/stderr logs
+        assert re.match(
+            r".*"
+            r"----- Captured Log \(stdout\) -----\n"
+            r"Dummy message\n"
+            r"----- End of Logs -----\n"
+            r".*",
+            log_data,
+            re.MULTILINE | re.DOTALL
+        )
+        # cwltool call with reference to the command and stdout/stderr redirects
+        assert re.match(
+            r".*"
+            rf"cwltool.*job {process.id}.*\$ echo \\\n"
+            r"\s+'Dummy message' \> [\w\-/\.]+/stdout\.log 2\> [\w\-/\.]+/stderr\.log\n"
+            r".*",
+            log_data,
+            re.MULTILINE | re.DOTALL
+        ), f"Information expected in:\n{log_data}"
+        assert f"[cwltool] [job {process.id}] completed success" in log_data
 
 
-def test_stdout_stderr_logging_for_commandline_tool_failure():
+def test_stdout_stderr_logging_for_commandline_tool_failure(caplog):
     """
     Execute a process and assert that stderr is correctly logged to log file upon failing process execution.
     """
+    caplog.set_level(logging.INFO, logger="cwltool")
+    caplog.set_level(logging.INFO, logger="weaver")
+
+    with contextlib.ExitStack() as stack:
+        xml_file = stack.enter_context(tempfile.NamedTemporaryFile(suffix=".xml"))  # noqa
+        workdir = stack.enter_context(tempfile.TemporaryDirectory())
+        process = MockProcess(shell_command="echo", with_message_input=True)
+    wps_package_instance = MockWpsPackage(identifier=process["id"], title=process["title"],
+                                          payload=process, package=process["package"])
+    wps_package_instance.settings = {}
+    wps_package_instance.mock_status_location = xml_file.name
+    wps_package_instance.set_workdir(workdir)
+
+    # ExecuteResponse mock
+    wps_request = MockWpsRequest(process_id=process["id"], with_message_input=False)
+    wps_response = type("", (object,), {"_update_status": lambda *_, **__: 1})()
+
+    stderr = io.StringIO()
+    try:
+        with contextlib.redirect_stderr(stderr):
+            wps_package_instance._handler(wps_request, wps_response)
+    except PackageExecutionError as exception:
+        assert "Failed package execution" in exception.args[0]
+        assert "Missing required input parameter 'message'" in exception.args[0]
+        # depending on debug/command-line & pytest config, captured logs can be 'hijacked' or not, use any active one
+        log_err = stderr.getvalue() + "\n" + caplog.text
+        assert "Could not retrieve any internal application log." not in log_err, (
+            "Since tool did not reach execution, not captured logged is expected."
+        )
+        assert "Traceback (most recent call last):" in log_err
+        assert "weaver.processes.wps_package|mock-process" in log_err
+        assert "Missing required input parameter 'message'" in log_err
+    else:
+        pytest.fail("\"wps_package._handler()\" was expected to throw \"PackageExecutionError\" exception")
+
+
+def test_stdout_stderr_logging_for_commandline_tool_exception(caplog):
+    """
+    Execute a process and assert that traceback is correctly logged to log file upon failing process execution.
+    """
+    caplog.set_level(logging.INFO, logger="cwltool")
+    caplog.set_level(logging.INFO, logger="weaver")
+
     with contextlib.ExitStack() as stack:
         xml_file = stack.enter_context(tempfile.NamedTemporaryFile(suffix=".xml"))  # noqa
         workdir = stack.enter_context(tempfile.TemporaryDirectory())
         process = MockProcess(shell_command="not_existing_command")
     wps_package_instance = MockWpsPackage(identifier=process["id"], title=process["title"],
                                           payload=process, package=process["package"])
+    wps_package_instance.settings = {}
     wps_package_instance.mock_status_location = xml_file.name
     wps_package_instance.set_workdir(workdir)
+    expect_log = os.path.splitext(wps_package_instance.mock_status_location)[0] + ".log"
 
     # ExecuteResponse mock
     wps_request = MockWpsRequest(process_id=process["id"])
     wps_response = type("", (object,), {"_update_status": lambda *_, **__: 1})()
-    # FIXME: add more specific asserts... validate CWL command called but as some execution error entry logged
+
+    stderr = io.StringIO()
     try:
-        wps_package_instance._handler(wps_request, wps_response)
+        with contextlib.redirect_stderr(stderr):
+            wps_package_instance._handler(wps_request, wps_response)
     except PackageExecutionError as exception:
         assert "Completed permanentFail" in exception.args[0]
+        # depending on debug/command-line & pytest config, captured logs can be 'hijacked' or not, use any active one
+        with open(expect_log, mode="r", encoding="utf-8") as file:
+            job_err = file.read()
+        log_err = stderr.getvalue() + "\n" + caplog.text + "\n" + job_err
+        assert "Could not retrieve any internal application log." in log_err, (
+            "Since command did not run, nothing captured is expected"
+        )
+        assert "Traceback (most recent call last):" in log_err
+        assert "weaver.processes.wps_package|mock-process" in log_err
     else:
         pytest.fail("\"wps_package._handler()\" was expected to throw \"PackageExecutionError\" exception")