Eric Stein

(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'