Restore error - Failed to patch with remote file


#1

Hi,

Can someone help me with this error? The same error also occurs with the old task.

RestoredFiles: 0
SizeOfRestoredFiles: 0
RestoredFolders: 0
RestoredSymlinks: 0
PatchedFiles: 0
DeletedFiles: 0
DeletedFolders: 0
DeletedSymlinks: 0
MainOperation: Restore
ParsedResult: Error
Version: 2.0.4.10 (2.0.4.10_canary_2018-12-29)
EndTime: 1/3/2019 10:05:43 PM (1546560343)
BeginTime: 1/3/2019 9:56:40 PM (1546559800)
Duration: 00:09:02.9900580
MessagesActualLength: 16
WarningsActualLength: 0
ErrorsActualLength: 2
LimitedMessages: [
    2019-01-03 21:56:40 -02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: A operação Restore foi iniciada,
    2019-01-03 21:56:40 -02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2019-01-03 21:56:41 -02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (9 bytes),
    2019-01-03 21:56:42 -02 - [Information-Duplicati.Library.Main.Database.LocalRestoreDatabase-SearchingBackup]: Searching backup 0 (1/3/2019 9:20:24 PM) ...,
    2019-01-03 21:56:42 -02 - [Information-Duplicati.Library.Main.Operation.RestoreHandler-RemoteFileCount]: 1 remote files are required to restore,
    2019-01-03 21:56:42 -02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bca5c6cbb26a54b95a987e980339f7d52.dblock.zip (1.023,92 MB),
    2019-01-03 21:58:22 -02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-bca5c6cbb26a54b95a987e980339f7d52.dblock.zip (1.023,92 MB),
    2019-01-03 21:58:32 -02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bca5c6cbb26a54b95a987e980339f7d52.dblock.zip (1.023,92 MB),
    2019-01-03 22:00:13 -02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-bca5c6cbb26a54b95a987e980339f7d52.dblock.zip (1.023,92 MB),
    2019-01-03 22:00:23 -02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bca5c6cbb26a54b95a987e980339f7d52.dblock.zip (1.023,92 MB),
...
]
LimitedWarnings: []
LimitedErrors: [
    2019-01-03 22:05:43 -02 - [Error-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFailed]: Failed to patch with remote file: "duplicati-bca5c6cbb26a54b95a987e980339f7d52.dblock.zip", message: A task was canceled.,
    2019-01-03 22:05:43 -02 - [Error-Duplicati.Library.Main.Operation.RestoreHandler-RestoreFileFailed]: Could not find a part of the path "/home/XXXXXXX/03-01-2019-19-11/XXXXXXXXX.sql.gz".
]
Log data:
2019-01-03 22:05:43 -02 - [Error-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFailed]: Failed to patch with remote file: "duplicati-bca5c6cbb26a54b95a987e980339f7d52.dblock.zip", message: A task was canceled.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
  at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x00026] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Runtime.CompilerServices.ConfiguredTaskAwaitable+ConfiguredTaskAwaiter.GetResult () [0x00000] in <967102960bb24f539a74a4fad131a396>:0 
  at System.IO.Stream+<CopyToAsyncInternal>d__27.MoveNext () [0x000a0] in <967102960bb24f539a74a4fad131a396>:0 
--- End of stack trace from previous location where exception was thrown ---
  at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x0001a] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Runtime.CompilerServices.ConfiguredTaskAwaitable+ConfiguredTaskAwaiter.GetResult () [0x00000] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Net.Http.HttpContent+<LoadIntoBufferAsync>d__17.MoveNext () [0x000a9] in <87c6b1e277154b6695cbb15be1cb8e88>:0 
--- End of stack trace from previous location where exception was thrown ---
  at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw () [0x0000c] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Threading.Tasks.Task task) [0x0001a] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Threading.Tasks.Task task) [0x00028] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd (System.Threading.Tasks.Task task) [0x00008] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Runtime.CompilerServices.ConfiguredTaskAwaitable+ConfiguredTaskAwaiter.GetResult () [0x00000] in <967102960bb24f539a74a4fad131a396>:0 
  at System.Net.Http.HttpClient+<SendAsyncWorker>d__47.MoveNext () [0x00171] in <87c6b1e277154b6695cbb15be1cb8e88>:0 
--- End of stack trace from previous location where exception was thrown ---
  at Duplicati.Library.Main.AsyncDownloader+AsyncDownloaderEnumerator+AsyncDownloadedFile.get_TempFile () [0x00008] in <67fc15b21e344070849a0f6dd9bbef24>:0 
  at Duplicati.Library.Main.Operation.RestoreHandler.DoRun (Duplicati.Library.Main.Database.LocalDatabase dbparent, Duplicati.Library.Utility.IFilter filter, Duplicati.Library.Main.RestoreResults result) [0x003bb] in <67fc15b21e344070849a0f6dd9bbef24>:0 
2019-01-03 22:05:43 -02 - [Error-Duplicati.Library.Main.Operation.RestoreHandler-RestoreFileFailed]: Could not find a part of the path "/home/xxxxxxxxxx/03-01-2019-19-11/XXXXXXXXXXXX.sql.gz".
System.IO.DirectoryNotFoundException: Could not find a part of the path "/home/xxxxx/03-01-2019-19-11/xxxxxxx.sql.gz".
  at System.IO.FileStream..ctor (System.String path, System.IO.FileMode mode, System.IO.FileAccess access, System.IO.FileShare share, System.Int32 bufferSize, System.Boolean anonymous, System.IO.FileOptions options) [0x00164] in <967102960bb24f539a74a4fad131a396>:0 
  at System.IO.FileStream..ctor (System.String path, System.IO.FileMode mode, System.IO.FileAccess access, System.IO.FileShare share) [0x00000] in <967102960bb24f539a74a4fad131a396>:0 
  at (wrapper remoting-invoke-with-check) System.IO.FileStream..ctor(string,System.IO.FileMode,System.IO.FileAccess,System.IO.FileShare)
  at System.IO.File.OpenRead (System.String path) [0x00000] in <967102960bb24f539a74a4fad131a396>:0 
  at Duplicati.Library.Common.IO.SystemIOLinux.FileOpenRead (System.String path) [0x00000] in <718b1f014bcd47c49b77c782ddc3c836>:0 
  at Duplicati.Library.Main.Operation.RestoreHandler.DoRun (Duplicati.Library.Main.Database.LocalDatabase dbparent, Duplicati.Library.Utility.IFilter filter, Duplicati.Library.Main.RestoreResults result) [0x005ca] in <67fc15b21e344070849a0f6dd9bbef24>:0

#2

repeated many times is probably leading up to an error that’s not captured with LimitedMessages of 10 lines. "Failed to patch with remote file: “duplicati-bca5c6cbb26a54b95a987e980339f7d52.dblock.zip” is consistent. What storage type is the backup on, and is it generally working well for your Duplicati backups and restores? Anything different about this one that may explain why it’s seemingly failing to give Duplicati the file it needs? The time between retries is sometimes minimal (10 seconds), sometimes much longer. Maybe a network fail?


#3

I may be misreading something here, but is your dblock file (Upload volume) 1GB in size?

(BTW - I edited your post by putting “~~~ json” before and “~~~” after the error text to make it more readable.)


#4

Hi,

Thanks!! Yes, have 1 GB size.
Is this size advisable? The source data have 25 GB


#5

Hi,

Thanks!! Storage is One drive v2 I’m suspicious of the network.at this point I was able to restore, but the error still occurred.


#6

