Skip to content

Commit f182d26

Browse files
itssimonitssimon
authored
Include unhandled exceptions in request log (#95)
* WIP * Make it configurable * Get Sentry event ID * Fix
1 parent ad2c80d commit f182d26

File tree

9 files changed

+122
-82
lines changed

9 files changed

+122
-82
lines changed

‎apitally/client/request_logging.py

Lines changed: 22 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,12 @@
1414
from uuid import uuid4
1515

1616
from apitally.client.logging import get_logger
17+
from apitally.client.sentry import get_sentry_event_id_async
18+
from apitally.client.server_errors import (
19+
get_exception_type,
20+
get_truncated_exception_msg,
21+
get_truncated_exception_traceback,
22+
)
1723

1824

1925
logger = get_logger(__name__)
@@ -88,6 +94,7 @@ class RequestLoggingConfig:
8894
log_request_body: Whether to log the request body (only if JSON or plain text)
8995
log_response_headers: Whether to log response header values
9096
log_response_body: Whether to log the response body (only if JSON or plain text)
97+
log_exception: Whether to log unhandled exceptions in case of server errors
9198
mask_query_params: Query parameter names to mask in logs. Expects regular expressions.
9299
mask_headers: Header names to mask in logs. Expects regular expressions.
93100
mask_request_body_callback: Callback to mask the request body. Expects (method, path, body) and returns the masked body as bytes or None.
@@ -102,6 +109,7 @@ class RequestLoggingConfig:
102109
log_request_body: bool = False
103110
log_response_headers: bool = True
104111
log_response_body: bool = False
112+
log_exception: bool = True
105113
mask_query_params: List[str] = field(default_factory=list)
106114
mask_headers: List[str] = field(default_factory=list)
107115
mask_request_body_callback: Optional[Callable[[RequestDict], Optional[bytes]]] = None
@@ -153,7 +161,7 @@ def __init__(self, config: Optional[RequestLoggingConfig]) -> None:
153161
self.config = config or RequestLoggingConfig()
154162
self.enabled = self.config.enabled and _check_writable_fs()
155163
self.serialize = _get_json_serializer()
156-
self.write_deque: deque[bytes] = deque([], MAX_REQUESTS_IN_DEQUE)
164+
self.write_deque: deque[Dict[str, Any]] = deque([], MAX_REQUESTS_IN_DEQUE)
157165
self.file_deque: deque[TempGzipFile] = deque([])
158166
self.file: Optional[TempGzipFile] = None
159167
self.lock = threading.Lock()
@@ -163,7 +171,9 @@ def __init__(self, config: Optional[RequestLoggingConfig]) -> None:
163171
def current_file_size(self) -> int:
164172
return self.file.size if self.file is not None else 0
165173

166-
def log_request(self, request: RequestDict, response: ResponseDict) -> None:
174+
def log_request(
175+
self, request: RequestDict, response: ResponseDict, exception: Optional[BaseException] = None
176+
) -> None:
167177
if not self.enabled or self.suspend_until is not None:
168178
return
169179
parsed_url = urlparse(request["url"])
@@ -215,13 +225,19 @@ def log_request(self, request: RequestDict, response: ResponseDict) -> None:
215225
request["headers"] = self._mask_headers(request["headers"]) if self.config.log_request_headers else []
216226
response["headers"] = self._mask_headers(response["headers"]) if self.config.log_response_headers else []
217227

218-
item = {
228+
item: Dict[str, Any] = {
219229
"uuid": str(uuid4()),
220230
"request": _skip_empty_values(request),
221231
"response": _skip_empty_values(response),
222232
}
223-
serialized_item = self.serialize(item)
224-
self.write_deque.append(serialized_item)
233+
if exception is not None and self.config.log_exception:
234+
item["exception"] = {
235+
"type": get_exception_type(exception),
236+
"message": get_truncated_exception_msg(exception),
237+
"traceback": get_truncated_exception_traceback(exception),
238+
}
239+
get_sentry_event_id_async(lambda event_id: item["exception"].update({"sentry_event_id": event_id}))
240+
self.write_deque.append(item)
225241

226242
def write_to_file(self) -> None:
227243
if not self.enabled or len(self.write_deque) == 0:
@@ -232,7 +248,7 @@ def write_to_file(self) -> None:
232248
while True:
233249
try:
234250
item = self.write_deque.popleft()
235-
self.file.write_line(item)
251+
self.file.write_line(self.serialize(item))
236252
except IndexError:
237253
break
238254

‎apitally/client/sentry.py

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,38 @@
1+
import asyncio
2+
import contextlib
3+
from typing import Callable, Set
4+
5+
6+
_tasks: Set[asyncio.Task] = set()
7+
8+
9+
def get_sentry_event_id_async(cb: Callable[[str], None]) -> None:
10+
try:
11+
from sentry_sdk.hub import Hub
12+
from sentry_sdk.scope import Scope
13+
except ImportError:
14+
return # pragma: no cover
15+
if not hasattr(Scope, "get_isolation_scope") or not hasattr(Scope, "_last_event_id"):
16+
# sentry-sdk < 2.2.0 is not supported
17+
return # pragma: no cover
18+
if Hub.current.client is None:
19+
return # sentry-sdk not initialized
20+
21+
scope = Scope.get_isolation_scope()
22+
if event_id := scope._last_event_id:
23+
cb(event_id)
24+
return
25+
26+
async def _wait_for_sentry_event_id(scope: Scope) -> None:
27+
i = 0
28+
while not (event_id := scope._last_event_id) and i < 100:
29+
i += 1
30+
await asyncio.sleep(0.001)
31+
if event_id:
32+
cb(event_id)
33+
34+
with contextlib.suppress(RuntimeError): # ignore no running loop
35+
loop = asyncio.get_running_loop()
36+
task = loop.create_task(_wait_for_sentry_event_id(scope))
37+
_tasks.add(task)
38+
task.add_done_callback(_tasks.discard)

‎apitally/client/server_errors.py

Lines changed: 37 additions & 63 deletions
Original file line numberDiff line numberDiff line change
@@ -1,14 +1,15 @@
11
from __future__ import annotations
22

33
import asyncio
4-
import contextlib
54
import sys
65
import threading
76
import traceback
87
from collections import Counter
98
from dataclasses import dataclass
109
from typing import Any, Dict, List, Optional, Set
1110

11+
from apitally.client.sentry import get_sentry_event_id_async
12+
1213

1314
MAX_EXCEPTION_MSG_LENGTH = 2048
1415
MAX_EXCEPTION_TRACEBACK_LENGTH = 65536
@@ -34,49 +35,17 @@ def __init__(self) -> None:
3435
def add_server_error(self, consumer: Optional[str], method: str, path: str, exception: BaseException) -> None:
3536
if not isinstance(exception, BaseException):
3637
return # pragma: no cover
37-
exception_type = type(exception)
3838
with self._lock:
3939
server_error = ServerError(
4040
consumer=consumer,
4141
method=method.upper(),
4242
path=path,
43-
type=f"{exception_type.__module__}.{exception_type.__qualname__}",
44-
msg=self._get_truncated_exception_msg(exception),
45-
traceback=self._get_truncated_exception_traceback(exception),
43+
type=get_exception_type(exception),
44+
msg=get_truncated_exception_msg(exception),
45+
traceback=get_truncated_exception_traceback(exception),
4646
)
4747
self.error_counts[server_error] += 1
48-
self.capture_sentry_event_id(server_error)
49-
50-
def capture_sentry_event_id(self, server_error: ServerError) -> None:
51-
try:
52-
from sentry_sdk.hub import Hub
53-
from sentry_sdk.scope import Scope
54-
except ImportError:
55-
return # pragma: no cover
56-
if not hasattr(Scope, "get_isolation_scope") or not hasattr(Scope, "_last_event_id"):
57-
# sentry-sdk < 2.2.0 is not supported
58-
return # pragma: no cover
59-
if Hub.current.client is None:
60-
return # sentry-sdk not initialized
61-
62-
scope = Scope.get_isolation_scope()
63-
if event_id := scope._last_event_id:
64-
self.sentry_event_ids[server_error] = event_id
65-
return
66-
67-
async def _wait_for_sentry_event_id(scope: Scope) -> None:
68-
i = 0
69-
while not (event_id := scope._last_event_id) and i < 100:
70-
i += 1
71-
await asyncio.sleep(0.001)
72-
if event_id:
73-
self.sentry_event_ids[server_error] = event_id
74-
75-
with contextlib.suppress(RuntimeError): # ignore no running loop
76-
loop = asyncio.get_running_loop()
77-
task = loop.create_task(_wait_for_sentry_event_id(scope))
78-
self._tasks.add(task)
79-
task.add_done_callback(self._tasks.discard)
48+
get_sentry_event_id_async(lambda event_id: self.sentry_event_ids.update({server_error: event_id}))
8049

8150
def get_and_reset_server_errors(self) -> List[Dict[str, Any]]:
8251
data: List[Dict[str, Any]] = []
@@ -98,29 +67,34 @@ def get_and_reset_server_errors(self) -> List[Dict[str, Any]]:
9867
self.sentry_event_ids.clear()
9968
return data
10069

101-
@staticmethod
102-
def _get_truncated_exception_msg(exception: BaseException) -> str:
103-
msg = str(exception).strip()
104-
if len(msg) <= MAX_EXCEPTION_MSG_LENGTH:
105-
return msg
106-
suffix = "... (truncated)"
107-
cutoff = MAX_EXCEPTION_MSG_LENGTH - len(suffix)
108-
return msg[:cutoff] + suffix
109-
110-
@staticmethod
111-
def _get_truncated_exception_traceback(exception: BaseException) -> str:
112-
prefix = "... (truncated) ...\n"
113-
cutoff = MAX_EXCEPTION_TRACEBACK_LENGTH - len(prefix)
114-
lines = []
115-
length = 0
116-
if sys.version_info >= (3, 10):
117-
traceback_lines = traceback.format_exception(exception)
118-
else:
119-
traceback_lines = traceback.format_exception(type(exception), exception, exception.__traceback__)
120-
for line in traceback_lines[::-1]:
121-
if length + len(line) > cutoff:
122-
lines.append(prefix)
123-
break
124-
lines.append(line)
125-
length += len(line)
126-
return "".join(lines[::-1]).strip()
70+
71+
def get_exception_type(exception: BaseException) -> str:
72+
exception_type = type(exception)
73+
return f"{exception_type.__module__}.{exception_type.__qualname__}"
74+
75+
76+
def get_truncated_exception_msg(exception: BaseException) -> str:
77+
msg = str(exception).strip()
78+
if len(msg) <= MAX_EXCEPTION_MSG_LENGTH:
79+
return msg
80+
suffix = "... (truncated)"
81+
cutoff = MAX_EXCEPTION_MSG_LENGTH - len(suffix)
82+
return msg[:cutoff] + suffix
83+
84+
85+
def get_truncated_exception_traceback(exception: BaseException) -> str:
86+
prefix = "... (truncated) ...\n"
87+
cutoff = MAX_EXCEPTION_TRACEBACK_LENGTH - len(prefix)
88+
lines = []
89+
length = 0
90+
if sys.version_info >= (3, 10):
91+
traceback_lines = traceback.format_exception(exception)
92+
else:
93+
traceback_lines = traceback.format_exception(type(exception), exception, exception.__traceback__)
94+
for line in traceback_lines[::-1]:
95+
if length + len(line) > cutoff:
96+
lines.append(prefix)
97+
break
98+
lines.append(line)
99+
length += len(line)
100+
return "".join(lines[::-1]).strip()

‎apitally/django.py

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -216,6 +216,7 @@ def __call__(self, request: HttpRequest) -> HttpResponse:
216216
"size": response_size,
217217
"body": response_body,
218218
},
219+
exception=getattr(request, "unhandled_exception", None),
219220
)
220221
else:
221222
response = self.get_response(request)

