Logging vs. Exceptions

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

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

···

On Thu, 10 Nov 2005, lroland@gmail.com wrote:

lroland@gmail.com wrote:

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

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

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.

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 : john.carter@tait.co.nz
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.

···

On Thu, 10 Nov 2005, lroland@gmail.com wrote:

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.

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.new(:pattern => "[%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

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 : john.carter@tait.co.nz
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.

···

On Fri, 11 Nov 2005, lroland@gmail.com wrote:

     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