Logging when print is the only option
(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'