ERROR: Upgrading database failed going to official Debian 2.1.19 package

dickon.reed · April 5, 2017, 7:18am

I wanted to upgrade my urbackup server, so I:

Upgrade its OS to Debian 8 (from 7).
wget https://hndl.urbackup.org/Server/2.1.19/urbackup-server_2.1.19_amd64.deb
Installed the deb
I then got a working urbackup server but without any of my clients or backups, since the deb is using /var/urbackup and my old install had the database in /usr/local/var/urbackup.
Took the server down (/etc/init.d/urbackupsrv stop)
Copied the database over from /usr/local/var/urbackup.
Started the server again
Database upgrade ran.
Database upgrade failed, according to the web interface and log.
Took the server down.
Copied back the database from a failed device containing 1 which I rebuilt and fscked
Put the server up.
The database upgrade failed again.
The urbackup web interface is now down and I now see in the tail of /var/log/urbackup.log:

2017-04-01 20:45:40: ERROR: Error getting file patch for “6BBHhwdwPmO9g9cGRwVm|C/Program Files/UrBackup/urbackup/open_files.dat” from ruby. Errorcode: TIMEOUT (2)
2017-04-01 20:45:41: ERROR: Client ruby went offline.
2017-04-01 20:56:12: ERROR: Backup failed
2017-04-01 20:56:12: WARNING: Exponential backoff: Waiting at least 40m before next file backup
2017-04-01 20:56:12: WARNING: Connecting to ClientService of “ruby” failed: Sending logdata to client failed
2017-04-01 20:56:13: ERROR: Error opening file ‘/home/dickon/urbackups/mouse/Image_C_140814-0450.vhd’
2017-04-01 20:56:13: ERROR: Error opening file ‘/home/dickon/urbackups/mouse/Image_C_141013-1052.vhdz’
2017-04-01 20:56:13: ERROR: Error opening file ‘/home/dickon/urbackups/mouse/Image_C_141021-1000.vhdz’
2017-04-01 20:56:13: ERROR: Error opening file ‘/home/dickon/urbackups/mouse/Image_C_141030-2038.vhdz’
2017-04-01 20:56:13: ERROR: Error opening file ‘/home/dickon/urbackups/mouse/Image_C_141107-1009.vhdz’
2017-04-01 20:56:13: ERROR: Error opening file ‘/home/dickon/urbackups/mouse/Image_C_141119-1114.vhdz’
2017-04-01 21:59:29: WARNING: Shutting down (Signal 15)
2017-04-05 05:47:41: WARNING: Upgrading…
2017-04-05 05:47:41: WARNING: Upgrading database to version 8
2017-04-05 05:47:42: WARNING: Upgrading database to version 9
2017-04-05 05:47:43: WARNING: Upgrading database to version 10
2017-04-05 05:47:45: WARNING: Upgrading database to version 11
2017-04-05 05:47:45: WARNING: Upgrading database to version 12
2017-04-05 05:47:45: WARNING: Upgrading database to version 13
2017-04-05 05:47:45: WARNING: Upgrading database to version 14
2017-04-05 05:47:45: WARNING: Upgrading database to version 15
2017-04-05 05:47:46: WARNING: Upgrading database to version 16
2017-04-05 05:47:46: WARNING: Upgrading database to version 17
2017-04-05 05:47:46: WARNING: Upgrading database to version 18
2017-04-05 05:47:46: WARNING: Upgrading database to version 19
2017-04-05 05:47:46: WARNING: Upgrading database to version 20
2017-04-05 05:47:47: WARNING: Upgrading database to version 21
2017-04-05 05:47:47: WARNING: Upgrading database to version 22
2017-04-05 05:47:47: WARNING: Upgrading database to version 23
2017-04-05 05:47:47: WARNING: Upgrading database to version 24
2017-04-05 05:47:47: WARNING: Upgrading database to version 25
2017-04-05 05:47:48: WARNING: Upgrading database to version 26
2017-04-05 05:47:48: WARNING: Upgrading database to version 27
2017-04-05 05:47:48: WARNING: Upgrading database to version 28
2017-04-05 05:47:48: WARNING: Upgrading database to version 29
2017-04-05 05:47:48: WARNING: Upgrading database to version 30
2017-04-05 05:47:49: WARNING: Upgrading database to version 31
2017-04-05 05:47:49: WARNING: Upgrading database to version 32
2017-04-05 05:47:49: WARNING: Upgrading database to version 33
2017-04-05 05:47:49: WARNING: Upgrading database to version 34
2017-04-05 05:47:49: WARNING: Upgrading database to version 35
2017-04-05 05:47:50: WARNING: Upgrading database to version 36
2017-04-05 05:47:50: WARNING: Upgrading database to version 37
2017-04-05 05:47:50: WARNING: Upgrading database to version 38
2017-04-05 05:47:51: WARNING: Upgrading database to version 39
2017-04-05 05:47:51: WARNING: Upgrading database to version 40
2017-04-05 05:47:51: WARNING: Upgrading database to version 41
2017-04-05 05:47:51: WARNING: Upgrading database to version 42
2017-04-05 05:47:51: WARNING: Upgrading database to version 43
2017-04-05 05:47:52: WARNING: Upgrading database to version 44
2017-04-05 05:47:52: WARNING: Upgrading database to version 45
2017-04-05 05:47:52: WARNING: Upgrading database to version 46
2017-04-05 05:47:53: WARNING: Upgrading database to version 48
2017-04-05 05:47:53: WARNING: Upgrading database to version 49
2017-04-05 05:47:53: WARNING: Upgrading database to version 50
2017-04-05 05:47:53: WARNING: Upgrading database to version 51
2017-04-05 05:47:53: WARNING: Upgrading database to version 52
2017-04-05 05:47:54: WARNING: Upgrading database to version 53
2017-04-05 05:47:54: WARNING: Done.
2017-04-05 05:47:55: WARNING: Creating file entry index. This might take a while…
2017-04-05 05:51:21: WARNING: Shutting down (Signal 15)
2017-04-05 05:52:53: WARNING: Upgrading…
2017-04-05 05:52:53: WARNING: Upgrading database to version 36
2017-04-05 05:52:56: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 05:52:56: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists. Retrying in 1s…
2017-04-05 05:52:57: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 05:52:57: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists. Retrying in 1s…
2017-04-05 05:52:58: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 05:52:58: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists. Retrying in 1s…
2017-04-05 05:52:59: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 05:52:59: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists. Retrying in 1s…
2017-04-05 05:53:00: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 05:53:00: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists. Retrying in 1s…
2017-04-05 05:53:01: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 05:53:01: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists
2017-04-05 05:53:01: ERROR: Upgrading database failed. Shutting down server.
2017-04-05 07:10:58: WARNING: Upgrading…
2017-04-05 07:10:58: WARNING: Upgrading database to version 36
2017-04-05 07:25:34: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 07:25:34: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists. Retrying in 1s…
2017-04-05 07:25:35: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 07:25:35: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists. Retrying in 1s…
2017-04-05 07:25:36: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 07:25:36: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists. Retrying in 1s…
2017-04-05 07:25:37: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 07:25:37: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists. Retrying in 1s…
2017-04-05 07:25:38: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 07:25:38: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists. Retrying in 1s…
2017-04-05 07:25:39: WARNING: SQLite: table files already exists errorcode: 1
2017-04-05 07:25:39: ERROR: Error preparing Query [CREATE TABLE files_db.files (id INTEGER PRIMARY KEY,backupid INTEGER,fullpath TEXT,shahash BLOB,filesize INTEGER,created INTEGER DEFAULT (CAST(strftime(’%s’,‘now’) as INTEGER)),rsize INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT, next_entry INTEGER, prev_entry INTEGER, pointed_to INTEGER)]: table files already exists
2017-04-05 07:25:39: ERROR: Upgrading database failed. Shutting down server.

