In [ ]:
import logging
logging.info("test info msg")
logging.warning("test warning msg")
In the two call just made, one printed its message to STDOUT, while the other seemed to do nothing. What's going on?
Calls the the module-level functions debug, info, warning, etc make implicit calls to the function logging.basicConfig. This initiates the "root logger", and configures it to do a minimal set of useful things, including streaming certain messages to the console. The default severity level (below which messages are not passed on) is WARNING, which explains why the INFO-level message was not displayed.
Let's explicitly access the root logger and change the level.
Logger objects are NEVER initialized explicitly. Instead, specific loggers are generated by a factory function: logging.getLogger(MY_LOGGER_NAME). Subsequent calls to the same function from within the same Python application will always return the SAME Logger object.
In [ ]:
# get a named logger from the logger factory
logr = logging.getLogger("root")
# note: "getLogger"
# - is a module-level function
# - always returns the same object for a given argument
# - is camel-cased
In [ ]:
# let's see what this thing is
dir(logr)
In [ ]:
# Now we'll set its level and test.
logr.setLevel(logging.INFO)
# equivalently:
# logr.setLevel("INFO")
logr.info("test info msg")
logging.warning("test warning msg")
Great! It works. You've now seen a little demo of the default (root) logger, its severity filter, and how to change it.
Note the tricksery: I called the info method of the Logger object named logr, but I called the warning method of the module called logging. Yet they both were handled by the same (root) logger.
You can think of the message path as a series of possible rejections:
In [ ]:
from IPython.display import Image
Image("https://docs.python.org/2/_images/logging_flow.png")
As mentioned previously, the logging.basicConfig function configures a Logger object named root, and affiliates it with a Handler and that Handler with a Formatter.
Let's explicitly build a system that replicates this behavior:
In [ ]:
# Start by building the objects
# get a logger from the factory
snarf = logging.getLogger("my_logger_named_snarf")
snarf.setLevel(logging.INFO)
# this will be discussed later
snarf.propagate = False
# make a handler; default StreamHandler behavior is to stream the output to STDOUT
snarfs_handler = logging.StreamHandler()
# NOTE: level-based filters can be set in the handler as well as the logger
snarfs_handler.setLevel(logging.WARNING)
# make a formatter with the magic syntax sauce
magic_syntax_sauce = "%(levelname)s:%(name)s:%(message)s"
snarfs_handlers_formatter = logging.Formatter(magic_syntax_sauce)
In [ ]:
# ipython-specific digression: remove all handlers
## This is only relevant in an environment (like ipython) in which commands get run multiple times
## in the same python process. Restart the kernel to reset the logging environment.
snarf.handlers = []
In [ ]:
# associate everything
snarfs_handler.setFormatter(snarfs_handlers_formatter)
snarf.addHandler(snarfs_handler)
In [ ]:
# we should see only the WARNING message, since that's the setting in the handler
snarf.debug("test debug")
snarf.info("test info")
snarf.warning("test warning")
Yeah!
Let's do the following:
In [ ]:
import sys
import logging
class Pet(object):
def __init__(self, **kwargs):
# attach all keyword arguments
[setattr(self,k,v) for k,v in kwargs.items()]
# get the class name
self.animal = self.__class__.__name__
assert self.animal != "Pet"
def talk(self):
sys.stdout.write("{}\n".format(self.word))
def get_bio(self):
sys.stdout.write("This pet is a {0} named {1}. It has {2} legs.\n".format(self.animal,self.name,self.legs))
class Cat(Pet):
def __init__(self, **kwargs):
# default values
self.name = "Tom"
self.word = "Meow"
self.legs = 4
super(Cat,self).__init__(**kwargs)
class Dog(Pet):
def __init__(self, **kwargs):
# default values
self.name = "Fido"
self.word = "Arf!"
self.legs = 4
super(Dog,self).__init__(**kwargs)
class Snake(Pet):
def __init__(self, **kwargs):
# default values
self.name = "Voltemort"
self.word = "Sssss"
self.legs = 0
super(Snake,self).__init__(**kwargs)
Now we create a few pet objects.
In [ ]:
c = Cat()
c.get_bio()
In [ ]:
d = Dog(name="Lassie")
d.get_bio()
In [ ]:
# This command is commented-out, so that the "run all" option works.
#p = Pet(name="Mr. Centipede",legs=100)
In [ ]:
s_1 = Snake()
s_2 = Snake(word="Ss")
s_1.get_bio()
s_1.talk()
print("The second snake says: {}".format(s_2.word))
In [ ]:
# helper function
def the_pets_speak(list_of_pets):
sys.stdout.write("The pets will speak now:\n")
for pet in list_of_pets:
pet.talk()
In [ ]:
list_of_pets = [c,d,s_1,s_2]
the_pets_speak(list_of_pets)
In [ ]:
# a new base class that is derived from the old base class
class LoggablePet(Pet):
def __init__(self, **kwargs):
# call the constructor of the parrent class first
super(LoggablePet,self).__init__(**kwargs)
# now make a logger that is named by the animal and its name
self.logger_name = "pet_world." + self.animal + "." + self.name
self.logger = logging.getLogger(self.logger_name)
# The only change below here is to inherit from LoggablePet, instead of Pet
class Cat(LoggablePet):
def __init__(self, **kwargs):
# default values
self.name = "Tom"
self.word = "Meow"
self.legs = 4
super(Cat,self).__init__(**kwargs)
class Dog(LoggablePet):
def __init__(self, **kwargs):
# default values
self.name = "Fido"
self.word = "Arf!"
self.legs = 4
super(Dog,self).__init__(**kwargs)
class Snake(LoggablePet):
def __init__(self, **kwargs):
# default values
self.name = "Voltemort"
self.word = "Sssss"
self.legs = 0
super(Snake,self).__init__(**kwargs)
In [ ]:
c = Cat(name="Boots")
c.logger.debug("test debug message")
[crickets]
(...unless you're rerunning this cell after making changes to the logger in cells below; remember, loggers are persisted for the life of the kernel and getLogger will always return the same object given the same argument...)
We need to change the level of the logger, so it passes on a DEBUG message.
In [ ]:
c.logger.setLevel(logging.DEBUG)
c.logger.debug("test debug message")
We've added no handlers to the logger, yet the message was handled by a StreamHandler with a basic Formatter set. How did this happen?
In [ ]:
c.logger.parent
Aha! the default parent logger is a RootLogger object with a default StreamHandler and Formatter configured. We can change this behavior in two ways:
propagate flag, meaning that messages are not passed to parent loggers
In [ ]:
## handler-removing method
# save the root logger's handler
stream_handler = c.logger.parent.handlers[0]
# empty the handlers list
c.logger.parent.handlers = []
# and test!
c.logger.debug("test debug message")
# add it back, if you wish
#c.logger.parent.addHandler(stream_handler)
In [ ]:
## change the propagate flag
#c.logger.propagate = False
#c.logger.debug("test debug message")
#c.logger.propagate = True
Remember that we've left the root logger with no handlers.
Now, let's try to meet the specifications from the top of the section.
Start by making a FileHandler.
In [ ]:
file_path = "./logs/"
# delete all the files at this location
!rm ./logs/*
log_file_name = file_path + c.logger_name + ".log"
file_handler = logging.FileHandler(log_file_name)
c.logger.addHandler(file_handler) # FYI: adding the same handler a second time has no effect
c.logger.debug("test debug message")
Check for a log file at the specified path.
Also notice that the log file format is a bit unhelpful.
In [ ]:
better_magic_syntax_sauce = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
file_formatter = logging.Formatter(better_magic_syntax_sauce)
file_handler.setFormatter(file_formatter)
c.logger.debug("test debug message")
Also note that the default level of the handler must be DEBUG, because it printed out message. Let's test that:
In [ ]:
file_handler.setLevel(logging.INFO)
c.logger.debug("shouldn't see this DEBUG message")
c.logger.info("should see this INFO message")
# and set it back
file_handler.setLevel(logging.DEBUG)
Now that we have a good handler and formatter, let's just build them into the class definitions. Let's also add some built-in logging.
In [ ]:
class LoggablePet(Pet):
def __init__(self, **kwargs):
# call the constructor of the parrent class first
super(LoggablePet,self).__init__(**kwargs)
# set up logger
self.logger_name = "pet_world." + self.animal + "." + self.name
self.logger = logging.getLogger(self.logger_name)
self.logger.setLevel(logging.DEBUG)
# set up handler
self.log_file_name = file_path + self.logger_name + ".log"
self.file_handler = logging.FileHandler(self.log_file_name)
self.file_handler.setLevel(logging.DEBUG)
self.logger.addHandler(self.file_handler)
# add formatter
self.file_handler.setFormatter(file_formatter)
# built-in logging
self.logger.info("{} is ready for play!".format(self.name))
# no changes below here
class Cat(LoggablePet):
def __init__(self, **kwargs):
# default values
self.name = "Tom"
self.word = "Meow"
self.legs = 4
super(Cat,self).__init__(**kwargs)
class Dog(LoggablePet):
def __init__(self, **kwargs):
# default values
self.name = "Fido"
self.word = "Arf!"
self.legs = 4
super(Dog,self).__init__(**kwargs)
class Snake(LoggablePet):
def __init__(self, **kwargs):
# default values
self.name = "Voltemort"
self.word = "Sssss"
self.legs = 0
super(Snake,self).__init__(**kwargs)
In [ ]:
d = Dog()
Log message looks good in file.
In [ ]:
s_1 = Snake()
s_2 = Snake(name="Lucifer")
# Be careful with pets of the same name and animal type but different attributes!
Now let's meet the other specifications from above; namely, a parent logger that prints WARNING and above to the screen, while printing everything to a file.
IMPORTANT: Hierarchies of loggers (apart from the RootLogger) are defined by period-separated logger names. For example, a logger named "abc.def" is automatically a child of a logger named "abc". This is why all the Pet object logger names start with "pet_world".
In [ ]:
# get the parent logger and set its base level
global_logger = logging.getLogger("pet_world")
global_logger.setLevel(logging.DEBUG)
# make a file handler
global_file_handler = logging.FileHandler(file_path + "global.log")
global_file_handler.setFormatter(file_formatter)
# make a stream handler
global_stream_handler = logging.StreamHandler()
global_stream_handler.setLevel(logging.WARNING)
# add the handlers
global_logger.handlers = []
global_logger.addHandler(global_file_handler)
global_logger.addHandler(global_stream_handler)
In [ ]:
global_logger.info("info")
global_logger.warning("warning")
In [ ]:
d.logger.info("some doggy info")
d.logger.warning("a doggy warning!")
So, WARNING and above messages are printed to the screen not only for the global logger, but also for its children (i.e. any loggers with names that start with "pet_world"). Additionally, each logger prints every message to a file.
Yay! We built the specified logging system.
Most libraries that include logging use loggers defined at the module level. Therefore, a commonly-used module naming convention is:
logger = logging.getLogger(__name__)
The benefit of this is that all loggers can be determined at compile-time (rather than run-time). To investigate this paradigm, each class has been put in a separate module.
The last task in the tutorial is to investigate the logging configuration file found in the local directory, along with the pet modules and the run.py script.
In [ ]: