scheduled backup fails with uncaught exception: sqlite3.OperationalError: database is locked

[sysdbugfactory]

Description

This issue happened on a Manjaro linux computer where borg and vorta have been up and running since 2021 with 3 differents backups profiles. Everything is up to date. The computer was rebooted less than 48h ago.

After being AFK for a little while I came back to my computer screen to find a large error window that did not fit the screen and did not allow to copy its content. I was able to find the error in the log file which I pasted below.

Initiating a backup manually on all 3 profiles worked and did not raise this error again.

I was not able to replicate this random database lock that happened unattended.
I'm still filing a report as instructed to document the issue.

Environment

• OS: Manjaro Linux (Arch based)
• Vorta version: 0.8.12
• Installed from: AUR ( https://github.com/borgbase/vorta/archive/v0.8.12.tar.gz )
• Borg version: 1.2.4

Logs

2023-07-30 18:47:50,023 - vorta.network_status.network_manager - WARNING - Couldn't load settings for /org/freedesktop/NetworkManager/Settings/119
Traceback (most recent call last):
  File "/usr/lib/python3.11/site-packages/vorta/network_status/network_manager.py", line 53, in get_known_wifis
    settings = self._nm.get_settings(connection_path)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/vorta/network_status/network_manager.py", line 143, in get_settings
    return get_result(settings.call('GetSettings'))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/vorta/network_status/network_manager.py", line 167, in get_result
    raise DBusException("DBus call failed: {}".format(msg.arguments()))
vorta.network_status.network_manager.DBusException: DBus call failed: ['uid 1000 has no permission to perform this operation']

2023-07-30 18:48:03,000 - root - CRITICAL - Uncaught exception, file a report at https://github.com/borgbase/vorta/issues/new/choose
Traceback (most recent call last):
  File "/usr/lib/python3.11/site-packages/peewee.py", line 3246, in execute_sql
    cursor.execute(sql, params or ())
sqlite3.OperationalError: database is locked

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.11/site-packages/vorta/views/schedule_tab.py", line 161, in populate_from_profile
    self.populate_wifi()
  File "/usr/lib/python3.11/site-packages/vorta/views/schedule_tab.py", line 183, in populate_wifi
    for wifi in get_sorted_wifis(self.profile()):
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/vorta/utils.py", line 332, in get_sorted_wifis
    db_wifi.save()
  File "/usr/lib/python3.11/site-packages/playhouse/signals.py", line 71, in save
    ret = super(Model, self).save(*args, **kwargs)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/peewee.py", line 6785, in save
    rows = self.update(**field_dict).where(self._pk_expr()).execute()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/peewee.py", line 1966, in inner
    return method(self, database, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/peewee.py", line 2037, in execute
    return self._execute(database)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/peewee.py", line 2555, in _execute
    cursor = database.execute(self)
             ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/peewee.py", line 3254, in execute
    return self.execute_sql(sql, params)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/peewee.py", line 3244, in execute_sql
    with __exception_wrapper__:
  File "/usr/lib/python3.11/site-packages/peewee.py", line 3014, in __exit__
    reraise(new_type, new_type(exc_value, *exc_args), traceback)
  File "/usr/lib/python3.11/site-packages/peewee.py", line 192, in reraise
    raise value.with_traceback(tb)
  File "/usr/lib/python3.11/site-packages/peewee.py", line 3246, in execute_sql
    cursor.execute(sql, params or ())
peewee.OperationalError: database is locked

[m3nu]

sqlite3.OperationalError: database is locked

Is the DB opened in another application?

[sysdbugfactory]

Is the DB opened in another application?

I cannot think of an application that would access this DB apart from vorta itself.
so most probably not.

[sten0]

Out of curiosity, did you recently restore your full home directory from a vorta backup?

[sysdbugfactory]

No home directory restore in recent history or ever.

The home directory on this computer is not part of the backups as it is mostly empty and holds no file of importance.

Could it be that vorta locked the database when it tried and failed to gather information about the network connections and remained locked while waiting for a timeout as a scheduled backup tried to launch ?

[sten0]

sysdbugfactory ***@***.***> writes:

No home directory restore in recent history or ever. The home directory on this computer is not part of the backups as it is mostly empty and holds no file of importance.

If you mean that the $HOME of the user who runs Vorta is not part of the dataset that is backed up, then this refutes my hypothesis.

Could it be that vorta locked the database when it tried and failed to gather information about the network connections and remained locked while waiting for a timeout as a scheduled backup tried to launch ?

Good question, I think you might be on to something! :)

[sysdbugfactory]

that's what I meant. $HOME is not part of the dataset.

This network_manager WARNING is a recurring occurence that shows up quite a number of times in the logs, so it could be an unlucky coincidence that both this and the scheduled backup happened at the same time.

grep "vorta.network_status.network_manager - WARNING" * | wc -l gives 343 occurences over the last 6 days.

[github-actions]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[sten0]

sysdbugfactory ***@***.***> writes:

that's what I meant. $HOME is not part of the dataset.

Ok, that rules that out :)

This network_manager WARNING is a recurring occurence that shows up quite a number of times in the logs, so it could be an unlucky coincidence that both this and the scheduled backup happened at the same time. `grep "vorta.network_status.network_manager - WARNING" * | wc -l` gives 343 occurences over the last 6 days.

@sysdbugfactory Have things improved in the months since you wrote this? I seem to remember that there may have been some some network-manager changes in the Vorta 0.9.x series.

[m3nu]

We can tone down those logs, if there are too many.