UrBackup Server 2.1.7 beta/Client 2.1.7 (updated) beta

Major changes with server 2.1.x beta

  • Groups for client settings
  • Ability to reconnect during indexing if connection is broken
  • Define which volumes need to be snapshotted together (snapshot groups)
  • Image backup mounting, browsing and archival on Windows, Linux and FreeBSD (does not work in FreeBSD jails and with VHD/VHDZ on FreeBSD)

Major changes with client 2.1.x beta

  • Ability to reconnect during indexing if connection is broken
  • Improved image backup performance
  • Windows Backup API support (tested backup and restore with Microsoft SQL, tested backup with Microsoft Exchange and Hyper V)
  • File backups and restores use the change block data from the change block tracking driver now (you can install the beta client over a CBT client and this will work)
  • Define which volumes need to be snapshotted together (snapshot groups)

Changes with server 2.1.7 beta

  • Timeout archived image backups
  • Do not delete archived images
  • Create metadata directory if directory symlink changes to a directory during incremental file backup
  • Fix symlinked file to file changes during incremental backups with btrfs
  • Hostname database and settings to configure it to not start backups if clients have certain hostnames
  • Apply dataplan limit of 1GB if client says connection is metered
  • Fix patch alignment for large sparse extents (>4GB)
  • Print OS error code if setting file time fails
  • Force settings update after settings change during upgrade
  • Fix resetting thread priorities on Linux
  • Cope with client identity reset (should not occur)
  • Windows msi installer: Ignore ImDisk install return code
  • Remove duplicate executable on Linux
  • Correctly show group archive settings

Changes with client 2.1.6 beta

  • Prevent access_keys.properties race condition
  • Update client access key if not present
  • Properly reserve bit in change indicator for symbolic links and special files. This will cause incremental backups to re-load all files
  • Send information about current connection being metered to server (Windows 10)

Changes with client 2.1.7 beta

  • Make dependency to wlanapi.dll optional, such that the client works on a Windows Server 2012R2 default install

Upgrade process

As always: Replace the executables (via the installers) and the database of the server/client will be updated on first running it.

Place the files from the update directory into C:\Program Files\UrBackupServer\urbackup or /var/urbackup to auto-update clients. Disable Download client from update server in the server settings to prevent the server from downloading the current version.

On Linux e.g. with:

cd /var/urbackup && wget -r -l1 --no-parent --reject "index.html*" -nH -nd -N "https://ssl.webpack.de/beta.urbackup.org/Client/2.1.5%20beta/update/"

or use this update script: https://github.com/ptempier/get_urbackupclient/blob/master/updateclient.sh

Downgrade process (server)

Stop the UrBackup server, restore C:\Program Files\UrBackupServer\urbackup or /var/urbackup from a backup before upgrade and then install the previous version over the beta release.

Downloads

Upgrading from 2.1.6 to 2.1.7, /usr/sbin/urbackupsrv is missing in Debian package, resulting in a non-operational service.

ln -s /usr/bin/urbackupsrv /usr/sbin/urbackupsrv fix the problem

Also, signature files are missing in https://ssl.webpack.de/beta.urbackup.org/Client/2.1.6%20beta/update/ so the clients autoupdate is’nt possible …

Regards,

Upgrading manually with UrBackupUpdate.exe from 2.1.5 to 2.1.6 (W2012 R2 with cbt)
The client doesn’t reconnect to the server, client debug log shows :

2016-12-15 10:36:15: Loaded -fileserv- plugin
2016-12-15 10:36:15: Loaded -fsimageplugin- plugin
2016-12-15 10:36:15: Loaded -cryptoplugin- plugin
2016-12-15 10:36:15: Loading DLL "urbackup.dll" failed. Error Code: 126
2016-12-15 10:36:15: ERROR: Loading urbackup.dll failed
2016-12-15 10:36:15: Looking for old Sessions... 0 sessions

Regards,

Seems to be missing wlanapi.dll on W2012R2. Will try to work-around that issue. Good I forgot to create the signatures :wink:

Thanks for server and client updates, all works fine now :thumbsup: !

Could you please give us more explanations about these new parameters :

Which values should we use to ensure that our office branch VMs WAN backups will always start ?

Regards,

This affects only Windows 10 clients with Wifi set to “metered” or connected via mobile device hotspots.

It looks like since upgrading my test server from 2.1.6 to 2.1.7 client and server, snapshot group together is broken and not all the volumes are backed up (e.g here, volume F: is missing) . Also SYSVOL backup failed on the 1st try and succeed on the second.

Backups :

Logs :

Client settings :

Client debug log :

