assert_event_logged ???

[taryn]

Does anyone know of a way to test whether or not a log event actually
made it into the log?
We want to make sure that some of our important events (eg "user x was
archived by user y") actually make it into the log.

but AFAICS there's no way to get information back *out* of logger -
it's input-only.

I could hook up something ugly by setting up a fake logger and
checking if it's empty after running a block of code... but I was
hoping for something more elegent.

Any clues?
Anyone done this before?
Anyone think it's a stupid idea (and willing to share why)?

Taryn

[Xavier Shay]

> I could hook up something ugly by setting up a fake logger and
> checking if it's empty after running a block of code... but I was
> hoping for something more elegent.

This is classically how you automatically test external services (see
action mailer tests, see activemessaging tests)

Xav

[Cameron Barrie]

Could you check if the logger.class was sent a method such as info or
error?

Cameron

[taryn]

Ya - done it with ActionMailer - but that seems less ugly because you
can actually access data *from* ActionMailer. For Logger I'd have to
set up a temporary logger file, then use some sort of dodgy system
calls to manually go through the file to figureout the strings in
it. :P
This feels ugly to me.
I'd much prefer to be able to do something like
assert_equal my_msg, logger.last_message

;)

[taryn]

On Mar 4, 3:42 pm, Cameron Barrie <pho...@mvpaustralia.com.au> wrote:
> Could you check if the logger.class was sent a method such as info or
> error?

Not sure how I'd do that. Do you know?

[Lachie]

On Tue, Mar 4, 2008 at 3:37 PM, taryn <google...@taryneast.org> wrote:
>
> Does anyone know of a way to test whether or not a log event actually
> made it into the log?
> We want to make sure that some of our important events (eg "user x was
> archived by user y") actually make it into the log.
>
> but AFAICS there's no way to get information back *out* of logger -
> it's input-only.

I've written a rails log parser, but its crude and only reads logs
from a fairly specific version of rails.

What I've done in the past is have a separate log (I called it an audit log).
The output was tab delimited and in a machine readable format, with fields like
time of event in epoch seconds
the component (maybe UsersController)
an event label (maybe user_archived)
then some event specific parameters (user x, user y, etc)

Then reading the logs back later for analysis or, say auditing is very easy

I'd unit test and implement it as its own specific class. From the
components which use it, mock up your audit logger's interface

You could implement it as a singleton:

class Audit
def self.log(event,*args)
...
end
end

call it in your code like

Audit.log(:user_archived,user_x.id,user_y.id)

would that work?

> I could hook up something ugly by setting up a fake logger and
> checking if it's empty after running a block of code... but I was
> hoping for something more elegent.
>
> Any clues?
> Anyone done this before?
> Anyone think it's a stupid idea (and willing to share why)?
>
> Taryn
> >
>

--
Lachie
http://blog.smartbomb.com.au
http://www.flickr.com/photos/lachie/

[Cameron Barrie]

I'm sure you could create some sort of observer on the class that the
logger object is instantiated from and assert that it is sent a
method call for info or error(which ever one your calling).

Cam

[Pete Yandell]

On 04/03/2008, at 3:37 PM, taryn wrote:

> Does anyone know of a way to test whether or not a log event actually
> made it into the log?
> We want to make sure that some of our important events (eg "user x was
> archived by user y") actually make it into the log.

If you're using rspec, you can grab my Not A Mock plugin and use call
recording to track calls to the logger, something like:

it "should log correctly" do
RAILS_DEFAULT_LOGGER.track_method(:info)
# Run your test
RAILS_DEFAULT_LOGGER.should have_received(:info).with(...)
end

More info on Not A Mock, including installation instructions are here: http://notahat.com/not_a_mock

- Pete

[Lachie]

On Tue, Mar 4, 2008 at 3:50 PM, Cameron Barrie
<pho...@mvpaustralia.com.au> wrote:
>
> I'm sure you could create some sort of observer on the class that the
> logger object is instantiated from and assert that it is sent a
> method call for info or error(which ever one your calling).

Yeah, if you want to test the normal logger, use a mock

I'm using RR at the moment. I'd do it like

mock(your_object.logger).debug("the expected message")

If your_object.logger doesn't receive the debug message with "the
expected message" the test will FAIL.

other mocking libs can do the same thing, you'll just have to look up the doco

For test unit, I'd recommend either RR or Mocha (Mocha being the more mature)

> Cam
>
>
>
>
> On 04/03/2008, at 3:46 PM, taryn wrote:
>
> >
> >
> > On Mar 4, 3:42 pm, Cameron Barrie <pho...@mvpaustralia.com.au> wrote:
> >> Could you check if the logger.class was sent a method such as info or
> >> error?
> >
> > Not sure how I'd do that. Do you know?
> >
> > >
>
>
> >
>

--

[taryn]

Interesting idea. So basically have a generic log and an "event log"
for important, auditable events. Cool... and I'd write my own accessor
methods for the latest methods - which would require keeping around
the last few messages, or whatever.

Cool idea, but sadly not a quick-to-implement one ;)
More of a long-term solution - which I assume will not make it past
the PM. :(
But I'll put t to him anyway.

[taryn]

On Mar 4, 3:50 pm, Cameron Barrie <pho...@mvpaustralia.com.au> wrote:
> I'm sure you could create some sort of observer on the class that the
> logger object is instantiated from and assert that it is sent a
> method call for info or error(which ever one your calling).

This sounds like a good idea for the current system. I'll have a look
into observers - of which I have only passing aquaintence through the
user notifier ;)


Thanks both of you :)

