October 21, 2016

Log your scripts

Integration

P4Python and the Python logging API

Many of the P4Python scripts I have encountered (and written myself) are simple triggers or little utilities that typically do not require logging. Occasionally, though, some of these scripts become complex projects performing a multitude of functions and invoking many different Perforce commands. Debugging these scripts and performing any kind of post-mortem in case of a failure then becomes a challenge. Logging has been provided to address these challenges.

 

Python has an impressive logging API that has been described elsewhere, so I just want to highlight the bits I need for this post.

 

For example:

 

import logging

logger = logging.getLogger("MyLogger")

handler = logging.StreamHandler()

formatter = logging.Formatter(

        '%(asctime)s %(name)-12s %(levelname)-8s %(message)s')

handler.setFormatter(formatter)

logger.addHandler(handler)

logger.setLevel(logging.DEBUG)


logger.debug('often makes a very good meal of %s', 'visiting tourists')

 

For me, the important bits are:

·      There are different ways to get a logger instance; I prefer a named instance (“MyLogger”) that will be created for me by the factory method getLogger.

·      A logger can have different handlers.

o   Handlers can output log information to different locations, such as log files, email messages, network sockets and so on.

o   Handlers can have different formatters that determine how the message appears.

o   Each handler can have a different filter to ignore messages (not shown here).

o   Each handler can have different sensitivity, for example only react to warnings and errors. In this example, the logger itself accepts debug messages, but the handler could override this to reduce the sensitivity.

·      Finally, a logger accepts error(), warning(), info() and debug() calls to log some information at a particular severity level.

 

By having a logger defined this way, your code can determine the type of message you want to log and its importance, while the handler can decide if and how to present the information. A neat separation of concerns.

 

So how does this apply to P4Python?

 

I have seen a few script writers who needed or wanted logging in their P4Python script and solved this by subclassing P4. You would then typically wrap the P4.run() method to log the commands going in and the messages and errors coming out of the Perforce Helix server. If you choose to do this, please remember that the signature is:

 

P4.run(cmd, *args, **kargs)

 

Do not forget the keyword arguments **kargs, or you will encounter problems.

 

But I have always been of the opinion that if users of a system always have to write a wrapper themselves, it is the duty of the software author to provide this facility out of the box. So, P4Python has gained a logging facility. Simply assign a logger to your P4 object:

 

            p4.logger = logging.getLogger(“MyLogger”)

 

Obviously, you will need to add handlers and potentially formatters and so on to the logger you just created, to determine what, how and where to log information. P4 will do the rest. It will use the following four calls:

 

            info()              your command with all its arguments

            debug()          any output coming from the server

            warning()       any warnings

            error()             any errors

 

Note that you will still get warnings and errors even if you disable exception handling (via p4.exception_level = 0, for example). The messages from the server are still written into the p4.messages array, and P4.run() will also send the messages to the log.

 

For some of the output (filelog and print, specifically), the output is specifically formatted slightly different from what the server would normally return; the special formatting should make it more readable. To make the different output possible, I have smuggled an extra keyword “resultLogging” through the stack; this is one of the reasons why you should pass in the keyword arguments as well if you subclass P4 (see this post here).

 

But now you do not have to wrap P4 anymore for logging purposes: it is built-in. The new logging facility should make it a lot easier to maintain and debug your scripts. Check out P4Python 2016.1 Patch1 to see its full glory (previous versions omitted the logging of warning and errors).

 

Let me know what you think. Why don’t you share some of your scripts with us by putting them into the workshop and tweeting their location?

 

You can reach me on @p4sven with any comments or feedback, as usual.

 

Happy hacking!