FreeNAS server - 1.4.5 client incr file backups not working

philiplu · December 4, 2014, 7:35am

I’ve been running UrBackup a couple months, with the server running in a jail under FreeNAS (FreeBSD), clients on a mix of Win 7 and Win 8.1. Everything worked fine up to a week ago, when the clients were autoupdated to version 1.4.5 from 1.4.4. The server was running 1.4.5 when the problem started, though it is now on 1.4.6 and the problem is still present. I install the server from source, and not using the PBI plugin. I’ve updated the server from source 2 or 3 times since the initial installation, with no problem.

Incremental file backups run with no errors or warnings, but the only files being pushed to the server are backup_client.db (always) and open_files.dat (sometimes) under C:\Program Files\UrBackup\urbackup. A full file backup was run since the incremental backups stopped working, and it seems to have worked (pushed about 15,000 changed files).

I turned on “end-to-end verification of all file backups” then ran an incremental file backup. After about 6 hours, the backup reported about 7000 verification errors, again with only backup_client.db and open_files.dat being updated. The error count is reasonable for the # of files that were modified and should have been pushed to the server (mostly browser caching).

I turned end-to-end verification back off, and restarted the server and client with --loglevel debug. Running another incremental file backup, I get this for the server log:

2014-12-03 23:07:25: msg=START BACKUP INCR
2014-12-03 23:07:25: Starting incremental file backup...
2014-12-03 23:07:25: phil-PC: Connecting for filelist...
2014-12-03 23:07:25: Created new database connection for urbackup/backup_server.db
2014-12-03 23:07:25: phil-PC: Waiting for filelist
2014-12-03 23:07:25: Created new database connection for urbackup/backup_server.db
2014-12-03 23:08:25: Indexing of "D" done. 1 filesystem lookups 10886 db lookups and 1 db updates
2014-12-03 23:08:25: Indexing of "E" done. 1 filesystem lookups 2199 db lookups and 1 db updates
2014-12-03 23:08:25: Indexing of "C" done. 2 filesystem lookups 29388 db lookups and 2 db updates
2014-12-03 23:08:25: phil-PC: Doing backup with hashed transfer...
2014-12-03 23:08:25: phil-PC: Connecting to client...
2014-12-03 23:08:25: phil-PC: Loading file list...
2014-12-03 23:08:25: phil-PC Starting incremental backup...
2014-12-03 23:08:25: phil-PC: Calculating file tree differences...
2014-12-03 23:08:27: phil-PC: Calculating tree difference size...
2014-12-03 23:08:27: phil-PC: Linking unchanged and loading new files...
2014-12-03 23:08:28: Created new database connection for urbackup/backup_server.db
2014-12-03 23:08:29: Waiting for file transfers...
2014-12-03 23:08:31: Loading file "backup_client.db"
2014-12-03 23:08:32: GT: Loaded file "backup_client.db"
2014-12-03 23:08:32: Loading file "open_files.dat"
2014-12-03 23:08:32: PT: Hashing file "backup_client.db"
2014-12-03 23:08:32: GT: Loaded file "open_files.dat"
2014-12-03 23:08:33: Setting cachesize to 40960
2014-12-03 23:08:33: PT: Hashing file "open_files.dat"
2014-12-03 23:08:33: HT: Copying file: "/backups/phil-PC/141203-2307/C/Program Files/UrBackup/urbackup/backup_client.db"
2014-12-03 23:08:33: HT: Copying file: "/backups/phil-PC/141203-2307/C/Program Files/UrBackup/urbackup/open_files.dat"
2014-12-03 23:08:34: Writing new file list...
2014-12-03 23:08:35: Created new database connection for urbackup/backup_server.db
2014-12-03 23:08:37: Waiting for file hashing and copying threads...
2014-12-03 23:08:38: Creating symbolic links. -1
2014-12-03 23:08:38: Creating symbolic links. -2
2014-12-03 23:08:38: Symbolic links created.
2014-12-03 23:08:38: Transferred 70.3355 MB - Average speed: 42.9134 MBit/s
2014-12-03 23:08:38: Script does not exist urbackup/post_incr_filebackup
2014-12-03 23:08:38: server_prepare_hash Thread finished (exit)
2014-12-03 23:08:38: Setting cachesize to 40960
2014-12-03 23:08:38: server_hash Thread finished - normal
2014-12-03 23:08:39: Time taken for backing up client phil-PC: 1m 14s
2014-12-03 23:08:39: Backup succeeded
2014-12-03 23:08:39: Updating statistics...
2014-12-03 23:08:39: Copying files from files_new table...
2014-12-03 23:08:39: Deleting contents of files_new table...
2014-12-03 23:08:39: Updating image stats...
2014-12-03 23:08:39: Updating deleted files...
2014-12-03 23:08:39: Updating file stats...
2014-12-03 23:08:39: File processing speed: 0.000284614 files/s
2014-12-03 23:08:39: Updating files stats: 50%
2014-12-03 23:08:39: Done updating statistics.

