Issue with file upload to explicit FTPS (python hangs)

Need help with FileZilla Server? Something does not work as expected? In this forum you may find an answer.

Moderator: Project members

Post Reply
Message
Author
pjir
500 Command not understood
Posts: 2
Joined: 2022-12-04 18:37

Issue with file upload to explicit FTPS (python hangs)

#1 Post by pjir » 2022-12-04 20:42

Hi all,
first of all thanks for a good secure ftp server. I have tried to create FTP client with python, i am able to connect and retrieve file or listing after a small fix:

Code: Select all

class MyFTP_TLS(ftplib.FTP_TLS):
    """Explicit FTPS, with shared TLS session"""
    def ntransfercmd(self, cmd, rest=None):
        conn, size = ftplib.FTP.ntransfercmd(self, cmd, rest)
        if self._prot_p:
            conn = self.context.wrap_socket(conn,
                                            server_hostname=self.host,
                                            session=self.sock.session)  # this is the fix
        return conn, size
But I have problem with upload file (STOR command), it works, but... All data is uploaded, but script hangs when closing data connection. I have look to communication via Wireshark and python send close_notify message, it arrives to remote machine, unfortunately FZS does not answer to close_notify.
Both, FZS and python stuck in read :-(

Tested with latest Filezilla Server (1.5.1) and Python 3.11.0, all on Win10 (fully updated).
Problem is with TLS1.2 and TLS1.3

FZS log:

Code: Select all

<Date> Info [Type] Message
<03-12-2022 11:13:39> FTP Session 48 127.0.0.1 test-submit [Response] 150 Starting data transfer.
<03-12-2022 11:13:39> FTP Session 48 127.0.0.1 test-submit [Trace] tls_layer_impl::continue_handshake()
<03-12-2022 11:13:39> FTP Session 48 127.0.0.1 test-submit [Trace] tls_layer_impl::continue_handshake()
<03-12-2022 11:13:39> FTP Session 48 127.0.0.1 test-submit [Trace] TLS Handshake successful
<03-12-2022 11:13:39> FTP Session 48 127.0.0.1 test-submit [Trace] TLS Session resumed
<03-12-2022 11:13:39> FTP Session 48 127.0.0.1 test-submit [Trace] Protocol: TLS1.2, Key exchange: ECDHE-X25519, Cipher: AES-256-GCM, MAC: AEAD, ALPN: 
<03-12-2022 11:13:39> FTP Session 48 127.0.0.1 test-submit [Trace] session::on_socket_event(): source = data, flag = 2, error = 0, state = 2
^^^^ here FZS hangs

Python can continue with timeout exception if I set timeout variable (otherwise it waits indefinitely).
With timeout set (in example 5sec) FZS continues:

Code: Select all

<03-12-2022 11:13:45> FTP Session 48 127.0.0.1 test-submit [Trace] tls_layer_impl::shutdown()
<03-12-2022 11:13:45> FTP Session 48 127.0.0.1 test-submit [Trace] tls_layer_impl::continue_shutdown()
<03-12-2022 11:13:45> FTP Session 48 127.0.0.1 test-submit [Trace] data_socket_->shutdown() = 0
<03-12-2022 11:13:45> FTP Session 48 127.0.0.1 test-submit [Response] 226 Operation successful
<03-12-2022 11:13:45> FTP Session 48 127.0.0.1 test-submit [Command] QUIT
<03-12-2022 11:13:45> FTP Session 48 127.0.0.1 test-submit [Response] 221 Goodbye. 
The problem is reproducible, just run both (FZS + python script) on localhost. Tested in local network, localhost, on internet. The behavior is always the same.

Please, does anyone know where the error might be?

User avatar
botg
Site Admin
Posts: 35505
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: Issue with file upload to explicit FTPS (python hangs)

#2 Post by botg » 2022-12-04 20:53

Could you please provide a complete Python script?

pjir
500 Command not understood
Posts: 2
Joined: 2022-12-04 18:37

Re: Issue with file upload to explicit FTPS (python hangs)

#3 Post by pjir » 2022-12-04 21:11

sorry, of course

Code: Select all

import ftplib
import io

time_limit = 5

class MyFTP_TLS(ftplib.FTP_TLS):
    """Explicit FTPS, with shared TLS session"""
    def ntransfercmd(self, cmd, rest=None):
        conn, size = ftplib.FTP.ntransfercmd(self, cmd, rest)
        if self._prot_p:
            conn = self.context.wrap_socket(conn,
                                            server_hostname=self.host,
                                            session=self.sock.session)  # this is the fix
        return conn, size

with MyFTP_TLS(timeout = time_limit) as ftps:
    ftps.set_debuglevel(2)
    ftps.connect(host = '127.0.0.1', port = 2121)
    ftps.login(user = 'test-submit', passwd = 'pass-for-test')
    ftps.prot_p()
    ftps.storbinary('STOR data.bin', io.BytesIO(b'test-123'))
server set to "Require explicit FTP over TLS"

User avatar
botg
Site Admin
Posts: 35505
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: Issue with file upload to explicit FTPS (python hangs)

#4 Post by botg » 2022-12-04 23:28

Thank you. Problem has been identified. Note that this issue is triggered by Python's ftplib being quite slow, it needlessly waits for things it doesn't need to wait for.

User avatar
oibaf
Contributor
Posts: 398
Joined: 2021-07-16 21:02
First name: Fabio
Last name: Alemagna

Re: Issue with file upload to explicit FTPS (python hangs)

#5 Post by oibaf » 2022-12-06 08:13

The problem has been fixed, the fix will be in the upcoming release.

piyushm
500 Command not understood
Posts: 3
Joined: 2023-05-03 14:19
First name: Piyush
Last name: M

Re: Issue with file upload to explicit FTPS (python hangs)

#6 Post by piyushm » 2023-05-03 14:43

I tried with the new version (v1.6.7), however the issue persists.

Additionally, the file that gets created on server comes as corrupt. Its a tar.gz file and when we extract it using winrar, the progress bar reaches towards end then gives error about corrupt archive.

Below is the sample code

Code: Select all

import ftplib
import os
from ftplib import FTP_TLS
ftp_conn = FTP_TLS()
ftp_conn.connect("ftp server url","ftp server port")
ftp_conn.login(user = "username", passwd = 'mypass')
ftp_conn.set_pasv(True)
ftp_conn.prot_p()
try:
	folder = 'path to folder'
	destpath = os.path.join(folder, os.path.basename("myfilename"))
	if folder not in ftp_conn.nlst():
		ftp_conn.mkd(folder)
	ftp_conn.cwd(folder)
	ftp_conn.storbinary("STOR " + os.path.basename(destpath), open("file to upload", "rb"), 1024)
	ftp_conn.close()
except ftplib.all_errors as ftp_err:
	print("something went wrong")
Below is the log output

Code: Select all

<Date> Info [Type] Message
<03-05-2023 20:07:53> FTP Session 29 92.18.27.20 appserver [Response] 227 Entering Passive Mode (92,18,91,21,224,6)
<03-05-2023 20:07:53> FTP Session 29 92.18.27.20 appserver [Command] NLST
<03-05-2023 20:07:53> FTP Session 29 92.18.27.20 appserver [Response] 150 About to start data transfer.
<03-05-2023 20:07:53> FTP Session 29 92.18.27.20 appserver [Error] TLS session of data connection not resumed.
<03-05-2023 20:07:53> FTP Session 29 92.18.27.20 appserver [Response] 425 Unable to build data connection: TLS session of data connection not resumed.

User avatar
botg
Site Admin
Posts: 35505
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: Issue with file upload to explicit FTPS (python hangs)

#7 Post by botg » 2023-05-03 17:45

Based on the log, no remote file was even touched to begin with.

piyushm
500 Command not understood
Posts: 3
Joined: 2023-05-03 14:19
First name: Piyush
Last name: M

Re: Issue with file upload to explicit FTPS (python hangs)

#8 Post by piyushm » 2023-05-04 08:33

Hello,

I'm sorry for the confusion. Let me explain the use case in detail.

The application tries to upload one more files consecutively by invoking upload_file_to_ftp method (snippet below) .

Last year when I was facing the timeout issue, I came across a fix to ftplib by overriding ftplib's ntransfercmd & storbinary commands. It seemed to worked for me at the time (our testing was insufficient). We recently discovered below error logs in out application:

Code: Select all

Traceback (most recent call last):
backupscript.py line 45, in storbinary
    return self.voidresp()
  File "/usr/lib/python3.8/ftplib.py", line 255, in voidresp
    resp = self.getresp()
  File "/usr/lib/python3.8/ftplib.py", line 240, in getresp
    resp = self.getmultiline()
  File "/usr/lib/python3.8/ftplib.py", line 226, in getmultiline
    line = self.getline()
  File "/usr/lib/python3.8/ftplib.py", line 208, in getline
    line = self.file.readline(self.maxline + 1)
AttributeError: 'NoneType' object has no attribute 'readline'
The uploaded backup archives were corrupt.

We have already upgraded to v1.6.7 of FZS to try fixing this, so cannot reproduce logs for previous version (1.5.x)

I tested afresh with two approaches:
1. Without the fix
Code:

Code: Select all

import ftplib
import os
from ftplib import FTP_TLS

def upload_file_to_ftp(srcfile, dst_filename):
	ftp_conn = FTP_TLS()
	ftp_conn.connect("ftp server url","ftp server port")
	ftp_conn.login(user = "username", passwd = 'mypass')
	ftp_conn.set_pasv(True)
	ftp_conn.prot_p()
	try:
		folder = 'path to folder'
		destpath = os.path.join(folder, os.path.basename(dst_filename))
		if folder not in ftp_conn.nlst():
			ftp_conn.mkd(folder)
		ftp_conn.cwd(folder)
		ftp_conn.storbinary("STOR " + os.path.basename(destpath), open(srcfile, "rb"), 1024)
		ftp_conn.close()
	except ftplib.all_errors as ftp_err:
		print("something went wrong")

upload_file_to_ftp(srcfile="/path/to/source/file1", dst_filename="file1")
upload_file_to_ftp(srcfile="/path/to/source/file2", dst_filename="file2")
Log output:

Code: Select all

<Date> Info [Type] Message
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 [Response] 220-FileZilla Server 1.6.7
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 [Response] 220 Please visit https://filezilla-project.org/
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 [Command] AUTH TLS
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 [Response] 234 Using authentication type TLS.
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 [Command] USER appserver
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 [Response] 331 Please, specify the password.
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 [Command] PASS ****
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Response] 230 Login successful.
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Command] PBSZ 0
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Response] 200 PBSZ=0
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Command] PROT P
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Response] 200 Protection level set to P
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Command] TYPE A
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Response] 200 Type set to A
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Command] PASV
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Response] 227 Entering Passive Mode (92,18,27,21,230,221)
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Command] NLST
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Response] 150 About to start data transfer.
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Error] TLS session of data connection not resumed.
<04-05-2023 13:47:26> FTP Session 212 92.18.27.20 appserver [Response] 425 Unable to build data connection: TLS session of data connection not resumed.
No directories or files were created due to the error.

2. With the fix
Code:

Code: Select all

import ftplib
import os
from ftplib import FTP_TLS

class PATCHED_FTP_TLS(FTP_TLS):
    """Explicit FTPS, with shared TLS session"""
    def ntransfercmd(self, cmd, rest=None):
        import ftplib
        conn, size = ftplib.FTP.ntransfercmd(self, cmd, rest)
        if self._prot_p:
            conn = self.context.wrap_socket(conn,
                                            server_hostname=self.host,
                                            session=self.sock.session)  # this is the fix
        return conn, size
    
    def storbinary(self, cmd, fp, blocksize=8192, callback=None, rest=None):
        """Store a file in binary mode.  A new port is created for you.
        Args:
            cmd: A STOR command.
            fp: A file-like object with a read(num_bytes) method.
            blocksize: The maximum data size to read from fp and send over
                        the connection at once.  [default: 8192]
            callback: An optional single parameter callable that is called on
                    each block of data after it is sent.  [default: None]
            rest: Passed to transfercmd().  [default: None]
        Returns:
            The response code.
        """
        self.voidcmd('TYPE I')
        with self.transfercmd(cmd, rest) as conn:
            while 1:
                buf = fp.read(blocksize)
                if not buf:
                    break
                conn.sendall(buf)
                if callback:
                    callback(buf)
            # shutdown ssl layer
            import ssl            
            if isinstance(conn, ssl.SSLSocket):
                # conn.unwrap()
                pass
            self.close()
        try:
            return self.voidresp()
        except Exception:
            # exc_det = frappe.get_traceback()
            # frappe.log_error("Error uploading: %s" % (exc_det))
            # send_email(False, "[Exception : FTP]", "Error uploading: {0}".format(exc_det))
            return ""

