Using Mockito / PowerMock to verify a log has been written

Question

I have a class which writes messages to some logs. The class is a utility which doesn't do anything else, it runs in the background, checks a few things and logs them. I'm wondering if it's possible for me to verify in a unit test that the log has been written to without caring about what it is actually writing. Here's my class being tested:

//imports...

public class MyClass {
  private static Log log = LogFactory.getLog(MyClass.class);

  public MyClass() {
    log.info("MyClass is being created.");
  }

  public void doThing() {
    if( everything_is_fine ) {
      log.info("This is a message to say everything is fine.");
    } else {
      log.error("Uh oh...");
    }
  }
}

And my tester class:

// imports ...

@RunWith(PowerMockRunner.class)
@PrepareForTest({MyClass.class,LogFactory.class})
public class MyClassTest {
  Log mockLog;

  @Before
  public void setup() {
    PowerMockito.mockStatic(LogFactory.class);
    mockLog = mock(Log.class);
    PowerMockito.when(LogFactory.getLog(MyClass.class)).thenReturn(mockLog);
  }

  @Test
  public void test_everything_is_ok() {
    MyClass mything = new MyClass();    // should write to log.info
    mything.doThing();                  // should write to log.info

    verify(mockLog, atLeastOnce()).info(anyString());
    verify(mockLog, never()).error(anyString());
  }

  @Test
  public void test_everything_is_not_ok() {
    MyClass mything = new MyClass();    // should write to log.info

    // do something which makes things not ok

    mything.doThing();                  // should write to log.error

    verify(mockLog, atLeastOnce()).info(anyString());
    verify(mockLog, atLeastOnce()).error(anyString());
  }
}

When I run the tests, I expect that the log.info() is invoked for both tests, and the log.error() is invoked only for the second. However I'm getting a "Wanted but not invoked" for the log.info for both tests. and for log.error on the second. So either:
1) My code is broken and not writing to the log, or
2) My test is broken.

I'm thinking that I've messed up something in my test, probably something really obvious, so has anyone had experience testing something like this who could help me out? Any and all help will be appreciated.

UPDATE:

Thanks to those who helped out, I've got a solution now.

After playing around with the code for a bit, I discovered that there seems to be an issue with the initialization of the log. Doing private static Log log = LogFactory.getLog(MyClass.class); didn't seem to use the mock correctly, so if I move it to the constructor it seemed to be mocked OK and my tests all work as expected:

public class MyClass {
  private static Log log;

  public MyClass() {
    MyClass.log = LogFactory.getLog(MyClass.class);
    log.info("MyClass is being created.");
  }

  // etc ...
}

I've got it working now, but can anyone explain why initializing the log the first way didn't work? Or perhaps point me to somewhere which explains it? I'm not sure if there's a gap in my understanding of how Java initializes objects or if it's a limitation of mocking frameworks.

Have you seen this : http://stackoverflow.com/questions/8948916/mocking-logger-and-loggerfactory-with-powermock-and-mockito ? — Tiberiu C., Jul 10 '13 at 08:54
@user2406376: Thanks! I'd been searching around for about an hour trying to find anything on this, and of course you find it for me straight after I post. It looks very similar, but I'm not sure if it's identical, I'll give it a go and close this one if it turns out to be a duplicate. — andyc, Jul 10 '13 at 09:07
@andyc Hi I want to point out that if these log messages are important part of your system you should introduce a real dependency that make clear theses log are features, instead of relying on static code of a standard logger. For this matter I would recommend a class `Reporter` with methods such as `reportIncorrectUseOfYAndZForActionX` or `reportProgressStartedForActionX`. That would be meaningful and visible in in your the whole design, and you wouldn't need static mocking tools like PowerMock. — bric3, Jul 10 '13 at 13:32
@Brice: Thanks for the suggestion, I'd never really thought of doing something like that. Just to clarify though, in `MyClass` I would have a variable like `Reporter reporter = new Reporter()`, and I would replace the `log.info()` and `log.error()` statements with something like `reporter.reportCreationOfObject()`, `reporter.reportEverythingOK()`, and `reporter.reportReallyBadError()`. I would then also have a `Reporter` class which internally still writes to a log using the standard logging functions? — andyc, Jul 11 '13 at 02:16
@andyc Yup that'it. Of course you should adapt the names that should describe the feature in *business* terms. Also note that this `Reporter` could be injected via the dependency injection of the system, that's not a requirement, but it could be useful. If this reporting is important I personally like to make it a dependency at construction time (constructor injection). — bric3, Jul 11 '13 at 08:56

score 0 · Answer 1 · answered Nov 20 '14 at 13:03

You can make an abstraction over the Logger like we did here in our project:

https://github.com/4finance/uptodate-gradle-plugin/blob/master/src/main/groovy/com/ofg/uptodate/LoggerProxy.groovy

Then you have to constructors

https://github.com/4finance/uptodate-gradle-plugin/blob/master/src/main/groovy/com/ofg/uptodate/UptodatePlugin.groovy

One with LoggerProxy initialized and one for tests where you can mock it out and verify if proper text was passed. No need for dirty hacks ;)

score 0 · Answer 2 · answered Jan 24 '17 at 10:34

0

Since I had the same problem (private static Log log = LogFactory.getLog(MyClass.class);), I'm posting what I did to solve it.

Instead of modifying logger initialization (I was limited by coding rules) I simply split test in different classes...

answered Jan 24 '17 at 10:34

Bob Rivers

5,261
6
47
59

Using Mockito / PowerMock to verify a log has been written

2 Answers2