I don’t see anything in there explaining why all the changed files were ignored. Here’s the client-side log. Again, I don’t see anything too weird, though it’s curious that the “START SC” commands always say the ShadowCopy is already present.

2014-12-03 23:07:06: FileSrv: UDP: PING received... sending PONG. Delay=41ms
2014-12-03 23:07:22: ClientService cmd: START BACKUP INCR#pw=<pw>
2014-12-03 23:07:22: rc=0 hasError=true state=0
2014-12-03 23:07:22: ClientService cmd: #<cmd>#PING RUNNING --#token=<token>
2014-12-03 23:07:22: ClientService cmd: #<cmd>#3START BACKUP#token=<token>
2014-12-03 23:07:22: Removing VSS log data...
2014-12-03 23:07:22: rc=0 hasError=true state=0
2014-12-03 23:07:22: Final path: D:\
2014-12-03 23:07:22: Final path: E:\
2014-12-03 23:07:22: Final path: C:\
2014-12-03 23:07:22: Final path: D:\
2014-12-03 23:07:22: Final path: E:\
2014-12-03 23:07:22: Final path: C:\
2014-12-03 23:07:23: ClientService cmd: STATUS#pw=<pw>
2014-12-03 23:07:23: rc=0 hasError=true state=0
2014-12-03 23:07:32: ClientService cmd: #<cmd>#2PING RUNNING pc_done=&eta_ms=1704471#token=<token>
2014-12-03 23:07:32: rc=0 hasError=true state=0
2014-12-03 23:07:34: Creating shadowcopy of "D" in indexDirs()
2014-12-03 23:07:35: Number of Writers: 11
2014-12-03 23:07:35: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer MSSearch Service Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Number of Writers: 11
2014-12-03 23:07:35: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer MSSearch Service Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:35: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:39: ClientService cmd: PONG
2014-12-03 23:07:41: Number of Writers: 11
2014-12-03 23:07:41: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:42: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:42: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:42: Writer System Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:42: Writer ASR Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:42: Writer Registry Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:42: Writer Shadow Copy Optimization Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:42: Writer MSSearch Service Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:42: Writer BITS Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:42: Writer COM+ REGDB Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:42: Writer WMI Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:42: ClientService cmd: #<cmd>#2PING RUNNING pc_done=&eta_ms=1694464#token=<token>
2014-12-03 23:07:42: rc=0 hasError=true state=0
2014-12-03 23:07:47: Shadowcopy path: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy374
2014-12-03 23:07:47: done.
2014-12-03 23:07:48: Scanning for changed hard links in "D"...
2014-12-03 23:07:48: Indexing "D"...
2014-12-03 23:07:52: ClientService cmd: #<cmd>#2PING RUNNING pc_done=&eta_ms=1684453#token=<token>
2014-12-03 23:07:52: rc=0 hasError=true state=0
2014-12-03 23:07:53: Indexing of "D" done. 1 filesystem lookups 10886 db lookups and 1 db updates
2014-12-03 23:07:53: Creating shadowcopy of "E" in indexDirs()
2014-12-03 23:07:53: Number of Writers: 11
2014-12-03 23:07:53: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:53: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:53: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:53: Writer System Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:53: Writer ASR Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:53: Writer Registry Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:53: Writer Shadow Copy Optimization Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:53: Writer MSSearch Service Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:53: Writer COM+ REGDB Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:53: Writer BITS Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:53: Writer WMI Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:54: Number of Writers: 11
2014-12-03 23:07:54: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:54: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:54: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:54: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:54: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:54: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:54: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:54: Writer MSSearch Service Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:54: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:54: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:54: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:57: FileSrv: UDP: PING received... sending PONG. Delay=242ms
2014-12-03 23:07:57: Number of Writers: 11
2014-12-03 23:07:58: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:58: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:58: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:07:58: Writer System Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:58: Writer ASR Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:58: Writer Registry Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:58: Writer Shadow Copy Optimization Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:58: Writer MSSearch Service Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:58: Writer COM+ REGDB Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:58: Writer BITS Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:07:58: Writer WMI Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:01: Shadowcopy path: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy375
2014-12-03 23:08:01: done.
2014-12-03 23:08:02: Scanning for changed hard links in "E"...
2014-12-03 23:08:02: Indexing "E"...
2014-12-03 23:08:02: ClientService cmd: #<cmd>#2PING RUNNING pc_done=&eta_ms=1674441#token=<token>
2014-12-03 23:08:02: rc=0 hasError=true state=0
2014-12-03 23:08:04: Indexing of "E" done. 1 filesystem lookups 2199 db lookups and 1 db updates
2014-12-03 23:08:04: Creating shadowcopy of "C" in indexDirs()
2014-12-03 23:08:04: Number of Writers: 11
2014-12-03 23:08:04: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:04: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:04: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:04: Writer System Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:04: Writer ASR Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:04: Writer Shadow Copy Optimization Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:04: Writer COM+ REGDB Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:04: Writer MSSearch Service Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:04: Writer Registry Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:04: Writer BITS Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:04: Writer WMI Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:05: Number of Writers: 11
2014-12-03 23:08:05: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:05: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:05: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:05: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:05: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:05: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:05: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:05: Writer MSSearch Service Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:05: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:05: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:05: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:09: Number of Writers: 11
2014-12-03 23:08:09: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:09: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:09: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:09: Writer System Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:09: Writer ASR Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:09: Writer Shadow Copy Optimization Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:09: Writer COM+ REGDB Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:09: Writer MSSearch Service Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:09: Writer Registry Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:09: Writer BITS Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:09: Writer WMI Writer has failure state VSS_WS_WAITING_FOR_BACKUP_COMPLETE with error S_OK.
2014-12-03 23:08:10: Shadowcopy path: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy376
2014-12-03 23:08:10: done.
2014-12-03 23:08:11: Scanning for changed hard links in "C"...
2014-12-03 23:08:11: Indexing "C"...
2014-12-03 23:08:12: ClientService cmd: #<cmd>#2PING RUNNING pc_done=&eta_ms=1664431#token=<token>
2014-12-03 23:08:12: rc=0 hasError=true state=0
2014-12-03 23:08:20: Indexing of "C" done. 2 filesystem lookups 29388 db lookups and 2 db updates
2014-12-03 23:08:20: Deleting backup of changed dirs...
2014-12-03 23:08:22: ClientService cmd: #<cmd>#GET VSSLOG
2014-12-03 23:08:22: VSS logdata - 236 bytes
2014-12-03 23:08:22: ClientService cmd: #<cmd>#2PING RUNNING pc_done=&eta_ms=1654426#token=<token>
2014-12-03 23:08:22: rc=0 hasError=true state=0
2014-12-03 23:08:22: rc=0 hasError=true state=0
2014-12-03 23:08:22: rc=0 hasError=true state=0
2014-12-03 23:08:22: FileSrv: Info: Window size=524288
2014-12-03 23:08:22: FileSrv: Received data...
2014-12-03 23:08:22: FileSrv: Received a Packet.
2014-12-03 23:08:22: FileSrv: Sending file (normal) urbackup/filelist.ub
2014-12-03 23:08:22: FileSrv: Mapped name: C:\Program Files\UrBackup\urbackup\data\filelist.ub
2014-12-03 23:08:23: FileSrv: Reading last file part
2014-12-03 23:08:23: FileSrv: Info: File End
2014-12-03 23:08:23: FileSrv: Closed file.
2014-12-03 23:08:23: ClientService cmd: STATUS#pw=<pw>
2014-12-03 23:08:23: rc=0 hasError=true state=0
2014-12-03 23:08:25: ClientService cmd: #<cmd>#START SC "D"#token=<token>
2014-12-03 23:08:25: orig_target=D:\ volpath=\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy374
2014-12-03 23:08:25: Shadowcopy already present.
2014-12-03 23:08:25: rc=0 hasError=true state=0
2014-12-03 23:08:26: ClientService cmd: #<cmd>#STOP SC "D"#token=<token>
2014-12-03 23:08:26: Number of Writers: 11
2014-12-03 23:08:26: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:26: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:26: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:26: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:26: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:26: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:26: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:26: Writer MSSearch Service Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:26: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:26: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:26: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:26: Deleting shadowcopy for path "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy374\" -2
2014-12-03 23:08:27: Deleting Shadowcopy for dir "D:\"
2014-12-03 23:08:27: rc=0 hasError=true state=0
2014-12-03 23:08:27: ClientService cmd: #<cmd>#START SC "E"#token=<token>
2014-12-03 23:08:27: orig_target=E:\ volpath=\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy375
2014-12-03 23:08:27: Shadowcopy already present.
2014-12-03 23:08:27: rc=0 hasError=true state=0
2014-12-03 23:08:27: ClientService cmd: #<cmd>#STOP SC "E"#token=<token>
2014-12-03 23:08:28: Number of Writers: 11
2014-12-03 23:08:28: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:28: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:28: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:28: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:28: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:28: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:28: Writer MSSearch Service Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:28: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:28: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:28: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:28: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:28: Deleting shadowcopy for path "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy375\" -2
2014-12-03 23:08:29: Deleting Shadowcopy for dir "E:\"
2014-12-03 23:08:29: rc=0 hasError=true state=0
2014-12-03 23:08:29: ClientService cmd: #<cmd>#START SC "C"#token=<token>
2014-12-03 23:08:29: orig_target=C:\ volpath=\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy376
2014-12-03 23:08:29: Shadowcopy already present.
2014-12-03 23:08:29: rc=0 hasError=true state=0
2014-12-03 23:08:29: FileSrv: Received data...
2014-12-03 23:08:29: FileSrv: Received a Packet.
2014-12-03 23:08:29: FileSrv: Sending file (normal) <token>|C/Program Files/UrBackup/urbackup/backup_client.db
2014-12-03 23:08:29: FileSrv: Mapped name: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy376\\Program Files\UrBackup\urbackup\backup_client.db
2014-12-03 23:08:30: FileSrv: Reading last file part
2014-12-03 23:08:30: FileSrv: Info: File End
2014-12-03 23:08:30: FileSrv: Closed file.
2014-12-03 23:08:30: FileSrv: Received data...
2014-12-03 23:08:30: FileSrv: Received a Packet.
2014-12-03 23:08:30: FileSrv: Sending file (normal) <token>|C/Program Files/UrBackup/urbackup/open_files.dat
2014-12-03 23:08:30: FileSrv: Mapped name: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy376\\Program Files\UrBackup\urbackup\open_files.dat
2014-12-03 23:08:30: FileSrv: Reading last file part
2014-12-03 23:08:30: FileSrv: Info: File End
2014-12-03 23:08:30: FileSrv: Closed file.
2014-12-03 23:08:30: ClientService cmd: #<cmd>#STOP SC "C"#token=<token>
2014-12-03 23:08:31: Number of Writers: 11
2014-12-03 23:08:31: Writer Task Scheduler Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:31: Writer VSS Metadata Store Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:31: Writer Performance Counters Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:31: Writer System Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:31: Writer ASR Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:31: Writer WMI Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:31: Writer MSSearch Service Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:31: Writer COM+ REGDB Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:31: Writer BITS Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:31: Writer Shadow Copy Optimization Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:31: Writer Registry Writer has failure state VSS_WS_STABLE with error S_OK.
2014-12-03 23:08:31: Deleting shadowcopy for path "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy376\" -2
2014-12-03 23:08:31: Deleting Shadowcopy for dir "C:\"
2014-12-03 23:08:32: rc=0 hasError=true state=0
2014-12-03 23:08:32: ClientService cmd: #<cmd>#DID BACKUP
2014-12-03 23:08:32: rc=0 hasError=true state=0
2014-12-03 23:08:32: ClientService cmd: #<cmd>#2PING RUNNING pc_done=100&eta_ms=1707229#token=<token>
2014-12-03 23:08:32: rc=0 hasError=true state=0
2014-12-03 23:08:36: FileSrv: Recv Error in RecvMessage
2014-12-03 23:08:36: FileSrv: Deleting Memory...
2014-12-03 23:08:36: FileSrv: done.
2014-12-03 23:08:36: ClientService cmd: #<cmd>#2LOGDATA 1417676919 0-1417676845-Starting incremental file backup...
0-1417676905-Indexing of "D" done. 1 filesystem lookups 10886 db lookups and 1 db updates
0-1417676905-Indexing of "E" done. 1 filesystem lookups 2199 db lookups and 1 db updates
0-1417676905-Indexing of "C" done. 2 filesystem lookups 29388 db lookups and 2 db updates
0-1417676905-phil-PC: Loading file list...
0-1417676905-phil-PC: Calculating file tree differences...
0-1417676907-phil-PC: Calculating tree difference size...
0-1417676907-phil-PC: Linking unchanged and loading new files...
0-1417676909-Waiting for file transfers...
0-1417676914-Writing new file list...
0-1417676917-Waiting for file hashing and copying threads...
0-1417676918-Transferred 70.3355 MB - Average speed: 42.9134 MBit/s
0-1417676919-Time taken for backing up client phil-PC: 1m 14s
0-1417676919-Backup succeeded

