Include TI UUID in scheduler, DAG processor, triggerer, and worker logs by kaxil · Pull Request #65458 · apache/airflow

kaxil · 2026-04-18T07:07:14Z

Engineers currently cannot grep a single ti_id and reconstruct a task's full lifecycle timeline. The Execution API binds ti_id to every log line via bind_contextvars, but scheduler, DAG processor, triggerer, and worker each emit it in some places and not others. This PR closes that gap.

What changed

Component	Change	Rationale
Worker (`task-sdk/.../task_runner.py`)	`bind_contextvars(ti_id=str(msg.ti.id), ...)` at the top of `startup()`	One worker process = one TI. No cross-task leak risk, so context binding is strictly correct and instruments every subsequent log line (including ones added in future changes).
Triggerer (`jobs/triggerer_job_runner.py:1308`)	Extend the existing `bind_log_contextvars(trigger_id=...)` to also bind `ti_id` + composite TI keys when `trigger.task_instance` is present	`run_trigger` runs inside `asyncio.create_task`, which snapshots the context at creation, so the binding stays scoped to that coroutine.
Scheduler (`jobs/scheduler_job_runner.py`)	Add `ti_id=%s` as a positional arg to eight TI-touching log calls across `_enqueue_task_instances_with_queued_state`, `process_executor_events`, and `_maybe_requeue_stuck_ti`	Explicit positional args (no `bind_contextvars`) because the scheduler is a long-running process and any unhandled exception mid-loop would leave a stale `ti_id` bound for the rest of the process lifetime, corrupting all subsequent log lines. Per-iteration `with bound_contextvars(...)` would be correct but re-indents ~200 lines of hot-path code. Positional args are both safer and less invasive.
DAG processor (`dag_processing/processor.py`)	Add `ti_id` to `_execute_callbacks` and `_execute_task_callbacks` log calls (kwarg where the call is pure-structlog style, `%-format` positional where the call is stdlib style)	Same reasoning as scheduler.

Design notes

Why not bind_contextvars everywhere? The earlier draft of this PR did exactly that. But we found a contextvar leak: if any exception propagates out of the per-TI loop body, the post-loop unbind_contextvars is skipped and the last TI's ti_id stays bound for the remainder of the scheduler process. Because merge_contextvars is wired into the stdlib logging foreign_pre_chain, this taints every subsequent log line -- including ones that have nothing to do with that TI. Inverts the goal of the PR. Per-iteration bound_contextvars context manager is correct but requires re-indenting long loop bodies. For the scheduler and DAG processor, explicit positional ti_id=%s args are both safer and less invasive.
Why is it OK to bind in the worker? A worker is a fresh process that runs exactly one TI. There is no cross-iteration or cross-TI state to leak into. The bind is strictly correct and instruments every log line for free.
Why is it OK to bind in the triggerer?run_trigger is launched via asyncio.create_task, which copies the current contextvars.Context at task creation. Any contextvar bound inside the coroutine is scoped to that task and cannot leak into another trigger's coroutine or the triggerer's supervisor loop.

Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks.

@jedcunningham

…tions Addresses review feedback from @jedcunningham on apache#65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string.

After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695.

dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent.

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

github-actions · 2026-04-19T00:45:37Z

Backport successfully created: v3-2-test

Note: As of Merging PRs targeted for Airflow 3.X
the committer who merges the PR is responsible for backporting the PRs that are bug fixes (generally speaking) to the maintenance branches.

In matter of doubt please ask in #release-management Slack channel.

Status	Branch	Result
✅	v3-2-test

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

kaxil · 2026-04-18T07:07:14Z

Engineers currently cannot grep a single ti_id and reconstruct a task's full lifecycle timeline. The Execution API binds ti_id to every log line via bind_contextvars, but scheduler, DAG processor, triggerer, and worker each emit it in some places and not others. This PR closes that gap.

What changed

