Uploads randomly truncated with TLS 1.3 #602
Description
I discovered a bug using rclone to sync some data over to a pyftpdlib-based application. Essentially, if TLS 1.3 is used, most uploads will randomly get truncated near the end.
For example, if we try uploading a file that is 29633874 bytes large, we can see it getting truncated sometimes:
$ rclone -P -vv --fast-list --ftp-disable-tls13 copy /usr/share/xyz/webroot/project/A.bin Project:/project
2023/05/29 19:24:31 DEBUG : 2 go routines active
2023/05/29 19:24:31 DEBUG : ftp://host:2121/project: closing 1 unused connections
root@lb-jh3py:~# rclone -P -vv --fast-list copy /usr/share/xyz/webroot/project/A.bin Project:"/project"
2023/05/29 19:25:21 DEBUG : rclone: Version "v1.62.2" starting with parameters ["rclone" "-P" "-vv" "--fast-list" "copy" "/usr/share/xyz/webroot/project/A.bin" "Project:/project"]
2023/05/29 19:25:21 DEBUG : Creating backend with remote "/usr/share/xyz/webroot/project/A.bin"
2023/05/29 19:25:21 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2023/05/29 19:25:21 DEBUG : fs cache: adding new entry for parent of "/usr/share/xyz/webroot/project/A.bin", "/usr/share/xyz/webroot/project"
2023/05/29 19:25:21 DEBUG : Creating backend with remote "Projectproject:/project"
2023/05/29 19:25:21 DEBUG : ftp://host:2121/project: Connecting to FTP server
2023/05/29 19:25:21 DEBUG : ftp://host:2121/project: dial("tcp","host:2121")
2023/05/29 19:25:21 DEBUG : ftp://host:2121/project: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023-05-29 19:25:22 DEBUG : A.bin: Need to transfer - File not found at Destination
2023-05-29 19:25:22 DEBUG : ftp://host:2121/project: dial("tcp","127.0.0.1:58205")
2023-05-29 19:25:22 DEBUG : ftp://host:2121/project: > dial: conn=*tls.Conn, err=<nil>
2023-05-29 19:25:23 ERROR : A.bin: corrupted on transfer: sizes differ 29633874 vs 29437952
2023-05-29 19:25:23 INFO : A.bin: Removing failed copy
2023-05-29 19:25:23 ERROR : Attempt 1/3 failed with 1 errors and: corrupted on transfer: sizes differ 29633874 vs 29437952
2023-05-29 19:25:23 DEBUG : A.bin: Need to transfer - File not found at Destination
2023-05-29 19:25:24 DEBUG : ftp://host:2121/project: dial("tcp","127.0.0.1:58749")
2023-05-29 19:25:24 DEBUG : ftp://host:2121/project: > dial: conn=*tls.Conn, err=<nil>
2023-05-29 19:25:25 ERROR : A.bin: corrupted on transfer: sizes differ 29633874 vs 28487680
2023-05-29 19:25:25 INFO : A.bin: Removing failed copy
2023-05-29 19:25:25 ERROR : Attempt 2/3 failed with 1 errors and: corrupted on transfer: sizes differ 29633874 vs 28487680
2023-05-29 19:25:25 DEBUG : A.bin: Need to transfer - File not found at Destination
2023-05-29 19:25:25 DEBUG : ftp://host:2121/project: dial("tcp","127.0.0.1:58468")
2023-05-29 19:25:25 DEBUG : ftp://host:2121/project: > dial: conn=*tls.Conn, err=<nil>
2023-05-29 19:25:27 ERROR : A.bin: corrupted on transfer: sizes differ 29633874 vs 29224960
2023-05-29 19:25:27 INFO : A.bin: Removing failed copy
2023-05-29 19:25:27 ERROR : Attempt 3/3 failed with 1 errors and: corrupted on transfer: sizes differ 29633874 vs 29224960
Transferred: 84.783 MiB / 84.783 MiB, 100%, 16.957 MiB/s, ETA 0s
Errors: 1 (retrying may help)
Elapsed time: 6.1s
The upload was truncated at 29224960 bytes (compared with original filesize of 29633874).
In the FTPS server with debug logging, we see:
May 29 19:25:26 server manage.py[3866644]: DEBUG:pyftpdlib:[debug] call: recv(), err: ssl-want-read (<TLS_DTPHandler(id=140092900063744, addr='127.0.0.1:59684', ssl=True, user='ftpuser', ssl-data=True, sending-file=<tempfile._TemporaryFileWrapper object at 0x7f69eb8b8940>, bytes-trans=24539136)>)
May 29 19:25:26 server manage.py[3866644]: DEBUG:pyftpdlib:[debug] call: recv(), err: ssl-want-read (<TLS_DTPHandler(id=140092900063744, addr='127.0.0.1:59684', ssl=True, user='ftpuser', ssl-data=True, sending-file=<tempfile._TemporaryFileWrapper object at 0x7f69eb8b8940>, bytes-trans=24866816)>)
May 29 19:25:26 server manage.py[3866644]: DEBUG:pyftpdlib:[debug] call: recv(), err: ssl-want-read (<TLS_DTPHandler(id=140092900063744, addr='127.0.0.1:59684', ssl=True, user='ftpuser', ssl-data=True, sending-file=<tempfile._TemporaryFileWrapper object at 0x7f69eb8b8940>, bytes-trans=27439104)>)
May 29 19:25:26 server manage.py[3866644]: DEBUG:pyftpdlib:[debug] call: recv(), err: ssl-want-read (<TLS_DTPHandler(id=140092900063744, addr='127.0.0.1:59684', ssl=True, user='ftpuser', ssl-data=True, sending-file=<tempfile._TemporaryFileWrapper object at 0x7f69eb8b8940>, bytes-trans=27504640)>)
May 29 19:25:26 server manage.py[3866644]: DEBUG:pyftpdlib:[debug] call: recv(), err: SysCallError(104, 'ECONNRESET') (<TLS_DTPHandler(id=140092900063744, addr='127.0.0.1:59684', ssl=True, user='ftpuser', ssl-data=True, sending-file=<tempfile._TemporaryFileWrapper object at 0x7f69eb8b8940>, bytes-trans=29224960)>)
May 29 19:25:26 server manage.py[3866644]: DEBUG:pyftpdlib:[debug] call: _do_ssl_shutdown() -> os.write, err: BrokenPipeError(32, 'Broken pipe') (<TLS_DTPHandler(id=140092900063744, addr='127.0.0.1:59684', ssl=True, user='ftpuser', ssl-data=True, sending-file=<tempfile._TemporaryFileWrapper object at 0x7f69eb8b8940>, bytes-trans=29224960)>)
May 29 19:25:26 server manage.py[3866644]: DEBUG:pyftpdlib:[debug] call: close() (<TLS_DTPHandler(id=140092900063744, addr='127.0.0.1:59684', ssl=True, user='ftpuser', ssl-data=True, sending-file=<tempfile._TemporaryFileWrapper object at 0x7f69eb8b8940>, bytes-trans=29224960)>)
May 29 19:25:26 server manage.py[3866644]: DEBUG:pyftpdlib:127.0.0.1:59684-[ftpuser] -> 226 Transfer complete.
May 29 19:25:26 server manage.py[3866644]: INFO:pyftpdlib:127.0.0.1:59684-[ftpuser] STOR /tmp/tmp8pdhfjfd completed=1 bytes=29224960 seconds=1.058
The FTP handler gets a ECONNRESET for some reason instead of a proper TLS 1.3 shutdown.
If we re-run the test and disable TLS 1.3 in rclone using the --ftp-disable-tls13 flag, the upload succeeds perfectly every time:
$ rclone -P -vv --fast-list --ftp-disable-tls13 copy /usr/share/xyz/webroot/project/A.bin Project:/project
Versions:
- The rclone version tested is 1.62.2.
- pyftdlib is version 1.5.7.
- The OpenSSL version on the client (rclone) is unclear because it's a statically linked Go binary. (Not even sure if Go uses OpenSSL or if they use BoringSSL.)
- OpenSSL on the server (pyftpdlib) is 1.1.1f-1ubuntu2.18.
Root Cause Speculation
It's quite possible there's an underlying bug here in pyopenssl or even OpenSSL:
openssl/openssl#10880
There's a closed bug in proftpd that looks the same as my debug log above:
proftpd/proftpd#959
And their workaround is here: proftpd/proftpd@6d6cde2
Thanks!