Logging vs. Exceptions

[lroland]

Hi all

I am moving a rather big Perl application to Ruby, due to the nasty way
Perl (un)handles exceptions we originally used log4perl (a log4j/log4r
like logging facility) heavily in a 'log and recover' like manner.

Ruby however have a quite nice exception semantics and thus I am
playing with using exceptions where I used to use logging. This brings
us to the dilemma of when to throw errors and when to log them. I read
on the net that a good policy is to either 'catch, wrap and throw', or
'log and recover', but never neither nor both.

Although this sounds like a reasonable plan I contiguously find myself
in limbo between doing the one or the other or mixing both.

i.e. if I have a class which contains a public method: 'x', and a
private method: 'y' (called by 'x'). Let's also put in as constraint
that it is vital that calling method: 'x' does not blow up the program
- the solution I ended up with is to catch the possible exceptions that
'y' may have thrown, log the errors and do something to recover (i.e.
thus letting the caller of 'x' handle whatever went wrong in 'x' by the
means of status codes).

-----------------
def x
:
begin
res = y( args )
rescue
log("error calling method: y")
# the method calling x should handle this
# or maybe we should propagate the exception thrown from y
# (or re throw a new one) for the caller to handle
return nil
end

return res
end

def y
:
# do a lots of commands that may throws exceptions
if error
raise Exception.new("something went wrong")
end
:
return res
end
-----------------

Although I normally follow the guidelines of not doing both I am
leaning towards letting the exception code also use the logging
facility that way I can propagate nested exceptions up through the code
and still have the all the errors logged into one place - would this be
ugly ? or bad design ?. I am a old school Haskell, C and Perl
programmer so I am not used to do much exception handling thus I would
like some opinions on the best practices of logging vs. exception
handling ?.



Regards.

Lars Roland

 

[Hugh Sasse]

Hi all [...]
Ruby however have a quite nice exception semantics and thus I am
playing with using exceptions where I used to use logging. This brings
us to the dilemma of when to throw errors and when to log them. I read
on the net that a good policy is to either 'catch, wrap and throw', or
'log and recover', but never neither nor both.

What is a paniclog if not both an throw and a logging?
And a crash dump?

Hugh

 

[Robert Klemme]

Hi all

I am moving a rather big Perl application to Ruby, due to the nasty
way Perl (un)handles exceptions we originally used log4perl (a
log4j/log4r like logging facility) heavily in a 'log and recover'
like manner.

Ruby however have a quite nice exception semantics and thus I am
playing with using exceptions where I used to use logging. This
brings us to the dilemma of when to throw errors and when to log
them. I read on the net that a good policy is to either 'catch, wrap
and throw', or 'log and recover', but never neither nor both.

Although this sounds like a reasonable plan I contiguously find myself
in limbo between doing the one or the other or mixing both.

i.e. if I have a class which contains a public method: 'x', and a
private method: 'y' (called by 'x'). Let's also put in as constraint
that it is vital that calling method: 'x' does not blow up the program
- the solution I ended up with is to catch the possible exceptions
that 'y' may have thrown, log the errors and do something to recover
(i.e. thus letting the caller of 'x' handle whatever went wrong in
'x' by the means of status codes).

-----------------
def x
:
begin
res = y( args )
rescue
log("error calling method: y")
# the method calling x should handle this
# or maybe we should propagate the exception thrown from y
# (or re throw a new one) for the caller to handle
return nil
end

return res
end

def y
:
# do a lots of commands that may throws exceptions
if error
raise Exception.new("something went wrong")
end
:
return res
end
-----------------

It's difficult to discuss this with such an abstract example. Depending on
the nature of method x and its place in the overall application architecture
it may be wise or unwise to catch and log the exception...

Although I normally follow the guidelines of not doing both I am
leaning towards letting the exception code also use the logging
facility that way I can propagate nested exceptions up through the
code and still have the all the errors logged into one place - would
this be ugly ?

I'm not sure how exactly you want to do this. IMHO it's like this: the
place that throws the exception never logs anything because it doesn't know
how the exception is handled. On the higher level (can be arbitrary many
levels in between) an exception is caught and dealt with. Dealing can mean
anything from logging, over retrying to recovering and doing something else.

or bad design ?. I am a old school Haskell, C and Perl
programmer so I am not used to do much exception handling thus I would
like some opinions on the best practices of logging vs. exception
handling ?.

Exceptions are for exceptional cases, i.e. when a piece of code cannot
continue as planned (disk full during IO for example). We had a discussion
yesterday or the day before that revolved around using return values vs.
exceptions.

If you provide more insight into your app we might be able to come up with
more specific input.

Kind regards

robert

 

[swille]

def x

:
begin
res =3D y( args )
rescue
log("error calling method: y")
# the method calling x should handle this
# or maybe we should propagate the exception thrown from y
# (or re throw a new one) for the caller to handle
return nil
end

return res
end

def y
:
# do a lots of commands that may throws exceptions
if error
raise Exception.new("something went wrong")
end
:
return res
end

IMHO, your y method is almost defeating the purpose of exceptions --
you can't get a backtrace to figure out what exactly went wrong. But
of course, without seeing the processing that's going on in y, it's
hard to say what the semantics should really be. Maybe you really do
need to process each line regardless of whether the previous one
succeeded. Also, I don't know what res would return from y, but maybe
in this case an integer/errno type of return would be appropriate. At
least then you might be able to explain or handle what's happened
without interrupting the processing in y.

 

[John Carter]