Component	Change	Rationale
Worker (`task-sdk/.../task_runner.py`)	`bind_contextvars(ti_id=str(msg.ti.id), ...)` at the top of `startup()`	One worker process = one TI. No cross-task leak risk, so context binding is strictly correct and instruments every subsequent log line (including ones added in future changes).
Triggerer (`jobs/triggerer_job_runner.py:1308`)	Extend the existing `bind_log_contextvars(trigger_id=...)` to also bind `ti_id` + composite TI keys when `trigger.task_instance` is present	`run_trigger` runs inside `asyncio.create_task`, which snapshots the context at creation, so the binding stays scoped to that coroutine.
Scheduler (`jobs/scheduler_job_runner.py`)	Add `ti_id=%s` as a positional arg to eight TI-touching log calls across `_enqueue_task_instances_with_queued_state`, `process_executor_events`, and `_maybe_requeue_stuck_ti`	Explicit positional args (no `bind_contextvars`) because the scheduler is a long-running process and any unhandled exception mid-loop would leave a stale `ti_id` bound for the rest of the process lifetime, corrupting all subsequent log lines. Per-iteration `with bound_contextvars(...)` would be correct but re-indents ~200 lines of hot-path code. Positional args are both safer and less invasive.
DAG processor (`dag_processing/processor.py`)	Add `ti_id` to `_execute_callbacks` and `_execute_task_callbacks` log calls (kwarg where the call is pure-structlog style, `%-format` positional where the call is stdlib style)	Same reasoning as scheduler.

Design notes

Why not bind_contextvars everywhere? The earlier draft of this PR did exactly that. But we found a contextvar leak: if any exception propagates out of the per-TI loop body, the post-loop unbind_contextvars is skipped and the last TI's ti_id stays bound for the remainder of the scheduler process. Because merge_contextvars is wired into the stdlib logging foreign_pre_chain, this taints every subsequent log line -- including ones that have nothing to do with that TI. Inverts the goal of the PR. Per-iteration bound_contextvars context manager is correct but requires re-indenting long loop bodies. For the scheduler and DAG processor, explicit positional ti_id=%s args are both safer and less invasive.
Why is it OK to bind in the worker? A worker is a fresh process that runs exactly one TI. There is no cross-iteration or cross-TI state to leak into. The bind is strictly correct and instruments every log line for free.
Why is it OK to bind in the triggerer?run_trigger is launched via asyncio.create_task, which copies the current contextvars.Context at task creation. Any contextvar bound inside the coroutine is scoped to that task and cannot leak into another trigger's coroutine or the triggerer's supervisor loop.

Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks.

@jedcunningham

…tions Addresses review feedback from @jedcunningham on apache#65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string.

After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695.

dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent.

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

github-actions · 2026-04-19T00:45:37Z

Backport successfully created: v3-2-test

Note: As of Merging PRs targeted for Airflow 3.X
the committer who merges the PR is responsible for backporting the PRs that are bug fixes (generally speaking) to the maintenance branches.

In matter of doubt please ask in #release-management Slack channel.

Status	Branch	Result
✅	v3-2-test

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

kaxil · 2026-04-18T07:07:14Z

Engineers currently cannot grep a single ti_id and reconstruct a task's full lifecycle timeline. The Execution API binds ti_id to every log line via bind_contextvars, but scheduler, DAG processor, triggerer, and worker each emit it in some places and not others. This PR closes that gap.

What changed

Component	Change	Rationale
Worker (`task-sdk/.../task_runner.py`)	`bind_contextvars(ti_id=str(msg.ti.id), ...)` at the top of `startup()`	One worker process = one TI. No cross-task leak risk, so context binding is strictly correct and instruments every subsequent log line (including ones added in future changes).
Triggerer (`jobs/triggerer_job_runner.py:1308`)	Extend the existing `bind_log_contextvars(trigger_id=...)` to also bind `ti_id` + composite TI keys when `trigger.task_instance` is present	`run_trigger` runs inside `asyncio.create_task`, which snapshots the context at creation, so the binding stays scoped to that coroutine.
Scheduler (`jobs/scheduler_job_runner.py`)	Add `ti_id=%s` as a positional arg to eight TI-touching log calls across `_enqueue_task_instances_with_queued_state`, `process_executor_events`, and `_maybe_requeue_stuck_ti`	Explicit positional args (no `bind_contextvars`) because the scheduler is a long-running process and any unhandled exception mid-loop would leave a stale `ti_id` bound for the rest of the process lifetime, corrupting all subsequent log lines. Per-iteration `with bound_contextvars(...)` would be correct but re-indents ~200 lines of hot-path code. Positional args are both safer and less invasive.
DAG processor (`dag_processing/processor.py`)	Add `ti_id` to `_execute_callbacks` and `_execute_task_callbacks` log calls (kwarg where the call is pure-structlog style, `%-format` positional where the call is stdlib style)	Same reasoning as scheduler.