2016-12-16 13:06:00: ERROR: Not found
2016-12-16 13:07:35: WARNING: Info not found at 'e:' - reindexing
2016-12-16 13:07:35: ERROR: Unknown error for Volume 'e:' - update err=87
2016-12-16 13:07:41: Loaded -fileserv- plugin
2016-12-16 13:07:41: Loaded -fsimageplugin- plugin
2016-12-16 13:07:41: Loaded -cryptoplugin- plugin
2016-12-16 13:07:41: SQLite: recovered 5608 frames from WAL file C:\Program Files\UrBackup\urbackup\backup_client.db-wal code: 283
2016-12-16 13:07:42: urbackupserver: Server started up successfully!
2016-12-16 13:07:42: FileSrv: Backup privileges set successfully
2016-12-16 13:07:42: FileSrv: Backup privileges set successfully (SE_SECURITY_NAME)
2016-12-16 13:07:42: FileSrv: Backup privileges set successfully (SE_RESTORE_NAME)
2016-12-16 13:07:42: FileSrv: Binding UDP socket at port 35622...
2016-12-16 13:07:42: FileSrv: done.
2016-12-16 13:07:42: FileSrv: Disabling new behavior...
2016-12-16 13:07:42: FileSrv: Servername: -SVIMPORT-
2016-12-16 13:07:42: Started UrBackupClient Backend...
2016-12-16 13:07:42: FileSrv: Server started up successfully
2016-12-16 13:07:42: FileSrv: UDP Thread startet
2016-12-16 13:07:42: Filesystem. Vol="\\?\Volume{800fbec7-ce42-11e5-80bb-806e6f6e6963}\" Name="réservé au système" Type="ntfs" VPaths=0 Size=366997504
2016-12-16 13:07:42: Bootable flag set for volume
2016-12-16 13:07:42: Found potential candidate: \\?\Volume{800fbec7-ce42-11e5-80bb-806e6f6e6963}\ Score: 3
2016-12-16 13:07:42: Filesystem. Vol="\\?\Volume{fdfe77c5-a27d-11e6-80fe-d5b618546188}\" Name="data" Type="ntfs" VPaths=1 Size=64421359616
2016-12-16 13:07:42: Bootable flag not set for volume
2016-12-16 13:07:42: Filesystem. Vol="\\?\Volume{04334b41-a8e8-11e6-8100-c00c095e5db9}\" Name="nouveau nom" Type="ntfs" VPaths=1 Size=48315232256
2016-12-16 13:07:42: Bootable flag not set for volume
2016-12-16 13:07:42: Filesystem. Vol="\\?\Volume{800fbec8-ce42-11e5-80bb-806e6f6e6963}\" Name="" Type="ntfs" VPaths=1 Size=64055406592
2016-12-16 13:07:42: Filesystem is System partition. Skipping...
2016-12-16 13:07:42: Filesystem. Vol="\\?\Volume{800fbecc-ce42-11e5-80bb-806e6f6e6963}\" Name="" Type="" VPaths=1 Size=-1
2016-12-16 13:07:42: Bootable flag not set for volume
2016-12-16 13:07:42: Selected volume \\?\Volume{800fbec7-ce42-11e5-80bb-806e6f6e6963}
2016-12-16 13:07:42: System dir: C:\Windows
2016-12-16 13:07:42: Volpath: \\.\C:
2016-12-16 13:07:42: Device is not GPT formatted (0)
2016-12-16 13:07:42: Found no EFI System Partition
2016-12-16 13:07:42: urbackupserver: No available slots... starting new Worker
2016-12-16 13:07:42: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:07:43: Looking for old Sessions... 0 sessions
2016-12-16 13:07:43: Internet only mode not enabled. Waiting for local server for 3:00...
2016-12-16 13:07:43: Final path: E:\
2016-12-16 13:07:43: Cannot read data from device (D:\)
2016-12-16 13:07:43: Device D:\ isn't NTFS formatted
2016-12-16 13:07:43: WARNING: Info not found at 'e:' - reindexing
2016-12-16 13:07:43: Deleting directory FRN info from database...
2016-12-16 13:07:43: Deleting saved journal data from database...
2016-12-16 13:07:43: Starting indexing process..
2016-12-16 13:07:43: Added 0 directory FRNs to temporary database...
2016-12-16 13:07:43: MFT has 0 FRNs.
2016-12-16 13:07:43: Copying directory FRNs to database...
2016-12-16 13:07:43: Dropping temporary database...
2016-12-16 13:07:43: Saving new journal data to database. Forcing update...
2016-12-16 13:07:43: ERROR: Unknown error for Volume 'e:' - update err=87
2016-12-16 13:07:43: Setting indexing to done for e:
2016-12-16 13:07:43: Reindexing of 'e:' done.
2016-12-16 13:07:43: Final path: E:\
2016-12-16 13:07:51: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#1CHANNEL capa=65047&token=158YTMONjujIdlXC3OtS&restore_version=1&virtual_client=
2016-12-16 13:07:51: New channel: Number of Channels: 1
2016-12-16 13:08:33: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:08:51: ClientService cmd: PONG
2016-12-16 13:09:07: ClientService cmd: STATUS DETAIL#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:09:08: ClientService cmd: STATUS DETAIL#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:09:08: rc=0 hasError=true state=0
2016-12-16 13:09:24: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:09:29: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2PING RUNNING pc_done=0&status_id=22&speed_bpms=0&total_bytes=-1&done_bytes=0#token=158YTMONjujIdlXC3OtS
2016-12-16 13:09:29: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#MBR driveletter=E
2016-12-16 13:09:29: rc=0 hasError=true state=0
2016-12-16 13:09:30: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#INCR IMAGE letter=E:&hashsize=3932000&token=158YTMONjujIdlXC3OtS&checksum=1&bitmap=1&status_id=22&running_jobs=1&cbitmapsize=1966028
2016-12-16 13:09:30: Device D:\ isn't NTFS formatted
2016-12-16 13:09:30: Script "C:\Program Files\UrBackup\preimagebackup.bat" does not exist
2016-12-16 13:09:30: Creating shadowcopy of "E:"...
2016-12-16 13:09:31: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:09:32: Number of Writers: 10
2016-12-16 13:09:32: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:32: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:32: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:32: Writer System Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:32: Writer SqlServerWriter has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:32: Writer ASR Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:32: Writer WMI Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:32: Writer Shadow Copy Optimization Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:32: Writer COM+ REGDB Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:32: Writer Registry Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:34: Number of Writers: 10
2016-12-16 13:09:34: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:34: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:34: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:34: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:34: Writer SqlServerWriter has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:34: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:34: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:34: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:34: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:34: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:38: Number of Writers: 10
2016-12-16 13:09:39: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:39: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:39: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2016-12-16 13:09:39: Writer System Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:39: Writer SqlServerWriter has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:39: Writer ASR Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:39: Writer WMI Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:39: Writer Shadow Copy Optimization Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:39: Writer COM+ REGDB Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:39: Writer Registry Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2016-12-16 13:09:39: Shadowcopy path: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy9
2016-12-16 13:09:39: Shadowcopy path: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy10
2016-12-16 13:09:39: Shadowcopy path: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11
2016-12-16 13:09:39: done.
2016-12-16 13:09:39: Change block tracking reports 3 MB have changed on shadow copy \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy9
2016-12-16 13:09:39: Change block tracking active on volume E:
2016-12-16 13:09:39: Bitmap urbackup\hdat_img_e_.cbt does not exist. Nothing to merge.
2016-12-16 13:09:39: Zeroing image hash data of volume E:...
2016-12-16 13:09:39: Change block tracking reports 2.5 MB have changed on shadow copy \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy10
2016-12-16 13:09:39: Change block tracking active on volume f:
2016-12-16 13:09:39: Bitmap urbackup\hdat_img_f_.cbt does not exist. Nothing to merge.
2016-12-16 13:09:39: Zeroing image hash data of volume f:...
2016-12-16 13:09:39: Change block tracking reports 16 MB have changed on shadow copy \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11
2016-12-16 13:09:39: Change block tracking active on volume c:
2016-12-16 13:09:39: Bitmap urbackup\hdat_img_c_.cbt does not exist. Nothing to merge.
2016-12-16 13:09:39: Zeroing image hash data of volume c:...
2016-12-16 13:09:39: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2PING RUNNING pc_done=0&status_id=22&speed_bpms=0&total_bytes=-1&done_bytes=0#token=158YTMONjujIdlXC3OtS
2016-12-16 13:09:39: Filesystem type is ntfs (\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy9)
2016-12-16 13:09:39: TotalNumberOfClusters=15727871 numberOfClusters=15727871 n_clusters=1965984 StartingLcn=0 BitmapSize=15727871 r_bytes=1966000
2016-12-16 13:09:39: Trying to exclude contents of file \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy9\System Volume Information\{0911fc37-c2a9-11e6-8105-d9061d436d57}{3808876b-c176-4e48-b7ae-04046e6cc752} from backup...
2016-12-16 13:09:40: Trying to exclude contents of file \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy9\System Volume Information\{3808876b-c176-4e48-b7ae-04046e6cc752} from backup...
2016-12-16 13:09:40: FSINFO: blocksize=4096 size=64421363200 has_error=false used_space=106016768
2016-12-16 13:09:40: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#MBR driveletter=SYSVOL
2016-12-16 13:09:40: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#MBR driveletter=SYSVOL
2016-12-16 13:09:40: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2PING RUNNING pc_done=0&status_id=24&speed_bpms=0&total_bytes=-1&done_bytes=0#token=158YTMONjujIdlXC3OtS
2016-12-16 13:09:40: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2PING RUNNING pc_done=0&status_id=26&speed_bpms=0&total_bytes=-1&done_bytes=0#token=158YTMONjujIdlXC3OtS
2016-12-16 13:09:40: rc=0 hasError=true state=0
2016-12-16 13:09:40: rc=0 hasError=true state=0
2016-12-16 13:09:40: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#FULL IMAGE letter=SYSVOL&token=158YTMONjujIdlXC3OtS&checksum=1&bitmap=1&status_id=26&running_jobs=3
2016-12-16 13:09:40: Filesystem type is ntfs (\\?\Volume{800fbec7-ce42-11e5-80bb-806e6f6e6963})
2016-12-16 13:09:40: TotalNumberOfClusters=89599 numberOfClusters=89599 n_clusters=11200 StartingLcn=0 BitmapSize=89599 r_bytes=11216
2016-12-16 13:09:40: FSINFO: blocksize=4096 size=367001088 has_error=false used_space=300224512
2016-12-16 13:09:41: Block did change: 0 mixed=true
2016-12-16 13:09:43: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:09:43: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2LOGDATA 1481890181 0-1481890180-Starting unscheduled incremental image backup of volume "C:"...
0-1481890180-Image backup is being backed up in a snapshot group together with volumes E:, c:\
2-1481890181-Backing up System Reserved (SYSVOL) partition failed. Image backup failed
0-1481890181-Time taken for backing up client SVIMPORT: 1s
2-1481890181-Backup failed

