Simple log filtering

This tutorial explains how to write a simple filter for the Uttk's back end. This filter is simple and is 10 lines of code long, but very powerful. When using, the --rpath option of Uttk, there are a lot of tests with a status equals to SKIP(100%) which are logged. You probably want to see only the tests you have selected with the --rpath option. The filter, we are going to write through this tutorial, do that job.

First of all, this tutorial presents the basic concept to understand how the back end of Uttk works. Then it explains how to write the filter.

The back end

Uttk's back end is a tree of classes that observe themselves using the Observable design pattern. The root of the tree is an instance of the Logger class. The inner node are instances of one of the filter class hierarchy. The leaves are instances of one of the dumper classes.

The logger receives notification from the strategy being run. Then, it dispatches them to all its observers. An observer of the logger may be either a dumper or a filter. The dumper cannot be observed (they do not implement the Observable design pattern) but are associated to a stream in which they dump all the notifications they receive from the class they observe. There are several format available for dumping the notification (Yaml, XML, HTML, ...). The filters observe a logger or another filter and are observed by several other filters/dumpers. The filters may block or forward/repeat some of the notifications they receive to their observers. They may also alter some.

The filter: CutSkip100

Consider the following test suite:

$ cat check.yml
---
Test the pluralizer program: !S::Suite
  attributes: !S::Cmd
    command: ./pluralizer.rb
    exit: 0
  contents:
    - Test the bird word:
        input: "bird" 
        output: "birds\n" 
    - Test the mouse word:
        args: "mouse" 
        output: "mice\n" 
    - Test a bad word:
        args: "b1rd" 
        output: "" 
        error: "wrong word!\n" 
        exit: 1
    - Test the child word:
        args: "child" 
        output: "children\n"

of this little program:

$ cat pluralizer.rb
#! /usr/bin/env ruby

def main()
  if (ARGV.length == 0)
    word = STDIN.gets.chomp
  else
    word = ARGV[0]
  end
  if word =~ /\d/
    STDERR.puts "wrong word!" 
    exit 1
  else
    puts word + "s" 
  end
end

main

This program pass only 50% of its test suite:

$ uttk check.yml
---
root:
  contents:
    - Test the pluralizer program:
        contents:
          - Test the bird word:
              status: PASS
          - Test the mouse word:
              status: FAIL
          - Test a bad word:
              status: PASS
          - Test the child word:
              status: FAIL
        status: FAIL(50%)
  status: FAIL(50%)
--- |
 /-----------------------------------------------------------------------------.
 |                         *** Some tests failed ***                           |
 | The last status was not PASS but something like FAIL(42%) (just FAIL stands |
 | for FAIL(0%)). This means that 42% of tests *pass* but 100% was expected.   |
 | To investigate results these different outputs are available:               |
 |   - the standard output is the shortest one (like a progression bar).       |
 |   - log.html contains an HTML/JavaScript page nice to display big outputs.  |
 |   - log.yml contains more information in the very readable YAML format.     |
 |   - log.xml contains the output as an XML document.                         |
 `-----------------------------------------------------------------------------/

So now, since we are debugging our great program we don't want to run all the tests each time we test our modifications. So we use the --rpath option to select the failed desired test:

$ uttk --rpath '/////(mouse|child)' check.yml
---
root:
  contents:
    - Test the pluralizer program:
        contents:
          - Test the bird word:
              status: SKIP(100%)
          - Test the mouse word:
              status: FAIL
          - Test a bad word:
              status: SKIP(100%)
          - Test the child word:
              status: FAIL
        status: FAIL(50%)
  status: FAIL(50%)
--- |
 /-----------------------------------------------------------------------------.
 |                         *** Some tests failed ***                           |
 | The last status was not PASS but something like FAIL(42%) (just FAIL stands |
 | for FAIL(0%)). This means that 42% of tests *pass* but 100% was expected.   |
 | To investigate results these different outputs are available:               |
 |   - the standard output is the shortest one (like a progression bar).       |
 |   - log.html contains an HTML/JavaScript page nice to display big outputs.  |
 |   - log.yml contains more information in the very readable YAML format.     |
 |   - log.xml contains the output as an XML document.                         |
 `-----------------------------------------------------------------------------/

We also don't want to see the test with a SKIP(100%) status. To do so, we will write the CutSkip100 filter. But before, we need to understand how look like the notification that pass through a filter. The Basic dumper allow us to see them verbatim:

$ uttk --rpath '/////(mouse|child)' -F Basic check.yml
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/attributes/strategy, Uttk::Strategies::Cmd] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/attributes/command, "./pluralizer.rb"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/attributes/exit, 0] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the bird word[type: Uttk::Strategies::Cmd]/status, "SKIP(100%)"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the mouse word[type: Uttk::Strategies::Cmd]/args, "mouse"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the mouse word[type: Uttk::Strategies::Cmd]/running, "./pluralizer.rb mouse"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the mouse word[type: Uttk::Strategies::Cmd]/output_status, :FAILED] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the mouse word[type: Uttk::Strategies::Cmd]/my_output, "mouses\n"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the mouse word[type: Uttk::Strategies::Cmd]/ref_output, "mice\n"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the mouse word[type: Uttk::Strategies::Cmd]/my_exit, 0] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the mouse word[type: Uttk::Strategies::Cmd]/status, "FAIL"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the mouse word[type: Uttk::Strategies::Cmd]/reason, "output is different"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test a bad word[type: Uttk::Strategies::Cmd]/args, "b1rd"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test a bad word[type: Uttk::Strategies::Cmd]/status, "SKIP(100%)"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the child word[type: Uttk::Strategies::Cmd]/args, "child"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the child word[type: Uttk::Strategies::Cmd]/running, "./pluralizer.rb child"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the child word[type: Uttk::Strategies::Cmd]/output_status, :FAILED] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the child word[type: Uttk::Strategies::Cmd]/my_output, "childs\n"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the child word[type: Uttk::Strategies::Cmd]/ref_output, "children\n"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the child word[type: Uttk::Strategies::Cmd]/my_exit, 0] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the child word[type: Uttk::Strategies::Cmd]/status, "FAIL"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/contents[ordered]/Test the child word[type: Uttk::Strategies::Cmd]/reason, "output is different"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/contents[ordered]/Test the pluralizer program[type: Uttk::Strategies::Suite]/status, "FAIL(50%)"] block_given: false
NOTIFICATION: [:new_leaf, /root[type: Uttk::Strategies::Suite]/status, "FAIL(50%)"] block_given: false
NOTIFICATION: [:close] block_given: false
--- |
 /-----------------------------------------------------------------------------.
 |                         *** Some tests failed ***                           |
 | The last status was not PASS but something like FAIL(42%) (just FAIL stands |
 | for FAIL(0%)). This means that 42% of tests *pass* but 100% was expected.   |
 | To investigate results these different outputs are available:               |
 |   - the standard output is the shortest one (like a progression bar).       |
 |   - log.html contains an HTML/JavaScript page nice to display big outputs.  |
 |   - log.yml contains more information in the very readable YAML format.     |
 |   - log.xml contains the output as an XML document.                         |
 `-----------------------------------------------------------------------------/

You can see that a notification is composed by:

Actually, there is also an information about whether or not a block is provided but you can consider that it is always false. Plus, you can also consider that the identifier is always :new_leaf.

What we want to see is only the status different of SKIP(100%), so we must first match all the notifications with a path that end with "status" and display only those which have a value not equal to SKIP(100%).

First we must create a directory where to store our filters:

$ mkdir -p filters

Then, edit the new filter class:

$ cat filters/CutSkip100.rb
module Uttk

  module Filters

    class CutSkip100 < RPathFilter
      include Concrete

      match '^status$/!SKIP[(]100%[)]\Z', :display

      def display ( path )
        leaf = path.pop.segment
        notif :new_leaf, path, leaf
      end

    end # class CutSkip100

  end # module Filters

end # module Uttk

The match method is the key point of this filter (note that this method is available only because we inherits from the filter RPathFilter instead of the filter Filter. This method takes a "regexp_path" as first argument and a method to call as second argument. The "regexp_path" is matched against the path of every notification the filter receive. If the notification path matches then the method mentioned as second argument is called. The method display that we define just below does only repeat the notification.

Now, you can try your filter using this command:

$ uttk --rpath '/////(mouse|child)' -I . -F 'CutSkip100: Default' check.yml
---
root:
  contents:
    - Test the pluralizer program:
        contents:
          - Test the mouse word:
              status: FAIL
          - Test the child word:
              status: FAIL
        status: FAIL(50%)
  status: FAIL(50%)
--- |
 /-----------------------------------------------------------------------------.
 |                         *** Some tests failed ***                           |
 | The last status was not PASS but something like FAIL(42%) (just FAIL stands |
 | for FAIL(0%)). This means that 42% of tests *pass* but 100% was expected.   |
 | To investigate results these different outputs are available:               |
 |   - the standard output is the shortest one (like a progression bar).       |
 |   - log.html contains an HTML/JavaScript page nice to display big outputs.  |
 |   - log.yml contains more information in the very readable YAML format.     |
 |   - log.xml contains the output as an XML document.                         |
 `-----------------------------------------------------------------------------/

Further information, about how to use the RegexpPath and/or the RPathFilter can be found in the Uttk API documentation.