8000 add tracing for handler chain (#7908) · codeperl/localstack@f141482 · GitHub
[go: up one dir, main page]
Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly
Appearance settings

Commit f141482

Browse files
thrauthrau
authored
add tracing for handler chain (localstack#7908)
1 parent d28e4c3 commit f141482

File tree

3 files changed

+359
-0
lines changed

3 files changed

+359
-0
lines changed

‎localstack/aws/app.py

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,9 @@
1+
from localstack import config
12
from localstack.aws import handlers
3+
from localstack.aws.chain import HandlerChain
24
from localstack.aws.handlers.metric_handler import MetricHandler
35
from localstack.aws.handlers.service_plugin import ServiceLoader
6+
from localstack.aws.trace import TracingHandlerChain
47
from localstack.services.plugins import SERVICE_PLUGINS, ServiceManager, ServicePluginManager
58
from localstack.utils.ssl import create_ssl_cert, install_predefined_cert_if_available
69

@@ -71,6 +74,13 @@ def __init__(self, service_manager: ServiceManager = None) -> None:
7174
]
7275
)
7376

77+
def new_chain(self) -> HandlerChain:
78+
if config.DEBUG_HANDLER_CHAIN:
79+
return TracingHandlerChain(
80+
self.request_handlers, self.response_handlers, self.exception_handlers
81+
)
82+
return super().new_chain()
83+
7484

