ETA 47 years full backup

[herbert]

I have a client which I backup but is not online very often - and if only for a short time.
What I did is enforcing the user of the specific client to start the PC every few month and keep it running for some days.
This time I do have a ETA of 47 years and I know that most of the data is already existing on the urbackup server, but it is stuck at downloading MetaData packages.

|05/02/18 10:27  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.3658 MB at 0 Bit/s|
|---|---|---|
|05/02/18 10:28  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.3658 MB at 0 Bit/s|
|05/02/18 10:29  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.3658 MB at 0 Bit/s|
|05/02/18 10:30  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.3658 MB at 0 Bit/s|
|05/02/18 10:31  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.3658 MB at 0 Bit/s|
|05/02/18 10:32  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.3658 MB at 0 Bit/s|
|05/02/18 10:33  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.3658 MB at 0 Bit/s|
|05/02/18 10:34  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.3658 MB at 0 Bit/s|
|05/02/18 10:35  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.3658 MB at 0 Bit/s|
|05/02/18 10:36  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36581 MB at 0 Bit/s|
|05/02/18 10:37  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36581 MB at 0 Bit/s|
|05/02/18 10:38  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36581 MB at 0 Bit/s|
|05/02/18 10:39  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36581 MB at 0 Bit/s|
|05/02/18 10:40  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36581 MB at 0 Bit/s|
|05/02/18 10:41  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36581 MB at 0 Bit/s|
|05/02/18 10:42  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36581 MB at 0 Bit/s|
|05/02/18 10:43  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36581 MB at 0 Bit/s|
|05/02/18 10:44  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36581 MB at 0 Bit/s|
|05/02/18 10:45  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36581 MB at 0 Bit/s|
|05/02/18 10:46  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36582 MB at 0 Bit/s|
|05/02/18 10:47  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36582 MB at 0 Bit/s|
|05/02/18 10:48  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36582 MB at 0 Bit/s|
|05/02/18 10:49  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36582 MB at 0 Bit/s|
|05/02/18 10:50  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36582 MB at 0 Bit/s|
|05/02/18 10:51  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36582 MB at 0 Bit/s|
|05/02/18 10:52  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36582 MB at 0 Bit/s|
|05/02/18 10:53  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36582 MB at 0 Bit/s|
|05/02/18 10:54  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36582 MB at 0 Bit/s|
|05/02/18 10:55  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36582 MB at 0 Bit/s|
|05/02/18 10:57  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36583 MB at 0 Bit/s|
|05/02/18 10:58  |DEBUG  |Loading "urbackup/FILE_METADATA|It0PXTsD2OaOu5y3XDIX|683". Loaded 6.36583 MB at 0 Bit/s|

What is happening ? Why does it take that long and where is the file located, I am unable to find it.

I am a little confused to be honest, and also couldn’t find anything helpful on the internet nor in the forum.
Server is 2.2.11 on a QNAP
Client is 2.2.5 on Windows 10

Something I missed, the client itsef says

[herbert]

The last information I got from the client logs

Starting unscheduled incremental file backup...
Selected no components to backup
Restarting shadow copy of C:\ because it was started by this server
Scanning for changed hard links on volume of "C:\"...
Indexing of "C" done. 45 filesystem lookups 22528 db lookups and 35 db updates
Restarting shadow copy of D:\ because it was started by this server
Scanning for changed hard links on volume of "D:\"...
Indexing of "D" done. 1 filesystem lookups 55891 db lookups and 1 db updates
Desktop: Loading file list...
Desktop: Calculating file tree differences...
Desktop: Indexing file entries from last backup...
Desktop: Calculating tree difference size...
Desktop: Linking unchanged and loading new files...
Error getting parallel hash for file "Spotify.exe" line 143711
Error getting parallel hash for file "Spotify.exe" line 143713
Waiting for file transfers...
Waiting for file hashing and copying threads...
Waiting for metadata download stream to finish
Error reading current metadata
Writing new file list...
Number of copied file entries from last backup is 265889
Transferred 27.8266 MB - Average speed: 209.368 KBit/s
(Before compression: 76.5372 MB ratio: 2.75051)
290.761 GB of files were already present on the server and did not need to be transferred
Time taken for backing up client Desktop: 21m 19s
Backup failed

I restarted the urbackup server, because STOP the full backup activity on the server was not working.
No I started the full backup from the client site and at the moment the server log activity shows

|05/02/18 11:16  |INFO  |Starting unscheduled full file backup...|
|---|---|---|
|05/02/18 11:16  |DEBUG  |Desktop: Connecting for filelist...|
|05/02/18 11:16  |DEBUG  |Desktop: Waiting for filelist|
|05/02/18 11:16  |DEBUG  |Desktop: Connecting for filelist (async)...|
|05/02/18 11:17  |INFO  |Waiting for parallel hash load stream to finish|
|05/02/18 11:19  |ERROR  |Error during parallel hash load: TIMEOUT|
|5/02/18 11:21  |ERROR  |Error starting parallel hash load|
|---|---|---|
|05/02/18 11:21  |ERROR  |Backup had an early error. Deleting partial backup.|

I have no clue.

[uroni]

Moved to testing category because parallel hash load was enabled.

[herbert]

ah, you are right.
I disable it and verify if the backups are working afterwards.

thanks for the hint even if it was not intended

[herbert]

Backup runs without issues now - having turned of parallel hashing. It still takes a really long time, but I assume it reduces the time to finish pretty fast, because most of the files are already stored on the server.