The PEAK Developers' Center   IntroToPeak/LessonFive UserPreferences
HelpContents Search Diffs Info Edit Subscribe XML Print View Up

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.


  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) 
Hmm. There's a lot of information and capabilities there. We're interested in the general format of a logging call, and which logging calls are provided. Looking through the list of methods, things like critical, 'debugwarningerror, and info` all look handy. The other methods we can ignore for now.

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):
    3     Customers = binding.Obtain(storage.DMFor(Customer))
    4     log = binding.Obtain(PropertyName("helloworld.logger"))
    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"%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):
    3     Groups = binding.Obtain(storage.DMFor(Group))
    4     log = binding.Obtain(PropertyName("helloworld.logger"))
    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    = 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.)

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 
As you can see, the logging system automatically adds a timestamp, the system name, an application name, and a processid, very similar to the way the unix syslog works.

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") 
Lots of different users are using this program, though, and we don't really want log files in whatever directory they happen to run the command from. We could specify an absolute path, but it would have to be one that all the potential users could write to. This is a practical solution: just have the file be writable by a group all the users belong to.

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") 
Here we're telling the logger to send the log messages to syslog under the local7 facility. We don't specify a log level, because that can be controlled by the syslog configuration. That of course means that PEAK must fully generate and send all messages, which is an overhead worth thinking about if you select syslog logging. If you don't want that overhead, you can specify a level just like for the logfile logger, and PEAK will only syslog messages at that level and higher.

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

EditText of this page (last modified 2004-02-16 17:44:06)
FindPage by browsing, title search , text search or an index
Or try one of these actions: AttachFile, DeletePage, LikePages, LocalSiteMap, SpellCheck