Skip to content

fix: capture S3 diagnostics and stop logging presigned URLs on SQL cache failures - #114

Draft
tkislan wants to merge 1 commit into
mainfrom
fix/113-sql-cache-upload-diagnostics
Draft

fix: capture S3 diagnostics and stop logging presigned URLs on SQL cache failures#114
tkislan wants to merge 1 commit into
mainfrom
fix/113-sql-cache-upload-diagnostics

Conversation

@tkislan

@tkislan tkislan commented Jul 29, 2026

Copy link
Copy Markdown
Contributor

@coderabbitai ignore

Closes #113.

What was wrong

upload_sql_cache reported failures using only the string produced by raise_for_status(). For presigned S3 uploads that discarded the one thing identifying the cause (the response body) while including the one thing that should never reach logs (the presigned URL, which carries X-Amz-Credential and X-Amz-Security-Token). Because a unique URL was interpolated into every message, no two occurrences shared a message string, so downstream error tracking saw a stream of unrelated errors instead of one issue with a rising count.

The change, in one before/after

Before — actual production output, redacted:

Failed to upload SQL cache: 403 Client Error: Forbidden for url:
https://<bucket>.s3.<region>.amazonaws.com/<ws>/<int>/<key>?X-Amz-Algorithm=AWS4-HMAC-SHA256
&X-Amz-Credential=<REDACTED>&X-Amz-Expires=900&X-Amz-Security-Token=<REDACTED>

After — the same 403, run through the new code:

message: 'Failed to upload SQL cache'
  sql_caching_cause: 'failed_to_upload_to_cache'
  status_code: 403
  s3_error_code: 'AccessDenied'
  s3_error_message: 'Request has expired'
  s3_expires: '2026-07-29T12:15:00Z'
  s3_server_time: '2026-07-29T12:31:07Z'
  aws_request_id: '8XJ2K9'
  aws_host_id: 'hostid=='
  aws_date: 'Tue, 29 Jul 2026 12:31:07 GMT'
  object_host: 'bkt.s3.eu-west-1.amazonaws.com'
  object_path: '/ws-123/int-456/abcdef'
  url_expires_in: 900
  seconds_since_url_issued: 931.4

The last two lines are the point: 931.4 > 900 makes an expiry-driven failure self-evident, and s3_error_code separates the four causes that all present as a bare 403 today (AccessDenied+expired, ExpiredToken, plain AccessDenied, SignatureDoesNotMatch).

What's in it

  • Capture S3's diagnostics. <Code>, <Message>, <Expires>, <ServerTime> from the body, plus x-amz-request-id / x-amz-id-2 / Date. Only those four elements are read — <CanonicalRequest>, <StringToSign> and <AWSAccessKeyId> echo the signed query string and are never logged. <Expires>/<ServerTime>/Date are AWS's own clock-independent answer to "did the URL run out of time", independent of this pod's accounting.
  • Never log the presigned URL. raise_for_status() is gone; the status check is explicit and its failure path never builds a string containing the URL. A redaction pass strips the query string off anything URL-shaped in any text destined for a log.
  • Measure the gap. get_sql_cache now returns a SqlCacheUpload(url, issued_at) NamedTuple; issued_at is taken before the webapp round-trip so the measurement is a conservative upper bound on lifetime consumed.
  • Constant messages. All four logger.error sites in the module take a single string literal with everything variable in extra.
  • Distinct cause for serialization. Parquet/pickle failures get failed_to_serialize_cache instead of being conflated with upload failures, and log only the exception type — the message quotes user column names.
  • Download path. pd.read_parquet(download_url) fetched the URL with urllib internally and raised before S3's body was ever read. The object is now fetched explicitly, so the same diagnostics are available. The parquet→pickle fallback is preserved and now downloads once instead of twice.
  • Connect timeouts. timeout=(5, None) on both transfers. Read is left unbounded so slow-but-healthy transfers of large cache objects are unaffected; a hung connect is unambiguously a bug and its exception is swallowed like any other.

Cache failures remain swallowed and can never fail the user's query.

Notes for the reviewer

Two things worth knowing, both found while verifying rather than assumed:

Removing raise_for_status() is not sufficient on its own. requests' ConnectionError/Timeout/SSLError embed the URL via urllib3's MaxRetryError, in a scheme-less, path-only form:

HTTPSConnectionPool(host='...', port=443): Max retries exceeded with
url: /ws/int/key?X-Amz-Credential=...&X-Amz-Security-Token=...

So the redaction pattern deliberately makes the scheme optional. A https?://-anchored pattern is a no-op on this input, which is the shape that actually occurs on network failures.

urlsplit(None) does not raise — it returns SplitResultBytes(path=b'', ...). A bytes value in extra makes json.dumps fail inside report_error_to_webapp, which is outside any try, so the entire error report is silently discarded. Both URL helpers now guard on isinstance(url, str).

Disproven hypothesis, so it isn't re-litigated: chunked encoding is not the cause of the 403s. requests.put(url, data=<tempfile>) sends Content-Length with no Transfer-Encodingsuper_len resolves the length from the fd.

Testing

tests/unit/test_sql_caching.py: 26 tests in 31.1s → 74 in 1.4s.

The old suite contained a test making a real network call to localhost:19456 whose read_parquet/read_pickle mocks were provably dead — it exited through the cache-info handler and never reached the code it claimed to test. It is now patched properly and asserts both mocks were called.

