on_scheduler_change callback causes race conditions in updating BackupProfile, causing spurious catch-up runs #2316
Description
Description
In short: due to the controls loading their values sequentially, calling on_scheduler_change for every control change event results in BackupProfile's schedule fields being briefly reset to 0 at startup. This causes a race condition with the startup check for a "missed run": the missed-run check can happen before the controls fully load, which means it is run with e.g. a FixedTime of 0h0m, that is, midnight.
When this happens, Vorta incorrectly runs a catch-up run, because given a run the previous day, it calculates the "next run" as happening at midnight of the current day, which is always in the past, and thus "missed".
Details
on_scheduler_change gets called three times at startup, once for each field (intervalUnit, intervalCount, fixedTime). Because on_scheduler_change unconditionally updates all fields of profile, the following sequence occurred during my testing, with time since first log line on the left:
| time | update source | interval_unit | interval_count | fixed_hour | fixed_minute |
|---|---|---|---|---|---|
| 350ms | intervalUnit | (set) | 0 | 0 | 0 |
| 440ms | intervalCount | (set) | (set) | 0 | 0 |
| 480ms | fixedTime | (set) | (set) | (set) | (set) |
In my tests, the missed-run check calculated its next_time at 385ms, thus getting the incorrect midnight fixedTime set.
Proposed fixes
The simplest reasonable fix would probably be to use separate callbacks for each update that only updates the relevant fields. This would result in more database updating than is strictly necessary, but that's probably fine.
Debouncing the callback would fix this instance, but leaves it open to slower machines running into the same issue.
Perhaps a better fix would be to keep a flag for each control that is set the first time it fires an update callback, so that we could wait to update the profile until every control has been updated. Or, alternately, until the control is updated a second time - since the first time is just from loading the data from profile anyway (and thus we don't need to save those values back to profile). I doubt it is possible for a user to e.g. update intervalUnit before fixedTime has loaded, so updating on the second call from any given control should be safe.
I'd be glad to open PRs for any of the above approaches, let me know if you have preferences (or a different approach)
Background
I was investigating #2312 and noticed some strange log lines in there - it's clear that the user had set the time to 18:00, and yet these lines were present at the beginning of the log:
2025-12-10 09:48:06,138 - vorta.scheduler - INFO - Setting timer for profile 1
2025-12-10 09:48:06,139 - vorta.scheduler - DEBUG - Scheduling next run for 2025-12-11 00:00:00
2025-12-10 09:48:06,153 - vorta.scheduler - INFO - Setting timer for profile 1
2025-12-10 09:48:06,154 - vorta.scheduler - DEBUG - Scheduling next run for 2025-12-11 00:00:00
2025-12-10 09:48:06,163 - vorta.scheduler - INFO - Setting timer for profile 1
2025-12-10 09:48:06,163 - vorta.scheduler - DEBUG - Scheduling next run for 2025-12-11 18:00:00
I was able to reproduce by reconstructing the user's situation: using faketime to do a little time travelling, I created a new repo, set the schedule for 6pm, ran it at 10am, and then skipped forward to the next day at 10am. As the user described, Vorta ran a "catch-up" for a nonexistent scheduled run, and then scheduled for the next day. I also saw the spurious midnight schedules and catch-up run, and tracked them down with some added logging. The debug-scheduler-race branch in my fork has the added logging for reference.
Reproduction
- I tried to reproduce the issue.
- I was able to reproduce the issue.
OS
Ubuntu 25.04, xfce
Version of Vorta
v0.11.1 (run from dev, git commit 996aa8c)
What did you install Vorta with?
Other
Version of Borg
1.4.0
Logs
2025-12-16 10:57:57,642 - vorta.i18n - DEBUG - Loading translation succeeded for ['en-Latn-US', 'en-US', 'en-Latn', 'en'].
2025-12-16 10:57:57,744 - root - DEBUG - Not a private SSH key file: authorized_keys~
2025-12-16 10:57:57,744 - root - DEBUG - Not a private SSH key file: authorized_keya
2025-12-16 10:57:57,745 - root - DEBUG - Not a private SSH key file: .authorized_keys.un~
2025-12-16 10:57:57,745 - root - DEBUG - Not a private SSH key file: authorized_keys
2025-12-16 10:57:57,760 - vorta.views.source_tab - DEBUG - Added item number 0 from 1
2025-12-16 10:57:57,980 - root - INFO - Using NetworkManagerMonitor NetworkStatusMonitor implementation.
2025-12-16 10:57:57,993 - vorta.views.schedule_page - DEBUG - sc (intervalUnit) profile 2: 18 0
2025-12-16 10:57:58,025 - vorta.views.schedule_page - DEBUG - sc profile 2: 0 0
2025-12-16 10:57:58,026 - vorta.scheduler - DEBUG - Profile: 2, 0 0
2025-12-16 10:57:58,027 - vorta.scheduler - INFO - Setting timer for profile 2
2025-12-16 10:57:58,027 - vorta.scheduler - DEBUG - last_time: 2025-12-15 10:20:14.248727
2025-12-16 10:57:58,027 - vorta.scheduler - DEBUG - next time (pre-check): 2025-12-16 00:00:00 (0 0)
2025-12-16 10:57:58,027 - vorta.scheduler - DEBUG - Catching up by running job for Testing (2)
2025-12-16 10:57:58,028 - vorta.scheduler - INFO - Starting background backup for Testing
2025-12-16 10:57:58,029 - vorta.notifications - DEBUG - success notifications suppressed
2025-12-16 10:57:58,031 - vorta.keyring.abc - DEBUG - No module named 'objc'
2025-12-16 10:57:58,072 - asyncio - DEBUG - Using selector: EpollSelector
2025-12-16 10:57:58,073 - vorta.keyring.abc - DEBUG - Using VortaSecretStorageKeyring
2025-12-16 10:57:58,073 - vorta.borg.borg_job - DEBUG - Using VortaSecretStorageKeyring keyring to store passwords.
2025-12-16 10:57:58,074 - asyncio - DEBUG - Using selector: EpollSelector
2025-12-16 10:57:58,074 - vorta.keyring.secretstorage - DEBUG - Found 0 passwords matching repo URL.
2025-12-16 10:57:58,074 - vorta.borg.borg_job - DEBUG - Password not found in primary keyring. Falling back to VortaDBKeyring.
2025-12-16 10:57:58,078 - vorta.network_status.network_manager - ERROR - Failed to get currently connected WiFi network, assuming none
Traceback (most recent call last):
File "/home/ell/clone/vorta/src/vorta/network_status/network_manager.py", line 35, in get_current_wifi
active_connection = self._nm.get_active_connection_info(active_connection_path)
File "/home/ell/clone/vorta/src/vorta/network_status/network_manager.py", line 135, in get_active_connection_info
connection=read_dbus_property(active_connection, 'Connection'),
~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/home/ell/clone/vorta/src/vorta/network_status/network_manager.py", line 162, in read_dbus_property
return get_result(msg)
File "/home/ell/clone/vorta/src/vorta/network_status/network_manager.py", line 169, in get_result
raise DBusException("DBus call failed: {}".format(msg.arguments()))
vorta.network_status.network_manager.DBusException: DBus call failed: ['Object does not exist at path “/”']
2025-12-16 10:57:58,080 - vorta.scheduler - INFO - Preparation for backup successful.
2025-12-16 10:57:58,081 - vorta.borg.jobs_manager - DEBUG - Add job for site 2
2025-12-16 10:57:58,081 - vorta.borg.jobs_manager - DEBUG - Start job on site: 2
2025-12-16 10:57:58,083 - vorta.views.schedule_page - DEBUG - sc (intervalCount) profile 2: 0 0
2025-12-16 10:57:58,117 - vorta.views.schedule_page - DEBUG - sc profile 2: 0 0
2025-12-16 10:57:58,118 - vorta.scheduler - DEBUG - Profile: 2, 0 0
2025-12-16 10:57:58,119 - vorta.scheduler - INFO - Setting timer for profile 2
2025-12-16 10:57:58,120 - vorta.scheduler - DEBUG - last_time: 2025-12-15 10:20:14.248727
2025-12-16 10:57:58,120 - vorta.scheduler - DEBUG - next time (pre-check): 2025-12-16 00:00:00 (0 0)
2025-12-16 10:57:58,120 - vorta.scheduler - DEBUG - Catching up by running job for Testing (2)
2025-12-16 10:57:58,121 - vorta.scheduler - DEBUG - A job for repo 2 is already active.
2025-12-16 10:57:58,122 - vorta.scheduler - DEBUG - Paused 2 until 2025-12-16 11:57:58
2025-12-16 10:57:58,123 - vorta.views.schedule_page - DEBUG - sc (fixedTime) profile 2: 0 0
2025-12-16 10:57:58,167 - vorta.borg.borg_job - INFO - Running command: /usr/bin/borg create --list --progress --info --log-json --json --filter=AM -C lz4 /home/ell/borgtest2::devcentre-2025-12-16-105758 /home/ell/Pictures/1350px-Love_Actually_(2003)_Interconnections.svg.png
2025-12-16 10:57:58,209 - vorta.views.schedule_page - DEBUG - sc profile 2: 18 0
2025-12-16 10:57:58,210 - vorta.scheduler - DEBUG - Profile: 2, 18 0
2025-12-16 10:57:58,210 - vorta.scheduler - DEBUG - Nothing scheduled for profile 2 because of timeout until 2025-12-16 11:57:58.
2025-12-16 10:57:58,309 - vorta.borg.jobs_manager - DEBUG - Add job for site default
2025-12-16 10:57:58,309 - vorta.borg.jobs_manager - DEBUG - Start job on site: default
2025-12-16 10:57:58,343 - vorta.borg.borg_job - INFO - Running command: /usr/bin/borg --version
2025-12-16 10:57:58,501 - vorta.borg.borg_job - INFO - Creating archive at "/home/ell/borgtest2::devcentre-2025-12-16-105758"
2025-12-16 10:57:58,787 - vorta.borg.jobs_manager - DEBUG - Finish job for site: default
2025-12-16 10:57:58,788 - vorta.scheduler - DEBUG - Refreshing all scheduler timers
2025-12-16 10:57:58,788 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: default
2025-12-16 10:57:58,794 - vorta.scheduler - DEBUG - Profile: 1, 18 0
2025-12-16 10:57:58,794 - vorta.scheduler - DEBUG - Scheduler for profile 1 is disabled.
2025-12-16 10:57:58,796 - vorta.scheduler - DEBUG - Profile: 2, 18 0
2025-12-16 10:57:58,796 - vorta.scheduler - DEBUG - Nothing scheduled for profile 2 because of timeout until 2025-12-16 11:57:58.
2025-12-16 10:57:59,326 - vorta.scheduler - DEBUG - Profile: 2, 18 0
2025-12-16 10:57:59,326 - vorta.scheduler - DEBUG - Nothing scheduled for profile 2 because of timeout until 2025-12-16 11:57:58.
2025-12-16 10:57:59,326 - vorta.borg.jobs_manager - DEBUG - Finish job for site: 2
2025-12-16 10:57:59,326 - vorta.borg.jobs_manager - DEBUG - No more jobs for site: 2
2025-12-16 10:57:59,408 - vorta.notifications - DEBUG - success notifications suppressed
2025-12-16 10:57:59,408 - vorta.scheduler - INFO - Backup creation successful.
2025-12-16 10:57:59,408 - vorta.scheduler - DEBUG - Unpaused 2
2025-12-16 10:57:59,409 - vorta.scheduler - DEBUG - Profile: 2, 18 0
2025-12-16 10:57:59,409 - vorta.scheduler - INFO - Setting timer for profile 2
2025-12-16 10:57:59,410 - vorta.scheduler - DEBUG - last_time: 2025-12-16 10:57:59.165611
2025-12-16 10:57:59,410 - vorta.scheduler - DEBUG - next time (pre-check): 2025-12-17 18:00:00 (18 0)
2025-12-16 10:57:59,410 - vorta.scheduler - DEBUG - Scheduling next run for 2025-12-17 18:00:00
2025-12-16 10:57:59,416 - vorta.scheduler - INFO - Doing post-backup jobs for Testing
2025-12-16 10:57:59,417 - vorta.scheduler - INFO - Finished background task for profile Testing
2025-12-16 10:57:59,417 - vorta.notifications - DEBUG - success notifications suppressed
2025-12-16 10:57:59,418 - vorta.scheduler - DEBUG - Profile: 2, 18 0
2025-12-16 10:57:59,418 - vorta.scheduler - INFO - Setting timer for profile 2
2025-12-16 10:57:59,419 - vorta.scheduler - DEBUG - last_time: 2025-12-16 10:57:59.165611
2025-12-16 10:57:59,419 - vorta.scheduler - DEBUG - next time (pre-check): 2025-12-17 18:00:00 (18 0)
2025-12-16 10:57:59,419 - vorta.scheduler - DEBUG - Scheduling next run for 2025-12-17 18:00:00
2025-12-16 11:12:58,005 - vorta.scheduler - DEBUG - Refreshing all scheduler timers
2025-12-16 11:12:58,009 - vorta.scheduler - DEBUG - Profile: 1, 18 0
2025-12-16 11:12:58,010 - vorta.scheduler - DEBUG - Scheduler for profile 1 is disabled.
2025-12-16 11:12:58,012 - vorta.scheduler - DEBUG - Profile: 2, 18 0
2025-12-16 11:12:58,013 - vorta.scheduler - INFO - Setting timer for profile 2
2025-12-16 11:12:58,013 - vorta.scheduler - DEBUG - last_time: 2025-12-16 10:57:59.165611
2025-12-16 11:12:58,014 - vorta.scheduler - DEBUG - next time (pre-check): 2025-12-17 18:00:00 (18 0)
2025-12-16 11:12:58,014 - vorta.scheduler - DEBUG - Scheduling next run for 2025-12-17 18:00:00