Verifying files in Backblaze B2 fails with "SecureChannelFailure (Authentication failed, see inner exception.)"

patrick96 · January 17, 2021, 4:37pm

I am trying to get Duplicati to upload to Backblaze B2 for the first time. The upload seems fine and files do appear inside the bucket, but duplicati produces three errors in the “Verify Files” phase:

2021-01-17 17:08:15 +01 - [Error-Duplicati.Library.Main.Operation.TestHandler-RemoteFileProcessingFailed]: Failed to process file duplicati-20210117T155036Z.dlist.zip.aes
2021-01-17 17:09:02 +01 - [Error-Duplicati.Library.Main.Operation.TestHandler-RemoteFileProcessingFailed]: Failed to process file duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes
2021-01-17 17:09:49 +01 - [Error-Duplicati.Library.Main.Operation.TestHandler-RemoteFileProcessingFailed]: Failed to process file duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes

This happens when running a backup (in the “Verify files” phase), but also when just running “Verify files” from the UI.

I am running duplicati 2.0.5.111_canary_2020-09-26 on mono 6.12.0 as root.

As advised in other support support threads, I looked at the live log. Here are all the messages in the live log of a single verify operation with the log level set to verbose:

Jan 17, 2021 5:09 PM: The operation Test has completed
Jan 17, 2021 5:09 PM: Failed to process file duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes
Jan 17, 2021 5:09 PM: Backend event: Get - Failed: duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes (49.94 MB)
Jan 17, 2021 5:09 PM: Operation Get with file duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes attempt 5 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:09 PM: Backend event: Get - Started: duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes (49.94 MB)
Jan 17, 2021 5:09 PM: Backend event: Get - Retrying: duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes (49.94 MB)
Jan 17, 2021 5:09 PM: Operation Get with file duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes attempt 4 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:09 PM: Backend event: Get - Started: duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes (49.94 MB)
Jan 17, 2021 5:09 PM: Backend event: Get - Retrying: duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes (49.94 MB)
Jan 17, 2021 5:09 PM: Operation Get with file duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes attempt 3 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:09 PM: Backend event: Get - Started: duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes (49.94 MB)
Jan 17, 2021 5:09 PM: Backend event: Get - Retrying: duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes (49.94 MB)
Jan 17, 2021 5:09 PM: Operation Get with file duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes attempt 2 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:09 PM: Backend event: Get - Started: duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes (49.94 MB)
Jan 17, 2021 5:09 PM: Backend event: Get - Retrying: duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes (49.94 MB)
Jan 17, 2021 5:09 PM: Operation Get with file duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes attempt 1 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:09 PM: Backend event: Get - Started: duplicati-b3d9e8fcc80274bb68fbc151731cd6cfe.dblock.zip.aes (49.94 MB)
Jan 17, 2021 5:09 PM: Failed to process file duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes
Jan 17, 2021 5:09 PM: Backend event: Get - Failed: duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes (29.12 KB)
Jan 17, 2021 5:09 PM: Operation Get with file duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes attempt 5 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:09 PM: Backend event: Get - Started: duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes (29.12 KB)
Jan 17, 2021 5:08 PM: Backend event: Get - Retrying: duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes (29.12 KB)
Jan 17, 2021 5:08 PM: Operation Get with file duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes attempt 4 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:08 PM: Backend event: Get - Started: duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes (29.12 KB)
Jan 17, 2021 5:08 PM: Backend event: Get - Retrying: duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes (29.12 KB)
Jan 17, 2021 5:08 PM: Operation Get with file duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes attempt 3 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:08 PM: Backend event: Get - Started: duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes (29.12 KB)
Jan 17, 2021 5:08 PM: Backend event: Get - Retrying: duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes (29.12 KB)
Jan 17, 2021 5:08 PM: Operation Get with file duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes attempt 2 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:08 PM: Backend event: Get - Started: duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes (29.12 KB)
Jan 17, 2021 5:08 PM: Backend event: Get - Retrying: duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes (29.12 KB)
Jan 17, 2021 5:08 PM: Operation Get with file duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes attempt 1 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:08 PM: Backend event: Get - Started: duplicati-i4d80468ec7f24d10a7710e34f91cc7d1.dindex.zip.aes (29.12 KB)
Jan 17, 2021 5:08 PM: Failed to process file duplicati-20210117T155036Z.dlist.zip.aes
Jan 17, 2021 5:08 PM: Backend event: Get - Failed: duplicati-20210117T155036Z.dlist.zip.aes (2.25 KB)
Jan 17, 2021 5:08 PM: Operation Get with file duplicati-20210117T155036Z.dlist.zip.aes attempt 5 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:08 PM: Backend event: Get - Started: duplicati-20210117T155036Z.dlist.zip.aes (2.25 KB)
Jan 17, 2021 5:08 PM: Backend event: Get - Retrying: duplicati-20210117T155036Z.dlist.zip.aes (2.25 KB)
Jan 17, 2021 5:08 PM: Operation Get with file duplicati-20210117T155036Z.dlist.zip.aes attempt 4 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:08 PM: Backend event: Get - Started: duplicati-20210117T155036Z.dlist.zip.aes (2.25 KB)
Jan 17, 2021 5:07 PM: Backend event: Get - Retrying: duplicati-20210117T155036Z.dlist.zip.aes (2.25 KB)
Jan 17, 2021 5:07 PM: Operation Get with file duplicati-20210117T155036Z.dlist.zip.aes attempt 3 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:07 PM: Backend event: Get - Started: duplicati-20210117T155036Z.dlist.zip.aes (2.25 KB)
Jan 17, 2021 5:07 PM: Backend event: Get - Retrying: duplicati-20210117T155036Z.dlist.zip.aes (2.25 KB)
Jan 17, 2021 5:07 PM: Operation Get with file duplicati-20210117T155036Z.dlist.zip.aes attempt 2 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:07 PM: Backend event: Get - Started: duplicati-20210117T155036Z.dlist.zip.aes (2.25 KB)
Jan 17, 2021 5:07 PM: Backend event: Get - Retrying: duplicati-20210117T155036Z.dlist.zip.aes (2.25 KB)
Jan 17, 2021 5:07 PM: Operation Get with file duplicati-20210117T155036Z.dlist.zip.aes attempt 1 of 5 failed with message: Error: SecureChannelFailure (Authentication failed, see inner exception.)
Jan 17, 2021 5:07 PM: Backend event: Get - Started: duplicati-20210117T155036Z.dlist.zip.aes (2.25 KB)
Jan 17, 2021 5:07 PM: Backend event: List - Completed: (36 bytes)
Jan 17, 2021 5:07 PM: Backend event: List - Started: ()
Jan 17, 2021 5:07 PM: The operation Test has started

