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: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
