diff --git a/README.md b/README.md index 35abd8a..40170b5 100644 --- a/README.md +++ b/README.md @@ -76,9 +76,9 @@ Output: === Nullscope Report === --- Timings --- -request: - auth | Calls: 1 | Avg: 0.0012s | Total: 0.0012s - handler | Calls: 1 | Avg: 0.0234s | Total: 0.0234s +request | Calls: 1 | Avg: 0.0250s | Total: 0.0250s + auth | Calls: 1 | Avg: 0.0012s | Total: 0.0012s + handler | Calls: 1 | Avg: 0.0234s | Total: 0.0234s ``` ## Configuration diff --git a/ROADMAP.md b/ROADMAP.md index c3ed57c..35a5988 100644 --- a/ROADMAP.md +++ b/ROADMAP.md @@ -21,9 +21,9 @@ ## Version 0.3.0 - Observability -- [ ] Exception tracking in scopes (record exception info) -- [ ] Logging-based reporter adapter -- [ ] Scope tags/labels support +- [x] Exception tracking in scopes (record exception info) +- [x] Logging-based reporter adapter +- ~~Scope tags/labels support~~ — deferred (`**metadata` covers the use case) ## Version 0.4.0 - Polish diff --git a/docs/examples.md b/docs/examples.md index d6dccd9..02d726a 100644 --- a/docs/examples.md +++ b/docs/examples.md @@ -93,6 +93,24 @@ async def refresh_cache(): ... ``` +## Logging Reporter + +```python +import logging +from nullscope import TelemetryContext, LogReporter + +# Uses the "nullscope.telemetry" logger at DEBUG level by default +telemetry = TelemetryContext(LogReporter()) + +# Or configure with a custom logger and level +logger = logging.getLogger("myapp.telemetry") +telemetry = TelemetryContext(LogReporter(logger=logger, level=logging.INFO)) + +with telemetry("request"): + handle_request() +# Emits: "timing scope=request duration=0.0234s" +``` + ## Custom Reporter Implementation ```python diff --git a/pyproject.toml b/pyproject.toml index 1b77a70..eb6c317 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [project] name = "nullscope" -version = "0.2.0" +version = "0.3.0" description = "Zero-cost telemetry for Python. No-op when disabled, rich context when enabled." readme = "README.md" requires-python = ">=3.10, <3.15" diff --git a/src/nullscope/__init__.py b/src/nullscope/__init__.py index 7d0116f..815a17d 100644 --- a/src/nullscope/__init__.py +++ b/src/nullscope/__init__.py @@ -41,6 +41,9 @@ END_MONOTONIC_S: Final[str] = "end_monotonic_s" START_WALL_TIME_S: Final[str] = "start_wall_time_s" # Epoch seconds (correlation) END_WALL_TIME_S: Final[str] = "end_wall_time_s" +ERROR: Final[str] = "error" +ERROR_TYPE: Final[str] = "error_type" +ERROR_MESSAGE: Final[str] = "error_message" _SCOPE_NAME_PATTERN = re.compile(r"^[a-z][a-z0-9_]*(?:\.[a-z][a-z0-9_]*)*$") _REQUIRED_REPORTER_METHODS: Final[tuple[str, ...]] = ("record_timing", "record_metric") @@ -61,6 +64,9 @@ class _TelemetryMetadata(TypedDict, total=False): end_monotonic_s: float start_wall_time_s: float end_wall_time_s: float + error: bool + error_type: str + error_message: str @runtime_checkable @@ -219,6 +225,10 @@ def __exit__( "start_wall_time_s": self._start_wall_time_s, "end_wall_time_s": end_wall_time_s, } + if exc_type is not None: + built["error"] = True + built["error_type"] = exc_type.__qualname__ + built["error_message"] = str(exc_val) if exc_val else "" enhanced_metadata: dict[str, Any] = {**built, **self._metadata} # Report to all reporters @@ -398,68 +408,110 @@ def shutdown(self) -> None: """No-op lifecycle method for API compatibility.""" def as_dict(self) -> dict[str, Any]: - """Return a JSON-serializable snapshot of collected data (testing).""" + """Return a JSON-serializable snapshot of collected data.""" return { - "timings": {key: list(values) for key, values in self.timings.items()}, - "metrics": {key: list(values) for key, values in self.metrics.items()}, + "timings": { + scope: [{"duration": d, **m} for d, m in entries] + for scope, entries in self.timings.items() + }, + "metrics": { + scope: [{"value": v, **m} for v, m in entries] + for scope, entries in self.metrics.items() + }, } def get_report(self) -> str: """Generate hierarchical telemetry report.""" lines = ["=== Nullscope Report ===\n"] - - # Group by hierarchy - timing_tree = self._build_hierarchy(self.timings) - self._format_tree(timing_tree, lines, "Timings") - - if self.metrics: - lines.append("\n--- Metrics ---") - for scope, values in sorted(self.metrics.items()): - total = sum(v[0] for v in values if isinstance(v[0], int | float)) - lines.append( - f"{scope:<40} | Count: {len(values):<4} | Total: {total:,.0f}", - ) - + self._format_timings(lines) + self._format_metrics(lines) return "\n".join(lines) - def _build_hierarchy( - self, - data: dict[str, deque[tuple[float, dict[str, Any]]]], - ) -> dict[str, Any]: - """Build tree structure from dot-separated scope names.""" - tree: dict[str, Any] = {} - for scope, values in data.items(): + def _format_timings(self, lines: list[str]) -> None: + if not self.timings: + return + lines.append("\n--- Timings ---") + scope_set = set(self.timings) + # Identify prefixes that need structural header lines + headers: set[str] = set() + for scope in scope_set: parts = scope.split(".") - current = tree - for part in parts[:-1]: - current = current.setdefault(part, {}) - current[parts[-1]] = values - return tree - - def _format_tree( - self, - tree: dict[str, Any], - lines: list[str], - title: str, - depth: int = 0, - ) -> None: - """Format hierarchical tree with indentation.""" - if depth == 0: - lines.append(f"\n--- {title} ---") - - for key, value in sorted(tree.items()): - indent = " " * depth - if isinstance(value, dict): - lines.append(f"{indent}{key}:") - self._format_tree(value, lines, title, depth + 1) + for i in range(1, len(parts)): + prefix = ".".join(parts[:i]) + if prefix not in scope_set: + headers.add(prefix) + + for item in sorted(scope_set | headers): + parts = item.split(".") + indent = " " * (len(parts) - 1) + name = parts[-1] + if item in headers: + lines.append(f"{indent}{name}:") else: - # Leaf node - actual timing data - durations = [v[0] for v in value] - avg_time = sum(durations) / len(durations) - total_time = sum(durations) + values = self.timings[item] + durations = [v[0] for v in values] + avg = sum(durations) / len(durations) + total = sum(durations) lines.append( - f"{indent}{key:<30} | " + f"{indent}{name:<30} | " f"Calls: {len(durations):<4} | " - f"Avg: {avg_time:.4f}s | " - f"Total: {total_time:.4f}s", + f"Avg: {avg:.4f}s | " + f"Total: {total:.4f}s", ) + + def _format_metrics(self, lines: list[str]) -> None: + if not self.metrics: + return + lines.append("\n--- Metrics ---") + for scope, values in sorted(self.metrics.items()): + count = len(values) + numeric = [v[0] for v in values if isinstance(v[0], int | float)] + # Check metric_type from any entry's metadata + metric_type = None + for _, meta in values: + if "metric_type" in meta: + metric_type = meta["metric_type"] + break + if metric_type == "gauge" and numeric: + last = numeric[-1] + lines.append(f"{scope:<40} | Count: {count:<4} | Last: {last:,.2f}") + elif numeric: + total = sum(numeric) + lines.append(f"{scope:<40} | Count: {count:<4} | Total: {total:,.0f}") + else: + lines.append(f"{scope:<40} | Count: {count:<4}") + + +class LogReporter: + """Reporter that emits telemetry as structured log records. + + Useful in production environments with existing log aggregation. + Scope and primary value appear in the message; full metadata is + attached via the ``extra`` dict for formatters that support it. + """ + + __slots__ = ("_logger", "_level") + + def __init__( + self, logger: logging.Logger | None = None, level: int = logging.DEBUG + ) -> None: + self._logger = logger or logging.getLogger("nullscope.telemetry") + self._level = level + + def record_timing(self, scope: str, duration: float, **metadata: Any) -> None: + self._logger.log( + self._level, + "timing scope=%s duration=%.4fs", + scope, + duration, + extra={"telemetry_metadata": metadata}, + ) + + def record_metric(self, scope: str, value: Any, **metadata: Any) -> None: + self._logger.log( + self._level, + "metric scope=%s value=%s", + scope, + value, + extra={"telemetry_metadata": metadata}, + ) diff --git a/tests/test_core.py b/tests/test_core.py index 688e50d..34baf46 100644 --- a/tests/test_core.py +++ b/tests/test_core.py @@ -1,5 +1,6 @@ import asyncio import importlib +import logging import os from types import ModuleType from unittest.mock import MagicMock, patch @@ -170,3 +171,123 @@ def test_timed_rejects_invalid_scope_names() -> None: with pytest.raises(ValueError, match="Invalid Decorator scope name"): telemetry.timed("Invalid.Scope") + + +def test_report_shows_nested_and_parent_scopes() -> None: + with patch.dict(os.environ, {"NULLSCOPE_ENABLED": "1"}): + nullscope = _reload_nullscope() + reporter = nullscope.SimpleReporter() + telemetry = nullscope.TelemetryContext(reporter) + + with telemetry("request"), telemetry("auth"): + pass + + report = reporter.get_report() + assert "request" in report + assert "auth" in report + # Parent scope should show its own stats, not just be a header + assert report.count("Calls:") == 2 + + +def test_report_shows_structural_headers() -> None: + with patch.dict(os.environ, {"NULLSCOPE_ENABLED": "1"}): + nullscope = _reload_nullscope() + reporter = nullscope.SimpleReporter() + telemetry = nullscope.TelemetryContext(reporter) + + # Only record "a.b.c" — no "a" or "a.b" scopes + with telemetry("a"), telemetry("b"), telemetry("c"): + pass + + # Manually clear parent scopes to simulate only having "a.b.c" + reporter.timings = {k: v for k, v in reporter.timings.items() if k == "a.b.c"} + + report = reporter.get_report() + # "a:" and "b:" should appear as structural headers + assert "a:" in report + assert "b:" in report + assert "Calls:" in report + + +def test_as_dict_returns_dicts_with_named_keys() -> None: + with patch.dict(os.environ, {"NULLSCOPE_ENABLED": "1"}): + nullscope = _reload_nullscope() + reporter = nullscope.SimpleReporter() + telemetry = nullscope.TelemetryContext(reporter) + + with telemetry("op"): + telemetry.count("items", 3) + + data = reporter.as_dict() + # Timings entries should be dicts with "duration" key + timing_entry = data["timings"]["op"][0] + assert "duration" in timing_entry + assert isinstance(timing_entry["duration"], float) + assert "depth" in timing_entry + + # Metrics entries should be dicts with "value" key + metric_entry = data["metrics"]["op.items"][0] + assert "value" in metric_entry + assert metric_entry["value"] == 3 + + +def test_report_gauge_shows_last_value() -> None: + with patch.dict(os.environ, {"NULLSCOPE_ENABLED": "1"}): + nullscope = _reload_nullscope() + reporter = nullscope.SimpleReporter() + telemetry = nullscope.TelemetryContext(reporter) + + telemetry.gauge("queue.depth", 42) + telemetry.gauge("queue.depth", 38) + + report = reporter.get_report() + assert "Last: 38" in report + # Should NOT show "Total: 80" + assert "Total: 80" not in report + + +def test_exception_metadata_recorded_on_scope_exit() -> None: + with patch.dict(os.environ, {"NULLSCOPE_ENABLED": "1"}): + nullscope = _reload_nullscope() + reporter = nullscope.SimpleReporter() + telemetry = nullscope.TelemetryContext(reporter) + + with pytest.raises(ValueError, match="bad"), telemetry("op"): + raise ValueError("bad") + + # Exception should have propagated (not swallowed) + _, metadata = reporter.timings["op"][0] + assert metadata["error"] is True + assert metadata["error_type"] == "ValueError" + assert metadata["error_message"] == "bad" + + +def test_exception_metadata_absent_on_success() -> None: + with patch.dict(os.environ, {"NULLSCOPE_ENABLED": "1"}): + nullscope = _reload_nullscope() + reporter = nullscope.SimpleReporter() + telemetry = nullscope.TelemetryContext(reporter) + + with telemetry("op"): + pass + + _, metadata = reporter.timings["op"][0] + assert "error" not in metadata + + +def test_log_reporter_emits_timing_record() -> None: + with patch.dict(os.environ, {"NULLSCOPE_ENABLED": "1"}): + nullscope = _reload_nullscope() + logger = MagicMock() + reporter = nullscope.LogReporter(logger=logger, level=logging.INFO) + telemetry = nullscope.TelemetryContext(reporter) + + with telemetry("op"): + pass + + logger.log.assert_called() + args, kwargs = logger.log.call_args + assert args[0] == logging.INFO + assert "timing" in args[1] + assert "scope=" in args[1] + assert "telemetry_metadata" in kwargs["extra"] diff --git a/uv.lock b/uv.lock index 54466a6..337995a 100644 --- a/uv.lock +++ b/uv.lock @@ -278,7 +278,7 @@ wheels = [ [[package]] name = "nullscope" -version = "0.2.0" +version = "0.3.0" source = { editable = "." } [package.optional-dependencies]