7585
def main():
7686
"""

‎localstack/aws/trace.py

Lines changed: 345 additions & 0 deletions
< F438 /tr>
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,345 @@
1+
import dataclasses
2+
import inspect
3+
import logging
4+
import time
5+
from typing import Any, Callable
6+
7+
from werkzeug.datastructures import Headers
8+
9+
from localstack.http import Response
10+
from localstack.utils.patch import Patch, Patches
11+
12+
from .api import RequestContext
13+
from .chain import ExceptionHandler, Handler, HandlerChain
14+
15+
LOG = logging.getLogger(__name__)
16+
17+
18+
class Action:
19+
"""
20+
Encapsulates something that the handler performed on the request context, request, or response objects.
21+
"""
22+
23+
name: str
24+
25+
def __init__(self, name: str):
26+
self.name = name
27+
28+
def __repr__(self):
29+
return self.name
30+
31+
32+
class SetAttributeAction(Action):
33+
"""
34+
The handler set an attribute of the request context or something else.
35+
"""
36+
37+
key: str
38+
value: Any | None
39+
40+
def __init__(self, key: str, value: Any | None = None):
41+
super().__init__("set")
42+
self.key = key
43+
self.value = value
44+
45+
def __repr__(self):
46+
if self.value is None:
47+
return f"set {self.key}"
48+
return f"set {self.key} = {self.value!r}"
49+
50+
51+
class ModifyHeadersAction(Action):
52+
"""
53+
The handler modified headers in some way, either adding, updating, or removing headers.
54+
"""
55+
56+
def __init__(self, name: str, before: Headers, after: Headers):
57+
super().__init__(name)
58+
self.before = before
59+
self.after = after
60+
61+
@property
62+
def header_actions(self) -> list[Action]:
63+
after = self.after
64+
before = self.before
65+
66+
actions = []
67+
68+
headers_set = dict(set(after.items()) - set(before.items()))
69+
headers_removed = {k: v for k, v in before.items() if k not in after}
70+
71+
for k, v in headers_set.items():
72+
actions.append(Action(f"set '{k}: {v}'"))
73+
for k, v in headers_removed.items():
74+
actions.append(Action(f"del '{k}: {v}'"))
75+
76+
return actions
77+
78+
79+
@dataclasses.dataclass
80+
class HandlerTrace:
81+
handler: Handler
82+
"""The handler"""
83+
duration_ms: float
84+
"""The runtime duration of the handler in milliseconds"""
85+
actions: list[Action]
86+
"""The actions the handler chain performed"""
87+
88+
@property
89+
def handler_module(self):
90+
return self.handler.__module__
91+
92+
@property
93+
def handler_name(self):
94+
if inspect.isfunction(self.handler):
95+
return self.handler.__name__
96+
else:
97+
return self.handler.__class__.__name__
98+
99+
100+
def _log_method_call(name: str, actions: list[Action]):
101+
"""Creates a wrapper around the original method `_fn`. It appends an action to the `actions`
102+
list indicating that the function was called and then returns the original function."""
103+
104+
def _proxy(self, _fn, *args, **kwargs):
105+
actions.append(Action(f"call {name}"))
106+
return _fn(*args, **kwargs)
107+
108+
return _proxy
109+
110+
111+
class TracingHandlerBase:
112+
"""
113+
This class is a Handler that records a trace of the execution of another request handler. It has two
114+
attributes: `trace`, which stores the tracing information, and `delegate`, which is the handler or
115+
exception handler that will be traced.
116+
"""
117+
118+
trace: HandlerTrace | None
119+
delegate: Handler | ExceptionHandler
120+
121+
def __init__(self, delegate: Handler | ExceptionHandler):
122+
self.trace = None
123+
self.delegate = delegate
124+
125+
def do_trace_call(
126< 10000 /td>+
self, fn: Callable, chain: HandlerChain, context: RequestContext, response: Response
127+
):
128+
"""
129+
Wraps the function call with the tracing functionality and records a HandlerTrace.
130+
131+
The method determines changes made by the request handler to specific aspects of the request.
132+
Changes made to the request context and the response headers/status by the request handler are then
133+
examined, and appropriate actions are added to the `actions` list of the trace.
134+
135+
:param fn: which is the function to be traced, which is the request/response/exception handler
136+
:param chain: the handler chain
137+
:param context: the request context
138+
:param response: the response object
139+
"""
140+
then = time.perf_counter()
141+
142+
actions = []
143+
144+
prev_context = dict(context.__dict__)
145+
prev_stopped = chain.stopped
146+
prev_request_identity = id(context.request)
147+
prev_terminated = chain.terminated
148+
prev_request_headers = context.request.headers.copy()
149+
prev_response_headers = response.headers.copy()
150+
prev_response_status = response.status_code
151+
152+
# add patches to log invocations or certain functions
153+
patches = Patches(
154+
[
155+
Patch.function(
156+
context.request.get_data,
157+
_log_method_call("request.get_data", actions),
158+
),
159+
Patch.function(
160+
context.request._load_form_data,
161+
_log_method_call("request._load_form_data", actions),
162+
),
163+
Patch.function(
164+
response.get_data,
165+
_log_method_call("response.get_data", actions),
166+
),
167+
]
168+
)
169+
patches.apply()
170+
171+
try:
172+
return fn()
173+
finally:
174+
now = time.perf_counter()
175+
# determine some basic things the handler changed in the context
176+
patches.undo()
177+
178+
# chain
179+
if chain.stopped and not prev_stopped:
180+
actions.append(Action("stop chain"))
181+
if chain.terminated and not prev_terminated:
182+
actions.append(Action("terminate chain"))
183+
184+
# request contex
185+
if context.region and not prev_context.get("region"):
186+
actions.append(SetAttributeAction("region", context.region))
187+
if context.account_id and not prev_context.get("account_id"):
188+
actions.append(SetAttributeAction("account_id", context.account_id))
189+
if context.service and not prev_context.get("service"):
190+
actions.append(SetAttributeAction("service", context.service.service_name))
191+
if context.operation and not prev_context.get("operation"):
192+
actions.append(SetAttributeAction("operation", context.operation.name))
193+
if context.service_request and not prev_context.get("service_request"):
194+
actions.append(SetAttributeAction("service_request"))
195+
if context.service_response and not prev_context.get("service_response"):
196+
actions.append(SetAttributeAction("service_response"))
197+
198+
# request
199+
if id(context.request) != prev_request_identity:
200+
actions.append(Action("replaced request object"))
201+
202+
# response
203+
if response.status_code != prev_response_status:
204+
actions.append(SetAttributeAction("response stats_code", response.status_code))
205+
if context.request.headers != prev_request_headers:
206+
actions.append(
207+
ModifyHeadersAction(
208+
"modify request headers",
209+
prev_request_headers,
210+
context.request.headers.copy(),
211+
)
212+
)
213+
if response.headers != prev_response_headers:
214+
actions.append(
215+
ModifyHeadersAction(
216+
"modify response headers", prev_response_headers, response.headers.copy()
217+
)
218+
)
219+
220+
self.trace = HandlerTrace(
221+
handler=self.delegate, duration_ms=(now - then) * 1000, actions=actions
222+
)
223+
224+
225+
class TracingHandler(Handler, TracingHandlerBase):
226+
delegate: Handler
227+
228+
def __init__(self, delegate: Handler):
229+
super().__init__(delegate)
230+
231+
def __call__(self, chain: HandlerChain, context: RequestContext, response: Response):
232+
def _call():
233+
return self.delegate(chain, context, response)
234+
235+
return self.do_trace_call(_call, chain, context, response)
236+
237+
238+
class TracingExceptionHandler(ExceptionHandler, TracingHandlerBase):
239+
delegate: ExceptionHandler
240+
241+
def __init__(self, delegate: ExceptionHandler):
242+
super().__init__(delegate)
243+
244+
def __call__(
245+
self, chain: HandlerChain, exception: Exception, context: RequestContext, response: Response
246+
):
247+
def _call():
248+
return self.delegate(chain, exception, context, response)
249+
250+
return self.do_trace_call(_call, chain, context, response)
251+
252+
253+
class TracingHandlerChain(HandlerChain):
254+
"""
255+
DebuggingHandlerChain - A subclass of HandlerChain for logging and tracing handlers.
256+
10000 257+
Attributes:
258+
- duration (float): Total time taken for handling request in milliseconds.
259+
- request_handler_traces (list[HandlerTrace]): List of request handler traces.
260+
- response_handler_traces (list[HandlerTrace]): List of response handler traces.
261+
- exception_handler_traces (list[HandlerTrace]): List of exception handler traces.
262+
263+
Methods:
264+
- handle(context: RequestContext, response: Response):
265+
- _call_response_handlers(response): .
266+
- _call_exception_handlers(e, response): Overrides HandlerChain's _call_exception_handlers method and adds tracing handler to exception handlers.
267+
- _log_report(): Logs the trace report in the format specified.
268+
"""
269+
270+
duration: float
271+
request_handler_traces: list[HandlerTrace]
272+
response_handler_traces: list[HandlerTrace]
273+
exception_handler_traces: list[HandlerTrace]
274+
275+
def __init__(self, *args, **kwargs):
276+
super().__init__(*args, **kwargs)
277+
self.request_handler_traces = []
278+
self.response_handler_traces = []
279+
self.exception_handler_traces = []
280+
281+
def handle(self, context: RequestContext, response: Response):
282+
"""Overrides HandlerChain's handle method and adds tracing handler to request handlers. Logs the trace
283+
report with request and response details."""
284+
then = time.perf_counter()
285+
try:
286+
self.request_handlers = [TracingHandler(handler) for handler in self.request_handlers]
287+
return super().handle(context, response)
288+
finally:
289+
self.duration = (time.perf_counter() - then) * 1000
290+
self.request_handler_traces = [handler.trace for handler in self.request_handlers]
291+
self._log_report()
292+
293+
def _call_response_handlers(self, response):
294+
self.response_handlers = [TracingHandler(handler) for handler in self.response_handlers]
295+
try:
296+
return super()._call_response_handlers(response)
297+
finally:
298+
self.response_handler_traces = [handler.trace for handler in self.response_handlers]
299+
300< 10000 /code>+
def _call_exception_handlers(self, e, response):
301+
self.exception_handlers = [
302+
TracingExceptionHandler(handler) for handler in self.exception_handlers
303+
]
304+
try:
305+
return super()._call_exception_handlers(e, response)
306+
finally:
307+
self.exception_handler_traces = [handler.trace for handler in self.exception_handlers]
308+
309+
def _log_report(self):
310+
report = []
311+
request = self.context.request
312+
response = self.response
313+
314+
def _append_traces(traces: list[HandlerTrace]):
315+
"""Format and appends a list of traces to the report, and recursively append the trace's
316+
actions (if any)."""
317+
318+
for trace in traces:
319+
if trace is None:
320+
continue
321+
322+
report.append(
323+
f"{trace.handler_module:43s} {trace.handler_name:30s} {trace.duration_ms:8.2f}ms"
324+
)
325+
_append_actions(trace.actions, 46)
326+
327+
def _append_actions(actions: list[Action], indent: int):
328+
for action in actions:
329+
report.append((" " * indent) + f"- {action!r}")
330+
331+
if isinstance(action, ModifyHeadersAction):
332+
_append_actions(action.header_actions, indent + 2)
333+
334+
report.append(f"request: {request.method} {request.url}")
335+
report.append(f"response: {response.status_code}")
336+
report.append("---- request handlers " + ("-" * 63))
337+
_append_traces(self.request_handler_traces)
338+
report.append("---- response handlers " + ("-" * 63))
339+
_append_traces(self.response_handler_traces)
340+
report.append("---- exception handlers " + ("-" * 63))
341+
_append_traces(self.exception_handler_traces)
342+
# Add a separator and total duration value to the end of the report
343+
report.append(f"{'=' * 68} total {self.duration:8.2f}ms")
344+
345+
LOG.info("handler chain trace report:\n%s\n%s", "=" * 85, "\n".join(report))

‎localstack/config.py

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -477,6 +477,9 @@ def in_docker():
477477
DISABLE_EVENTS = is_env_true("DISABLE_EVENTS")
478478
DEBUG_ANALYTICS = is_env_true("DEBUG_ANALYTICS")
479479

480+
# whether to log fine-grained debugging information for the handler chain
481+
DEBUG_HANDLER_CHAIN = is_env_true("DEBUG_HANDLER_CHAIN")
482+
480483
# whether to eagerly start services
481484
EAGER_SERVICE_LOADING = is_env_true("EAGER_SERVICE_LOADING")
482485

@@ -785,6 +788,7 @@ def in_docker():
785788
"CFN_ENABLE_RESOLVE_REFS_IN_MODELS",
786789
"CUSTOM_SSL_CERT_PATH",
787790
"DEBUG",
791+
"DEBUG_HANDLER_CHAIN",
788792
"DEFAULT_REGION",
789793
"DEVELOP",
790794
"DEVELOP_PORT",

0 commit comments

Comments
 (0)
0