Well, it will work but it’s a very large file to be transferring back and forth which increases the likelihood of a transfer failure.

Additionally, if you’re restoring that means you have to download 1GB to your local drive AND decompress it (I’m not sure if you does some or all), and then restore it.

So you probably need 3GB free space (1G for download, 1G for extract, 1G for final). Do you have enough free disk space?

Edit: Note that the above numbers are assuming the restored file is a 1G file. If you are only restoring say a 5 MB file then you’d need 1G for download, 1G (or 5MB) for extract, then 5MB for final.


#7

Alternatively, if somehow the changed parts in the 5MB file sound up scattered in 10 different dblocks, you may download 10GB to piece it together. 1GB is a pretty large increase from the default 50MB, although if your network won’t download a 1GB file, I’d have expected you’d be seeing that in the sampled verification done after every backup (unless you had also set –no-backend-verification or –backend-test-samples=0).

Choosing sizes in Duplicati has some notes on sizes. You can change –dblock-size whenever you like. but there won’t be repack just then. Over time, backups, deletes (per retention policy), and compacts will do it.

I’m not sure where this issue is now. It sounds like the main objective of the restore was achieved on a new attempt for which we’ve seen no info. If you want that pursued, –log-file portions at –log-file-log-level=Retry would give a better view of what’s going on, including a lower-level (but not lowest-possible) backend view.


#8

HI,
Thanks all! I reduce the size and now I working with no errors.

Thanks for the tips and explanations!


#9

Since my last post, backups seem to have being going fine. Today I tried using the GUI under the job to restore a file (an MS Access database, *.accdb) to replace my version which seemed to have a problem. The file size is approx 6MB. Apart from using an awful lot of bandwidth it appeared to be working fine. It spent quite a few minutes saying “Downloading files”, considering that the B2 bucket has only 37 files with a total of 147MB and surely it doesn’t need them all!
The first attempt threw an error, I think it seemed to indicate a problem with the location. Log info is below (I trust I’ve pasted the right log):


* Mar 14, 2019 2:43 PM: Failed to restore 1 files, additionally the following files failed to download, which may be the cause: duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes

* Mar 14, 2019 2:43 PM: Failed to restore file: "C:\Users\Jay\Desktop\Alex Database - Current as at Sept. '11.accdb". File hash is HfIJ0Hig96lTUKzV42w59PV9BEIugitLAJv+IiADbzo=, expected hash is XNIpUN5e3e9fyRrXFJ6wWtMfFo9sPVLmpu5elQRRoR8=

* Mar 14, 2019 2:43 PM: Failed to patch with remote file: "duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes", message: Failed to decrypt data (invalid passphrase?): Invalid password or corrupted data

* Mar 14, 2019 2:43 PM: Backend event: Get - Failed: duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes (31.23 MB)

* Mar 14, 2019 2:43 PM: Backend event: Get - Started: duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes (31.23 MB)

* Mar 14, 2019 2:43 PM: Backend event: Get - Retrying: duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes (31.23 MB)

* Mar 14, 2019 2:42 PM: Backend event: Get - Started: duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes (31.23 MB)

* Mar 14, 2019 2:42 PM: Backend event: Get - Retrying: duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes (31.23 MB)

* Mar 14, 2019 2:41 PM: Backend event: Get - Started: duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes (31.23 MB)

* Mar 14, 2019 2:41 PM: Backend event: Get - Retrying: duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes (31.23 MB)

* Mar 14, 2019 2:41 PM: Backend event: Get - Started: duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes (31.23 MB)

* Mar 14, 2019 2:40 PM: Backend event: Get - Retrying: duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes (31.23 MB)

* Mar 14, 2019 2:40 PM: Backend event: Get - Started: duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes (31.23 MB)

* Mar 14, 2019 2:40 PM: 1 remote files are required to restore 

So I tried it again restoring the file to my Desktop folder. But the resulting file was smaller than expected and worked no better than the current faulty version. The next attempt did not even have a resulting file to show for it.
Here is another saved log FWIW:

  "RestoredFiles": 0,
  "SizeOfRestoredFiles": 0,
  "RestoredFolders": 0,
  "RestoredSymlinks": 0,
  "PatchedFiles": 0,
  "DeletedFiles": 0,
  "DeletedFolders": 0,
  "DeletedSymlinks": 0,
  "MainOperation": "Restore",
  "RecreateDatabaseResults": null,
  "ParsedResult": "Error",
  "Version": "2.0.4.12 (2.0.4.12_canary_2019-01-16)",
  "EndTime": "2019-03-14T02:27:42.2366434Z",
  "BeginTime": "2019-03-14T02:16:42.7887451Z",
  "Duration": "00:10:59.4478983",
  "MessagesActualLength": 36,
  "WarningsActualLength": 0,
  "ErrorsActualLength": 4,
  "Messages": [
    "2019-03-14 15:16:42 +13 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Restore has started",
    "2019-03-14 15:16:42 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2019-03-14 15:16:47 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (37 bytes)",
    "2019-03-14 15:16:47 +13 - [Information-Duplicati.Library.Main.Database.LocalRestoreDatabase-SearchingBackup]: Searching backup 16 (6/02/2019 8:00:00 p.m.) ...",
    "2019-03-14 15:16:47 +13 - [Information-Duplicati.Library.Main.Operation.RestoreHandler-RemoteFileCount]: 3 remote files are required to restore",
    "2019-03-14 15:16:47 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)",
    "2019-03-14 15:17:16 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)",
    "2019-03-14 15:17:35 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)",
    "2019-03-14 15:18:04 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)",
    "2019-03-14 15:18:22 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)",
    "2019-03-14 15:18:57 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)",
    "2019-03-14 15:19:15 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)",
    "2019-03-14 15:19:48 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)",
    "2019-03-14 15:20:06 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)",
    "2019-03-14 15:20:41 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Failed: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)",
    "2019-03-14 15:20:41 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b708a3567db7a4ee99e5bc7d0f309031f.dblock.zip.aes (45.55 MB)",
    "2019-03-14 15:21:12 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b708a3567db7a4ee99e5bc7d0f309031f.dblock.zip.aes (45.55 MB)",
    "2019-03-14 15:21:31 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b708a3567db7a4ee99e5bc7d0f309031f.dblock.zip.aes (45.55 MB)",
    "2019-03-14 15:22:05 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b708a3567db7a4ee99e5bc7d0f309031f.dblock.zip.aes (45.55 MB)",
    "2019-03-14 15:22:23 +13 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b708a3567db7a4ee99e5bc7d0f309031f.dblock.zip.aes (45.55 MB)"
  ],
  "Warnings": [],
  "Errors": [
    "2019-03-14 15:20:41 +13 - [Error-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFailed]: Failed to patch with remote file: \"duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes\", message: Failed to decrypt data (invalid passphrase?): Invalid password or corrupted data",
    "2019-03-14 15:24:30 +13 - [Error-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFailed]: Failed to patch with remote file: \"duplicati-b708a3567db7a4ee99e5bc7d0f309031f.dblock.zip.aes\", message: Failed to decrypt data (invalid passphrase?): Invalid password or corrupted data",
    "2019-03-14 15:27:42 +13 - [Error-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFailed]: Failed to patch with remote file: \"duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes\", message: Failed to decrypt data (invalid passphrase?): Invalid password or corrupted data",
    "2019-03-14 15:27:42 +13 - [Error-Duplicati.Library.Main.Operation.RestoreHandler-RestoreFileFailed]: Failed to restore file: \"C:\\Users\\Jay\\Desktop\\Alex Database - Current as at Sept. '11.accdb\". File hash is pu9BSetwlMmcQH5bdJfHlqx5Ut9CKZiLYn+RmliR374=, expected hash is BkeOxjeU6KtjWosC6gSIcyMyYqn0yDYMI4pnpwnWUGQ="
  ],
  "BackendStatistics": {
    "RemoteCalls": 16,
    "BytesUploaded": 0,
    "BytesDownloaded": 0,
    "FilesUploaded": 0,
    "FilesDownloaded": 0,
    "FilesDeleted": 0,
    "FoldersCreated": 0,
    "RetryAttempts": 12,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 37,
    "KnownFileSize": 147168305,
    "LastBackupDate": "2019-03-14T15:00:00+13:00",
    "BackupListCount": 17,
    "TotalQuotaSpace": 0,
    "FreeQuotaSpace": 0,
    "AssignedQuotaSpace": -1,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Restore",
    "ParsedResult": "Success",
    "Version": "2.0.4.12 (2.0.4.12_canary_2019-01-16)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2019-03-14T02:16:42.7887451Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
} 

