Tag: logging


A ReportingLogger class for Lokai

March 24th, 2012 — 6:57pm

Now that we have looked at logging requirements and the logging module it’s time to look at some code. This is the basic Logger class that I use. It provides statistics recording for making commit/rollback decisions, and it provides a method for executing handler methods from the logger instance. This is quite powerful and allows the calling program to interact with handlers without knowing the detail of what handlers actually exist.

We start in the obvious way by inheriting from Logger class. We initialise the statistics, and inhibit propagation up the hierarchy. Inhibiting propagation is open to debate. In my case it has the effect of limiting all of my file related actions to the lower level of the hierarchy, and leaves the root level to flush output when the program exits.

class RecordingLogger(logging.Logger):

    def __init__(self, name, level=logging.NOTSET):
        logging.Logger.__init__(self, name=name, level=level)
        self._set_stats()
        self.propagate = 0

_set_stats initialises the level accumulators

    def _set_stats(self):
        self.stats = {'CRITICAL': 0,
                      'ERROR': 0,
                      'WARNING': 0,
                      'INFO': 0,
                      'MONITOR': 0,
                      'DEBUG': 0}

Overwrite _log just to add a line that accumulates the statistics. Note that it uses the message level name rather than the level value.

    def _log(self, level, msg, args, exc_info=None, extra=None):
        self.stats[logging.getLevelName(level)] += 1
        logging.Logger._log(self, level=level, msg=msg, args=args,
                            exc_info=exc_info, extra=extra)

execute is a key method that passes a function name and some arguments to all handlers that the logger can find. I use it for flushing buffers and setting email subject text. It can be used to execute any function you might want to define on a handler. The method is actually an iterator that returns any response that it finds from each execution. The method execute_all assumes you don’t care about the returns and simply executes everything.

    def execute(self, function, *args, **kwargs):
        """ Apply this function to all the handlers for this
            logger. Ignore if the handler does not support the
            function.

            This supports return values by yielding the answer at each
            level.
        """
        c = self
        while c:
            for hdlr in c.handlers:
                if hasattr(hdlr, function):
                    target = getattr(hdlr, function)
                    if callable(target):
                        yield target(*args, **kwargs)
            if not c.propagate:
                c = None    #break out
            else:
                c = c.parent

    def execute_all(self, function, *args, **kwargs):
        """ call execute in a loop and throw away any responses.
        """
        for resp in self.execute(function, *args, **kwargs):
            pass

Add a flush method that flushes all findable handlers and resets the statistics.

 
    def flush(self):
        self.execute_all('flush')
        self._set_stats()

And then we set this to be the default logger

    
logging.setLoggerClass(RecordingLogger)

And that’s it, really. The next step is to look at a handler and see what goes on there.

Comments Off on A ReportingLogger class for Lokai | Development

Python Logging Module Gaps and Matches

March 23rd, 2012 — 11:08pm

