Skip to content

feat(events): Add logging to debug queries #103766

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Nov 20, 2025
+91 −4
Merged

feat(events): Add logging to debug queries #103766

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
33 changes: 29 additions & 4 deletions src/sentry/snuba/rpc_dataset_common.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -108,6 +108,18 @@ def check_timeseries_has_data(timeseries: SnubaData, y_axes: list[str]):
return False


def log_rpc_request(message: str, rpc_request):
rpc_debug_json = json.loads(MessageToJson(rpc_request))
logger.info(
message,
extra={
"rpc_query": rpc_debug_json,
"referrer": rpc_request.meta.referrer,
"trace_item_type": rpc_request.meta.trace_item_type,
},
)


class RPCBase:
"""Utility Methods"""

Expand Down Expand Up @@ -322,6 +334,8 @@ def _run_table_query(
"""Run the query"""
table_request = cls.get_table_rpc_request(query)
rpc_request = table_request.rpc_request
if debug:
log_rpc_request("Running a table query with debug on", rpc_request)
try:
rpc_response = snuba_rpc.table_rpc([rpc_request])[0]
except Exception as e:
Expand Down Expand Up @@ -531,6 +545,8 @@ def update_timestamps(
def _run_timeseries_rpc(
self, debug: bool, rpc_request: TimeSeriesRequest
) -> TimeSeriesResponse:
if debug:
log_rpc_request("Running a timeseries query with debug on", rpc_request)
try:
return snuba_rpc.timeseries_rpc([rpc_request])[0]
except Exception as e:
Expand Down Expand Up @@ -793,10 +809,19 @@ def run_top_events_timeseries_query(
requests.append(other_request)

"""Run the query"""
timeseries_rpc_response = snuba_rpc.timeseries_rpc(requests)
rpc_response = timeseries_rpc_response[0]
if len(timeseries_rpc_response) > 1:
other_response = timeseries_rpc_response[1]
if params.debug:
for rpc_request in requests:
Copy link
Contributor

@cursor cursor bot Nov 20, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Bug: Variable shadowing causes wrong request in debug metadata

The logging loop reuses the variable name rpc_request, shadowing the first request that was assigned on line 786. This causes set_debug_meta on line 832 to receive the wrong request (the last one from the loop instead of the first one), mismatching it with rpc_response which is always the first response.

Fix in Cursor Fix in Web

log_rpc_request("Running a top events query with debug on", rpc_request)
try:
timeseries_rpc_response = snuba_rpc.timeseries_rpc(requests)
rpc_response = timeseries_rpc_response[0]
if len(timeseries_rpc_response) > 1:
other_response = timeseries_rpc_response[1]
except Exception as e:
# add the rpc to the error so we can include it in the response
if params.debug:
setattr(e, "debug", MessageToJson(rpc_request))
Copy link
Contributor

@cursor cursor bot Nov 20, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Bug: Wrong request attached to exception in error handler

The exception handler references rpc_request from the logging loop above, which contains only the last request from the requests list. When multiple requests are sent (e.g., when include_other is True), the wrong request gets attached to the exception. The error could be caused by any request in the list, but only the last one from the logging loop is captured.

Fix in Cursor Fix in Web

raise
Comment on lines +820 to +824
Copy link

@sentry sentry bot Nov 20, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Bug: The rpc_request variable is incorrectly reassigned in a loop, causing the exception handler and set_debug_meta to use the wrong request's debug information.
Severity: HIGH | Confidence: High

🔍 Detailed Analysis

The rpc_request variable is reassigned within the debug logging loop (lines 813-814). After the loop, rpc_request incorrectly holds the last item from the requests list (the other_request when include_other=True). This leads to incorrect debug information being attached to exceptions (lines 820-824) and in set_debug_meta (line 846) when params.debug=True and include_other=True. If the first request causes an error, the debug info will misleadingly show the second request's details, hindering effective debugging.

💡 Suggested Fix

Rename the loop variable rpc_request to avoid reassigning the outer scope's rpc_request. Alternatively, store the rpc_request that caused the error in a separate variable before the try block, or ensure the correct rpc_request is accessible in the except block.

🤖 Prompt for AI Agent 
Review the code at the location below. A potential bug has been identified by an AI
agent.
Verify if this is a real issue. If it is, propose a fix; if not, explain why it's not
valid.

Location: src/sentry/snuba/rpc_dataset_common.py#L820-L824

Potential issue: The `rpc_request` variable is reassigned within the debug logging loop
(lines 813-814). After the loop, `rpc_request` incorrectly holds the last item from the
`requests` list (the `other_request` when `include_other=True`). This leads to incorrect
debug information being attached to exceptions (lines 820-824) and in `set_debug_meta`
(line 846) when `params.debug=True` and `include_other=True`. If the first request
causes an error, the debug info will misleadingly show the second request's details,
hindering effective debugging.

Did we get this right? 👍 / 👎 to inform future reviews.
Reference_id: 2862835


"""Process the results"""
map_result_key_to_timeseries = defaultdict(list)
Expand Down
62 changes: 62 additions & 0 deletions tests/snuba/api/endpoints/test_organization_events_stats_span_indexed.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2442,6 +2442,68 @@ def test_debug_param(self) -> None:
]
)

def test_debug_with_top_events(self) -> None:
self.store_spans(
[
self.create_span(
{"sentry_tags": {"transaction": "foo", "status": "success"}},
start_ts=self.day_ago + timedelta(minutes=1),
duration=2000,
),
self.create_span(
{"sentry_tags": {"transaction": "bar", "status": "success"}},
start_ts=self.day_ago + timedelta(minutes=1),
duration=2000,
),
],
is_eap=True,
)

self.user = self.create_user("superuser@example.com", is_superuser=True)
self.create_team(organization=self.organization, members=[self.user])
self.login_as(user=self.user)

response = self._do_request(
data={
"start": self.day_ago,
"end": self.day_ago + timedelta(minutes=4),
"interval": "1m",
"query": "",
"yAxis": ["count()"],
"field": ["transaction"],
"project": self.project.id,
"dataset": "spans",
"topEvents": 2,
"debug": True,
},
)

assert response.status_code == 200, response.content

assert (
"FUNCTION_COUNT"
== response.data["bar"]["meta"]["debug_info"]["query"]["expressions"][0]["aggregation"][
"aggregate"
]
)

response = self._do_request(
data={
"start": self.day_ago,
"end": self.day_ago + timedelta(minutes=4),
"interval": "1m",
"query": "",
"yAxis": ["count()"],
"field": ["transaction"],
"project": self.project.id,
"dataset": "spans",
"topEvents": 2,
},
)

assert response.status_code == 200, response.content
assert "debug_info" not in response.data["bar"]["meta"]

@patch("sentry.utils.snuba_rpc.timeseries_rpc")
def test_debug_param_with_error(self, mock_query) -> None:
self.user = self.create_user("superuser@example.com", is_superuser=True)
Expand Down
Loading