I am moving a rather big Perl application to Ruby, due to the nasty way
Perl (un)handles exceptions we originally used log4perl (a log4j/log4r
like logging facility) heavily in a 'log and recover' like manner.

General Rule of Thumb...

Never catch an exception you don't know how to handle.

If you can't actually make things better by catching it, don't. Let it go
up until somebody higher up does.

A commonish idiom I will use is catch and rethrow. If for example, at an
intermediate level I have more information about what was happening, I
will catch and add that info to the exception or perhaps create a
new and different one (but including the backtrace info from the first.)

And then raise that for a higher level to catch.

So in my scripts any mucks ups by the user unwinds accumulating info until
it can present a very relevant and accurate error message to the user.

If it's a bug it unwinds to a catcher of last resort that explicitly
states, "Sorry, it's John's fault" and then dumps a (very) detailed
backtrace. 99% of the time I can fix the bug straight off one of those
reports.

Except in a handler of last resort, always raise and rescue the most
explicit and least general exception you can. Even if you have to spin a
new Exception subclass for the occasion. Failure to do so will mask bugs
and render your code inflexible.




John Carter Phone : (64)(3) 358 6639
Tait Electronics Fax : (64)(3) 359 4632
PO Box 1645 Christchurch Email : (e-mail address removed)
New Zealand

Carter's Clarification of Murphy's Law.

"Things only ever go right so that they may go more spectacularly wrong later."

From this principle, all of life and physics may be deduced.

 

[lroland]

Here is parts of the code, newly rewritten from Perl to Ruby. The code
is a basic scanner that uses clamav to scan a file for virus and logs
errors using log4r. The 'scan' method handles the scan result and the
'talk' method speaks to clamav using a socket. The talk method may
throw exceptions but, the scan function tries to grab these, logs
whatever goes wrong and generally tries to be as exception safe as
possible. Also I use a customized exception class that logs all
exceptions using the same log4r object as the rest of the code.

What I would like is to get some opinions/comments on is how to mingle
logging and exception handling together in a usable and yet clean way
(I personally do not feel that the code below is as clean as it could
be but I am still looking for the correct division of responsibility
between the logging and exception code)

---------
require 'socket'
require 'log4r'
include Log4r

class ClamScanner
attr_accessor :socket, :result, :logger

def initialize()
@logger = Logger['test']
@socket = '/var/run/clamav/clamd.sock'
end

def check()
res = talk("PING")
if(res !~ /PONG$/)
@logger.error("check failed: erroneous clam answer: #{res}")
return false
end
return true
end

def scan( path )
if(@result)
@logger.info("reusing previous scan result: <#{@result}> of:
<#{path}>")
else
begin
res = talk("SCAN #{path}")
rescue ScannerException
@logger.error("unable to scan message: #{path}")
return nil
end

if(res =~ /: (.*) FOUND$/)
@logger.info("virus: #{$1} in: #{path}")
@result = $1;
elsif(res =~ /: (Zip module failure) ERROR$/)
@logger.info("broken zip in #{path}")
@result = 'Broken.ZIP.Archive'
elsif(res =~ /OK$/)
@logger.info("no virus detected in: #{path}")
@result = 'clean'
else
@logger.error("unknwon clam resource problem: #{$1}: when
scanning: #{path}")
return nil
end
end

return @result
end

def talk( msg )
data = nil
session = nil

if msg.nil?
raise ScannerException.new("method called with empty args")
end
begin
session = UNIXSocket.new(@socket)
session.send(msg,0)
data = session.recvfrom(512)[0] # [0] ensures we only get clam's
respons
session.close()
rescue
raise ScannerException.new("unable to use socket: #{@socket}")
end
return data
end
end

# exception class that logs using our log4r object
class ScannerException < RuntimeError
logger = nil
def initialize( message )
@logger = Logger['test']
@logger.error(message)
end
end

# create logger
logger = Logger.new('test')
outputter = Outputter.stdout
outputter.formatter = PatternFormatter.newpattern => "[%l] %d :: %m")
logger.outputters = outputter

# test scanner
clamav = ClamScanner.new();
if !clamav.check()
logger.error("woop error")
exit(1)
end

# scan this file
file = '/path/to/test.file'
res = clamav.scan( file )
---------


Regards

Lars Roland

 

[John Carter]

begin
session = UNIXSocket.new(@socket)
session.send(msg,0)
data = session.recvfrom(512)[0] # [0] ensures we only get clam's
respons
session.close()
rescue
raise ScannerException.new("unable to use socket: #{@socket}")
end

Evil! Evil! Evil! DON'T _DO_ THAT!

You have now masked every error in that section and munged them into one.
You could have a simple programming bug, or something weird may be
happening on your system, but it will all collapse into one error and you
will have not the foggiest idea what happened or why.


So try one of these variants...

best practice would be trap just those exceptions you know can arise..

rescue ASpecificError
raise ScannerExecption.new(.....)
end

or (if you must catch all) at least record what it was, don't mask the
unexpected.

rescue Exception => details
raise ScannerException.new( "blah blah #{details}")
end

or, since you are not really adding much of value at this level, just
don't catch anything at this level, (never catch an exception you don't
know how to handle.)



John Carter Phone : (64)(3) 358 6639
Tait Electronics Fax : (64)(3) 359 4632
PO Box 1645 Christchurch Email : (e-mail address removed)
New Zealand

Carter's Clarification of Murphy's Law.

"Things only ever go right so that they may go more spectacularly wrong later."

From this principle, all of life and physics may be deduced.