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]
> > >
> > >
> >
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