2016-12-16 13:09:43: rc=0 hasError=true state=0
2016-12-16 13:09:43: Block did change: 753152 mixed=true
2016-12-16 13:09:43: Block did change: 753792 mixed=false
2016-12-16 13:09:43: Block did change: 753920 mixed=false
2016-12-16 13:09:43: Block did change: 754048 mixed=false
2016-12-16 13:09:43: Block did change: 754176 mixed=false
2016-12-16 13:09:43: Block did change: 772096 mixed=false
2016-12-16 13:09:43: Block did change: 777216 mixed=false
2016-12-16 13:09:43: Block did change: 777344 mixed=false
2016-12-16 13:09:43: Block did change: 777472 mixed=false
2016-12-16 13:09:43: Block did change: 786432 mixed=true
2016-12-16 13:09:43: Sending image done
2016-12-16 13:09:44: rc=0 hasError=true state=4
2016-12-16 13:09:45: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:09:46: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:09:46: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2LOGDATA 1481890185 0-1481890169-Starting unscheduled incremental image backup of volume "E:"...
0-1481890169-Basing image backup on last incremental or full image backup
0-1481890169-Creating writable snapshot of previous image backup...
0-1481890180-Change block tracking active. Max 8 MB have changed.
0-1481890180-Image backup is being backed up in a snapshot group together with volumes f:\, c:\
0-1481890185-Transferred 12.3106 MB - Average speed: 6.66725 MBit/s
0-1481890185-Time taken for backing up client SVIMPORT: 15s
0-1481890185-Backup succeeded