Design notes

Why not bind_contextvars everywhere? The earlier draft of this PR did exactly that. But we found a contextvar leak: if any exception propagates out of the per-TI loop body, the post-loop unbind_contextvars is skipped and the last TI's ti_id stays bound for the remainder of the scheduler process. Because merge_contextvars is wired into the stdlib logging foreign_pre_chain, this taints every subsequent log line -- including ones that have nothing to do with that TI. Inverts the goal of the PR. Per-iteration bound_contextvars context manager is correct but requires re-indenting long loop bodies. For the scheduler and DAG processor, explicit positional ti_id=%s args are both safer and less invasive.
Why is it OK to bind in the worker? A worker is a fresh process that runs exactly one TI. There is no cross-iteration or cross-TI state to leak into. The bind is strictly correct and instruments every log line for free.
Why is it OK to bind in the triggerer?run_trigger is launched via asyncio.create_task, which copies the current contextvars.Context at task creation. Any contextvar bound inside the coroutine is scoped to that task and cannot leak into another trigger's coroutine or the triggerer's supervisor loop.

Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks.

@jedcunningham

…tions Addresses review feedback from @jedcunningham on apache#65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string.

After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695.

dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent.

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

github-actions · 2026-04-19T00:45:37Z

Backport successfully created: v3-2-test

Note: As of Merging PRs targeted for Airflow 3.X
the committer who merges the PR is responsible for backporting the PRs that are bug fixes (generally speaking) to the maintenance branches.

In matter of doubt please ask in #release-management Slack channel.

Status	Branch	Result
✅	v3-2-test

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

kaxil · 2026-04-18T07:07:14Z

Engineers currently cannot grep a single ti_id and reconstruct a task's full lifecycle timeline. The Execution API binds ti_id to every log line via bind_contextvars, but scheduler, DAG processor, triggerer, and worker each emit it in some places and not others. This PR closes that gap.

What changed

Component	Change	Rationale
Worker (`task-sdk/.../task_runner.py`)	`bind_contextvars(ti_id=str(msg.ti.id), ...)` at the top of `startup()`	One worker process = one TI. No cross-task leak risk, so context binding is strictly correct and instruments every subsequent log line (including ones added in future changes).
Triggerer (`jobs/triggerer_job_runner.py:1308`)	Extend the existing `bind_log_contextvars(trigger_id=...)` to also bind `ti_id` + composite TI keys when `trigger.task_instance` is present	`run_trigger` runs inside `asyncio.create_task`, which snapshots the context at creation, so the binding stays scoped to that coroutine.
Scheduler (`jobs/scheduler_job_runner.py`)	Add `ti_id=%s` as a positional arg to eight TI-touching log calls across `_enqueue_task_instances_with_queued_state`, `process_executor_events`, and `_maybe_requeue_stuck_ti`	Explicit positional args (no `bind_contextvars`) because the scheduler is a long-running process and any unhandled exception mid-loop would leave a stale `ti_id` bound for the rest of the process lifetime, corrupting all subsequent log lines. Per-iteration `with bound_contextvars(...)` would be correct but re-indents ~200 lines of hot-path code. Positional args are both safer and less invasive.
DAG processor (`dag_processing/processor.py`)	Add `ti_id` to `_execute_callbacks` and `_execute_task_callbacks` log calls (kwarg where the call is pure-structlog style, `%-format` positional where the call is stdlib style)	Same reasoning as scheduler.

Design notes

