Re: Unit testing custom log event factory fails intermittently

I don't think there's any lingering threads, Carter.

I changed my test to follow the pattern of
AsyncLoggerConfigErrorOnFormat.java. Same story -- works locally; in
CI, it works if it's the only test that's run; and intermittently if
run with the whole suite. The test is very simple and should look
familiar as it's inspiration is from doNotProcessPlaceholdersTwice in
AsyncLoggerConfigErrorOnFormat.java.

class Scratch
{
    private static BufferedReader _reader;

    @BeforeClass
    public static void beforeClass() throws IOException
    {
        System.setProperty("log4j2.logEventFactory",
                           MyGoodLogEventFactory.class.getName());
        File tmpFile = File.createTempFile(Scratch.class.getName(), ".log");

        tmpFile.deleteOnExit();

        System.setProperty("log-file", tmpFile.getAbsolutePath());
        System.setProperty(CONFIGURATION_FILE_PROPERTY,
                           "fileAppender.xml");

        _reader = new BufferedReader(new FileReader(tmpFile));
    }

    @AfterClass
    public static void afterClass()
    {
        IOUtils.closeQuietly(_reader);
    }

    @Test
    public void Test_that_slf4j_log_messages_with_marker_get_handled_correctly()
            throws IOException
    {
        // GIVEN: An SLF4J logger
        Logger slf4jLogger = LoggerFactory.getLogger("FileLogger");

        // WHEN: The SLF4J logger is used with the "MASK" marker
        slf4jLogger.debug(MyGoodMaskMarker.MY_GOOD_SLF4J_MARKER,
"Hello, {}", "test");

        // THEN: The resulting message is as expected
        Assert.assertEquals("Hello, XYZ", _reader.readLine());
    }
}

The fileAppender.xml contains this:

<Configuration status="WARN">
    <Appenders>
        <File name="File1"
              fileName="${sys:log-file}"
              bufferedIO="false"
              immediateFlush="true"
              append="false">
            <PatternLayout>
                <Pattern>%m%n</Pattern>
            </PatternLayout>
        </File>
    </Appenders>

    <Loggers>
        <Root level="DEBUG">
            <AppenderRef ref="File1"/>
        </Root>
    </Loggers>
</Configuration>

Two questions:

1. Do you see any issues with this test code?
2. Is there some other way to set the LogEventFactory besides a system
property? I don't have to use the system property. That can be
manually tested.

On Wed, Sep 29, 2021 at 8:42 PM Carter Kozak <[email protected]> wrote:
>
> I think the LoggerContextRule can fail to apply the provided configuration if another thread happens to access a logger (re-initializing the default config) after the rule has stopped the old context, but before it has initialized the new one. We may be able to update it with a loop so it tries harder, ideally throwing an exception if it fails to set the expected context.
> Is there any chance another test may be leaking threads beyond the scope of the test?
>
> -ck
>
> On Wed, Sep 29, 2021, at 14:33, Gary Gregory wrote:
> > Another reason to stick to Maven ;-)
> >
> > On Wed, Sep 29, 2021, 14:32 Travis Spencer <[email protected]> wrote:
> >
> > > Thanks, Gary, for the reply. Unfortunately, a -D approach means a ton
> > > of Gradle voodoo. I can ask one of the witchdocers to help with that,
> > > but will try to copy the technique used AsyncLoggerConfigErrorOnFormat
> > > first. Will report back on how it goes either way. Happy to receive
> > > additional suggestions in the meantime.
> > >
> > >
> > > On Wed, Sep 29, 2021 at 8:08 PM Gary Gregory <[email protected]>
> > > wrote:
> > > >
> > > > I would suggest finding some baseline that works by using -D on the
> > > command
> > > > line definition of your CI.
> > > >
> > > > Gary
> > > >
> > > > On Wed, Sep 29, 2021, 12:12 Travis Spencer <[email protected]> wrote:
> > > >
> > > > > Greetings, Log4j list.
> > > > >
> > > > > I am testing some extensions that I have made to my usage of Log4j.
> > > > > This usage involves a custom log event factory. I set this in my
> > > > > actual program on startup using a system property. Now, to test this
> > > > > in a unit test, I'm trying to set a system property in the same sort
> > > > > of way. To that end, I have a static block in the test and a JUnit
> > > > > ClassRule like this:
> > > > >
> > > > > static
> > > > > {
> > > > >     System.setProperty("log4j2.logEventFactory",
> > > > > MyGoodLogEventFactory.class.getName());
> > > > > }
> > > > >
> > > > > @ClassRule
> > > > > public static LoggerContextRule _context = new
> > > > > LoggerContextRule("myGoodConfig.xml");
> > > > >
> > > > > This works perfectly on my local machine. In our CI system, however,
> > > > > this fails sometimes. If I run only this one test in the CI system, it
> > > > > passes every time. If I run all unit tests, however, it usually fails,
> > > > > but does occasionally succeed. The hypothesis is that it depends on
> > > > > which unit test is run first and whether or not the Log4j subsystem is
> > > > > initialized yet. If it's not, the system property above is set and
> > > > > everything works. If the Log4j subsystem is initialized, however, by
> > > > > the time this test runs, then the system property (and thus the log
> > > > > event factory) is not used.
> > > > >
> > > > > To test this hypothesis, I updated the test to do this instead:
> > > > >
> > > > > static
> > > > > {
> > > > >     System.setProperty("log4j2.logEventFactory",
> > > > > MaskedLogEventFactory.class.getName());
> > > > >     LoggerContextRule context = new
> > > LoggerContextRule("myGoodConfig.xml");
> > > > >     if (context.getLoggerContext() != null) context.reconfigure();
> > > > >     _context = context;
> > > > > }
> > > > >
> > > > > @ClassRule
> > > > > public static LoggerContextRule _context;
> > > > >
> > > > > This had no effect though, and the test still passed locally, passed
> > > > > remotely if it was the only test run, but failed intermittently if run
> > > > > as a part of the entire suite.
> > > > >
> > > > > Looking through the Log4j source, I only found one test that was
> > > > > setting a custom log event factory,
> > > > >
> > > > >
> > > src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigErrorOnFormat.java.
> > > > > This test, however, doesn't use the LoggerContextRule to configure the
> > > > > system. I really like this API for the tests and would like to
> > > > > continue to use it.
> > > > >
> > > > > Can anyone offer me help in:
> > > > >
> > > > > 1. Confirming that my hypothesis is correct that the tests likely fail
> > > > > intermittently due to the initialization state of the Log4j subsystem
> > > > > 2. Suggest a way to make the rest more resilient
> > > > >
> > > > > TIA!
> > > > >
> > > > > Travis Spencer
> > > > >
> > > > > ---------------------------------------------------------------------
> > > > > To unsubscribe, e-mail: [email protected]
> > > > > For additional commands, e-mail: [email protected]
> > > > >
> > > > >
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: [email protected]
> > > For additional commands, e-mail: [email protected]
> > >
> > >
> >