I would love to know what it’s problem is!


#10

Any log from failure may help, but there are several. Posted log looks like Job --> Show log --> Remote.

Viewing the log files of a backup job
Viewing the Duplicati Server Logs

are some others. Job --> Show log --> General gives summary information that could show more about whatever is going wrong that’s causing the transfer attempt to start –number-of-retries (default 5) times.

About --> Show log --> Live --> Retry can be used to watch your retries live, to see the details of failures. Longer term logging can be set up as described above, if you’d rather log to a file than watch live logging.

Did you have a way to see bandwidth? From the second log, it looks like nothing actually got transferred:

and neither log shows success. What do the earlier backup logs at Job --> Show log --> General show?

in the second log (along with no bytes or files downloaded) is a bad sign. Are there any previous retries?

There’s normally a verification at the end of the backup that does downloads. If you have a problem with downloads for some reason (please check all of your networking equipment, and consider a speed test) then the sort of download issues pasted here might be visible. What’s the history of the first paste’s log?

Going to the job’s Destination screen and pressing “Test connection” would be worthwhile, but it usually does a quick file list attempt, so even if that works it’s not a guarantee that a large file download will work.

Although it looks from what’s shown so far like inability to download files from B2, I don’t know what may have changed to start this all of a sudden, and am suggesting a look at old logs to check transfer history.

Check Your Bandwidth would be worth trying, but I’m not sure it’s as realistic as actual transfers with B2.

Duplicati.CommandLine.BackendTester.exe can do realistic tests, but I suggest easier tests/checks first.


#11

TBH, the bandwidth what I was referring to was the recorded downloading from B2, almost 2GB just trying to restore the one file. But as you suggested, the retries might be the cause here. I’ll try again and get the logs you suggested.


#12

OK, so I tried this again, allowed it to retry twice and cancelled it and tried to capture most of a live log, LMK if it’s helpful:


{"ClassName":"System.Threading.ThreadAbortException","Message":"Thread was being aborted.","Data":null,"InnerException":null,"HelpURL":null,"StackTraceString":" at Duplicati.Library.Main.AsyncDownloader.AsyncDownloaderEnumerator.MoveNext()\r\n at Duplicati.Library.Main.Operation.RestoreHandler.DoRun(LocalDatabase dbparent, IFilter filter, RestoreResults result)\r\n at Duplicati.Library.Main.Operation.RestoreHandler.Run(String[] paths, IFilter filter)\r\n at Duplicati.Library.Main.Controller.&lt;&gt;c__DisplayClass14_0.&lt;Restore&gt;b__0(RestoreResults result)\r\n at Duplicati.Library.Main.Controller.RunAction[T](T result, String[]&amp; paths, IFilter&amp; filter, Action`1 method)\r\n at Duplicati.Library.Main.Controller.Restore(String[] paths, IFilter filter)\r\n at Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":"8\nMoveNext\nDuplicati.Library.Main, Version=2.0.4.12, Culture=neutral, PublicKeyToken=null\nDuplicati.Library.Main.AsyncDownloader+AsyncDownloaderEnumerator\nBoolean MoveNext()","HResult":-2146233040,"Source":"Duplicati.Library.Main","WatsonBuckets":null}

* Mar 15, 2019 9:34 AM: Running Restore took 0:00:01:42.561

* Mar 15, 2019 9:34 AM: Operation Get with file duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes attempt 3 of 5 failed with message: Thread was being aborted.

{"ClassName":"System.Threading.ThreadAbortException","Message":"Thread was being aborted.","Data":null,"InnerException":null,"HelpURL":null,"StackTraceString":" at System.Threading.Thread.AbortInternal()\r\n at System.Threading.Thread.Abort()\r\n at Duplicati.Library.Main.BasicResults.TaskControlRendevouz()\r\n at Duplicati.Library.Main.BackendManager.ThreadRun()\r\n at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)\r\n at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)\r\n at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)\r\n at System.Threading.ThreadHelper.ThreadStart()","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":"8\nAbortInternal\nmscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\nSystem.Threading.Thread\nVoid AbortInternal()","HResult":-2146233040,"Source":"mscorlib","WatsonBuckets":null}

* Mar 15, 2019 9:34 AM: Backend event: Get - Retrying: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)

* Mar 15, 2019 9:34 AM: Operation Get with file duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes attempt 2 of 5 failed with message: Failed to decrypt data (invalid passphrase?): Invalid password or corrupted data

{"ClassName":"System.Security.Cryptography.CryptographicException","Message":"Failed to decrypt data (invalid passphrase?): Invalid password or corrupted data","Data":null,"InnerException":{"ClassName":"SharpAESCrypt.SharpAESCrypt+WrongPasswordException","Message":"Invalid password or corrupted data","Data":null,"InnerException":null,"HelpURL":null,"StackTraceString":" at SharpAESCrypt.SharpAESCrypt.ReadEncryptionHeader(String password, Boolean skipFileSizeCheck)\r\n at SharpAESCrypt.SharpAESCrypt..ctor(String password, Stream stream, OperationMode mode, Boolean skipFileSizeCheck)\r\n at Duplicati.Library.Encryption.AESEncryption.Decrypt(Stream input)\r\n at Duplicati.Library.Encryption.EncryptionBase.Decrypt(Stream input, Stream output)","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":"8\nReadEncryptionHeader\nSharpAESCrypt, Version=1.3.1.0, Culture=neutral, PublicKeyToken=da45da0a7b8da0d2\nSharpAESCrypt.SharpAESCrypt\nVoid ReadEncryptionHeader(System.String, Boolean)","HResult":-2146233296,"Source":"SharpAESCrypt","WatsonBuckets":null},"HelpURL":null,"StackTraceString":" at Duplicati.Library.Main.BackendManager.coreDoGetPiping(FileEntryItem item, IEncryption useDecrypter, Int64&amp; retDownloadSize, String&amp; retHashcode)\r\n at Duplicati.Library.Main.BackendManager.DoGet(FileEntryItem item)\r\n at Duplicati.Library.Main.BackendManager.ThreadRun()","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":"8\ncoreDoGetPiping\nDuplicati.Library.Main, Version=2.0.4.12, Culture=neutral, PublicKeyToken=null\nDuplicati.Library.Main.BackendManager\nDuplicati.Library.Utility.TempFile coreDoGetPiping(FileEntryItem, Duplicati.Library.Interface.IEncryption, Int64 ByRef, System.String ByRef)","HResult":-2146233296,"Source":"Duplicati.Library.Main","WatsonBuckets":null}

