feat(stage16): implement observability — structured logging, metrics, tracing
- JSONFormatter, ContextVars, set_research_run_id() with short logger names - self-built Counter/Histogram/Gauge system (no external deps) - Prometheus text export at /metrics - Request logging middleware with X-Request-ID - Metrics instrumentation: search_queries, sources_fetched, claims, contradictions - Histograms: research_duration, llm_request_duration - Gauge: active_research_runs - 13 + 21 = 34 tests
This commit is contained in:
NSCT Agent
204
tests/test_logging.py
Normal file
204
tests/test_logging.py
Normal file
@@ -0,0 +1,204 @@
|
||||
"""Tests for NSCT structured logging (logging_config)."""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import json
|
||||
import logging
|
||||
import os
|
||||
import sys
|
||||
import tempfile
|
||||
from io import StringIO
|
||||
|
||||
import pytest
|
||||
|
||||
# Ensure src is on path for imports
|
||||
sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..", "src"))
|
||||
|
||||
|
||||
class TestLoggingConfig:
|
||||
"""Tests for logging_config.py functionality."""
|
||||
|
||||
def setup_method(self) -> None:
|
||||
"""Reset logging state before each test."""
|
||||
root = logging.getLogger()
|
||||
root.handlers.clear()
|
||||
# Clear request context
|
||||
from nsct.logging_config import _request_ctx, _request_ctx_token
|
||||
_request_ctx.clear()
|
||||
_request_ctx_token.set({})
|
||||
from nsct.logging_config import _research_run_id
|
||||
_research_run_id.set(None)
|
||||
|
||||
# --- JSON formatter ---
|
||||
|
||||
def test_json_formatter_produces_valid_json(self) -> None:
|
||||
"""Ein Log-Eintrag muss gültiges JSON ergeben."""
|
||||
from nsct.logging_config import JSONFormatter
|
||||
|
||||
formatter = JSONFormatter()
|
||||
record = logging.LogRecord(
|
||||
name="nsct.api", level=logging.INFO, pathname="test.py",
|
||||
lineno=42, msg="test message", args=(), exc_info=None,
|
||||
)
|
||||
output = formatter.format(record)
|
||||
data = json.loads(output)
|
||||
|
||||
assert "timestamp" in data
|
||||
assert data["level"] == "INFO"
|
||||
assert data["module"] == "nsct.api"
|
||||
assert data["message"] == "test message"
|
||||
assert "elapsed_ms" in data
|
||||
|
||||
def test_json_formatter_includes_research_run_id(self) -> None:
|
||||
"""research_run_id wird aus ContextVar in den Log-Eintrag übernommen."""
|
||||
from nsct.logging_config import JSONFormatter, set_research_run_id
|
||||
|
||||
set_research_run_id("test-run-123")
|
||||
|
||||
formatter = JSONFormatter()
|
||||
record = logging.LogRecord(
|
||||
name="nsct.stages", level=logging.DEBUG, pathname="test.py",
|
||||
lineno=10, msg="claim extracted", args=(), exc_info=None,
|
||||
)
|
||||
data = json.loads(formatter.format(record))
|
||||
assert data["research_run_id"] == "test-run-123"
|
||||
|
||||
def test_json_formatter_includes_stage(self) -> None:
|
||||
"""stage aus _request_ctx wird mit ausgegeben."""
|
||||
from nsct.logging_config import JSONFormatter, set_request_ctx
|
||||
|
||||
set_request_ctx(stage="searching")
|
||||
|
||||
formatter = JSONFormatter()
|
||||
record = logging.LogRecord(
|
||||
name="nsct.api", level=logging.WARNING, pathname="test.py",
|
||||
lineno=5, msg="timeout", args=(), exc_info=None,
|
||||
)
|
||||
data = json.loads(formatter.format(record))
|
||||
assert data["stage"] == "searching"
|
||||
|
||||
def test_json_formatter_with_exception(self) -> None:
|
||||
"""exc_info wird im JSON enthalten sein."""
|
||||
from nsct.logging_config import JSONFormatter
|
||||
|
||||
formatter = JSONFormatter()
|
||||
try:
|
||||
raise ValueError("test error")
|
||||
except Exception:
|
||||
exc_info = sys.exc_info()
|
||||
|
||||
record = logging.LogRecord(
|
||||
name="nsct", level=logging.ERROR, pathname="test.py",
|
||||
lineno=99, msg="error occurred", args=(), exc_info=exc_info,
|
||||
)
|
||||
data = json.loads(formatter.format(record))
|
||||
assert "exc_info" in data
|
||||
assert "test error" in data["exc_info"]
|
||||
|
||||
# --- setup_logging ---
|
||||
|
||||
def test_setup_logging_default_level(self) -> None:
|
||||
"""setup_logging mit default Level INFO."""
|
||||
from nsct.logging_config import setup_logging
|
||||
|
||||
setup_logging(level="INFO", json_format=True)
|
||||
root = logging.getLogger()
|
||||
assert root.level == logging.INFO
|
||||
|
||||
def test_setup_logging_custom_level(self) -> None:
|
||||
"""setup_logging mit DEBUG Level."""
|
||||
from nsct.logging_config import setup_logging
|
||||
|
||||
setup_logging(level="DEBUG", json_format=True)
|
||||
root = logging.getLogger()
|
||||
assert root.level == logging.DEBUG
|
||||
|
||||
def test_setup_logging_with_env_var(self, monkeypatch) -> None:
|
||||
"""NSCT_LOG_LEVEL aus Environment wird gelesen."""
|
||||
monkeypatch.setenv("NSCT_LOG_LEVEL", "WARNING")
|
||||
|
||||
from nsct.logging_config import setup_logging
|
||||
setup_logging(json_format=True)
|
||||
|
||||
root = logging.getLogger()
|
||||
assert root.level == logging.WARNING
|
||||
|
||||
def test_setup_logging_json_to_stdout(self) -> None:
|
||||
"""JSON-Formatter schreibt zu stdout."""
|
||||
from nsct.logging_config import JSONFormatter, setup_logging
|
||||
|
||||
setup_logging(level="INFO", json_format=True)
|
||||
root = logging.getLogger()
|
||||
|
||||
# Capture stdout — replace handler's stream temporarily
|
||||
stream = StringIO()
|
||||
for handler in root.handlers:
|
||||
handler.setStream(stream)
|
||||
|
||||
logger = logging.getLogger("nsct.api")
|
||||
logger.info("hello world")
|
||||
output = stream.getvalue()
|
||||
data = json.loads(output.strip())
|
||||
assert data["message"] == "hello world"
|
||||
|
||||
def test_setup_logging_to_file(self, tmp_path) -> None:
|
||||
"""NSCT_LOG_FILE → Logs gehen in Datei."""
|
||||
log_file = str(tmp_path / "nsct.log")
|
||||
import os
|
||||
os.environ["NSCT_LOG_FILE"] = log_file
|
||||
|
||||
try:
|
||||
from nsct.logging_config import setup_logging
|
||||
setup_logging(level="INFO", json_format=True)
|
||||
|
||||
logger = logging.getLogger("nsct.cli")
|
||||
logger.info("file log test")
|
||||
|
||||
with open(log_file) as f:
|
||||
content = f.read()
|
||||
assert "file log test" in content
|
||||
finally:
|
||||
del os.environ["NSCT_LOG_FILE"]
|
||||
# Re-setup for other tests
|
||||
root = logging.getLogger()
|
||||
root.handlers.clear()
|
||||
from nsct.logging_config import JSONFormatter
|
||||
from nsct.logging_config import _request_ctx, _request_ctx_token
|
||||
_request_ctx.clear()
|
||||
_request_ctx_token.set({})
|
||||
from nsct.logging_config import _research_run_id
|
||||
_research_run_id.set(None)
|
||||
|
||||
def test_get_logger_short_names(self) -> None:
|
||||
"""Short names (api, orchestration, stages, cli) werden aufgelöst."""
|
||||
from nsct.logging_config import get_logger
|
||||
|
||||
assert get_logger("api").name == "nsct.api"
|
||||
assert get_logger("orchestration").name == "nsct.orchestration"
|
||||
assert get_logger("stages").name == "nsct.stages"
|
||||
assert get_logger("cli").name == "nsct.cli"
|
||||
|
||||
def test_get_logger_default(self) -> None:
|
||||
"""get_logger() ohne Argument → nsct."""
|
||||
from nsct.logging_config import get_logger
|
||||
|
||||
assert get_logger() is get_logger("nsct")
|
||||
assert get_logger().name == "nsct"
|
||||
|
||||
def test_request_context_clear(self) -> None:
|
||||
"""clear_request_ctx löscht den Kontext."""
|
||||
from nsct.logging_config import set_request_ctx, clear_request_ctx, _request_ctx
|
||||
|
||||
set_request_ctx(stage="synthesizing", research_run_id="abc")
|
||||
assert len(_request_ctx) > 0
|
||||
clear_request_ctx()
|
||||
assert len(_request_ctx) == 0
|
||||
|
||||
def test_no_new_dependencies(self) -> None:
|
||||
"""logging_config.py nutzt nur Standard-Lib."""
|
||||
from nsct import logging_config as mod
|
||||
import inspect
|
||||
source = inspect.getsource(mod)
|
||||
# Should NOT import loguru or prometheus_client
|
||||
assert "import loguru" not in source
|
||||
assert "from loguru" not in source
|
||||
296
tests/test_metrics.py
Normal file
296
tests/test_metrics.py
Normal file
@@ -0,0 +1,296 @@
|
||||
"""Tests for NSCT metrics system (self-built, no prometheus-client required)."""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import os
|
||||
import threading
|
||||
import time
|
||||
|
||||
import pytest
|
||||
|
||||
# Ensure src is on path
|
||||
import sys
|
||||
sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..", "src"))
|
||||
|
||||
from nsct import metrics
|
||||
|
||||
|
||||
class TestCounters:
|
||||
"""Test counter operations."""
|
||||
|
||||
def setup_method(self) -> None:
|
||||
"""Reset counters before each test."""
|
||||
from nsct.metrics import _counters, _lock
|
||||
with _lock:
|
||||
_counters.clear()
|
||||
|
||||
def test_increment(self) -> None:
|
||||
"""Counter erhöht sich um 1."""
|
||||
val = metrics.increment("test_counter")
|
||||
assert val == 1
|
||||
val = metrics.increment("test_counter")
|
||||
assert val == 2
|
||||
|
||||
def test_increment_amount(self) -> None:
|
||||
"""Counter erhöht sich um den angegebenen Betrag."""
|
||||
val = metrics.increment("test_counter", 5)
|
||||
assert val == 5
|
||||
val = metrics.increment("test_counter", 3)
|
||||
assert val == 8
|
||||
|
||||
def test_get_counter_zero(self) -> None:
|
||||
"""Nicht existenter Counter gibt 0 zurück."""
|
||||
assert metrics.get_counter("nonexistent") == 0
|
||||
|
||||
def test_counter_persistence(self) -> None:
|
||||
"""Counter-Wert wird über mehrere Aufrufe beibehalten."""
|
||||
metrics.increment("persist", 10)
|
||||
assert metrics.get_counter("persist") == 10
|
||||
|
||||
|
||||
class TestHistograms:
|
||||
"""Test histogram operations."""
|
||||
|
||||
def setup_method(self) -> None:
|
||||
from nsct.metrics import _histograms, _lock
|
||||
with _lock:
|
||||
_histograms.clear()
|
||||
|
||||
def test_observe(self) -> None:
|
||||
"""Beobachtung wird im Histogramm gespeichert."""
|
||||
metrics.observe("request_seconds", 0.5)
|
||||
val = metrics.get_counter("request_seconds_count") if hasattr(metrics, 'get_counter') else None
|
||||
assert metrics.observe("request_seconds", 1.0) == 1.0
|
||||
|
||||
def test_observe_bucket(self) -> None:
|
||||
"""Beobachtungen werden in die korrekten Buckets gezählt."""
|
||||
metrics.observe("test_hist", 0.3)
|
||||
metrics.observe("test_hist", 0.8)
|
||||
metrics.observe("test_hist", 2.5)
|
||||
|
||||
from nsct.metrics import _histograms, _lock
|
||||
with _lock:
|
||||
h = _histograms["test_hist"]
|
||||
assert h["_count"] == 3
|
||||
assert h["_sum"] == 3.6
|
||||
|
||||
def test_histogram_context_manager(self) -> None:
|
||||
"""Context manager misst die Dauer korrekt."""
|
||||
from nsct.metrics import _histograms, _lock
|
||||
|
||||
# Clear histogram state
|
||||
with _lock:
|
||||
_histograms["hist_test"] = {"_count": 0, "_sum": 0.0, "buckets": {str(b): 0 for b in (0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0, 25.0, 50.0, 100.0)}}
|
||||
|
||||
with metrics.histogram("hist_test"):
|
||||
time.sleep(0.05)
|
||||
|
||||
with _lock:
|
||||
h = _histograms["hist_test"]
|
||||
assert h["_count"] == 1
|
||||
assert h["_sum"] >= 0.05
|
||||
|
||||
def test_default_buckets(self) -> None:
|
||||
"""Histogram hat die Standard-Buckets."""
|
||||
from nsct.metrics import _histograms, _lock
|
||||
metrics.observe("bucket_test", 0.5)
|
||||
with _lock:
|
||||
h = _histograms["bucket_test"]
|
||||
assert "0.5" in h["buckets"]
|
||||
assert "1.0" in h["buckets"]
|
||||
|
||||
|
||||
class TestGauges:
|
||||
"""Test gauge operations."""
|
||||
|
||||
def setup_method(self) -> None:
|
||||
from nsct.metrics import _gauges, _lock
|
||||
with _lock:
|
||||
_gauges.clear()
|
||||
|
||||
def test_gauge_set_and_get(self) -> None:
|
||||
"""Gauge-Wert wird gesetzt und gelesen."""
|
||||
metrics.gauge("active_runs", 5)
|
||||
assert metrics.get_gauge("active_runs") == 5.0
|
||||
|
||||
def test_gauge_default_zero(self) -> None:
|
||||
"""Nicht gesetzter Gauge gibt 0.0 zurück."""
|
||||
assert metrics.get_gauge("nonexistent") == 0.0
|
||||
|
||||
def test_gauge_overwrite(self) -> None:
|
||||
"""Gauge-Wert wird überschrieben."""
|
||||
metrics.gauge("x", 1)
|
||||
metrics.gauge("x", 10)
|
||||
assert metrics.get_gauge("x") == 10.0
|
||||
|
||||
|
||||
class TestPrometheusExport:
|
||||
"""Test Prometheus text format rendering."""
|
||||
|
||||
def setup_method(self) -> None:
|
||||
from nsct.metrics import _counters, _histograms, _gauges, _lock
|
||||
with _lock:
|
||||
_counters.clear()
|
||||
_histograms.clear()
|
||||
_gauges.clear()
|
||||
|
||||
def test_render_empty(self) -> None:
|
||||
"""Leere Metrics geben nur eine leere Zeile zurück."""
|
||||
text = metrics.render_prometheus()
|
||||
# Empty string or just newline is acceptable
|
||||
assert text.strip() == ""
|
||||
|
||||
def test_render_counter(self) -> None:
|
||||
"""Counter werden korrekt exportiert."""
|
||||
metrics.increment("my_counter", 42)
|
||||
text = metrics.render_prometheus()
|
||||
assert "my_counter 42" in text
|
||||
assert "# HELP my_counter" in text
|
||||
assert "# TYPE my_counter counter" in text
|
||||
|
||||
def test_render_histogram(self) -> None:
|
||||
"""Histogram wird korrekt exportiert."""
|
||||
metrics.observe("my_hist", 0.1)
|
||||
metrics.observe("my_hist", 1.0)
|
||||
text = metrics.render_prometheus()
|
||||
assert "my_hist_count 2" in text
|
||||
assert "my_hist_sum 1.1" in text
|
||||
assert "# TYPE my_hist histogram" in text
|
||||
assert 'my_hist_bucket{le="+Inf"}' in text
|
||||
|
||||
def test_render_gauge(self) -> None:
|
||||
"""Gauge wird korrekt exportiert."""
|
||||
metrics.gauge("my_gauge", 7)
|
||||
text = metrics.render_prometheus()
|
||||
assert "my_gauge 7.0" in text
|
||||
assert "# TYPE my_gauge gauge" in text
|
||||
|
||||
def test_render_combined(self) -> None:
|
||||
"""Kombinierter Export aller Metrik-Typen."""
|
||||
metrics.increment("search_queries_total", 100)
|
||||
metrics.increment("sources_fetched_total", 50)
|
||||
metrics.increment("claims_extracted_total", 25)
|
||||
metrics.increment("contradictions_detected_total", 5)
|
||||
metrics.increment("research_completed_total", 8)
|
||||
metrics.increment("research_failed_total", 2)
|
||||
metrics.observe("research_duration_seconds", 2.5)
|
||||
metrics.observe("llm_request_duration_seconds", 0.3)
|
||||
metrics.gauge("active_research_runs", 3)
|
||||
|
||||
text = metrics.render_prometheus()
|
||||
|
||||
assert "search_queries_total 100" in text
|
||||
assert "sources_fetched_total 50" in text
|
||||
assert "claims_extracted_total 25" in text
|
||||
assert "contradictions_detected_total 5" in text
|
||||
assert "research_completed_total 8" in text
|
||||
assert "research_failed_total 2" in text
|
||||
assert "research_duration_seconds_count 1" in text
|
||||
assert "llm_request_duration_seconds_count 1" in text
|
||||
assert "active_research_runs 3.0" in text
|
||||
|
||||
def test_render_thread_safety(self) -> None:
|
||||
"""render_prometheus ist thread-sicher."""
|
||||
errors = []
|
||||
|
||||
def worker() -> None:
|
||||
try:
|
||||
for _ in range(100):
|
||||
metrics.increment("concurrent", 1)
|
||||
metrics.render_prometheus()
|
||||
except Exception as e:
|
||||
errors.append(str(e))
|
||||
|
||||
threads = [threading.Thread(target=worker) for _ in range(4)]
|
||||
for t in threads:
|
||||
t.start()
|
||||
for t in threads:
|
||||
t.join()
|
||||
|
||||
assert errors == []
|
||||
|
||||
|
||||
class TestConstants:
|
||||
"""Test pre-defined metric name constants."""
|
||||
|
||||
def test_constant_values(self) -> None:
|
||||
"""Konstanten sind korrekt definiert."""
|
||||
from nsct.metrics import (
|
||||
C_SEARCH_QUERIES_TOTAL,
|
||||
C_SOURCES_FETCHED_TOTAL,
|
||||
C_CLAIMS_EXTRACTED_TOTAL,
|
||||
C_CONTRADICTIONS_DETECTED_TOTAL,
|
||||
C_RESEARCH_COMPLETED_TOTAL,
|
||||
C_RESEARCH_FAILED_TOTAL,
|
||||
H_RESEARCH_DURATION,
|
||||
H_LLM_REQUEST_DURATION,
|
||||
G_ACTIVE_RESEARCH_RUNS,
|
||||
)
|
||||
assert C_SEARCH_QUERIES_TOTAL == "search_queries_total"
|
||||
assert C_SOURCES_FETCHED_TOTAL == "sources_fetched_total"
|
||||
assert C_CLAIMS_EXTRACTED_TOTAL == "claims_extracted_total"
|
||||
assert C_CONTRADICTIONS_DETECTED_TOTAL == "contradictions_detected_total"
|
||||
assert C_RESEARCH_COMPLETED_TOTAL == "research_completed_total"
|
||||
assert C_RESEARCH_FAILED_TOTAL == "research_failed_total"
|
||||
assert H_RESEARCH_DURATION == "research_duration_seconds"
|
||||
assert H_LLM_REQUEST_DURATION == "llm_request_duration_seconds"
|
||||
assert G_ACTIVE_RESEARCH_RUNS == "active_research_runs"
|
||||
|
||||
def test_constants_on_metrics_instance(self) -> None:
|
||||
"""Konstanten sind auch auf metrics-Instanz verfügbar."""
|
||||
assert metrics.C_SEARCH_QUERIES_TOTAL == "search_queries_total"
|
||||
assert metrics.H_RESEARCH_DURATION == "research_duration_seconds"
|
||||
|
||||
|
||||
class TestMetricsIntegration:
|
||||
"""Integration tests — realistic pipeline usage."""
|
||||
|
||||
def setup_method(self) -> None:
|
||||
from nsct.metrics import _counters, _histograms, _gauges, _lock
|
||||
with _lock:
|
||||
_counters.clear()
|
||||
_histograms.clear()
|
||||
_gauges.clear()
|
||||
|
||||
def test_full_pipeline_metrics(self) -> None:
|
||||
"""Simuliert einen vollständigen Pipeline-Durchlauf."""
|
||||
# Search phase
|
||||
metrics.increment("search_queries_total", 5)
|
||||
|
||||
# Fetch phase
|
||||
metrics.increment("sources_fetched_total", 3)
|
||||
|
||||
# Extract phase
|
||||
metrics.increment("claims_extracted_total", 12)
|
||||
|
||||
# Contradiction detected
|
||||
metrics.increment("contradictions_detected_total", 2)
|
||||
|
||||
# Research completed
|
||||
metrics.observe("research_duration_seconds", 3.2)
|
||||
metrics.increment("research_completed_total", 1)
|
||||
|
||||
# Active runs
|
||||
metrics.gauge("active_research_runs", 0)
|
||||
|
||||
# Verify export
|
||||
text = metrics.render_prometheus()
|
||||
assert "search_queries_total 5" in text
|
||||
assert "sources_fetched_total 3" in text
|
||||
assert "claims_extracted_total 12" in text
|
||||
assert "contradictions_detected_total 2" in text
|
||||
assert "research_completed_total 1" in text
|
||||
assert "active_research_runs 0.0" in text
|
||||
assert "research_duration_seconds_count 1" in text
|
||||
|
||||
def test_no_new_dependencies(self) -> None:
|
||||
"""metrics.py hat keine externen Abhängigkeiten."""
|
||||
from nsct import metrics as mod
|
||||
import inspect
|
||||
source = inspect.getsource(mod)
|
||||
assert "import prometheus" not in source
|
||||
assert "from prometheus" not in source
|
||||
assert "import loguru" not in source
|
||||
# Should only import stdlib
|
||||
assert "import threading" in source
|
||||
assert "import time" in source
|
||||
Reference in New Issue
Block a user