kojak

Kojak

Kojak is a bald and bold inspector and debug logger for Ruby apps. It aims to provide debug (a.k.a. verbose) logging without writing actual any single line of logging and printing junk. It also aims to add no overhead to the execution whatsoever.

Introduction

Take a look at the following code...

class SomeFancyTransport
  # *snip *

  def receive
    begin
      log "Waiting for messages ..."
      line = readline
      log "Message received, decoding ..."
      payload = JSON.parse(line)
      log "Decoded: #{payload.inspect}"
      log "Acknowledging ..."
      send(:_ack => true, :_id => payload['_id'])
      return payload
    rescue Timeout::Error
      log "Pinging ..."
      send(:_ping => true)
    rescue EOFError
      log "Connection closed!"
      @eof = true
    rescue => err
      log "Receive error: #{err.to_s}"
      send(:_err => err.to_h) rescue nil
    end

    nil
  end
end

Uhh, let's face it, this sucks... It looks ugly, getting throuhg and figuring out what that function does is complicated. It has 2x much code than it should, and even though log can be only a stub in non-verbose mode, it'll still takes execution time and adds overhead. I heard some wisdom from my friend Jens some time ago:

Your goal toward every single line of code in your app is go get rid of her, less code == less bugs.

So let's get rid of junk...

class SomeFancyTransport
  # *snip *

  def decode(s)
    JSON.parse(s)
  end

  def ack(id)
    send(:_ack => true, :_id => payload['_id'])
  end

  def ping
    send(:_ping => true)
  end

  def receive_err(err)
    send(:_err => err.to_h)
  end

  def eof!
    @eof = true
  end

  def receive
    begin
      payload = decode(readline)
      ack(payload['_id'])
      return payload
    rescue Timeout::Error
      ping
    rescue EOFError
      eof!
    rescue => err
      receive_err(err) rescue nil
    end

    nil
  end
end

Um, but that's more code! Well, yes and no... Let's see, actual code to be executed stays the same, rest are just method names and definitions. Though, now the code is self documented and it's not sliced through and through with junk logging lines. Easier to read, easier to test. But hey... where's the logging? Well, here it is:

class SomeFancyTransport
  extend Kojak::Inspector
  investigate :readline, :decode, :ack, :ping, ...
end

Kojak.investigate_all!

Hell yeah, magic! But not so much... investigate declares all methods that should be inspected. Then investigate_all! from Kojak goes through all these methods and redeclares them - it wraps original method with debugging stuff. Now when you call that method, our inspector will gather informatin about the execution (arguments, returns, thrown errors, execution time, etc.) and nicely print it out for you.

Now answer youself to one very important question. When looking at verbose log, what's more important for you? This...

Waiting for messages ...
Message Received! Decoding ...
Acknowledging ...
Receive error: couldn't acknowledge

Or maybe this:

SomeFancyTransport#readline (in ./lib/foo/some_fancy_transport.rb:15):
| realtime = 10.12388s
| pid      = 38711
| input    = []
| output   = "{\"_id\":\"1\"}"
SomeFancyTransport#decode (in ./lib/foo/some_fancy_transport.rb:20):
| realtime = 0.01425s
| pid      = 38711
| input    = ["{\"_id\":\"1\"}"]
| output   = {:id => 1}
SomeFancyTransport#ack (in ./lib/foo/some_fancy_transport.rb:30):
| realtime = 0.03331s
| pid      = 38711
| input    = [1]
| error    = #<StandardError: couldn't acknowledge>
SomeFancyTransport#receive_err (in ./lib/foo/some_fancy_transport.rb:40):
| realtime = 0.00010s
| pid      = 38711
| input    = #<StandardError: couldn't acknowledge>
| output   = [true, {:_err => {:kind => "standard_error", :message => "couldn't acknowledge"}}]

So here we swapped bunch of crappy logging code that produces a bit of useless text messages into self-documented code, with no logging that produces this full debug info including source location, input arguments, output and even real execution time or pid of the process.

TODO: continue ...