[Matt Palmer]

Mock objects.

require 'mocha'

class MockLogTest < Test::Unit::TestCase
def test_will_pass
RAILS_DEFAULT_LOGGER.expects(:info).at_least_once.with("something funny")
RAILS_DEFAULT_LOGGER.info("something funny")
end

def test_will_fail
RAILS_DEFAULT_LOGGER.expects(:info).at_least_once.with("something funny")
RAILS_DEFAULT_LOGGER.info("something else")
end
end

- Matt

[Geoff Tench]

On Tue, Mar 4, 2008 at 3:37 PM, taryn <google...@taryneast.org> wrote:

Another way that you could accomplish this is using a Proxy or Delegator for the logger, although, not being a Rails expert by any stretch of the imagination, I'm not sure how easy this would be in your situation.

Something like this would certainly give you the assertion that you're after, while preserving normal logging behaviour:

class ProxyLogger
 
  attr :messages
  attr :logger
 
  def initialize(logger)
    @logger = logger
    @messages = Hash.new { |h, k| h[k] = [] }
  end
 
  def method_missing(name, *args)
    @messages[name] << args[0]
    if @logger.respond_to?(name)
      @logger.send(name, args)
    end
  end
 
  def assert_logged(level, msg)
    return @messages[level].include?(msg)
  end
 
end

# e.g.
DEBUG_MSG = "My debug message"
proxy = ProxyLogger.new(existing_logger)
proxy.debug(DEBUG_MSG)
proxy.assert_logged(:debug, DEBUG_MSG) # => true
proxy.assert_logged(:info, DEBUG_MSG) # => false

Cheers,

Geoff.
 

[taryn]

On Mar 4, 4:29 pm, "Geoff Tench" <geoff.te...@gmail.com> wrote:
> Another way that you could accomplish this is using a Proxy or Delegator for
> the logger, although, not being a Rails expert by any stretch of the
> imagination, I'm not sure how easy this would be in your situation.
>

Ya - was thinking along similar lines myself, actually. I've just
monkey-patched the Logger in test-helper thus:

# monkey patch ruby's "Logger" to make it accessible to tests
class Logger
alias old_add add
def add(lvl, *args)
@last_logged ||= {}
@last_logged[lvl] ||= []
@last_logged[lvl] << args[1]
old_add(lvl, *args)
end
def last_logged(lvl = nil)
@last_logged unless lvl
(@last_logged ||= {})[lvl]
end
end

class Test::Unit::TestCase

def logger
RAILS_DEFAULT_LOGGER
end

# assert that the log has received the given message at the given
log
# level.
def assert_event_logged(lvl = Logger::DEBUG, msg = nil, &the_block)
yield the_block
last_logged = logger.last_logged(lvl)
assert !last_logged.blank?, "should have logged some message at
the #{lvl} level"
assert last_logged.include?(msg), "should have logged the given
message #{msg} at the #{lvl} level"
end
end


def test_should_log_a_msg
msg = "forcing the logger to log"
assert_event_logged(Logger::DEBUG, msg) do
logger.debug msg
end
end

Stil a bit ugly - but works with the current logger.
need to try testing it with some more detailed/gory log operations (eg
what happens with multiple log messages going in?