Why not bind_contextvars everywhere? The earlier draft of this PR did exactly that. But we found a contextvar leak: if any exception propagates out of the per-TI loop body, the post-loop unbind_contextvars is skipped and the last TI's ti_id stays bound for the remainder of the scheduler process. Because merge_contextvars is wired into the stdlib logging foreign_pre_chain, this taints every subsequent log line -- including ones that have nothing to do with that TI. Inverts the goal of the PR. Per-iteration bound_contextvars context manager is correct but requires re-indenting long loop bodies. For the scheduler and DAG processor, explicit positional ti_id=%s args are both safer and less invasive.
Why is it OK to bind in the worker? A worker is a fresh process that runs exactly one TI. There is no cross-iteration or cross-TI state to leak into. The bind is strictly correct and instruments every log line for free.
Why is it OK to bind in the triggerer?run_trigger is launched via asyncio.create_task, which copies the current contextvars.Context at task creation. Any contextvar bound inside the coroutine is scoped to that task and cannot leak into another trigger's coroutine or the triggerer's supervisor loop.

Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks.

@jedcunningham

…tions Addresses review feedback from @jedcunningham on apache#65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string.

After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695.

dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent.

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

github-actions · 2026-04-19T00:45:37Z

Backport successfully created: v3-2-test

Note: As of Merging PRs targeted for Airflow 3.X
the committer who merges the PR is responsible for backporting the PRs that are bug fixes (generally speaking) to the maintenance branches.

In matter of doubt please ask in #release-management Slack channel.

Status	Branch	Result
✅	v3-2-test

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

kaxil · 2026-04-18T07:07:14Z

Engineers currently cannot grep a single ti_id and reconstruct a task's full lifecycle timeline. The Execution API binds ti_id to every log line via bind_contextvars, but scheduler, DAG processor, triggerer, and worker each emit it in some places and not others. This PR closes that gap.

What changed

Component	Change	Rationale
Worker (`task-sdk/.../task_runner.py`)	`bind_contextvars(ti_id=str(msg.ti.id), ...)` at the top of `startup()`	One worker process = one TI. No cross-task leak risk, so context binding is strictly correct and instruments every subsequent log line (including ones added in future changes).
Triggerer (`jobs/triggerer_job_runner.py:1308`)	Extend the existing `bind_log_contextvars(trigger_id=...)` to also bind `ti_id` + composite TI keys when `trigger.task_instance` is present	`run_trigger` runs inside `asyncio.create_task`, which snapshots the context at creation, so the binding stays scoped to that coroutine.
Scheduler (`jobs/scheduler_job_runner.py`)	Add `ti_id=%s` as a positional arg to eight TI-touching log calls across `_enqueue_task_instances_with_queued_state`, `process_executor_events`, and `_maybe_requeue_stuck_ti`	Explicit positional args (no `bind_contextvars`) because the scheduler is a long-running process and any unhandled exception mid-loop would leave a stale `ti_id` bound for the rest of the process lifetime, corrupting all subsequent log lines. Per-iteration `with bound_contextvars(...)` would be correct but re-indents ~200 lines of hot-path code. Positional args are both safer and less invasive.
DAG processor (`dag_processing/processor.py`)	Add `ti_id` to `_execute_callbacks` and `_execute_task_callbacks` log calls (kwarg where the call is pure-structlog style, `%-format` positional where the call is stdlib style)	Same reasoning as scheduler.

Design notes

Why not bind_contextvars everywhere? The earlier draft of this PR did exactly that. But we found a contextvar leak: if any exception propagates out of the per-TI loop body, the post-loop unbind_contextvars is skipped and the last TI's ti_id stays bound for the remainder of the scheduler process. Because merge_contextvars is wired into the stdlib logging foreign_pre_chain, this taints every subsequent log line -- including ones that have nothing to do with that TI. Inverts the goal of the PR. Per-iteration bound_contextvars context manager is correct but requires re-indenting long loop bodies. For the scheduler and DAG processor, explicit positional ti_id=%s args are both safer and less invasive.
Why is it OK to bind in the worker? A worker is a fresh process that runs exactly one TI. There is no cross-iteration or cross-TI state to leak into. The bind is strictly correct and instruments every log line for free.
Why is it OK to bind in the triggerer?run_trigger is launched via asyncio.create_task, which copies the current contextvars.Context at task creation. Any contextvar bound inside the coroutine is scoped to that task and cannot leak into another trigger's coroutine or the triggerer's supervisor loop.

Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks.

