Recovery fails shortly after starting


#1

Hi all,

Just started using Urbackup 2.2.11 on a Ubuntu 16.04 system with windows clients 2.2.5 (range of OS’s from windows 7 to server 2012). We don’t have any issues running backups, they all do the job just fine. However I’m having great difficulty getting the recover CD to work properly, have also tried multiple versions of the recovery CD with no difference. Half the time it simply won’t find our backup server, the rest of the time it will start a recovery then fail pretty much straight away (I can see the activity appear in the web console and then disappear stating it finished in 1 minute with 0 bytes). The very first time I tried it, the process made it to 6% before failing. All computers and servers are on the same network and subnet, not using internet mode at all (and it’s not an option). Completely at a loss as to what is going on, I’ve put the debug log below, hopefully it can shed some light on what’s going on.

2018-05-23 08:29:05: Starting HTTP-Server on port 55414
2018-05-23 08:29:05: HTTP: Server started up successfully!
2018-05-23 08:29:05: SQLite: recovered 13127 frames from WAL file /var/urbackup/backup_server.db-wal code: 283
2018-05-23 08:29:05: SQLite: recovered 73081 frames from WAL file /var/urbackup/backup_server_files.db-wal code: 283
2018-05-23 08:29:05: SQLite: recovered 8830 frames from WAL file /var/urbackup/backup_server_link_journal.db-wal code: 283
2018-05-23 08:29:05: SQLite: recovered 31958 frames from WAL file /var/urbackup/backup_server_links.db-wal code: 283
2018-05-23 08:29:05: SQLite: recovered 493 frames from WAL file /var/urbackup/backup_server_settings.db-wal code: 283
2018-05-23 08:29:05: SQLite: recovered 13127 frames from WAL file /var/urbackup/backup_server.db-wal code: 283
2018-05-23 08:29:05: SQLite: recovered 493 frames from WAL file /var/urbackup/backup_server_settings.db-wal code: 283
2018-05-23 08:29:05: SQLite: recovered 73081 frames from WAL file /var/urbackup/backup_server_files.db-wal code: 283
2018-05-23 08:29:06: SQLite: recovered 31958 frames from WAL file /var/urbackup/backup_server_links.db-wal code: 283
2018-05-23 08:29:06: SQLite: recovered 8830 frames from WAL file /var/urbackup/backup_server_link_journal.db-wal code: 283
2018-05-23 08:29:06: Started UrBackup…
2018-05-23 08:29:06: Removing temporary files…
2018-05-23 08:29:06: Recreating temporary folder…
2018-05-23 08:29:06: Testing if backup destination can handle subvolumes and snapshots…
Testing for btrfs…
ERROR: not a btrfs filesystem: /media/BACKUP//testA54hj5luZtlorr494
TEST FAILED: Creating test btrfs subvolume failed
Testing for zfs…
TEST FAILED: Dataset is not set via /etc/urbackup/dataset
2018-05-23 08:29:06: Backup destination cannot handle subvolumes and snapshots. Snapshots disabled.
2018-05-23 08:29:06: Testing if backup destination can handle filesystem transactions…
MOUNT TEST OK
2018-05-23 08:29:06: Binding to interface enp2s0f0 for broadcasting…
2018-05-23 08:29:06: Broadcasting on interface IP 192.168.70.240
2018-05-23 08:29:06: UrBackup Server start up complete.
2018-05-23 08:29:06: Server started up successfully!
2018-05-23 08:29:06: Looking for old Sessions… 0 sessions
2018-05-23 08:29:06: Downloading version file…
2018-05-23 08:29:08: Downloading version file…
2018-05-23 08:29:08: Downloading version file…
2018-05-23 08:29:09: Downloading server version info…
2018-05-23 08:29:10: Downloading dataplan database…

2018-05-23 08:29:37: Getting client settings…
2018-05-23 08:29:37: Getting client settings…
2018-05-23 08:29:37: Getting client settings…
2018-05-23 08:29:37: Flushing FileClient…
2018-05-23 08:29:38: Getting client settings…
2018-05-23 08:29:38: Sending backup incr interval…

2018-05-23 08:29:49: HTTP: No available slots… starting new Worker
2018-05-23 08:31:18: New Backupclient: ##restore##15270677648220
2018-05-23 08:31:37: Socket has error: 111
2018-05-23 08:31:43: Channel message: LOGIN username=&password=
2018-05-23 08:31:43: Lost channel connection to ##restore##15270677648220. has_error=true
2018-05-23 08:31:44: Socket has error: 111
2018-05-23 08:31:44: Connecting Channel to ##restore##15270677648220 failed - CONNECT error -55
2018-05-23 08:31:59: Channel message: SALT username=admin
2018-05-23 08:32:02: Channel message: LOGIN username=admin&password=486bb3a8cd536c88d1211bb7c36e33d4
2018-05-23 08:32:02: Channel message: GET BACKUPCLIENTS
2018-05-23 08:32:05: Channel message: GET BACKUPIMAGES ******
2018-05-23 08:32:07: Channel message: DOWNLOAD IMAGE with_used_bytes=1&img_id=500128486&time=1526873311&mbr=true
2018-05-23 08:32:18: Channel message: DOWNLOAD IMAGE with_used_bytes=1&img_id=500128486&time=1526873311&mbr=false
2018-05-23 08:32:35: ERROR: Writing to output pipe failed processMsg-1
2018-05-23 08:32:35: Socket has error: 111
2018-05-23 08:32:35: Connecting Channel to ##restore##15270677648220 failed - CONNECT error -55
2018-05-23 08:32:37: Socket has error: 111
2018-05-23 08:32:45: Socket has error: 111
2018-05-23 08:32:45: Connecting Channel to ##restore##15270677648220 failed - CONNECT error -55


#2

Ok so after a bit of testing, it seems that the particular drive or other hardware in the machine I were restoring to was faulty. The process worked flawlessly from a different PC. One other thing I did however was to completely disable the UFW in Ubuntu and flush the ip tables as well.