Best practice question: logging

Ruby
1

I want to sprinkle my code (Ruby, not Rails) liberally with logging
calls so that when things go wrong I can see what happened.

  • is Ruby’s Logger class the best practice to use, or is there another
    that’s cooler? For example it looks like Logger is not that flexible
    about changing the format of log entries.

  • Is it better to define a global $Logger variable to hold the new
    Logger object across classes and methods, or bettor to do a @l =
    Logger.new(STDOUT) in each class’s initializer?

  • how do I minimize the overhead when logging is OFF?

  • is one of these idioms faster than the other:

if debugging
@l.debug(“wow, what was that?”
end

@l.debug(“wow, what was that?” if debugging

@l.debug # no condition, just set @l.level = Logger::ERROR

Any other tips or pointers would be greatly appreciated!

Pito

2

Pito S. [email protected] writes:

I want to sprinkle my code (Ruby, not Rails) liberally with logging
calls so that when things go wrong I can see what happened.
[…]
Any other tips or pointers would be greatly appreciated!

Ok, directly in the category “other tips”, if you want to see
precisely what’s happening, during debugging, you could “trace” the
methods.

I don’t know if the feature is already implemented in Ruby, but it
should be possible to do so without too much difficulty.

Basically, you would say:

trace YourClass,:aMethod

and then the method YourClass.aMethod would be modified to print
tracing logs upon entering (with parameters), and exiting (with
results).

Tracing several methods would let you get logs such as:

C/USER[134]> (e 5)

  1. Trace: (E '5)
  2. Trace: (O '4)
  3. Trace: (E '3)
    4. Trace: (O '2)
    5. Trace: (E '1)
    6. Trace: (O '0)
    6. Trace: O ==> NIL
    5. Trace: E ==> NIL
    4. Trace: O ==> NIL
  4. Trace: E ==> NIL
  5. Trace: O ==> NIL
  6. Trace: E ==> NIL
    NIL
    C/USER[135]> (e 4)
  7. Trace: (E '4)
  8. Trace: (O '3)
  9. Trace: (E '2)
    4. Trace: (O '1)
    5. Trace: (E '0)
    5. Trace: E ==> T
    4. Trace: O ==> T
  10. Trace: E ==> T
  11. Trace: O ==> T
  12. Trace: E ==> T
    T
    C/USER[136]>

When done, it would be useful to unwrap the methods with calls such as:

untrace YourClass,:aMethod

3

I don’t know if the feature is already implemented in Ruby, but it
should be possible to do so without too much difficulty.

Basically, you would say:

trace YourClass,:aMethod

Checkout ruby -rtracer, too.
=r

4

Pito S. wrote:

  • how do I minimize the overhead when logging is OFF?

log.debug { “a message about #{topics.join.inspect}” }

is faster than

log.debug “a message about #{topics.join.inspect}”

because the interpolation and #join and #inspect only happen if log is
in debug level.

5

On Jul 21, 2009, at 9:50 AM, Pito S. wrote:

@l.debug # no condition, just set @l.level = Logger::ERROR

Any other tips or pointers would be greatly appreciated!

I asked this same question about a year ago and got lots of help. Here
is what I created:

I didn’t write a lot of documentation in these classes and modules.
Hopefully the concepts are clear enough from the code provided.

Logging is a pretty interesting process in my opinion. You may just
write messages to STDOUT, to a file, to a network socket, or all of
the above. Also, sometimes you want to disable logging but adding
“logger.log(“some message”) unless logger.disabled?” all over the
place is very ugly. As such, I use the Null Object pattern so you can
“switch out” the logging class behind the scenes to one that just
drops all messages.

For live logging, you call Logger.make_live (class method). To disable
logging, Logger.make_null.

If you have specific questions on this code, reply back. I haven’t
looked at in since I wrote it 1+ years ago but I’m sure I can answer
any questions that arise.

cr

6

Pito S.:

I want to sprinkle my code (Ruby, not Rails) liberally with
logging calls so that when things go wrong I can see what happened.

[…]

  • how do I minimize the overhead when logging is OFF?

I’m stadning before this very choice at the moment.

In my previous program, I used a home-brew Log class (which operated
only using class methods, so I just simply used one Log object – the
class itself – in all of my code: Log.write “debug info”).

Still, I now think that I’ll use the Ruby standard Logger class, but
instead of calling it explicitely in all of my code (going through all
of my methods and adding logging stuff to them, which I find both looks
ugly and in many cases makes them much longer) I’ll use metaprogramming
techniques to wrap method calls with logging lines if and only if
the logging is on. I’m thinking someting towards AOP, and I played
with Aquarium¹ a bit. I think this is a similar approach that Pascal
J. Bourguignon meant when mentioning the Tracer class.

This approach allows to have a single place in code that does all the
logging (and says which methods emit log output), keeps the methods
clean and to-the-point (without any logging stuff in them) and means
that with logging off there’s exactly no overhead (the logging code is
simply not included at all).

¹ http://aquarium.rubyforge.org/

— Shot