IntroToPeak/LessonFive

UserPreferences

Up: IntroToPeak Previous: IntroToPeak/LessonFour Next: ?IntroToPeak/LessonSix

Lesson Five: Using Logs (DON'T USE THIS YET)

(NOTE: this lesson was written based on speculations about future PEAK features. It does not reflect current PEAK capabilities, and the things described here may change before they're implemented. You have been warned.)

So, our application is deployed. People are using it. But who? And how much? And just who was it who changed the greeting for vvips to "Your most humble servant greets you, Grand and Mighty Poobah!"? Management would like to know.

Well, we can't help them with the last question, because that's already in the past. But we can start gathering the data needed to answer these sorts of questions, using PEAK's logging facilities. So in this lesson, we'll introduce logging, and show how to incorporate it into our program.

Contents

1. Lesson Five: Using Logs (DON'T USE THIS YET)
1. Generating Log Messages
2. Logging to the Terminal
3. Other Logging Destinations
4. Multiple Log Destinations

Generating Log Messages

Keeping with the PEAK philosophy of making things easily configurable, we're not going to hardcode where our log messages go. Instead our code will simply ask the configuration system for a logging object, and pass that object the log messages.

A logger in PEAK is something that provides the ILogger interface. Let's take a look:

% peak help running.ILogger 
Help on class ILogger in module peak.running.interfaces: 
 
class ILogger(protocols.interfaces.Interface) 
 |  A PEP 282 "logger" object, minus configuration methods 
 |   
 |  All methods that take 'msg' and positional arguments 'args' will 
 |   interpolate 'args' into 'msg', so the format is a little like a 
 |  'printf' in C.  For example, in this code: 
 |   
 |      aLogger.debug("color=%s; number=%d", "blue", 42) 
 |   
 |  the log message will be rendered as '"color=blue; number=42"'.  Loggers 
 |  should not interpolate the message until they have verified that the 
 |  message will not be trivially suppressed.  (For example, if the logger 
 |  is not accepting messages of the designated priority level.)  This avoids 
 |  needless string processing in code that does a lot of logging calls that 
 |  are mostly suppressed.  (E.g. debug logging.) 
 |   
 |  Methods that take a '**kwargs' keywords argument only accept an 'exc_info' 
 |  flag as a keyword argument.  If 'exc_info' is a true value, exception data 
 |  from 'sys.exc_info()' is added to the log message. 
 |   
 |  Method resolution order: 
 |      ILogger 
 |      protocols.interfaces.Interface 
 |      __builtin__.object 
 |   
 |  Methods defined here: 
 |   
 |  critical(msg, *args, **kwargs) 
 |      Log 'msg' w/level CRITICAL 
 |   
 |  debug(msg, *args, **kwargs) 
 |      Log 'msg' w/level DEBUG 
 |   
 |  error(msg, *args, **kwargs) 
 |      Log 'msg' w/level ERROR 
 |   
 |  exception(msg, *args) 
 |      Log 'msg' w/level ERROR, add exception info 
 |   
 |  getEffectiveLevel(lvl) 
 |      Get minimum priority level required for messages to be accepted 
 |   
 |  info(msg, *args, **kwargs) 
 |      Log 'msg' w/level INFO 
 |   
 |  isEnabledFor(lvl) 
 |      Return true if logger will accept messages of level 'lvl' 
 |   
 |  log(lvl, msg, *args, **kwargs) 
 |      Log 'msg' w/level 'lvl' 
 |   
 |  warning(msg, *args, **kwargs) 
 |      Log 'msg' w/level WARNING 
 |   
 |  ---------------------------------------------------------------------- 
 |  Data and other attributes inherited from protocols.interfaces.Interface: 
 |   
 |  __dict__ = <dictproxy object> 
 |      dictionary for instance variables (if defined) 
 |   
 |  __metaclass__ = <class 'protocols.interfaces.InterfaceClass'> 
 |   
 |  __weakref__ = <attribute '__weakref__' of 'Interface' objects> 
 |      list of weak references to the object (if defined) 
 

So let's modify our to command to log who is greeting whom (I'm going to omit the usage text when I show modified versions of our commands from now on; you've seen that text often enough already!):

    1 class toCmd(commands.AbstractCommand):
    2 
    3     Customers = binding.Obtain(storage.DMFor(Customer))
    4     log = binding.Obtain(PropertyName("helloworld.logger"))
    5 
    6     def _run(self):
    7         if len(self.argv)<2: raise commands.InvocationError("Missing name")
    8         storage.beginTransaction(self)
    9         print self.Customers[self.argv[1]].greeting()
   10         self.log.info("%s issued greeting to %s", self.environ['USER'],
   11             self.argv[1])
   12         storage.commitTransaction(self)

We've added two lines here. The first sets up a class variable log and binds it to the configuration key helloworld.logger. We'll talk about what we set that key to in the next section. The second line generates the actual log entry. As you can see, we call the info method of our ILogger instance, and pass it a message containing substitution points, and the values to be substituted.

Now let's consider our for command:

    1 class forCmd(commands.AbstractCommand):
    2 
    3     Groups = binding.Obtain(storage.DMFor(Group))
    4     log = binding.Obtain(PropertyName("helloworld.logger"))
    5 
    6     def _run(self):
    7         if len(self.argv)<2: raise commands.InvocationError("Missing arguments")
    8         parts = ' '.join(self.argv[1:]).split(':')
    9         if len(parts)!=2: raise commands.InvocationError("Bad argument format")
   10         groupname = parts[0].strip(); message = parts[1].strip()
   11         storage.beginTransaction(self)
   12         if groupname in self.Groups:
   13             group = self.Groups[groupname]
   14             self.log.warning('Greeting for group %s changed to "%s" by %s',
   15                 groupname, message, self.environ['USER'])
   16         else:
   17             group = self.Groups.newItem()
   18             group.name = groupname
   19             self.log.warning('Greeting ("%s") for group %s added by %s',
   20                 message, groupname, self.environ['USER'])
   21         group.text = message
   22         storage.commitTransaction(self)

Again we set up the logger. Here we have two possible logged messages, depending on whether or not this is the first time a message has been set for the group.

This time we're logging at warning level, figuring that messages changes should be relatively rare, and if someone is monitoring the logs that's probably what they'll be interested in seeing. As implied by the help information up above, PEAK provides ways of filtering the generated log messages based on priority, of which info and warning are two examples. This way, if all we need to know is who is changing the messages, we can set PEAK to ignore the info messages generated by uses of the to command.

Logging to the Terminal

So how do we tell PEAK what we want to log, and where? We do that by specifying those details when we define what goes in to the helloworld.logger configuration variable.

To start with, let's configure the logging information to be dumped to stderr, so we can test our logging code and make sure it is doing what we want. And since we're testing, we're going to want to see messages of any priority. debug is the lowest priority, so we'll tell the logger to log everything from debug on up. (We aren't using any debug calls now, but we might want to add some later next time we have to do some debugging of our application.)

[helloworld] 
 
messagedb = naming.LinkRef('sqlite:messages.db') 
logger = logs.LogStream(stream=importString('sys.stderr'), level=logs.DEBUG) 

Here we are using PEAK's LogStream logger. To work, it needs to know which stream to write to, so we tell it using stream=importString('sys.stderr'). We need to use importString because sys.stderr is an import path. We also tell the logger the minimum level of message to log. (Message levels are named the same as the corresponding method names, but using all caps).

Let's try it out:

% ./hello to Jeff 
I am so happy to see you, Jeff 
Dec 09 19:34:12 stage PEAK[12865]: rdmurray issued greeting to Jeff 
% ./hello for peon: "Hi, %s" 
Dec 09 19:36:49 stage PEAK[12870]: Greeting ("Hi, %s") for group peon added by rdmurray 
% ./hello for peon: "Hi, scum" 
Dec 09 19:37:49 stage PEAK[12871]: Greeting for group peon changed to "Hi, scum" by rdmurray 

Other Logging Destinations

OK, so everything is working. We don't want these messages appearing on the console when we roll out this new version, so we'd better redirect the logs. We could have them go to a file:

logger = naming.LinkRef("logfile:helloworld.log?level=INFO") 

Many systems have a simpler solution, though, and PEAK supports it: syslog. Here's how we'd direct our logging to syslog:

logger = naming.LinkRef("syslog:local7") 

Multiple Log Destinations

The Boss is really worried about that unauthorized message change. He wants to be notified immediatly of any new message changes. Systems has set up a unix named pipe that they've tied to their paging system, so anything written to that pipe will get sent to the boss's pager. But we still need to keep logs of all access, for those usage statistics he also wants. So we can't just redirect logging, at warning level, to the pipe. We need to send the logging info to two destinations, with two different filtering levels.

And here's how we do it:

logger = logtee:{syslog:local7},{logfile:/tmp/pageboss?level=WARNING} 

(NB: Neither syslog: nor logtee: are currently hooked up in peak.ini, so these examples don't work/aren't tested)

Up: IntroToPeak Previous: IntroToPeak/LessonFour Next: ?IntroToPeak/LessonSix