Here is the JSON object attached to the first error:

{
    "ClassName": "System.Net.WebException",
    "Message": "Error: SecureChannelFailure (Authentication failed, see inner exception.)",
    "Data": null,
    "InnerException": {
        "ClassName": "System.Security.Authentication.AuthenticationException",
        "Message": "Authentication failed, see inner exception.",
        "Data": null,
        "InnerException": {
            "Message": "Ssl error:100003e8:SSL routines:OPENSSL_internal:SSLV3_ALERT_CLOSE_NOTIFY\n  at /build/mono/src/mono/external/boringssl/ssl/tls_record.c:462",
            "Data": {},
            "InnerException": null,
            "StackTrace": "  at Mono.Btls.MonoBtlsContext.ProcessHandshake () [0x00048] in <1af2426e91d1474d92e5d471c4ca8f95>:0 \n  at Mono.Net.Security.MobileAuthenticatedStream.ProcessHandshake (Mono.Net.Security.AsyncOperationStatus status, System.Boolean renegotiate) [0x000da] in <1af2426e91d1474d92e5d471c4ca8f95>:0 \n  at (wrapper remoting-invoke-with-check) Mono.Net.Security.MobileAuthenticatedStream.ProcessHandshake(Mono.Net.Security.AsyncOperationStatus,bool)\n  at Mono.Net.Security.AsyncHandshakeRequest.Run (Mono.Net.Security.AsyncOperationStatus status) [0x00006] in <1af2426e91d1474d92e5d471c4ca8f95>:0 \n  at Mono.Net.Security.AsyncProtocolRequest.ProcessOperation (System.Threading.CancellationToken cancellationToken) [0x000fc] in <1af2426e91d1474d92e5d471c4ca8f95>:0 ",
            "HelpLink": null,
            "Source": "System",
            "HResult": -2146233088
        },
        "HelpURL": null,
        "StackTraceString": "  at Mono.Net.Security.MobileAuthenticatedStream.ProcessAuthentication (System.Boolean runSynchronously, Mono.Net.Security.MonoSslAuthenticationOptions options, System.Threading.CancellationToken cancellationToken) [0x00262] in <1af2426e91d1474d92e5d471c4ca8f95>:0 \n  at Mono.Net.Security.MonoTlsStream.CreateStream (System.Net.WebConnectionTunnel tunnel, System.Threading.CancellationToken cancellationToken) [0x0016a] in <1af2426e91d1474d92e5d471c4ca8f95>:0 \n  at System.Net.WebConnection.CreateStream (System.Net.WebOperation operation, System.Boolean reused, System.Threading.CancellationToken cancellationToken) [0x001ba] in <1af2426e91d1474d92e5d471c4ca8f95>:0 ",
        "RemoteStackTraceString": null,
        "RemoteStackIndex": 0,
        "ExceptionMethod": null,
        "HResult": -2146233087,
        "Source": "mscorlib"
    },
    "HelpURL": null,
    "StackTraceString": "  at System.Net.WebConnection.CreateStream (System.Net.WebOperation operation, System.Boolean reused, System.Threading.CancellationToken cancellationToken) [0x0021a] in <1af2426e91d1474d92e5d471c4ca8f95>:0 \n  at System.Net.WebConnection.InitConnection (System.Net.WebOperation operation, System.Threading.CancellationToken cancellationToken) [0x00141] in <1af2426e91d1474d92e5d471c4ca8f95>:0 \n  at System.Net.WebOperation.Run () [0x0009a] in <1af2426e91d1474d92e5d471c4ca8f95>:0 \n  at System.Net.WebCompletionSource`1[T].WaitForCompletion () [0x00094] in <1af2426e91d1474d92e5d471c4ca8f95>:0 \n  at System.Net.HttpWebRequest.RunWithTimeoutWorker[T] (System.Threading.Tasks.Task`1[TResult] workerTask, System.Int32 timeout, System.Action abort, System.Func`1[TResult] aborted, System.Threading.CancellationTokenSource cts) [0x000f8] in <1af2426e91d1474d92e5d471c4ca8f95>:0 \n  at Duplicati.Library.Utility.AsyncHttpRequest+AsyncWrapper.GetResponseOrStream () [0x0004d] in <d08ee1948ceb4d19838c99ad6efa8ab7>:0 \n  at Duplicati.Library.Utility.AsyncHttpRequest.GetResponse () [0x00044] in <d08ee1948ceb4d19838c99ad6efa8ab7>:0 \n  at Duplicati.Library.Backend.Backblaze.B2.Get (System.String remotename, System.IO.Stream stream) [0x000e1] in <8de899d4da6c4b28b925e45ed4ae1022>:0 \n  at Duplicati.Library.Main.BackendManager.coreDoGetPiping (Duplicati.Library.Main.BackendManager+FileEntryItem item, Duplicati.Library.Interface.IEncryption useDecrypter, System.Int64& retDownloadSize, System.String& retHashcode) [0x00259] in <69351e729b034105bffb62d55f82ef1c>:0 \n  at Duplicati.Library.Main.BackendManager.DoGet (Duplicati.Library.Main.BackendManager+FileEntryItem item) [0x002ff] in <69351e729b034105bffb62d55f82ef1c>:0 \n  at Duplicati.Library.Main.BackendManager.ThreadRun () [0x000ff] in <69351e729b034105bffb62d55f82ef1c>:0 ",
    "RemoteStackTraceString": null,
    "RemoteStackIndex": 0,
    "ExceptionMethod": null,
    "HResult": -2146233079,
    "Source": "Duplicati.Library.Utility"
}

