-
-
Notifications
You must be signed in to change notification settings - Fork 4.4k
chore(issues): Add LoggedRetry to log retry information #94840
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.
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
base: master
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,50 @@ | ||
import logging | ||
from types import TracebackType | ||
from typing import Any, Self | ||
|
||
from urllib3 import BaseHTTPResponse | ||
from urllib3.connectionpool import ConnectionPool | ||
from urllib3.util.retry import Retry | ||
|
||
default_logger = logging.getLogger(__name__) | ||
|
||
|
||
class LoggedRetry(Retry): | ||
def __init__(self, logger: logging.Logger | None = None, **kwargs: Any) -> None: | ||
super().__init__(**kwargs) | ||
self.logger = logger or default_logger | ||
|
||
def increment( | ||
self, | ||
method: str | None = None, | ||
url: str | None = None, | ||
response: BaseHTTPResponse | None = None, | ||
error: Exception | None = None, | ||
_pool: ConnectionPool | None = None, | ||
_stacktrace: TracebackType | None = None, | ||
) -> Self: | ||
# Increment uses Retry.new to instantiate a new instance so we need to | ||
# manually propagate the logger as it can't be passed through increment. | ||
retry = super().increment( | ||
method=method, | ||
url=url, | ||
response=response, | ||
error=error, | ||
_pool=_pool, | ||
_stacktrace=_stacktrace, | ||
) | ||
retry.logger = self.logger | ||
|
||
extra: dict[str, str | int | None] = { | ||
"request_method": method, | ||
"request_url": url, | ||
"retry_total_remaining": retry.total, | ||
} | ||
if response is not None: | ||
extra["response_status"] = response.status | ||
if error is not None: | ||
extra["error"] = error.__class__.__name__ | ||
|
||
self.logger.info("Request retried", extra=extra) | ||
|
||
return retry |
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -14,6 +14,7 @@ | |
) | ||
from sentry.models.grouphashmetadata import GroupHashMetadata | ||
from sentry.net.http import connection_from_url | ||
from sentry.net.retry import LoggedRetry | ||
from sentry.seer.signed_seer_api import make_signed_seer_api_request | ||
from sentry.seer.similarity.types import ( | ||
IncompleteSeerDataError, | ||
|
@@ -65,14 +66,18 @@ def get_similarity_data_from_seer( | |
options.get("seer.similarity.circuit-breaker-config"), | ||
) | ||
|
||
retries: LoggedRetry | None = None | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. So is a There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Yeah, it's a bit weird but I wanted to keep consistency with |
||
if total := options.get("seer.similarity.grouping-ingest-retries"): | ||
retries = LoggedRetry(logger=logger, total=total) | ||
|
||
try: | ||
response = make_signed_seer_api_request( | ||
seer_grouping_connection_pool, | ||
SEER_SIMILAR_ISSUES_URL, | ||
json.dumps({"threshold": SEER_MAX_GROUPING_DISTANCE, **similar_issues_request}).encode( | ||
"utf8" | ||
), | ||
retries=options.get("seer.similarity.grouping-ingest-retries"), | ||
retries=retries, | ||
timeout=options.get("seer.similarity.grouping-ingest-timeout"), | ||
metric_tags={"referrer": referrer} if referrer else {}, | ||
) | ||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -183,7 +183,6 @@ def test_simple( | |
mock_seer_request.assert_called_with( | ||
"POST", | ||
SEER_SIMILAR_ISSUES_URL, | ||
retries=options.get("seer.similarity.grouping-ingest-retries"), | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I don't totally get how we're not passing this parameter anymore. Doesn't it just have a different value (either a There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This was a bit of a cleanup, the option defaults to At the end of the day the behavior is the same since POSTs default to 0 retries in urllib3 when retries is None. |
||
timeout=options.get("seer.similarity.grouping-ingest-timeout"), | ||
body=orjson.dumps(expected_seer_request_params), | ||
headers={"content-type": "application/json;charset=utf-8"}, | ||
|
@@ -613,7 +612,6 @@ def test_no_optional_params(self, mock_seer_request: mock.MagicMock) -> None: | |
mock_seer_request.assert_called_with( | ||
"POST", | ||
SEER_SIMILAR_ISSUES_URL, | ||
retries=options.get("seer.similarity.grouping-ingest-retries"), | ||
timeout=options.get("seer.similarity.grouping-ingest-timeout"), | ||
body=orjson.dumps( | ||
{ | ||
|
@@ -641,7 +639,6 @@ def test_no_optional_params(self, mock_seer_request: mock.MagicMock) -> None: | |
mock_seer_request.assert_called_with( | ||
"POST", | ||
SEER_SIMILAR_ISSUES_URL, | ||
retries=options.get("seer.similarity.grouping-ingest-retries"), | ||
timeout=options.get("seer.similarity.grouping-ingest-timeout"), | ||
body=orjson.dumps( | ||
{ | ||
|
@@ -672,7 +669,6 @@ def test_no_optional_params(self, mock_seer_request: mock.MagicMock) -> None: | |
mock_seer_request.assert_called_with( | ||
"POST", | ||
SEER_SIMILAR_ISSUES_URL, | ||
retries=options.get("seer.similarity.grouping-ingest-retries"), | ||
timeout=options.get("seer.similarity.grouping-ingest-timeout"), | ||
body=orjson.dumps( | ||
{ | ||
|
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,52 @@ | ||
import logging | ||
from unittest.mock import Mock, call, patch | ||
|
||
from urllib3 import PoolManager | ||
from urllib3.exceptions import ConnectTimeoutError | ||
from urllib3.response import HTTPResponse | ||
|
||
from sentry.net.retry import LoggedRetry | ||
|
||
|
||
def test_logged_retry() -> None: | ||
mock_logger = Mock(spec=logging.Logger) | ||
|
||
pool = PoolManager( | ||
retries=LoggedRetry(mock_logger, total=2, status_forcelist=[500]), | ||
) | ||
|
||
with patch( | ||
"urllib3.connectionpool.HTTPConnectionPool._make_request", | ||
side_effect=[ | ||
ConnectTimeoutError(), | ||
HTTPResponse(status=500, body=b"not ok"), | ||
HTTPResponse(status=200, body=b"ok"), | ||
], | ||
): | ||
response = pool.request("GET", "http://example.com") | ||
|
||
assert mock_logger.info.call_count == 2 | ||
mock_logger.assert_has_calls( | ||
[ | ||
call.info( | ||
"Request retried", | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. these logs are on top of other logs which log what actually happened on each attempt, right? and this just logs the state of the retry, with the actual failure getting logged however it gets logged There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Yep, these are purely additive |
||
extra={ | ||
"request_method": "GET", | ||
"request_url": "/", | ||
"retry_total_remaining": 1, | ||
"error": "ConnectTimeoutError", | ||
}, | ||
), | ||
call.info( | ||
"Request retried", | ||
extra={ | ||
"request_method": "GET", | ||
"request_url": "/", | ||
"retry_total_remaining": 0, | ||
"response_status": 500, | ||
}, | ||
), | ||
] | ||
) | ||
assert response.status == 200 | ||
assert response.data == b"ok" |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Is there a reason we're logging the error type but not the error message?