@jedcunningham

…tions Addresses review feedback from @jedcunningham on apache#65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string.

After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695.

dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent.

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

github-actions · 2026-04-19T00:45:37Z

Backport successfully created: v3-2-test

Note: As of Merging PRs targeted for Airflow 3.X
the committer who merges the PR is responsible for backporting the PRs that are bug fixes (generally speaking) to the maintenance branches.

In matter of doubt please ask in #release-management Slack channel.

Status	Branch	Result
✅	v3-2-test

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

kaxil · 2026-04-18T07:07:14Z

Engineers currently cannot grep a single ti_id and reconstruct a task's full lifecycle timeline. The Execution API binds ti_id to every log line via bind_contextvars, but scheduler, DAG processor, triggerer, and worker each emit it in some places and not others. This PR closes that gap.

What changed

Component	Change	Rationale
Worker (`task-sdk/.../task_runner.py`)	`bind_contextvars(ti_id=str(msg.ti.id), ...)` at the top of `startup()`	One worker process = one TI. No cross-task leak risk, so context binding is strictly correct and instruments every subsequent log line (including ones added in future changes).
Triggerer (`jobs/triggerer_job_runner.py:1308`)	Extend the existing `bind_log_contextvars(trigger_id=...)` to also bind `ti_id` + composite TI keys when `trigger.task_instance` is present	`run_trigger` runs inside `asyncio.create_task`, which snapshots the context at creation, so the binding stays scoped to that coroutine.
Scheduler (`jobs/scheduler_job_runner.py`)	Add `ti_id=%s` as a positional arg to eight TI-touching log calls across `_enqueue_task_instances_with_queued_state`, `process_executor_events`, and `_maybe_requeue_stuck_ti`	Explicit positional args (no `bind_contextvars`) because the scheduler is a long-running process and any unhandled exception mid-loop would leave a stale `ti_id` bound for the rest of the process lifetime, corrupting all subsequent log lines. Per-iteration `with bound_contextvars(...)` would be correct but re-indents ~200 lines of hot-path code. Positional args are both safer and less invasive.
DAG processor (`dag_processing/processor.py`)	Add `ti_id` to `_execute_callbacks` and `_execute_task_callbacks` log calls (kwarg where the call is pure-structlog style, `%-format` positional where the call is stdlib style)	Same reasoning as scheduler.

Design notes

Why not bind_contextvars everywhere? The earlier draft of this PR did exactly that. But we found a contextvar leak: if any exception propagates out of the per-TI loop body, the post-loop unbind_contextvars is skipped and the last TI's ti_id stays bound for the remainder of the scheduler process. Because merge_contextvars is wired into the stdlib logging foreign_pre_chain, this taints every subsequent log line -- including ones that have nothing to do with that TI. Inverts the goal of the PR. Per-iteration bound_contextvars context manager is correct but requires re-indenting long loop bodies. For the scheduler and DAG processor, explicit positional ti_id=%s args are both safer and less invasive.
Why is it OK to bind in the worker? A worker is a fresh process that runs exactly one TI. There is no cross-iteration or cross-TI state to leak into. The bind is strictly correct and instruments every log line for free.
Why is it OK to bind in the triggerer?run_trigger is launched via asyncio.create_task, which copies the current contextvars.Context at task creation. Any contextvar bound inside the coroutine is scoped to that task and cannot leak into another trigger's coroutine or the triggerer's supervisor loop.

Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks.

@jedcunningham

…tions Addresses review feedback from @jedcunningham on apache#65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string.

After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695.

dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent.

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

github-actions · 2026-04-19T00:45:37Z

Backport successfully created: v3-2-test

Note: As of Merging PRs targeted for Airflow 3.X
the committer who merges the PR is responsible for backporting the PRs that are bug fixes (generally speaking) to the maintenance branches.

In matter of doubt please ask in #release-management Slack channel.

Status	Branch	Result
✅	v3-2-test

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

kaxil · 2026-04-18T07:07:14Z

