Improve validation errors and log test duration

tavern/_core/pytest/item.py

@@ -1,6 +1,7 @@
 import dataclasses
 import logging
 import pathlib
+import time
 from collections.abc import Callable, Iterable, MutableMapping
 
 import pytest
@@ -236,6 +237,7 @@ def _load_fixture_values(self):
         return values
 
     def runtest(self) -> None:
+        start_time = time.perf_counter()
         self.global_cfg = load_global_cfg(self.config)
 
         load_plugins(self.global_cfg)
@@ -296,6 +298,12 @@ def runtest(self) -> None:
             if xfail:
                 raise Exception(f"internal: xfail test did not fail '{xfail}'")
         finally:
+            duration = time.perf_counter() - start_time
+            logger.info(
+                "tavern.test_duration_seconds=%0.3f test=%s",
+                duration,
+                self.name,
+            )
             call_hook(
                 self.global_cfg,
                 "pytest_tavern_beta_after_every_test_run",

tavern/_core/schema/jsonschema.py

@@ -37,6 +37,44 @@
 
 logger: logging.Logger = logging.getLogger(__name__)
 
+def _format_error_path(path):
+    parts = []
+    for item in path:
+        if isinstance(item, int):
+            if parts:
+                parts[-1] = f"{parts[-1]}[{item}]"
+            else:
+                parts.append(f"[{item}]")
+        else:
+            parts.append(str(item))
+    return ".".join(parts)
+
+
+def _extract_missing_required_key(error: ValidationError) -> str | None:
+    match = re.search(r"'(.+?)' is a required property", error.message)
+    if match:
+        return match.group(1)
+    return None
+
+
+def _format_validation_message(error: ValidationError) -> str:
+    message = error.message
+    if error.validator == "required":
+        missing_key = _extract_missing_required_key(error)
+        path = list(error.absolute_path)
+        if missing_key:
+            path.append(missing_key)
+        path_str = _format_error_path(path)
+        stage_name = None
+        if isinstance(error.instance, Mapping):
+            stage_name = error.instance.get("name") or error.instance.get("id")
+        if stage_name:
+            message = f"{message} (stage: {stage_name})"
+        if path_str:
+            message = f"{message} (path: {path_str})"
+    return message
+
+
 
 def is_str_or_bytes_or_token(checker, instance):
     return Draft7Validator.TYPE_CHECKER.is_type(instance, "string") or isinstance(
@@ -163,7 +201,7 @@ def verify_jsonschema(to_verify: Mapping, schema: Mapping) -> None:
                 content = "\n".join(list(lines))
                 real_context.append(
                     f"""
-{c.message}
+{_format_validation_message(c)}
 {filename}: line {first_line}-{last_line}:
 
 {content}
@@ -172,7 +210,7 @@ def verify_jsonschema(to_verify: Mapping, schema: Mapping) -> None:
             else:
                 real_context.append(
                     f"""
-{c.message}
+{_format_validation_message(c)}
 
 <error: unable to find input file for context>
 """

tests/unit/test_helpers.py

@@ -1,4 +1,6 @@
 import contextlib
+import logging
+import pathlib
 import json
 import sys
 import tempfile
@@ -13,6 +15,7 @@
 from tavern._core import exceptions
 from tavern._core.dict_util import _check_and_format_values, format_keys
 from tavern._core.loader import ForceIncludeToken
+from tavern._core.pytest.config import TavernInternalConfig, TestConfig
 from tavern._core.pytest.item import YamlItem
 from tavern._core.schema.extensions import validate_file_spec
 from tavern._core.strict_util import (
@@ -458,3 +461,31 @@ def test_unset(self, section):
         level = StrictLevel.from_options([section])
 
         assert level.option_for(section).setting == StrictSetting.UNSET
+
+
+def test_logs_test_duration(caplog, monkeypatch, request):
+    spec = {"test_name": "duration", "stages": [{"name": "stage"}]}
+    item = YamlItem.from_parent(
+        name="duration", parent=request.node, spec=spec, path=pathlib.Path("test.tavern.yaml")
+    )
+    item.funcargs = {}
+    item.fixturenames = []
+
+    test_config = TestConfig(
+        variables={},
+        strict=StrictLevel(),
+        follow_redirects=False,
+        stages=[],
+        tavern_internal=TavernInternalConfig(pytest_hook_caller=Mock(), backends={}),
+    )
+
+    monkeypatch.setattr("tavern._core.pytest.item.load_global_cfg", lambda _cfg: test_config)
+    monkeypatch.setattr("tavern._core.pytest.item.load_plugins", lambda _cfg: None)
+    monkeypatch.setattr("tavern._core.pytest.item.verify_tests", lambda _spec: None)
+    monkeypatch.setattr("tavern._core.pytest.item.run_test", lambda *_args, **_kwargs: None)
+    monkeypatch.setattr("tavern._core.pytest.item.call_hook", lambda *_args, **_kwargs: None)
+
+    with caplog.at_level(logging.INFO, logger="tavern._core.pytest.item"):
+        item.runtest()
+
+    assert any("tavern.test_duration_seconds=" in record.message for record in caplog.records)

tests/unit/test_schema.py

@@ -205,3 +205,14 @@ def test_empty_list_val(self):
         with TestBadSchemaAtCollect.wrapfile_nondict(text) as filename:
             with pytest.raises(BadSchemaError):
                 load_single_document_yaml(filename)
+
+
+def test_missing_required_key_includes_stage_context(test_dict):
+    test_dict["stages"][0].pop("request")
+
+    with pytest.raises(BadSchemaError) as exc:
+        verify_tests(test_dict)
+
+    msg = str(exc.value)
+    assert "stage: Make sure number is returned correctly" in msg
+    assert "path: stages[0].request" in msg