Skip to content

Commit 60ed644

Browse files
sfc-gh-dszmolkaMirror Bot
authored andcommitted
SNOW-4218352: log batch download retries at WARN, final failure at ERROR, and surface S3 request IDs
GitOrigin-RevId: bcf0607cb5c0943200275d116406cbf895f55e58
1 parent b4a5554 commit 60ed644

6 files changed

Lines changed: 143 additions & 22 deletions

File tree

‎DESCRIPTION.md‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,8 @@ https://docs.snowflake.com/
77
Source code is also available at: https://github.com/snowflakedb/snowflake-connector-python
88

99
# Release Notes
10+
- v4.8.1 (Unreleased)
11+
- Fixed large result set batch chunk download logging every transient retry at ERROR level with a traceback. Intermediate retries now log at WARNING; only the final failure after all retries are exhausted logs at ERROR with a traceback. These retry and failure logs now also include the S3 request IDs (`x-amz-request-id` / `x-amz-id-2`) when present, to aid troubleshooting and correlation with AWS-side records (SNOW-4218352).
1012
- v4.8.0(Sep 30,2026)
1113
- Fixed external-browser (SSO) authentication to validate the `Origin` header on the local callback server, rejecting tokens delivered from unexpected origins. A trailing slash in the origin (e.g. `https://account.snowflakecomputing.com/`) is now accepted on par with the bare origin, matching JDBC and other driver behaviour. Preconnect probe connections (empty recv) no longer count against the retry budget and no longer abort the login flow.
1214
- Added the `SNOWFLAKE_TLS_CIPHERS` environment variable to restrict which TLS ciphers the connector offers. It takes a colon-separated list; names beginning with `TLS_` are applied as TLS 1.3 cipher suites and the remainder as the cipher list for TLS 1.2 and below, so a single variable covers both. Leaving it unset keeps OpenSSL's defaults unchanged, and an unrecognized cipher name is rejected rather than silently ignored. The restriction covers Snowflake API traffic, cloud-storage (stage) transfers, OCSP/CRL fetches and IdP requests. Requests issued by the AWS and Azure SDKs, and asynchronous connections, are not covered — for TLS 1.3 suites specifically they cannot be, because the Python standard library exposes no API for restricting them.

‎src/snowflake/connector/aio/_result_batch.py‎

Lines changed: 11 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,7 @@
3434
from snowflake.connector.result_batch import ResultBatch as ResultBatchSync
3535
from snowflake.connector.result_batch import (
3636
_create_nanoarrow_iterator,
37+
_s3_request_id_log_suffix,
3738
inline_first_chunk_rowcount,
3839
)
3940
from snowflake.connector.secret_detector import SecretDetector
@@ -232,6 +233,7 @@ async def download_chunk(http_session):
232233

233234
content, encoding = None, None
234235
for retry in range(max(MAX_DOWNLOAD_RETRY, 1)):
236+
amz_request_id_suffix = ""
235237
try:
236238

237239
async with TimerContextManager() as download_metric:
@@ -284,6 +286,7 @@ async def download_chunk(http_session):
284286
) as session:
285287
response, content, encoding = await download_chunk(session)
286288