I have a number of requirements for logging. This is how I’ve matched them up to the logging module.

  • Process related messages are emailed to a system manager email address.

    I’ve decided that I want to distinguish messages by level. So for this case any CRITICAL message needs to go to the system manager address. This means that I need an email handler with a filter that selects messages with a level higher than some limit. A normal default filter will do this, using setLevel() on the relevant handlers.

  • File related messages are emailed to a data manager address.

    Using the level concept, I need to identify messages with a level less than some limit. This is not a default test, so I need a custom filter that I can associate with another email handler.

    I could, of course, have used two different named loggers to make this distinction, and that might have been more in the spirit of the logging module. I havn’t got a particular reason for using message levels, but it seems to be doing the job so I’m not going to change it yet.

  • Messages for a single file are grouped together.

    This is easily achieved with a buffering handler. Messages are accumulated until the process finishes with the file, and then they are flushed out. The problem is that the logging module does not have any method to flush on demand other than closing the logging sub-system. I wanted to keep the sub-system open and act as required when processing a file starts and stops. To do this I need a way of getting the logger instance to scan through its handlers and flush if appropriate. Doing it this way keeps the logging sub-system initialisation in one place and allows me to use something like getLogger().flush() in the code.

  • The email subject line is set dynamically to reflect the current file.

    Setting meta data such as the subject line for an email happens when a handler is instantiated. The logging module allows handlers to be added and removed dynamically, so the default way of setting a dynamic subject line would be to add a suitable handler when processing starts, and remove it later. Doing this would mean that the code would need to know something about how the logger instance was constructed. The alternative is to have a logger method that updates data as appropriate. I can then use getLogger().do_something(with_this_text) and have the logger instance sort it all out for me.

  • All messages go to a common log file for basic record keeping.

    This is easy – I just have a stream handler as the root logger and make sure that all message by default go to a named handler. This second level named handler is set up when the program starts and I provide a set of wrapper functions that log messages to the defined name.

  • Messages are also posted to the Lokai database as actions that must be addressed

    This needs a special handler that is added to the buffering handler along with the email handler. That way, a flush of the buffering handler sends the whole message set to both email and database. The database handler needs to be written, of course, and it does whatever is needed to create activity nodes in the Lokai database.

  • Message statistics are provided for managing end of file actions.

    At the end of processing a file the program needs to know whether to commit results or rollback. Processing a file may result in a mixture of error and warning messages, so we need to know what happened. By default the logging module does not keep records of what it has seen, and a buffering handler does not provide access to its buffer for analysis. I decided to provide a modified Logger class that keeps a count of messages at each message level. The logging module allows me to set this new class as the default when instantiating loggers.

The next few instalments will cover some of the details, although, naturally, the real detail is in theLokai code.

Comments Off on Python Logging Module Gaps and Matches | Development

Python Logging Exposed

March 22nd, 2012 — 5:38pm

In my previous post I outlined the logging requirements for Lokai file processing. This time I’m going to look at the logging module to see what it provides, and to identify what extensions we will need.

Just to be clear, I’m talking Python 2.x here, not 3. I don’t think there’s any significant difference, but I’m not an expert.

To start with, you, the programmer, do not actually instantiate any logging objects. To do anything at all you have to refer to a logger by name:

import logger
# Find or create the 'A' logger instance
log_instance_a = logger.getLogger('A')
# Send a message of level ERROR
log_instance_a.log(ERROR, 'Oops, an error')

As it says in the documentation, this means you always get the same logger instance and you do not need to pass things around.

You can name as many different logger instance as you like, and you can create hierarchies. The logger ‘A.B.C’ gets you the ‘C’ logger underneath ‘A.B’. The particular feature of such a hierarchy is that, by default, any message sent to logger ‘A.B.C’ will also go to logger ‘A.B’ and thence to ‘A’.

The next point is that messages are all allocated a level number. This is used to distinguish types of messages. The levels defined in the module are:

CRITICAL = 50
FATAL = CRITICAL
ERROR = 40
WARNING = 30
WARN = WARNING
INFO = 20
DEBUG = 10

You can choose the level you want to log when you set up your logger, so, within your code you can be liberal with debug output, for example, and turn it on or off for each program run by setting the appropriate parameter in the initialisation.

