borgbase / vorta

Desktop Backup Client for Borg Backup
https://vorta.borgbase.com
GNU General Public License v3.0
1.98k stars 132 forks source link

Incomplete database migration: duplicate column name #1761

Closed sysdbugfactory closed 5 months ago

sysdbugfactory commented 1 year ago

Description

Vorta is configured to launch automatically when opening a user session. I noticed the vorta icon was missing from the tray so I tried launching it manually which seemed to have no effect. I then tried to invoke it from a terminal where vorta told me it failed with a CRITICAL error uncaught exception and directed me to report a bug here. it seems the issue is database related with a sqlite3 error about a duplicate column name.

I am able to reproduce the issue on my computer as the current local database state seems to be the culprit, but I don't think someone else will be able to reproduce the bug on a different computer.

I have no clue as to how the local sqlite database got into this state. I suspect some kind of migration process went wrong somewhere. Maybe it tries to repeat itself despite having been already applied ?

Environment

Terminal Output

2023-07-27 17:38:06,588 - 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/dist-packages/peewee.py", line 3177, in execute_sql
    cursor.execute(sql, params or ())
sqlite3.OperationalError: duplicate column name: schedule_interval_unit

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/bin/vorta", line 33, in <module>
    sys.exit(load_entry_point('vorta==0.8.10', 'gui_scripts', 'vorta')())
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/vorta/__main__.py", line 66, in main
    init_db(sqlite_db)
  File "/usr/lib/python3/dist-packages/vorta/store/connection.py", line 83, in init_db
    run_migrations(current_schema, con)
  File "/usr/lib/python3/dist-packages/vorta/store/migrations.py", line 190, in run_migrations
    _apply_schema_update(
  File "/usr/lib/python3/dist-packages/vorta/store/migrations.py", line 225, in _apply_schema_update
    migrate(*operations)
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 886, in migrate
    operation.run()
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 164, in run
    self._handle_result(method(*self.args, **kwargs))
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 158, in _handle_result
    self._handle_result(item)
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 155, in _handle_result
    result.run()
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 164, in run
    self._handle_result(method(*self.args, **kwargs))
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 153, in _handle_result
    self.execute(result)
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 149, in execute
    self.migrator.database.execute(node)
  File "/usr/lib/python3/dist-packages/peewee.py", line 3190, in execute
    return self.execute_sql(sql, params, commit=commit)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/peewee.py", line 3174, in execute_sql
    with __exception_wrapper__:
  File "/usr/lib/python3/dist-packages/peewee.py", line 2950, in __exit__
    reraise(new_type, new_type(exc_value, *exc_args), traceback)
  File "/usr/lib/python3/dist-packages/peewee.py", line 191, in reraise
    raise value.with_traceback(tb)
  File "/usr/lib/python3/dist-packages/peewee.py", line 3177, in execute_sql
    cursor.execute(sql, params or ())
peewee.OperationalError: duplicate column name: schedule_interval_unit

Looking into closed bug reports it seems this has already happened sporadically a few times in the past, see the following issues: https://github.com/borgbase/vorta/issues/1114 https://github.com/borgbase/vorta/issues/1117 https://github.com/borgbase/vorta/issues/1364 https://github.com/borgbase/vorta/issues/1501

The proposed solution on those closed issue are probably obsolete and lack a detailed step by step solution.

What is the step by step process to check the current database schema is the proper one ? What is the step by step process to update the database version so the migration does not trigger again and where can I find the correct value ?

thanks

m3nu commented 1 year ago

You probably used the Git version at some point and already have this migration in your settings DB. Solution is to find the settings.db (?) file and increase the schema version number there.

sysdbugfactory commented 1 year ago

As this computer has been running debian stable for over 10 years since debian squeeze and never had any other source for software installation than debian stable repository, we can safely exclude the git version hypothesis as there is no chance this applies here.

As mentioned in my report I had gathered from the other closed issue that such a manual edit could allow vorta to start again, but as I said I would like to verify first that the migration has been properly applied before engaging in mindless editing of version numbers. I'd rather avoid risking breaking things by doing a manual edit without making sure the database is not affected by a partial migration.

As also mentioned I have no clue on how to do such an edit and require a step by step guide to do so, along with the version number I am supposed to put in.

Had such a guide been provided the first time the issue was reported here, I would have been able to fix the issue on my own without opening a new issue.

FWIW here are my 2 cents of feedback: IMHO having a user edit the software database seems like a hackish workaround and a recipe for disaster. Certainly not a proper and elegant solution to an issue that should not happen in the first place. The migration process should be able to detect that the migration has already been done and that it does not need to be applied again instead of throwing a critical uncaught exception.

The fact that the migration process could proceed without updating to the correct version at all seems to me to be a matter of concern, that it has happened several times to different people in recent years seems to call for an investigation in what is causing this issue to happen and improving the migration process to prevent the issue from happening again or fixing it automatically when it happens.

sysdbugfactory commented 1 year ago

Trying to understand what could have caused this issue to happen in the first place, I looked at the logs in $HOME/.cache/Vorta/log

I think I found the moment it happened about a month ago, the log file vorta.log.2023-06-29 states

2023-06-28 14:23:47,181 - vorta.scheduler - INFO - Setting timer for profile 1
2023-06-28 14:23:47,185 - vorta.scheduler - INFO - Nothing scheduled for profile 1 because it would be the first backup for this profile.
2023-06-28 14:27:04,025 - 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/dist-packages/peewee.py", line 3177, in execute_sql
    cursor.execute(sql, params or ())
sqlite3.OperationalError: duplicate column name: schedule_interval_unit

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/bin/vorta", line 33, in <module>
    sys.exit(load_entry_point('vorta==0.8.10', 'gui_scripts', 'vorta')())
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/vorta/__main__.py", line 66, in main
    init_db(sqlite_db)
  File "/usr/lib/python3/dist-packages/vorta/store/connection.py", line 83, in init_db
    run_migrations(current_schema, con)
  File "/usr/lib/python3/dist-packages/vorta/store/migrations.py", line 190, in run_migrations
    _apply_schema_update(
  File "/usr/lib/python3/dist-packages/vorta/store/migrations.py", line 225, in _apply_schema_update
    migrate(*operations)
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 886, in migrate
    operation.run()
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 164, in run
    self._handle_result(method(*self.args, **kwargs))
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 158, in _handle_result
    self._handle_result(item)
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 155, in _handle_result
    result.run()
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 164, in run
    self._handle_result(method(*self.args, **kwargs))
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 153, in _handle_result
    self.execute(result)
  File "/usr/lib/python3/dist-packages/playhouse/migrate.py", line 149, in execute
    self.migrator.database.execute(node)
  File "/usr/lib/python3/dist-packages/peewee.py", line 3190, in execute
    return self.execute_sql(sql, params, commit=commit)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/peewee.py", line 3174, in execute_sql
    with __exception_wrapper__:
  File "/usr/lib/python3/dist-packages/peewee.py", line 2950, in __exit__
    reraise(new_type, new_type(exc_value, *exc_args), traceback)
  File "/usr/lib/python3/dist-packages/peewee.py", line 191, in reraise
    raise value.with_traceback(tb)
  File "/usr/lib/python3/dist-packages/peewee.py", line 3177, in execute_sql
    cursor.execute(sql, params or ())
peewee.OperationalError: duplicate column name: schedule_interval_unit

Past this point all logs are the same error repeating again and again.

I am unsure what happened there, vorta has been running for at least a couple years and no change have been made to the profile. vorta logs being out of band from the system logs it is difficult to trace if something else happened elsewhere on the system that could have lead to this issue happening.

sysdbugfactory commented 1 year ago

After a week I am back on site but with no proper solution offered in the meantime, I have no other choice but to remove vorta and switch to another way of having borg backup run on this computer as it cannot stay any longer without backups.

Additional information: this system has several user profiles, each with its own vorta instance and user backup profiles, so each have their own separate settings. All the user profiles I tested on the computer are affected by the same error. And vorta fails to run on every profile.

Latest upgrade of vorta dates back to the range between 2021-04-11 and 2021-04-18 depending on user profile.

The issue appeared after upgrading debian stable from v11 bullseye to v12 bookworm follwing the official debian manual: https://www.debian.org/releases/stable/amd64/release-notes/index.en.html

I am in charge of a few other debian stable computers at different remote sites relying on vorta for their backup strategy, I'll have to check each one to make sure there are not affected by this issue too and remove vorta there if required until a proper fix is released somewhere.

I have to say that my trust in vorta has been affected by this, as there is no warning that vorta fails to start the user do not notive the issue and are unaware their data is not safe. It is quite bad to discover by chance that the backup software has stopped running by itself a month ago. With this problem being known for years popping here and there, the lack of a proper guide anyone can follow to fix this situation is unsettling.

real-yfprojects commented 1 year ago

I have to say that my trust in vorta has been affected by this, as there is no warning that vorta fails to start the user do not notive the issue and are unaware their data is not safe. It is quite bad to discover by chance that the backup software has stopped running by itself a month ago. With this problem being known for years popping here and there, the lack of a proper guide anyone can follow to fix this situation is unsettling.

I am sorry to hear about your discontent. Vorta is not a software sold and developed by a company or a team of developers. At the moment there are only two guys maintaining the software in their free time. We are working on growing the community though, e.g. with our ongoing participation in GSoC. That is to say there are many major and minor issues with Vorta that have to be solved but we only have limited resources. While we do have a large (technical) user base, there are a few regular contributors but little regular help with reviewing PRs, fixing bugs and triaging issues. The latter being quite difficult in complex desktop environments and dependencies.

The same applies to this issue. We have very limited information on the state of the database and how it has gotten into this state. And now we are expected to remotely solve the problem without any idea what went wrong. This is especially difficult since the database is managed by our dependency peewee. We therefore don't know whether the underlying issue lies in our code or in theirs.

To start of I would be very pleased if you could provide me the database that led to this issue. If you do not want to disclose it here you can also send it to my gmail address with the user name yfprojects. Thanks.

However I do see a general problem with the current way Vorta handles db migrations. Next time something happens like you report Vorta should only try to migrate those database parts that actually need to be changed. That means it shouldn't try to add a column if the column already exists. I just hope peewee provides a way to do that. I'll open a seperate issue to track this feature request.

Regarding your second point that Vorta fails in secrecy we are already planning on improving error handling.

sysdbugfactory commented 1 year ago

I do understand what an open source project is and how it oftens runs on limited resources.

That said I am not asking you to fix my problem remotely, but simply to give me explicit information so I can help myself without losing my data. As this is recurring issue, IMHO having a step by step guide in the documentation would lighten the support need by allowing user to help themselves, until you get around to look into the issue and improve the migration process.

I am sorry I cannot provide the database, as I said I had to remove vorta because it is not reliable enough at the moment that I can trust it for a critical operation such as managing backups. The problematic db is no more, it got deleted when I uninstalled vorta to switch to pika-backup1 which the other GUI for borg backup. Hopefully at some point in the future vorta will be mature enough and I'll be able to switch back.

Right now I'm considering switching from borg to restic until borg fix their security and crypto issues planned in the v2 rewrite and v1.3.

real-yfprojects commented 1 year ago

That said I am not asking you to fix my problem remotely, but simply to give me explicit information so I can help myself without losing my data. As this is recurring issue, IMHO having a step by step guide in the documentation would lighten the support need by allowing user to help themselves, until you get around to look into the issue and improve the migration process.

Well, in practice you are requesting for a remote fix. There is little difference between fixing something myself or providing instructions so that others can fix this. Since I don't in which state your db was I don't know what needs to be fixed. At the same time I have basically no clue what went wrong. I therefore can do little to look into the issue.

With that being said, we can improve the migration process as I already laid out. However that isn't as staightforward as it sounds and will therefore take quite some time to be fixed.

github-actions[bot] commented 5 months ago

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.

github-actions[bot] commented 5 months ago

This issue was closed because it has been stalled for 7 days with no activity.