* Mar 15, 2019 9:34 AM: RemoteOperationGet took 0:00:00:35.690

* Mar 15, 2019 9:33 AM: Backend event: Get - Started: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)

* Mar 15, 2019 9:33 AM: Starting - RemoteOperationGet

* Mar 15, 2019 9:33 AM: Backend event: Get - Retrying: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)

* Mar 15, 2019 9:33 AM: Operation Get with file duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes attempt 1 of 5 failed with message: Failed to decrypt data (invalid passphrase?): Invalid password or corrupted data

{"ClassName":"System.Security.Cryptography.CryptographicException","Message":"Failed to decrypt data (invalid passphrase?): Invalid password or corrupted data","Data":null,"InnerException":{"ClassName":"SharpAESCrypt.SharpAESCrypt+WrongPasswordException","Message":"Invalid password or corrupted data","Data":null,"InnerException":null,"HelpURL":null,"StackTraceString":" at SharpAESCrypt.SharpAESCrypt.ReadEncryptionHeader(String password, Boolean skipFileSizeCheck)\r\n at SharpAESCrypt.SharpAESCrypt..ctor(String password, Stream stream, OperationMode mode, Boolean skipFileSizeCheck)\r\n at Duplicati.Library.Encryption.AESEncryption.Decrypt(Stream input)\r\n at Duplicati.Library.Encryption.EncryptionBase.Decrypt(Stream input, Stream output)","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":"8\nReadEncryptionHeader\nSharpAESCrypt, Version=1.3.1.0, Culture=neutral, PublicKeyToken=da45da0a7b8da0d2\nSharpAESCrypt.SharpAESCrypt\nVoid ReadEncryptionHeader(System.String, Boolean)","HResult":-2146233296,"Source":"SharpAESCrypt","WatsonBuckets":null},"HelpURL":null,"StackTraceString":" at Duplicati.Library.Main.BackendManager.coreDoGetPiping(FileEntryItem item, IEncryption useDecrypter, Int64&amp; retDownloadSize, String&amp; retHashcode)\r\n at Duplicati.Library.Main.BackendManager.DoGet(FileEntryItem item)\r\n at Duplicati.Library.Main.BackendManager.ThreadRun()","RemoteStackTraceString":null,"RemoteStackIndex":0,"ExceptionMethod":"8\ncoreDoGetPiping\nDuplicati.Library.Main, Version=2.0.4.12, Culture=neutral, PublicKeyToken=null\nDuplicati.Library.Main.BackendManager\nDuplicati.Library.Utility.TempFile coreDoGetPiping(FileEntryItem, Duplicati.Library.Interface.IEncryption, Int64 ByRef, System.String ByRef)","HResult":-2146233296,"Source":"Duplicati.Library.Main","WatsonBuckets":null}

* Mar 15, 2019 9:33 AM: RemoteOperationGet took 0:00:00:33.939

* Mar 15, 2019 9:33 AM: Backend event: Get - Started: duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes (49.91 MB)

* Mar 15, 2019 9:33 AM: Starting - RemoteOperationGet

* Mar 15, 2019 9:33 AM: 3 remote files are required to restore

* Mar 15, 2019 9:33 AM: GetMissingVolumes took 0:00:00:00.001

* Mar 15, 2019 9:33 AM: Starting - GetMissingVolumes

* Mar 15, 2019 9:33 AM: ScanForExistingSourceBlocksFast took 0:00:00:00.078

* Mar 15, 2019 9:33 AM: CommitBlockMarker took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - CommitBlockMarker

* Mar 15, 2019 9:33 AM: Target file is patched with some local data: C:\Users\Jay\Desktop\Alex Database - Current as at Sept. '11.2019-02-07.accdb

* Mar 15, 2019 9:33 AM: ExecuteReader: SELECT DISTINCT "Fileset-E223E078E1415E45B54CD4503D74991A"."TargetPath", "Fileset-E223E078E1415E45B54CD4503D74991A"."Path", "Fileset-E223E078E1415E45B54CD4503D74991A"."ID", "Blocks-E223E078E1415E45B54CD4503D74991A"."Index", "Blocks-E223E078E1415E45B54CD4503D74991A"."Hash", "Blocks-E223E078E1415E45B54CD4503D74991A"."Size" FROM "Fileset-E223E078E1415E45B54CD4503D74991A", "Blocks-E223E078E1415E45B54CD4503D74991A", "File", (SELECT "File"."Path", "File"."BlocksetID", MAX("Fileset"."Timestamp") FROM "Fileset", "FilesetEntry", "File" WHERE "FilesetEntry"."FileID" = "File"."ID" AND "FilesetEntry"."FilesetID" = "Fileset"."ID" AND "File"."Path" IN (SELECT DISTINCT "Fileset-E223E078E1415E45B54CD4503D74991A"."Path" FROM "Fileset-E223E078E1415E45B54CD4503D74991A", "Blocks-E223E078E1415E45B54CD4503D74991A" WHERE "Fileset-E223E078E1415E45B54CD4503D74991A"."ID" = "Blocks-E223E078E1415E45B54CD4503D74991A"."FileID" AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Restored" = 0 AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Metadata" = 0 AND "Fileset-E223E078E1415E45B54CD4503D74991A"."TargetPath" != "Fileset-E223E078E1415E45B54CD4503D74991A"."Path" ) GROUP BY "File"."Path" ) S, "Block", "BlocksetEntry" WHERE "BlocksetEntry"."BlocksetID" = "S"."BlocksetID" AND "BlocksetEntry"."BlocksetID" = "File"."BlocksetID" AND "BlocksetEntry"."BlockID" = "Block"."ID" AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Index" = "BlocksetEntry"."Index" AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Hash" = "Block"."Hash" AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Size" = "Block"."Size" AND "S"."Path" = "Fileset-E223E078E1415E45B54CD4503D74991A"."Path" AND "Fileset-E223E078E1415E45B54CD4503D74991A"."ID" = "Blocks-E223E078E1415E45B54CD4503D74991A"."FileID" AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Restored" = 0 AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Metadata" = 0 AND "Fileset-E223E078E1415E45B54CD4503D74991A"."TargetPath" != "Fileset-E223E078E1415E45B54CD4503D74991A"."Path" ORDER BY "Fileset-E223E078E1415E45B54CD4503D74991A"."ID", "Blocks-E223E078E1415E45B54CD4503D74991A"."Index" took 0:00:00:00.002

