The very first FTP session on the very first run is left alive even if when the program exists

The initial session used to retrieve a file list from remote FTP backup repository, right when backup starts for the first time isn’t properly closed or reused. Or maybe there is some specific reason for that?

I’ll check logs if it’s ever used for anything. I think it’s not. And it’s left open until it times out from the server side. Even backup completion doesn’t close the connection when program terminates. Which is quite strange.

I did run another backup, confirmed. The first session initiated with FTP, isn’t reused or closed.

Yet that seems to be only the case, if the destination path is empty and backup starts from fresh. - It still gives a sloppy impression how the program operates with sessions. Just add the close somewhere. If there’s any data in the backup destination, and it’s not the first run. Then the session isn’t left hanging.

  • Thanks

I can’t reproduce this with FileZilla on localhost. The CreateFolder() method uses requests the same way as all others, and it does close the response. The FTP backend uses the .NET Framework FtpWebRequest which might be buggy. The alternate FTP backend uses a different library (although it seems creating the folder does not work with that one).

Do you mean "" as the destination path or a folder that does not exist yet? I tested a folder that does not exist.

Sure is. That’s an OS thing. What’s your OS, and can you find any connection leftovers on port 21?

and I used an empty destination path set up in GUI, then exported which I suspect is OP’s use case.

I’m testing with CLI on Canary on Windows. If one’s on Linux, the mono FTP might also differ.

My first connection as reported by Filezilla Server:

(000002)7/13/2023 9:26:49 AM - (not logged in) (::1)> Connected on port 21, sending welcome message...
(000002)7/13/2023 9:26:49 AM - (not logged in) (::1)> 220-FileZilla Server 0.9.60 beta
(000002)7/13/2023 9:26:49 AM - (not logged in) (::1)> 220-written by Tim Kosse (
(000002)7/13/2023 9:26:49 AM - (not logged in) (::1)> 220 Please visit
(000002)7/13/2023 9:26:49 AM - (not logged in) (::1)> USER duplicati
(000002)7/13/2023 9:26:49 AM - (not logged in) (::1)> 331 Password required for duplicati
(000002)7/13/2023 9:26:49 AM - (not logged in) (::1)> PASS ********
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> 230 Logged on
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> OPTS utf8 on
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> 202 UTF8 mode is always enabled. No need to send this command.
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> PWD
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> 257 "/" is current directory.
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> TYPE A
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> 200 Type set to A
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> EPSV
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> 229 Entering Extended Passive Mode (|||51955|)
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> LIST
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> 150 Opening data channel for directory listing of "/"
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> 226 Successfully transferred "/"
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> QUIT
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> 221 Goodbye
(000002)7/13/2023 9:26:49 AM - duplicati (::1)> disconnected.

Wireshark saw a close, although looking at several similar connections, it varied which end closed first.
Server must close in response to client QUIT. It did. If client didn’t as well, netstat would show leftovers.
RFC 793 details how close (or half-closed) works. Many lingering leftover names contain WAIT or ACK.

My first connection ended like this:

No.	Time	Source	Destination	Protocol	Length	Info
36	2023-07-13 09:33:04.302371	::1	::1	FTP	70	Request: QUIT
37	2023-07-13 09:33:04.302394	::1	::1	TCP	64	ftp(21) → 57342 [ACK] Seq=447 Ack=77 Win=2618880 Len=0
38	2023-07-13 09:33:04.302438	::1	::1	FTP	77	Response: 221 Goodbye
39	2023-07-13 09:33:04.302451	::1	::1	TCP	64	57342 → ftp(21) [ACK] Seq=77 Ack=460 Win=2618368 Len=0
40	2023-07-13 09:33:04.302474	::1	::1	TCP	64	ftp(21) → 57342 [FIN, ACK] Seq=460 Ack=77 Win=2618880 Len=0
41	2023-07-13 09:33:04.302486	::1	::1	TCP	64	57342 → ftp(21) [ACK] Seq=77 Ack=461 Win=2618368 Len=0
42	2023-07-13 09:33:04.303948	::1	::1	TCP	64	57342 → ftp(21) [FIN, ACK] Seq=77 Ack=461 Win=2618368 Len=0
43	2023-07-13 09:33:04.304000	::1	::1	TCP	64	ftp(21) → 57342 [ACK] Seq=461 Ack=78 Win=2618880 Len=0

Ok, let’s dig bit more details, because it’s summer and I’m not too busy.

During backup, I’ve configured Duplicati to use a single connection:

Client info: (Win)

Server info:
2023-07-14T20:41:18.162Z << [FTP Session # A.B.C.D] 220-FileZilla Server 1.6.7

Client logs in as normal, and enters command:

And after that, the session isn’t ever used again. The restriction of single connection isn’t followed, because rest of transfers create a new connection(s). Wouldn’t it make then sense to close this connection immediately after the MLSD results? Now it’s just left lingering?

Rest of STOR commands for iblock / dblock use a single session including the dindex. Then it’s closed. Then verify seems to use a new connection which is fine.

I’m just wondering why the first MLSD (ls) connection is left open, if it’s not reused. It would make sense to close it or reuse it.

With my configuration, where I’ve got many very long running backup sets. It was really easy to spot that there are lingering unused connections open to the server. Due to firewall configuration, I’ve got limited number of ports reserved for FTPS, yet this isn’t a real problem, because I’ve got one hour timeout configured for idle connections. Yet, now when I’ve realized that the connection is really useless, I could shorten the timeout to 15 minutes. It still should be short enough not to terminate the useful upload connections, where I do prefer keepalive connection instead of full reconnect.

For details, sure it’s the AFTP module, the FTPS module itself is way too broken with bad TLS handling.

When using FTPS - Ref: 2023-07-19T10:30:31.400Z [FTP Session # A.B.C.D test] GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.

Yet this doesn’t actually terminate the connection, but it still gives an error. I’ve had this problem with Windows FTPS earlier, and even fixed it (ie, broken exception handling) for Python FTPS to get it working. Ref: Sami Lehtinen - Python 3.2 MS FTPS/SSL/TLS lockup & fix

But to be honest. This really doesn’t matter, really absolutely meaningless issue, compared to the data corruption issues. It’s technically cosmetical error that two connections are being used, when one would be sufficient. I admit it, tidy people are annyoing, messy world works too. :wink:

Sure the lingering connection is actually closed when Duplicati finally exists, now when I tested with smaller sets. Most of my backups runs for several hours and because I have only 60 minutes idle timeout, I saw lots of timeout errors in logs. Which I assumed to be caused by left over sockets. But it seems that assumption wasn’t completely accurate. Now when I tested with minimal test setup, I found out that it’s just unnecessary open connection “while” the backup runs.

Yet, I’m not completely sure, if that conclusion is true either. Because I’m quite sure I’ve seen those connections lingering on the server even if the backup dlist is present after clean restart and verify won’t take that long. So there might be some situation which does cause the session to be left over even after the backup has completed. - From the session IDs I see that it’s the first session I’m talking about.

This only apply to upload of data (dblock) buffers, not to all operations for a given backup.

I think that what you see may be a bug nonetheless.
This I can reproduce and it seems to come during the PreBackupVerify call at the beginning of the backup process, this is doing a list of the files in the backend directory (in your case /) and it is just calling the List() function in the backend.
However the results are held in a local variable (tp) in the VerifyRemoteList function of the BackupHandler.cs module, but this variable is not explicitly freed when the function exits. That could be the reason the FTP session is only cleared when the backup end (and the whole process exits).

I admit that I will not lose sleep over the idea of having this bug in Duplicati though.

Edit: on second thought, the idea is basically correct but the problem is not is as simple as a forgotten free in VerifyRemoteList. It’s probably more than each uploaded file is run in its own task, while the prebackup verify is run in the main task.

I’m pretty confused by all the confusion, but FWIW on Wireshark using aftp (now that I know it’s used), testing with a small file, the initial MLST finished just fine when reassembled, but not so fine on Filezilla, where log started other actions before the QUIT after MLST. That seems to be after the backup finished which was about 4 seconds in my test, and probably long enough to time out in large backup described.

I did see my dblock and dindex STOR in the same connection, and now I’m wondering about interaction with asynchronous-concurrent-upload-limit at default setting of 4. Wouldn’t want to avoid concurrency…

When performing asynchronous uploads, the maximum number of concurrent uploads allowed.

You can actually see what I think is the QUIT from first MLST way down at the end of the Filezilla log as

(000030)7/19/2023 10:42:31 AM - duplicati (::1)> RETR
(000030)7/19/2023 10:42:31 AM - duplicati (::1)> 150 Opening data channel for file download from server of "/"
(000030)7/19/2023 10:42:31 AM - duplicati (::1)> 226 Successfully transferred "/"
(000030)7/19/2023 10:42:31 AM - duplicati (::1)> disconnected.
(000024)7/19/2023 10:42:32 AM - duplicati (::1)> QUIT
(000024)7/19/2023 10:42:32 AM - duplicati (::1)> 221 Goodbye
(000024)7/19/2023 10:42:32 AM - duplicati (::1)> disconnected.

When Wireshark reassembles the first connection, it all looks smooth, as one can’t see the exact timing:

150 Opening data channel for directory listing of "/"
226 Successfully transferred "/"
221 Goodbye

but looking at actual packets shows the gap (which in my case was 4 seconds idle, with no idle timeout)

No.	Time	Source	Destination	Protocol	Length	Info
38	2023-07-19 10:42:28.455569	::1	::1	FTP	98	Response: 226 Successfully transferred "/"
39	2023-07-19 10:42:28.455587	::1	::1	TCP	64	53536 → ftp(21) [ACK] Seq=80 Ack=570 Win=2618368 Len=0
368	2023-07-19 10:42:32.496707	::1	::1	FTP	70	Request: QUIT
369	2023-07-19 10:42:32.496767	::1	::1	TCP	64	ftp(21) → 53536 [ACK] Seq=570 Ack=86 Win=2618880 Len=0
370	2023-07-19 10:42:32.497020	::1	::1	FTP	77	Response: 221 Goodbye
371	2023-07-19 10:42:32.497067	::1	::1	TCP	64	53536 → ftp(21) [ACK] Seq=86 Ack=583 Win=2618368 Len=0
372	2023-07-19 10:42:32.497125	::1	::1	TCP	64	ftp(21) → 53536 [FIN, ACK] Seq=583 Ack=86 Win=2618880 Len=0
373	2023-07-19 10:42:32.497154	::1	::1	TCP	64	53536 → ftp(21) [ACK] Seq=86 Ack=584 Win=2618368 Len=0
374	2023-07-19 10:42:32.498676	::1	::1	TCP	64	53536 → ftp(21) [FIN, ACK] Seq=86 Ack=584 Win=2618368 Len=0
375	2023-07-19 10:42:32.498742	::1	::1	TCP	64	ftp(21) → 53536 [ACK] Seq=584 Ack=87 Win=2618880 Len=0