Backup failing: "Path cannot be null" and "TLS warning: SSL3 alert write: fatal: bad record mac"

solf · February 24, 2020, 6:40pm

I’ve been running Duplicati - 2.0.5.1_beta_2020-01-18 since ~whenever it has been released and been on previous beta before (more than a year I think).

Last week one of my big backups started failing.

It started with “Found 1 remote files that are not recorded in local storage, please run repair”.

I did run repair as prompted and after that it never worked properly again.

What appears to be happening – it’s either the repeat of the “Found 1 remote files that are not recorded in local storage, please run repair” problem or, after a repair, it goes something like this:

Storage is FTP with SSL on local network, server is Windows 7 running Filezilla server
Backup is running
It fails to properly transfer one of the files with "System.Net.Sockets.SocketException: An established connection was aborted by the software in your host machine
"
– Checking out Filezilla logs reveals this error: “Data connection TLS warning: SSL3 alert write: fatal: bad record mac”
There’s what looks like a retry for the file under another name and it typically succeeds.
However later on the backup encounters “System.ArgumentNullException: Path cannot be null.” on another file; it looks like it is then retried 5 times under different names but never succeeds and backup dies

I’ll attach the relevant duplicati log at the end.

Any suggestions what should I try? I’ve read that full index rebuild may take days and given the nature of this issue it seems like it might not fix anything?

Thanks!

P.S. Timestamps are correct, backup does take forever (it takes very long under ‘normal’ circumstances and during the day I run duplicati with low cpu/io priority as well)

Log file is too big for the post, so it’s attached as zip:
dup-log.zip (7.3 KB)

Most relevant log sections:

2020-02-24 13:52:49 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-ia869d67054c24dd9a073856c903b2f94.dindex.zip.aes ()
2020-02-24 13:52:49 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-ia869d67054c24dd9a073856c903b2f94.dindex.zip.aes ()
2020-02-24 13:52:49 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-idc8b6aaaa58349af9bba024a83907605.dindex.zip.aes ()
2020-02-24 13:52:49 -04 - [Information-Duplicati.Library.Main.BackendManager-RenameRemoteTargetFile]: Renaming "duplicati-ia869d67054c24dd9a073856c903b2f94.dindex.zip.aes" to "duplicati-idc8b6aaaa58349af9bba024a83907605.dindex.zip.aes"
2020-02-24 13:52:59 -04 - [Retry-Duplicati.Library.Main.BackendManager-RetryPut]: Operation Put with file duplicati-idc8b6aaaa58349af9bba024a83907605.dindex.zip.aes attempt 5 of 5 failed with message: Path cannot be null.
Parameter name: path
System.ArgumentNullException: Path cannot be null.
Parameter name: path
   at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share)
   at Duplicati.Library.Encryption.EncryptionBase.Encrypt(String inputfile, String outputfile)
   at Duplicati.Library.Main.BackendManager.FileEntryItem.Encrypt(IEncryption encryption, IBackendWriter stat)
   at Duplicati.Library.Main.BackendManager.DoPut(FileEntryItem item)
   at Duplicati.Library.Main.BackendManager.ThreadRun()