The json objects for the other errors look the same, if you also need them, please let me know.

I have not found any other topic with the same SSL error. For this run I enabled accept-any-ssl-certificate just to make sure this wasn’t the problem, but the issues occurs with and without that option.

For completeness, here is the bug report zip file I generated through the UI directly after the verify phase failed: bugreport.zip (1.8 MB)

Any help would be appreciated. Please let me know if I need to provide further information.

drwtsn32 · January 18, 2021, 4:30am

Welcome to the forum!

Very interesting that the backup phase works fine but only the verify phase fails. I would like to try and replicate your issue. I see you’re u sing Duplicati 2.0.5.111 and mono 6.12.0. What operating system is this?

patrick96 · January 18, 2021, 9:46am

Thanks for looking into this.

I am using an up-to-date ArchLinux system, I can give you more info if you need it, like a complete package list. But I was also able to reproduce the same error trying to back up a single file inside an Ubuntu 20.10 docker container (with duplicati 2.0.5.1). So I’m pretty sure this isn’t exclusive to my distro and can be replicated more or less easily in other places.

I started the docker container with

docker run -it ubuntu:20.10

To install duplicati I ran the following in the docker shell:

cd ~
unminize
apt install apt-transport-https sudo nano git-core python software-properties-common dirmngr mono-devel curl -y
curl -O https://updates.duplicati.com/beta/duplicati_2.0.5.1-1_all.deb
dpkg -i duplicati_2.0.5.1-1_all.deb
apt --fix-broken install