* Mar 15, 2019 9:33 AM: Starting - ExecuteReader: SELECT DISTINCT "Fileset-E223E078E1415E45B54CD4503D74991A"."TargetPath", "Fileset-E223E078E1415E45B54CD4503D74991A"."Path", "Fileset-E223E078E1415E45B54CD4503D74991A"."ID", "Blocks-E223E078E1415E45B54CD4503D74991A"."Index", "Blocks-E223E078E1415E45B54CD4503D74991A"."Hash", "Blocks-E223E078E1415E45B54CD4503D74991A"."Size" FROM "Fileset-E223E078E1415E45B54CD4503D74991A", "Blocks-E223E078E1415E45B54CD4503D74991A", "File", (SELECT "File"."Path", "File"."BlocksetID", MAX("Fileset"."Timestamp") FROM "Fileset", "FilesetEntry", "File" WHERE "FilesetEntry"."FileID" = "File"."ID" AND "FilesetEntry"."FilesetID" = "Fileset"."ID" AND "File"."Path" IN (SELECT DISTINCT "Fileset-E223E078E1415E45B54CD4503D74991A"."Path" FROM "Fileset-E223E078E1415E45B54CD4503D74991A", "Blocks-E223E078E1415E45B54CD4503D74991A" WHERE "Fileset-E223E078E1415E45B54CD4503D74991A"."ID" = "Blocks-E223E078E1415E45B54CD4503D74991A"."FileID" AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Restored" = 0 AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Metadata" = 0 AND "Fileset-E223E078E1415E45B54CD4503D74991A"."TargetPath" != "Fileset-E223E078E1415E45B54CD4503D74991A"."Path" ) GROUP BY "File"."Path" ) S, "Block", "BlocksetEntry" WHERE "BlocksetEntry"."BlocksetID" = "S"."BlocksetID" AND "BlocksetEntry"."BlocksetID" = "File"."BlocksetID" AND "BlocksetEntry"."BlockID" = "Block"."ID" AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Index" = "BlocksetEntry"."Index" AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Hash" = "Block"."Hash" AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Size" = "Block"."Size" AND "S"."Path" = "Fileset-E223E078E1415E45B54CD4503D74991A"."Path" AND "Fileset-E223E078E1415E45B54CD4503D74991A"."ID" = "Blocks-E223E078E1415E45B54CD4503D74991A"."FileID" AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Restored" = 0 AND "Blocks-E223E078E1415E45B54CD4503D74991A"."Metadata" = 0 AND "Fileset-E223E078E1415E45B54CD4503D74991A"."TargetPath" != "Fileset-E223E078E1415E45B54CD4503D74991A"."Path" ORDER BY "Fileset-E223E078E1415E45B54CD4503D74991A"."ID", "Blocks-E223E078E1415E45B54CD4503D74991A"."Index"

* Mar 15, 2019 9:33 AM: Starting - ScanForExistingSourceBlocksFast

* Mar 15, 2019 9:33 AM: ScanForExistingTargetBlocks took 0:00:00:00.006

* Mar 15, 2019 9:33 AM: CommitBlockMarker took 0:00:00:00.001

* Mar 15, 2019 9:33 AM: Starting - CommitBlockMarker

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: UPDATE "Fileset-E223E078E1415E45B54CD4503D74991A" SET "TargetPath" = "C:\Users\Jay\Desktop\Alex Database - Current as at Sept. '11.2019-02-07.accdb" WHERE "ID" = 1 took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: UPDATE "Fileset-E223E078E1415E45B54CD4503D74991A" SET "TargetPath" = "C:\Users\Jay\Desktop\Alex Database - Current as at Sept. '11.2019-02-07.accdb" WHERE "ID" = 1

* Mar 15, 2019 9:33 AM: Target file exists and will be restored to: C:\Users\Jay\Desktop\Alex Database - Current as at Sept. '11.2019-02-07.accdb

* Mar 15, 2019 9:33 AM: Starting - ScanForExistingTargetBlocks

* Mar 15, 2019 9:33 AM: CreateDirectory took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: ExecuteReader: SELECT "TargetPath" FROM "Fileset-E223E078E1415E45B54CD4503D74991A" WHERE "BlocksetID" == -100 took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteReader: SELECT "TargetPath" FROM "Fileset-E223E078E1415E45B54CD4503D74991A" WHERE "BlocksetID" == -100

* Mar 15, 2019 9:33 AM: Starting - CreateDirectory

* Mar 15, 2019 9:33 AM: PrepareBlockList took 0:00:00:00.022