2014-12-03 23:08:36: rc=0 hasError=true state=0
2014-12-03 23:08:39: ClientService cmd: PONG
2014-12-03 23:08:42: FileSrv: ClientThread deleted. 1024 KB Memory freed.

Any idea what’s going on, and how to get incremental file backups working? Again, this only appeared once the clients were updated to 1.4.5. Older client backends worked fine.

uroni · December 4, 2014, 10:56pm

Thanks for reporting this rather serious issue.

The client version here https://sourceforge.net/projects/urbackup/files/Client/1.4.6/ should include a fix for this bug. I am trying to reproduce your issue and once I can confirm this issue is fixed I’ll update the website and put it into the auto-update.

philiplu · December 5, 2014, 6:25am

I’ve downloaded the x64 msi version of 1.4.6 on my Win 7 desktop. That seems to have fixed the problem.

One caveat - I then tried downloading the msi on my Win 8.1 laptop using Chrome, and Chrome said the file was malware and refused to let me at it. I didn’t get this warning on the Win 7 desktop, even though it’s using the same version of Chrome. I verified the MD5/SHA1 on both machines, and the downloaded files are identical. No idea why Chrome on Win 8.1 only is saying the download is malware.

Hmm - a bit later now. I noticed I didn’t have AdBlock Plus or Ghostery running on the laptop’s Chrome. I do run Ghostery on the desktop. Installed AdBlock Plus extension in Chrome on the laptop, downloaded the 1.4.6 client MSI, and this time, no warning about malware. Again, the downloaded file is the same as before (cmp/md5/shasum).