And for the actual backup, I was also able to just use the commandline:

touch /root/backup.txt
duplicati-cli backup "b2://<BUCKET_NAME>//duplicati/Test?auth-username=<KEY_ID>&auth-password=<APPLICATION_KEY>" /root/backup.txt --backup-name=Backblaze-Test --dbpath=/root/.config/Duplicati/abc.sqlite --compression-module=zip --dblock-size=50mb --encryption-module= --no-encryption=true

The mono version here was 6.8.0

drwtsn32 · January 18, 2021, 2:56pm

Great, thanks for your detailed instructions. I will look at reproducing your issue and report back.

drwtsn32 · January 18, 2021, 4:09pm

Puzzling. I set up a new Ubuntu Server 20.10 VM, installed mono-devel (from standard Ubuntu repo), and then installed duplicati 2.0.5.1. Created a new B2 bucket, application key, and was able to back up just fine. Verification phases passes the test too. Used your suggested command line to run duplicati-cli.

I did another backup (this time of /etc) and then I had two backups on the remote side, 6 files. Did a full verification of all files and it passed without issue.

The application key I created has full read/write access to the test bucket. Lifecycle settings set at default (although “keep only latest version” is better with Duplicati as it manages version history on its own). Object lock is disabled. How was your B2 bucket configured?

patrick96 · January 18, 2021, 8:10pm

Very puzzling indeed. Thanks for trying to reproduce this. This confirms that the problem is on my end.

I did create a new bucket with the exact same settings as you mentioned and it still fails on the verification.

I have done some more digging and found that I can’t even download files if I access the backblaze API directly (through curl in my case). There I am getting the following message:

curl: (35) error:140943E8:SSL routines:ssl3_read_bytes:reason(1000)

This confirms that this is not a duplicati issue.

I will try to solve this on my own and contact backblaze support if need be. I’ll also report back here if I manage to solve this issue.

Thank you very much for taking the time to debug this with me, I appreciate it

patrick96 · January 19, 2021, 1:16am

I finally figured it out. It was a DNS issue

For whatever reason my router resolved the backblaze download hostname to an IP address that is no longer in use.

I have now switched over to 8.8.8.8 as my DNS server and everything works fine. I expect this invalid value disappears from my router’s cache at some point. Though dig shows a TTL of 0 for the entry, so it should have been removed already.

drwtsn32 · January 19, 2021, 5:04am

Thanks for following up! Glad you figured it out!

Toinne · February 11, 2022, 8:29pm

Just wanted to add that I had the same issue with backblaze and pfblockerng on pfsense flagging the backblaze ip as phishing and thus blocking it on DNS.

Adding the following domains to the pfblockng whitelist solved my issue.

.backblazeb2.com # Backblaze whitelist for duplicati
.backblaze.com # Backblaze whitelist for duplicati

ts678 · February 13, 2022, 7:16pm

Welcome to the forum @Toinne and thanks for the input.

Recent Outages: Why We Accelerated Registry Changes describes a similar-but-worse registrar issue.
Duplicati’s other storage providers seem to suffer from this less. Some are major names. Others aren’t.