Engineers currently cannot grep a single ti_id and reconstruct a task's full lifecycle timeline. The Execution API binds ti_id to every log line via bind_contextvars, but scheduler, DAG processor, triggerer, and worker each emit it in some places and not others. This PR closes that gap.

What changed

Component	Change	Rationale
Worker (`task-sdk/.../task_runner.py`)	`bind_contextvars(ti_id=str(msg.ti.id), ...)` at the top of `startup()`	One worker process = one TI. No cross-task leak risk, so context binding is strictly correct and instruments every subsequent log line (including ones added in future changes).
Triggerer (`jobs/triggerer_job_runner.py:1308`)	Extend the existing `bind_log_contextvars(trigger_id=...)` to also bind `ti_id` + composite TI keys when `trigger.task_instance` is present	`run_trigger` runs inside `asyncio.create_task`, which snapshots the context at creation, so the binding stays scoped to that coroutine.
Scheduler (`jobs/scheduler_job_runner.py`)	Add `ti_id=%s` as a positional arg to eight TI-touching log calls across `_enqueue_task_instances_with_queued_state`, `process_executor_events`, and `_maybe_requeue_stuck_ti`	Explicit positional args (no `bind_contextvars`) because the scheduler is a long-running process and any unhandled exception mid-loop would leave a stale `ti_id` bound for the rest of the process lifetime, corrupting all subsequent log lines. Per-iteration `with bound_contextvars(...)` would be correct but re-indents ~200 lines of hot-path code. Positional args are both safer and less invasive.
DAG processor (`dag_processing/processor.py`)	Add `ti_id` to `_execute_callbacks` and `_execute_task_callbacks` log calls (kwarg where the call is pure-structlog style, `%-format` positional where the call is stdlib style)	Same reasoning as scheduler.

Design notes

Why not bind_contextvars everywhere? The earlier draft of this PR did exactly that. But we found a contextvar leak: if any exception propagates out of the per-TI loop body, the post-loop unbind_contextvars is skipped and the last TI's ti_id stays bound for the remainder of the scheduler process. Because merge_contextvars is wired into the stdlib logging foreign_pre_chain, this taints every subsequent log line -- including ones that have nothing to do with that TI. Inverts the goal of the PR. Per-iteration bound_contextvars context manager is correct but requires re-indenting long loop bodies. For the scheduler and DAG processor, explicit positional ti_id=%s args are both safer and less invasive.
Why is it OK to bind in the worker? A worker is a fresh process that runs exactly one TI. There is no cross-iteration or cross-TI state to leak into. The bind is strictly correct and instruments every log line for free.
Why is it OK to bind in the triggerer?run_trigger is launched via asyncio.create_task, which copies the current contextvars.Context at task creation. Any contextvar bound inside the coroutine is scoped to that task and cannot leak into another trigger's coroutine or the triggerer's supervisor loop.

Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks.

@jedcunningham

…tions Addresses review feedback from @jedcunningham on apache#65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string.

After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695.

dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent.

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

github-actions · 2026-04-19T00:45:37Z

Backport successfully created: v3-2-test

Note: As of Merging PRs targeted for Airflow 3.X
the committer who merges the PR is responsible for backporting the PRs that are bug fixes (generally speaking) to the maintenance branches.

In matter of doubt please ask in #release-management Slack channel.

Status	Branch	Result
✅	v3-2-test

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

kaxil · 2026-04-18T07:07:14Z

Engineers currently cannot grep a single ti_id and reconstruct a task's full lifecycle timeline. The Execution API binds ti_id to every log line via bind_contextvars, but scheduler, DAG processor, triggerer, and worker each emit it in some places and not others. This PR closes that gap.

What changed