So far this is looking pretty flexible, but there is more. For this I’m going to illustrate the path taken by a message when logger.log is invoked. What follows is not code, exactly, but it should identify the key entry points for making any alterations or additions that may be needed.

    instance = logger.getLogger('A')
    instance.log(ERROR, 'text)
        #[Enter Logger.log method]
(a)     if self.isEnabledFor(level):
            self._log(level, msg, args, **kwargs)
                #[Enter Logger._log]
                record = self.makeRecord( ... msg ... )
                self.handle(record)
                    #[Enter Logger.handle]
(b)                 allowed = self.filter(record)
                        #[Enter Filterer.filter]
(c)                     for f in self.filters:
                            if not f.filter(record):
                                return True
                        return False
    		if allowed:
                    self.callHandlers(record)
                        #[Enter Logger.callHandlers]
(d)                     # ignoring propagation up hierarchy 
(e)                     for hdlr in self.handlers:
(f)                         if record.levelno >= hdlr.level:
                            hdlr.handle(record)
                                #[Enter Handler.handle] 
(g)                             if self.filter(record):
                                    # do something with the record

So, let’s look at what is going on. Firstly, the whole run of code is aimed at passing a log record to a handler. This is where the work gets done and the logger module has a range of example handlers that you can use. These include simple write to standard error, write to file, buffer records for later, send by email, send across a socket, and so on. In fact, a given logger instance can have any number of handlers, so your single message can result in any number of different storage or communication actions.

Secondly, there are 4 places where the message can be rejected or accepted. Point (a) is the basic limit on the numeric value of the message level. Anything less than this limit is rejected. Point (b) introduces logger level filtering. You can add any number of filters (see point (c)) and the first one to pass allows the message through. It gets better, because we see at point (f) that each individual handler also has a numeric filter, and, at point (g), its own set of filters. The result is that you have both coarse and fine control over what gets published at all, and what gets handled by which handler.

That covers the basics, but there are two more things to be aware of. One is that any handler has a format method that can be tuned to structure records into something meaningful, depending on the target output. The other is that a buffering handler must have a method of outputting records. This can be another Handler object (with filtering, if you wish).

That looks pretty flexible. You can link together handlers and filters in whatever combination suits your application, and you can write your own Handler objects. Next time we’ll see how that matches the Lokai requirements.

Comments Off on Python Logging Exposed | Development

Making the Python logger module do your bidding

March 21st, 2012 — 6:52pm

One of the things that Lokai supports is the automatic download and processing of data. For this type of operation logging is clearly important, both to inform people of problems to solve, and to keep records. In Lokai, the logging module has been brought in to service these various needs.

The basic automation concept is that files are placed in a directory, and a process comes along and loops through the files until none are left. For logging, we need to recognise that there are two groups of people involved.

One group, the data managers, are interested in the files themselves: was the file processed, were there any errors in the content of the file, are there any actions arising from the content. As far as possible, this group would perhaps prefer that all errors or actions for a single file are reported in one pass, rather than having the process stop on the first sign of trouble. More, the reported errors should be grouped into a single message to reduce email traffic.

The second group, the system managers, are interested in the correct operation of the process. In this case, the process might stop if there is a system or programming issue.

For both groups, the logs must identify the actual file being processed.

To cover the various needs of these groups Lokai provides a number of more or less configurable facilities:

  • Process related messages are emailed to a system manager email address.
  • File related messages are emailed to a data manager address.
  • Messages for a single file are grouped together.
  • The email subject line is set dynamically to reflect the current file.
  • All messages go to a common log file for basic record keeping.
  • Messages from file processing are accumulated and emitted as a single message for the whole file.
  • Messages are also posted to the Lokai database as actions that must be addressed
  • Message statistics are provided for managing end of file actions.

To put this into some sort of context, a file processing program might have this type of structure:

initialise_logging()

try:

    for file_to_process in get_next_file():

        set_email_subject("Processing file %s" file_to_process)

        for line in open(file_to_process):

            ...

            log_a_message(text) # As appropriate

        if log_messages_have_errors():
            abandon()
        else:
            commit()
        flush_log_messages()

except:
    log_a_message(error_text)
    flush_log_messages()
exit()

Obviously, this leaves out a great deal, but it serves to identify what type of calls we might want to make. Much of this is quite straightforward for the logging module. On the other hand, logging does not support dynamic update of meta data, so set_email_subject is something new. As it happens, we also have some work to do do to make some of the other things happen behind the scenes. My next post will look at the features of the logging module to see what might be done.

2 comments » | Development

Back to top