Thanks for the thanks, and the above is why I suspect some unknown fraction of current “FTP (Alternative)” users may have trouble if it breaks, plus I personally prefer breaking as little as possible as things progress.
I think that’s a worthy idea. FTP from Windows 10 64bit simply doesn’t work yet, right? was a recent round of tag-team FTP bashing, and that doesn’t even get deep in the plain-text perils of using it over the Internet.
Latest tech news on the debug effort is that FluentFTP/FluentFTP.Examples/OpenRead.cs shows the bug after I add conn.EnableThreadSafeDataConnections = true;, and does OK if I don’t do that. Good/bad:
(000289)7/8/2019 10:34:59 AM - (not logged in) (127.0.0.1)> Connected on port 21, sending welcome message...
(000289)7/8/2019 10:34:59 AM - (not logged in) (127.0.0.1)> 220-FileZilla Server 0.9.60 beta
(000289)7/8/2019 10:34:59 AM - (not logged in) (127.0.0.1)> 220-written by Tim Kosse (tim.kosse@filezilla-project.org)
(000289)7/8/2019 10:34:59 AM - (not logged in) (127.0.0.1)> 220 Please visit https://filezilla-project.org/
(000289)7/8/2019 10:34:59 AM - (not logged in) (127.0.0.1)> USER duplicati
(000289)7/8/2019 10:34:59 AM - (not logged in) (127.0.0.1)> 331 Password required for duplicati
(000289)7/8/2019 10:34:59 AM - (not logged in) (127.0.0.1)> PASS ********
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> 230 Logged on
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> FEAT
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> 211-Features:
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> MDTM
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> REST STREAM
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> SIZE
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> MLST type*;size*;modify*;
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> MLSD
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> UTF8
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> CLNT
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> MFMT
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> EPSV
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> EPRT
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> 211 End
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> OPTS UTF8 ON
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> 202 UTF8 mode is always enabled. No need to send this command.
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> SYST
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> 215 UNIX emulated by FileZilla
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> TYPE I
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> 200 Type set to I
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> SIZE /2.0.4.22_debug_aftp_test_1/duplicati-access-privileges-test.tmp
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> 213 83
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> EPSV
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> 229 Entering Extended Passive Mode (|||54291|)
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> RETR /2.0.4.22_debug_aftp_test_1/duplicati-access-privileges-test.tmp
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> 150 Opening data channel for file download from server of "/2.0.4.22_debug_aftp_test_1/duplicati-access-privileges-test.tmp"
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> 226 Successfully transferred "/2.0.4.22_debug_aftp_test_1/duplicati-access-privileges-test.tmp"
(000289)7/8/2019 10:34:59 AM - duplicati (127.0.0.1)> disconnected.
(000290)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> Connected on port 21, sending welcome message...
(000290)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> 220-FileZilla Server 0.9.60 beta
(000290)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> 220-written by Tim Kosse (tim.kosse@filezilla-project.org)
(000290)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> 220 Please visit https://filezilla-project.org/
(000290)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> USER duplicati
(000290)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> 331 Password required for duplicati
(000290)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> PASS ********
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 230 Logged on
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> FEAT
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 211-Features:
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> MDTM
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> REST STREAM
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> SIZE
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> MLST type*;size*;modify*;
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> MLSD
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> UTF8
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> CLNT
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> MFMT
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> EPSV
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> EPRT
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 211 End
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> OPTS UTF8 ON
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 202 UTF8 mode is always enabled. No need to send this command.
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> SYST
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 215 UNIX emulated by FileZilla
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> TYPE I
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 200 Type set to I
(000291)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> Connected on port 21, sending welcome message...
(000291)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> 220-FileZilla Server 0.9.60 beta
(000291)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> 220-written by Tim Kosse (tim.kosse@filezilla-project.org)
(000291)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> 220 Please visit https://filezilla-project.org/
(000291)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> USER duplicati
(000291)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> 331 Password required for duplicati
(000291)7/8/2019 10:39:09 AM - (not logged in) (127.0.0.1)> PASS ********
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 230 Logged on
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> OPTS UTF8 ON
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 202 UTF8 mode is always enabled. No need to send this command.
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> SYST
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 215 UNIX emulated by FileZilla
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> PWD
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 257 "/" is current directory.
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> CWD /
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 250 CWD successful. "/" is current directory.
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> TYPE I
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 200 Type set to I
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> SIZE /2.0.4.22_debug_aftp_test_1/duplicati-access-privileges-test.tmp
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 213 83
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> TYPE A
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 200 Type set to A
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> EPSV
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 229 Entering Extended Passive Mode (|||51186|)
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> RETR /2.0.4.22_debug_aftp_test_1/duplicati-access-privileges-test.tmp
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 150 Opening data channel for file download from server of "/2.0.4.22_debug_aftp_test_1/duplicati-access-privileges-test.tmp"
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 226 Successfully transferred "/2.0.4.22_debug_aftp_test_1/duplicati-access-privileges-test.tmp"
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> QUIT
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> 221 Goodbye
(000290)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> disconnected.
(000291)7/8/2019 10:39:09 AM - duplicati (127.0.0.1)> disconnected.
Other FluentFTP advice about EnableThreadSafeDataConnections:
What exactly EnableThreadSafeDataConnections does? #64
Dispose when using EnableThreadSafeDataConnections #275
https://github.com/robinrodricks/FluentFTP
Asynchronous support:
...
Improves thread safety by cloning the FTP control connection for file transfers (optional)
but I’m not familiar enough with Duplicati’s threading design (including exceptions and errors) to advise…
Unfortunately the idea of using a slightly earlier FluentFTP (19.2.2 before the #318 fix) didn’t avoid the bug.
A different Duplicati avoidance might be to switch downloads to the high-level API, as uploads has done… The upload change could be used as a model, but it’s still more of a change than I’d rather attempt myself.
EDIT:
Verified by editing source in dnSpy debugger that any of these 3 fixes is enough to solve the TYPE A error:
- Move OpenRead SetDataType to after CloneConnection (rather than before), like other methods do
- Add CurrentDataType to CloneConnection
- Set
EnableThreadSafeDataConnections = falsein Duplicati.Library.Backend.AlternativeFTP.dll
The first two could go together as a FluentFTP fix, but the last one is one Duplicati could do independently. Test of a several GB backup and restore (with --no-local-blocks=true) did OK, but what else is a concern?
EDIT 2:
Alternative ftp backend #1690 appears to be contributed code in 2016 (including the code and comment on EnableThreadSafeDataConnections = true being needed. And possibly it was indeed required in 2016.
Multiple file uploads keep re-opening connection #40 is where FluentFTP made several changes in 2017 to fix problems, and reduce the need to set EnableThreadSafeDataConnections = true. Default changed, suggesting false was generally the best plan. Test and usage since then might be heavier on false case.