Thanks so much for the elaborate investigation and taking the effort to
share your findings with us. I want to participate in this therapy session.
I learnt the hard way that one should test the logging behaviour of a
certain class. That is, the logging behaviour of subject should be a part
of business requirements and the target needs to be the implemented code,
not the framework/library being used. One should try to verify neither the
(say) Spring logging, nor custom diagnostic logs. It should be logs
mandated by business requirements of code you wrote.
I test such classes with a custom JUnit 5 extension I built at work. In a
nutshell, I create a new stripped `LoggerContext` with a custom `LogEvent`
recording root appender and store/access it via `ExtensionContext` of
JUnit. Similar to you, I pass the `Logger` (created using this test-scoped
`LoggerContext`) to the class using a package-private ctor. This is how it
looks like while flying:
@Log4jEventRecorderEnabled
class LoggingDecodingExceptionHandlerTest {
@Test
void exceptions_should_get_logged(Log4jEventRecorder
log4jEventRecorder) {
// Execute the logic
Logger logger =
log4jEventRecorder.loggerContext().getLogger(Foo.class);
new Foo(logger).runBusinessLogic(...);
// Verify the logging
List<LogEvent> events = log4jEventRecorder.events();
// ...
}
}
Fully thread-safe thanks to `ExtensionContext`-based storage. I have
intentions to share this tooling in `log4j-core-test`, let me know if you
are interested.
What if we are not able to pass the `Logger` instance? Judging from my
experience, a majority of such test cases are invalid. Yet, valid ones do
exist, at relatively few numbers. For those, I rename the test class to
`*ForkedTest` and configure Maven to run them in their forked JVM instances.
On Fri, May 5, 2023 at 3:23 PM Björn Kautler <bjo...@kautler.net> wrote:
> Hi
>
> Thanks for all the hints so far.
>
> I had some time to revisit this topic recently.
> After much blood, sweat and tears (trying out many things, poking around,
> rethinking things, ...),
> I came to the conclusion that there is no satisfactory solution to what I
> intend to do.
>
> I'll describe in more detail now what the situation is, what I found out,
> and with what I ended up doing finally,
> for others to maybe benefit and for curious people to know.
> Maybe you even come up with some other option I didn't consider yet.
> If you are not in either of those groups of people, feel free to stop
> reading here, so I don't waste your time. :-)
>
> ---
>
> There are two "categories" of log messages I was interested in in my tests.
> 1. log messages produced by my code
> 2. log messages produced by Weld
>
> The loggers in my code are all instance fields.
> Even better, they are all injected by CDI, so I can easily control where
> they are coming from.
>
> The loggers in Weld on the other hand are all in static fields in
> interfaces as I learned now.
>
> For my own log messages, I validate that in the right situations, the right
> log messages are written (or not written).
> For the Weld log messages, I mainly tried to verify that there are no WARN
> or higher messages logged.
>
> It turned out that a "thread-local list appender" would not really help.
> In the unit tests most - but not all - log messages are happening on the
> test thread, so for the most messages this could have worked,
> but of course not so much for verifying there are no WARN+ messages logged
> as this could easily miss messages on other threads,
> and of course not for validating the messages happening on other threads.
> This is especially bad in the integ tests, where many threads are involved
> that should have been checked for no WARN+ messages.
>
> The idea with the thread-id based routing logger sounded interesting.
> Getting hold of the actual appender for the thread was a bit cumbersome,
> but nothing that cannot be hidden in a utility method.
> This - together with capturing the thread id where the other-thread log
> messages happened - even allowed to test some of those.
> But other than that it has the same problems the "thread-local list
> appender" would have had.
>
> For verifying there are no WARN+ messages logged, especially in the integ
> tests,
> I also tried to configure a custom appender with level WARN that just
> throws an exception if any log message is produced.
> (Just now found the `AlwaysFailAppender` that does exactly the same)
> Unfortunately this also did not work out too well, because the loggers in
> Weld are not only in static interface fields,
> they are also done through the JBoss logging library, that captures and
> ignores any `Throwable` coming out of the underlying log4j2
> `logger.logMessage(...)` call,
> so the `ignoreExceptions = false` super constructor argument was
> effectively useless for verifying the Weld messages, but worked fine for
> own log messages not done through JBoss logging.
>
> So for the Weld loggers that cannot be verified by a failing appender,
> cannot be verified by thread-based appender, and are kept in static fields,
> I did not have any other idea how to do it, besides maybe somehow ensuring
> each test iteration runs with the classes in dedicated class loaders.
> While I'm not sure whether this would even be possible in a sane way, I
> imagine this to be a major performance and memory hog.
> So in that case it might then probably be easier, cleaner, and better to
> not run the tests in parallel, but sequentially and keep the old "clear
> appender before test starts" logic, or reconfigure the logger context.
> But for now, unless I or you have a better idea how to test it, I decided
> to just remove these verifications and trust in the users reporting
> warnings or errors happening due to my library. :-(
>
> That leaves me with verifying my own log messages.
>
> As described above, even there a thread-based solution is sub-optimal and
> maybe cannot handle all cases.
> So I indeed had a look at `LoggerContextRule` and `LoggerContextResolver`
> so see what they do and possibly port it over to a Spock extension.
> Actually, both of these do not even create new logger contexts.
> They get (through calling `Configurator.initialize(...)`) the context from
> the context selector, so e.g. the one for the test classes class loader
> with the class loader selector or the default context with the basic
> seletor,
> and then they reconfigure that context for the given config URL, so they
> are also both not the least ready for parallel test execution either.
>
> And also the `LoggerContextRule` has the option to manually give a
> `contextSelectorClass`, but it then uses a system property to set it,
> which a parallel test could then again set to a different value, or use
> while it shouldn't use that.
> It also sets two other system properties, that as far as I have seen are
> used nowhere though, they are just set in the beginning and unset in the
> end.
> I guess this is for requesting them manually while debugging test execution
> or similar.
>
> So here is what I ended up doing now:
> - do `Configurator.shutdown(Configurator.initialize("log4j initializer",
> "log4j2-test.xml"));` before any test starts to bootstrap log4j as I got
> errors about mbean registration and after disabling mbean usage warnings
> about multiple enum type converters for the same type as the log4j
> initialization is not done in a thread-safe way (
> https://issues.apache.org/jira/browse/LOG4J2-1094)
> - set `Log4jContextSelector` to
> `org.apache.logging.log4j.core.selector.BasicContextSelector` so that I can
> inject a newly created logger context using `ContextAnchor.THREAD_CONTEXT`
> that is then used when calling `Configurator.initialize(...)`
> - have a Spock extensions that creates a new logger context using `new
> LoggerContext(...)`
> - set the created context to `ContextAnchor.THREAD_CONTEXT` for the
> selector to find it
> - call `Configurator.initialize(...)` which then gets the newly created
> logger context through the basic selector, configures it and returns it
> - set the context to `ContextAnchor.THREAD_CONTEXT` again as the context
> factory did set and unset it
> - inject the logger context to the test instance
> - do the test
> - call `Configurator.shutdown(...)` afterwards
> - unset the `ContextAnchor.THREAD_CONTEXT`
>
> In the test code I then have a CDI producer that uses this logger context
> to create loggers according to injection points and so gives the right
> loggers to the SUT,
> and for the verification, I can get the list appender from that same logger
> context to verify exactly the intended messages.
>
> If I would not have injected the loggers, I think by using the basic
> context selector and setting the `THREAD_CONTEXT` again after the
> `initialize` call,
> the code in question would still get the loggers from the right context as
> long as no static logger fields are used.
>
> Regards
> Björn
>
>
> Am Di., 7. Juni 2022 um 20:26 Uhr schrieb Matt Sicker <boa...@gmail.com>:
>
> > Using the LoggerContextResolver extension, you can indeed get a
> > per-test LoggerContext, but without a corresponding ContextSelector
> > plugin to go with it, you'll have to use JUnit's parameter resolvers
> > to get the Logger or LoggerContext rather than using LogManager. While
> > that pattern works fine in our tests, that's mainly because of what
> > Piotr mentioned about how we log through StatusLogger in the library,
> > so that makes testing regular Loggers simpler here.
> >
> > On Mon, Jun 6, 2022 at 12:47 AM Piotr P. Karwasz
> > <piotr.karw...@gmail.com> wrote:
> > >
> > > Hi, Björn,
> > >
> > > On Wed, 13 Apr 2022 at 17:46, Björn Kautler <bjo...@kautler.net>
> wrote:
> > > >
> > > > I'm currently using ListAppender from log4j2-core-test, to test that
> > > > the logging of the project does what it should do.
> > > > For that I configured a ListAppender in the log4j2 config file that
> is
> > > > used for the tests.
> > > > In a custom global Spock extension (the test framework I use), I
> > > > retrieve the appender
> > > > using ListAppender.getListAppender and call clear() on it before an
> > > > iteration starts,
> > > > so I only get the logs written during that test and it also does not
> > > > overflow the RAM.
> > >
> > > The main question that has not been asked in this thread is: are your
> > > loggers static or instance fields in the classes that you are testing?
> > >
> > > If it is the former (the far most common scenario), the idea of a
> > > LoggerContext per test will not work, since the logger is bound to a
> > > LoggerContext during class initialization. You can however create
> > > multiple list appenders and use RoutingAppender to select the correct
> > > one during testing:
> > >
> > > <Routing name="Routing">
> > > <Routes pattern="$${event:ThreadId}">
> > > <Route>
> > > <List name="${event:ThreadId}"/>
> > > </Route>
> > > </Routes>
> > > </Routing>
> > >
> > > This configuration will get you a different list appender for each
> > > thread, so your logic should work.
> > >
> > > Regarding the Log4j2 unity tests, the situation is different: the
> > > classes we test do not contain loggers, just a `StatusLogger`. While
> > > Matt's extension that provides a different logger context per test
> > > mostly solves the test concurrency problem, the tests that check the
> > > `StatusLogger` output still can not be run concurrently.
> > >
> > > Piotr
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
> > > For additional commands, e-mail: log4j-user-h...@logging.apache.org
> > >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
> > For additional commands, e-mail: log4j-user-h...@logging.apache.org
> >
> >
>