2016-12-16 13:09:51: Deleting shadowcopy for path "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy9\" -2
2016-12-16 13:09:53: rc=0 hasError=true state=0
2016-12-16 13:09:53: rc=0 hasError=true state=0
2016-12-16 13:09:53: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2PING RUNNING pc_done=22&status_id=26&speed_bpms=0&total_bytes=300224512&done_bytes=67354624#token=158YTMONjujIdlXC3OtS
2016-12-16 13:09:53: rc=0 hasError=true state=0
2016-12-16 13:09:53: ClientService cmd: PONG
2016-12-16 13:09:54: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:09:55: Deleting Shadowcopy for dir "E:\"
2016-12-16 13:09:57: Deleting Shadowcopy for dir "f:\"
2016-12-16 13:09:58: Deleting Shadowcopy for dir "c:\"
2016-12-16 13:10:03: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2PING RUNNING pc_done=57&status_id=26&speed_bpms=7836.04&total_bytes=300224512&done_bytes=172306432#token=158YTMONjujIdlXC3OtS
2016-12-16 13:10:04: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:10:13: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2PING RUNNING pc_done=84&status_id=26&speed_bpms=8151.27&total_bytes=300224512&done_bytes=253571072#token=158YTMONjujIdlXC3OtS
2016-12-16 13:10:14: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:10:18: rc=0 hasError=true state=4
2016-12-16 13:10:18: Sending full image done
2016-12-16 13:10:21: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2PING RUNNING pc_done=0&status_id=27&speed_bpms=0&total_bytes=-1&done_bytes=0#token=158YTMONjujIdlXC3OtS
2016-12-16 13:10:21: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#MBR driveletter=ESP
2016-12-16 13:10:21: rc=0 hasError=true state=0
2016-12-16 13:10:21: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#FULL IMAGE letter=ESP&token=158YTMONjujIdlXC3OtS&checksum=1&bitmap=1&status_id=27&running_jobs=1
2016-12-16 13:10:21: ERROR: Not found
2016-12-16 13:10:21: rc=0 hasError=true state=0
2016-12-16 13:10:22: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2PING RUNNING pc_done=0&status_id=25&speed_bpms=0&total_bytes=-1&done_bytes=0#token=158YTMONjujIdlXC3OtS
2016-12-16 13:10:22: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#MBR driveletter=C
2016-12-16 13:10:22: rc=0 hasError=true state=0
2016-12-16 13:10:22: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#INCR IMAGE letter=C:&hashsize=3909664&token=158YTMONjujIdlXC3OtS&checksum=1&bitmap=1&status_id=25&running_jobs=1&shadowid=3&cbitmapsize=1954860
2016-12-16 13:10:23: rc=0 hasError=true state=0
2016-12-16 13:10:23: Filesystem type is ntfs (\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11)
2016-12-16 13:10:23: TotalNumberOfClusters=15638527 numberOfClusters=15638527 n_clusters=1954816 StartingLcn=0 BitmapSize=15638527 r_bytes=1954832
2016-12-16 13:10:23: Trying to exclude contents of file \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11\HIBERFIL.SYS from backup...
2016-12-16 13:10:23: Error opening file handle to \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11\HIBERFIL.SYS
2016-12-16 13:10:23: Trying to exclude contents of file \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11\pagefile.sys from backup...
2016-12-16 13:10:23: Trying to exclude contents of file \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11\swapfile.sys from backup...
2016-12-16 13:10:23: Error opening file handle to \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11\swapfile.sys
2016-12-16 13:10:23: Trying to exclude contents of file \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11\System Volume Information\{0911fc39-c2a9-11e6-8105-d9061d436d57}{3808876b-c176-4e48-b7ae-04046e6cc752} from backup...
2016-12-16 13:10:23: Trying to exclude contents of file \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11\System Volume Information\{3808876b-c176-4e48-b7ae-04046e6cc752} from backup...
2016-12-16 13:10:23: FSINFO: blocksize=4096 size=64055410176 has_error=false used_space=17489592320
2016-12-16 13:10:24: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:10:27: Block did change: 0 mixed=true
[...]
2016-12-16 13:10:58: Block did change: 6021248 mixed=false
2016-12-16 13:10:58: Sending image done
2016-12-16 13:10:59: rc=0 hasError=true state=4
2016-12-16 13:10:59: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:11:00: ClientService cmd: #IZbOZjIIvmRDgP9XAYDQu#ADD IDENTITY
2016-12-16 13:11:00: rc=0 hasError=true state=0
2016-12-16 13:11:00: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:11:02: rc=0 hasError=true state=0
2016-12-16 13:11:03: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#2LOGDATA 1481890262 0-1481890180-Starting unscheduled incremental image backup of volume "C:"...
0-1481890180-Image backup is being backed up in a snapshot group together with volumes E:, c:\
0-1481890222-Basing image backup on last incremental or full image backup
0-1481890222-Creating writable snapshot of previous image backup...
0-1481890224-Change block tracking active. Max 235.5 MB have changed.
0-1481890262-Transferred 164.079 MB - Average speed: 34.7505 MBit/s
0-1481890262-Time taken for backing up client SVIMPORT: 1m 21s
0-1481890262-Backup succeeded