Tests pin each acceptance criterion mechanically, including: no credential survives into any logged field across ~40 adversarial inputs; the message string is identical across different failure kinds; no extra key collides with a reserved LogRecord attribute; every extra value is JSON-serializable on every failure path; and buffer.seek(0) before the pickle fallback is pinned with real pickle bytes, so removing it fails loudly rather than silently breaking every pickle-format cache read.

black / isort / flake8 / mypy clean. Full suite: 1016 passed, 4 skipped.

Follow-ups, deliberately not in this PR

  1. LoggerManager re-adds handlers on every get_logger() call. The re-entry guard at logging.py:238 only fires when the level changes, so file_logger accumulates ~10 WebappErrorHandlers and every toolkit error is reported to the webapp ~10 times. Invisible in CI, where the handler isn't attached. Pre-existing, but this PR ships richer extra dicts so it amplifies. Wants its own issue.
  2. No success-path baseline for seconds_since_url_issued. It is logged only on failure, so there's no distribution to judge 931s against. Emitting it via output_sql_metadata would fix that, but that payload is a contract with the webapp — out of scope here.
  3. isort . also rewrites deepnote_toolkit/streamlit_data_apps.py, which is mis-sorted on main and unrelated. Left alone to keep this diff scoped.

🤖 Generated with Claude Code

https://claude.ai/code/session_015xJczfWE4mq3ux7ZU9ZeU9

…che failures

`upload_sql_cache` reported failures using only the string from
`raise_for_status()`. For presigned S3 uploads that discarded the one thing
identifying the cause (the response body) while including the one thing that
should never reach logs (the presigned URL, which carries X-Amz-Credential and
X-Amz-Security-Token). The unique URL in every message also meant no two
occurrences shared a message string, so downstream error tracking could not
group them.

- Extract S3's <Code>/<Message>/<Expires>/<ServerTime> plus x-amz-request-id
  rather than the exception string. Only those four elements are read;
  <CanonicalRequest>, <StringToSign> and <AWSAccessKeyId> echo the signed query
  string and are never logged.
- Redact credential-bearing material from any text destined for a log. The
  primary defence strips the query string off anything URL-shaped, including the
  scheme-less path-only form urllib3 puts in connection errors - so network
  failures, not just HTTP ones, are covered.
- Carry the URL's issue time in a SqlCacheUpload NamedTuple and log
  seconds_since_url_issued beside url_expires_in, making an expiry-driven
  failure self-evident.
- Use constant log messages with all variable data in `extra`, at all four sites
  in the module.
- Give serialization failures a distinct `failed_to_serialize_cache` cause, and
  log only the exception type for them - the message quotes user column names.
- Fetch the cached object explicitly instead of handing the URL to pandas, which
  fetched it with urllib and raised before S3's error body was ever read. The
  parquet/pickle fallback is preserved and now downloads once instead of twice.
- Bound the connect phase of both transfers at 5s; read is left unbounded so
  slow but healthy transfers of large cache objects are unaffected.

Cache failures remain swallowed and can never fail the user's query.

tests/unit/test_sql_caching.py goes from 26 tests in 31.1s to 74 in 1.4s - the
former suite had a test making a real network call to localhost:19456 whose
mocks were provably dead.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_015xJczfWE4mq3ux7ZU9ZeU9
@github-actions

Copy link
Copy Markdown

📦 Python package built successfully!

  • Version: 2.4.0.dev2+a444c2f
  • Wheel: deepnote_toolkit-2.4.0.dev2+a444c2f-py3-none-any.whl
  • Install:
    pip install "deepnote-toolkit @ https://deepnote-staging-runtime-artifactory.s3.amazonaws.com/deepnote-toolkit-packages/2.4.0.dev2%2Ba444c2f/deepnote_toolkit-2.4.0.dev2%2Ba444c2f-py3-none-any.whl"

@codecov

codecov Bot commented Jul 29, 2026

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 94.49541% with 6 lines in your changes missing coverage. Please review.
✅ Project coverage is 74.85%. Comparing base (6198101) to head (c9fa363).
✅ All tests successful. No failed tests found.

Files with missing lines Patch % Lines
deepnote_toolkit/sql/sql_caching.py 96.19% 3 Missing and 1 partial ⚠️
deepnote_toolkit/sql/sql_execution.py 50.00% 2 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##             main     #114      +/-   ##
==========================================
+ Coverage   74.42%   74.85%   +0.43%     
==========================================
  Files          95       95              
  Lines        5704     5790      +86     
  Branches      850      860      +10     
==========================================
+ Hits         4245     4334      +89     
+ Misses       1182     1177       -5     
- Partials      277      279       +2     
Flag Coverage Δ
combined 74.85% <94.49%> (+0.43%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

@deepnote-bot

Copy link
Copy Markdown

🚀 Review App Deployment Started

📝 Description 🌐 Link / Info
🌍 Review application ra-114
🔑 Sign-in URL Click to sign-in
📊 Application logs View logs
🔄 Actions Click to redeploy
🚀 ArgoCD deployment View deployment
Last deployed 2026-07-29 15:56:10 (UTC)
📜 Deployed commit 4ba3570a0a1410c9a378aa4a93ca5bbe61a7dc6c
🛠️ Toolkit version a444c2f

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

SQL cache upload errors discard the S3 response body and log the presigned URL

2 participants