`action_logging` dependency logs invalid requests before route validation can reject them

[ferruzzi]

Apache Airflow version

main

What happened and how to reproduce it?

While helping someone troubleshoot a CI failure on one of their PRs, I think I may have found an issue with how action_logging works in the FastAPI routes. The API is definitely one of my blind spots so I could be entirely mistaken about this, and I passed my notes and thoughts into Cline/Claude to hep consolidate them into something that hopefully makes sense... so apologies for the blatant LLM formatting but I figure it was better than a bullet list of half-formed thoughts and observations.

I'm hoping someone with real API experience can either verify this is an actual issue or close this. (@pierrejeambrun, @bugraoz93 ??)

The action_logging() decorator is registered as a FastAPI Depends() on several routes (variables, connections, pools, etc.). Because FastAPI evaluates dependencies before executing the route function body, the audit log entry is written and committed before the route has a chance to validate the request.

This means that requests which will be rejected (providing team_name when multi_team is disabled was the example that led to this, for example) still produce an audit log entry with session.commit(). This has two consequences:

1. Incorrect audit trail — rejected/invalid requests appear in the audit log as if they were attempted actions
2. SQLite lock conflicts in tests — the eager session.commit() in the logging dependency can collide with other sessions that hold write locks (I think this was the root cause of a database is locked test failure in Feat/check multi team enabled when team name provided api #63994)

Where the problem lives:

• airflow-core/src/airflow/api_fastapi/logging/decorators.py — the log_action inner function (returned by action_logging()) creates a Log object and calls session.commit() unconditionally at the end
• All routes that use dependencies=[..., Depends(action_logging()), ...] are affected

Affected routes (non-exhaustive):

• POST /variables and PATCH /variables/{key}
• POST /connections and PATCH /connections/{connection_id}
• POST /pools and PATCH /pools/{pool_name}
• (and others — search for Depends(action_logging()))

Claude's suggested fix (someone with better API background needs to confirm this is a good idea first):

Move request validation checks (like the multi_team check) into their own FastAPI dependency that runs before action_logging(). This way invalid requests are rejected before any audit log entry is created. For example:

# Current (validation happens in route body, AFTER action_logging fires):
@router.post(
    "",
    dependencies=[Depends(action_logging()), Depends(requires_access_variable("POST"))],
)
def post_variable(post_body: ..., session: SessionDep):
    if post_body.team_name is not None and not conf.getboolean("core", "multi_team"):
        raise HTTPException(400, "team_name cannot be set when multi_team mode is disabled.")
    ...

# Proposed (validation runs as a dependency, BEFORE action_logging):
def validate_team_name_allowed(request: Request):
    """Reject requests that include team_name when multi_team is disabled."""
    # Only check for methods that accept a body
    if request.method in ("POST", "PATCH", "PUT"):
        body = await request.json()
        if body.get("team_name") is not None and not conf.getboolean("core", "multi_team"):
            raise HTTPException(400, "team_name cannot be set when multi_team mode is disabled.")

@router.post(
    "",
    dependencies=[
        Depends(validate_team_name_allowed),  # runs first
        Depends(action_logging()),
        Depends(requires_access_variable("POST")),
    ],
)
def post_variable(post_body: ..., session: SessionDep):
    ...

Alternatively, the action_logging decorator itself could be made conditional — only commit the log if the route succeeds — but that's a bigger change with wider implications for the audit trail design.

What you think should happen instead?

No response

Operating System

No response

Versions of Apache Airflow Providers

No response

Deployment

None

Deployment details

No response

Anything else?

No response

Are you willing to submit PR?

• Yes I am willing to submit a PR!

Code of Conduct

• I agree to follow this project's Code of Conduct

[bugraoz93]

Thanks for raising @ferruzzi!
Indeed, Depends() on executing before the route. It is dependency injection at its base and indeed could log something wrong.
Route doesn't call if one of the dependencies fails. In the authorisation, we are already throwing an exception if enabled, and the team name passed (even None) is not in the list. So it should fail on the authorisation layer but that doesn't mean if action_logging starts and finishes within that time, it can execute.

airflow/airflow-core/src/airflow/api_fastapi/core_api/security.py

Lines 730 to 751 in d292e0e

	async def _collect_teams_to_check(
	method: ResourceMethod,
	request: Request,
	resource_id: str | None,
	get_existing_team: Callable[[str], str | None],
	) -> set[str | None]:
	"""Collect validated team names from existing resource (DB) and/or request body."""
	if not conf.getboolean("core", "multi_team"):
	return {None}
	teams: set[str | None] = set()
	if method != "POST":
	teams.add(get_existing_team(resource_id) if resource_id else None)
	if method in ("POST", "PUT"):
	with suppress(JSONDecodeError):
	raw = (await request.json()).get("team_name")
	if raw and not Team.get_name_if_exists(raw):
	raise HTTPException(
	status_code=status.HTTP_400_BAD_REQUEST,
	detail=f"Team {raw!r} does not exist",
	)
	teams.add(raw)
	return teams

Checking if we have a team in another decorator looks like a good idea but we should somehow make them a chained dependency, as validate_team_name_allowed should be a dependency of action_logging, so the order should be defined. So this can be reused where needed as another subinjection
Ex have the chain depends idea and also exit before, so allow authorisation to fail if this case happens:

def validate_team_name_allowed(...):
    ....

def action_logging(..., team_name_dep=Depends(validate_team_name_allowed)):
    if not team_name_dep:
        return
    ...

@router.post(
    "",
    dependencies=[Depends(action_logging()), Depends(requires_access_variable("POST"))],
)
def ..(...):
    ..

Another one could be subdependency https://fastapi.tiangolo.com/tutorial/dependencies/dependencies-with-yield/#sub-dependencies-with-yield, whose order is definite which requires still a bit more effort

FastAPI will make sure that the "exit code" in each dependency with yield is run in the correct order.

@pierrejeambrun could have better ideas

Vincent can also put some take here in the team name and authorisation context, but I saw he is vacationing, so I didn't want to tag

[ferruzzi]

Thanks for checking into it. I'm not sure how big of an issue it really is, but it smelled a little funny when I saw that and thought maybe I should get someone more experienced on the API stuff looking at it.

@ahilashsasidharan - you may want to keep an eye on here, just to follow along.

[pierrejeambrun]

It was implemented like this at first to log 'access' independently if the route fails or succeed.

Validation, business logic, existing db states or many reasons could make the 'endpoint' fail, while we still log the 'access'.

Extract from the code.

        # Explicit commit to persist the access log independently if the path operation fails or not.
        # Also it cannot be deferred to a 'function' scoped dependency because of the `request` parameter.
        session.commit()

Why do you think this is a problem?

What would be your expectation for 'failed' operation?

If we only want to 'log' successful operation, we can simply remove that session.commit, and the commit will be deferred to the session cleanup code that happens just before returning the response.

[ferruzzi]

If it's intentional then it's fine. I was troubleshooting a failing test in that PR I linked and it looked to me like it was an issue with that decorator locking the db row. But if that's the intended behavior, I'm fine with being wrong. Feel free to close this if you aren't convinced.

[pierrejeambrun]

Thanks for raising this Denis, I'll close this for now as this is expected. But if I missed something or we would like to change that behavior, feel free to re-open and we can work on it.