Component	Change	Rationale
Worker (`task-sdk/.../task_runner.py`)	`bind_contextvars(ti_id=str(msg.ti.id), ...)` at the top of `startup()`	One worker process = one TI. No cross-task leak risk, so context binding is strictly correct and instruments every subsequent log line (including ones added in future changes).
Triggerer (`jobs/triggerer_job_runner.py:1308`)	Extend the existing `bind_log_contextvars(trigger_id=...)` to also bind `ti_id` + composite TI keys when `trigger.task_instance` is present	`run_trigger` runs inside `asyncio.create_task`, which snapshots the context at creation, so the binding stays scoped to that coroutine.
Scheduler (`jobs/scheduler_job_runner.py`)	Add `ti_id=%s` as a positional arg to eight TI-touching log calls across `_enqueue_task_instances_with_queued_state`, `process_executor_events`, and `_maybe_requeue_stuck_ti`	Explicit positional args (no `bind_contextvars`) because the scheduler is a long-running process and any unhandled exception mid-loop would leave a stale `ti_id` bound for the rest of the process lifetime, corrupting all subsequent log lines. Per-iteration `with bound_contextvars(...)` would be correct but re-indents ~200 lines of hot-path code. Positional args are both safer and less invasive.
DAG processor (`dag_processing/processor.py`)	Add `ti_id` to `_execute_callbacks` and `_execute_task_callbacks` log calls (kwarg where the call is pure-structlog style, `%-format` positional where the call is stdlib style)	Same reasoning as scheduler.

Design notes

Why not bind_contextvars everywhere? The earlier draft of this PR did exactly that. But we found a contextvar leak: if any exception propagates out of the per-TI loop body, the post-loop unbind_contextvars is skipped and the last TI's ti_id stays bound for the remainder of the scheduler process. Because merge_contextvars is wired into the stdlib logging foreign_pre_chain, this taints every subsequent log line -- including ones that have nothing to do with that TI. Inverts the goal of the PR. Per-iteration bound_contextvars context manager is correct but requires re-indenting long loop bodies. For the scheduler and DAG processor, explicit positional ti_id=%s args are both safer and less invasive.
Why is it OK to bind in the worker? A worker is a fresh process that runs exactly one TI. There is no cross-iteration or cross-TI state to leak into. The bind is strictly correct and instruments every log line for free.
Why is it OK to bind in the triggerer?run_trigger is launched via asyncio.create_task, which copies the current contextvars.Context at task creation. Any contextvar bound inside the coroutine is scoped to that task and cannot leak into another trigger's coroutine or the triggerer's supervisor loop.

Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks.

@jedcunningham

…tions Addresses review feedback from @jedcunningham on apache#65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string.

After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695.

dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent.

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

github-actions · 2026-04-19T00:45:37Z

Backport successfully created: v3-2-test

Note: As of Merging PRs targeted for Airflow 3.X
the committer who merges the PR is responsible for backporting the PRs that are bug fixes (generally speaking) to the maintenance branches.

In matter of doubt please ask in #release-management Slack channel.

Status	Branch	Result
✅	v3-2-test

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

@jedcunningham