2016-12-16 13:11:03: rc=0 hasError=true state=0
2016-12-16 13:11:16: ClientService cmd: #IjgABWzUdWWSTo1VYeEOl#ADD IDENTITY
2016-12-16 13:11:16: rc=0 hasError=true state=0
2016-12-16 13:11:21: ClientService cmd: #IpWspIG4DB89iHJZe37km#ADD IDENTITY
2016-12-16 13:11:21: rc=0 hasError=true state=0
2016-12-16 13:11:33: ClientService cmd: #IZbOZjIIvmRDgP9XAYDQu#ADD IDENTITY
2016-12-16 13:11:33: rc=0 hasError=true state=0
2016-12-16 13:11:37: ClientService cmd: #IkvV9ysYQO0J3REjvKrjz#ADD IDENTITY
2016-12-16 13:11:37: rc=0 hasError=true state=0
2016-12-16 13:11:51: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:11:53: ClientService cmd: PONG
2016-12-16 13:12:42: ClientService cmd: STATUS#pw=0BgC2pccVJyLKb5hU7w6GHTVbSGhwK
2016-12-16 13:12:53: ClientService cmd: PONG
2016-12-16 13:12:53: rc=0 hasError=true state=3
2016-12-16 13:12:53: ClientService cmd: #I1c3dCwbXIY3wth00RJ1r#1CHANNEL capa=65047&token=158YTMONjujIdlXC3OtS&restore_version=1&virtual_client=
2016-12-16 13:12:53: New channel: Number of Channels: 1

Regards,

I haven’t changed anything in this area. Could you send me more complete server and client logs? Thanks!

I think this is a client issue because it does the same thing when backuping the same client on another 2.1.7 server …

Would make more sense to backup the client with a 2.1.6 server, wouldn’t it?

The server log shows that the client sends the correct image backups and then the server proceeds to backup C:\ twice instead of f:\ and c:\ once each.

Can you try this server: urbackup-server_2.1.7.0_TEST_amd64.deb (3.1 MB)

You’re right …
It works fine with server 2.1.6 / client 2.1.7. After backup finished with server 2.1.6, i’ll test with your 2.1.7_TEST release.

Thanks !

BTW, client have 3 volumes : C: , E: and F/

Still not working with 2.1.7_TEST

urbackup.log :

