Problems after upgrade to 2.0.4.21

Support
1

On the weekend, I upgraded to the latest version 2.0.4.21 on one PC. Afterwards, I have error reports on all backups I have configured on this PC. The error occurs after every backup. Running repair did not help. It is different for the different configurations, but seems to be the same for each job (of one configuration). I have attached one example at the end of this post. Unfortunately, I cannot downgrade since the database changed to version 9. My questions:

  • are these errors critical? I mean, is there data lost in the update?
  • Can they be fixed?
  • or, alternatively: is there a way to downgrade and still keep my backup history?

Some information:

  • backup via ftp to my router (fritzbox), aes encrypted
  • I already set http-operation-timeout to 10 mins (there was an old post about this), but to no end (the whole backup took 5 mins).

Thx for the help, Uli

Here is the log:
{
“DeletedFiles”: 0,
“DeletedFolders”: 0,
“ModifiedFiles”: 0,
“ExaminedFiles”: 4179,
“OpenedFiles”: 0,
“AddedFiles”: 0,
“SizeOfModifiedFiles”: 0,
“SizeOfAddedFiles”: 0,
“SizeOfExaminedFiles”: 1074532257,
“SizeOfOpenedFiles”: 0,
“NotProcessedFiles”: 0,
“AddedFolders”: 0,
“TooLargeFiles”: 0,
“FilesWithError”: 0,
“ModifiedFolders”: 0,
“ModifiedSymlinks”: 0,
“AddedSymlinks”: 0,
“DeletedSymlinks”: 0,
“PartialBackup”: false,
“Dryrun”: false,
“MainOperation”: “Backup”,
“CompactResults”: null,
“DeleteResults”: {
“DeletedSetsActualLength”: 0,
“DeletedSets”: ,
“Dryrun”: false,
“MainOperation”: “Delete”,
“CompactResults”: null,
“ParsedResult”: “Success”,
“Version”: “2.0.4.21 (2.0.4.21_experimental_2019-06-28)”,
“EndTime”: “2019-07-03T19:01:00.0422824Z”,
“BeginTime”: “2019-07-03T19:00:59.892479Z”,
“Duration”: “00:00:00.1498034”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null,
“BackendStatistics”: {
“RemoteCalls”: 32,
“BytesUploaded”: 0,
“BytesDownloaded”: 263315025,
“FilesUploaded”: 0,
“FilesDownloaded”: 15,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 24,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 188,
“KnownFileSize”: 2884376316,
“LastBackupDate”: “2019-06-29T09:23:34+02:00”,
“BackupListCount”: 27,
“TotalQuotaSpace”: 0,
“FreeQuotaSpace”: 0,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.4.21 (2.0.4.21_experimental_2019-06-28)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2019-07-03T19:00:55.872369Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
},
“RepairResults”: null,
“TestResults”: {
“MainOperation”: “Test”,
“VerificationsActualLength”: 6,
“Verifications”: [
{
“Key”: “duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes”,
“Value”: [
{
“Key”: “Error”,
“Value”: “Fehler beim Entschlüsseln der Daten (ungültige Passphrase?): Invalid password or corrupted data”
}
]
},
{
“Key”: “duplicati-i961947860e384806999c9a355489591d.dindex.zip.aes”,
“Value”: [
{
“Key”: “Error”,
“Value”: “Fehler beim Entschlüsseln der Daten (ungültige Passphrase?): Invalid password or corrupted data”
}
]
},
{
“Key”: “duplicati-id12f7c0ec9a147b4870b0cd8c8ef2eb8.dindex.zip.aes”,
“Value”: [
{
“Key”: “Error”,
“Value”: “File length is invalid”
}
]
},
{
“Key”: “duplicati-20190410T042907Z.dlist.zip.aes”,
“Value”: [
{
“Key”: “Error”,
“Value”: “Die Datei duplicati-20190410T042907Z.dlist.zip.aes wurde heruntergeladen und hat die Größe 3106, erwartet war allerdings die Größe 3101”
}
]
},
{
“Key”: “duplicati-idb53ad1303c744519141918784f02089.dindex.zip.aes”,
“Value”: [
{
“Key”: “Error”,
“Value”: “Die Datei duplicati-idb53ad1303c744519141918784f02089.dindex.zip.aes wurde heruntergeladen und hat die Größe 57060, erwartet war allerdings die Größe 56845”
}
]
},
{
“Key”: “duplicati-b87766ae87b7f476890655b1d68ee1547.dblock.zip.aes”,
“Value”: [
{
“Key”: “Error”,
“Value”: “Die Datei duplicati-b87766ae87b7f476890655b1d68ee1547.dblock.zip.aes wurde heruntergeladen und hat die Größe 52602839, erwartet war allerdings die Größe 52398301”
}
]
}
],
“ParsedResult”: “Success”,
“Version”: “2.0.4.21 (2.0.4.21_experimental_2019-06-28)”,
“EndTime”: “2019-07-03T19:05:49.0222423Z”,
“BeginTime”: “2019-07-03T19:01:00.8925778Z”,
“Duration”: “00:04:48.1296645”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null,
“BackendStatistics”: {
“RemoteCalls”: 32,
“BytesUploaded”: 0,
“BytesDownloaded”: 263315025,
“FilesUploaded”: 0,
“FilesDownloaded”: 15,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 24,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 188,
“KnownFileSize”: 2884376316,
“LastBackupDate”: “2019-06-29T09:23:34+02:00”,
“BackupListCount”: 27,
“TotalQuotaSpace”: 0,
“FreeQuotaSpace”: 0,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.4.21 (2.0.4.21_experimental_2019-06-28)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2019-07-03T19:00:55.872369Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
},
“ParsedResult”: “Error”,
“Version”: “2.0.4.21 (2.0.4.21_experimental_2019-06-28)”,
“EndTime”: “2019-07-03T19:05:49.1823108Z”,
“BeginTime”: “2019-07-03T19:00:55.8627219Z”,
“Duration”: “00:04:53.3195889”,
“MessagesActualLength”: 84,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 6,
“Messages”: [
“2019-07-03 21:00:55 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: Die Operation Backup wurde gestartet”,
“2019-07-03 21:00:57 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()”,
“2019-07-03 21:00:57 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (188 Bytes)”,
“2019-07-03 21:01:00 +02 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: No remote filesets were deleted”,
“2019-07-03 21:01:00 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()”,
“2019-07-03 21:01:00 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (188 Bytes)”,
“2019-07-03 21:01:00 +02 - [Information-Duplicati.Library.Main.Operation.TestHandler-MissingRemoteHash]: No hash or size recorded for duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes, performing full verification”,
“2019-07-03 21:01:00 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes ()”,
“2019-07-03 21:01:01 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes ()”,
“2019-07-03 21:01:11 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes ()”,
“2019-07-03 21:01:11 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes ()”,
“2019-07-03 21:01:21 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes ()”,
“2019-07-03 21:01:22 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes ()”,
“2019-07-03 21:01:32 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes ()”,
“2019-07-03 21:01:32 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes ()”,
“2019-07-03 21:01:42 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes ()”,
“2019-07-03 21:01:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Failed: duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes ()”,
“2019-07-03 21:01:43 +02 - [Information-Duplicati.Library.Main.Operation.TestHandler-MissingRemoteHash]: No hash or size recorded for duplicati-i961947860e384806999c9a355489591d.dindex.zip.aes, performing full verification”,
“2019-07-03 21:01:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i961947860e384806999c9a355489591d.dindex.zip.aes ()”,
“2019-07-03 21:01:43 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-i961947860e384806999c9a355489591d.dindex.zip.aes ()”
],
“Warnings”: ,
“Errors”: [
“2019-07-03 21:01:43 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i25e18162fe564e9d8596bc9ca9980607.dindex.zip.aes”,
“2019-07-03 21:02:25 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i961947860e384806999c9a355489591d.dindex.zip.aes”,
“2019-07-03 21:03:08 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-id12f7c0ec9a147b4870b0cd8c8ef2eb8.dindex.zip.aes”,
“2019-07-03 21:03:51 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20190410T042907Z.dlist.zip.aes”,
“2019-07-03 21:04:37 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-idb53ad1303c744519141918784f02089.dindex.zip.aes”,
“2019-07-03 21:05:49 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b87766ae87b7f476890655b1d68ee1547.dblock.zip.aes”
],
“BackendStatistics”: {
“RemoteCalls”: 32,
“BytesUploaded”: 0,
“BytesDownloaded”: 263315025,
“FilesUploaded”: 0,
“FilesDownloaded”: 15,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 24,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 188,
“KnownFileSize”: 2884376316,
“LastBackupDate”: “2019-06-29T09:23:34+02:00”,
“BackupListCount”: 27,
“TotalQuotaSpace”: 0,
“FreeQuotaSpace”: 0,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Backup”,
“ParsedResult”: “Success”,
“Version”: “2.0.4.21 (2.0.4.21_experimental_2019-06-28)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2019-07-03T19:00:55.872369Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
}

2

PS. I ran “delete and recover” (löschen und wiederherstellen) on another configuration, but it stopped with “file length invalid”. Now all backups of this configuration are gone. The error message appeared as a red box, but no log file is available. Are the backups lost?

3

Hello @UliM and welcome to the forum!

If “delete and recover” (löschen und wiederherstellen) was actually more like the below, then you were in database management, which wouldn’t affect the backup itself, only the database that tracks what’s in it.

msgid "Recreate (delete and repair)"
msgstr "Wiederherstellen (löschen und reparieren)"

I’d suggest slowing down, and turning off scheduled backups because more attempts may make things worse. Unless you’ve already run a compact, then generally changes to backup files are just added files with names like dblock and dindex (in pairs, and many), with a dlist file uploaded to show what’s present.

You can look at your backup files with something that shows dates, to see if it looks like that, or if you got newer dates on dlist files with old dates in the name. The job logs will also show whether a compact ran.

EDIT:

When looking at the actual files, please also check sizes. I see some complaints such as the below that make me wonder if there’s confusion about FTP transfer mode (ASCII versus binary). Got a server log?

“Die Datei duplicati-b87766ae87b7f476890655b1d68ee1547.dblock.zip.aes wurde heruntergeladen und hat die Größe 52602839, erwartet war allerdings die Größe 52398301”

FTP Binary and ASCII Transfer Types And The Case of Corrupt Files

EDIT 2:

The way the math behind that works is that if you assume an encrypted file is very random, the expected chance of something looking like a single-character line ending for your FRITZ!Box OS (perhaps Linux?) would be 1 in 256, so changing a file into the network-standard two-character line ending is expansion of 1.00390625 original file size. That breaks decryption, and is what you got in the two files with size errors:

“was downloaded and has the size 57060, but was expected the size 56845” got 1.003782214794617
“was downloaded and its size is 52602839, but it was expected to be 52398301” got 1.0039035235131

Duplicati code looks like it sets UseBinary = true for backup data transfers, and false for a directory listing, assuming your “Storage Type” is set to “FTP”. If you’re on “FTP (Alternative)”, this concerns me:

DownloadDataType Binary value ignored on ASCII-configured FTP servers #318 but I need to look more. Meanwhile please check your FTP server configuration settings to see if it has one for its transfer mode.

On Duplicati’s end, this Feb 17, 2019 commit looks like it updated its alternative FTP client to a new one.

EDIT 3:

I don’t have the exact right versions to spot the change, but comparing 2.0.4.5 beta to latest canary gets:

2.0.4.5 beta

(000077)7/3/2019 21:19:43 PM - duplicati (127.0.0.1)> TYPE I
(000077)7/3/2019 21:19:43 PM - duplicati (127.0.0.1)> 200 Type set to I
(000077)7/3/2019 21:19:43 PM - duplicati (127.0.0.1)> SIZE duplicati-20181205T233136Z.dlist.zip
(000077)7/3/2019 21:19:43 PM - duplicati (127.0.0.1)> 213 624
(000077)7/3/2019 21:19:43 PM - duplicati (127.0.0.1)> EPSV
(000077)7/3/2019 21:19:43 PM - duplicati (127.0.0.1)> 229 Entering Extended Passive Mode (|||49562|)
(000077)7/3/2019 21:19:43 PM - duplicati (127.0.0.1)> RETR duplicati-20181205T233136Z.dlist.zip
(000077)7/3/2019 21:19:43 PM - duplicati (127.0.0.1)> 150 Opening data channel for file download from server of "/ftp_test_1/duplicati-20181205T233136Z.dlist.zip"
(000077)7/3/2019 21:19:43 PM - duplicati (127.0.0.1)> 226 Successfully transferred "/ftp_test_1/duplicati-20181205T233136Z.dlist.zip"

2.0.4.22 canary

(000080)7/3/2019 21:22:47 PM - duplicati (127.0.0.1)> TYPE I
(000080)7/3/2019 21:22:47 PM - duplicati (127.0.0.1)> 200 Type set to I
(000080)7/3/2019 21:22:47 PM - duplicati (127.0.0.1)> SIZE duplicati-20181205T233136Z.dlist.zip
(000080)7/3/2019 21:22:47 PM - duplicati (127.0.0.1)> 213 624
(000080)7/3/2019 21:22:47 PM - duplicati (127.0.0.1)> TYPE A
(000080)7/3/2019 21:22:47 PM - duplicati (127.0.0.1)> 200 Type set to A
(000080)7/3/2019 21:22:47 PM - duplicati (127.0.0.1)> EPSV
(000080)7/3/2019 21:22:47 PM - duplicati (127.0.0.1)> 229 Entering Extended Passive Mode (|||49906|)
(000080)7/3/2019 21:22:47 PM - duplicati (127.0.0.1)> RETR duplicati-20181205T233136Z.dlist.zip
(000080)7/3/2019 21:22:47 PM - duplicati (127.0.0.1)> 150 Opening data channel for file download from server of "/ftp_test_1/duplicati-20181205T233136Z.dlist.zip"
(000080)7/3/2019 21:22:47 PM - duplicati (127.0.0.1)> 226 Successfully transferred "/ftp_test_1/duplicati-20181205T233136Z.dlist.zip"

testing a “direct restore” from an old FTP backup I had laying around. Notice it now sets ASCII mode then downloads a binary file… Surprisingly, it’s still able to deal with the file, but some FTP servers lie that they actually set ASCII mode. Possibly FileZilla Server does. Or maybe a larger file would expand and break…

@UliM could possibly try the same direct restore experiment, switching from “FTP (Alternative)” to “FTP” if “FTP (Alternative)” has trouble. Which storage type was used before upgrade was done. Is it still in use?

4

Reproduced this problem by trying “direct restore” of an old Linux backup using Windows Duplicati FTP. Used package inetutils-ftpd as an FTP server. The error from About → Show log → Live → Retry was:

Jul 4, 2019 10:02 AM: Operation Get with file duplicati-20181124T033217Z.dlist.zip attempt 5 of 5 failed with message: The file duplicati-20181124T033217Z.dlist.zip was downloaded and had size 2206 but the size was expected to be 2201

Below is how this dlist slowly grew by 5 bytes by translating Linux LF (0a) line endings to CR LF (0d 0a):

00000070  68 60 64 62 60 00 15 f2  48 2c ce 00 aa 0a f6 70  h`db`...H,.....p
00000070  68 60 64 62 60 00 15 f2  48 2c ce 00 aa 0d 0a f6   h`db`...H,......

00000440  11 f7 c9 39 18 0a c9 4d  43 05 ae a8 9d 4d b4 f5  ...9...MC....M..
00000440  d1 11 f7 c9 39 18 0d 0a  c9 4d 43 05 ae a8 9d 4d   ....9....MC....M

00000610  0e 14 ac 59 2b 0a 7e 13  6d b5 3e 56 f8 dd 50 36  ...Y+.~.m.>V..P6
00000610  7a 9a 0e 14 ac 59 2b 0d  0a 7e 13 6d b5 3e 56 f8   z....Y+..~.m.>V.

00000620  69 5c 2c 0a c7 08 db 1b  f8 1c ae 0d ce 65 2c c2  i\,..........e,.
00000620  dd 50 36 69 5c 2c 0d 0a  c7 08 db 1b f8 1c ae 0d   .P6i\,..........

000007d0  a0 44 84 cc 4d 1d ce be  f6 53 34 df df a4 7e 0a  .D..M....S4...~.
000007E0  df a4 7e 0d 0a 07 84 20  42 85 70 04 41 c1 45 38   ..~.... B.p.A.E8

FRITZ!OS is Linux-based, and the problem might be only on UNIX-like FTP servers. Windows already treats CR LF as its line ending, so no conversion for it is required. What to do for a CR without a LF in original source is controversial. The standard wants CR NUL, but the problem is NUL is troublesome. Regardless, the FTP server I used for the test left simple CR alone, and only translated LF into CR LF.

If any development volunteers know FluentFTP, feel free to join. I haven’t found the source-level cause, however if it turns out to be a third-party library bug, I hope there’s some workaround Duplicati can use.

5

During a backup, what seems to happen is that the files upload OK, then download for verifying backend files sample finds the files different than expected, tripping over decryption integrity check, or size greater than expected due to expansion. The good news there is that changing from “FTP (Alternative)” to “FTP” might solve all the download issues. Was there originally a problem with “FTP” that called for not using it?

Need feedback from @UliM on this and maybe some other things, such as how files on FRITZ!Box look. Please also say whether there’s a database saved from before the Recreate, or if you have no database. Having a database means you could switch to “FTP” and try a test command to see if the backup files are what database expects. If you have no database, then you’d switch to “FTP” then see if “Recreate” works.

More for developer information, the simple way to characterize (and maybe later debug) the problem may be to use Duplicati.CommandLine.BackendTool.exe to do the get download without all the other Duplicati action. This is also a quick way to see what release does what, if one has their release file folders around. As expected, this regression was added with the 2.0.4.16 commit that changed the FTP client while doing work for parallel uploads. I don’t know whether the FTP update was essential, i.e. if it got needed features.

“C:\ProgramData\Duplicati\duplicati-2.0.4.16_canary_2019-03-28\Duplicati.CommandLine.BackendTool” get “aftp://user:pass@192.168.0.109/home/user/DuplicatiBackups/test1” “duplicati-20181124T033217Z.dlist.zip”

for example gets the corrupted 2206 byte version instead of the good 2201 byte version that 2.0.4.15 gets.
The 2.0.4.16 (and even 2.0.4.22) upload worked worse from BackendTool than actual Duplicati, making 0 length file out of a Windows file containing two lines and CR LF line endings. Sample upload command is:

"C:\ProgramData\Duplicati\duplicati-2.0.4.16_canary_2019-03-28\Duplicati.CommandLine.BackendTool" put "aftp://user:pass@127.0.0.1/ftp_test_1" "two_lines.txt"
Command failed: One or more errors occurred.
System.AggregateException: One or more errors occurred. ---> FluentFTP.FtpException: Error while uploading the file to the server. See InnerException for more info. ---> System.ObjectDisposedException: Cannot access a closed file.
   at System.IO.__Error.FileNotOpen()
   at System.IO.FileStream.get_Length()
   at FluentFTP.FtpClient.<UploadFileInternalAsync>d__311.MoveNext()
   --- End of inner exception stack trace ---
   at FluentFTP.FtpClient.<UploadFileInternalAsync>d__311.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 FluentFTP.FtpClient.<UploadAsync>d__306.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.Backend.AlternativeFTP.AlternativeFtpBackend.<PutAsync>d__37.MoveNext()
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at Duplicati.CommandLine.BackendTool.Program.RealMain(String[] _args)
---> (Inner Exception #0) FluentFTP.FtpException: Error while uploading the file to the server. See InnerException for more info. ---> System.ObjectDisposedException: Cannot access a closed file.
   at System.IO.__Error.FileNotOpen()
   at System.IO.FileStream.get_Length()
   at FluentFTP.FtpClient.<UploadFileInternalAsync>d__311.MoveNext()
   --- End of inner exception stack trace ---
   at FluentFTP.FtpClient.<UploadFileInternalAsync>d__311.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 FluentFTP.FtpClient.<UploadAsync>d__306.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.Backend.AlternativeFTP.AlternativeFtpBackend.<PutAsync>d__37.MoveNext()<---

Above is to FileZilla Server, which is able to log the details, so you can see it’s doing binary (a.k.a. image):

(000092)7/4/2019 18:32:38 PM - duplicati (127.0.0.1)> TYPE I
(000092)7/4/2019 18:32:38 PM - duplicati (127.0.0.1)> 200 Type set to I
(000092)7/4/2019 18:32:38 PM - duplicati (127.0.0.1)> EPSV
(000092)7/4/2019 18:32:38 PM - duplicati (127.0.0.1)> 229 Entering Extended Passive Mode (|||57487|)
(000092)7/4/2019 18:32:38 PM - duplicati (127.0.0.1)> STOR two_lines.txt

2.0.4.15 uploads the file OK. 2.0.4.16 download is bad in Server and BackendTool, whereas uploads might be OK in Server (not well-proven, especially to know if FRITZ!Box got empty files), but bad in BackendTool.

6

Oh, FTP, always biting :confused:

The downloading happens here:

Looking into the overload in FluentFTP, it explicitly sets the type to Binary:

public Stream OpenRead (string path)
{
	return OpenRead (path, FtpDataType.Binary, 0L, checkIfFileExists: true);
}

Was this with aFTP ? It is strange that it would emit TYPE A when there is an option in FluentFTP that explicitly sets it to binary?

7

“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?

8

Yes, I found that as well. I think this is the same problem, just triggered in another way.

Since it does not appear to be fixed in later versions, maybe a short-term fix is to downgrade FluentFTP?

I think we need to debug FluentFTP directly, and then submit a fix up-stream.

The fix for issue 318, could explain what happens. If it restarts the connection for some reason, but does not reset the ForceSetDataType flag, it might end up emitting the TYPE A:

9

Dealing with backends for implementing parallel uploads original post said this. I have no opinion myself:

I’ve started looking into a theory that the below on file transfers is doing an incomplete clone, therefore coming up with an FTPClient with CurrentDataType uninitialized, and therefore 0, and therefore ASCII:

I’m not sure if I can patch this in the debugger (haven’t tried yet), and am not set up on Windows to build. Another way of testing if it’s the problem is to set EnableThreadSafeDataConnections to false if we dare:

Current data type not set when using EnableThreadSafeDataConnections #184 was a similar partial clone, and Fix download file data type bug. #202 added the DownloadDataType and UploadDataType, but it looks like those are for the high-level API whereas Duplicati downloads use the low-level API. The TYPE I before the SIZE might be a force-to-binary, and TYPE A after it might be a return to the incorrect CurrentDataType:

This needs a whole lot more testing (and I’d like to come up with a simpler test case if a FluentFTP issue gets filed, but once again I’m somewhat limited in C# build abilities…) but that’s the update I wanted to do.

EDIT:

Looking at the prior fix, and the current CloneConnection calls in FtpClient_LowLevel.cs, I notice there are SetDataType* calls done afterwards for an OpenReadAsync, OpenWrite, OpenWriteAsync, OpenAppend, and OpenAppendAsync, however in OpenRead (which is what Duplicati uses) the SetDataType precedes CloneConnection. Maybe the ordering fixes up the incomplete cloning, except for the case Duplicati uses?

EDIT 2:

Getting way too speculative, possibly attempted fix for #318 made the problem more visible by being more definite about setting the connection transfer type to what’s usually the right value, but in our case is wrong. That would be a good outcome, because downgrading to some version before this recent fix might help us.

10

Hellot ts678 and all the other participants of this thread,

thank you very much for the feedback. You really take this seriously, I appreciate this very much. I like duplicati a lot, it is a great tool that saved me already from loosing data.

I solved my problem by switching to “FTP”, instead of “FTP (alternative)”. All is up and working again. Problem with ftp is,it is not that stable. Especially at my wife’s Laptop, which is connected via WLAN, once a month one of the daily backups does not finish correctly, and then a “Repair” is necessary (which is too much to do for my wife). I think I will buy some NAS for backup, and use a different protocol (e.g. ssh/sftp).

Thanks again for the feedback & the great work you are doing!

11

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 = false in 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.

12

It appears that this problem was introduced Sep 26, 2017 while fixing issue Current data type not set when using EnableThreadSafeDataConnections #184 with pull request Fix download file data type bug. #202 that moved the OpenRead SetDataType from after to before the CloneConnection for reasons that are not clear to me, but may have been to prove that the fixes to CloneConnection now indeed clone DownloadDataType and UploadDataType, otherwise failure would continue. Change is here. Unfortunately for Duplicati use, the reordering proves (by failure) that clone of CurrentDataType is not working, because it’s not coded. Unless there’s some reason the new ordering is required, I’m still thinking FluentFTP should add one or both of my two fixes above. What’s unknown is how long it will take, and how long Duplicati can wait, given ACD push.

Doing downgrade of FluentFTP to 18.0.2 fixed my test case. Next up in nuget is 19.0.0, which has the bug. Technically changing the major version from our current 21 all the way down to 18 may break compatibility.

I’m still tempted to recommend setting “EnableThreadSafeDataConnections = false” (or deleting that line). Further searching still finds nobody else seeing this almost two-year-old issue. Maybe nobody sets “true”?

13

The update was only present in the canary, so all beta users should not see issues?

If you have the time, submitting a patch to FluentFTP would eventually solve our issues and allow us to upgrade. You have the traces that shows the problem, so it should pass right away.

Unfortunately, we have a thight deadline with AmzCD closing in mid august. We need to have a beta out very soon, to allow warning AmzCD users.

On the other hand we do not want to push untested software, and do not want to break the backups for other users.

That leaves three options as I see it:

  1. Delay the update, leaving AmzCD users hanging
  2. Push the current experimental, potentially breaking FTP setups (not all servers have the problem)
  3. Patch a copy of FluentFTP (based on v21) and ship with that

I am not in favor of settting the EnableThreadSafeDataConnections flag as that exposes even more untested code, and completely changes the way the library works.

Unfortunately, I cannot do any of this before saturday (at best). If you have a patch file, that would speed up things.

Would a decent solution be to ship the current beta, warning the AmzCD users, and breaking some of the FTP backups? Then we follow with a new beta in a week or two that has the patched FTP library?

14

They won’t see it until beta soon, or Experimental or Canary now. This is a chance to stop regression.

I can open an issue, but I’m not sure it will be a pull request unless they’re as accepting as Duplicati of changes that have not actually been built (except in the debugger). There’s also typically a question on whether we could set EnableThreadSafeDataConnections = false, and I don’t know with certainty.

Agree that it changes how the library works, but I suspect that the untested library code is the true case, generally speaking. Agree that it would not be tested by Duplicati before, though maybe by everyone else.

Ugh. Well, I guess one thought is that some of them might be able to go to “FTP” from “FTP (Alternative)”, and those who run Windows FTP servers may never see a regression. I guess support can cover others.

Exact timeline for FluentFTP fix is unknown, but yes there could be a followup Beta, and other bugs might be found as well. It can also be release-noted to help people who read the release note before their install.

Release note could also mention the ACD issue as a heads-up to those who read, but delay on the install. I’m actually not certain this is a shutdown of all integrations. It might be just a couple, but Duplicati was hit.

If current experimental goes beta, Backends are not disposed after upload operations #3808 hurts SFTP and I’m not sure which other backends, but beta schedule might not have time for another experimental…

I’m almost wishing there was a branching structure where we could do 2.0.4.5-plus-warning instead of a schedule dictated by getting the warning out. The risk would then just be the usual will-update-update one and some needless work to those not on ACD. We’d also delay some good fixes made in the next beta…

Below is my dnSpy patch of moving the SetDataType back to after the CloneConnection. It likely deserves a look by someone else, and another test to watch it work. FluentFTP uses MIT License, so no GPL worry.

image
image706×242 12 KB

Or maybe you had a source patch in mind? In that case, I suppose there could be some build risk instead.

This is unfortunately a squeeze due to an external schedule, but I expect it’s not the last one that’ll happen.

15

Can a 4th option be to create a beta release that only includes the change for the AmzCD warning? We can then get this out sooner, and allow for more time to test the other changes in the canaries.

16

OpenRead with EnableThreadSafeDataConnections = true does ASCII when it shouldn’t #428 has been opened as a FluentFTP issue summarizing the problem, its suspected cause, and proposed code fixes.

The “4th option” from @warwickmm is what I meant by “2.0.4.5-plus-warning”, but I said it more lightly because I’m not sure what sort of complexity it adds. I’ve seen branching headaches in other systems…

17

Of course! That is a better solution. It will make the version numbers a little wonky, but it breaks nothing (that is not already broken) and gets the warning out. I will see if I can get that build out during the weekend.

18

The fix is released in FluentFTP 26.0.0, might not be quite as I had in mind, but does seem to pass my test. Actually testing in Duplicati didn’t work, as sliding the new DLL in wound up with Duplicati not recognizing it. Looking into this further, I think Duplicati’s is looking for a particular version number, so a rebuild is required.