Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Tests failing because Logback appenders don't exist #457

Closed
sleberknight opened this issue Feb 4, 2024 · 3 comments · Fixed by #459
Closed

Tests failing because Logback appenders don't exist #457

sleberknight opened this issue Feb 4, 2024 · 3 comments · Fixed by #459
Assignees
Labels
bug Something isn't working
Milestone

Comments

@sleberknight
Copy link
Member

After the last few commits were merged, we suddenly started seeing InMemoryAppenderTest and LoggingComparisonListenerTest fail. The errors look like:

Error:    InMemoryAppenderTest$EventAssertions.shouldAssertNumberOfLoggingEventsOnly [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null

This happens in the GitHub Actions CI environment, and also when running tests from the command line in Gitpod, i.e, via mvn test. But this does not happen when running the tests using Maven from the command line on my MacBook Pro or from within IntelliJ. All the tests pass when running them using the Java Test Runner in VSCode in Gitpod.

The problem is that InMemoryAppenderTest and LoggingComparisonListenerTest both rely on specific Logback appenders, since they are testing Logback and appending behavior. But in the GitHub Actions environment and from the command line in Gitpod (both of which are Linux), the appenders are simply gone when these tests run.

There are two factors at play here. First, Maven's Surefire test plugin runs tests in a non-deterministic manner (as it should since we don't want tests to require execution in a specific order). Second, some tests are using Dropwizard testing extensions like DropwizardAppExtension and DropwizardClientExtension, both of which - rather unfortunately - mess with the Logback logging configuration once tests have executed. They do this presumably because they actually create and start a Dropwizard application for testing purposes. Both of these extensions use the DropwizardTestSupport class, which does the following in its private stopIfRequired method:

// Don't leak logging appenders into other test cases
if (configuration != null) {
    configuration.getLoggingFactory().reset();
} else {
    LoggingUtil.getLoggerContext().getLogger(Logger.ROOT_LOGGER_NAME).detachAndStopAllAppenders();
}

The key part is the call to detachAndStopAllAppenders. When you combine that with the non-deterministic test execution order, if tests that use a Dropwizard extension execute before InMemoryAppenderTest or LoggingComparisonListenerTest, then the appenders will have been removed already, and thus our tests fail.

I don't think it's great for the Dropwizard extensions to detach and stop all appenders. I'd rather they not mess with the Logback logging configuration at all during tests. But I doubt that's going to change. So, the solution here is that we need to ensure that the expected appender exists. And specifically, we need to change InMemoryAppenderExtension so that if it sees that the appender does not exist in its beforeEach method, it resets the Logback logging configuration.

For this issue, make the fix in InMemoryAppenderExtension. But later the reset mechanism can be exposed so that any test could do this. And this would allow tests that use the useful but troublesome Dropwizard extensions to reset the logging configuration in a @AfterAll method. This would have the side-benefit of ensuring tests can log. For many years now, it has annoyed me that if a test using a Dropwizard extension runs early in the test execution, none of the subsequent tests log anything (because all the appenders were removed).

Here is output from a recent test run in GitHub Actions:

Error:  Failures: 
Error:    InMemoryAppenderTest$EventAssertions.shouldAssertNumberOfLoggingEventsOnly [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest$EventAssertions.shouldAssertWhenContainsLoggingEvents [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest$EventAssertions.shouldAssertWhenEmpty [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest$EventAssertions.shouldCheckContainsMessageWhenItDoesNotExist [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest$EventAssertions.shouldCheckContainsMessageWhenItExists [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest$EventAssertions.shouldGetOrderedLoggingEventsOnly [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest$GetEventMap.shouldReturnCopyOfEventMap [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest$GetEventMap.shouldReturnEvents [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest$GetEventMap.shouldReturnUnmodifiableCopyOfEventMap [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest.shouldAppendAnEvent [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest.shouldClearAllLoggingEvents [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest.shouldReturnEventsInOrderTheyWereLogged [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    InMemoryAppenderTest.shouldReturnOrderedLogMessages [Expected an appender named 'InMemoryAppenderTestAppender' for logger 'org.kiwiproject.test.logback.InMemoryAppenderTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    LoggingComparisonListenerTest.shouldLogWithNoTestName [Expected an appender named 'LoggingComparisonListenerTestAppender' for logger 'org.kiwiproject.test.xmlunit.LoggingComparisonListenerTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    LoggingComparisonListenerTest.shouldLogWithTestName [Expected an appender named 'LoggingComparisonListenerTestAppender' for logger 'org.kiwiproject.test.xmlunit.LoggingComparisonListenerTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    LoggingComparisonListenerTest.shouldLogWithTestName_FromTestInfo [Expected an appender named 'LoggingComparisonListenerTestAppender' for logger 'org.kiwiproject.test.xmlunit.LoggingComparisonListenerTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    LoggingComparisonListenerTest.shouldNotLogWhenComparisonResultIsNotDifferent(ComparisonResult)[1] [Expected an appender named 'LoggingComparisonListenerTestAppender' for logger 'org.kiwiproject.test.xmlunit.LoggingComparisonListenerTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
Error:    LoggingComparisonListenerTest.shouldNotLogWhenComparisonResultIsNotDifferent(ComparisonResult)[2] [Expected an appender named 'LoggingComparisonListenerTestAppender' for logger 'org.kiwiproject.test.xmlunit.LoggingComparisonListenerTest' of type org.kiwiproject.test.logback.InMemoryAppender] 
Expecting actual not to be null
[INFO] 
Error:  Tests run: 1463, Failures: 18, Errors: 0, Skipped: 0
@sleberknight sleberknight added the bug Something isn't working label Feb 4, 2024
@sleberknight sleberknight added this to the 3.2.1 milestone Feb 4, 2024
@sleberknight sleberknight self-assigned this Feb 4, 2024
@sleberknight
Copy link
Member Author

In addition, we could also create a Jupiter extension that would automagically reset the Logback logging system assuming the default logback-test.xml (and maybe if that isn't found it falls back to logback.xml. For example:

@ExtendWith(ResetLogbackLoggingExtension.class)
class MyTest {
    // ...
}

And if there is a need to customize the logging configuration, then it could be registered programmatically:

class MyTest {

    @RegisterExtension
    static final ResetLogbackLoggingExtension resetLogbackExtension =
            ResetLogbackLoggingExtension.builder()
                .withLoggingConfiguration("my-custom-test-logback-config.xml")
                .build()
    // ...
}

The extension would reset Logback after all tests have run, e.g. in a @AfterAll.

@sleberknight
Copy link
Member Author

And now for some strange reason, doing amvn test inside Gitpod works just fine...all 1,463 tests pass. But still seeing the failures in GitHub Actions CI, so...

@sleberknight
Copy link
Member Author

Never mind, it still fails in Gitpod....

sleberknight added a commit that referenced this issue Feb 6, 2024
* Update InMemoryAppenderExtension so that it will reset
  the Logback logging system if it doesn't find the expected
  appenders. It only tries once, which will fix the case when
  a previously-executed test corrupts the logging system,
  like DropwizardAppExtension and DropwizardClientExtension
  both do by stopping and detaching ALL appenders.

Fixes #457
dsingley pushed a commit that referenced this issue Feb 6, 2024
* Update InMemoryAppenderExtension so that it will reset
  the Logback logging system if it doesn't find the expected
  appenders. It only tries once, which will fix the case when
  a previously-executed test corrupts the logging system,
  like DropwizardAppExtension and DropwizardClientExtension
  both do by stopping and detaching ALL appenders.

Fixes #457
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant