diff --git a/xtest/abac.py b/xtest/abac.py index ec92bb5e..98c069d0 100644 --- a/xtest/abac.py +++ b/xtest/abac.py @@ -262,14 +262,13 @@ def __init__(self, otdfctl_path: str | None = None): def kas_registry_list(self) -> list[KasEntry]: cmd = self.otdfctl + "policy kas-registry list".split() logger.info(f"kr-ls [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) if out: print(out) - assert code == 0 + assert process.returncode == 0 o = json.loads(out) if not o: return [] @@ -285,7 +284,7 @@ def kas_registry_create( if public_key: cmd += [f"--public-keys={public_key.model_dump_json()}"] logger.info(f"kr-create [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) @@ -308,7 +307,7 @@ def kas_registry_keys_list(self, kas: KasEntry) -> list[KasKey]: cmd = self.otdfctl + "policy kas-registry key list".split() cmd += [f"--kas={kas.uri}"] logger.info(f"kr-keys-ls [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) @@ -338,7 +337,7 @@ def kas_registry_create_public_key_only( f"--key-id={public_key.kid}", f"--algorithm={public_key.algStr}", ] - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) @@ -355,7 +354,7 @@ def key_assign_ns(self, key: KasKey, ns: Namespace) -> NamespaceKey: f"--namespace={ns.id}", ] logger.info(f"key-assign [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) @@ -372,14 +371,13 @@ def grant_assign_ns(self, kas: KasEntry, ns: Namespace) -> KasGrantNamespace: f"--namespace-id={ns.id}", ] logger.info(f"grant-update [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) if out: print(out) - assert code == 0 + assert process.returncode == 0 return KasGrantNamespace.model_validate_json(out) def key_assign_attr(self, key: KasKey, attr: Attribute) -> AttributeKey: @@ -389,7 +387,7 @@ def key_assign_attr(self, key: KasKey, attr: Attribute) -> AttributeKey: f"--attribute={attr.id}", ] logger.info(f"key-assign [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) @@ -406,14 +404,13 @@ def grant_assign_attr(self, kas: KasEntry, attr: Attribute) -> KasGrantAttribute f"--attribute-id={attr.id}", ] logger.info(f"grant-update [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) if out: print(out) - assert code == 0 + assert process.returncode == 0 return KasGrantAttribute.model_validate_json(out) def key_assign_value(self, key: KasKey, val: AttributeValue) -> ValueKey: @@ -423,7 +420,7 @@ def key_assign_value(self, key: KasKey, val: AttributeValue) -> ValueKey: f"--value={val.id}", ] logger.info(f"key-assign [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) @@ -440,14 +437,13 @@ def grant_assign_value(self, kas: KasEntry, val: AttributeValue) -> KasGrantValu f"--value-id={val.id}", ] logger.info(f"grant-update [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) if out: print(out) - assert code == 0 + assert process.returncode == 0 return KasGrantValue.model_validate_json(out) def key_unassign_ns(self, key: KasKey, ns: Namespace) -> NamespaceKey: @@ -457,14 +453,13 @@ def key_unassign_ns(self, key: KasKey, ns: Namespace) -> NamespaceKey: f"--namespace={ns.id}", ] logger.info(f"key-assign [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) if out: print(out) - assert code == 0 + assert process.returncode == 0 return NamespaceKey.model_validate_json(out) # Deprecated in otdfctl 0.22 @@ -475,14 +470,13 @@ def grant_unassign_ns(self, kas: KasEntry, ns: Namespace) -> KasGrantNamespace: f"--namespace-id={ns.id}", ] logger.info(f"grant-update [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) if out: print(out) - assert code == 0 + assert process.returncode == 0 return KasGrantNamespace.model_validate_json(out) def key_unassign_attr(self, key: KasKey, attr: Attribute) -> AttributeKey: @@ -492,7 +486,7 @@ def key_unassign_attr(self, key: KasKey, attr: Attribute) -> AttributeKey: f"--attribute={attr.id}", ] logger.info(f"key-assign [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) @@ -509,14 +503,13 @@ def grant_unassign_attr(self, kas: KasEntry, attr: Attribute) -> KasGrantAttribu f"--attribute-id={attr.id}", ] logger.info(f"grant-update [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) if out: print(out) - assert code == 0 + assert process.returncode == 0 return KasGrantAttribute.model_validate_json(out) def key_unassign_value(self, key: KasKey, val: AttributeValue) -> ValueKey: @@ -526,7 +519,7 @@ def key_unassign_value(self, key: KasKey, val: AttributeValue) -> ValueKey: f"--value={val.id}", ] logger.info(f"key-assign [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) @@ -543,27 +536,25 @@ def grant_unassign_value(self, kas: KasEntry, val: AttributeValue) -> KasGrantVa f"--value-id={val.id}", ] logger.info(f"grant-update [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) if out: print(out) - assert code == 0 + assert process.returncode == 0 return KasGrantValue.model_validate_json(out) def namespace_list(self) -> list[Namespace]: cmd = self.otdfctl + "policy attributes namespaces list".split() logger.info(f"ns-ls [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: - print(err, file=sys.stderr, flush=code != 0) + print(err, file=sys.stderr, flush=True) if out: - print(out, flush=code != 0) - assert code == 0 + print(out, flush=True) + assert process.returncode == 0 o = json.loads(out) if not o: return [] @@ -573,14 +564,13 @@ def namespace_create(self, name: str) -> Namespace: cmd = self.otdfctl + "policy attributes namespaces create".split() cmd += [f"--name={name}"] logger.info(f"ns-create [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: - print(err, file=sys.stderr, flush=code != 0) + print(err, file=sys.stderr, flush=True) if out: - print(out, flush=code != 0) - assert code == 0 + print(out, flush=True) + assert process.returncode == 0 return Namespace.model_validate_json(out) def attribute_create( @@ -596,14 +586,13 @@ def attribute_create( if values: cmd += [f"--value={','.join(values)}"] logger.info(f"attr-create [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: - print(err, file=sys.stderr, flush=code != 0) + print(err, file=sys.stderr, flush=True) if out: - print(out, flush=code != 0) - assert code == 0 + print(out, flush=True) + assert process.returncode == 0 return Attribute.model_validate_json(out) def scs_create(self, scs: list[SubjectSet]) -> SubjectConditionSet: @@ -612,14 +601,13 @@ def scs_create(self, scs: list[SubjectSet]) -> SubjectConditionSet: cmd += [f"--subject-sets=[{','.join([s.model_dump_json() for s in scs])}]"] logger.info(f"scs-create [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: - print(err, file=sys.stderr, flush=code != 0) + print(err, file=sys.stderr, flush=True) if out: - print(out, flush=code != 0) - assert code == 0 + print(out, flush=True) + assert process.returncode == 0 return SubjectConditionSet.model_validate_json(out) def scs_map( @@ -638,20 +626,19 @@ def scs_map( ] logger.info(f"sm-create [{' '.join(cmd)}]") - process = subprocess.Popen(cmd, stdout=subprocess.PIPE) - code = process.wait() + process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE) out, err = process.communicate() if err: print(err, file=sys.stderr) if out: print(out) if ( - code != 0 + process.returncode != 0 and not self.flag_scs_map_action_standard - and err.find(b"--action-standard") >= 0 + and err and err.find(b"--action-standard") >= 0 ): self.flag_scs_map_action_standard = True return self.scs_map(sc, value) - assert code == 0 + assert process.returncode == 0 return SubjectMapping.model_validate_json(out) diff --git a/xtest/conftest.py b/xtest/conftest.py index be923e3c..08a5ecc5 100644 --- a/xtest/conftest.py +++ b/xtest/conftest.py @@ -7,6 +7,8 @@ import secrets import assertions import json +import logging +import sys from cryptography.hazmat.primitives.asymmetric import rsa from cryptography.hazmat.primitives import serialization from pathlib import Path @@ -14,7 +16,34 @@ import abac import tdfs -from typing import cast +from typing import cast, Any + + +# Configure pytest to capture all subprocess output +@pytest.hookimpl(trylast=True) +def pytest_configure(config: Any) -> None: + # Set log capture level to debug to ensure all logs are captured + if hasattr(config, "option"): + config.option.log_cli = True + config.option.log_cli_level = "DEBUG" + config.option.log_cli_format = ( + "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + ) + + # Configure logging to ensure we see everything from subprocesses + logging.basicConfig( + level=logging.DEBUG, + format="%(asctime)s - %(name)s - %(levelname)s - %(message)s", + stream=sys.stdout, # Ensure output goes to stdout for pytest capture + ) + # Make sure subprocess logger is set to DEBUG level + logging.getLogger("subprocess").setLevel(logging.DEBUG) + + # Set environment variable to make sure Python doesn't buffer stdout/stderr + os.environ["PYTHONUNBUFFERED"] = "1" + + # Set buffering mode for subprocess to line buffered + os.environ["PYTHONFAULTHANDLER"] = "1" def englist(s: tuple[str]) -> str: diff --git a/xtest/pytest.ini b/xtest/pytest.ini new file mode 100644 index 00000000..5bc26df1 --- /dev/null +++ b/xtest/pytest.ini @@ -0,0 +1,19 @@ +[pytest] +# Display all logs during test runs +log_cli = True +log_cli_level = DEBUG +log_cli_format = %(asctime)s - %(name)s - %(levelname)s - %(message)s + +# Configure subprocess settings for better output capture +pythonpath = . +python_files = test_*.py +python_classes = Test* +python_functions = test_* + +# Log all test activity including setup and teardown +log_level = DEBUG + +# Set buffer size to 0 for immediate output +env = + PYTHONUNBUFFERED=1 + PYTHONFAULTHANDLER=1 diff --git a/xtest/sdk/js/cli.sh b/xtest/sdk/js/cli.sh index 5eef47fc..25437cae 100755 --- a/xtest/sdk/js/cli.sh +++ b/xtest/sdk/js/cli.sh @@ -74,7 +74,7 @@ if [ "$1" == "supports" ]; then nano_attribute_bug) set -o pipefail # Versions released unable to set nanotdf attributes - npx $CTL --version | jq -re '.["@opentdf/sdk"]' | awk -F. '{ if ($1 > 0 || ($1 == 0 && $2 > 4) || ($1 == 0 && $2 == 4 && $3 > 0)) exit 1; else exit 0; }' + npx $CTL --version | jq -re '.["@opentdf/sdk"]' | awk -F. '{ if ($1 > 0 || ($1 == 0 && $2 > 4) || ($1 == 0 && $2 == 4 && $3 >= 0)) exit 1; else exit 0; }' exit $? ;; *) diff --git a/xtest/tdfs.py b/xtest/tdfs.py index 3b4d1617..c77312bd 100644 --- a/xtest/tdfs.py +++ b/xtest/tdfs.py @@ -416,9 +416,33 @@ def decrypt( env = dict(os.environ) env |= local_env if expect_error: - subprocess.check_output(c, stderr=subprocess.STDOUT, env=env) + # Use run instead of check_output to ensure we capture all output + result = subprocess.run( + c, + env=env, + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + check=False, + text=False, # Keep as bytes to match existing code + ) + # Store output and stderr in the exception for proper reporting + if result.returncode != 0: + error = subprocess.CalledProcessError(result.returncode, c) + error.output = result.stdout + error.stderr = result.stderr + raise error + return result.stdout else: - subprocess.check_call(c, env=env) + # For normal operation, capture output for logging purposes + result = subprocess.run( + c, + env=env, + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + check=True, + text=False, # Keep as bytes to match existing code + ) + return result.stdout def supports(self, feature: feature_type) -> bool: if feature in self._supports: diff --git a/xtest/test_policytypes.py b/xtest/test_policytypes.py index 3de20776..52d90bce 100644 --- a/xtest/test_policytypes.py +++ b/xtest/test_policytypes.py @@ -1,6 +1,8 @@ import filecmp +import logging import subprocess import pytest +import sys from pathlib import Path import tdfs @@ -9,6 +11,20 @@ cipherTexts: dict[str, Path] = {} +# Improved logging configuration +logger = logging.getLogger("xtest") +# Configure logging to ensure we see everything +logging.basicConfig( + level=logging.DEBUG, + format="%(asctime)s - %(name)s - %(levelname)s - %(message)s", + stream=sys.stdout, # Ensure output goes to stdout for pytest capture +) +# Make sure our logger is set to DEBUG level +logger.setLevel(logging.DEBUG) + +# Configure subprocess logging if needed +logging.getLogger("subprocess").setLevel(logging.DEBUG) + def skip_rts_as_needed( encrypt_sdk: tdfs.SDK, @@ -102,18 +118,40 @@ def decrypt_or_dont( rt_file: Path, ): if expect_success: - decrypt_sdk.decrypt(ct_file, rt_file, container) + output = decrypt_sdk.decrypt(ct_file, rt_file, container) assert filecmp.cmp(pt_file, rt_file) + # Log successful output for debugging + if output and logger.isEnabledFor(logging.DEBUG): + logger.debug( + f"Successful decrypt output: {output.decode(errors='replace')}" + ) else: try: - decrypt_sdk.decrypt(ct_file, rt_file, container, expect_error=True) + output = decrypt_sdk.decrypt(ct_file, rt_file, container, expect_error=True) assert False, "decrypt succeeded unexpectedly" except subprocess.CalledProcessError as exc: - assert any( - e in exc.output or exc.stderr - for e in [b"forbidden", b"unable to reconstruct split key"] + output_content = getattr(exc, "output", b"").decode(errors="replace") + stderr_content = getattr(exc, "stderr", b"").decode(errors="replace") + + # Make sure we have complete output for debugging + logger.debug( + f"Command failed as expected. Return code: {exc.returncode}\n" + f"Output: {output_content}\n" + f"Stderr: {stderr_content}" ) + # Verify it failed for the expected reason + if not any( + e in (exc.output or b"") or e in (exc.stderr or b"") + for e in [b"forbidden", b"unable to reconstruct split key"] + ): + logger.warning( + f"Failed to decrypt {ct_file} with {decrypt_sdk} in {container}: {exc}\n" + f"Output: {output_content}\n" + f"Stderr: {stderr_content}" + ) + assert False, f"decrypt failed with unexpected error: {exc}" + def test_and_attributes_success( attribute_with_and_type: Attribute,