2016-12-16 18:06:20: msg=START IMAGE FULL
2016-12-16 18:06:20: Starting unscheduled full image backup of volume "E:"...
2016-12-16 18:06:20: Basing image backup on last incremental or full image backup
2016-12-16 18:06:20: WARNING: Error retrieving last image backup. Doing full image backup instead.
2016-12-16 18:06:29: Image backup is being backed up in a snapshot group together with volumes f:\, c:\
2016-12-16 18:06:29: msg=WAKEUP
2016-12-16 18:06:29: Starting unscheduled full image backup of volume "C:"...
2016-12-16 18:06:29: Image backup is being backed up in a snapshot group together with volumes E:, c:\
2016-12-16 18:06:29: Backing up SYSVOL...
2016-12-16 18:06:29: Starting unscheduled full image backup of volume "SYSVOL"...
2016-12-16 18:06:29: Starting unscheduled full image backup of volume "C:"...
2016-12-16 18:06:29: Image backup is being backed up in a snapshot group together with volumes E:, c:\
2016-12-16 18:06:29: Backing up SYSVOL...
2016-12-16 18:06:29: Starting unscheduled full image backup of volume "SYSVOL"...
2016-12-16 18:06:29: Updating statistics...
2016-12-16 18:06:29: Updating image stats...
2016-12-16 18:06:29: Updating file statistics...
2016-12-16 18:06:29: Done updating statistics.
2016-12-16 18:06:30: ERROR: Backing up System Reserved (SYSVOL) partition failed. Image backup failed
2016-12-16 18:06:30: Time taken for backing up client SVIMPORT: 1s
2016-12-16 18:06:30: ERROR: Backup failed
2016-12-16 18:06:30: msg=WAKEUP
2016-12-16 18:06:31: msg=WAKEUP
2016-12-16 18:06:31: WARNING: Exponential backoff: Waiting at least 40m before next image backup
2016-12-16 18:06:43: Transferred 103.187 MB - Average speed: 36.8795 MBit/s
2016-12-16 18:06:43: Script does not exist urbackup/post_full_imagebackup
2016-12-16 18:06:43: Time taken for backing up client SVIMPORT: 23s
2016-12-16 18:06:43: Backup succeeded
2016-12-16 18:06:43: Updating statistics...
2016-12-16 18:06:43: Updating image stats...
2016-12-16 18:06:43: Updating file statistics...
2016-12-16 18:06:43: Done updating statistics.
2016-12-16 18:06:44: msg=WAKEUP
2016-12-16 18:07:11: Transferred 286.909 MB - Average speed: 57.027 MBit/s
2016-12-16 18:07:11: Script does not exist urbackup/post_full_imagebackup
2016-12-16 18:07:11: Updating statistics...
2016-12-16 18:07:11: Updating image stats...
2016-12-16 18:07:11: Updating file statistics...
2016-12-16 18:07:11: Done updating statistics.
2016-12-16 18:07:12: Backing up SYSVOL done.
2016-12-16 18:07:12: Backing up EFI System Partition...
2016-12-16 18:07:12: Starting unscheduled full image backup of volume "ESP"...
2016-12-16 18:07:12: Request of EFI System Partition failed. Reason: Not found
2016-12-16 18:07:12: Transferred 139 bytes - Average speed: 74.128 KBit/s
2016-12-16 18:07:12: Script does not exist urbackup/post_full_imagebackup
2016-12-16 18:07:12: msg=WAKEUP
2016-12-16 18:07:13: Backing up EFI System Partition done.
2016-12-16 18:07:13: Basing image backup on last incremental or full image backup
2016-12-16 18:07:13: WARNING: Error retrieving last image backup. Doing full image backup instead.
2016-12-16 18:07:13: msg=WAKEUP
2016-12-16 18:07:24: Transferred 91.4262 MB - Average speed: 71.204 MBit/s
2016-12-16 18:07:24: Script does not exist urbackup/post_full_imagebackup
2016-12-16 18:07:24: Time taken for backing up client SVIMPORT: 55s
2016-12-16 18:07:24: Backup succeeded
2016-12-16 18:07:24: Updating statistics...
2016-12-16 18:07:24: Updating image stats...
2016-12-16 18:07:24: Updating file statistics...
2016-12-16 18:07:24: Done updating statistics.

Could you try this one? urbackup-server_2.1.7.0_TEST2_amd64.deb (3.1 MB)

Works fine :

