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 ...