Logging
From charlesreid1
I discovered the Python logging module via Stack Overflow: http://stackoverflow.com/questions/9321741/printing-to-screen-and-writing-to-a-file-at-the-same-time
Python logging module can be used to log information at various levels (information, warn, debug, etc.), and log them to various destinations.
Contents
Single Destination
Single Destination (Screen) Simple Example
This is a simple script that creates a single logging destination (the screen/console) and logs an information message to the screen:
import logging
console = logging.StreamHandler()
console.setLevel(logging.INFO)
logging.getLogger('').addHandler(console)
logging.info('This message goes to the screen')
Single Destination (Screen) With Custom Formatting
The stock date formatting that logging uses is so-so. But you don't have to deal with it, you can redefine it:
import logging
console = logging.StreamHandler()
console.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s %(message)s',datefmt='%m-%d %H:%M')
console.setFormatter(formatter)
logging.getLogger('').addHandler(console)
logging.info('hello world')
Single Destination (File) With Custom Formatting
import logging
logging.basicConfig(level=logging.INFO,
format='%(asctime)s %(message)s',
datefmt='%m-%d %H:%M',
filename=log_file,
filemode='w')
logging.info('Hello file!')
Multiple Destinations
Multiple Destinations (File and Screen) Simple Example
Combining the above, to create a file logger and a screen logger:
import logging
logging.basicConfig(level=logging.INFO,
format='%(asctime)s %(message)s',
datefmt='%m-%d %H:%M',
filename=log_file,
filemode='w')
console = logging.StreamHandler()
console.setLevel(logging.INFO)
logging.getLogger('').addHandler(console)
logging.info('hello world')
Multiple Destinations (File and Screen) Complicated Example
This one's outta the logging cookbook: https://docs.python.org/2/howto/logging-cookbook.html#logging-to-multiple-destinations
import logging
# set up logging to file - see previous section for more details
logging.basicConfig(level=logging.DEBUG,
format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
datefmt='%m-%d %H:%M',
filename='/temp/myapp.log',
filemode='w')
# define a Handler which writes INFO messages or higher to the sys.stderr
console = logging.StreamHandler()
console.setLevel(logging.INFO)
# set a format which is simpler for console use
formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
# tell the handler to use this format
console.setFormatter(formatter)
# add the handler to the root logger
logging.getLogger('').addHandler(console)
# Now, we can log to the root logger, or any other logger. First the root...
logging.info('Jackdaws love my big sphinx of quartz.')
# Now, define a couple of other loggers which might represent areas in your
# application:
logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')
logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')
Strategies for Using Logging
Here's some info on how I use logging.
Separating Code
I set up all of my logging-related variables in a single file, which I can then import wherever I need to append information to the log. This ensures that everyone has access to the same logs, that all changes are propagated, and that code stays fresh and clean.
Printing Exceptions
My pattern is to handle exceptions with a call to logging.error() or logger.error(). When you call this function, you can also pass the exc_info argument to include exception information:
try:
open('/path/to/does/not/exist', 'rb')
except (SystemExit, KeyboardInterrupt):
raise
except Exception, e:
logger.error('Failed to open file', exc_info=True)
Signing Log Messages
Sometimes it is good to know which file, module, or process is logging particular information. A good case in point is if you have multithreaded code - different threads are writing different information, and you want each to sign their log messages differently.
In this case, you can create a sign_message() method, which is passed a plain string and which returns a string prepended with an identifying piece of information.
So the string "Encountered an exception" would become "[bot1] Encountered an exception". This, combined with logging's timestamp capabilities, will allow you to determine exactly what's happening and when.
Here's an example of this strategy from a log file for a Twitter bot flock. With lots of Twitter bots in a given Twitter bot flock, I don't want to have a separate log for each bot - I want each bot to print to the same log file. But I don't want hundreds of messages from who knows what bots! Here's an example of a "signed" log file, each bot prepending with its twitter handle:
02-22-2015 13:04 Hello darling! I am the Lumberjack logger. 02-22-2015 13:04 [@charlesreid1] Finished populating a new tweet queue with 5 tweets. 02-22-2015 13:04 [@charlesreid2] Finished populating a new tweet queue with 5 tweets. 02-22-2015 13:04 [@charlesreid3] Finished populating a new tweet queue with 5 tweets. 02-22-2015 13:04 [@charlesreid1] Hello world! That's number 1 of 5. 02-22-2015 13:04 [@charlesreid2] Hello world! That's number 1 of 5. 02-22-2015 13:04 [@charlesreid3] Hello world! That's number 1 of 5. 02-22-2015 13:04 [@charlesreid1] Hello world! That's number 2 of 5. 02-22-2015 13:04 [@charlesreid2] Hello world! That's number 2 of 5. 02-22-2015 13:04 [@charlesreid3] Hello world! That's number 2 of 5. 02-22-2015 13:04 [@charlesreid1] Hello world! That's number 3 of 5. 02-22-2015 13:04 [@charlesreid2] Hello world! That's number 3 of 5. 02-22-2015 13:04 [@charlesreid3] Hello world! That's number 3 of 5. 02-22-2015 13:04 [@charlesreid1] Hello world! That's number 4 of 5. 02-22-2015 13:04 [@charlesreid2] Hello world! That's number 4 of 5. 02-22-2015 13:04 [@charlesreid3] Hello world! That's number 4 of 5. 02-22-2015 13:04 [@charlesreid1] Hello world! That's number 5 of 5. 02-22-2015 13:04 [@charlesreid2] Hello world! That's number 5 of 5. 02-22-2015 13:04 [@charlesreid3] Hello world! That's number 5 of 5.
Logging Multiple Levels
You may have a need to log at multiple levels. The examples above mainly just use INFO, but what about DEBUG or WARN or others?
Well, it's dead simple. Whereas before you would be logging INFO level messages:
import logging
# set up your logging...
message1 = "Hello cruel world!"
logging.info(message1)
to log a debug message, you would say:
message1 = "Hello cruel world!"
logging.debug(message1)
and to log a warning message, you would say:
message1 = "Hello cruel world!"
logging.warn(message1)
List of log levels: https://docs.python.org/3/library/logging.html#levels
Level Numeric value CRITICAL 50 ERROR 40 WARNING 30 INFO 20 DEBUG 10 NOTSET 0
References
Logging documentation on Python.org: https://docs.python.org/3/library/logging.html
Good practice logging: https://fangpenlin.com/posts/2012/08/26/good-logging-practice-in-python/