#1386·backrest

Interval schedule with Last Run Time clock runs a backup twice after wake from sleep

Author: lemon1324Created Sep 16, 2026Updated Sep 16, 2026
Labelsbug

Describe the bug

On a plan using an interval schedule with the "Last Run Time" clock, waking the machine after it has slept past the plan's next run time causes that plan's backup to run twice back-to-back instead of once. The catch-up backup starts correctly on wake, but a second backup of the same plan starts immediately after the first finishes, uploading real new data with the first backup's snapshot as its parent. The next run is then scheduled one interval after the second (extra) backup, not the first.

To Reproduce

  1. Configure a plan with an interval schedule on the Last Run Time clock.
  2. Let the machine sleep past the plan's next scheduled run time.
  3. Wake the machine.
  4. Observe two backups of the same plan run back-to-back, rather than one catch-up backup.

Reproduced on three consecutive wakes. A run that fires while the machine is already awake, with no clock jump, runs only once; the duplication is specific to the wake/clock-jump. Also see additional context below.

Expected behavior

One catch-up backup on wake, with the next run scheduled one interval after that single backup completes.

Platform Info

  • OS and Architecture: Windows 11 Home, version 25H2 (OS build 26200.9457), x64-based processor
  • Backrest Version: 1.14.1 (commit 875c9cb), restic 0.19.1

Additional context

  • Native install using the installer's system-user option, so Backrest runs as SYSTEM.
  • Repository on Backblaze B2 via the S3 endpoint.
  • Plan's schedule block from config.json:
    json
    "schedule": { "maxFrequencyHours": 12, "clock": "CLOCK_LAST_RUN_TIME" }
  • Sequence from the process log (local time, UTC-6; ts values converted, full redacted log below):
  1. 18:08:46 - the watchdog logs detected a clock jump ... rescheduling all tasks, and in the same millisecond the overdue backup (runAt 07:47:58) starts running.
  2. The queue reset then re-adds the same plan's backup with the same overdue runAt, presumably because the last-run-time anchor hasn't updated while the first backup is still in progress.
  3. 18:14:26 - the first backup completes, and its own reschedule is skipped: task was created before last queue reset, skipping reschedule.
  4. 18:14:28 - after a short index-snapshots task, the re-added backup runs, finishing at 18:19:25.
  5. The next backup is scheduled for 06:19:25 the following day, 12 hours after the second backup.
  • Suspected cause: the clock-jump reschedule rebuilds the queue while the plan's backup is already dequeued and running. Because the rebuild computes the next run from the last completed run, it re-adds a backup that is already overdue, and it does not account for the in-progress one.
  • Impact: low; the second snapshot is deduplicated and small, but it costs an extra backup run and upload on every wake.
  • Possibly separate, minor: per-run log timestamps carry a Z suffix but are actually local time; the per-run log shows the backup command at 18:09:05.401Z, while the resulting snapshot's backup_start is 18:09:05-06:00.

Redacted Log

The first line is from the previous evening and shows the overdue run time being set; everything after ... is the wake on 2026-09-10.

json
{"level":"info","ts":1789004878.870042,"msg":"scheduled task","task":"backup for plan \"<PLAN>\"","runAt":"2026-09-10T07:47:58-06:00"}
...
{"level":"warn","ts":1789085326.053549,"msg":"detected a clock jump, watchdog timer is off from realtime by 55505638ms, rescheduling all tasks"}
{"level":"warn","ts":1789085326.0702553,"msg":"syncmanager detected clock jump of 15h25m5.6243421s, forcing reconnection"}
{"level":"info","ts":1789085326.0545492,"msg":"running task","task":"backup for plan \"<PLAN>\"","runAt":"2026-09-10T07:47:58-06:00"}
{"level":"info","ts":1789085326.0775073,"msg":"scheduling default tasks, waiting for task queue reset."}
{"level":"info","ts":1789085326.079398,"msg":"syncmanager applying new config, waiting for existing sync goroutines to exit"}
{"level":"info","ts":1789085326.115433,"msg":"syncmanager no known host peers declared, sync client exiting early"}
{"level":"info","ts":1789085326.1507993,"msg":"reset task queue, scheduling new task set","timezone":"Local"}
{"level":"info","ts":1789085326.1507993,"msg":"scheduled task","task":"collect garbage","runAt":"2026-09-10T18:08:47-06:00"}
{"level":"info","ts":1789085326.1772835,"msg":"scheduled task","task":"backup for plan \"<PLAN>\"","runAt":"2026-09-10T07:47:58-06:00"}
{"level":"info","ts":1789085666.5695813,"msg":"scheduled task","task":"index snapshots for repo \"b2-primary\"","runAt":"2026-09-10T18:14:26-06:00"}
{"level":"debug","ts":1789085666.5776272,"msg":"task was created before last queue reset, skipping reschedule","task":"backup for plan \"<PLAN>\""}
{"level":"info","ts":1789085666.5776272,"msg":"running task","task":"index snapshots for repo \"b2-primary\"","runAt":"2026-09-10T18:14:26-06:00"}
{"level":"debug","ts":1789085668.578541,"msg":"found 6 known snapshot IDs for repo <REPO_GUID> in 1.0387ms"}
{"level":"info","ts":1789085668.5801618,"msg":"running task","task":"backup for plan \"<PLAN>\"","runAt":"2026-09-10T07:47:58-06:00"}
{"level":"info","ts":1789085965.0296881,"msg":"scheduled task","task":"index snapshots for repo \"b2-primary\"","runAt":"2026-09-10T18:19:25-06:00"}
{"level":"info","ts":1789085965.036581,"msg":"scheduled task","task":"backup for plan \"<PLAN>\"","runAt":"2026-09-11T06:19:25-06:00"}
{"level":"info","ts":1789085965.036581,"msg":"running task","task":"index snapshots for repo \"b2-primary\"","runAt":"2026-09-10T18:19:25-06:00"}
{"level":"debug","ts":1789085966.6304207,"msg":"found 7 known snapshot IDs for repo <REPO_GUID> in 506.6µs"}
{"level":"info","ts":1789085966.6314995,"msg":"running task","task":"collect garbage","runAt":"2026-09-10T18:08:47-06:00"}
{"level":"info","ts":1789085966.6336055,"msg":"collecting garbage operations","operations_removed":0,"removed_by_age":0,"removed_by_limit":0,"removed_by_snapshot_forgotten":0,"removed_by_type":{},"removed_by_unknown_peer_keyid":0}
{"level":"info","ts":1789085966.6357293,"msg":"collecting garbage logs","logs_removed":0}
{"level":"info","ts":1789085966.6362543,"msg":"scheduled task","task":"collect garbage","runAt":"2026-09-11T18:19:26-06:00"}