Safis Logging

When building distributed applications, the ability to audit their behavior is a necessity. Often, the easiest way to get at this information is by logging it!

The goal of the Safis logging subsystem is to provide the ability to log your application's behavior with minimal developer friction.

Getting Started

So, let's suppose you're developing an application for your evil overlord. The aim, of course, is to take over the world; but you'd best start small.

require 'safis/logging'

log.warn 'The world shall be ours! ...in due time.'

Which outputs your nefarious intentions to STDOUT:

WARN: [Object 19:57:24] The world shall be ours! ...in due time. [2009-07-01T19:57:24.818687-07:00]

The time is duplicated you say? Why haven't I been dropped into a shark tank for daring to denormalize your log output!?

Well, we often forget that it will be a bleary-eyed developer who will be pouring over these logs. As such, they should give them the information they care about first, and more granular information second.

After all, you can't afford to execute all of your minions for easily avoidable failure; and you certainly don't want the overlord to do the same to you!

The Hierarchy

Much of the power of the Safis logger comes from gleaning the structure of your application. You use, Modules and Classes, right?

require 'safis/logging'

module Villany
  log.warn 'Loading Villany...'

  class SharkTankTrapDoor
    def open!
      log.info 'Dropping the hero into a tank of certain death! With laser beams.'

      begin
        ...
      rescue TrapDoorFailure => err
        log.fatal 'The trap door failed to open. Execute the nearest henchman immediately!', err
      end
    end
  end
end

Of course, the trap door will fail, embarrassing the overlord for the last time:

WARN: [Villany 20:24:32] Loading Villany... [2009-07-01T20:24:32.329174-07:00]
INFO: [Villany::SharkTankTrapDoor 20:24:36] Dropping the hero into a tank of certain death! With laser beams. [2009-07-01T20:24:36.197427-07:00]
FATAL: [Villany::SharkTankTrapDoor 20:24:38] The trap door failed to open. Execute the nearest henchman immediately! [2009-07-01T20:24:38.747175-07:00]
TrapDoorFailure: The magma vents are blocked.
/villany/power_source/geothermal.rb:27:in `reroute_magma_flow'
/villany/power_source/geothermal.rb:53:in `check_power_levels'
...

Of course, there's also a variety of menial tasks that your overlord just can't be bothered to peruse. You can filter out log events that you don't need. Building on the above example, if we had set the following filter level (in the global context):

log.filter_level = :warn

The :info log event would be filtered out of the log output. It would look like:

WARN: [Villany 20:24:32] Loading Villany... [2009-07-01T20:24:32.329174-07:00]
FATAL: [Villany::SharkTankTrapDoor 20:24:38] The trap door failed to open. Execute the nearest henchman immediately! [2009-07-01T20:24:38.747175-07:00]
TrapDoorFailure: The magma vents are blocked.
/villany/power_source/geothermal.rb:27:in `reroute_magma_flow'
/villany/power_source/geothermal.rb:53:in `check_power_levels'
...

Furthermore, filter levels inherit from their parent Logs. For example:

log.filter_level = :fatal

module Villany
  class SharkTankTrapDoor
    log.filter_level = :info
  end
end

In this case, Villany inherits from the global scope's log (Object's log), so the initial :warn log event would be filtered. However, Villany::SharkTankTrapDoor overrides that with a filter level of :info, allowing the other two log events to be outputted unscathed:

INFO: [Villany::SharkTankTrapDoor 20:24:36] Dropping the hero into a tank of certain death! With laser beams. [2009-07-01T20:24:36.197427-07:00]
FATAL: [Villany::SharkTankTrapDoor 20:24:38] The trap door failed to open. Execute the nearest henchman immediately! [2009-07-01T20:24:38.747175-07:00]
TrapDoorFailure: The magma vents are blocked.
/villany/power_source/geothermal.rb:27:in `reroute_magma_flow'
/villany/power_source/geothermal.rb:53:in `check_power_levels'
...