Files
fastapi/tests/test_telemetry/test_exceptions.py
T

250 lines
8.7 KiB
Python

import pytest
from fastapi import FastAPI, HTTPException, Request
from fastapi.responses import JSONResponse, StreamingResponse
from fastapi.testclient import TestClient
from opentelemetry import trace
from opentelemetry._logs import NoOpLoggerProvider, SeverityNumber
from opentelemetry.sdk.trace.sampling import ALWAYS_OFF
from .conftest import metric_points, server_spans
@pytest.mark.parametrize("sampled", [True, False])
def test_exception_is_logged_once_with_trace_context(telemetry, logs, sampled):
config, spans, reader = telemetry
if not sampled:
config["tracer_provider"].sampler = ALWAYS_OFF
app = FastAPI(telemetry=config)
contexts = []
error = ValueError("test failure")
@app.get("/items/{item_id}")
def endpoint(item_id: int):
contexts.append(trace.get_current_span().get_span_context())
raise error
assert (
TestClient(app, raise_server_exceptions=False).get("/items/1").status_code
== 500
)
(data,) = logs.get_finished_logs()
record = data.log_record
assert record.event_name == "http.server.request.exception"
assert record.timestamp is not None
assert record.timestamp <= record.observed_timestamp
assert (
data.instrumentation_scope.schema_url
== "https://opentelemetry.io/schemas/1.44.0"
)
assert record.exception is error
assert record.trace_id == contexts[0].trace_id
assert record.span_id != 0
if sampled:
(server,) = server_spans(spans)
assert record.span_id == server.context.span_id
assert record.severity_number == SeverityNumber.ERROR
assert record.attributes["http.route"] == "/items/{item_id}"
assert record.attributes["exception.type"] == "ValueError"
assert record.attributes["exception.message"] == "test failure"
assert "raise error" in record.attributes["exception.stacktrace"]
assert len(server_spans(spans)) == int(sampled)
@pytest.mark.parametrize("raises", [False, True])
def test_exclusion_applies_to_mounted_apps(telemetry, logs, raises):
config, spans, reader = telemetry
scopes = []
child = FastAPI(telemetry=config)
@child.get("/{name}")
def endpoint(*, request: Request, name: str):
scopes.append(request.scope)
if name == "excluded" and raises:
raise ValueError("excluded error")
return name
parent = FastAPI(
telemetry={
**config,
"exclude": lambda scope: scope["path"] == "/child/excluded",
}
)
parent.mount("/child", child)
client = TestClient(parent, raise_server_exceptions=False)
assert client.get("/child/excluded").status_code == (500 if raises else 200)
assert not spans.get_finished_spans()
assert not logs.get_finished_logs()
assert not metric_points(reader=reader)
assert "fastapi.telemetry" not in scopes[0]
assert client.get("/child/included").json() == "included"
(span,) = server_spans(spans)
assert span.attributes["http.route"] == "/child/{name}"
assert metric_points(reader=reader)[0].count == 1
def test_handled_exceptions_and_validation_are_not_error_logs(telemetry, logs):
config, spans, reader = telemetry
app = FastAPI(telemetry=config)
@app.exception_handler(ValueError)
async def handled(request, exc):
return JSONResponse({"detail": "handled"}, status_code=400)
@app.get("/items/{value}")
def endpoint(value: int):
if value == 1:
raise HTTPException(404)
raise ValueError("handled by application")
client = TestClient(app)
assert client.get("/items/no").status_code == 422
assert client.get("/items/1").status_code == 404
assert client.get("/items/2").status_code == 400
assert client.get("/missing").status_code == 404
(validation,) = logs.get_finished_logs()
assert validation.log_record.severity_number == SeverityNumber.WARN
assert validation.log_record.event_name == "fastapi.validation.failed"
assert validation.log_record.timestamp is not None
assert validation.log_record.timestamp <= validation.log_record.observed_timestamp
assert validation.log_record.exception is None
@pytest.mark.parametrize("stage", ["stream", "cleanup"])
def test_errors_after_response_started_are_logged(telemetry, logs, stage):
from fastapi import Depends
config, spans, reader = telemetry
app = FastAPI(telemetry=config)
def fail():
raise ValueError("after response started")
async def dependency():
yield
if stage == "cleanup":
fail()
@app.get("/", dependencies=[Depends(dependency)])
async def endpoint():
if stage == "stream":
async def stream():
yield "start"
fail()
return StreamingResponse(stream())
return "ok"
assert TestClient(app, raise_server_exceptions=False).get("/").status_code == 200
(data,) = logs.get_finished_logs()
(span,) = server_spans(spans)
assert data.log_record.trace_id == span.context.trace_id
assert (
"after response started" in data.log_record.attributes["exception.stacktrace"]
)
@pytest.mark.parametrize("mode", ["logs_only", "disabled", "noop", "excluded"])
def test_independent_log_configuration(telemetry, logs, mode):
config, spans, reader = telemetry
if mode == "logs_only":
config.update(tracing=False, metrics=False)
elif mode == "disabled":
config["logs"] = False
elif mode == "noop":
config["logger_provider"] = NoOpLoggerProvider()
else:
config["exclude"] = lambda scope: True
app = FastAPI(telemetry=config)
@app.get("/")
def endpoint():
raise ValueError("test")
assert TestClient(app, raise_server_exceptions=False).get("/").status_code == 500
records = logs.get_finished_logs()
assert len(records) == int(mode == "logs_only")
if records:
assert records[0].log_record.trace_id == 0
@pytest.mark.parametrize("status", [404, 503])
@pytest.mark.parametrize("sampled", [False, True])
def test_http_exception_records_status_without_exception_telemetry(
telemetry, logs, status, sampled
):
from opentelemetry.trace import StatusCode
config, spans, reader = telemetry
if not sampled:
config["tracer_provider"].sampler = ALWAYS_OFF
app = FastAPI(telemetry=config)
@app.get("/items/{item_id}")
def endpoint(item_id: int):
raise HTTPException(status, "private exception detail")
response = TestClient(app).get("/items/1")
assert response.status_code == status
assert response.json() == {"detail": "private exception detail"}
assert not logs.get_finished_logs()
(point,) = metric_points(reader=reader)
assert point.count == 1
assert point.attributes["http.response.status_code"] == status
assert point.attributes["http.route"] == "/items/{item_id}"
assert point.attributes.get("error.type") == ("503" if status == 503 else None)
finished = spans.get_finished_spans()
assert all(not span.events for span in finished)
if sampled:
(server,) = server_spans(spans)
assert server.attributes["http.response.status_code"] == status
assert server.status.status_code == (
StatusCode.ERROR if status == 503 else StatusCode.UNSET
)
else:
assert not finished
def test_exception_handler_failure_is_logged_once_as_unhandled(telemetry, logs):
config, _, _ = telemetry
failure = RuntimeError("handler failed")
app = FastAPI(telemetry=config)
@app.exception_handler(HTTPException)
async def handler(request, exc):
raise failure
@app.get("/")
async def endpoint():
raise HTTPException(404, "original")
assert TestClient(app, raise_server_exceptions=False).get("/").status_code == 500
(data,) = logs.get_finished_logs()
assert data.log_record.exception is failure
assert data.log_record.body == "Unhandled exception in FastAPI request"
class ApplicationError(Exception):
pass
def test_exception_type_matches_spans_metrics_and_logs(telemetry, logs):
config, spans, reader = telemetry
app = FastAPI(telemetry=config)
@app.get("/")
async def endpoint():
raise ApplicationError("failed")
assert TestClient(app, raise_server_exceptions=False).get("/").status_code == 500
(record,) = logs.get_finished_logs()
expected = f"{__name__}.ApplicationError"
assert record.log_record.attributes["exception.type"] == expected
failed_spans = [
span for span in spans.get_finished_spans() if span.status.is_ok is False
]
assert {span.name for span in failed_spans} == {"GET /", "fastapi.endpoint"}
assert all(span.attributes["error.type"] == expected for span in failed_spans)
(point,) = metric_points(reader=reader)
assert point.attributes["error.type"] == expected