def upload_file_to_ftp(srcfile, dst_filename):
    ftp_conn = PATCHED_FTP_TLS()
    ftp_conn.connect("ftp server url","ftp server port")
    ftp_conn.login(user = "username", passwd = 'mypass')
    ftp_conn.set_pasv(True)
    ftp_conn.prot_p()
    try:
        folder = 'path to folder'
        destpath = os.path.join(folder, os.path.basename(dst_filename))
        if folder not in ftp_conn.nlst():
            ftp_conn.mkd(folder)
        ftp_conn.cwd(folder)
        ftp_conn.storbinary("STOR " + os.path.basename(destpath), open(srcfile, "rb"), 1024)
        ftp_conn.close()
    except ftplib.all_errors as ftp_err:
        print("something went wrong")

upload_file_to_ftp(srcfile="/path/to/source/file1", dst_filename="file1")
upload_file_to_ftp(srcfile="/path/to/source/file2", dst_filename="file2")
Log output:

Code: Select all

<Date> Info [Type] Message
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 [Response] 220-FileZilla Server 1.6.7
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 [Response] 220 Please visit https://filezilla-project.org/
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 [Command] AUTH TLS
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 [Response] 234 Using authentication type TLS.
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 [Command] USER appserver
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 [Response] 331 Please, specify the password.
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 [Command] PASS ****
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 230 Login successful.
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Command] PBSZ 0
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 200 PBSZ=0
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Command] PROT P
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 200 Protection level set to P
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Command] TYPE A
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 200 Type set to A
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Command] PASV
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 227 Entering Passive Mode (92,18,27,21,235,62)
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Command] NLST
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 150 Starting data transfer.
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 226 Operation successful
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Command] MKD 20230504_134336
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 257 "/20230504_134336" created successfully.
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Command] CWD 20230504_134336
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 250 CWD command successful
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Command] TYPE I
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 200 Type set to I
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Command] PASV
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 227 Entering Passive Mode (92,18,27,21,242,38)
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Command] STOR 20230504_134336-myapp-database.sql.gz
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Response] 150 About to start data transfer.
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Error] GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Status] Client did not properly shut down TLS connection
<04-05-2023 13:43:38> FTP Session 208 92.18.27.20 appserver [Error] Control channel closed with error from source 0. Reason: ECONNABORTED - Connection aborted.
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 [Response] 220-FileZilla Server 1.6.7
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 [Response] 220 Please visit https://filezilla-project.org/
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 [Command] AUTH TLS
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 [Response] 234 Using authentication type TLS.
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 [Command] USER appserver
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 [Response] 331 Please, specify the password.
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 [Command] PASS ****
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Response] 230 Login successful.
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Command] PBSZ 0
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Response] 200 PBSZ=0
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Command] PROT P
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Response] 200 Protection level set to P
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Command] TYPE A
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Response] 200 Type set to A
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Command] PASV
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Response] 227 Entering Passive Mode (92,18,27,21,217,117)
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Command] NLST
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Response] 150 About to start data transfer.
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Response] 226 Operation successful
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Command] CWD 20230504_134336
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Response] 250 CWD command successful
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Command] TYPE I
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Response] 200 Type set to I
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Command] PASV
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Response] 227 Entering Passive Mode (92,18,27,21,244,78)
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Command] STOR 20230504_134336-myapp-files.tar
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Response] 150 Starting data transfer.
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Error] GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Status] Client did not properly shut down TLS connection
<04-05-2023 13:43:39> FTP Session 209 92.18.27.20 appserver [Error] Control channel closed with error from source 0. Reason: ECONNABORTED - Connection aborted.
gunzip output

Code: Select all

$ gunzip 20230504_124937-myapp-database.sql.gz

gzip: 20230504_124937-myapp-database.sql.gz: unexpected end of file

User avatar
botg
Site Admin
Posts: 35505
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: Issue with file upload to explicit FTPS (python hangs)

#9 Post by botg » 2023-05-04 09:34

shutdown must be called on the TLS connection, such that a proper TLS closure alert can be sent. Depending on how the python stuff works, shutdown may in addition also need to be called on the underlying TCP socket to ensure the socket itself gets closed in an orderly fashion, such that all pending data gets written out.

piyushm
500 Command not understood
Posts: 3
Joined: 2023-05-03 14:19
First name: Piyush
Last name: M

Re: Issue with file upload to explicit FTPS (python hangs)

#10 Post by piyushm » 2023-05-05 10:30

Thanks for the reply botg. While I'm not sure how this can be achieved, I tried starting from zero with the mostly common extension of FTP_TLS which overrides the ntransfercmd command only (i.e. removed override of storbinary method).
Apparently, it seems to be working for most of the deployments. I'll postback when the testing is complete.

Post Reply