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
>
>