‎apitally/flask.py

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -190,6 +190,7 @@ def add_request(
190190
"size": response_size,
191191
"body": response_body,
192192
},
193+
exception=g.unhandled_exception if "unhandled_exception" in g else None,
193194
)
194195

195196
def get_path(self, environ: WSGIEnvironment) -> Optional[str]:

‎apitally/litestar.py

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -251,6 +251,7 @@ def add_request(
251251
"size": response_size,
252252
"body": response_body,
253253
},
254+
exception=request.state["exception"] if "exception" in request.state else None,
254255
)
255256

256257
def get_path(self, request: Request) -> Optional[str]:

‎apitally/starlette.py

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -228,6 +228,7 @@ def add_request(
228228
"size": response_size,
229229
"body": response_body,
230230
},
231+
exception=exception,
231232
)
232233

233234
def get_path(self, request: Request, routes: Optional[list[BaseRoute]] = None) -> Optional[str]:

‎tests/test_client_request_logging.py

Lines changed: 12 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -60,7 +60,7 @@ async def test_request_logger_end_to_end(
6060
request_logger: RequestLogger, request_dict: RequestDict, response_dict: ResponseDict
6161
):
6262
for _ in range(3):
63-
request_logger.log_request(request_dict, response_dict)
63+
request_logger.log_request(request_dict, response_dict, RuntimeError("test"))
6464