…nd worker logs (#65458) (#65476) * [v3-2-test] Bump actions/github-script in the github-actions-updates group (#65150) (#65160) Bumps the github-actions-updates group with 1 update: [actions/github-script](https://github.com/actions/github-script). Updates `actions/github-script` from 8.0.0 to 9.0.0 - [Release notes](https://github.com/actions/github-script/releases) - [Commits](actions/github-script@ed59741...3a2844b) (cherry picked from commit e5a047c) --- updated-dependencies: - dependency-name: actions/github-script dependency-version: 9.0.0 dependency-type: direct:production update-type: version-update:semver-major dependency-group: github-actions-updates ... Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> * [v3-2-test] Added breeze generate issue content for airflow-ctl (#65042) (#65241) * Add breeze generate issue content for airflow-ctl * add new command to doc (cherry picked from commit b24538b) Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> * [v3-2-test] Run release calendar verification on its own schedule (#65118) (#65242) * Move release calendar verification to its own scheduled workflow Run dev/verify_release_calendar.py from a dedicated daily scheduled workflow instead of as a canary job in the main CI pipeline, and notify the #release-management Slack channel when the check fails so the issue is surfaced to release managers directly. * Include wiki and calendar links in release calendar Slack alert (cherry picked from commit 048e9a1) * [v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) Support engineers could not reconstruct a task's full lifecycle from logs because only the Execution API emitted the TaskInstance UUID consistently. Adding ti_id to log lines across the other components makes 'grep ti_id=X' surface every log touching that task, from scheduling through completion. - Worker: bind ti_id to structlog context at startup(). Fresh process per TI means no cross-task leak risk. - Triggerer: extend existing bind_log_contextvars at trigger start. The asyncio.create_task context copy scopes the binding per coroutine. - Scheduler: add ti_id=%s to eight TI-touching log calls across _enqueue_task_instances_with_queued_state, process_executor_events, and _maybe_requeue_stuck_ti. Explicit positional args avoid the contextvar leak a bind+unbind pattern would introduce on exception paths. - DAG processor: add ti_id to callback-processing log lines in _execute_callbacks and _execute_task_callbacks. * Move ti_id into TaskInstance.__repr__; revert redundant log-line additions Addresses review feedback from @jedcunningham on #65458: instead of sprinkling ti_id=%s onto individual scheduler log lines, put the UUID in TaskInstance.__repr__ once and let every %s-formatted TI log line inherit it for free. Strictly better: covers log lines this PR didn't touch and lines added by future PRs without further plumbing. Net diff vs main goes from +61/-16 to +51/-14. Changes: - TaskInstance.__repr__ now appends `ti_id={self.id}` before the closing bracket (matches the existing TaskInstanceNote repr precedent). - Reverted 10 log-line ti_id additions in scheduler_job_runner.py where the existing `%s` format arg was a TaskInstance; repr now supplies ti_id. - Kept the explicit `ti_id=%s` in the "TaskInstance Finished" msg: it formats individual fields (dag_id, task_id, etc.), not %s on the TI, so the repr shortcut does not apply. - Kept DAG processor structlog-kwargs ti_id additions: those go through structlog's kwargs path, not __repr__. - Updated one test assertion in test_scheduler_job.py that hardcoded the exact TaskInstance repr string. * Update test_not_enough_pool_slots for new TaskInstance repr After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695. * Fix test_not_enough_pool_slots ordering assumption on MySQL dr.task_instances[0] can return can_run first on MySQL (alphabetical default ordering) instead of cannot_run, so the expected ti_id used in the "Not executing" assertion grabbed the wrong task's UUID and the substring check failed on MySQL CI even though it passed on SQLite. Look up the TI by task_id instead to make the assertion order-independent. (cherry picked from commit 1a0efe7) Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com> --------- Signed-off-by: dependabot[bot] <support@github.com> Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> Co-authored-by: Jarek Potiuk <jarek@potiuk.com> Co-authored-by: Justin Pakzad <114518232+justinpakzad@users.noreply.github.com> Co-authored-by: Kaxil Naik <kaxilnaik@gmail.com>

kaxil requested review from XD-DENG, amoghrajesh, ashb, dstandish, ephraimbuddy, hussein-awala and jedcunningham as code owners April 18, 2026 07:07

boring-cyborgBot added area:DAG-processing area:Scheduler including HA (high availability) scheduler area:task-sdk area:Triggerer labels Apr 18, 2026

jedcunningham approved these changes Apr 18, 2026
View reviewed changes

Comment threadairflow-core/src/airflow/jobs/scheduler_job_runner.py Outdated

kaxil added 3 commits April 18, 2026 22:00

Update test_not_enough_pool_slots for new TaskInstance repr
b200e0c
After adding ti_id to TaskInstance.__repr__, test_not_enough_pool_slots needs to include ti_id in the expected log substring. Same fix pattern as test_process_executor_events_with_callback at line 695.

kaxil merged commit 1a0efe7 into apache:mainApr 19, 2026
107 checks passed

kaxil deleted the kaxilnaik/ti-uuid-log-context-binding branch April 19, 2026 00:44

kaxil added this to the Airflow 3.2.2 milestone Apr 19, 2026

github-actionsBot mentioned this pull request Apr 19, 2026
[v3-2-test] Include TI UUID in scheduler, DAG processor, triggerer, and worker logs (#65458) #65476
Merged

ashb mentioned this pull request Apr 28, 2026
Show the task ID attributes (ti_id, task_id, etc.) once, not on every log line #66036
Merged

vatsrahul1001 mentioned this pull request May 21, 2026
Status of testing of Apache Airflow 3.2.2rc3 #67282
Closed