You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@airflow.apache.org by "bmanan7 (via GitHub)" <gi...@apache.org> on 2026/07/31 17:32:23 UTC
[PR] Fix duplicated task logs in the WASB log handler [airflow]
bmanan7 opened a new pull request, #70860:
URL: https://github.com/apache/airflow/pull/70860
### What's wrong
When a task attempt's log is uploaded to Azure Blob Storage more than once, the same lines get
stored again and again. A log that should be a few MB ends up being hundreds of MB, or GB, of the
same content repeated.
Two things combine to cause it:
1. **The local log file is never emptied after it is uploaded.** `WasbRemoteLogIO.upload()` reads
the whole local file and uploads it, then only deletes it if `delete_local_copy` is set, and
`[logging] delete_local_logs` defaults to `False`:
```python
log = local_loc.read_text()
has_uploaded = self.write(log, remote_loc)
if has_uploaded and self.delete_local_copy:
shutil.rmtree(os.path.dirname(local_loc))
```
2. **The log file is opened in append mode and never truncated.** `open("ab")` in the Task SDK
supervisor, `NonCachingRotatingFileHandler` (default mode `"a"`) in `FileTaskHandler`, and
`open(full_path, "a").close()` in `FileTaskHandler._init_file`.
So if a second run of the *same attempt* happens on a worker that still has the log file, the file
already contains the previous run's lines, and `write()` appends all of them to a blob that
already has them.
### When it happens
The common trigger is a **reschedule-mode sensor**. `UP_FOR_RESCHEDULE` does not increment
`try_number`, so every poke writes to the same `attempt=N.log` key, and every poke is a separate
worker process. With N pokes, poke 1's lines are stored N times, poke 2's N-1 times, and so on.
It only happens when a later lifecycle reuses the same local log path. That is the case on a
long-lived worker (Celery, Local) or with a shared logs volume, where the poke finds the log file
already on disk. Where every lifecycle starts on a fresh filesystem, such as one pod per task with
no shared volume, there is no duplication at all, though the read-modify-write cost below still
applies. Retries are not affected either way, since `try_number` changes and each attempt gets its
own key.
### What it costs
A sensor in reschedule mode with the default `poke_interval` of 60 seconds, waiting 24 hours, is
1,440 poke lifecycles. Measured with a minimal reschedule-mode sensor Dag on Airflow 3.3, one poke
writes about 1 KB of log (real Dags write considerably more), so the honest log for that attempt is
about 1.4 MiB:
| | today | with this fix | change |
|---|---|---|---|
| log stored in the blob | **1,013 MiB** | **1.4 MiB** | -99.9% |
| bytes uploaded | **476 GiB** | 1,013 MiB | -99.8% |
| bytes downloaded | **475 GiB** | 1,012 MiB | -99.8% |
| total network transfer | **950 GiB** | 2.0 GiB | -99.8% |
| peak worker memory for the last upload | **~2 GiB** | ~3 MiB | -99.8% |
| storage operations | 4,320 | 4,320 | unchanged |
The stored blob is **720x larger** than the log it represents. Three practical consequences:
- **Workers run out of memory.** Every upload holds the whole blob in memory to append to it. Near
the end of a day-long sensor that is gigabytes on a worker sized for a sensor. This is not
hypothetical: it is exactly how the identical S3 bug was found and reported in #67144.
- **Logs become slow or impossible to read.** Opening that task's log in the UI downloads the whole
blob, and what you get back is the same lines repeated hundreds of times, which is hard to read
even when it loads.
- **It costs money where blob traffic is metered.** Treat this as an illustration only, since prices
vary by region, tier and networking setup. At $0.01/GB each way for data processed through an
Azure private endpoint, that single sensor task moves about 1,020 GB a day, roughly **$10 per
sensor task per day**, versus about **2 cents** after this fix. Ten such sensors over a month is
$3,000 of traffic that carries nothing new. Deployments that talk to storage over a free path pay
nothing extra in transfer, but still pay in stored bytes, worker memory and log-view latency.
### The fix
The S3 handler had this exact bug, in this exact scenario, and fixed it in #67144. This applies the
same two changes to the Azure handler, which has neither:
1. Empty the local log file after a successful upload, so the next lifecycle only sends what is new.
This intentionally matches what #67144 did for `S3RemoteLogIO`, rather than inventing a different
mechanism for Azure, so the two handlers behave the same way.
2. Only insert a newline separator when the existing blob does not already end with one. Without
this, every appended segment also gains a blank line, and the WASB output differs from the S3
output for the same input.
#68304, a follow-up draft to the S3 fix, noted that "the Google and Azure object store logging may
have a similar memory bug due to a download, append, upload process". This confirms it for Azure.
The equivalent gap in the GCS handler is left for a separate PR.
### Not fixed here
The handler still downloads the whole remote log and re-uploads it on every write, so transfer keeps
growing with the square of the number of uploads even once duplication is gone (the 1,013 MiB /
1,012 MiB column above). That needs appending instead of rewriting, which is a bigger change, so it
is out of scope here.
### Tests
Three behaviours, all of which fail if you revert the change:
- `test_upload_repeated_appends_no_duplication`: three lifecycles appending to one local log; the
blob must contain each line exactly once. Without the fix it contains
`cycle 1\n\ncycle 1\ncycle 2\n\ncycle 1\ncycle 2\ncycle 3\n`.
- `test_upload_truncates_local_log_only_after_successful_write`: parametrized on whether the upload
succeeded. On success the local file is emptied; **on failure it is left alone** so the logs can
still be retried. The failure case is the concern raised during review of #68304, so it is pinned
rather than left implicit.
- `test_write_on_existing_log_already_newline_terminated`: no extra blank line when the blob
already ends in a newline. The existing `test_write_on_existing_log` still pins the other
direction, and no existing test was modified.
`uv run --project providers/microsoft/azure pytest providers/microsoft/azure/tests/unit/microsoft/azure/log/`
gives 24 passed. `prek` pre-commit and manual stages pass on the changed files.
---
##### Was generative AI tooling used to co-author this PR?
- [X] Yes (Claude Code, Opus 5)
Generated-by: Claude Code (Opus 5) following [the guidelines](https://github.com/apache/airflow/blob/main/contributing-docs/05_pull_requests.rst#gen-ai-assisted-contributions)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix duplicated task logs in the WASB log handler [airflow]
Posted by "Miretpl (via GitHub)" <gi...@apache.org>.
Miretpl commented on PR #70860:
URL: https://github.com/apache/airflow/pull/70860#issuecomment-5148323404
Thanks and welcome to the project!
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] Fix duplicated task logs in the WASB log handler [airflow]
Posted by "Miretpl (via GitHub)" <gi...@apache.org>.
Miretpl merged PR #70860:
URL: https://github.com/apache/airflow/pull/70860
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@airflow.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org