FTP "Test Connection" Fail When Folder Has Many Files

bernarddt · February 14, 2023, 3:38pm

Getting this strange error. When I edit my Backup Config, under Destination, there is a “Test Connection” button. When I click this button the test fails with “FTP Error 425, Can't open Data connection”. When I point it to another folder on the FTP Server (same login) with fewer files (say < 1000), the test is successful.

The destination folder is the original folder on the FTP server that Duplicati backup to for just over a year, so the file count is 1500+. I’ve tried a few folders and noticed that any folder with more than 1000 files fails this “Test” action.

I’ve also tried the same folder on the FileZilla client, and it can open the folder. The FileZilla Server does show me that the connection was aborted by Duplicati (“425 Error while transfering data: ECONNABORTED - Connection aborted”).

Why would a high file count in the destination folders cause this error? It also causes problems with the backup, that are successful, but it still errors at the last minute.

Duplicati - 2.0.6.3_beta_2021-06-17
Running on Windows Server 2016, Using FileZilla Server as the destination (FileZilla Server 1.4.1)

The Duplicati logs shows the following:

Feb 14, 2023 5:14 PM: Request for http://localhost:8200/api/v1/remoteoperation/test gave error
System.Net.WebException: The remote server returned an error: (425) Can't open data connection.
   at System.Net.FtpWebRequest.DataStreamClosed(CloseExState closeState)
   at System.Net.FtpDataStream.System.Net.ICloseEx.CloseEx(CloseExState closeState)
   at System.Net.FtpDataStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at Duplicati.Library.Utility.OverrideableStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at System.IO.StreamReader.Dispose(Boolean disposing)
   at System.IO.TextReader.Dispose()
   at Duplicati.Library.Backend.FTP.<List>d__18.<>m__Finally1()
   at Duplicati.Library.Backend.FTP.<List>d__18.System.IDisposable.Dispose()
   at Duplicati.Library.Interface.BackendExtensions.TestList(IBackend backend)
   at Duplicati.Server.WebServer.RESTMethods.RemoteOperation.TestConnection(String url, RequestInfo info)
   at Duplicati.Server.WebServer.RESTHandler.DoProcess(RequestInfo info, String method, String module, String key)
Feb 14, 2023 5:14 PM: Reporting error gave error
System.ObjectDisposedException: Cannot write to a closed TextWriter.
   at System.IO.__Error.WriterClosed()
   at System.IO.StreamWriter.Flush(Boolean flushStream, Boolean flushEncoder)
   at Duplicati.Server.WebServer.RESTHandler.DoProcess(RequestInfo info, String method, String module, String key)

Then the backup log is as follows:

System.AggregateException: One or more errors occurred. ---> System.AggregateException: The remote server returned an error: (425) Can't open data connection. ---> System.Net.WebException: The remote server returned an error: (425) Can't open data connection.
   at CoCoL.AutomationExtensions.<RunTask>d__10`1.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.BackupHandler.<FlushBackend>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.BackupHandler.<RunAsync>d__20.MoveNext()
   --- End of inner exception stack trace ---
   at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext()
   --- End of inner exception stack trace ---
   at CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task)
   at Duplicati.Library.Main.Controller.<>c__DisplayClass14_0.<Backup>b__0(BackupResults result)
   at Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action`1 method)
   at Duplicati.Library.Main.Controller.Backup(String[] inputsources, IFilter filter)
   at Duplicati.Server.Runner.Run(IRunnerData data, Boolean fromQueue)
