> I came to the conclusion that there is no satisfactory solution to what I
intend to do.
Lies, lies, lies.
Everything alternative facts. :-D
Ralph had a simple but brilliant idea that he mentioned in LOG4J2-1094.
I removed all the custom logic and instead now enable
`log4j.isThreadContextMapInheritable`,
and then use a TCM entry to identify the log messages properly and
associate them to the correct test iteration.
This even works properly with the static logger fields.
With this I can properly identify the log messages done within a test
iteration, also on child threads,
and after the test I can use the same key to clear out those log messages
from the `ListAppender` to not overflow the RAM.
> I have intentions to share this tooling in `log4j-core-test`, let me know
if you are interested.
Thanks, but it looks like I'm perfectly fine with the TCM solution which
also is much leaner. :-)
Regards
Björn
Am Mo., 8. Mai 2023 um 13:35 Uhr schrieb Volkan Yazıcı <vol...@yazi.ci>:
> 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
> > >
> > >
> >
>
