Logging can offer much more flexibility than simply printing a message to the console but it can be difficult to know where to start. This post looks a some examples of simple python logging to get you started.
Why ‘log’ instead of ‘print’?
Printing to the console is usually one of the first things you learn with any language. It’s easy to use ‘print()‘ to give messages to your users, display debugging for you, and output error messages and warnings.
But it’s also easy to get in a muddle with commenting and uncommenting print statements when you are trying to debug.
Instead of using print we can use logging which allows us to:
- specify different levels of message,
- control when messages are logged
- direct outputs to files, screen, and elsewhere
Simple logging in python
A Simple Example
Logging can be very simple. This example shows how by just importing the logging module and setting the logging level you can do everything that you were previously doing with print, but with greater flexibility.
import logging # Set the logging level to log all messages 'debug' and higher logging.basicConfig(level=logging.DEBUG) # Write log messages at different levels logging.debug("write this to the log - debug") logging.info("write this to the log - info") logging.error("write this to the log - error") logging.warning("write this to the log - warning") logging.critical("write this to the log - critical")
Which will print the following output:
DEBUG:root:save this to the log - debug INFO:root:save this to the log - info ERROR:root:save this to the log - error WARNING:root:save this to the log - warning CRITICAL:root:save this to the log - critical
For normal use, you will probably want the logging level set to ‘info’ or perhaps ‘warning’, and go to ‘debug’ when you want see debugging messages.
Now, rather than commenting and uncommenting print statements, we can just use different levels of logging.
When you send messages to the logger, you specify their level. This esssentially means that you can filter out messages depending on their logging level. For example it’s unlikely that you would want to print out the results of each iteration of a loop during normal use, but this can be very useful for debugging.
||Use it for|
|Debug||Instead of having a print statement that you comment out, you use the debugging logging level. Examples might include showing the index and values in a loop, or checking that a variable stores the value you expect.|
|Info||You can use this logging level for things like printing messages to the user, returning results of functions that the user will want to see (i.e. not debugging info).|
|Warning||You could I suppose just use ‘info’ for this. For important messages that the user may want to intervene on – e.g. incorrect login info, loading large files and so on|
|Error||Use this when something goes wrong – can also be combined with exception handling.|
|Critical||There probably aren’t all that many situations that warrant a ‘critical’ message over an ‘error’ message. This option is here nevertheless.|
Output to file rather than the console
Often it is more useful to output the log to a separate log file, rather than to the console. This example will create a log file ‘example.log’, and save to it the same logging outputs as before.
import logging LOG_FILENAME = 'example.log' logging.basicConfig(filename=LOG_FILENAME,level=logging.DEBUG) logging.debug("write this message to log file - debug")
Note: this will stop logging information being directed to the console. See below for how to have output to both the console and a file.
Adding a timestamp to the output
The basic logging does not include any date or timestamp of when the log was made. To add a timestamp was can set the formatting to the logging basicConfig:
import logging format_string = '%(levelname)s: %(asctime)s: %(message)s' logging.basicConfig(level=logging.DEBUG, filename="example.log", format=format_string) logging.debug("write this to the log - debug")
Which will output the log message with the log level, the date and time, along with our message.
DEBUG: 2017-02-14 20:38:01,457 write this to the log - debug
Output to a file and the console
In the simple examples above we have had to chose between either output to the console, or output to a file. It is also possible to output to both the console and to a file. We’ll need to do a little be more set up for this, however.
The first difference is that we will create an instance of logging (called ‘logger’ in this case). Creating our logger object will give us the flexibility we need to set outputs for console and log files.
import logging logging_format = '%(levelname)s: %(asctime)s: %(message)s' logging.basicConfig(level=logging.DEBUG, format=logging_format) logger = logging.getLogger() # create a file handler handler = logging.FileHandler('console_and_file.log') # create a logging format formatter = logging.Formatter(logging_format) handler.setFormatter(formatter) # add the handlers to the logger logger.addHandler(handler) logger.info("save this to the log")
Customise the logger further
Change the logging level
It’s quite common to want to be able to output a different level of detail to the console and the log file. It might be that we want all messages to go to the log file, but only the most important (say warning and above) to be directed to the screen. We may also want the log file to be timestamped, but the console output to not take a timestamp. We can do that by modifying the above example.
import logging #set different formats for logging output console_logging_format = '%(levelname)s: %(message)s' file_logging_format = '%(levelname)s: %(asctime)s: %(message)s' # configure logger logging.basicConfig(level=logging.DEBUG, format=console_logging_format) logger = logging.getLogger() # create a file handler for output file handler = logging.FileHandler('console_and_file.log') # set the logging level for log file handler.setLevel(logging.INFO) # create a logging format formatter = logging.Formatter(file_logging_format) handler.setFormatter(formatter) # add the handlers to the logger logger.addHandler(handler) # output logging messages logger.info("save this to the log - info logger") logger.debug("save this to the log - debug logger") logger.error("save this to the log - error - logger") logger.warning("save this to the log - warning - logger") logger.critical("save this to the log - critical - logger")
The file output is now:
INFO: 2017-02-12 15:10:52,325: save this to the log - info logger ERROR: 2017-02-12 15:10:52,328: save this to the log - error - logger WARNING: 2017-02-12 15:10:52,329: save this to the log - warning - logger CRITICAL: 2017-02-12 15:10:52,330: save this to the log - critical - logger
Which has a timestamp, but is not capturing the debug and info level messages.
The console output on the other hand is:
INFO: save this to the log - info logger DEBUG: save this to the log - debug logger ERROR: save this to the log - error - logger WARNING: save this to the log - warning - logger CRITICAL: save this to the log - critical - logge
Which keeps the debug level info, but does not have a timestamp.