* Mar 15, 2019 9:33 AM: CreateProgressTracker took 0:00:00:00.004

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: CREATE TEMPORARY TRIGGER "UpdateTotalStats_FileProgress-860C0FE1A17656448D535DDC236F7F27" AFTER UPDATE ON "FileProgress-860C0FE1A17656448D535DDC236F7F27" BEGIN UPDATE "TotalProgress-860C0FE1A17656448D535DDC236F7F27" SET "FilesFullyRestored" = "TotalProgress-860C0FE1A17656448D535DDC236F7F27"."FilesFullyRestored" + (CASE WHEN NEW."BlocksRestored" = NEW."TotalBlocks" THEN 1 ELSE 0 END) - (CASE WHEN OLD."BlocksRestored" = OLD."TotalBlocks" THEN 1 ELSE 0 END) , "FilesPartiallyRestored" = "TotalProgress-860C0FE1A17656448D535DDC236F7F27"."FilesPartiallyRestored" + (CASE WHEN NEW."BlocksRestored" BETWEEN 1 AND NEW."TotalBlocks" - 1 THEN 1 ELSE 0 END) - (CASE WHEN OLD."BlocksRestored" BETWEEN 1 AND OLD."TotalBlocks" - 1 THEN 1 ELSE 0 END) , "BlocksRestored" = "TotalProgress-860C0FE1A17656448D535DDC236F7F27"."BlocksRestored" + NEW."BlocksRestored" - OLD."BlocksRestored" , "SizeRestored" = "TotalProgress-860C0FE1A17656448D535DDC236F7F27"."SizeRestored" + NEW."SizeRestored" - OLD."SizeRestored" ; END took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: CREATE TEMPORARY TRIGGER "UpdateTotalStats_FileProgress-860C0FE1A17656448D535DDC236F7F27" AFTER UPDATE ON "FileProgress-860C0FE1A17656448D535DDC236F7F27" BEGIN UPDATE "TotalProgress-860C0FE1A17656448D535DDC236F7F27" SET "FilesFullyRestored" = "TotalProgress-860C0FE1A17656448D535DDC236F7F27"."FilesFullyRestored" + (CASE WHEN NEW."BlocksRestored" = NEW."TotalBlocks" THEN 1 ELSE 0 END) - (CASE WHEN OLD."BlocksRestored" = OLD."TotalBlocks" THEN 1 ELSE 0 END) , "FilesPartiallyRestored" = "TotalProgress-860C0FE1A17656448D535DDC236F7F27"."FilesPartiallyRestored" + (CASE WHEN NEW."BlocksRestored" BETWEEN 1 AND NEW."TotalBlocks" - 1 THEN 1 ELSE 0 END) - (CASE WHEN OLD."BlocksRestored" BETWEEN 1 AND OLD."TotalBlocks" - 1 THEN 1 ELSE 0 END) , "BlocksRestored" = "TotalProgress-860C0FE1A17656448D535DDC236F7F27"."BlocksRestored" + NEW."BlocksRestored" - OLD."BlocksRestored" , "SizeRestored" = "TotalProgress-860C0FE1A17656448D535DDC236F7F27"."SizeRestored" + NEW."SizeRestored" - OLD."SizeRestored" ; END

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: CREATE TEMPORARY TRIGGER "TrackRestoredBlocks_Blocks-E223E078E1415E45B54CD4503D74991A" AFTER UPDATE OF "Restored" ON "Blocks-E223E078E1415E45B54CD4503D74991A" WHEN OLD."Restored" != NEW."Restored" AND NEW."Metadata" = 0 BEGIN UPDATE "FileProgress-860C0FE1A17656448D535DDC236F7F27" SET "BlocksRestored" = "FileProgress-860C0FE1A17656448D535DDC236F7F27"."BlocksRestored" + (NEW."Restored" - OLD."Restored") , "SizeRestored" = "FileProgress-860C0FE1A17656448D535DDC236F7F27"."SizeRestored" + ((NEW."Restored" - OLD."Restored") * NEW.Size) WHERE "FileProgress-860C0FE1A17656448D535DDC236F7F27"."FileId" = NEW."FileID" ; END took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: CREATE TEMPORARY TRIGGER "TrackRestoredBlocks_Blocks-E223E078E1415E45B54CD4503D74991A" AFTER UPDATE OF "Restored" ON "Blocks-E223E078E1415E45B54CD4503D74991A" WHEN OLD."Restored" != NEW."Restored" AND NEW."Metadata" = 0 BEGIN UPDATE "FileProgress-860C0FE1A17656448D535DDC236F7F27" SET "BlocksRestored" = "FileProgress-860C0FE1A17656448D535DDC236F7F27"."BlocksRestored" + (NEW."Restored" - OLD."Restored") , "SizeRestored" = "FileProgress-860C0FE1A17656448D535DDC236F7F27"."SizeRestored" + ((NEW."Restored" - OLD."Restored") * NEW.Size) WHERE "FileProgress-860C0FE1A17656448D535DDC236F7F27"."FileId" = NEW."FileID" ; END

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: INSERT INTO "TotalProgress-860C0FE1A17656448D535DDC236F7F27" ( "TotalFiles", "TotalBlocks", "TotalSize" , "FilesFullyRestored", "FilesPartiallyRestored", "BlocksRestored", "SizeRestored" ) SELECT IFNULL(COUNT("P"."FileId"), 0), IFNULL(SUM("P"."TotalBlocks"), 0), IFNULL(SUM("P"."TotalSize"), 0) , IFNULL(COUNT(CASE WHEN "P"."BlocksRestored" = "P"."TotalBlocks" THEN 1 ELSE NULL END), 0) , IFNULL(COUNT(CASE WHEN "P"."BlocksRestored" BETWEEN 1 AND "P"."TotalBlocks" - 1 THEN 1 ELSE NULL END), 0) , IFNULL(SUM("P"."BlocksRestored"), 0), IFNULL(SUM("P"."SizeRestored"), 0) FROM "FileProgress-860C0FE1A17656448D535DDC236F7F27" "P" took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: INSERT INTO "TotalProgress-860C0FE1A17656448D535DDC236F7F27" ( "TotalFiles", "TotalBlocks", "TotalSize" , "FilesFullyRestored", "FilesPartiallyRestored", "BlocksRestored", "SizeRestored" ) SELECT IFNULL(COUNT("P"."FileId"), 0), IFNULL(SUM("P"."TotalBlocks"), 0), IFNULL(SUM("P"."TotalSize"), 0) , IFNULL(COUNT(CASE WHEN "P"."BlocksRestored" = "P"."TotalBlocks" THEN 1 ELSE NULL END), 0) , IFNULL(COUNT(CASE WHEN "P"."BlocksRestored" BETWEEN 1 AND "P"."TotalBlocks" - 1 THEN 1 ELSE NULL END), 0) , IFNULL(SUM("P"."BlocksRestored"), 0), IFNULL(SUM("P"."SizeRestored"), 0) FROM "FileProgress-860C0FE1A17656448D535DDC236F7F27" "P"

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: INSERT INTO "FileProgress-860C0FE1A17656448D535DDC236F7F27" ("FileId", "TotalBlocks", "TotalSize", "BlocksRestored", "SizeRestored") SELECT "F"."ID", IFNULL(COUNT("B"."ID"), 0), IFNULL(SUM("B"."Size"), 0) , IFNULL(COUNT(CASE "B"."Restored" WHEN 1 THEN "B"."ID" ELSE NULL END), 0) , IFNULL(SUM(CASE "B"."Restored" WHEN 1 THEN "B"."Size" ELSE 0 END), 0) FROM "Fileset-E223E078E1415E45B54CD4503D74991A" "F" LEFT JOIN "Blocks-E223E078E1415E45B54CD4503D74991A" "B" ON "B"."FileID" = "F"."ID" WHERE "B"."Metadata" IS NOT 1 GROUP BY "F"."ID" took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: INSERT INTO "FileProgress-860C0FE1A17656448D535DDC236F7F27" ("FileId", "TotalBlocks", "TotalSize", "BlocksRestored", "SizeRestored") SELECT "F"."ID", IFNULL(COUNT("B"."ID"), 0), IFNULL(SUM("B"."Size"), 0) , IFNULL(COUNT(CASE "B"."Restored" WHEN 1 THEN "B"."ID" ELSE NULL END), 0) , IFNULL(SUM(CASE "B"."Restored" WHEN 1 THEN "B"."Size" ELSE 0 END), 0) FROM "Fileset-E223E078E1415E45B54CD4503D74991A" "F" LEFT JOIN "Blocks-E223E078E1415E45B54CD4503D74991A" "B" ON "B"."FileID" = "F"."ID" WHERE "B"."Metadata" IS NOT 1 GROUP BY "F"."ID"

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: CREATE TEMPORARY TABLE "TotalProgress-860C0FE1A17656448D535DDC236F7F27" ( "TotalFiles" INTEGER NOT NULL, "TotalBlocks" INTEGER NOT NULL, "TotalSize" INTEGER NOT NULL , "FilesFullyRestored" INTEGER NOT NULL, "FilesPartiallyRestored" INTEGER NOT NULL , "BlocksRestored" INTEGER NOT NULL, "SizeRestored" INTEGER NOT NULL ) took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "TotalProgress-860C0FE1A17656448D535DDC236F7F27" ( "TotalFiles" INTEGER NOT NULL, "TotalBlocks" INTEGER NOT NULL, "TotalSize" INTEGER NOT NULL , "FilesFullyRestored" INTEGER NOT NULL, "FilesPartiallyRestored" INTEGER NOT NULL , "BlocksRestored" INTEGER NOT NULL, "SizeRestored" INTEGER NOT NULL )

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: DROP TABLE IF EXISTS "TotalProgress-860C0FE1A17656448D535DDC236F7F27" took 0:00:00:00.002

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "TotalProgress-860C0FE1A17656448D535DDC236F7F27"

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: CREATE TEMPORARY TABLE "FileProgress-860C0FE1A17656448D535DDC236F7F27" ( "FileId" INTEGER PRIMARY KEY , "TotalBlocks" INTEGER NOT NULL, "TotalSize" INTEGER NOT NULL , "BlocksRestored" INTEGER NOT NULL, "SizeRestored" INTEGER NOT NULL ) took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "FileProgress-860C0FE1A17656448D535DDC236F7F27" ( "FileId" INTEGER PRIMARY KEY , "TotalBlocks" INTEGER NOT NULL, "TotalSize" INTEGER NOT NULL , "BlocksRestored" INTEGER NOT NULL, "SizeRestored" INTEGER NOT NULL )

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: DROP TABLE IF EXISTS "FileProgress-860C0FE1A17656448D535DDC236F7F27" took 0:00:00:00.001

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "FileProgress-860C0FE1A17656448D535DDC236F7F27"

* Mar 15, 2019 9:33 AM: Starting - CreateProgressTracker

* Mar 15, 2019 9:33 AM: FindMissingBlocks took 0:00:00:00.002

* Mar 15, 2019 9:33 AM: Restore list contains 64 blocks with a total size of 6.09 MB

* Mar 15, 2019 9:33 AM: ExecuteScalarInt64: SELECT SUM("Size") FROM "Blocks-E223E078E1415E45B54CD4503D74991A" took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteScalarInt64: SELECT SUM("Size") FROM "Blocks-E223E078E1415E45B54CD4503D74991A"

* Mar 15, 2019 9:33 AM: Starting - FindMissingBlocks