Very weird - maybe the SourceForge ad networks have been hacked. That seems likely - earlier, after Chrome first refused access to the downloaded MSI, I noticed a few minutes later that a file Installation.exe was downloaded without my acknowledgement, from get.up1004.info, and Chrome was on a page at getmoviefix.info telling me to install a flash player update. So clearly something got hacked somewhere. I’m starting to doubt it’s my laptop, though - an MSE full scan came up clean after a reboot, I did not run the Installation.exe (of course), and Sysinternals ProcMon and ProcExp don’t show anything weird running. Hopefully, this is SourceForge ads trying to install a drive-by and failing, though I’ll probably just pave and reinstall the laptop to be sure (get to try out UrBackup’s image restore ).

uroni · December 5, 2014, 4:35pm

Are you sure it was Chrome and not the Windows 8 “Smart screen” protection? (It lets you run the installer if you press “more information”)

I checked the msi installer and the hash is identical with what I uploaded and I haven’t heard anything about sourceforge being hacked.

Thanks for confirming that it fixes the bug!

john3354 · December 5, 2014, 5:15pm

Is there any way you could do an incremental release to get this fix out? I think I am hitting on this issue with one of my backup clients as it has not been able to do an incremental since I upgraded to 1.4.6.

philiplu · December 5, 2014, 5:26pm

Yes, I’m sure. If I tell Ghostery to allow Google Analytics on SourceForge in Chrome on my Win 7 desktop, then Chrome will block the download as malicious there as well. Disable Google Analytics, and no warning. Tried a few downloads, and I get the warning for both the 1.4.6 client MSI and EXE, and the 1.4.5 client MSI as well, but not the 1.4.6 client tarball.

uroni · December 5, 2014, 7:05pm

The client 1.3.6 fixes it.

Other sourceforge projects have this issue as well. I think that are already enough issues:

https://sourceforge.net/p/forge/site-support/9036/
https://sourceforge.net/p/forge/site-support/9022/
https://sourceforge.net/p/forge/site-support/9034/

If you think they would benefit from your analysis, please add it at one of those tickets.

john3354 · December 5, 2014, 7:44pm

Possibly silly question: Is it possible to just download that to the server and it will push out from there? I do not see where the client software is located at on the server?