How to verify (with unit test) that error stack is printed in the log file?

Question

In continuing to this answer I wrote a unit test to verify that in case of error, the stack will be printed in the log file.

The tested method:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

private final Logger logger = LoggerFactory.getLogger(getClass());

public long getFq(String fi) {
    try {            
        return calcSomeThing(fi.toLowerCase());
    } catch (Exception e) {
        logger.error("unable to calculate SomeThing.  Error: "
                , e);
        return -1;
    }
}

The unit test:

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.read.ListAppender;
import org.slf4j.LoggerFactory;

@Test
public void getFileQualifier() {

    // get Logback Logger
    Logger logger = (Logger) LoggerFactory.getLogger(QService.class);

    // create and start a ListAppender
    ListAppender<ILoggingEvent> listAppender = new ListAppender<>();
    listAppender.start();

    // add the appender to the logger
    // addAppender is outdated now
    logger.addAppender(listAppender);

    // call method under test
    QService.getFq(null);

    // JUnit assertions
    List<ILoggingEvent> logsList = listAppender.list;
    Assert.assertEquals("unable to calculate SomeThing.  Error: ", logsList.get(0)
            .getFormattedMessage());
    Assert.assertEquals(Level.ERROR, logsList.get(0)
            .getLevel());

    Assert.assertEquals("java.lang.NullPointerException: null", logsList.get(1)
            .getMessage());
    Assert.assertEquals(Level.ERROR, logsList.get(1)
            .getLevel());

    Assert.assertThat("(QService.java", containsString(logsList.get(2)
            .getMessage()));
    Assert.assertEquals(Level.ERROR, logsList.get(2)
            .getLevel());
}

Well, although I can see the stack is indeed printed in the log file, the unit test failed because of the logsList contains only one item (the first printed line only [unable to calculate SomeThing. Error: ]).

java.lang.IndexOutOfBoundsException: Index 1 out of bounds for length 1

Why does it happen and how it can be tested?

EDIT

Answers: the answers (all are quotes from @Gavin's answer and comment, thank you):

On the first question (Why does it happen) the answer is:

It looks to me that exceptions is stored separately from the message in the log event

On the second question (how it can be tested) the answer is:

to find what you are looking for in the list of log events and can be expressed in a manner suitable to your domain, e.g checking the that a Throwable was logged, perhaps looking in org.apache.log4j.spi.LoggingEvent for appropriate methods

Finally, my code to verify it was:

Assert.assertEquals(logsList.get(0).getThrowableProxy().getClassName(), "java.lang.NullPointerException");

A Unit test shouldn't test if slf4j is doing what it is supposed to do. That project has its own unit tests, I'm sure. What your code is supposed to test is not if the stack trace is printed in the log, but if the error message and the exception arrive at the logger. From there on, it's slf4j's functionality. — RealSkeptic, Jun 28 '20 at 13:52
@RealSkeptic I want to verify that the ```logger.error``` indeed be called with the ```e``` variable — yoni, Jun 28 '20 at 13:56
I have used junit rules and have extended the log appenders to make sure the correct messages are be logged. From there it’s up to the logging framework to do its job. I have an old repo with an attempt at this. Not saying it’s good code but I can make it public if you think it might help — Gavin, Jun 28 '20 at 14:17
@Gavin the appropriate way to do this is not to send the OP to your old code, but rather, copy the relevant parts of your code and create an answer to the question. — RealSkeptic, Jun 28 '20 at 15:39
@RealSkeptic ah. It did feel “wrong” after I did it. Though I choose this way for a few reason. The major one being there is a number of classes. I will look at fixing this as soon as. Thanks for the pointer. — Gavin, Jun 29 '20 at 08:25
@Gavin thank you for your repo. It seems to be a very nice tool for verifying log messages, but anyway, the problem that was described in my question occurring there as well. The stack isn't part of the log message, and can't be verified via unit tests also via this tool. — yoni, Jun 29 '20 at 08:41
@yoni. Thank you. Exception stacks arent automatically part of a long message, you have to either pass the exception object to the appropriate log method, or manually extract the stack from the exception and pass that to the log method as a String — Gavin, Jun 29 '20 at 08:46
@Gavin, I passed the exception object (with your test tool): ```Integer nullValue = null; try { nullValue += 1; } catch (NullPointerException e) { LOG.error(DEFAULT_LOG_MESSAGE, e); } aRule.expect().loggingEvent(LoggingLevel.ERROR, DEFAULT_LOG_MESSAGE); ``` and still, the stack wasn't part of the log message and the test was marked as pass: — yoni, Jun 29 '20 at 08:58
I think the issue here is that what I wrote was predicated on the log message only. I think the test correctly passes as the expected message is present. It looks to me that exceptions is stored separately from the message in the log event, so you will need to make modifications to the code to also assert and expectation on the exception. — Gavin, Jun 29 '20 at 09:14
@yoni Again, you shouldn't be checking that the stack trace is there. If there is an exception in the event, you shouldn't worry about the stack trace being part of the log - that's the log's implementation. What you should be checking is whether the logging event contains a throwable. That's it. — RealSkeptic, Jun 29 '20 at 09:19
I have removed the link to my code, and provided an overview as to an approach to test log messages in an answer to better fit with the ethos and mission of SO :D — Gavin, Jun 29 '20 at 09:46
This looks ok. I think for myself, so that I had better failure messages I would assert if `getThrowableProxy` is non null then would assert on the type rather than on the name. — Gavin, Jul 06 '20 at 10:59

score 2 · Accepted Answer · answered Jun 29 '20 at 09:41

This is how I have captured log messages in the past, this is based on an old blog (not written by me) that no longer seems to be available.

It is quite old code written for Java 7/8 and Junit4.

I will try to keep this short :)

First you need an Appender it is probably best to extend the AppenderSkeleton, something like:

public class RuleAppender extends AppenderSkeleton {
    private final List<LoggingEvent> loggingEvents = new ArrayList<>();

    protected RuleAppender() {
        super(true);

        this.setThreshold(Level.TRACE);
        setName("Rule Appender");
    }

    @Override
    public void close() {
        // No op in this case
    }

    @Override
    public boolean requiresLayout() {
        return false;
    }

    @Override
    protected void append(final LoggingEvent event) {
        loggingEvents.add(event);
    }

    public boolean hasEventsMeeting(LogExpectation logExpectation) {
         // Use the LogExpectation to determine if the list of log events contains what you want.
    }

    @Override
    public String toString() {
        return "RuleAppender";
    }
}

The LogExpectation is simply somewhere too define an expectation/criteria to match against the stored log events.

This is then wrapped up in a Junit Rule to make adding the the Appender to the Log4J a little easier, I did this by implementing TestRule and extending Statement, ensuring the first thing Statements evaluate method does is:

LogManager.getRootLogger().addAppender(ruleAppender);
LogManager.getRootLogger().setLevel(Level.ALL);

Notes: This can be done without a JUnit rule, so long as the above two lines are executed before the test in order to ensure the appending is added to Log4J (The custom appender is still required).

I have not gone into the JUnit rule code, as we probably should be moving to JUnit 5 which doesnt support Rules and I have not gone into LogExpecation as this is simply away to find what you are looking for in the list of log events and can be expressed in a manner suitable to your domain, e.g checking the that a Throwable was logged, perhaps looking in org.apache.log4j.spi.LoggingEvent for appropriate methods

Please have a look on the finally answer in the end of question above — yoni, Jul 06 '20 at 09:46

How to verify (with unit test) that error stack is printed in the log file?

1 Answers1

Linked