* Mar 15, 2019 9:33 AM: SetTargetPaths took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: UPDATE "Fileset-E223E078E1415E45B54CD4503D74991A" SET "TargetPath" = "C:\Users\Jay\Desktop\" || "TargetPath" took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: UPDATE "Fileset-E223E078E1415E45B54CD4503D74991A" SET "TargetPath" = "C:\Users\Jay\Desktop\" || "TargetPath"

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: UPDATE "Fileset-E223E078E1415E45B54CD4503D74991A" SET "TargetPath" = SUBSTR("Path", 80) took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: UPDATE "Fileset-E223E078E1415E45B54CD4503D74991A" SET "TargetPath" = SUBSTR("Path", 80)

* Mar 15, 2019 9:33 AM: Mapping restore path prefix to "\\SERVER\Data (E)\ALEX Dist\Alex Dist from Public\Databases and contacts lists\" to "C:\Users\Jay\Desktop\"

* Mar 15, 2019 9:33 AM: ExecuteScalarInt64: SELECT COUNT(*) FROM "Fileset-E223E078E1415E45B54CD4503D74991A" WHERE SUBSTR("Path", 1, 79) = "\\SERVER\Data (E)\ALEX Dist\Alex Dist from Public\Databases and contacts lists\" took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "Fileset-E223E078E1415E45B54CD4503D74991A" WHERE SUBSTR("Path", 1, 79) = "\\SERVER\Data (E)\ALEX Dist\Alex Dist from Public\Databases and contacts lists\"

* Mar 15, 2019 9:33 AM: ExecuteScalarInt64: SELECT COUNT(*) FROM "Fileset-E223E078E1415E45B54CD4503D74991A" WHERE SUBSTR("Path", 1, 125) = "\\SERVER\Data (E)\ALEX Dist\Alex Dist from Public\Databases and contacts lists\Alex Database - Current as at Sept. '11.accdb\" took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "Fileset-E223E078E1415E45B54CD4503D74991A" WHERE SUBSTR("Path", 1, 125) = "\\SERVER\Data (E)\ALEX Dist\Alex Dist from Public\Databases and contacts lists\Alex Database - Current as at Sept. '11.accdb\"

* Mar 15, 2019 9:33 AM: ExecuteScalarInt64: SELECT COUNT(*) FROM "Fileset-E223E078E1415E45B54CD4503D74991A" took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "Fileset-E223E078E1415E45B54CD4503D74991A"

* Mar 15, 2019 9:33 AM: Starting - SetTargetPaths

* Mar 15, 2019 9:33 AM: PrepareRestoreFileList took 0:00:00:00.014

* Mar 15, 2019 9:33 AM: Needs to restore 1 files (6.09 MB)

* Mar 15, 2019 9:33 AM: ExecuteReader: SELECT COUNT(DISTINCT "Fileset-E223E078E1415E45B54CD4503D74991A"."Path"), SUM("Blockset"."Length") FROM "Fileset-E223E078E1415E45B54CD4503D74991A", "Blockset" WHERE "Fileset-E223E078E1415E45B54CD4503D74991A"."BlocksetID" = "Blockset"."ID" took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteReader: SELECT COUNT(DISTINCT "Fileset-E223E078E1415E45B54CD4503D74991A"."Path"), SUM("Blockset"."Length") FROM "Fileset-E223E078E1415E45B54CD4503D74991A", "Blockset" WHERE "Fileset-E223E078E1415E45B54CD4503D74991A"."BlocksetID" = "Blockset"."ID"

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: CREATE INDEX "Blocks-E223E078E1415E45B54CD4503D74991A_FileIdIndexIndex" ON "Blocks-E223E078E1415E45B54CD4503D74991A" ("FileId", "Index") took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: CREATE INDEX "Blocks-E223E078E1415E45B54CD4503D74991A_FileIdIndexIndex" ON "Blocks-E223E078E1415E45B54CD4503D74991A" ("FileId", "Index")

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: CREATE INDEX "Blocks-E223E078E1415E45B54CD4503D74991A_HashSizeIndex" ON "Blocks-E223E078E1415E45B54CD4503D74991A" ("Hash", "Size") took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: CREATE INDEX "Blocks-E223E078E1415E45B54CD4503D74991A_HashSizeIndex" ON "Blocks-E223E078E1415E45B54CD4503D74991A" ("Hash", "Size")

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: CREATE INDEX "Fileset-E223E078E1415E45B54CD4503D74991A_Index" ON "Fileset-E223E078E1415E45B54CD4503D74991A" ("TargetPath") took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: CREATE INDEX "Fileset-E223E078E1415E45B54CD4503D74991A_Index" ON "Fileset-E223E078E1415E45B54CD4503D74991A" ("TargetPath")

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocks-E223E078E1415E45B54CD4503D74991A" ("ID" INTEGER PRIMARY KEY, "FileID" INTEGER NOT NULL, "Index" INTEGER NOT NULL, "Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL, "Restored" BOOLEAN NOT NULL, "Metadata" BOOLEAN NOT NULL) took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Blocks-E223E078E1415E45B54CD4503D74991A" ("ID" INTEGER PRIMARY KEY, "FileID" INTEGER NOT NULL, "Index" INTEGER NOT NULL, "Hash" TEXT NOT NULL, "Size" INTEGER NOT NULL, "Restored" BOOLEAN NOT NULL, "Metadata" BOOLEAN NOT NULL)

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: CREATE TEMPORARY TABLE "Fileset-E223E078E1415E45B54CD4503D74991A" ("ID" INTEGER PRIMARY KEY, "Path" TEXT NOT NULL, "BlocksetID" INTEGER NOT NULL, "MetadataID" INTEGER NOT NULL, "TargetPath" TEXT NULL, "DataVerified" BOOLEAN NOT NULL) took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: CREATE TEMPORARY TABLE "Fileset-E223E078E1415E45B54CD4503D74991A" ("ID" INTEGER PRIMARY KEY, "Path" TEXT NOT NULL, "BlocksetID" INTEGER NOT NULL, "MetadataID" INTEGER NOT NULL, "TargetPath" TEXT NULL, "DataVerified" BOOLEAN NOT NULL)

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: DROP TABLE IF EXISTS "Blocks-E223E078E1415E45B54CD4503D74991A" took 0:00:00:00.001

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Blocks-E223E078E1415E45B54CD4503D74991A"

* Mar 15, 2019 9:33 AM: ExecuteNonQuery: DROP TABLE IF EXISTS "Fileset-E223E078E1415E45B54CD4503D74991A" took 0:00:00:00.001

* Mar 15, 2019 9:33 AM: Starting - ExecuteNonQuery: DROP TABLE IF EXISTS "Fileset-E223E078E1415E45B54CD4503D74991A"

* Mar 15, 2019 9:33 AM: Searching backup 16 (6/02/2019 8:00:00 p.m.) ...

* Mar 15, 2019 9:33 AM: ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC

* Mar 15, 2019 9:33 AM: ExecuteScalarInt64: SELECT "Timestamp" FROM "Fileset" WHERE "ID" = 39 took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteScalarInt64: SELECT "Timestamp" FROM "Fileset" WHERE "ID" = 39

* Mar 15, 2019 9:33 AM: ExecuteReader: SELECT "ID" FROM "Fileset" WHERE "Timestamp" &lt;= 1549483200 ORDER BY "Timestamp" DESC took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteReader: SELECT "ID" FROM "Fileset" WHERE "Timestamp" &lt;= 1549483200 ORDER BY "Timestamp" DESC

* Mar 15, 2019 9:33 AM: ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC took 0:00:00:00.001