6565
request_logger.write_to_file()
6666
assert request_logger.current_file_size > 0
@@ -98,6 +98,8 @@ async def test_request_logger_end_to_end(
9898
assert item["response"]["size"] == response_dict["size"]
9999
assert base64.b64decode(item["request"]["body"]) == request_dict["body"]
100100
assert base64.b64decode(item["response"]["body"]) == response_dict["body"]
101+
assert item["exception"]["type"] == "builtins.RuntimeError"
102+
assert item["exception"]["message"] == "test"
101103

102104

103105
def test_request_log_exclusion(request_logger: RequestLogger, request_dict: RequestDict, response_dict: ResponseDict):
@@ -111,7 +113,7 @@ def test_request_log_exclusion(request_logger: RequestLogger, request_dict: Requ
111113

112114
request_logger.log_request(request_dict, response_dict)
113115
assert len(request_logger.write_deque) == 1
114-
item = json.loads(request_logger.write_deque[0])
116+
item = request_logger.write_deque[0]
115117
assert item["request"]["url"] == "http://localhost:8000/test"
116118
assert "headers" not in item["request"]
117119
assert "body" not in item["request"]
@@ -160,12 +162,12 @@ def mask_response_body_callback(request: RequestDict, response: ResponseDict) ->
160162
request_dict["headers"] += [("Authorization", "Bearer 123456"), ("X-Test", "123456")]
161163
request_logger.log_request(request_dict, response_dict)
162164

163-
item = json.loads(request_logger.write_deque[0])
165+
item = request_logger.write_deque[0]
164166
assert item["request"]["url"] == f"http://localhost/test?secret={MASKED_QUOTED}&test={MASKED_QUOTED}&other=abcdef"
165-
assert ["Authorization", "Bearer 123456"] not in item["request"]["headers"]
166-
assert ["Authorization", MASKED] in item["request"]["headers"]
167-
assert ["X-Test", "123456"] not in item["request"]["headers"]
168-
assert ["X-Test", MASKED] in item["request"]["headers"]
169-
assert ["Accept", "text/plain"] in item["request"]["headers"]
170-
assert item["request"]["body"] == base64.b64encode(BODY_MASKED).decode()
171-
assert item["response"]["body"] == base64.b64encode(BODY_MASKED).decode()
167+
assert ("Authorization", "Bearer 123456") not in item["request"]["headers"]
168+
assert ("Authorization", MASKED) in item["request"]["headers"]
169+
assert ("X-Test", "123456") not in item["request"]["headers"]
170+
assert ("X-Test", MASKED) in item["request"]["headers"]
171+
assert ("Accept", "text/plain") in item["request"]["headers"]
172+
assert item["request"]["body"] == BODY_MASKED
173+
assert item["response"]["body"] == BODY_MASKED

‎tests/test_client_server_errors.py

Lines changed: 9 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -29,17 +29,23 @@ def test_server_error_counter():
2929

3030

3131
def test_exception_truncation(mocker: MockerFixture):
32-
from apitally.client.server_errors import ServerErrorCounter
32+
from apitally.client.server_errors import (
33+
get_exception_type,
34+
get_truncated_exception_msg,
35+
get_truncated_exception_traceback,
36+
)
3337

3438
mocker.patch("apitally.client.server_errors.MAX_EXCEPTION_MSG_LENGTH", 32)
3539
mocker.patch("apitally.client.server_errors.MAX_EXCEPTION_TRACEBACK_LENGTH", 128)
3640

3741
try:
3842
raise ValueError("a" * 88)
3943
except ValueError as e:
40-
msg = ServerErrorCounter._get_truncated_exception_msg(e)
41-
tb = ServerErrorCounter._get_truncated_exception_traceback(e)
44+
type_ = get_exception_type(e)
45+
msg = get_truncated_exception_msg(e)
46+
tb = get_truncated_exception_traceback(e)
4247

48+
assert type_ == "builtins.ValueError"
4349
assert len(msg) == 32
4450
assert msg.endswith("... (truncated)")
4551
assert len(tb) <= 128

0 commit comments

Comments
 (0)