Skip to content

feat(rpc): Add more query logging #104480

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

Open
wmak wants to merge 1 commit into
base: master
Choose a base branch
from
Open

feat(rpc): Add more query logging #104480

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
16 changes: 0 additions & 16 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,18 +108,6 @@ def check_timeseries_has_data(timeseries: SnubaData, y_axes: list[str]):
return False


def log_rpc_request(message: str, rpc_request, rpc_logger: logging.Logger = logger):
rpc_debug_json = json.loads(MessageToJson(rpc_request))
rpc_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 @@ -343,7 +331,6 @@ def _run_table_query(
"""Run the query"""
table_request = cls.get_table_rpc_request(query)
rpc_request = table_request.rpc_request
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 @@ -553,7 +540,6 @@ def update_timestamps(
def _run_timeseries_rpc(
self, debug: bool, rpc_request: TimeSeriesRequest
) -> TimeSeriesResponse:
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 @@ -816,8 +802,6 @@ def run_top_events_timeseries_query(
requests.append(other_request)

"""Run the query"""
for rpc_request in requests:
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]
Expand Down
54 changes: 48 additions & 6 deletions src/sentry/utils/snuba_rpc.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
from __future__ import annotations

import logging
import os
from concurrent.futures import ThreadPoolExecutor
from dataclasses import dataclass
Expand All @@ -9,6 +10,7 @@
import sentry_sdk
import sentry_sdk.scope
import urllib3
from google.protobuf.json_format import MessageToJson
from google.protobuf.message import Message as ProtobufMessage
from rest_framework.exceptions import NotFound
from sentry_protos.snuba.v1.endpoint_create_subscription_pb2 import (
Expand Down Expand Up @@ -44,8 +46,10 @@
from sentry_protos.snuba.v1.request_common_pb2 import RequestMeta
from urllib3.response import BaseHTTPResponse

from sentry.utils import json, metrics
from sentry.utils.snuba import SnubaError, _snuba_pool

logger = logging.getLogger(__name__)
Copy link

@sentry sentry bot Dec 5, 2025

Choose a reason for hiding this comment

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

Bug: Removed log_rpc_request() function but left an orphaned call site in spans_rpc.py, causing an AttributeError on timeout.
Severity: CRITICAL | Confidence: High

🔍 Detailed Analysis

The pull request removed the log_rpc_request() function from rpc_dataset_common.py, but a call site in spans_rpc.py (around line 323) was not removed. When a trace query times out during pagination, this orphaned call will attempt to execute rpc_dataset_common.log_rpc_request(), leading to an AttributeError: module 'sentry.snuba.rpc_dataset_common' has no attribute 'log_rpc_request'. This unhandled exception will crash the request handler.

💡 Suggested Fix

Remove the orphaned call to rpc_dataset_common.log_rpc_request() in spans_rpc.py (around line 323) or migrate its logging logic to the new snuba_rpc.py.

🤖 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/utils/snuba_rpc.py#L52

Potential issue: The pull request removed the `log_rpc_request()` function from
`rpc_dataset_common.py`, but a call site in `spans_rpc.py` (around line 323) was not
removed. When a trace query times out during pagination, this orphaned call will attempt
to execute `rpc_dataset_common.log_rpc_request()`, leading to an `AttributeError: module
'sentry.snuba.rpc_dataset_common' has no attribute 'log_rpc_request'`. This unhandled
exception will crash the request handler.

Did we get this right? 👍 / 👎 to inform future reviews.
Reference ID: 5900602

RPCResponseType = TypeVar("RPCResponseType", bound=ProtobufMessage)

# Show the snuba query params and the corresponding sql or errors in the server logs
Expand Down Expand Up @@ -109,10 +113,23 @@ def _make_rpc_requests(
timeseries_requests = [] if timeseries_requests is None else timeseries_requests
requests = table_requests + timeseries_requests

endpoint_names = [
"EndpointTraceItemTable" if isinstance(req, TraceItemTableRequest) else "EndpointTimeSeries"
for req in requests
]
endpoint_names: list[str] = []
for request in requests:
endpoint_name = (
"EndpointTraceItemTable"
if isinstance(request, TraceItemTableRequest)
else "EndpointTimeSeries"
)
endpoint_names.append(endpoint_name)
logger.info(
f"Running a {endpoint_name} RPC query", # noqa: LOG011
extra={
"rpc_query": json.loads(MessageToJson(request)),
"referrer": request.meta.referrer,
"organization_id": request.meta.organization_id,
"trace_item_type": request.meta.trace_item_type,
},
)

referrers = [req.meta.referrer for req in requests]
assert (
Expand Down Expand Up @@ -150,10 +167,37 @@ def _make_rpc_requests(
table_response = TraceItemTableResponse()
table_response.ParseFromString(item.data)
table_results.append(table_response)

if len(table_response.column_values) > 0:
rpc_rows = len(table_response.column_values[0].results)
else:
rpc_rows = 0
logger.info(
"Table RPC query response",
extra={
"rpc_rows": rpc_rows,
"page_token": table_response.page_token,
"meta": table_response.meta,
},
)
metrics.distribution("snuba_rpc.table_response.length", rpc_rows)
elif isinstance(request, TimeSeriesRequest):
timeseries_response = TimeSeriesResponse()
timeseries_response.ParseFromString(item.data)
timeseries_results.append(timeseries_response)

if len(timeseries_response.result_timeseries) > 0:
rpc_rows = len(timeseries_response.result_timeseries[0].data_points)
else:
rpc_rows = 0
logger.info(
"Table RPC query response",
extra={
"rpc_rows": rpc_rows,
"meta": timeseries_response.meta,
},
)
Copy link
Contributor

@cursor cursor bot Dec 5, 2025

Choose a reason for hiding this comment

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

Bug: Incorrect log message for timeseries response

The log message for timeseries responses incorrectly states "Table RPC query response" when it should indicate a timeseries response. This appears to be a copy-paste error from the table response logging block above. This will make it difficult to distinguish between table and timeseries query responses in logs, hindering debugging and monitoring efforts.

Fix in Cursor Fix in Web

metrics.distribution("snuba_rpc.timeseries_response.length", rpc_rows)
return MultiRpcResponse(table_results, timeseries_results)


Expand Down Expand Up @@ -271,8 +315,6 @@ def _make_rpc_request(
sentry_sdk.get_current_scope() if thread_current_scope is None else thread_current_scope
)
if SNUBA_INFO:
from google.protobuf.json_format import MessageToJson

log_snuba_info(f"{referrer}.body:\n{MessageToJson(req)}") # type: ignore[arg-type]
with sentry_sdk.scope.use_isolation_scope(thread_isolation_scope):
with sentry_sdk.scope.use_scope(thread_current_scope):
Expand Down
Loading