---> (Inner Exception #0) System.AggregateException: The remote server returned an error: (425) Can't open data connection. ---> System.Net.WebException: The remote server returned an error: (425) Can't open data connection.
   at CoCoL.AutomationExtensions.<RunTask>d__10`1.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.BackupHandler.<FlushBackend>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.BackupHandler.<RunAsync>d__20.MoveNext()
   --- End of inner exception stack trace ---
   at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext()
---> (Inner Exception #0) System.Net.WebException: The remote server returned an error: (425) Can't open data connection.
   at CoCoL.AutomationExtensions.<RunTask>d__10`1.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.BackupHandler.<FlushBackend>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.BackupHandler.<RunAsync>d__20.MoveNext()<---

---> (Inner Exception #1) System.AggregateException: One or more errors occurred. ---> System.Net.WebException: The remote server returned an error: (425) Can't open data connection.
   at CoCoL.AutomationExtensions.<RunTask>d__10`1.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.BackupHandler.<FlushBackend>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.BackupHandler.<RunAsync>d__20.MoveNext()
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.Net.WebException: The remote server returned an error: (425) Can't open data connection.
   at CoCoL.AutomationExtensions.<RunTask>d__10`1.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.BackupHandler.<FlushBackend>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.BackupHandler.<RunAsync>d__20.MoveNext()<---
<---
<---

Edit: Ok I’ve now tested a bit with the file count, it starts failing exactly at 600 files, so 601 files fail, and 600 files does not fail.

Edit 2: I’ve now used the “FTP (Alternative)” and this one does not have this problem. I was using the “FTP” option.

ts678 · February 14, 2023, 9:08pm

That’s good to hear because I think the FTP option is Microsoft .NET Framework.
There’s not too much that we can do about that, especially since it’s obsolescent.

I happen to have a folder with 10 million empty files in it, so can get a similar end.
Note my FileZilla server is very old, so maybe puts up with the reset more quietly.
I managed to get 2961 files listed in one Wireshark TCP reassembly test. An end:

(000010)2/14/2023 15:17:18 PM - duplicati (127.0.0.1)> PASV
(000010)2/14/2023 15:17:18 PM - duplicati (127.0.0.1)> 227 Entering Passive Mode (127,0,0,1,215,188)
(000010)2/14/2023 15:17:18 PM - duplicati (127.0.0.1)> LIST
(000010)2/14/2023 15:17:50 PM - duplicati (127.0.0.1)> 150 Opening data channel for directory listing of "/emptyfiles"
(000010)2/14/2023 15:17:50 PM - duplicati (127.0.0.1)> 426 Connection closed; aborted transfer of "/emptyfiles"
(000010)2/14/2023 15:17:50 PM - duplicati (127.0.0.1)> disconnected.

“215,188” is server announcing that it’s waiting for its client on port 55228. Network:

1274	2023-02-14 15:17:50.706213	localhost-duplicati	localhost-duplicati	FTP-DATA	16365	FTP Data: 16321 bytes (PASV) (LIST)
1275	2023-02-14 15:17:50.706233	localhost-duplicati	localhost-duplicati	TCP	44	58098 → 55228 [ACK] Seq=1 Ack=138737 Win=2562560 Len=0
1276	2023-02-14 15:17:50.706249	localhost-duplicati	localhost-duplicati	TCP	44	58098 → 55228 [RST, ACK] Seq=1 Ack=138737 Win=0 Len=0
1277	2023-02-14 15:17:50.706251	localhost-duplicati	localhost-duplicati	FTP-DATA	32695	FTP Data: 32651 bytes (PASV) (LIST)
1278	2023-02-14 15:17:50.706311	localhost-duplicati	localhost-duplicati	TCP	44	58098 → 55228 [RST] Seq=1 Win=0 Len=0

EDIT:

Your Duplicati log at 5:14 doesn’t go with the FileZilla log at 5:38 but the latter is a very different timing than my failure which took about 32 seconds. Yours failed the same second as the LIST request which seems even stranger than my slow failure. I did look for short timeouts for mine, but haven’t found one.

EDIT 2:

Actually, my 32 second delay is possibly preparation time of a big file listing 10 million items, but I don’t have the capture any more to see exactly when the download began, so all I know now is how it ended.

EDIT 3:

I tried a more reasonable sized folder of 3116 files, and got 1690 before the reset, but what’s odd is that
Duplicati.CommandLine.BackendTool.exe can handle a list of a large folder. Redirecting to a file, I get
3116 files (plus a header line) for that folder, and 19580 files for a larger file. This is all from ftp: not aftp:

This is getting beyond my debug ability, and developers are scarce. Some code citations are in the post
FTP vs FTP (Alternative) but that’s mostly directed at the Test connection button. Backup may differ.