diff --git a/CHANGES.rst b/CHANGES.rst index 61beb5afc..b80cc3f55 100644 --- a/CHANGES.rst +++ b/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: diff --git a/Makefile b/Makefile index a3f2034f6..62ee1c698 100644 --- a/Makefile +++ b/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 diff --git a/setup.cfg b/setup.cfg index ce1c9142c..6865d609d 100644 --- a/setup.cfg +++ b/setup.cfg @@ -5,23 +5,23 @@ tag = True tag_name = {new_version} [bumpversion:file:CHANGES.rst] -search = +search = `Unreleased `_ (latest) ======================================================================== -replace = +replace = `Unreleased `_ (latest) ======================================================================== - + Changes: -------- - No change. - + Fixes: ------ - No change. - + .. _changes_{new_version}: - + `{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 diff --git a/tests/processes/test_wps_package.py b/tests/processes/test_wps_package.py index 1fef61011..530ce7f95 100644 --- a/tests/processes/test_wps_package.py +++ b/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") diff --git a/weaver/processes/wps_package.py b/weaver/processes/wps_package.py index 8ad8048a2..7a8b4c63c 100644 --- a/weaver/processes/wps_package.py +++ b/weaver/processes/wps_package.py @@ -80,6 +80,7 @@ from weaver.store.base import StoreJobs, StoreProcesses from weaver.utils import ( SUPPORTED_FILE_SCHEMES, + bytes2str, fetch_file, get_any_id, get_header, @@ -813,27 +814,9 @@ def try_or_raise_package_error(call, reason): class WpsPackage(Process): - # defined on __init__ call - package = None # type: Optional[CWL] - # defined only after/while _handler is called (or sub-methods) - package_id = None # type: Optional[str] - package_type = None # type: Optional[str] - package_requirement = None # type: Optional[CWL_RequirementsDict] - package_log_hook_stderr = None # type: Optional[str] - package_log_hook_stdout = None # type: Optional[str] - percent = None # type: Optional[Number] - remote_execution = None # type: Optional[bool] - log_file = None # type: Optional[str] - log_level = None # type: Optional[int] - logger = None # type: Optional[logging.Logger] - step_packages = None # type: Optional[CWL_WorkflowStepPackageMap] - step_launched = None # type: Optional[List[str]] - request = None # type: Optional[WorkerRequest] - response = None # type: Optional[ExecuteResponse] - _job = None # type: Optional[Job] - - def __init__(self, **kw): - # type: (**Any) -> None + + def __init__(self, package=None, payload=None, **kw): + # type: (CWL, Optional[JSON], **Any) -> None """ Creates a `WPS-3 Process` instance to execute a `CWL` application package definition. @@ -842,8 +825,25 @@ def __init__(self, **kw): Provided ``kw`` should correspond to :meth:`weaver.datatype.Process.params_wps` """ - self.payload = kw.pop("payload") - self.package = kw.pop("package") + # defined only after/while _handler is called (or sub-methods) + self.package_id = None # type: Optional[str] + self.package_type = None # type: Optional[str] + self.package_requirement = None # type: Optional[CWL_RequirementsDict] + self.package_log_hook_stderr = None # type: Optional[str] + self.package_log_hook_stdout = None # type: Optional[str] + self.percent = None # type: Optional[Number] + self.remote_execution = None # type: Optional[bool] + self.log_file = None # type: Optional[str] + self.log_level = None # type: Optional[int] + self.logger = None # type: Optional[logging.Logger] + self.step_packages = None # type: Optional[CWL_WorkflowStepPackageMap] + self.step_launched = None # type: Optional[List[str]] + self.request = None # type: Optional[WorkerRequest] + self.response = None # type: Optional[ExecuteResponse] + self._job = None # type: Optional[Job] + + self.payload = payload + self.package = package self.settings = get_settings() if not self.package: raise PackageRegistrationError("Missing required package definition for package process.") @@ -1539,7 +1539,7 @@ def make_location_input(self, input_type, input_definition): # auto-map local file if possible after security check if input_scheme == "vault": - vault_id = urlparse(input_location).hostname + vault_id = bytes2str(urlparse(input_location).hostname) input_url = get_vault_url(vault_id, self.settings) resp = request_extra("HEAD", input_url, settings=self.settings, headers=self.auth) if resp.status_code == 200: diff --git a/weaver/typedefs.py b/weaver/typedefs.py index 7a3529956..bf4970699 100644 --- a/weaver/typedefs.py +++ b/weaver/typedefs.py @@ -186,6 +186,8 @@ "inputs": CWL_Inputs, "outputs": CWL_Outputs, "steps": Dict[CWL_WorkflowStepID, CWL_WorkflowStep], + "stderr": str, + "stdout": str, "$namespaces": Dict[str, str], "$schemas": Dict[str, str] }, total=False)