2020-02-24 13:52:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Failed: duplicati-idc8b6aaaa58349af9bba024a83907605.dindex.zip.aes ()
2020-02-24 13:52:59 -04 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
System.ArgumentNullException: Path cannot be null.
Parameter name: path
   at Duplicati.Library.Main.BackendManager.WaitForEmpty(LocalDatabase db, IDbTransaction transation)
   at Duplicati.Library.Main.Operation.CompactHandler.DoDelete(LocalDeleteDatabase db, BackendManager backend, IEnumerable`1 deleteableVolumes, IDbTransaction& transaction)
   at Duplicati.Library.Main.Operation.CompactHandler.DoCompact(LocalDeleteDatabase db, Boolean hasVerifiedBackend, IDbTransaction& transaction, BackendManager sharedBackend)
   at Duplicati.Library.Main.Operation.DeleteHandler.DoRun(LocalDeleteDatabase db, IDbTransaction& transaction, Boolean hasVerifiedBacked, Boolean forceCompact, BackendManager sharedManager)
   at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired(BackendManager backend, Int64 lastVolumeSize)
   at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext()

and also:

2020-02-24 12:54:58 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bdc1300ae3a144f0e85e3c575c031a43d.dblock.zip.aes (249.97 MB)
2020-02-24 12:56:07 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bd96bb4144694462da4660a79c02051f5.dblock.zip.aes (14.64 MB)
2020-02-24 12:56:51 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-bdc1300ae3a144f0e85e3c575c031a43d.dblock.zip.aes attempt 1 of 5 failed with message: Unable to write data to the transport connection: An established connection was aborted by the software in your host machine.
System.IO.IOException: Unable to write data to the transport connection: An established connection was aborted by the software in your host machine. ---> System.Net.Sockets.SocketException: An established connection was aborted by the software in your host machine
   at System.Net.Sockets.Socket.BeginSend(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags, AsyncCallback callback, Object state)
   at System.Net.Sockets.NetworkStream.BeginWrite(Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Object state)
   --- End of inner exception stack trace ---
   at System.Net.Security._SslStream.EndWrite(IAsyncResult asyncResult)
   at System.Net.TlsStream.EndWrite(IAsyncResult asyncResult)
   at System.Net.FtpDataStream.EndWrite(IAsyncResult asyncResult)
   at System.IO.Stream.<>c.<BeginEndWriteAsync>b__53_1(Stream stream, IAsyncResult asyncResult)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncTrimPromise`1.Complete(TInstance thisRef, Func`3 endMethod, IAsyncResult asyncResult, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Utility.Utility.<CopyStreamAsync>d__11.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Backend.FTP.<PutAsync>d__19.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Main.Operation.Backup.BackendUploader.<DoPut>d__21.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Main.Operation.Backup.BackendUploader.<>c__DisplayClass17_0.<<UploadFileAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Duplicati.Library.Main.Operation.Backup.BackendUploader.<DoWithRetry>d__18.MoveNext()

Bobo · February 24, 2020, 11:21pm

Look at here. Similar error path cannot be null.
https://www.gitmemory.com/ts678
Also, is there any error messages on Filezilla server? Any logs?

solf · February 24, 2020, 11:52pm

Yeah, I’ve seen the existing ticket for ‘path cannot be null’ (sorry forgot to find/link to it) – missing dindex Repair fails -- 2.0.4.31 and up regression · Issue #4046 · duplicati/duplicati · GitHub

However that one specifically says that it only happens with un-encrypted backups. Mine is encrypted.

Re: Filezilla – as I mentioned in OP, there’s an error in Filezilla which corresponds to “System.Net.Sockets.SocketException: An established connection was aborted by the software in your host machine” and that is this: “Data connection TLS warning: SSL3 alert write: fatal: bad record mac”

I’ve googled ‘bad record mac’ and it appears to be generic error meaning that stream isn’t properly encrypted.

drwtsn32 · February 25, 2020, 3:14am

Is this the only backup you have going to the filezilla server? I’m curious if any other backups are working or if all are affected. If this is the only one can you set up a small second backup as a test to see if it has the same issue?

solf · February 25, 2020, 3:46am

Not the only one, I have a couple more (they back up to exactly the same Filezilla server).

It also worked fine for quite some time, so it’s probably not trivial to reproduce.

solf · February 27, 2020, 2:25pm

So any suggestions how do I go about fixing this backup?

Should I also open the bug ticket?

drwtsn32 · February 27, 2020, 3:17pm

It’s unclear to me if this is a Duplicati bug or something else. Did you create a self-signed certificate for Filezilla? If so was the Duplicati job configured to trust the cert’s hash?

Here’s what the setting looks like, you can set it on page 2 of the backup config:

solf · February 27, 2020, 3:43pm

It would be very strange if this weren’t a Duplicati bug…

The very same setup worked fine for over a year with previous Duplicati version. It also worked for > a month with new Duplicati version – until it broke last week for whatever reason.

If you check the attached log – it clearly can upload files and interact with file lists etc. on Filezilla just fine.

What appears to be happening:

at some point it fails to upload one file with an apparent encryption error (for whatever reason)
there’s a retry for that file and it appears to succeed (under a different name) with ‘Put - Completed:’
and only then, for whatever other reason, it goes bonkers repeatedly with repeated ‘Path cannot be null’ errors (for an entirely different file!) until it finally gives up

I mean… it’s possible, of course, that this isn’t a Duplicati issue, but I have difficult time imagining how it might be. ‘Path cannot be null’ seems to indicate that Duplicati invokes some system function with invalid arguments, which does seem to be a Duplicati issue (even if it is preceded by some other issue such as network or whatever failure).

To answer your question specifically – yes, it’s self-signed; yes, Duplicati is configured to trust it, otherwise it wouldn’t have worked for over a year.

drwtsn32 · February 27, 2020, 7:05pm

It may be a Duplicati bug, what I meant was that I’m not certain. It would be nice if we could figure out why only one backup is giving you this issue and not your other machines. Very odd…

solf · February 27, 2020, 10:11pm

Well, this backup seemed fine as well ~a week ago.

So it seems reasonable to assume that something happened with the backup state making it corrupted somehow.

Is there anything I can do to try to help debug it? Should I enable more detailed logging in Duplicati and try again?

drwtsn32 · February 28, 2020, 1:41am

I don’t think it is a corrupt backup issue. Your error is about a TLS connection issue right… So seems like a communication problem with the back end.

If a backup file is corrupt it would give you a different type of error message.

I wish I had another idea for you. Maybe someone else can think of something…

drwtsn32 · February 28, 2020, 2:08pm

By the way…

This sounds like Duplicati not properly handling the deeper level exception, which is that the network connection was terminated. I don’t think the “Path cannot be null” is the root issue.

If you only have one backup job on the machine that is giving you trouble, can you try setting up a simple second backup job just for testing purposes? (I know you said you have other backups on other machines working properly…) See if the new test job can back up a smaller amount of data successfully, or if it also gets the same TLS error.

solf · February 28, 2020, 2:37pm

I am not sure what are you asking for here? I already have backups on the same source machine that backup to the same destination (Filezilla) with SSL enabled, using the same login etc. etc. They work fine so far.

But moreover – yesterday I’ve changed log level for the job that kept failing – just to see if anything useful shows up in the log. Well, nothing useful showed up (guess verbose wasn’t enough).

BUT – the backup did complete successfully this time:

It still failed with an apparent TSL error “Data connection TLS warning: SSL3 alert write: fatal: bad record mac” (same as before)
It still went for a retry and apparently succeeded on retry (same as before)
However this was not followed by any “Path cannot be null” errors and the backup finished fine.

To me it looks like these are likely two separate issues – perhaps related, but separate.

One is that Duplicati possibly violates TLS sometimes.

Second is that it can fatally fail with “Path cannot be null” for whatever reason.

drwtsn32 · February 28, 2020, 3:42pm

Oh, ok… I wasn’t clear on that. So yeah it seems to be isolated to just one backup job then, very interesting.

Can you elaborate? The job still completed “successfully” as in you have the green check mark if you check the backup log history? But this TLS error still appeared in the logs? If so maybe the TLS error is non-fatal and is more of a distraction as to the root cause.

Is it possible you only spotted the TLS error message because the backup was failing for other reasons? In that case maybe other backup jobs show the non-fatal TLS error in the logs as well?

Would be interesting to find out…

solf · February 28, 2020, 4:11pm

Yes

Yes. As I wrote in OP – as per logs it seems when TLS error happens, there’s a subsequent successful retry under a different name (i.e. file is still uploaded to the backend).

However it is highly suspicious that this one specific backup started having TLS failure every time since last week.

It is, however, an order of magnitude bigger than two other backups that use the same (Filezilla) destination. Possibly relevant.

Yes. Unfortunately I’ve deleted logs before 02 Feb.

Checking the remaining log – TLS error certainly wasn’t a regular occurrence until last week’s failure. There might have been one case before (it’s hard to say since the error on Duplicati’s side is generic “System.Net.Sockets.SocketException: An established connection was aborted by the software in your host machine” which could happen for variety of reasons).

I don’t seem to have old Filezilla logs, so can’t check there.

ts678 · February 28, 2020, 5:13pm

What is the client OS, and is client Ethernet connected or something else (e.g. wireless)?
Filezilla Server’s error message sounds like below was sent or received – not sure which:

The Transport Layer Security (TLS) Protocol Version 1.3

6.2.  Error Alerts
...
   bad_record_mac:  This alert is returned if a record is received which
      cannot be deprotected.  Because AEAD algorithms combine decryption
      and verification, and also to avoid side-channel attacks, this
      alert is used for all deprotection failures.  This alert should
      never be observed in communication between proper implementations,
      except when messages were corrupted in the network.

Please check networking, watch for slowness, consider reseating/reconnecting/restarting, etc.

This would not be a Duplicati bug because it doesn’t drive TLS. It uses Windows on Windows.
On Linux, mono does TLS duties. Filezilla Server end at one time used GnuTLS lib for its TLS.

From your end, examining with Wireshark might be a good step. Alerts should be visible there.
Although the error sounds like an alert was involved, you can also see unexpected closes, etc.
Although it may be necessary to watch both ends, starting at server seeing issue may be best.

The Duplicati log at at least retry level will probably show retry at same time as server warns.
That would give the timestamp to go looking at network to see how it looked at the lower level.
Posting screenshots or text versions may help, although it may reveal a little bit of information.

solf · March 5, 2020, 11:26pm

So I still seem to get TLS errors sometimes, however it doesn’t lead to backup failure anymore.

I’ve looked into Filezilla Server settings and it looks like there’s no way to increase level of logging, so I’m stuck on that end.

Using Wireshark or other packet software requires expertise I don’t have – particularly given that there are gigabytes of data being transferred and TLS failures happen only sometimes (last one I found in Duplicati logs is from two days ago).

So I’m more or less stuck in terms of trying to figure out what’s going on with TLS. The connection to server is wireless on one end, however I do not remember observing any communication failures otherwise – particularly not on a frequent basis as seemed to be the case with Duplicati ~last week when every time the particular backup set would run into TLS failure (and only that set, not other sets).

I’m open to suggestions if there are any.

ts678 · March 6, 2020, 1:03am

Another somewhat challenging idea is to install rclone to use its FTP over TLS to see how it does.
Getting ‘bad record MAC’ on copies from Drive suggests that it does its own TLS with Go libraries.
Duplicati configuration would use the Rclone storage type, basically starting rclone to do transfers.
This will probably lose some of the usual transfer features, and I’m not sure how speed compares.

Another option would be to test different PC networking equipment even if it means a USB plug-in.
EDIT: For example, low-end WiFi USB adapters are under 10 U.S. Dollars. I’m on an adapter now.

solf · March 29, 2020, 4:59pm

This has started happening again – the same backup started failing in the same way.

Since I had no ideas as to how to debug it further without the major effort, I took the ‘easy way out’ and just disabled TLS requirement on the Fileziila side and removed SSL checkbox in Duplicati connection settings.

This has resolved the problem immediately (at least in so far as backups are not failing anymore).

I probably should try doing a full restore at some point to see if the backup is actually functional. I’m just reluctant to do it so far as I expect it’ll take ‘forever’.

aestetix · May 5, 2020, 1:34pm

I am having a similar issue, maybe the same thing.

I get the error “Path cannot be null. Parameter name: path”. Backup is encrypted, remote on Jottacloud.

When I look at the logs everything is green. I can’t see any errors or warnings at all. I don’t know where the error is coming from.

I am going to run a full test now, fortunately it’s not too big.

Edit: my guess is that this is to do with a locked file.

Edit 2: Verify command reported

Listing remote folder …
Extra unknown file: duplicati-[redacted].dblock.zip.aes
Missing file: duplicati-[redacted].dindex.zip.aes
Missing file: duplicati-[redacted].dindex.zip.aes
Missing file: duplicati-[redacted].dindex.zip.aes
Found 1 remote files that are not recorded in local storage, please run repair

ErrorID: ExtraRemoteFiles
Found 1 remote files that are not recorded in local storage, please run repair
Return code: 100

Will repair…