289+
amz_request_id_suffix = _s3_request_id_log_suffix(response)
287290
if response.status == OK:
288291
break
289292
# Raise error here to correctly go in to exception clause
@@ -301,12 +304,18 @@ async def download_chunk(http_session):
301304
if retry == MAX_DOWNLOAD_RETRY - 1:
302305
# Re-throw if we failed on the last retry
303306
e = e.args[0] if isinstance(e, RetryRequest) else e
307+
logger.error(
308+
f"Failed to fetch the large result set batch "
309+
f"{self.id} after {MAX_DOWNLOAD_RETRY} attempts, "
310+
f"giving up for the reason: '{e}'{amz_request_id_suffix}",
311+
exc_info=True,
312+
)
304313
raise e
305314
sleep_timer = next(backoff)
306-
logger.exception(
315+
logger.warning(
307316
f"Failed to fetch the large result set batch "
308317
f"{self.id} for the {retry + 1} th time, "
309-
f"backing off for {sleep_timer}s for the reason: '{e}'"
318+
f"backing off for {sleep_timer}s for the reason: '{e}'{amz_request_id_suffix}"
310319
)
311320
await asyncio.sleep(sleep_timer)
312321

‎src/snowflake/connector/result_batch.py‎

Lines changed: 33 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,29 @@
5555
MAX_INCOMPLETE_CHUNK_RETRY = 1
5656

5757

58+
def _s3_request_id_log_suffix(response: Response | None) -> str:
59+
"""Return a ``', S3 request id: ..., S3 extended request id: ...'`` log suffix, or ``''``.
60+
61+
S3 returns these trace headers (``x-amz-request-id`` / ``x-amz-id-2``) on every
62+
response, including error responses, so surfacing them in the retry/failure logs
63+
lets support correlate a failed chunk download with AWS-side records. Empty string
64+
when no response arrived (pure network failure) or the headers are absent (non-S3
65+
stage).
66+
"""
67+
headers = getattr(response, "headers", None)
68+
if headers is None or not hasattr(headers, "get"):
69+
return ""
70+
parts = []
71+
for name, label in (
72+
("x-amz-request-id", "S3 request id"),
73+
("x-amz-id-2", "S3 extended request id"),
74+
):
75+
value = headers.get(name)
76+
if isinstance(value, str) and value:
77+
parts.append(f"{label}: {value}")
78+
return f", {', '.join(parts)}" if parts else ""
79+
80+
5881
def inline_first_chunk_rowcount(data: dict[str, Any]) -> int:
5982
"""Rows attributed to the inline first chunk: ``total`` minus remote chunk rowCounts.
6083
@@ -520,6 +543,7 @@ def _download(
520543
else exponential_backoff()()
521544
)
522545
for retry in range(MAX_DOWNLOAD_RETRY):
546+
amz_request_id_suffix = ""
523547
try:
524548
with TimerContextManager() as download_metric:
525549
logger.debug(f"started downloading result batch id: {self.id}")
@@ -560,6 +584,7 @@ def _download(
560584
)
561585
response = local_session_manager.get(**request_data)
562586

587+
amz_request_id_suffix = _s3_request_id_log_suffix(response)
563588
if response.status_code == OK:
564589
logger.debug(
565590
f"successfully downloaded result batch id: {self.id}"
@@ -581,12 +606,18 @@ def _download(
581606
if retry == MAX_DOWNLOAD_RETRY - 1:
582607
# Re-throw if we failed on the last retry
583608
e = e.args[0] if isinstance(e, RetryRequest) else e
609+
logger.error(
610+
f"Failed to fetch the large result set batch "
611+
f"{self.id} after {MAX_DOWNLOAD_RETRY} attempts, "
612+
f"giving up for the reason: '{e}'{amz_request_id_suffix}",
613+
exc_info=True,
614+
)
584615
raise e
585616
sleep_timer = next(backoff)
586-
logger.exception(
617+
logger.warning(
587618
f"Failed to fetch the large result set batch "
588619
f"{self.id} for the {retry + 1} th time, "
589-
f"backing off for {sleep_timer}s for the reason: '{e}'"
620+
f"backing off for {sleep_timer}s for the reason: '{e}'{amz_request_id_suffix}"
590621
)
591622
time.sleep(sleep_timer)
592623

‎test/helpers.py‎

Lines changed: 14 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -48,27 +48,37 @@
4848
pass
4949

5050

51-
def create_mock_response(status_code: int) -> Mock:
51+
def create_mock_response(status_code: int, headers: dict | None = None) -> Mock:
5252
"""Create a Mock "Response" with a given status code. See `test_result_batch.py` for examples.
5353
Args:
5454
status_code: the status code of the response.
55+
headers: optional response headers (e.g. S3 ``x-amz-*`` trace headers).
5556
Returns:
5657
A Mock object that can be used as a Mock Response in tests.
5758
"""
5859
mock_resp = Mock()
5960
mock_resp.status_code = status_code
6061
mock_resp.raw = "success" if status_code == OK else "fail"
62+
mock_resp.headers = headers or {}
6163
return mock_resp
6264

6365

64-
def create_async_mock_response(status: int) -> AsyncMock:
65-
async def _create_async_mock_response(url, *, status, **kwargs):
66+
def create_async_mock_response(status: int, headers: dict | None = None) -> AsyncMock:
67+
# ``response_headers`` is named distinctly from the request ``headers`` kwarg the
68+
# real ``http_session.get(**request_data)`` passes, so the call-time request
69+
# headers don't override the bound response headers.
70+
async def _create_async_mock_response(
71+
url, *, status, response_headers=None, **kwargs
72+
):
6673
resp = AsyncMock(status=status)
6774
resp.read.return_value = "success" if status == OK else "fail"
6875
resp.status = status
76+
resp.headers = response_headers or {}
6977
return resp
7078

71-
return functools.partial(_create_async_mock_response, status=status)
79+
return functools.partial(
80+
_create_async_mock_response, status=status, response_headers=headers
81+
)
7282

7383

7484
def verify_log_tuple(

‎test/unit/aio/test_result_batch_async.py‎

Lines changed: 43 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -99,23 +99,44 @@ async def test_ok_response_download(mock_get):
9999
(555, OtherHTTPRetryableError), # random 5xx error
100100
],
101101
)
102-
async def test_retryable_response_download(errcode, error_class):
102+
async def test_retryable_response_download(errcode, error_class, caplog):
103103
"""This test checks that responses which are deemed 'retryable' are handled correctly."""
104104
# retryable exceptions
105+
amz_headers = {"x-amz-request-id": "test-req-id", "x-amz-id-2": "test-ext-id"}
105106
with mock.patch(
106-
REQUEST_MODULE_PATH + ".get", side_effect=create_async_mock_response(errcode)
107+
REQUEST_MODULE_PATH + ".get",
108+
side_effect=create_async_mock_response(errcode, headers=amz_headers),
107109
) as mock_get:
108110
# mock_get.return_value = create_async_mock_response(errcode)
109111

110112
with mock.patch("asyncio.sleep", return_value=None):
111-
with pytest.raises(error_class) as ex:
112-
_ = await result_batch._download()
113+
with caplog.at_level(
114+
logging.WARNING, logger="snowflake.connector.aio._result_batch"
115+
):
116+
with pytest.raises(error_class) as ex:
117+
_ = await result_batch._download()
113118
err_msg = ex.value.msg
114119
if isinstance(errcode, HTTPStatus):
115120
assert str(errcode.value) in err_msg
116121
else:
117122
assert str(errcode) in err_msg
118123
assert mock_get.call_count == MAX_DOWNLOAD_RETRY
124+
batch_logs = [
125+
r
126+
for r in caplog.records
127+
if r.name == "snowflake.connector.aio._result_batch"
128+
]
129+
assert (
130+
sum(r.levelno == logging.WARNING for r in batch_logs)
131+
== MAX_DOWNLOAD_RETRY - 1
132+
)
133+
assert sum(r.levelno == logging.ERROR for r in batch_logs) == 1
134+
# S3 trace headers are surfaced in every retry/failure log line (SNOW-4218352)
135+
assert all(
136+
"S3 request id: test-req-id" in r.getMessage()
137+
and "S3 extended request id: test-ext-id" in r.getMessage()
138+
for r in batch_logs
139+
)
119140

120141

121142
async def test_unauthorized_response_download():
@@ -150,21 +171,36 @@ async def test_non_200_response_download(status_code):
150171
assert mock_get.call_count == MAX_DOWNLOAD_RETRY
151172

152173

153-
async def test_retries_until_success():
174+
async def test_retries_until_success(caplog):
154175
with mock.patch(REQUEST_MODULE_PATH + ".get") as mock_get:
155176
error_codes = [BAD_REQUEST, UNAUTHORIZED, 201]
156177
# There is an OK added to the list of responses so that there is a success
157178
# and the retry loop ends.
179+
amz_headers = {"x-amz-request-id": "test-req-id", "x-amz-id-2": "test-ext-id"}
158180
mock_responses = [
159-
create_async_mock_response(code)("") for code in error_codes + [OK]
181+
create_async_mock_response(code, headers=amz_headers)("")
182+
for code in error_codes + [OK]
160183
]
161184
mock_get.side_effect = mock_responses
162185

163186
with mock.patch("asyncio.sleep", return_value=None):
164-
res, _ = await result_batch._download()
187+
with caplog.at_level(
188+
logging.WARNING, logger="snowflake.connector.aio._result_batch"
189+
):
190+
res, _ = await result_batch._download()
165191
assert res == "success"
166192
# call `get` once for each error and one last time when it succeeds
167193
assert mock_get.call_count == len(error_codes) + 1
194+
batch_logs = [
195+
r
196+
for r in caplog.records
197+
if r.name == "snowflake.connector.aio._result_batch"
198+
]
199+
assert sum(r.levelno == logging.WARNING for r in batch_logs) == len(error_codes)
200+
assert sum(r.levelno == logging.ERROR for r in batch_logs) == 0
201+
warning_logs = [r for r in batch_logs if r.levelno == logging.WARNING]
202+
assert warning_logs
203+
assert all("S3 request id: test-req-id" in r.getMessage() for r in warning_logs)
168204

169205

170206
@pytest.mark.skipolddriver

‎test/unit/test_result_batch.py‎

Lines changed: 40 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -123,21 +123,39 @@ def test_ok_response_download(mock_get):
123123
(555, OtherHTTPRetryableError), # random 5xx error
124124
],
125125
)
126-
def test_retryable_response_download(errcode, error_class):
126+
def test_retryable_response_download(errcode, error_class, caplog):
127127
"""This test checks that responses which are deemed 'retryable' are handled correctly."""
128128
# retryable exceptions
129+
amz_headers = {"x-amz-request-id": "test-req-id", "x-amz-id-2": "test-ext-id"}
129130
with mock.patch(SESSION_FROM_REQUEST_MODULE_PATH + ".get") as mock_get:
130-
mock_get.return_value = create_mock_response(errcode)
131+
mock_get.return_value = create_mock_response(errcode, headers=amz_headers)
131132

132133
with mock.patch("time.sleep", return_value=None):
133-
with pytest.raises(error_class) as ex:
134-
_ = result_batch._download()
134+
with caplog.at_level(
135+
logging.WARNING, logger="snowflake.connector.result_batch"
136+
):
137+
with pytest.raises(error_class) as ex:
138+
_ = result_batch._download()
135139
err_msg = ex.value.msg
136140
if isinstance(errcode, HTTPStatus):
137141
assert str(errcode.value) in err_msg
138142
else:
139143
assert str(errcode) in err_msg
140144
assert mock_get.call_count == MAX_DOWNLOAD_RETRY
145+
batch_logs = [
146+
r for r in caplog.records if r.name == "snowflake.connector.result_batch"
147+
]
148+
assert (
149+
sum(r.levelno == logging.WARNING for r in batch_logs)
150+
== MAX_DOWNLOAD_RETRY - 1
151+
)
152+
assert sum(r.levelno == logging.ERROR for r in batch_logs) == 1
153+
# S3 trace headers are surfaced in every retry/failure log line (SNOW-4218352)
154+
assert all(
155+
"S3 request id: test-req-id" in r.getMessage()
156+
and "S3 extended request id: test-ext-id" in r.getMessage()
157+
for r in batch_logs
158+
)
141159

142160

143161
def test_unauthorized_response_download():
@@ -170,19 +188,34 @@ def test_non_200_response_download(status_code):
170188
assert mock_get.call_count == MAX_DOWNLOAD_RETRY
171189

172190

173-
def test_retries_until_success():
191+
def test_retries_until_success(caplog):
174192
with mock.patch(SESSION_FROM_REQUEST_MODULE_PATH + ".get") as mock_get:
175193
error_codes = [BAD_REQUEST, UNAUTHORIZED, 201]
194+
amz_headers = {"x-amz-request-id": "test-req-id", "x-amz-id-2": "test-ext-id"}
176195
# There is an OK added to the list of responses so that there is a success
177196
# and the retry loop ends.
178-
mock_responses = [create_mock_response(code) for code in error_codes + [OK]]
197+
mock_responses = [
198+
create_mock_response(code, headers=amz_headers)
199+
for code in error_codes + [OK]
200+
]
179201
mock_get.side_effect = mock_responses
180202

181203
with mock.patch("time.sleep", return_value=None):
182-
res = result_batch._download()
204+
with caplog.at_level(
205+
logging.WARNING, logger="snowflake.connector.result_batch"
206+
):
207+
res = result_batch._download()
183208
assert res.raw == "success"
184209
# call `get` once for each error and one last time when it succeeds
185210
assert mock_get.call_count == len(error_codes) + 1
211+
batch_logs = [
212+
r for r in caplog.records if r.name == "snowflake.connector.result_batch"
213+
]
214+
assert sum(r.levelno == logging.WARNING for r in batch_logs) == len(error_codes)
215+
assert sum(r.levelno == logging.ERROR for r in batch_logs) == 0
216+
warning_logs = [r for r in batch_logs if r.levelno == logging.WARNING]
217+
assert warning_logs
218+
assert all("S3 request id: test-req-id" in r.getMessage() for r in warning_logs)
186219

187220

188221
# ---------------------------------------------------------------------------

0 commit comments

Comments
 (0)