Best practice question: logging

[Pito Salas]

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

 

[Pascal J. Bourguignon]

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
3. Trace: E ==> NIL
2. Trace: O ==> NIL
1. Trace: E ==> NIL
NIL
C/USER[135]> (e 4)
1. Trace: (E '4)
2. Trace: (O '3)
3. Trace: (E '2)
4. Trace: (O '1)
5. Trace: (E '0)
5. Trace: E ==> T
4. Trace: O ==> T
3. Trace: E ==> T
2. Trace: O ==> T
1. Trace: E ==> T
T
C/USER[136]>


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

untrace YourClass,:aMethod

 

[Roger Pack]

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

 

[Chuck Remes]

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!

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

http://gist.github.com/151454

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

 

[Joel VanderWerf]

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