Python and Logging

Python features a pretty cool (IMHO) logging feature that I am using for my project.  It allows you to log messages with varying levels of severity from DEBUG, INFO, WARNING, ERROR, to CRITICAL.  The code that I am using is shown below.     A sample of output is shown at the bottom of this post.

First we setup a logger.  The name "Main" will be used to connect to this logger from other modules.

    # Setup my logger    logger = logging.getLogger("Main") 

I want my messages to be logged to a file as well so this is done here.   Formatting for messages going to the file include prefixes for the time, name of the module from where the message comes, and the severity level for the message.  

    # Send output to a file as well
    loggingFormat = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"         
    logging.basicConfig(filename='logs/Robot.log', level=logging.INFO, /
        format=loggingFormat)

Create the handler that will be used to log our messages. 

    # Create console handler and set level to debug     
    ch = logging.StreamHandler()
        
I have a command line option that specifies the level of messages to be displayed on the console.  The following dictionary expands the code that I use there.   The two eval statements then apply the selected level to the logging handler.   Obviously this could be hard coded to dispense with the "eval" statement.

    # Set appropriate logging level based on options
    loggingLevels = {"D" : "DEBUG",
                     "I" : "INFO",
                     "W" : "WARNING",
                     "E" : "ERROR",
                     "C" : "CRITICAL"
                    } 
    eval("ch.setLevel(logging." + loggingLevels[options.loggingLevel] + ")") 
    eval("logger.setLevel(logging." + loggingLevels[options.loggingLevel] + ")")    

We want our messages to be preceded by the severity level so we build a formatter that will do that here.  There are a lot of formatting options but this is all I wanted for the console messages.

    # Create formatter     
    formatter = logging.Formatter("%(levelname)s - %(message)s")
    # Add formatter to ch         ch.setFormatter(formatter)

Finally we add the channel that we created above to our logger and we are ready to go.   My first message is at the debug level.

    # Add ch to logger    
    logger.addHandler(ch)    logger.debug("Initiating startup")

Modules within the robot use the same logger by connecting to it when they init:

    # Setup logging by connecting to our main logger
    self.logger = logging.getLogger('Main.' + __name__)

If I were going to be honest I would have to say that the above methods to get logging going are not all that straight forward!   It works but seems a bit convoluted to me.

Sample output from the startup of the 'bot, showing all messages, is below:

    pi@raspberrypi ~ $ sudo ./xxr  -lD  --disableStream
    DEBUG - Initiating startup with the following options:
    DEBUG -     map = ''
    DEBUG -     testBed = 'None'
    DEBUG -     disableStream = 'True'
    DEBUG -     auto = 'M'
    DEBUG -     disablePropulsion = 'None'
    DEBUG -     serialPort = 'ttyUSB0'
    DEBUG -     commandStart = 'True'
    DEBUG -     shutdown = 'None'
    DEBUG -     loggingLevel = 'D'
    DEBUG -     voltageCheck = 'None'
    DEBUG - Starting hardware interface and utilities
    DEBUG - Initialized utility
    DEBUG - Hardware interface has started
    DEBUG - Reference voltage at 4.8 volts
    DEBUG - Reference adjustment 0.965
    DEBUG - RPi Main voltage at 6.547 volts
    DEBUG - RPi voltage at 4.243 volts
    DEBUG - Main voltage at 7.881 volts
    DEBUG - 5v Bus voltage at 4.839 volts
    DEBUG - Starting daemon communication queues
    DEBUG - Killing old daemons
    DEBUG - Restarting daemons
    DEBUG - Disable stream command queued for action
    DEBUG - Starting robot classes
    DEBUG - Initialized control
    DEBUG - Initialized bridge
    DEBUG - Sensor at 0h and 0v
    DEBUG - Initialized sensor
    DEBUG - Initialized radar
    DEBUG - Initialized navigation
    DEBUG - Current bearing 220.0
    DEBUG - Initialized propulsion
    DEBUG - Initialized mapping
    DEBUG - Initialized proximity
    DEBUG - Robot is waiting for commands
    DEBUG - ----------------------------------
    DEBUG - RPi Main voltage at 6.490 volts
    DEBUG - RPi voltage at 4.196 volts
    DEBUG - Main voltage at 7.881 volts
    DEBUG - 5v Bus voltage at 4.839 volts
    DEBUG - Current range from sensor is 21.07421875
    DEBUG - Message queues are empty
    DEBUG - Current sensor (and robot) bearing 220.0
    INFO - Telemetry uploaded
    DEBUG - ----------------------------------