Rhino Mocks - using AssertWasCalled on Common.Logging ILog.Debug

Question

I'm having trouble using Rhino Mocks to assert that a method was called (and ideally with a particular parameter). The Method is ILog.Debug(FormatMessageHandler) in Common.Logging 2.0 using the new lamba syntax. It works fine using the old way plain ILog.Debug(string).

    // Sample Code to Test
    public int TestFuncLambda(ILog log, int a, int b)
    {
        log.Debug(m => m("TestFunc START"));

        int c = a + b;

        log.Debug(m => m("TestFunc END"));

        return c;
    }

    public int TestFunc(ILog log, int a, int b)
    {
        log.Debug("TestFunc START");

        int c = a + b;

        log.Debug("TestFunc END");

        return c;
    }

    [TestMethod]
    public void Should_log_start_TestFuncLamba()
    {
        var logger = MockRepository.GenerateMock<ILog>();

        logger.Stub(x => x.IsDebugEnabled).Return(true);

        TestFuncLambda(logger, 1, 2);

        // Doesn't work, says zero calls plus I'm not sure how to check for the word "START" in the string either
        logger.AssertWasCalled(x => x.Debug(Arg<FormatMessageHandler>.Is.Anything), o => o.IgnoreArguments());
    }

    [TestMethod]
    public void Should_log_start_TestFunc()
    {
        var logger = MockRepository.GenerateMock<ILog>();
        logger.Stub(x => x.IsDebugEnabled).Return(true);

        TestFunc(logger, 1, 2);

        // Works fine
        logger.AssertWasCalled(x => x.Debug(Arg<string>.Matches(Text.Contains("START"))));
    }

Answer 1

I'm going to assume here that you are just tinkering with Rhinomocks, and this has nothing to do with the logging framework, is that correct? I say this because there are no concrete implementations in your tests, only mocks.

Without testing your code, this line looks like it will always be zero:

logger.AssertWasCalled(x => x.Debug(Arg<FormatMessageHandler>.Is.Anything), o => o.IgnoreArguments());

because your actual method TestFunc() passes strings to log.Debug, and not a FormatMessageHandler:

So it would make sense that the number of calls is zero. Add a line to TestFunc() like this:

log.Debug(new FormatMessageHandler());

and see if that fixes it.

Answer 2

First, create a concrete class to see if the right Debug() method is being called in TestFuncLambda. This makes sure that it's not doing some sort of weird conversion of the lambda to string.

Once you verify that is should be calling the correct version, you've isolated the problem with RhinoMocks. It could be a bug with rhino mocks. So, lets reduce the failure set but wrapping the lambda in a new FormatMessageHandler() before you pass it into Debug. This ensures that the right mocked function is being called and not translated as something else.

If you haven't found a bug at this point, and it still doesn't work, try creating an instance of FormatMessageHandler() and saving it as a static member variable (just to test what's wrong). Pass in that saved on in the TestFuncDebug call to Debug() and the AssertWasCalled() call. If that doesn't work, I'm out of ideas.

BTW, I dont know what IgnoreArguments() is, but I never have to call it in my RhinoMocks calls to AssertWasCalled. Usually having Arg<>.Is.Anything works fine.

Answer 3

I figured it out. I was missing the Action part for the delegate. The proper syntax is:

logger.AssertWasCalled(x => x.Debug(Arg<Action<FormatMessageHandler>>.Is.Anything));

rather than

logger.AssertWasCalled(x => x.Debug(Arg<FormatMessageHandler>.Is.Anything), o => o.IgnoreArguments());

As mentioned o.IgnoreArguments() was redundant and not necessary.