Skip to content

Fix duplicated task logs in the WASB log handler - #70860

Merged
Miretpl merged 2 commits into
apache:mainfrom
bmanan7:fix-wasb-duplicate-logs
Jul 31, 2026
Merged

Fix duplicated task logs in the WASB log handler#70860
Miretpl merged 2 commits into
apache:mainfrom
bmanan7:fix-wasb-duplicate-logs

Conversation

@bmanan7

@bmanan7 bmanan7 commented Jul 31, 2026

Copy link
Copy Markdown
Contributor

Problem Statement

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:

    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 Fix duplicated logs and memory issue with S3 log handler #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 Fix duplicated logs and memory issue with S3 log handler #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.

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 Compare logs instead of truncating, allow changing object write mode #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.

related: #70867


Was generative AI tooling used to co-author this PR?
  • Yes (Claude Code, Opus 5)

Generated-by: Claude Code (Opus 5) following the guidelines

Several task-execution lifecycles can write to one remote log key. With a
reschedule-mode sensor, try_number does not change, so every poke uploads to
the same attempt log. The local log file is opened in append mode and is never
truncated after a successful upload, so a lifecycle that reuses the same local
path re-sends the lines the blob already holds and the stored log grows
quadratically. This depends on the local path being reused, which happens on a
long-lived worker or a shared logs volume, and not when every lifecycle starts
with a fresh one.

The S3 handler had the same defect, reported as a worker OOM and fixed in
apache#67144. Emptying the local file on a successful upload is intentionally the
same approach, so the two handlers stay consistent.
@Miretpl
Miretpl merged commit 7ae9d58 into apache:main Jul 31, 2026
83 checks passed
@Miretpl

Miretpl commented Jul 31, 2026

Copy link
Copy Markdown
Contributor

Thanks and welcome to the project!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants