ericstein

(Originally published on my old github blog on  2016-02-09)

I ran into a particularly annoying problem while working with Python's ftplib. My script, which downloads a large number of files from an FTP server overnight, was stopping. It wasn't failing, rather, just hanging. This code runs as part of a larger script that contains logging functions. I thought I should add logging for the FTP calls.

The docs describe a set_debug method for the FTP instance. Great. I can use that and see how the script is interacting with the server. The problem is that the FTP module uses print statements to pass this debugging info.

if self.debugging:
    print '*welcome*', self.sanitize(self.welcome)

I could use redirection to capture stdout, but I want the script to use the logging I've already set up.

This allowed me to play with decorators and resulted in this:

import sys
import StringIO
def logoutput(level='info'):
    def wrapper(f):
        def inner(*args, **kwargs):
            # Save the old stdout
            oldstdout = sys.stdout
            # Set stdout to a file like object
            sys.stdout = StringIO.StringIO()
            # run the original function
            output = f(*args, **kwargs)
            # write to the specific logging level
            getattr(logging, level)(sys.stdout.getvalue())
            # set stdout to what it was before 
            sys.stdout = oldstdout 
            return output
        return inner
    return wrapper

And here's how it's used:

import logging
import datetime
import ftplib

logging.basicConfig(filename=os.path.join('logdir', 'downloads{}.log'.format(datetime.date.today()),
    level=logging.DEBUG, format='%(asctime)s %(message)s')

@logoutput(level='debug')
def download():
    server = ftplib.FTP('ftp.example.com')
    server.set_debuglevel(1)
    server.login()
    with open('wanted.txt', 'w') as outfile:
        server.retrbinary('RETR wanted.txt', oufile.write, blocksize=8192)
    server.quit()

logging.debug('Starting the download function')
download()

This will give you one log file per day with very nice output:

2016-02-06 00:15:05,437 Starting the download function.
2016-02-06 00:15:05,570 *cmd* 'USER anonymous'
*resp* '331 Anonymous login ok'
*resp* '230-Anonymous access granted, restrictions apply\n \n Please read the file README.txt\n230    it was last modified on Tue Aug 15 14:29:31 2000 - 5653 days ago'
2016-02-06 00:15:05,959 *cmd* 'TYPE I'
*resp* '200 Type set to I'
*cmd* 'PASV'
*resp* '227 Entering Passive Mode (162,138,203,13,190,33).'
*cmd* 'RETR wanted.txt'
*resp* '150 Opening BINARY mode data connection for wanted.txt (207503 bytes)'
*resp* '226 Transfer complete'