Skip to content

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

Description

@tkislan

Summary

upload_sql_cache reports failures using only the string produced by requests.Response.raise_for_status(). For presigned S3 uploads this discards the one thing that identifies the cause (the response body) while including the one thing that should never reach logs (the presigned URL, which carries credentials).

We see intermittent 403 Forbidden responses on SQL cache uploads in production, and the current log line cannot distinguish between the several very different faults that all surface as a bare 403.

Current behaviour

deepnote_toolkit/sql/sql_caching.py:94-118:

temp_file.seek(0)
# PUT the file to cache_upload_url pre-signed s3 url
response = requests.put(upload_url, data=temp_file)
response.raise_for_status()
except Exception as exc:
    logger.error(
        "Failed to upload SQL cache: %s",
        exc,
        extra={"sql_caching_cause": "failed_to_upload_to_cache"},
    )

which produces (redacted):

Failed to upload SQL cache: 403 Client Error: Forbidden for url:
https://<bucket>.s3.<region>.amazonaws.com/<workspace-id>/<integration-id>/<cache-key>
?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Content-Sha256=UNSIGNED-PAYLOAD
&X-Amz-Credential=<REDACTED>&X-Amz-Date=<...>&X-Amz-Expires=900
&X-Amz-Security-Token=<REDACTED>

Problem 1 — the actual cause is thrown away

S3 returns an XML body on every error with a <Code> and <Message>. That body is the only place the real fault is stated. At least four causes are indistinguishable from 403 Client Error: Forbidden alone:

S3 <Code> Meaning
AccessDenied + "Request has expired" the URL's own X-Amz-Expires window elapsed before the PUT
ExpiredToken / "The provided token has expired" the temporary credentials behind the signature expired, which can happen before X-Amz-Expires — a presigned URL signed with STS credentials is only valid for the shorter of the two
AccessDenied (plain) the signing principal or a bucket policy no longer permits the write
SignatureDoesNotMatch the request sent doesn't match what was signed

These need completely different fixes, and today we cannot tell which one we're hitting.

The distinction matters here because the upload URL is obtained before the query is executed (sql_execution.py:445) and used after the query completes and the dataframe is serialized (sql_execution.py:540). The query duration plus serialization time therefore has to fit inside the URL's usable lifetime, so elapsed time is a prime suspect — but we have no measurement of it.

Problem 2 — the presigned URL ends up in logs

raise_for_status() builds its message as f"{status_code} Client Error: {reason} for url: {self.url}", so the entire query string is interpolated into the error. That includes X-Amz-Credential and X-Amz-Security-Token. The session token is a usable AWS credential until it expires, and this message is forwarded to the error-reporting pipeline by WebappErrorHandler in deepnote_toolkit/logging.py.

This should be fixed regardless of the 403 investigation.

Problem 3 — the message is unstable, so occurrences don't group

Because a unique URL is embedded in every message, no two occurrences share a message string. Downstream error tracking groups on message content, so a single recurring fault presents as a stream of unrelated errors rather than one issue with a rising count.

Proposed change

1. Capture S3's diagnostics instead of the exception string. Replace raise_for_status() with an explicit check that pulls the fields that matter:

def _describe_s3_error(response):
    """Non-sensitive diagnostics from a failed S3 response."""
    return {
        # S3 returns XML with <Code>/<Message> - the only statement of the real cause
        "s3_error_body": response.text[:1000],
        "status_code": response.status_code,
        # Needed if we ever have to ask AWS Support about a specific request
        "aws_request_id": response.headers.get("x-amz-request-id"),
        "aws_host_id": response.headers.get("x-amz-id-2"),
    }

2. Never log the presigned URL. Log the object path and the declared expiry, and drop the query string:

def _describe_presigned_url(url):
    """Object path and expiry window, without the credential-bearing query string."""
    parts = urlsplit(url)
    return {
        "object_path": parts.path,
        "url_expires_in": parse_qs(parts.query).get("X-Amz-Expires", [None])[0],
    }

3. Measure the gap between issuing and using the URL. This is the measurement that would tell us whether elapsed time is the cause. get_sql_cache currently returns a bare (dataframe, upload_url) tuple; it needs to also carry when the URL was received, e.g.

class SqlCacheUpload(NamedTuple):
    url: str
    issued_at: float  # time.monotonic() when the URL was received

then at upload time record round(time.monotonic() - upload.issued_at, 1) as seconds_since_url_issued. Comparing that against url_expires_in in the same log entry makes an expiry-driven failure self-evident.

4. Keep the message constant. Move everything variable into extra so occurrences group:

logger.error(
    "Failed to upload SQL cache",
    extra={
        "sql_caching_cause": "failed_to_upload_to_cache",
        **_describe_s3_error(response),
        **_describe_presigned_url(upload_url),
        "seconds_since_url_issued": elapsed,
    },
)

Note that non-HTTP failures in this block (parquet/pickle serialization errors) should keep a distinct sql_caching_cause so they don't get conflated with upload failures.

Acceptance criteria

  • A failed SQL cache upload logs S3's <Code>/<Message>, the HTTP status, and x-amz-request-id.
  • No presigned URL query string appears in any log or error report from this module.
  • The log entry states both how long the URL was valid for and how long it had been held.
  • The log message string is identical across occurrences; all variable data lives in extra.
  • Existing behaviour is unchanged: a cache upload failure is still swallowed and never fails the user's query.

Also in scope

The download path has the same blind spot. get_sql_cache logs "Failed to download dataframe from cache: %s" (sql_caching.py:69-73) around _try_read_cache, where pandas.read_parquet(download_url) fetches the URL internally — so any HTTP failure surfaces as whatever pandas/pyarrow raises, with no status code and no S3 error body. It's worth fetching the object explicitly so the same diagnostics are available, and it would confirm whether downloads fail for the same reason uploads do.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions