Skip to content

Fix 500 from the audit logger on a request body it cannot parse - #73226

Merged
kaxil merged 1 commit into
apache:mainfrom
astronomer:json-body-audit-log-500
Sep 16, 2026
Merged

kaxil merged 1 commit into
apache:mainfrom
astronomer:json-body-audit-log-500

Conversation

@kaxil

@kaxil kaxil commented Sep 15, 2026

Copy link
Copy Markdown
Member

Follow-up to #72683, which guarded the value json.loads returned but not the parse itself. Closes the class behind #49035 and #62354.

action_logging reads the request body to record it in the audit log, and parsed it with no error handling. Whether that mattered depended on the route: where the route declares a body, FastAPI parses and validates it first, so a bad body is a 4xx and this dependency never runs. Where the route declares no body -- the deletes, the favourite toggles, the backfill pause/cancel actions -- FastAPI never touches the body, so this was the only parse of it and the error escaped as a 500. The action was lost with it.

Against a local api-server, before:

POST   /api/v2/variables            -> 201
GET    /api/v2/variables/e2e_probe  -> 200   (exists)
DELETE /api/v2/variables/e2e_probe  -> 500
GET    /api/v2/variables/e2e_probe  -> 200   (still there -- the delete was lost)
File ".../airflow/api_fastapi/logging/decorators.py", line 207, in log_action
  parsed_body = await request.json()
File ".../starlette/requests.py", line 265, in json
  self._json = json.loads(body)
json.decoder.JSONDecodeError: Expecting property name enclosed in double quotes: line 1 column 2 (char 1)

After, for each input class that makes json.loads raise:

  malformed      DELETE -> 204   follow-up GET -> 404  (deleted)
  invalid_utf8   DELETE -> 204   follow-up GET -> 404  (deleted)
  oversized_int  DELETE -> 204   follow-up GET -> 404  (deleted)
  deeply_nested  DELETE -> 204   follow-up GET -> 404  (deleted)

Design rationale

A body this dependency cannot read is recorded as an access without a body, not rejected. It runs before the route so an access is logged whether or not the route succeeds -- the ordering is deliberate, per the discussion on #64641 -- which also means it must never be the reason a request fails. Returning 400 instead would put validation of a field the API does not declare inside the audit logger.

The catch is broad, matching what FastAPI does around the same call. json.loads raises JSONDecodeError for malformed input, UnicodeDecodeError for invalid UTF-8, a bare ValueError for an integer over int_max_str_digits, and RecursionError for deeply nested input. Enumerating types is how this line collected three earlier fixes that each missed the next shape, so it now matches FastAPI's own chain, which ends in except Exception.

requires_access_backfill parses the same body and suppressed only JSONDecodeError, so it re-raised on the others. A body it cannot read names no Dag, which is the state it already handles, so it now suppresses them the same way -- no authorization outcome changes. Reachable only when backfill_id is absent or unparsable, since a valid one is authorized from the path without reading the body.

The audit row keeps naming the resource. With no readable body, the masking branches fell back to an empty dict, so a variable or connection delete recorded {"method": "DELETE"} and lost the only record of what it destroyed -- Log has no column for it. Visible in one log, old row then new:

extra='{"method": "DELETE"}'
extra='{"variable_key": "e2e_malformed", "method": "DELETE"}'

Gotchas

The test enumerates the bodyless routes from the app and sends every input class above, rather than naming the endpoint of the latest report. It requires an audit row per route as well as a non-500, because a route rejected by an earlier dependency would otherwise pass while proving nothing -- PUT /parseDagFile/{file_token} does exactly that with a placeholder token, so it is exempted explicitly rather than silently.

action_logging reads the request body to record it in the audit log, and parsed it
with no error handling. Whether that mattered depended on the route it is attached
to: where the route declares a body, FastAPI parses and validates it first, so a
bad body is a 4xx and the dependency never runs. Where the route declares no body --
the deletes, the favourite toggles, the backfill pause/cancel actions -- FastAPI
never touches the body, so this dependency was the only thing that parsed it, and
the error escaped as a 500 for a request whose endpoint does not read a body at all.
The action was lost with it: a DELETE that answered 500 left the variable in place.

A body this dependency cannot read is now recorded as an access without a body. It
runs before the route so an access is logged whether or not the route succeeds,
which also means it must never be the reason a request fails. Returning 400 instead
would put validation of a field the API does not declare inside the audit logger.

The catch is broad, matching what FastAPI does around the same call. json.loads
raises JSONDecodeError for malformed input, UnicodeDecodeError for invalid UTF-8, a
bare ValueError for an integer over int_max_str_digits, and RecursionError for deeply
nested input. Three earlier fixes to this line each guarded a value json.loads
returned -- an empty body (apache#49035), a list (apache#62354), then non-dict bodies again
(apache#72683) -- and enumerating types is how each one missed the next shape.

requires_access_backfill parses the same body to find a dag_id and suppressed only
JSONDecodeError, so it re-raised on the others. A body it cannot read names no Dag,
which is the state it already handles, so it now suppresses them the same way. This
is reachable only when backfill_id is absent or unparsable, since a valid one is
authorized from the path without reading the body.

The test enumerates the routes from the app and sends every input class that makes
json.loads raise, rather than naming the endpoint of the latest report. It requires
an audit row per route as well as a non-500, so a route rejected by an earlier
dependency cannot pass while proving nothing.
@boring-cyborg boring-cyborg Bot added the area:API Airflow's REST/HTTP API label Sep 15, 2026
@eladkal eladkal added this to the Airflow 3.4.0 milestone Sep 16, 2026
@eladkal eladkal added the type:bug-fix Changelog: Bug Fixes label Sep 16, 2026
@kaxil
kaxil merged commit 896bde5 into apache:main Sep 16, 2026
79 checks passed
@kaxil
kaxil deleted the json-body-audit-log-500 branch September 16, 2026 07:22
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area:API Airflow's REST/HTTP API type:bug-fix Changelog: Bug Fixes

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants