Skip to content

Commit 49ae4f5

Browse files
authored
Merge pull request #326 from genlayer-foundation/JoaquinBN/query-logging
Add request tracing and bottleneck identification
2 parents 94ecbcc + 85116bc commit 49ae4f5

13 files changed

Lines changed: 422 additions & 60 deletions

File tree

backend/api/apps.py

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,3 +4,8 @@
44
class ApiConfig(AppConfig):
55
default_auto_field = 'django.db.models.BigAutoField'
66
name = 'api'
7+
8+
def ready(self):
9+
"""Initialize DRF tracing when the app is ready."""
10+
from tally.middleware.drf_tracing import install_drf_tracing
11+
install_drf_tracing()

backend/contributions/recaptcha_field.py

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,8 @@
99
from django_recaptcha.fields import ReCaptchaField as DjangoReCaptchaField
1010
from django_recaptcha.widgets import ReCaptchaV2Checkbox
1111

12+
from tally.middleware.tracing import trace_external
13+
1214

1315
class ReCaptchaField(serializers.Field):
1416
"""
@@ -55,7 +57,8 @@ def to_internal_value(self, data):
5557
try:
5658
# Use django-recaptcha's validation
5759
# The field expects the token value directly
58-
cleaned_value = self.django_field.clean(data)
60+
with trace_external('recaptcha', 'verify'):
61+
cleaned_value = self.django_field.clean(data)
5962
return cleaned_value
6063
except Exception as e:
6164
# Handle various validation errors
Lines changed: 11 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,14 @@
1-
"""Tally middleware package for logging."""
1+
"""Tally middleware package for logging and tracing."""
22
from .api_logging import APILoggingMiddleware
33
from .db_logging import DBLoggingMiddleware
4+
from .tracing import (
5+
trace_segment,
6+
trace_external,
7+
)
48

5-
__all__ = ['APILoggingMiddleware', 'DBLoggingMiddleware']
9+
__all__ = [
10+
'APILoggingMiddleware',
11+
'DBLoggingMiddleware',
12+
'trace_segment',
13+
'trace_external',
14+
]

backend/tally/middleware/api_logging.py

Lines changed: 55 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,9 @@
11
"""
22
API Layer Logging Middleware.
33
4-
Logs HTTP requests/responses for the [API] layer (Frontend <-> Backend).
4+
Logs HTTP requests/responses for the [API] layer with smart trace breakdown.
5+
- DEBUG=true: Logs all requests; shows breakdown for slow requests (>100ms)
6+
- DEBUG=false: Logs only 5xx errors with breakdown
57
"""
68
import time
79
from django.conf import settings
@@ -13,17 +15,25 @@
1315
clear_correlation_id,
1416
format_bytes,
1517
)
18+
from .tracing import (
19+
init_tracing,
20+
clear_tracing,
21+
get_segments,
22+
format_breakdown,
23+
should_expand_trace,
24+
)
1625

1726

1827
logger = get_api_logger()
1928

2029

2130
class APILoggingMiddleware:
2231
"""
23-
Middleware to log HTTP requests and responses.
32+
Middleware to log HTTP requests and responses with trace breakdown.
2433
25-
DEBUG=true: Logs all requests with method, path, status, duration, size
26-
DEBUG=false: Logs only errors (4xx, 5xx)
34+
Logging behavior:
35+
- DEBUG=true: All requests logged; breakdown shown for requests > 100ms
36+
- DEBUG=false: Only 5xx errors logged (always with breakdown)
2737
"""
2838

2939
# Paths to skip logging
@@ -43,9 +53,10 @@ def __call__(self, request):
4353
if any(request.path.startswith(path) for path in self.SKIP_PATHS):
4454
return self.get_response(request)
4555

46-
# Generate and set correlation ID
56+
# Initialize request tracking
4757
correlation_id = generate_correlation_id()
4858
set_correlation_id(correlation_id)
59+
init_tracing()
4960

5061
# Start timing
5162
start_time = time.time()
@@ -62,35 +73,57 @@ def __call__(self, request):
6273
# Get DB stats if available (set by DBLoggingMiddleware)
6374
db_query_count = getattr(request, '_db_query_count', 0)
6475
db_time_ms = getattr(request, '_db_time_ms', 0)
65-
logic_time_ms = duration_ms - db_time_ms
6676

67-
# Build log message with timing breakdown
68-
if db_query_count > 0:
69-
timing_info = f"{duration_ms:.0f}ms (db: {db_time_ms:.0f}ms/{db_query_count}q, logic: {logic_time_ms:.0f}ms)"
70-
else:
71-
timing_info = f"{duration_ms:.0f}ms"
77+
# Get trace segments
78+
segments = get_segments()
79+
80+
# Build timing info string
81+
timing_info = self._build_timing_info(duration_ms, db_time_ms, db_query_count)
7282

83+
# Build log message
7384
log_message = (
7485
f"{request.method} {request.path} "
7586
f"{response.status_code} "
7687
f"{timing_info} "
7788
f"{format_bytes(response_size)}"
7889
)
7990

80-
# Log based on status code and DEBUG setting
81-
is_error = response.status_code >= 400
91+
# Determine logging behavior
92+
is_server_error = response.status_code >= 500
93+
is_slow = should_expand_trace(duration_ms)
94+
has_segments = len(segments) > 0
8295

83-
if is_error:
84-
# Always log errors
85-
if response.status_code >= 500:
86-
logger.error(log_message)
87-
else:
88-
logger.warning(log_message)
96+
if is_server_error:
97+
# Always log 5xx errors with breakdown
98+
logger.error(log_message)
99+
if has_segments:
100+
self._log_breakdown(segments, level='error')
89101
elif settings.DEBUG:
90-
# In debug mode, log all requests
91-
logger.info(log_message)
102+
# In DEBUG mode, log all requests
103+
logger.debug(log_message)
104+
# Show breakdown for slow requests
105+
if is_slow and has_segments:
106+
self._log_breakdown(segments, level='debug')
92107

93-
# Clear correlation ID
108+
# Clear request tracking
94109
clear_correlation_id()
110+
clear_tracing()
95111

96112
return response
113+
114+
def _build_timing_info(self, duration_ms: float, db_time_ms: float, db_query_count: int) -> str:
115+
"""Build the timing info string for the log message."""
116+
if db_query_count > 0:
117+
return f"{duration_ms:.0f}ms (db: {db_time_ms:.0f}ms/{db_query_count}q)"
118+
return f"{duration_ms:.0f}ms"
119+
120+
def _log_breakdown(self, segments: list, level: str = 'debug') -> None:
121+
"""Log the trace breakdown with indentation."""
122+
breakdown = format_breakdown(segments)
123+
if breakdown:
124+
# Log each line of the breakdown
125+
for line in breakdown.split('\n'):
126+
if level == 'error':
127+
logger.error(line)
128+
else:
129+
logger.debug(line)
Lines changed: 142 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,142 @@
1+
"""
2+
DRF Automatic Instrumentation.
3+
4+
Monkey-patches Django REST Framework to automatically trace key lifecycle methods.
5+
This enables bottleneck identification without modifying existing view code.
6+
"""
7+
import functools
8+
from typing import Callable, Any
9+
10+
from .tracing import trace_segment
11+
12+
# Flag to ensure we only install once
13+
_installed = False
14+
15+
16+
def _wrap_method(original_method: Callable, segment_name: str) -> Callable:
17+
"""
18+
Wrap a method to trace its execution time.
19+
20+
Args:
21+
original_method: The original method to wrap
22+
segment_name: Name for the trace segment
23+
24+
Returns:
25+
Wrapped method that traces execution time
26+
"""
27+
@functools.wraps(original_method)
28+
def wrapper(*args, **kwargs) -> Any:
29+
with trace_segment(segment_name):
30+
return original_method(*args, **kwargs)
31+
return wrapper
32+
33+
34+
def _wrap_method_with_dynamic_name(original_method: Callable, name_prefix: str) -> Callable:
35+
"""
36+
Wrap a method with a dynamic segment name based on the class.
37+
38+
Args:
39+
original_method: The original method to wrap
40+
name_prefix: Prefix for the segment name (class name will be appended)
41+
42+
Returns:
43+
Wrapped method that traces execution time
44+
"""
45+
@functools.wraps(original_method)
46+
def wrapper(self, *args, **kwargs) -> Any:
47+
class_name = self.__class__.__name__
48+
segment_name = f"{name_prefix}:{class_name}"
49+
with trace_segment(segment_name):
50+
return original_method(self, *args, **kwargs)
51+
return wrapper
52+
53+
54+
def install_drf_tracing() -> None:
55+
"""
56+
Install automatic tracing on DRF classes.
57+
58+
Should be called once at application startup (e.g., in AppConfig.ready()).
59+
Instruments the following DRF methods:
60+
- APIView.check_permissions() -> "permissions"
61+
- APIView.check_throttles() -> "throttles"
62+
- GenericAPIView.get_serializer() -> "serializer:init"
63+
- GenericAPIView.get_queryset() -> "queryset:{ClassName}"
64+
- Serializer.to_representation() -> "serializer:render"
65+
- Serializer.to_internal_value() -> "serializer:parse"
66+
"""
67+
global _installed
68+
if _installed:
69+
return
70+
71+
try:
72+
from rest_framework.views import APIView
73+
from rest_framework.generics import GenericAPIView
74+
from rest_framework.serializers import Serializer
75+
76+
# Instrument APIView methods
77+
if hasattr(APIView, 'check_permissions'):
78+
APIView.check_permissions = _wrap_method(
79+
APIView.check_permissions,
80+
'permissions'
81+
)
82+
83+
if hasattr(APIView, 'check_throttles'):
84+
APIView.check_throttles = _wrap_method(
85+
APIView.check_throttles,
86+
'throttles'
87+
)
88+
89+
# Instrument GenericAPIView methods
90+
if hasattr(GenericAPIView, 'get_queryset'):
91+
GenericAPIView.get_queryset = _wrap_method_with_dynamic_name(
92+
GenericAPIView.get_queryset,
93+
'queryset'
94+
)
95+
96+
if hasattr(GenericAPIView, 'get_serializer'):
97+
GenericAPIView.get_serializer = _wrap_method(
98+
GenericAPIView.get_serializer,
99+
'serializer:init'
100+
)
101+
102+
# Instrument Serializer methods
103+
if hasattr(Serializer, 'to_representation'):
104+
original_to_representation = Serializer.to_representation
105+
106+
@functools.wraps(original_to_representation)
107+
def traced_to_representation(self, instance):
108+
# Only trace if this is the top-level serializer call
109+
# to avoid tracing nested serializer calls
110+
if not getattr(self, '_tracing_render', False):
111+
self._tracing_render = True
112+
try:
113+
with trace_segment('serializer:render'):
114+
return original_to_representation(self, instance)
115+
finally:
116+
self._tracing_render = False
117+
return original_to_representation(self, instance)
118+
119+
Serializer.to_representation = traced_to_representation
120+
121+
if hasattr(Serializer, 'to_internal_value'):
122+
original_to_internal = Serializer.to_internal_value
123+
124+
@functools.wraps(original_to_internal)
125+
def traced_to_internal_value(self, data):
126+
# Only trace if this is the top-level serializer call
127+
if not getattr(self, '_tracing_parse', False):
128+
self._tracing_parse = True
129+
try:
130+
with trace_segment('serializer:parse'):
131+
return original_to_internal(self, data)
132+
finally:
133+
self._tracing_parse = False
134+
return original_to_internal(self, data)
135+
136+
Serializer.to_internal_value = traced_to_internal_value
137+
138+
_installed = True
139+
140+
except ImportError:
141+
# DRF not installed, skip instrumentation
142+
pass

backend/tally/middleware/logging_utils.py

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -56,6 +56,7 @@ class LayeredFormatter(logging.Formatter):
5656
'tally.api': 'API',
5757
'tally.db': 'DB',
5858
'tally.app': 'APP',
59+
'tally.trace': 'TRACE',
5960
}
6061

6162
def format(self, record: logging.LogRecord) -> str:
@@ -86,6 +87,7 @@ class LayeredJSONFormatter(logging.Formatter):
8687
'tally.api': 'API',
8788
'tally.db': 'DB',
8889
'tally.app': 'APP',
90+
'tally.trace': 'TRACE',
8991
}
9092

9193
def format(self, record: logging.LogRecord) -> str:

0 commit comments

Comments
 (0)