2016-12-17 14:57:34: msg=START IMAGE FULL
2016-12-17 14:57:34: Starting unscheduled full image backup of volume "E:"...
2016-12-17 14:57:34: Basing image backup on last incremental or full image backup
2016-12-17 14:57:34: WARNING: Error retrieving last image backup. Doing full image backup instead.
2016-12-17 14:57:44: Image backup is being backed up in a snapshot group together with volumes f:\, c:\
2016-12-17 14:57:44: msg=WAKEUP
2016-12-17 14:57:44: Starting unscheduled full image backup of volume "F:"...
2016-12-17 14:57:44: Image backup is being backed up in a snapshot group together with volumes E:, c:\
2016-12-17 14:57:44: Basing image backup on last incremental or full image backup
2016-12-17 14:57:44: WARNING: Error retrieving last image backup. Doing full image backup instead.
2016-12-17 14:57:44: Starting unscheduled full image backup of volume "C:"...
2016-12-17 14:57:44: Image backup is being backed up in a snapshot group together with volumes E:, f:\
2016-12-17 14:57:44: Backing up SYSVOL...
2016-12-17 14:57:44: Starting unscheduled full image backup of volume "SYSVOL"...
2016-12-17 14:58:00: Transferred 103.187 MB - Average speed: 33.4893 MBit/s
2016-12-17 14:58:00: Script does not exist urbackup/post_full_imagebackup
2016-12-17 14:58:00: Time taken for backing up client SVIMPORT: 26s
2016-12-17 14:58:00: Backup succeeded
2016-12-17 14:58:00: Updating statistics...
2016-12-17 14:58:00: Updating image stats...
2016-12-17 14:58:00: Updating file statistics...
2016-12-17 14:58:00: Done updating statistics.
2016-12-17 14:58:01: msg=WAKEUP
2016-12-17 14:58:01: Transferred 91.4262 MB - Average speed: 46.6224 MBit/s
2016-12-17 14:58:01: Script does not exist urbackup/post_full_imagebackup
2016-12-17 14:58:01: Time taken for backing up client SVIMPORT: 16s
2016-12-17 14:58:01: Backup succeeded
2016-12-17 14:58:01: Updating statistics...
2016-12-17 14:58:01: Updating image stats...
2016-12-17 14:58:01: Updating file statistics...
2016-12-17 14:58:01: Done updating statistics.
2016-12-17 14:58:07: msg=WAKEUP
2016-12-17 14:58:25: Transferred 286.909 MB - Average speed: 59.8788 MBit/s
2016-12-17 14:58:25: Script does not exist urbackup/post_full_imagebackup
2016-12-17 14:58:25: Updating statistics...
2016-12-17 14:58:25: Updating image stats...
2016-12-17 14:58:25: Updating file statistics...
2016-12-17 14:58:25: Done updating statistics.
2016-12-17 14:58:25: Backing up SYSVOL done.
2016-12-17 14:58:25: Backing up EFI System Partition...
2016-12-17 14:58:25: Starting unscheduled full image backup of volume "ESP"...
2016-12-17 14:58:25: Request of EFI System Partition failed. Reason: Not found
2016-12-17 14:58:25: Transferred 139 bytes - Average speed: 69.496 KBit/s
2016-12-17 14:58:25: Script does not exist urbackup/post_full_imagebackup
2016-12-17 14:58:26: msg=WAKEUP
2016-12-17 14:58:26: Backing up EFI System Partition done.
2016-12-17 14:58:26: Basing image backup on last incremental or full image backup
2016-12-17 14:58:26: WARNING: Error retrieving last image backup. Doing full image backup instead.
2016-12-17 14:58:26: msg=WAKEUP
2016-12-17 15:26:43: Looking for old Sessions... 1 sessions
2016-12-17 15:38:32: Transferred 15.7532 GB - Average speed: 56.2533 MBit/s
2016-12-17 15:38:32: Script does not exist urbackup/post_full_imagebackup
2016-12-17 15:38:32: Time taken for backing up client SVIMPORT: 40m 47s
2016-12-17 15:38:32: Backup succeeded
2016-12-17 15:38:32: Updating statistics...
2016-12-17 15:38:32: Updating image stats...
2016-12-17 15:38:32: Updating file statistics...
2016-12-17 15:38:32: Done updating statistics.
2016-12-17 15:38:33: msg=WAKEUP
2016-12-17 15:44:55: msg=START IMAGE INCR
2016-12-17 15:44:55: Cannot do image backup because internet_no_images=true
2016-12-17 15:44:55: Starting unscheduled incremental image backup of volume "E:"...
2016-12-17 15:44:55: Basing image backup on last incremental or full image backup
2016-12-17 15:44:55: Creating writable snapshot of previous image backup...
2016-12-17 15:45:07: Change block tracking active. Max 8.5 MB have changed.
2016-12-17 15:45:07: Image backup is being backed up in a snapshot group together with volumes f:\, c:\
2016-12-17 15:45:07: msg=WAKEUP
2016-12-17 15:45:07: Starting unscheduled incremental image backup of volume "F:"...
2016-12-17 15:45:07: Image backup is being backed up in a snapshot group together with volumes E:, c:\
2016-12-17 15:45:07: Basing image backup on last incremental or full image backup
2016-12-17 15:45:07: Starting unscheduled incremental image backup of volume "C:"...
2016-12-17 15:45:07: Image backup is being backed up in a snapshot group together with volumes E:, f:\
2016-12-17 15:45:07: Backing up SYSVOL...
2016-12-17 15:45:07: Starting unscheduled full image backup of volume "SYSVOL"...
2016-12-17 15:45:07: Creating writable snapshot of previous image backup...
2016-12-17 15:45:10: Change block tracking active. Max 7.5 MB have changed.
2016-12-17 15:45:10: Starting trimming image file (if possible)
2016-12-17 15:45:11: Trimmed 0 bytes
2016-12-17 15:45:12: Transferred 12.8117 MB - Average speed: 6.35967 MBit/s
2016-12-17 15:45:12: Script does not exist urbackup/post_incr_imagebackup
2016-12-17 15:45:12: Time taken for backing up client SVIMPORT: 17s
2016-12-17 15:45:12: Backup succeeded
2016-12-17 15:45:12: Updating statistics...
2016-12-17 15:45:12: Updating image stats...
2016-12-17 15:45:12: Updating file statistics...
2016-12-17 15:45:12: Done updating statistics.
2016-12-17 15:45:13: msg=WAKEUP
2016-12-17 15:45:14: Starting trimming image file (if possible)
2016-12-17 15:45:14: Trimmed 0 bytes
2016-12-17 15:45:17: Transferred 9.21052 MB - Average speed: 8.1159 MBit/s
2016-12-17 15:45:17: Script does not exist urbackup/post_incr_imagebackup
2016-12-17 15:45:17: Time taken for backing up client SVIMPORT: 10s
2016-12-17 15:45:17: Backup succeeded
2016-12-17 15:45:17: Updating statistics...
2016-12-17 15:45:17: Updating image stats...
2016-12-17 15:45:17: Updating file statistics...
2016-12-17 15:45:17: Done updating statistics.
2016-12-17 15:45:18: msg=WAKEUP
2016-12-17 15:45:47: Transferred 286.909 MB - Average speed: 60.1136 MBit/s
2016-12-17 15:45:47: Script does not exist urbackup/post_full_imagebackup
2016-12-17 15:45:47: Updating statistics...
2016-12-17 15:45:47: Updating image stats...
2016-12-17 15:45:47: Updating file statistics...
2016-12-17 15:45:47: Done updating statistics.
2016-12-17 15:45:47: Backing up SYSVOL done.
2016-12-17 15:45:47: Backing up EFI System Partition...
2016-12-17 15:45:47: Starting unscheduled full image backup of volume "ESP"...
2016-12-17 15:45:47: Request of EFI System Partition failed. Reason: Not found
2016-12-17 15:45:47: Transferred 140 bytes - Average speed: 74.664 KBit/s
2016-12-17 15:45:47: Script does not exist urbackup/post_full_imagebackup
2016-12-17 15:45:48: msg=WAKEUP
2016-12-17 15:45:48: Backing up EFI System Partition done.
2016-12-17 15:45:48: Basing image backup on last incremental or full image backup
2016-12-17 15:45:48: Creating writable snapshot of previous image backup...
2016-12-17 15:45:48: msg=WAKEUP
2016-12-17 15:45:50: Change block tracking active. Max 143.5 MB have changed.
2016-12-17 15:46:12: Starting trimming image file (if possible)
2016-12-17 15:46:13: Trimmed 0 bytes
2016-12-17 15:46:17: Transferred 101.561 MB - Average speed: 30.0841 MBit/s
2016-12-17 15:46:17: Script does not exist urbackup/post_incr_imagebackup
2016-12-17 15:46:17: Time taken for backing up client SVIMPORT: 1m 10s
2016-12-17 15:46:17: Backup succeeded
2016-12-17 15:46:17: Updating statistics...
2016-12-17 15:46:17: Updating image stats...
2016-12-17 15:46:17: Updating file statistics...
2016-12-17 15:46:17: Done updating statistics.
2016-12-17 15:46:18: msg=WAKEUP

