Tutorial #4. Logging Interceptor

The sources for this tutorial may be found in the tutorial/04 directory of the Copland distribution.

Introduction

Sometimes (particularly when debugging) you want to be able to trace your program’s execution. You want to see when certain methods are being invoked, and with what parameters, and what the return values are. If an exception is being raised, you’d like to see that, too.

Although the calculator example we’ve been using up to this point is trivial enough that there’s really no need for such tracing, it is an easy one to demonstrate it on. So, let’s take the code we wrote for the last tutorial and add logging, just for the halibut.

What we’ll do is modify the program so that it logs everytime a method of the Calculator or Adder services is invoked from outside the service.

Steps

  1. copland.LoggingInterceptor

    Interceptors are another kind of service, similar to factory services, that Copland uses to intercept method calls. An instance of the interceptor service sits (conceptually) between the caller and the method, and acts as a filter for everything going into or out of the method.

    There is currently only one interceptor that ships with Copland—copland.LoggingInterceptor. It sits between the caller and the method and happily logs away, noting the parameters, return values, and exceptions that are raised.

  2. Adding the Interceptor

    Here we get to demonstrate one of (in my opinion) the “coolest” aspects of Copland. We can add the logging solely by editing our package descriptor—nothing else needs to change! Our Ruby objects remain blissfully ignorant that the logging has been added. Slick, huh?

    So, let’s open our package descriptor and add the interceptor to the Adder service first:

      Adder:
        implementor: tutorial/Adder
        interceptors:
          - service: copland.LoggingInterceptor
    

    The interceptors element is always a list of interceptors that should be added to the service. (By default, the interceptors will be invoked in the order they were added. You can change this, but it’s a bit beyond the scope of this tutorial.) Each element of the list must be a hash, each with the service element (at least) defined. That element must name a valid interceptor service. In this case, the interceptor service is copland.LoggingInterceptor.

    Now, let’s add the logging interceptor to the Calculator service:

      Calculator:
        interceptors:
          - service: copland.LoggingInterceptor
        ...
    

    Note that it is not important where the interceptors element appears in the service point—just as long as it appears at the “top level” of the service point definition.

  3. Running the Program

    So, we’ve got the interceptors in place now. Let’s try running the program and seeing what happens!

    You should see the exact same output from the last tutorial—the list of multiples and powers. However, there should be a file named “copland.log” in the same directory. This file has been appearing every time you’ve run your programs during these tutorials, but it has been largely empty because nothing has been logged. This time, however, there will be quite a bit of text in the log, looking something like this:

      # Logfile created on Sat Sep 04 09:29:58 MDT 2004 by logger.rb/1.5.2.4
      D, [2004-09-04T09:29:58.963327 #23288] DEBUG -- tutorial.Calculator: memory(  )
      D, [2004-09-04T09:29:58.963471 #23288] DEBUG -- tutorial.Calculator: memory => 0
      D, [2004-09-04T09:29:58.963522 #23288] DEBUG -- tutorial.Calculator: memory(  )
      D, [2004-09-04T09:29:58.963564 #23288] DEBUG -- tutorial.Calculator: memory => 0
      D, [2004-09-04T09:29:58.963651 #23288] DEBUG -- tutorial.Calculator: add( 5 )
      D, [2004-09-04T09:29:58.999262 #23288] DEBUG -- tutorial.Adder: add( 5, 0 )
      D, [2004-09-04T09:29:58.999486 #23288] DEBUG -- tutorial.Adder: add => 5.0
      D, [2004-09-04T09:29:58.999547 #23288] DEBUG -- tutorial.Calculator: add => 5.0
      D, [2004-09-04T09:29:58.999617 #23288] DEBUG -- tutorial.Calculator: memory=( 5.0 )
      D, [2004-09-04T09:29:58.999663 #23288] DEBUG -- tutorial.Calculator: memory= => 5.0
      ...
    

    Let’s analyze the output a bit. First, it’s saying that the #memory method was invoked, with no parameters, and that it returned 0. Then, it was invoked again, and returned 0 again. (This is because we’ve got two calculators going at once, both of them logging their method invocations.) Next, #add was invoked, with a parameter of 5. Then, the Adder’s #add is invoked, with two parameters (5, and 0). That method then returns a value of 5.0, followed by the Calculator’s #add method returning 5.0. Then, the #memory= method is invoked, with a value of 5.0, which it also returns.

    That’s a bit more verbose than we intended—for example, we didn’t really care to see all the memory method invocations. We’d like to be able to exclude those methods from the logger.

  4. Excluding Methods

    The LoggingInterceptor supports (among others) two parameters, exclude and include. Each of these elements is an array of special regular expressions that should match method names.

    By default, all methods are included. If you specify a set of exclude patterns, any method that matches any one of those patterns will be excluded from consideration. If you further specify a set of include patterns, then any method that has been excluded from consideration, and which matches any one of the include patterns, will be reincluded for consideration.

    So, let’s exclude the #memory and #memory= methods from the Calculator’s logging interceptor. We can do it by name each method explicitly, like this:

      Calculator:
        interceptors:
          - service: copland.LoggingInterceptor
            exclude:
              - memory
              - memory=
        ...
    
    Or, we can be a little more concise and use regular expressions:
      Calculator:
        interceptors:
          - service: copland.LoggingInterceptor
            exclude:
              - memory=?
        ...
    

    Delete the original copland.log (otherwise subsequent runs will just append to it) and then rerun your script. None of the memory methods are being logged! Much better.

Summary

In this tutorial you learned how to apply a logging interceptor to a service. You also learned how to exclude certain methods from being logged.

Note that you can easily specify that only certain methods should be logged (instead of the reverse, where only certain methods should not be logged). To do this, first exclude all methods (with a ”.*” regular expression), and then explicitly include the methods you want to log.

Also, it should be noted that the regular expressions for the include and exclude patterns are special: you can also specify the arity of the methods that should be included or excluded. For example, if you want to exclude all methods that are invoked with 3 parameters, you could do:

  exclude:
    - .*(3)

If you prefix the arity number with a comparison operator (less-than or greater-than), you can exclude (or include) methods that are invoked with less than or greater than that number of parameters:

  exclude:
    - .*(>3)
  include:
    - .*(5)

The above would exclude any method invoked with more than three parameters, unless it was invoked with exactly five parameters.