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 2.0.7.2 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 (tim.kosse@filezilla-project.org)
(000002)7/13/2023 9:26:49 AM - (not logged in) (::1)> 220 Please visit https://filezilla-project.org/
(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:
–asynchronous-concurrent-upload-limit=1

Client info:
2.0.7.1_beta_2023-05-25 (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:
MLSD /

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 duplicati-bd7c802b8fac14429add06283a2fbadbc.dblock.zip
(000030)7/19/2023 10:42:31 AM - duplicati (::1)> 150 Opening data channel for file download from server of "/duplicati-bd7c802b8fac14429add06283a2fbadbc.dblock.zip"
(000030)7/19/2023 10:42:31 AM - duplicati (::1)> 226 Successfully transferred "/duplicati-bd7c802b8fac14429add06283a2fbadbc.dblock.zip"
(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:

MLSD /
150 Opening data channel for directory listing of "/"
226 Successfully transferred "/"
QUIT
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

Thinking out loud it seems. - But I also just figured out some technical aspects which might affect what it seems like in the logs.

Again, this isn’t serious. And it’s just very minor thing, compared to something like restore completely failing. But I did see this again, and it happens at times. Session is left open, even when Duplicati is ready and exits. - Windows binary, run from CLI, and compacting stuff.

I did run a few tests with new version and this still happens, but it might be actually that it happens only when running compaction.

2024-01-02T06:58:44.610Z << [FTP Session 2026 IP USER] 230 Login successful.
2024-01-02T06:58:44.642Z >> [FTP Session 2026 IP USER] FEAT
2024-01-02T06:58:44.642Z << [FTP Session 2026 IP USER] 211-Features:
2024-01-02T06:58:44.642Z << [FTP Session 2026 IP USER] 211 End
2024-01-02T06:58:44.689Z >> [FTP Session 2026 IP USER] SYST
2024-01-02T06:58:44.689Z << [FTP Session 2026 IP USER] 215 UNIX emulated by FileZilla.
2024-01-02T06:58:44.704Z >> [FTP Session 2026 IP USER] TYPE I
2024-01-02T06:58:44.704Z << [FTP Session 2026 IP USER] 200 Type set to I
2024-01-02T06:58:44.720Z >> [FTP Session 2026 IP USER] SIZE duplicati-b6e88dbe954cb4aaa8321a981949f02fe.dblock.zip.aes
2024-01-02T06:58:44.720Z << [FTP Session 2026 IP USER] 213 33559821
2024-01-02T06:58:44.751Z >> [FTP Session 2026 IP USER] EPSV
2024-01-02T06:58:44.751Z << [FTP Session 2026 IP USER] 229 Entering Extended Passive Mode (|||21311|)
2024-01-02T06:58:44.939Z >> [FTP Session 2026 IP USER] RETR duplicati-b6e88dbe954cb4aaa8321a981949f02fe.dblock.zip.aes
2024-01-02T06:58:44.954Z << [FTP Session 2026 IP USER] 150 Starting data transfer.
2024-01-02T06:58:55.831Z << [FTP Session 2026 IP USER] 226 Operation successful
2024-01-02T07:58:55.840Z << [FTP Session 2026 IP USER] 421 Activity timeout.
2024-01-02T07:58:55.840Z !! [FTP Session 2026 IP USER] Control channel closed with error from source 0. Reason: ETIMEDOUT - Connection attempt timed out.

One connection is left lingering, even when Duplicati exists. But I hope the AFTP extra logging helps to pin this down.

But now when I really started to think about it. I’ll need to check the server keepalive (which was unconfigured = 2 hours, stateful firewall NAT timeout is 10 minutes (duh)). If it idles just long enough that NAT mapping dies, but there’s no keepalive traffic, and keepalive isn’t configured. It’s possible that Duplicati / client tires to close this connection but server doesn’t ever get that info, because session is dead on firewall level. - Duh!

I’ll need to recheck this on next major compaction run. Anyway, there’s usually one connection per backup job which seems to be quite persistent while the job is running. And that’s probably the one that got dropped by NAT. I might need to dig down the logs, is that connection reused at all.

I’ve also configured keepalive (what a n00b fail), to get around the keepalive issue. It also helps me to figure out if the connection is being used for anything at all after it’s first use. Or if it’s just forgotten open and closed when program terminates.

I have absolutely no idea if it is related to your problem, but for the record there is a problem I know in Duplicati AFTP backend, Get operations are done synchronously and assume that operations are terminated when the data is returned, while Ftp is a 2 ports exchange and the Get is only really finished when the status is returned on the control channel. So it can happen spuriously that Duplicati starts a new exchange straight away and misreads the status it gets, really the status for the previous Get operation, for the status of the current operation. This is a problem I did not have the energy to tackle for last release - but I was made aware of it by using the new logging feature (that’s why it is here).

This is minor issue again, technically quite irrelevant. But now I got what I wanted from logs:

||Line 286352: 2024-01-03T10:40:38.594Z << [FTP Session 116 IP USER] 230 Login successful.|
|---|---|
||Line 286353: 2024-01-03T10:40:38.641Z >> [FTP Session 116 IP USER] FEAT|
||Line 286354: 2024-01-03T10:40:38.641Z << [FTP Session 116 IP USER] 211-Features:|
||Line 286355: 2024-01-03T10:40:38.641Z << [FTP Session 116 IP USER] 211 End|
||Line 286358: 2024-01-03T10:40:38.704Z >> [FTP Session 116 IP USER] SYST|
||Line 286359: 2024-01-03T10:40:38.704Z << [FTP Session 116 IP USER] 215 UNIX emulated by FileZilla.|
||Line 286360: 2024-01-03T10:40:38.735Z >> [FTP Session 116 IP USER] PWD|
||Line 286361: 2024-01-03T10:40:38.735Z << [FTP Session 116 IP USER] 257 / is current directory.|
||Line 286362: 2024-01-03T10:40:38.766Z >> [FTP Session 116 IP USER] CWD /|
||Line 286363: 2024-01-03T10:40:38.766Z << [FTP Session 116 IP USER] 250 CWD command successful|
||Line 286364: 2024-01-03T10:40:38.797Z >> [FTP Session 116 IP USER] PWD|
||Line 286365: 2024-01-03T10:40:38.797Z << [FTP Session 116 IP USER] 257 / is current directory.|
||Line 286366: 2024-01-03T10:40:38.829Z >> [FTP Session 116 IP USER] TYPE I|
||Line 286367: 2024-01-03T10:40:38.829Z << [FTP Session 116 IP USER] 200 Type set to I|
||Line 286368: 2024-01-03T10:40:38.860Z >> [FTP Session 116 IP USER] EPSV|
||Line 286369: 2024-01-03T10:40:38.860Z << [FTP Session 116 IP USER] 229 Entering Extended Passive Mode (|||21276|)|
||Line 286370: 2024-01-03T10:40:38.907Z >> [FTP Session 116 IP USER] MLSD /|
||Line 286371: 2024-01-03T10:40:38.907Z << [FTP Session 116 IP USER] 150 Starting data transfer.|
||Line 286372: 2024-01-03T10:40:38.907Z << [FTP Session 116 IP USER] 226 Operation successful|
||Line 286762: 2024-01-03T10:47:58.925Z == [FTP Server] Session 116 ended gracefully.|

Note the session idling for over 7 minutes, before getting closed, without QUIT.

The very first session used to poll the directory, is left open (while Duplicati runs) and when process is completed, it’s closed.

The fact that it seemed to be open after Duplicati existing (on the server) was caused by the stateful firewall and lack of keep-alive. But when I check the TCP stack state on source server, I can see that the connection was closed when Duplicati exited. - That’s exactly as someone said in this thread, and it’s confirmed and true.

But, if the connection isn’t being used for anything after the initial lookup, why it’s left open at all? On the otherhand, it’s quite nice to see which servers are actively using Duplicati when there’s one session lingering from those servers / clients.

Summary, just thoughts. Can’t say if it’s right or wrong. There’s pros and cons. And compared to some other stuff, this is still very meaningless.