Thanks :sunglasses: !

BTW, creating an automatic image archive rule now works, but i’m unable to delete it after creating.
Also, creating an archive rule for “Full image backup” becomes “Image backup” after leaving / return in settings :

If i click on “Logs” and then go back in “Settings > Archive” :

Clicking on “Delete” and then on “Save” doesn’t remove the rule :

Regards,

Hmm, cannot reproduce the deletion issue. Maybe there are additional steps to reproduce?

Okay.
I’ve deleted all rules directly from the database and made some new tests.

It looks like archive rules at “General” level (i.e Settings > General > Archive) is buggy,

Setting a first rule for “Full image backup type” then click on “Add” button :

Ok, the rule is added in GUI. Click on “Save” :

Rule disappear from GUI :

BUT is present in database :

sqlite> select * from automatic_archival;
id          next_archival  interval    interval_unit  length      length_unit  backup_types  clientid    archive_window
----------  -------------  ----------  -------------  ----------  -----------  ------------  ----------  --------------
1           0              2419200     w              31534272    m            4             0           18;*;*;7
sqlite>

Adding the same rule at Group level seems to work fine but still show “Image backup” instead of “Full image backup” :

sqlite> select * from automatic_archival;
id          next_archival  interval    interval_unit  length      length_unit  backup_types  clientid    archive_window
----------  -------------  ----------  -------------  ----------  -----------  ------------  ----------  --------------
1           0              2419200     w              31534272    m            4             0           18;*;*;7
2           1482146247     2419200     w              31534272    m            4             -1          18;*;*;7
sqlite>

And rule is well reported on group members :

EDIT :

General archive rule seems to be visible after adding the group level rule.
Clicking on “Delete” :

And then “Save” :

Rule still here in GUI

But is deleted from database :

sqlite> select * from automatic_archival;
id          next_archival  interval    interval_unit  length      length_unit  backup_types  clientid    archive_window
----------  -------------  ----------  -------------  ----------  -----------  ------------  ----------  --------------
2           1482146247     2419200     w              31534272    m            4             -1          18;*;*;7
sqlite>

Regards,

Found that in fact, “Group level” archive rules are also displayed in “General settings” archive rules …

Which i think is not normal …

Regards,