* Mar 15, 2019 9:33 AM: Starting - ExecuteReader: SELECT "ID", "Timestamp" FROM "Fileset" ORDER BY "Timestamp" DESC

* Mar 15, 2019 9:33 AM: Starting - PrepareRestoreFileList

* Mar 15, 2019 9:33 AM: Starting - PrepareBlockList

* Mar 15, 2019 9:33 AM: ExecuteReader: SELECT DISTINCT "Name", "State" FROM "Remotevolume" WHERE "Name" IN (SELECT "Name" FROM "Remotevolume" WHERE "State" IN ("Deleted", "Deleting")) AND NOT "State" IN ("Deleted", "Deleting") took 0:00:00:00.001

* Mar 15, 2019 9:33 AM: Starting - ExecuteReader: SELECT DISTINCT "Name", "State" FROM "Remotevolume" WHERE "Name" IN (SELECT "Name" FROM "Remotevolume" WHERE "State" IN ("Deleted", "Deleting")) AND NOT "State" IN ("Deleted", "Deleting")

* Mar 15, 2019 9:33 AM: RemoteOperationList took 0:00:00:02.639

* Mar 15, 2019 9:33 AM: Backend event: List - Completed: (43 bytes)

* Mar 15, 2019 9:33 AM: Backend event: List - Started: ()

* Mar 15, 2019 9:33 AM: Starting - RemoteOperationList

* Mar 15, 2019 9:33 AM: ExecuteScalarInt64: SELECT COUNT(*) FROM "Block" WHERE "Size" &gt; 102400 took 0:00:00:00.003

* Mar 15, 2019 9:33 AM: Starting - ExecuteScalarInt64: SELECT COUNT(*) FROM "Block" WHERE "Size" &gt; 102400

* Mar 15, 2019 9:33 AM: ExecuteReader: SELECT "Key", "Value" FROM "Configuration" took 0:00:00:00.000

* Mar 15, 2019 9:33 AM: Starting - ExecuteReader: SELECT "Key", "Value" FROM "Configuration"

* Mar 15, 2019 9:33 AM: ExecuteReader: SELECT "Key", "Value" FROM "Configuration" took 0:00:00:00.001 

Also tried a database repair before that, (again), but it said it’s all good :neutral_face::wink:


#13

All rosy:star_struck: no warnings or errors at all.


#14

One drawback of the live log is it doesn’t show seconds, but earlier logs showed the retry in the minute after start, so it’s maybe neither too fast nor too slow (retry is often in the same rounded-to-the-minute).

It completed a Backend event: List so your B2 access must work, but it keeps complaining about a passphrase problem or possibly an error on that file, which varies per run – is the restore file changing?

duplicati-b9522954b15c74218bb6c899315c3b53e.dblock.zip.aes failed 2 times in the latest log.
duplicati-b2309aa2fcab04deebe6d51e37571832c.dblock.zip.aes failed 5 times in the earlier log.

In case it’s encryption (because I’m not seeing network-level issues in the last log you provided), are you running with default encryption, and has passphrase changed (it’s generally not supposed to allow that)?

There are a couple of ways to pull this apart further. One is a direct restore where you basically supply all settings over again, and build a partial temporary database instead of relying on the usual local database. What this should prove is whether there’s a passphrase problem on something like the dlist file that says what the backup date is, and what files it has. If it can get that far, THAT passphrase at least works there. Actually building the partial temporary database will pull down some dindex files, and maybe dblock files. You can try the actual desired restore if it keeps cooperating, while we keep on figuring out prior issues…

Getting files (such as the two we know are having trouble) and doing a manual decrypt could also be run. Duplicati.CommandLine.BackendTool.exe is quite universal, but for B2 a B2 UI download seems simpler. AES Crypt can try to decrypt it. If you prefer, SharpAESCrypt.exe in Duplicati’s install folder is its CLI tool:

C:\Program Files\Duplicati 2>SharpAESCrypt.exe
Usage: SharpAESCrypt e|d[o][1-4] <password> [<fromPath> [<toPath>]]

Use 'e' or 'd' to specify operation: encrypt or decrypt.
Append an 'o' to the operation for optimistic mode. This will skip some tests and leaves partial/invalid files on disk.
Append a single number (up to 4) to the operation to set the number of threads used for crypting. Default is single thread mode (1).

If you ommit the fromPath or toPath, stdin/stdout are used insted, e.g.:
  SharpAESCrypt e 1234 < file.jpg > file.jpg.aes

Abnormal exit will return an errorlevel above 0 (zero):
  4 - Password invalid
  3 - HMAC Mismatch / altered data (also invalid password for version 0 files)
  2 - Missing input stream / input file not found
  1 - Any other cryptographic or IO exception

C:\Program Files\Duplicati 2>

#15

Yes, this would be because I tried restoring from an earlier date the next time, just in case it helped.

Yes, default encryption. No, I’m not aware of any change to the passphrase. The ‘Test Connection’ function works fine, if this is the same passphrase you refer to.

The method you suggested of manually unencrypting was a bit beyond me, but I found I do have a saved configuration file, so I tried restoring from that. It looked promising and recreated a partial temporary database, but ended up throwing the same errors.
I’ve downloaded the needed .aes files from the B2 UI, but how do you go about getting the data out of them manually?


#16

The main test I’d hoped to get is of encryption passphrase. This is different from B2 access credentials. Encryption setting (what makes your B2 files .zip.aes instead of .zip) got done on the first setup screen:

image

This sounds like Restore --> Restore from configuration (one line down from Direct restore from backup files, and with some of its benefits that I’m after – maybe). If that’s what you did, and if the dates came up right for you to choose from, and if the file display also came up right, this means the dlist files decrypted OK. If it only complained about dblock files, then maybe the dindex files (dindex indexes dblock) were OK. “Same errors” meaning the same dblock file or files may mean it’s actual file damage, not a passphrase problem, however a manual decryption try might also confirm. What size are your two troublesome files?

If you mean you downloaded the two dblock files being talked about, they’re not enough to get source files back, but are just for decryption and integrity tests. The decrypt method would either use SharpAESCrypt per its help, using d to specify decryption, or if you install AES Crypt, right click the file, AES Decrypt, then

image

Using AES Crypt on Windows Graphical User Interface (GUI) Option

After decryption you’d be left with (by default) a zip file which you could then open with any ZIP program as a test, though if you had actual file damage it would probably have hit errors earlier when you tried decrypt.

Using these zip files to restore original source files is not practical to do entirely by hand for anything large, because by default the source file is sliced into 100KB blocks for deduplication purposes, so you’d have to collect all the blocks for reassembly. This is best done using a computer, either with normal restore (which is having troubles we’re trying to isolate to either a passphrase problem or a corruption problem), a “direct restore” (possibly the next thing to try, however I still hope you can first get an individual file decrypted with one of the suggested methods), or several other more exotic methods which I’ll hold off on pending a reply. However many files you downloaded, seeing a presumably issue-free download was a nice download test.

If you can confirm downloads seemed to work well, and can also confirm Restore from configuration files went as I proposed earlier, then maybe the direct restore won’t add much because the signs are the download part is working, and the passphrase part is mostly working – except not on two specific troubled files (so far as has been found with what’s been tried). I’d like to know lengths, and manual decrypt issues. Further clues as to whether there’s actually file damage or something else will help guide the next steps…

There’s enough conflicting information around that more info will probably always help. Obviously this isn’t supposed to be so hard. Is the primary recovery need right now that Access database, or are there more?