Problems after upgrade to 2.0.4.21

“aftp://” was the first focus. I spot-checked “ftp://” and found some oddities, but never the ASCII expansion.

Yes, that appears backwards from what was called for by Duplicati. Duplicati ships FluentFTP 21.0.0, and even though I can’t find signs of a FluentFTP fix since then, I see that it’s now up to 25.0.5 (haven’t tested).

Duplicati is now perhaps somewhat unusual because it uses both the low-level OpenRead() interface plus (since 2.0.4.16 changes) the high-level UploadAsync(). Previously it used OpenWrite(), i.e. no level mixing, however I would have thought (but haven’t proved) simple usage like BackendTool would avoid confusions.

Another quirk of FluentFTP is that it does a hidden second login to do the data transfer. Details are given at Duplicati does not close FTP connection correctly to backup backend #3230, where it made some trouble.

EnableThreadSafeDataConnections.is out of favor with the FluentFTP developer (who did add some fixes which possibly solve problems the original author used that setting to avoid)., It’s not clear Duplicati needs to set it to true, but I don’t understand backend threading well, including error handling and accident cases.

EDIT 1:

Here’s a more in-context view of the FTP sequences, including the hidden second login and the “TYPE A”:

“C:\ProgramData\Duplicati\duplicati-2.0.4.16_canary_2019-03-28\Duplicati.CommandLine.BackendTool” get “aftp://user:pass@127.0.0.1/ftp_test_1” “duplicati-20181205T223458Z.dlist.zip”

(000087)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> Connected on port 21, sending welcome message...
(000087)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> 220-FileZilla Server 0.9.60 beta
(000087)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> 220-written by Tim Kosse (tim.kosse@filezilla-project.org)
(000087)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> 220 Please visit https://filezilla-project.org/
(000087)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> USER user
(000087)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> 331 Password required for user
(000087)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> PASS ********
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 230 Logged on
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> FEAT
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 211-Features:
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)>  MDTM
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)>  REST STREAM
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)>  SIZE
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)>  MLST type*;size*;modify*;
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)>  MLSD
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)>  UTF8
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)>  CLNT
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)>  MFMT
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)>  EPSV
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)>  EPRT
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 211 End
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> OPTS UTF8 ON
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 202 UTF8 mode is always enabled. No need to send this command.
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> SYST
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 215 UNIX emulated by FileZilla
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> CWD /ftp_test_1
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 250 CWD successful. "/ftp_test_1" is current directory.
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> TYPE I
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 200 Type set to I
(000088)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> Connected on port 21, sending welcome message...
(000088)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> 220-FileZilla Server 0.9.60 beta
(000088)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> 220-written by Tim Kosse (tim.kosse@filezilla-project.org)
(000088)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> 220 Please visit https://filezilla-project.org/
(000088)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> USER user
(000088)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> 331 Password required for user
(000088)7/4/2019 17:49:26 PM - (not logged in) (127.0.0.1)> PASS ********
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 230 Logged on
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> OPTS UTF8 ON
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 202 UTF8 mode is always enabled. No need to send this command.
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> SYST
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 215 UNIX emulated by FileZilla
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> PWD
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 257 "/ftp_test_1" is current directory.
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> CWD /ftp_test_1
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 250 CWD successful. "/ftp_test_1" is current directory.
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> TYPE I
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 200 Type set to I
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> SIZE duplicati-20181205T223458Z.dlist.zip
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 213 522
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> TYPE A
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 200 Type set to A
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> EPSV
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 229 Entering Extended Passive Mode (|||64831|)
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> RETR duplicati-20181205T223458Z.dlist.zip
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 150 Opening data channel for file download from server of "/ftp_test_1/duplicati-20181205T223458Z.dlist.zip"
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 226 Successfully transferred "/ftp_test_1/duplicati-20181205T223458Z.dlist.zip"
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> QUIT
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> 221 Goodbye
(000087)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> disconnected.
(000088)7/4/2019 17:49:26 PM - duplicati (127.0.0.1)> disconnected.

I assume things are similar when going to Linux, but the FTP server there isn’t set up to log all the above. Please ask if you want a close look. I’m set up to tcpdump. That’s what got some data hex dumps earlier.

DownloadDataType Binary value ignored on ASCII-configured FTP servers #318 was fixed in 19.2.3, and Duplicati’s 21.0.0 shouldn’t have that issue, however I don’t know if there might be some similar issue left.

OpenRead and OpenWrite deprecated? #44 discussed what to do with them, given the newer interfaces.

What does EnableThreadSafeDataConnections do? says disabling it solved problems. Do we dare try it?