ftplib.error_reply: 226 Transfer complete.

[ftputiluser]

ftplib version: 3.2

Python version: 2.7.10

FTP server: Synology FTP server ready (this is a NAS appliance)

Client OS version: CentOS linux 6.4 - Linux serverXXX 2.6.32-358.el6.x86_64 #1 SMP Fri Feb 22 00:31:26 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

I have implemented a python script using ftplib to transfer several images at night, usually it transfers about 1500 to 2000 images (between 500 Mb to 700 Mb) daily... the thing is that sometimes the script fails and throws the traceback:

Traceback (most recent call last):
  File "/etc/scripts/proyecto_escaneo/envia.py", line 227, in <module>
    main()
  File "/etc/scripts/proyecto_escaneo/envia.py", line 178, in main
    resp_stf = send_to_ftp(local_path,remote_path,row[2])
  File "/etc/scripts/proyecto_escaneo/envia.py", line 100, in send_to_ftp
    transfer = ftp.upload_if_newer(source_file_path, dest_file_path)
  File "/root/.pyenv/versions/2.7.10/lib/python2.7/site-packages/ftputil/host.py", line 471, in upload_if_newer
    callback=callback)
  File "/root/.pyenv/versions/2.7.10/lib/python2.7/site-packages/ftputil/file_transfer.py", line 184, in copy_file
    target_fobj = target_file.fobj()
  File "/root/.pyenv/versions/2.7.10/lib/python2.7/site-packages/ftputil/file_transfer.py", line 94, in fobj
    return self._host.open(self.name, self.mode)
  File "/root/.pyenv/versions/2.7.10/lib/python2.7/site-packages/ftputil/host.py", line 180, in open
    host = self._available_child()
  File "/root/.pyenv/versions/2.7.10/lib/python2.7/site-packages/ftputil/host.py", line 158, in _available_child
    host._session.pwd()
  File "/root/.pyenv/versions/2.7.10/lib/python2.7/ftplib.py", line 587, in pwd
    return parse257(resp)
  File "/root/.pyenv/versions/2.7.10/lib/python2.7/ftplib.py", line 872, in parse257
    raise error_reply, resp
ftplib.error_reply: 226 Transfer complete.

The script runs from cron at a specific time... this is the code I am using to transfer the files:

def send_to_ftp(source_path, dest_path, codigo_reg):
    resp = 0
    files = []
    counter = 0
    error_trans = 0

    if os.path.isdir(source_path):
        for item in os.listdir(source_path):
            files.append(item)

        try:

            ftp = ftputil.FTPHost(HOST_FTP, USER_FTP, PASSWD_FTP)

            if not ftp.path.isdir(dest_path):
                logging.info("Se creara directorio remoto: %s" % (dest_path))
                ftp.makedirs(dest_path)


            for file in files:
                counter += 1
                source_file_path = source_path + file
                dest_file_path = dest_path + file
                transfer = ftp.upload_if_newer(source_file_path, dest_file_path)
                if transfer == True:
                    logging.info("%d Archivo %s tranferido con exito a %s" % (counter, source_file_path, dest_file_path))
                else:
                    logging.warning("%d Archivo %s NO se transfirio con exito (o ya existia en destino) a %s" % (counter, source_file_path, dest_file_path))
                    error_trans += 1

        except ftputil.error.FTPError, e:
            logging.critical("Error send_to_ftp() %s" % (e.args[0]))
            resp = -1
            return [resp, counter, error_trans, e]

        finally:
            if hasattr(ftputil, "ftp"):
                ftp.close()
    else:
        resp = -2

    return [resp, counter, error_trans]

This only happens a sometimes and I can't figure it out!!!

Any help would be very helpful.

[schwa]

Thanks for the report!

First of all, I don't see anything in your code that I'd expect to cause the traceback.

Replying to ftputiluser:

and I can't figure it out!!!

Don't panic! :-)

When a data transfer finishes, the server sends a 226 code like the one you're seeing in the traceback. There's the code in ftputil/file.py to get any "pending" messages from the server before marking the file closed:

    def close(self):
        """Close the `FTPFile`."""
        ...
        try:
            ...
            try:
                with ftputil.error.ftplib_error_to_ftp_io_error:
                    self._session.voidresp()
            except ftputil.error.FTPIOError as exc:
                # Ignore some errors, see tickets #51 and #17 at
                # http://ftputil.sschwarzer.net/trac/ticket/51 and
                # http://ftputil.sschwarzer.net/trac/ticket/17,
                # respectively.
                exc = str(exc)
                error_code = exc[:3]
                if exc.splitlines()[0] != "timed out" and \
                  error_code not in ("150", "426", "450", "451"):
                    raise
        finally:
            ...
            # If something went wrong before, the file is probably
            # defunct and subsequent calls to `close` won't help
            # either, so we consider the file closed for practical
            # purposes.
            self.closed = True

I have the suspicion that in your case the server sometimes sends the 226 response twice (or some other 2xx response and then 226). This would explain why the problem only occurs sporadically.

The code host._session.pwd() in FTPHost._available_child then accidentally "picks up" the "remaining" 226 status and fails because the pwd call expects a reply with a 257 status.

I'm still thinking about a proper way to fix or work around this problem.

Ideas:

• Call voidresp in file.close more than once. I don't think that's a good idea because this is kind of a shot in the dark. We don't know what responses subsequent voidresp calls would "pick up". Also, if the server doesn't send anything, we have to wait until a timeout happens.

• Catch the error_reply exception from host._session.pwd and continue with the next child session candidate. This is an "obvious" way to handle the problem. If the pwd call fails, the child session isn't usable, similar to the session timeout case, which catches error_temp.

Still, I'm not comfortable with implementing the second idea right now because I'd like to find out what actually happens. That is, what is the response for the session which was picked up by the voidresp call in close? Possibly more is going on than I assume and the findings may give some insight, so that we should handle the problem differently.

I'm going to attach some instrumented files.

[schwa]

Instrumented host.py

[schwa]

Instrumented file.py

[schwa]

I've attached two files to this ticket. Please put them in the ftputil library directory to replace the original files. Of course you should make backup copies of the files to restore them later.

Please redirect the resulting print output from your program to a file, compress it with tar or zip and attach it to this ticket. If you want, you can replace the print calls with logging calls. Anyway, I need the results. :-)

[schwa]

If your code has other print calls, you may want to filter the results with grep to include only the lines starting with "=== ":

grep "^=== " debug_output.txt > debug_output_filtered.txt

[ftputiluser]

Thanks for the quick reply!!!... I'll do the required changes and send you the results... only think is I am not going to be able to do this until next monday - company closed for holidays.

I'll let you know as soon as I have the results!

Regards and happy holidays.

[ftputiluser]

Hi,

I replaced the files, but I've got an error message when I run the program:

Traceback (most recent call last):
  File "./envia.py", line 8, in <module>
    import ftputil
  File "/root/.pyenv/versions/2.7.10/lib/python2.7/site-packages/ftputil/__init__.py", line 50, in <module>
    from ftputil.host    import FTPHost
  File "/root/.pyenv/versions/2.7.10/lib/python2.7/site-packages/ftputil/host.py", line 23, in <module>
    import ftputil.session_adapter
ImportError: No module named session_adapter

Please advice...

[schwa]

Oops, sorry. You need session_adapter.py, which I implemented to fix ticket #100. Please get the file from ftputil/session_adapter.py?format=txt and put it into the ftputil directory. Then the import should work.

[schwa]

Alternatively, you can download and unpack ftputil 3.3 and replace host.py and file.py with the files attached to this ticket.

[ftputiluser]

Just wanted you to know that the error has not presented itself again!!!...

[schwa]

That's no problem from my side. I suggest you let me know as soon as the error happens again.

If nothing happens within half a year or so, I may close the ticket as "worksforme". I do such things to avoid that open tickets accumulate if I can't reproduce a problem myself and don't have debugging data from the reporter.

Therefore, as soon as you have debugging data availabe, please reopen the ticket (if it's already closed) and attach the debugging data.

[ftputiluser]

Hello Schwa... the error has presented itself again!, this time I upgraded ftputil to latest version 3.3 and replaced files: host.py and file.py with the ones you attached to this ticket, then ran the script again and this time the error was thrown again... this is the output I got:

=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea1b6ca590> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea1b6ca590> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea1b6ca590> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169d1290> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169d1290> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169d1290> 226 Transfer complete.
(u'=== FTPFile, exception:', <ftputil.host.FTPHost object at 0x7fea169d1110>, '226 Transfer complete.')
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169d1590> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea1b6ca590> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea1b6ca590> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea1b6ca590> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169ae390> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169d1290> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169d1290> 226 Transfer complete.
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169d1290> 226 Transfer complete.
(u'=== FTPFile, exception:', <ftputil.host.FTPHost object at 0x7fea169d1110>, '226 Transfer complete.')
=== FTPFile, response: <ftputil.file.FTPFile object at 0x7fea169d1590> 226 Transfer complete.

Hope this is meaningful to you and can help resolve the problem...

The script has been working without problems for 1 1/2 month (aprox.) until this last weekend.

Please advice...

Best regards.

[schwa]

Thanks a lot for your feedback. Yes, this is meaningful, - but I don't know yet what to do with it. :-)

The server is supposed to send the 226 code after a successful transfer, or after an ABORT command, which doesn't apply here. If the 226 is seen after a PWD command, either the server sent more than one 226 (quite unlikely), or the 226 hadn't been read/seen before when the remote file was closed in FTPFile.close (much more likely).

I'm not yet sure how to deal with this. I think I'll have _available_child catch the error_reply exception, but I have the feeling that this is somewhat hackish and that there's a better solution. That said, I'd rather go for the first approach if I can't come up with a better one.

For the record, here are two interesting pages I found on the subject.

• ​https://stackoverflow.com/questions/15343022/dont-always-get-a-226-transfer-ok-at-the-end-of-an-ftp-upload
• ​https://www.mail-archive.com/ftpserver-users@mina.apache.org/msg01005.html

[ftputiluser]

Hi Schwa... unfortunately I am forced to change the protocol used to do this job/transfers (probably using pysftp) to avoid this failure... this process is important for the company...

I will do so in the following days progressively, so in the meantime if you come up with an idea for me to try just let me know... I'll try to help you as long as I can...

Regards Schwa!

[schwa]

I'm now handling the delayed 226 reply by catching error_reply in _available_child, see [8a846e32b6de].

[schwa]

I just released ftputil 3.3.1 with the fix. I hope that makes your move to another tool or library unnecessary. :-)

By the way, would pysftp handle the problem of this ticket?