(The full log is 800MB since it goes back years)

Expected result: I expected the upgrade to work.

I downloaded the server with:

and installed it, so now I have:

root@elephant:/# dpkg -l | grep urbackup
ii  urbackup-server                       2.1.19.0                             amd64        Server for doing backups of clients
root@elephant:/# cat /etc/issue
Debian GNU/Linux 8 \n \l

Note that I am using systemd after upgrading to Jessie.

Some inspection of the database:

sqlite3 /var/urbackup/backup_server.db
sqlite> .schema
CREATE TABLE clients (
 id INTEGER PRIMARY KEY,
 name TEXT,
 lastbackup DATE,
 lastseen DATE
, lastbackup_image DATE, bytes_used_files INTEGER, bytes_used_images INTEGER, delete_pending INTEGER);
CREATE TABLE backups (
 id INTEGER PRIMARY KEY,
 clientid INTEGER,
 backuptime DATE DEFAULT CURRENT_TIMESTAMP,
 incremental INTEGER,
 path TEXT
, complete INTEGER, running DATE, size_bytes INTEGER, done INTEGER, archived INTEGER, archive_timeout INTEGER, size_calculated INTEGER, resumed INTEGER, indexing_time_ms INTEGER);
CREATE TABLE files (
 backupid INTEGER,
 fullpath TEXT,
 shahash BLOB,
 filesize INTEGER,
 created DATE DEFAULT CURRENT_TIMESTAMP
, rsize INTEGER, did_count INTEGER, clientid INTEGER, incremental INTEGER, hashpath TEXT);
CREATE TABLE backup_images (
 id INTEGER PRIMARY KEY,
 clientid INTEGER,
 backuptime DATE DEFAULT CURRENT_TIMESTAMP,
 incremental INTEGER,
 incremental_ref INTEGER,
 path TEXT,
 complete INTEGER
, running DATE, size_bytes INTEGER, version INTEGER, letter TEXT);
CREATE TABLE files_del (
backupid INTEGER,
fullpath TEXT,
shahash BLOB,
filesize INTEGER,
created DATE,
rsize INTEGER,
clientid INTEGER, incremental INTEGER, is_del INTEGER, hashpath TEXT);
CREATE TABLE del_stats (
backupid INTEGER,
image INTEGER,
delsize INTEGER,
created DATE DEFAULT CURRENT_TIMESTAMP
, clientid INTEGER REFERENCES clients(id) ON DELETE CASCADE, incremental INTEGER, stoptime DATE);
CREATE TABLE clients_hist (
 id INTEGER REFERENCES clients(id) ON DELETE CASCADE,
 name TEXT,
 lastbackup DATE,
 lastseen DATE,
 lastbackup_image DATE,
 bytes_used_files INTEGER,
 bytes_used_images INTEGER,
 created DATE DEFAULT CURRENT_TIMESTAMP
, hist_id INTEGER REFERENCES clients_hist_id(id) ON DELETE CASCADE);
CREATE TABLE clients_hist_id (
 id INTEGER PRIMARY KEY,
 created DATE DEFAULT CURRENT_TIMESTAMP
);
CREATE TABLE logs (
 id INTEGER PRIMARY KEY,
 clientid INTEGER REFERENCES clients(id) ON DELETE CASCADE,
 created DATE DEFAULT CURRENT_TIMESTAMP,
 sent INTEGER DEFAULT 0,
 logdata TEXT
, errors INTEGER, warnings INTEGER, infos INTEGER, image INTEGER, incremental INTEGER, resumed INTEGER);
CREATE TABLE misc (
 id INTEGER PRIMARY KEY,
 tkey TEXT,
 tvalue TEXT
);
CREATE INDEX clients_hist_created_idx ON clients_hist (created);
CREATE INDEX logs_created_idx ON logs (created);
CREATE TABLE assoc_images ( img_id INTEGER REFERENCES backup_images(id) ON DELETE CASCADE, assoc_id INTEGER REFERENCES backup_images(id) ON DELETE CASCADE);
CREATE INDEX files_del_idx ON files_del (shahash, filesize, clientid);
CREATE TABLE files_new ( backupid INTEGER, fullpath TEXT, hashpath TEXT, shahash BLOB, filesize INTEGER, created DATE DEFAULT CURRENT_TIMESTAMP, rsize INTEGER, clientid INTEGER, incrementalR);
CREATE TABLE directory_links (id INTEGER PRIMARY KEY,clientid INTGER,name TEXT,target TEXT);
CREATE INDEX directory_links_idx ON directory_links (clientid, name);
CREATE INDEX directory_links_target_idx ON directory_links (clientid, target);
CREATE TABLE directory_link_journal (id INTEGER PRIMARY KEY,linkname TEXT,linktarget TEXT);
CREATE TABLE orig_client_settings (id INTEGER PRIMARY KEY,clientid INTEGER UNIQUE,data TEXT );
CREATE INDEX clients_hist_id_created_idx ON clients_hist_id (created);
CREATE INDEX files_idx ON files (shahash, filesize, clientid);
CREATE INDEX files_did_count ON files (did_count);
CREATE INDEX files_backupid ON files (backupid);
sqlite> select count(*) from files;
4192301
sqlite> select * from misc;
1|db_version|35
2|files_cache|none

On the old snapshot:

root@elephant:/mnt/usr/local/var/urbackup# cat server_version_info.properties
curr_version_num=2000000030

Any suggestions on moving forward? I’m thinking of going back to a clean database with a different backup storage and then copying over the clients and doing new full backups but that’s a shame since I’d have to clear up the old backups as appropriate.

uroni · April 5, 2017, 2:33pm

Are you sure you copied all the database files? It started from a low database version on upgrade which means this is a (partially) new database.

dickon.reed · April 5, 2017, 4:07pm

Is there more than one sqlite file? On the second attempt I did copy /var/urbackup/backup_server.db* and I was assuming that would match all the sqlite content. I’ll try again from the snapshot to confirm. However, due to the way I got the snapshot by failing a live md array I don’t know for sure that I’ve got a consistent database.

dickon.reed · April 7, 2017, 5:59am

Resolved

I ended up doing:

/etc/init.d/urbackupsrv stop
cd /var/urbackup
rm db
rsync -rvap --delete /mnt/usr/local/var/urbackup/* .
/etc/init.d/urbackuprv start

I then watched the database upgrade proceed cleanly in /var/log/ubrbackup.log and after that was able to make backups and use the web interface.

So I think what happened is that I had a mixture of database files from the old and new schemas.