This is a very good observation. When the status logger was implemented it
targeted System.out, which you obviously never want to close. Shortly there
after the ability to route it to a file instead was added. I guess we just
never thought to add logic to close it at shutdown.
Ralph
> On Feb 18, 2021, at 7:01 PM, Tim Perry <tim.v...@gmail.com> wrote:
>
> It looks to me like LoggerContext.stop(...) closes the file 'test.log'.
> However, I can't find anything closing 'status.log'. They are configured in
> the same XML file: log4j-filetest.xml
>
> <Configuration status="debug" dest="target/status.log"
> name="XMLConfigTest">
> <Properties>
> <Property name="filename">target/test.log</Property>
> </Properties> ...</Configuration>
> </Configuration>
>
> I modified the @Test from FileOutputTest to see if it could delete the log
> files in the test. On windows, neither file gets deleted and in both delete
> attempts I get an IOException with the message "The process cannot access
> the file because it is being used by another process.". On Ubuntu, no
> exception is thrown even though the file is obviously open. See the code
> below.
>
> From this I'm guessing that nothing closes status.log before the
> FileCleaner goes to delete it and that it triggers an exception on Windows,
> but not Linux. My guess is that the default file locking level is different
> between JVM's or OS's. What should be releasing the file handle for
> status.log? LoggerContext?
>
>
> @Test
> @LoggerContextSource("classpath:log4j-filetest.xml")
> public void testConfig() throws IOException {
> final Path logFile = Paths.get("target", "status.log");
> assertTrue(Files.exists(logFile), "Status output file does not
> exist");
> assertTrue(Files.size(logFile) > 0, "File is empty");
>
> try {
> Files.deleteIfExists(logFile);
> fail("Should not have been able to delete " + logFile); // this
> is called on Ubuntu, but not Windows
> } catch (IOException ioe) {
> // this is called for Windows,but not Ubuntu
> System.err.println("THIS SHOULD FAIL: Failed to delete " +
> logFile + ": " + ioe.getMessage());
> }
> final Path testLog = Paths.get("target", "test.log");
> try {
> Files.deleteIfExists(testLog);
> fail("Should not have been able to delete " + testLog); // this
> presumably would be called for Ubuntu, but we failed above.
> } catch (IOException ioe) {
> // this is called for Windows,but not Ubuntu
> System.err.println("THIS SHOULD FAIL: Failed to delete " +
> testLog + ": " + ioe.getMessage());
> }
> }
>
> On Thu, Feb 18, 2021 at 8:48 AM Matt Sicker <boa...@gmail.com> wrote:
>
>> The gist of what I recall the problem being was that sometimes, a file
>> might still be in use asynchronously for various appenders (e.g.,
>> during rolling, compression, etc.), so the shutdown and removal of
>> temporary files needs to signal that the configuration needs to shut
>> down. It looks like you may have found the missing link as to why this
>> wasn't working properly. In that particular error message, that is
>> some race condition where the temporary file is attempted to be
>> deleted before the configuration stops.
>>
>> On Wed, 17 Feb 2021 at 18:19, Tim Perry <tim.v...@gmail.com> wrote:
>>>
>>> Matt,
>>>
>>> The problem is:
>>> target\status.log failed with java.nio.file.FileSystemException:
>>> target\status.log: The process cannot access the file because it is being
>>> used by another process.
>>>
>>> I'm not familiar with how log4j should be releasing the log file to know
>>> where to look. I did notice the afterAll(context) method is never called
>> on
>>> the LoggerContextResolver. Would that explain why the file stays locked?
>>>
>>> Tim
>>>
>>> On Wed, Feb 17, 2021 at 1:49 PM Tim Perry <tim.v...@gmail.com> wrote:
>>>
>>>> Yes, I am on windows 10. I'm using Zulu OpenJdk for both Java 8 and 11,
>>>> maven 3.6.3, and a fairly new Eclipse. I'd be happy to help you sort
>> out
>>>> the problem. It will be fun: I haven't played around with those junit
>>>> features.
>>>>
>>>> On Wed, Feb 17, 2021 at 1:45 PM Matt Sicker <boa...@gmail.com> wrote:
>>>>
>>>>> Is that on Windows? If so, there seems to be a bug I've introduced in
>>>>> the JUnit 5 code that I tried to port from the JUnit 4 code correctly,
>>>>> but I don't have a Windows machine to test that out on iteratively.
>>>>> See
>>>>>
>> https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/test/java/org/apache/logging/log4j/junit/LoggerContextResolver.java
>>>>> for relevant code and the JUnit 4 version here in
>>>>>
>>>>>
>> https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/test/java/org/apache/logging/log4j/junit/LoggerContextRule.java
>>>>> which does reconfiguration a bit more heavily (but also in such a way
>>>>> that it works more consistently on Windows apparently?)
>>>>>
>>>>> On Wed, 17 Feb 2021 at 15:36, Tim Perry <tim.v...@gmail.com> wrote:
>>>>>>
>>>>>> I mean is that:
>>>>>>
>>>>>> * when I run "mvn install" on the command line then usually 1, but
>>>>>> sometimes 2 tests fail.
>>>>>> * when I right-click the src/tests/java folder in eclipse and do
>> "run as
>>>>>> JUnit" I get ~100 failures.
>>>>>>
>>>>>> I'm fairly sure the tests are *not* running in parallel.
>>>>>>
>>>>>> On Wed, Feb 17, 2021 at 1:11 PM Matt Sicker <boa...@gmail.com>
>> wrote:
>>>>>>
>>>>>>> I think he's referring to the need to run mvn install once before
>> the
>>>>>>> IDE will pick up snapshot jars for things like annotation
>> processing
>>>>>>> or other fancy things. Simple way to reproduce: try running "mvn
>>>>>>> package" without the "install" target.
>>>>>>>
>>>>>>> On Wed, 17 Feb 2021 at 13:58, Ralph Goers <
>> ralph.go...@dslextreme.com
>>>>>>
>>>>>>> wrote:
>>>>>>>>
>>>>>>>> Yeah, there is a very good chance if you are trying to run
>> tests in
>>>>> core
>>>>>>> in parallel on multiple threads that they will fail. Most of them
>>>>> expect
>>>>>>> their own LoggerContext.
>>>>>>>>
>>>>>>>> Ralph
>>>>>>>>
>>>>>>>>> On Feb 17, 2021, at 12:51 PM, Tim Perry <tim.v...@gmail.com>
>>>>> wrote:
>>>>>>>>>
>>>>>>>>> On master, I noticed that when I build in my IDE that lots of
>>>>> tests in
>>>>>>>>> log4j-core fail but when I build with maven they pass. In the
>>>>> past,
>>>>>>> when
>>>>>>>>> I've seen this on other projects it was caused by race
>>>>> conditions. I
>>>>>>>>> wonder: are there race conditions in the tests or the code
>> that
>>>>> need
>>>>>>> to be
>>>>>>>>> addressed?
>>>>>>>>>
>>>>>>>>> On Sun, Feb 7, 2021 at 1:46 PM Ralph Goers <
>>>>> ralph.go...@dslextreme.com
>>>>>>>>
>>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>>> Yes, that is why I am wondering why master is so flaky.
>>>>>>>>>>
>>>>>>>>>> Ralph
>>>>>>>>>>
>>>>>>>>>>> On Feb 7, 2021, at 2:34 PM, Gary Gregory <
>>>>> garydgreg...@gmail.com>
>>>>>>> wrote:
>>>>>>>>>>>
>>>>>>>>>>> FWIW but not master, I've been building release-2.x lately
>> over
>>>>> and
>>>>>>> over
>>>>>>>>>>> without issues aside from the rare random failure.
>>>>>>>>>>>
>>>>>>>>>>> G
>>>>>>>>>>>
>>>>>>>>>>> On Sun, Feb 7, 2021 at 2:37 PM Matt Sicker <
>> boa...@gmail.com>
>>>>> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> I'm not getting errors in log4j-api, though it's possible
>> some
>>>>> test
>>>>>>> is
>>>>>>>>>>>> missing a JUnit annotation which is causing that
>> ThreadContext
>>>>> data
>>>>>>>>>>>> corruption.
>>>>>>>>>>>>
>>>>>>>>>>>> I am, however, getting the same log4j-kafka test error.
>> I'll
>>>>> try
>>>>>>>>>>>> running the log4j-api tests a few more times to see if I
>> can
>>>>>>> reproduce
>>>>>>>>>>>> any test errors there.
>>>>>>>>>>>>
>>>>>>>>>>>> On Sun, 7 Feb 2021 at 12:20, Ralph Goers <
>>>>>>> ralph.go...@dslextreme.com>
>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>> I am trying to apply patches to the release-2.x branch and
>>>>> make the
>>>>>>>>>>>> corresponding changes in master. When I run a build in
>> master I
>>>>>>> cannot
>>>>>>>>>> get
>>>>>>>>>>>> it to succeed. It randomly fails in different ways. I
>>>>> typically run
>>>>>>> a
>>>>>>>>>> full
>>>>>>>>>>>> build when I make significant changes and don’t commit
>> unless
>>>>> it
>>>>>>>>>> passes. So
>>>>>>>>>>>> far I have spent well over an hour running the build at
>> least 6
>>>>>>> times
>>>>>>>>>>>> trying to get a successful build with no luck.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Run 1 fails in log4j-api
>>>>>>>>>>>>> [ERROR] Failures:
>>>>>>>>>>>>> [ERROR]
>>>>> AbstractLoggerTest.testMessageThrowsAndNullFormat:912
>>>>>>>>>>>>> Expected: a string containing
>>>>>>>>>>>> "org.apache.logging.log4j.spi.AbstractLogger caught
>>>>>>>>>>>> java.lang.IllegalStateException logging TestMessage: "
>>>>>>>>>>>>> but: was "2021-02-07 10:00:31,277
>> ForkJoinPool-1-worker-30
>>>>> WARN
>>>>>>>>>>>> Ignoring java.io.NotSerializableException:
>> java.lang.Object
>>>>> for
>>>>>>> key[2]
>>>>>>>>>>>> ('unserializable')"
>>>>>>>>>>>>> [ERROR]
>>>>>>> CloseableThreadContextTest.canReuseCloseableThreadContext:169
>>>>>>>>>>>> expected: <value> but was: <null>
>>>>>>>>>>>>> [ERROR] CloseableThreadContextTest.closeIsIdempotent:203
>>>>>>> expected:
>>>>>>>>>>>> <map to keep> but was: <null>
>>>>>>>>>>>>> [ERROR]
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> CloseableThreadContextTest.ifTheSameKeyIsAddedTwiceTheOriginalShouldBeUsed:103
>>>>>>>>>>>> expected: <innerValue> but was: <null>
>>>>>>>>>>>>> [ERROR]
>>>>> CloseableThreadContextTest.pushAllWillPushAllValues:237
>>>>>>>>>>>> expected: <key> but was: <>
>>>>>>>>>>>>> [ERROR]
>>>>> CloseableThreadContextTest.putAllWillPutAllValues:222
>>>>>>>>>>>> expected: <value> but was: <null>
>>>>>>>>>>>>> [ERROR]
>>>>> CloseableThreadContextTest.shouldAddAnEntryToTheMap:53
>>>>>>>>>>>> expected: <value> but was: <null>
>>>>>>>>>>>>> [ERROR]
>>>>>>>>>>>>
>>>>> CloseableThreadContextTest.shouldAddEntriesToBothStackAndMap:156
>>>>>>>>>> expected:
>>>>>>>>>>>> <value> but was: <null>
>>>>>>>>>>>>> [ERROR]
>>>>> CloseableThreadContextTest.shouldAddTwoEntriesToTheMap:63
>>>>>>>>>>>> expected: <value> but was: <null>
>>>>>>>>>>>>> [ERROR] CloseableThreadContextTest.shouldNestEntries:75
>>>>> expected:
>>>>>>>>>>>> <value> but was: <null>
>>>>>>>>>>>>> [ERROR]
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> CloseableThreadContextTest.shouldPreserveOldEntriesFromTheMapWhenAutoClosed:91
>>>>>>>>>>>> expected: <value> but was: <null>
>>>>>>>>>>>>> [ERROR]
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> CloseableThreadContextTest.shouldPushAndPopAParameterizedEntryToTheStack:137
>>>>>>>>>>>> expected: <message param> but was: <>
>>>>>>>>>>>>> [ERROR]
>>>>>>>>>>>>
>>>>> CloseableThreadContextTest.shouldPushAndPopAnEntryToTheStack:113
>>>>>>>>>> expected:
>>>>>>>>>>>> <message> but was: <>
>>>>>>>>>>>>> [ERROR]
>>>>>>>>>>>>
>>>>> CloseableThreadContextTest.shouldPushAndPopTwoEntriesToTheStack:124
>>>>>>>>>>>> expected: <message2> but was: <>
>>>>>>>>>>>>> [ERROR]
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> CloseableThreadContextTest.shouldRemoveAnEntryFromTheMapWhenAutoClosed:146
>>>>>>>>>>>> expected: <value> but was: <null>
>>>>>>>>>>>>> [INFO]
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> Run 2 fails in log4j-api
>>>>>>>>>>>>> [ERROR] Failures:
>>>>>>>>>>>>> [ERROR] LoggerTest.mdc:556 Test Year is null ==>
>> expected:
>>>>> not
>>>>>>> <null>
>>>>>>>>>>>>>
>>>>>>>>>>>>> Run 3 log4j-api passes but log4j-core fails
>>>>>>>>>>>>> [INFO]
>>>>>>>>>>>>> [ERROR] Failures:
>>>>>>>>>>>>> [ERROR]
>>>>> RollingDirectTimeNewDirectoryTest.streamClosedError:95
>>>>>>> check
>>>>>>>>>>>> failure
>>>>>>>>>>>>>
>>>>>>>>>>>>> Run 4 - log4j-api and log4j-core pass but fails in
>> log4j-kafka
>>>>>>>>>>>>> [ERROR] Failures:
>>>>>>>>>>>>> [ERROR] ConfigurationBuilderTest.testXmlConstructing:116
>>>>>>>>>>>> expected:<<?xml version="1.0" [?>
>>>>>>>>>>>>> ]<Configuration name=...> but was:<<?xml version="1.0"
>>>>>>>>>>>> [encoding="UTF-8"?>]<Configuration name=…>
>>>>>>>>>>>>>
>>>>>>>>>>>>> Run 5 - failure in log4j-core (I’m probably the last one
>> to
>>>>> touch
>>>>>>> this
>>>>>>>>>>>> so I’m the one who will most likely need to figure this one
>>>>> out)
>>>>>>>>>>>>>
>>>>>>>>>>>>> [ERROR] Failures:
>>>>>>>>>>>>> [ERROR]
>> RollingAppenderDirectWrite1906Test.testAppender:95
>>>>>>> 2021-02-07
>>>>>>>>>>>> 10:50:17,478 main INFO Log4j appears to be running in a
>> Servlet
>>>>>>>>>>>> environment, but there's no log4j-web module available. If
>> you
>>>>> want
>>>>>>>>>> better
>>>>>>>>>>>> web container support, please add the log4j-web JAR to
>> your web
>>>>>>> archive
>>>>>>>>>> or
>>>>>>>>>>>> server lib directory.
>>>>>>>>>>>>> 2021-02-07 10:50:17,488 main INFO Log4j appears to be
>> running
>>>>> in a
>>>>>>>>>>>> Servlet environment, but there's no log4j-web module
>>>>> available. If
>>>>>>> you
>>>>>>>>>> want
>>>>>>>>>>>> better web container support, please add the log4j-web JAR
>> to
>>>>> your
>>>>>>> web
>>>>>>>>>>>> archive or server lib directory.
>>>>>>>>>>>>> 2021-02-07 10:50:17,499 main DEBUG Took 0.003727 seconds
>> to
>>>>> load 3
>>>>>>>>>>>> plugins from sun.misc.Launcher$AppClassLoader@4aa298b7
>>>>>>>>>>>>> 2021-02-07 10:50:17,505 main DEBUG Took 0.005450 seconds
>> to
>>>>> load
>>>>>>> 220
>>>>>>>>>>>> plugins from sun.misc.Launcher$AppClassLoader@4aa298b7
>>>>>>>>>>>>> 2021-02-07 10:50:17,506 main DEBUG Took 0.000032 seconds
>> to
>>>>> load 0
>>>>>>>>>>>> plugins from sun.misc.Launcher$ExtClassLoader@44f75083
>>>>>>>>>>>>> 2021-02-07 10:50:17,506 main DEBUG PluginManager
>> 'Converter'
>>>>> found
>>>>>>> 46
>>>>>>>>>>>> plugins
>>>>>>>>>>>>> 2021-02-07 10:50:17,540 main DEBUG Starting
>>>>> OutputStreamManager
>>>>>>>>>>>> SYSTEM_OUT.false.false-1
>>>>>>>>>>>>> 2021-02-07 10:50:17,541 main DEBUG Initializing Thread
>>>>> Context Data
>>>>>>>>>>>> Service Providers
>>>>>>>>>>>>> 2021-02-07 10:50:17,541 main DEBUG Thread Context Data
>> Service
>>>>>>> Provider
>>>>>>>>>>>> initialization complete
>>>>>>>>>>>>> 2021-02-07 10:50:17,544 main INFO Log4j appears to be
>> running
>>>>> in a
>>>>>>>>>>>> Servlet environment, but there's no log4j-web module
>>>>> available. If
>>>>>>> you
>>>>>>>>>> want
>>>>>>>>>>>> better web container support, please add the log4j-web JAR
>> to
>>>>> your
>>>>>>> web
>>>>>>>>>>>> archive or server lib directory.
>>>>>>>>>>>>> 2021-02-07 10:50:17,545 main DEBUG PluginManager
>>>>>>> 'ConfigurationFactory'
>>>>>>>>>>>> found 4 plugins
>>>>>>>>>>>>> 2021-02-07 10:50:17,548 main INFO Log4j appears to be
>> running
>>>>> in a
>>>>>>>>>>>> Servlet environment, but there's no log4j-web module
>>>>> available. If
>>>>>>> you
>>>>>>>>>> want
>>>>>>>>>>>> better web container support, please add the log4j-web JAR
>> to
>>>>> your
>>>>>>> web
>>>>>>>>>>>> archive or server lib directory.
>>>>>>>>>>>>> 2021-02-07 10:50:17,549 main INFO Log4j appears to be
>> running
>>>>> in a
>>>>>>>>>>>> Servlet environment, but there's no log4j-web module
>>>>> available. If
>>>>>>> you
>>>>>>>>>> want
>>>>>>>>>>>> better web container support, please add the log4j-web JAR
>> to
>>>>> your
>>>>>>> web
>>>>>>>>>>>> archive or server lib directory.
>>>>>>>>>>>>> 2021-02-07 10:50:17,557 main INFO Log4j appears to be
>> running
>>>>> in a
>>>>>>>>>>>> Servlet environment, but there's no log4j-web module
>>>>> available. If
>>>>>>> you
>>>>>>>>>> want
>>>>>>>>>>>> better web container support, please add the log4j-web JAR
>> to
>>>>> your
>>>>>>> web
>>>>>>>>>>>> archive or server lib directory.
>>>>>>>>>>>>> 2021-02-07 10:50:17,558 main INFO Log4j appears to be
>> running
>>>>> in a
>>>>>>>>>>>> Servlet environment, but there's no log4j-web module
>>>>> available. If
>>>>>>> you
>>>>>>>>>> want
>>>>>>>>>>>> better web container support, please add the log4j-web JAR
>> to
>>>>> your
>>>>>>> web
>>>>>>>>>>>> archive or server lib directory.
>>>>>>>>>>>>> 2021-02-07 10:50:17,561 main DEBUG Using
>> configurationFactory
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@4387b79e
>>>>>>>>>>>>> 2021-02-07 10:50:17,562 main TRACE Trying to find
>>>>>>>>>>>> [log4j-rolling-direct-1906.xml] using context class loader
>>>>>>>>>>>> sun.misc.Launcher$AppClassLoader@4aa298b7.
>>>>>>>>>>>>> 2021-02-07 10:50:17,566 main INFO Log4j appears to be
>> running
>>>>> in a
>>>>>>>>>>>> Servlet environment, but there's no log4j-web module
>>>>> available. If
>>>>>>> you
>>>>>>>>>> want
>>>>>>>>>>>> better web container support, please add the log4j-web JAR
>> to
>>>>> your
>>>>>>> web
>>>>>>>>>>>> archive or server lib directory.
>>>>>>>>>>>>> 2021-02-07 10:50:17,567 main DEBUG Closing
>> BufferedInputStream
>>>>>>>>>>>> java.io.BufferedInputStream@2cbb3d47
>>>>>>>>>>>>> 2021-02-07 10:50:17,594 main DEBUG Watching configuration
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> '/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml'
>>>>>>>>>>>> for lastModified Sun Feb 07 10:46:58 MST 2021
>> (1612720018000)
>>>>>>>>>>>>> 2021-02-07 10:50:17,595 main DEBUG Starting
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> LoggerContext[name=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test)]
>>>>>>>>>>>> from configuration at log4j-rolling-direct-1906.xml
>>>>>>>>>>>>> 2021-02-07 10:50:17,595 main DEBUG Starting
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> LoggerContext[name=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),
>>>>>>>>>>>> org.apache.logging.log4j.core.LoggerContext@add0edd] with
>>>>>>> configuration
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]...
>>>>>>>>>>>>> 2021-02-07 10:50:17,595 main DEBUG Shutdown hook enabled.
>>>>>>> Registering a
>>>>>>>>>>>> new one.
>>>>>>>>>>>>> 2021-02-07 10:50:17,601 main DEBUG null null initializing
>>>>>>> configuration
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
>>>>>>>>>>>>> 2021-02-07 10:50:17,605 main DEBUG Installed 3 script
>> engines
>>>>>>>>>>>>> 2021-02-07 10:50:17,772 main DEBUG Oracle Nashorn version:
>>>>>>> 1.8.0_144,
>>>>>>>>>>>> language: ECMAScript, threading: Not Thread Safe, compile:
>>>>> true,
>>>>>>> names:
>>>>>>>>>>>> [nashorn, Nashorn, js, JS, JavaScript, javascript,
>> ECMAScript,
>>>>>>>>>> ecmascript],
>>>>>>>>>>>> factory class:
>>>>> jdk.nashorn.api.scripting.NashornScriptEngineFactory
>>>>>>>>>>>>> 2021-02-07 10:50:17,807 main DEBUG BeanShell Engine
>> version:
>>>>> 1.0,
>>>>>>>>>>>> language: BeanShell, threading: MULTITHREADED, compile:
>> true,
>>>>> names:
>>>>>>>>>>>> [beanshell, bsh, java], factory class:
>>>>>>> bsh.engine.BshScriptEngineFactory
>>>>>>>>>>>>> 2021-02-07 10:50:17,839 main DEBUG Groovy Scripting Engine
>>>>> version:
>>>>>>>>>> 2.0,
>>>>>>>>>>>> language: Groovy, threading: MULTITHREADED, compile: true,
>>>>> names:
>>>>>>>>>> [groovy,
>>>>>>>>>>>> Groovy], factory class:
>>>>>>>>>> org.codehaus.groovy.jsr223.GroovyScriptEngineFactory
>>>>>>>>>>>>> 2021-02-07 10:50:17,839 main DEBUG PluginManager 'Core'
>> found
>>>>> 117
>>>>>>>>>> plugins
>>>>>>>>>>>>> 2021-02-07 10:50:17,839 main DEBUG PluginManager 'Level'
>>>>> found 1
>>>>>>>>>> plugins
>>>>>>>>>>>>> 2021-02-07 10:50:17,845 main DEBUG Building
>>>>> Plugin[name=property,
>>>>>>>>>>>> class=org.apache.logging.log4j.core.config.Property].
>>>>>>>>>>>>> 2021-02-07 10:50:17,865 main TRACE TypeConverterRegistry
>>>>>>> initializing.
>>>>>>>>>>>>> 2021-02-07 10:50:17,865 main DEBUG PluginManager
>>>>> 'TypeConverter'
>>>>>>> found
>>>>>>>>>>>> 26 plugins
>>>>>>>>>>>>> 2021-02-07 10:50:17,873 main DEBUG createProperty(,
>>>>>>>>>>>> value="target/rolling-direct-1906")
>>>>>>>>>>>>> 2021-02-07 10:50:17,873 main DEBUG Building
>>>>> Plugin[name=properties,
>>>>>>>>>>>>
>> class=org.apache.logging.log4j.core.config.PropertiesPlugin].
>>>>>>>>>>>>> 2021-02-07 10:50:17,877 main DEBUG
>>>>>>>>>>>> configureSubstitutor(={baseDir=target/rolling-direct-1906},
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> Configuration(/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml))
>>>>>>>>>>>>> 2021-02-07 10:50:17,877 main DEBUG PluginManager 'Lookup'
>>>>> found 16
>>>>>>>>>>>> plugins
>>>>>>>>>>>>> 2021-02-07 10:50:17,878 main DEBUG Building
>>>>> Plugin[name=layout,
>>>>>>>>>>>> class=org.apache.logging.log4j.core.layout.PatternLayout].
>>>>>>>>>>>>> 2021-02-07 10:50:17,881 main TRACE Using value
>>>>>>> %d{yyyy-MM-dd-HH-mm-ss}
>>>>>>>>>>>> [%level] [%c] %msg%n for option pattern
>>>>>>>>>>>>> 2021-02-07 10:50:17,882 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> PatternSelector
>>>>>>>>>>>>> 2021-02-07 10:50:17,882 main TRACE Using value
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
>>>>>>>>>>>> for option configuration
>>>>>>>>>>>>> 2021-02-07 10:50:17,882 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> Replace
>>>>>>>>>>>>> 2021-02-07 10:50:17,882 main TRACE Using default value
>> UTF-8
>>>>> for
>>>>>>> option
>>>>>>>>>>>> charset
>>>>>>>>>>>>> 2021-02-07 10:50:17,883 main TRACE Using default value
>> true
>>>>> for
>>>>>>> option
>>>>>>>>>>>> alwaysWriteExceptions
>>>>>>>>>>>>> 2021-02-07 10:50:17,883 main TRACE Using default value
>> false
>>>>> for
>>>>>>> option
>>>>>>>>>>>> disableAnsi
>>>>>>>>>>>>> 2021-02-07 10:50:17,883 main TRACE Using default value
>> false
>>>>> for
>>>>>>> option
>>>>>>>>>>>> noConsoleNoAnsi
>>>>>>>>>>>>> 2021-02-07 10:50:17,883 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> header
>>>>>>>>>>>>> 2021-02-07 10:50:17,884 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> footer
>>>>>>>>>>>>> 2021-02-07 10:50:17,884 main DEBUG
>>>>>>>>>>>> PatternLayout$Builder(pattern="%d{yyyy-MM-dd-HH-mm-ss}
>>>>> [%level] [%c]
>>>>>>>>>>>> %msg%n", PatternSelector=null,
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> Configuration(/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml),
>>>>>>>>>>>> Replace=null, charset=null, alwaysWriteExceptions=null,
>>>>>>>>>> disableAnsi=null,
>>>>>>>>>>>> noConsoleNoAnsi=null, header=null, footer=null)
>>>>>>>>>>>>> 2021-02-07 10:50:17,884 main DEBUG PluginManager
>> 'Converter'
>>>>> found
>>>>>>> 46
>>>>>>>>>>>> plugins
>>>>>>>>>>>>> 2021-02-07 10:50:17,893 main DEBUG Building
>>>>>>>>>>>> Plugin[name=TimeBasedTriggeringPolicy,
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> class=org.apache.logging.log4j.core.appender.rolling.TimeBasedTriggeringPolicy].
>>>>>>>>>>>>> 2021-02-07 10:50:17,895 main TRACE Using default value 1
>> for
>>>>> option
>>>>>>>>>>>> interval
>>>>>>>>>>>>> 2021-02-07 10:50:17,895 main TRACE Using default value
>> false
>>>>> for
>>>>>>> option
>>>>>>>>>>>> modulate
>>>>>>>>>>>>> 2021-02-07 10:50:17,895 main TRACE Using default value 0
>> for
>>>>> option
>>>>>>>>>>>> maxRandomDelay
>>>>>>>>>>>>> 2021-02-07 10:50:17,895 main DEBUG
>>>>>>>>>>>> TimeBasedTriggeringPolicy$Builder(interval=null,
>> modulate=null,
>>>>>>>>>>>> maxRandomDelay=null)
>>>>>>>>>>>>> 2021-02-07 10:50:17,895 main DEBUG Building
>>>>> Plugin[name=Policies,
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> class=org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy].
>>>>>>>>>>>>> 2021-02-07 10:50:17,896 main DEBUG
>>>>>>>>>>>>
>> createPolicy(={TimeBasedTriggeringPolicy(nextRolloverMillis=0,
>>>>>>>>>> interval=1,
>>>>>>>>>>>> modulate=false)})
>>>>>>>>>>>>> 2021-02-07 10:50:17,896 main DEBUG Building
>>>>>>>>>>>> Plugin[name=DirectWriteRolloverStrategy,
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> class=org.apache.logging.log4j.core.appender.rolling.DirectWriteRolloverStrategy].
>>>>>>>>>>>>> 2021-02-07 10:50:17,897 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> maxFiles
>>>>>>>>>>>>> 2021-02-07 10:50:17,898 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> compressionLevel
>>>>>>>>>>>>> 2021-02-07 10:50:17,898 main TRACE Using value [] for
>> option
>>>>>>> Actions
>>>>>>>>>>>>> 2021-02-07 10:50:17,898 main TRACE Using default value
>> true
>>>>> for
>>>>>>> option
>>>>>>>>>>>> stopCustomActionsOnError
>>>>>>>>>>>>> 2021-02-07 10:50:17,898 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> tempCompressedFilePattern
>>>>>>>>>>>>> 2021-02-07 10:50:17,898 main TRACE Using value
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
>>>>>>>>>>>> for option config
>>>>>>>>>>>>> 2021-02-07 10:50:17,898 main DEBUG
>>>>>>>>>>>> DirectWriteRolloverStrategy$Builder(maxFiles=null,
>>>>>>>>>> compressionLevel=null,
>>>>>>>>>>>> ={}, stopCustomActionsOnError=null,
>>>>> tempCompressedFilePattern=null,
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> Configuration(/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml))
>>>>>>>>>>>>> 2021-02-07 10:50:17,899 main DEBUG Building
>>>>> Plugin[name=appender,
>>>>>>>>>>>>
>>>>> class=org.apache.logging.log4j.core.appender.RollingFileAppender].
>>>>>>>>>>>>> 2021-02-07 10:50:17,900 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> fileName
>>>>>>>>>>>>> 2021-02-07 10:50:17,901 main TRACE Using value
>>>>>>>>>>>>
>>>>> target/rolling-direct-1906/rollingfile.%d{yyyy-MM-dd-HH-mm-ss}.log
>>>>>>> for
>>>>>>>>>>>> option filePattern
>>>>>>>>>>>>> 2021-02-07 10:50:17,901 main TRACE Using default value
>> true
>>>>> for
>>>>>>> option
>>>>>>>>>>>> append
>>>>>>>>>>>>> 2021-02-07 10:50:17,901 main TRACE Using default value
>> false
>>>>> for
>>>>>>> option
>>>>>>>>>>>> locking
>>>>>>>>>>>>> 2021-02-07 10:50:17,902 main TRACE Using value
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> CompositeTriggeringPolicy(policies=[TimeBasedTriggeringPolicy(nextRolloverMillis=0,
>>>>>>>>>>>> interval=1, modulate=false)]) for option Policy
>>>>>>>>>>>>> 2021-02-07 10:50:17,902 main TRACE Using value
>>>>>>>>>>>> DirectWriteRolloverStrategy(maxFiles=2147483647) for option
>>>>> Strategy
>>>>>>>>>>>>> 2021-02-07 10:50:17,902 main TRACE Using default value
>> false
>>>>> for
>>>>>>> option
>>>>>>>>>>>> advertise
>>>>>>>>>>>>> 2021-02-07 10:50:17,902 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> advertiseUri
>>>>>>>>>>>>> 2021-02-07 10:50:17,902 main TRACE Using default value
>> false
>>>>> for
>>>>>>> option
>>>>>>>>>>>> createOnDemand
>>>>>>>>>>>>> 2021-02-07 10:50:17,902 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> filePermissions
>>>>>>>>>>>>> 2021-02-07 10:50:17,903 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> fileOwner
>>>>>>>>>>>>> 2021-02-07 10:50:17,903 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> fileGroup
>>>>>>>>>>>>> 2021-02-07 10:50:17,903 main TRACE Using default value
>> true
>>>>> for
>>>>>>> option
>>>>>>>>>>>> bufferedIo
>>>>>>>>>>>>> 2021-02-07 10:50:17,903 main TRACE Using default value
>> 8192
>>>>> for
>>>>>>> option
>>>>>>>>>>>> bufferSize
>>>>>>>>>>>>> 2021-02-07 10:50:17,903 main TRACE Using default value
>> true
>>>>> for
>>>>>>> option
>>>>>>>>>>>> immediateFlush
>>>>>>>>>>>>> 2021-02-07 10:50:17,904 main TRACE Using default value
>> true
>>>>> for
>>>>>>> option
>>>>>>>>>>>> ignoreExceptions
>>>>>>>>>>>>> 2021-02-07 10:50:17,904 main TRACE Using value
>>>>>>> %d{yyyy-MM-dd-HH-mm-ss}
>>>>>>>>>>>> [%level] [%c] %msg%n for option Layout
>>>>>>>>>>>>> 2021-02-07 10:50:17,904 main TRACE Using value
>> RollingFile for
>>>>>>> option
>>>>>>>>>>>> name
>>>>>>>>>>>>> 2021-02-07 10:50:17,905 main TRACE Using value
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
>>>>>>>>>>>> for option configuration
>>>>>>>>>>>>> 2021-02-07 10:50:17,905 main TRACE Using default value
>> null
>>>>> for
>>>>>>> option
>>>>>>>>>>>> Filter
>>>>>>>>>>>>> 2021-02-07 10:50:17,905 main TRACE Using value [] for
>> option
>>>>>>> Properties
>>>>>>>>>>>>> 2021-02-07 10:50:17,905 main DEBUG
>>>>>>>>>>>> RollingFileAppender$Builder(fileName=null,
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> filePattern="target/rolling-direct-1906/rollingfile.%d{yyyy-MM-dd-HH-mm-ss}.log",
>>>>>>>>>>>> append=null, locking=null,
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> Policies(CompositeTriggeringPolicy(policies=[TimeBasedTriggeringPolicy(nextRolloverMillis=0,
>>>>>>>>>>>> interval=1, modulate=false)])),
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> DirectWriteRolloverStrategy(DirectWriteRolloverStrategy(maxFiles=2147483647)),
>>>>>>>>>>>> advertise=null, advertiseUri=null, createOnDemand=null,
>>>>>>>>>>>> filePermissions=null, fileOwner=null, fileGroup=null,
>>>>>>> bufferedIo=null,
>>>>>>>>>>>> bufferSize=null, immediateFlush=null,
>> ignoreExceptions=null,
>>>>>>>>>>>> PatternLayout(%d{yyyy-MM-dd-HH-mm-ss} [%level] [%c]
>> %msg%n),
>>>>>>>>>>>> name="RollingFile",
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> Configuration(/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml),
>>>>>>>>>>>> Filter=null, ={})
>>>>>>>>>>>>> 2021-02-07 10:50:17,908 main DEBUG Starting
>> RollingFileManager
>>>>>>>>>>>>
>>>>> target/rolling-direct-1906/rollingfile.%d{yyyy-MM-dd-HH-mm-ss}.log
>>>>>>>>>>>>> 2021-02-07 10:50:17,909 main DEBUG PluginManager
>>>>> 'FileConverter'
>>>>>>> found
>>>>>>>>>> 2
>>>>>>>>>>>> plugins
>>>>>>>>>>>>> 2021-02-07 10:50:17,914 main DEBUG Setting prev file time
>> to
>>>>>>>>>>>> 1969-12-31T17:00:00.000-0700
>>>>>>>>>>>>> 2021-02-07 10:50:17,914 main DEBUG Initializing triggering
>>>>> policy
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> CompositeTriggeringPolicy(policies=[TimeBasedTriggeringPolicy(nextRolloverMillis=0,
>>>>>>>>>>>> interval=1, modulate=false)])
>>>>>>>>>>>>> 2021-02-07 10:50:17,914 main DEBUG Initializing triggering
>>>>> policy
>>>>>>>>>>>> TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=1,
>>>>>>>>>> modulate=false)
>>>>>>>>>>>>> 2021-02-07 10:50:17,916 main TRACE
>>>>> PatternProcessor.getNextTime
>>>>>>>>>>>> returning 2021/02/07-10:50:18.000,
>>>>>>> nextFileTime=2021/02/07-10:50:17.000,
>>>>>>>>>>>> prevFileTime=1969/12/31-17:00:00.000,
>>>>>>> current=2021/02/07-10:50:17.915,
>>>>>>>>>>>> freq=EVERY_SECOND
>>>>>>>>>>>>> 2021-02-07 10:50:17,917 main TRACE
>>>>> PatternProcessor.getNextTime
>>>>>>>>>>>> returning 2021/02/07-10:50:18.000,
>>>>>>> nextFileTime=2021/02/07-10:50:17.000,
>>>>>>>>>>>> prevFileTime=2021/02/07-10:50:17.000,
>>>>>>> current=2021/02/07-10:50:17.916,
>>>>>>>>>>>> freq=EVERY_SECOND
>>>>>>>>>>>>> 2021-02-07 10:50:17,917 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=0,
>>>>> prevFileTime=1612720217000,
>>>>>>>>>>>> nextFileTime=1612720217000
>>>>>>>>>>>>> 2021-02-07 10:50:17,919 main TRACE Using default
>> SystemClock
>>>>> for
>>>>>>>>>>>> timestamps.
>>>>>>>>>>>>> 2021-02-07 10:50:17,920 main DEBUG
>>>>>>>>>>>> org.apache.logging.log4j.core.time.internal.SystemClock
>> does
>>>>> not
>>>>>>> support
>>>>>>>>>>>> precise timestamps.
>>>>>>>>>>>>> 2021-02-07 10:50:17,921 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=true, currentFileTime=0,
>>>>> prevFileTime=1612720217000,
>>>>>>>>>>>> nextFileTime=1612720217000
>>>>>>>>>>>>> 2021-02-07 10:50:17,922 main DEBUG Building
>>>>> Plugin[name=appenders,
>>>>>>>>>>>>
>> class=org.apache.logging.log4j.core.config.AppendersPlugin].
>>>>>>>>>>>>> 2021-02-07 10:50:17,922 main DEBUG
>>>>> createAppenders(={RollingFile})
>>>>>>>>>>>>> 2021-02-07 10:50:17,923 main DEBUG Building
>>>>>>> Plugin[name=AppenderRef,
>>>>>>>>>>>> class=org.apache.logging.log4j.core.config.AppenderRef].
>>>>>>>>>>>>> 2021-02-07 10:50:17,924 main DEBUG
>>>>> createAppenderRef(filter=null,
>>>>>>> , )
>>>>>>>>>>>>> 2021-02-07 10:50:17,924 main DEBUG Building
>> Plugin[name=root,
>>>>>>>>>>>>
>>>>> class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
>>>>>>>>>>>>> 2021-02-07 10:50:17,927 main DEBUG createLogger(, , ,
>>>>>>> ={RollingFile},
>>>>>>>>>>>> ={},
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> Configuration(/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml),
>>>>>>>>>>>> filter=null)
>>>>>>>>>>>>> 2021-02-07 10:50:17,928 main DEBUG Building
>>>>> Plugin[name=loggers,
>>>>>>>>>>>> class=org.apache.logging.log4j.core.config.LoggersPlugin].
>>>>>>>>>>>>> 2021-02-07 10:50:17,929 main DEBUG createLoggers(={root})
>>>>>>>>>>>>> 2021-02-07 10:50:17,931 main DEBUG Configuration
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
>>>>>>>>>>>> initialized
>>>>>>>>>>>>> 2021-02-07 10:50:17,931 main DEBUG Starting configuration
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
>>>>>>>>>>>>> 2021-02-07 10:50:17,932 main DEBUG Log4j2
>>>>> ConfigurationScheduler
>>>>>>>>>>>> starting 1 threads
>>>>>>>>>>>>> 2021-02-07 10:50:17,932 main DEBUG Started configuration
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
>>>>>>>>>>>> OK.
>>>>>>>>>>>>> 2021-02-07 10:50:17,933 main TRACE Stopping
>>>>>>>>>>>>
>>>>> org.apache.logging.log4j.core.config.DefaultConfiguration@400cff1a.
>>>>>>> ..
>>>>>>>>>>>>> 2021-02-07 10:50:17,933 main TRACE DefaultConfiguration
>>>>> notified 1
>>>>>>>>>>>> ReliabilityStrategies that config will be stopped.
>>>>>>>>>>>>> 2021-02-07 10:50:17,933 main TRACE DefaultConfiguration
>>>>> stopping
>>>>>>> root
>>>>>>>>>>>> LoggerConfig.
>>>>>>>>>>>>> 2021-02-07 10:50:17,933 main TRACE DefaultConfiguration
>>>>> notifying
>>>>>>>>>>>> ReliabilityStrategies that appenders will be stopped.
>>>>>>>>>>>>> 2021-02-07 10:50:17,934 main TRACE DefaultConfiguration
>>>>> stopping
>>>>>>>>>>>> remaining Appenders.
>>>>>>>>>>>>> 2021-02-07 10:50:17,934 main DEBUG Shutting down
>>>>>>> OutputStreamManager
>>>>>>>>>>>> SYSTEM_OUT.false.false-1
>>>>>>>>>>>>> 2021-02-07 10:50:17,934 main DEBUG OutputStream closed
>>>>>>>>>>>>> 2021-02-07 10:50:17,934 main DEBUG Shut down
>>>>> OutputStreamManager
>>>>>>>>>>>> SYSTEM_OUT.false.false-1, all resources released: true
>>>>>>>>>>>>> 2021-02-07 10:50:17,934 main DEBUG Appender
>> DefaultConsole-1
>>>>>>> stopped
>>>>>>>>>>>> with status true
>>>>>>>>>>>>> 2021-02-07 10:50:17,934 main TRACE DefaultConfiguration
>>>>> stopped 1
>>>>>>>>>>>> remaining Appenders.
>>>>>>>>>>>>> 2021-02-07 10:50:17,934 main TRACE DefaultConfiguration
>>>>> cleaning
>>>>>>>>>>>> Appenders from 1 LoggerConfigs.
>>>>>>>>>>>>> 2021-02-07 10:50:17,934 main DEBUG Stopped
>>>>>>>>>>>>
>>>>> org.apache.logging.log4j.core.config.DefaultConfiguration@400cff1a
>>>>>>> OK
>>>>>>>>>>>>> 2021-02-07 10:50:17,989 main TRACE Reregistering MBeans
>> after
>>>>>>>>>>>> reconfigure.
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@65987993
>>>>>>>>>>>>> 2021-02-07 10:50:17,990 main TRACE Reregistering context
>>>>> (1/1):
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> 'testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test)'
>>>>>>>>>>>> org.apache.logging.log4j.core.LoggerContext@add0edd
>>>>>>>>>>>>> 2021-02-07 10:50:17,990 main TRACE Unregistering but no
>> MBeans
>>>>>>> found
>>>>>>>>>>>> matching
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test)'
>>>>>>>>>>>>> 2021-02-07 10:50:17,990 main TRACE Unregistering but no
>> MBeans
>>>>>>> found
>>>>>>>>>>>> matching
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=StatusLogger'
>>>>>>>>>>>>> 2021-02-07 10:50:17,990 main TRACE Unregistering but no
>> MBeans
>>>>>>> found
>>>>>>>>>>>> matching
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=ContextSelector'
>>>>>>>>>>>>> 2021-02-07 10:50:17,990 main TRACE Unregistering but no
>> MBeans
>>>>>>> found
>>>>>>>>>>>> matching
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=Loggers,name=*'
>>>>>>>>>>>>> 2021-02-07 10:50:17,991 main TRACE Unregistering but no
>> MBeans
>>>>>>> found
>>>>>>>>>>>> matching
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=Appenders,name=*'
>>>>>>>>>>>>> 2021-02-07 10:50:17,991 main TRACE Unregistering but no
>> MBeans
>>>>>>> found
>>>>>>>>>>>> matching
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=AsyncAppenders,name=*'
>>>>>>>>>>>>> 2021-02-07 10:50:17,991 main TRACE Unregistering but no
>> MBeans
>>>>>>> found
>>>>>>>>>>>> matching
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=AsyncLoggerRingBuffer'
>>>>>>>>>>>>> 2021-02-07 10:50:17,991 main TRACE Unregistering but no
>> MBeans
>>>>>>> found
>>>>>>>>>>>> matching
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=Loggers,name=*,subtype=RingBuffer'
>>>>>>>>>>>>> 2021-02-07 10:50:17,992 main DEBUG Registering MBean
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test)
>>>>>>>>>>>>> 2021-02-07 10:50:17,993 main DEBUG Registering MBean
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=StatusLogger
>>>>>>>>>>>>> 2021-02-07 10:50:17,994 main DEBUG Registering MBean
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=ContextSelector
>>>>>>>>>>>>> 2021-02-07 10:50:17,995 main DEBUG Registering MBean
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=Loggers,name=
>>>>>>>>>>>>> 2021-02-07 10:50:17,996 main DEBUG Registering MBean
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=Appenders,name=RollingFile
>>>>>>>>>>>>> 2021-02-07 10:50:17,996 main TRACE Using DummyNanoClock
>> for
>>>>>>> nanosecond
>>>>>>>>>>>> timestamps.
>>>>>>>>>>>>> 2021-02-07 10:50:17,996 main DEBUG
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> LoggerContext[name=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),
>>>>>>>>>>>> org.apache.logging.log4j.core.LoggerContext@add0edd]
>> started
>>>>> OK
>>>>>>> with
>>>>>>>>>>>> configuration
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>
>> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml].
>>>>>>>>>>>>> 2021-02-07 10:50:18,000 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=0,
>>>>> prevFileTime=1612720217000,
>>>>>>>>>>>> nextFileTime=1612720217000
>>>>>>>>>>>>> 2021-02-07 10:50:18,000 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=true, currentFileTime=0,
>>>>> prevFileTime=1612720217000,
>>>>>>>>>>>> nextFileTime=1612720217000
>>>>>>>>>>>>> 2021-02-07 10:50:18,001 main DEBUG Now writing to
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-18.log
>>>>> at
>>>>>>>>>>>> 2021-02-07T10:50:18.001-0700
>>>>>>>>>>>>> 2021-02-07 10:50:18,003 main DEBUG
>>>>>>>>>>>> AsyncLogger.ThreadNameStrategy=UNCACHED (user specified
>> null,
>>>>>>> default is
>>>>>>>>>>>> UNCACHED)
>>>>>>>>>>>>> 2021-02-07 10:50:18,003 main TRACE Using default
>> SystemClock
>>>>> for
>>>>>>>>>>>> timestamps.
>>>>>>>>>>>>> 2021-02-07 10:50:18,003 main DEBUG
>>>>>>>>>>>> org.apache.logging.log4j.core.time.internal.SystemClock
>> does
>>>>> not
>>>>>>> support
>>>>>>>>>>>> precise timestamps.
>>>>>>>>>>>>> 2021-02-07 10:50:18,056 main TRACE
>>>>> PatternProcessor.getNextTime
>>>>>>>>>>>> returning 2021/02/07-10:50:19.000,
>>>>>>> nextFileTime=2021/02/07-10:50:18.000,
>>>>>>>>>>>> prevFileTime=2021/02/07-10:50:17.000,
>>>>>>> current=2021/02/07-10:50:18.056,
>>>>>>>>>>>> freq=EVERY_SECOND
>>>>>>>>>>>>> 2021-02-07 10:50:18,056 main DEBUG Rolling
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-18.log
>>>>>>>>>>>>> 2021-02-07 10:50:18,056 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720218056,
>>>>>>>>>>>> prevFileTime=1612720217000, nextFileTime=1612720218000
>>>>>>>>>>>>> 2021-02-07 10:50:18,057 main DEBUG Found 0 eligible files,
>>>>> max is
>>>>>>>>>>>> 2147483647
>>>>>>>>>>>>> 2021-02-07 10:50:18,057 main TRACE
>>>>>>> DirectWriteRolloverStrategy.purge()
>>>>>>>>>>>> took 0.0 milliseconds
>>>>>>>>>>>>> 2021-02-07 10:50:18,058 main DEBUG OutputStream closed
>>>>>>>>>>>>> 2021-02-07 10:50:18,058 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720218056,
>>>>>>>>>>>> prevFileTime=1612720217000, nextFileTime=1612720218000
>>>>>>>>>>>>> 2021-02-07 10:50:18,058 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=true, currentFileTime=1612720218056,
>>>>>>>>>>>> prevFileTime=1612720217000, nextFileTime=1612720218000
>>>>>>>>>>>>> 2021-02-07 10:50:18,058 main DEBUG Now writing to
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-18.log
>>>>> at
>>>>>>>>>>>> 2021-02-07T10:50:18.058-0700
>>>>>>>>>>>>> 2021-02-07 10:50:19,009 main TRACE
>>>>> PatternProcessor.getNextTime
>>>>>>>>>>>> returning 2021/02/07-10:50:20.000,
>>>>>>> nextFileTime=2021/02/07-10:50:19.000,
>>>>>>>>>>>> prevFileTime=2021/02/07-10:50:18.000,
>>>>>>> current=2021/02/07-10:50:19.009,
>>>>>>>>>>>> freq=EVERY_SECOND
>>>>>>>>>>>>> 2021-02-07 10:50:19,009 main DEBUG Rolling
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-18.log
>>>>>>>>>>>>> 2021-02-07 10:50:19,010 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720219009,
>>>>>>>>>>>> prevFileTime=1612720218000, nextFileTime=1612720219000
>>>>>>>>>>>>> 2021-02-07 10:50:19,010 main DEBUG Found 0 eligible files,
>>>>> max is
>>>>>>>>>>>> 2147483647
>>>>>>>>>>>>> 2021-02-07 10:50:19,010 main TRACE
>>>>>>> DirectWriteRolloverStrategy.purge()
>>>>>>>>>>>> took 0.0 milliseconds
>>>>>>>>>>>>> 2021-02-07 10:50:19,010 main DEBUG OutputStream closed
>>>>>>>>>>>>> 2021-02-07 10:50:19,011 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720219009,
>>>>>>>>>>>> prevFileTime=1612720218000, nextFileTime=1612720219000
>>>>>>>>>>>>> 2021-02-07 10:50:19,011 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=true, currentFileTime=1612720219009,
>>>>>>>>>>>> prevFileTime=1612720218000, nextFileTime=1612720219000
>>>>>>>>>>>>> 2021-02-07 10:50:19,011 main DEBUG Now writing to
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-19.log
>>>>> at
>>>>>>>>>>>> 2021-02-07T10:50:19.011-0700
>>>>>>>>>>>>> 2021-02-07 10:50:20,011 main TRACE
>>>>> PatternProcessor.getNextTime
>>>>>>>>>>>> returning 2021/02/07-10:50:21.000,
>>>>>>> nextFileTime=2021/02/07-10:50:20.000,
>>>>>>>>>>>> prevFileTime=2021/02/07-10:50:19.000,
>>>>>>> current=2021/02/07-10:50:20.011,
>>>>>>>>>>>> freq=EVERY_SECOND
>>>>>>>>>>>>> 2021-02-07 10:50:20,011 main DEBUG Rolling
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-19.log
>>>>>>>>>>>>> 2021-02-07 10:50:20,011 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720220011,
>>>>>>>>>>>> prevFileTime=1612720219000, nextFileTime=1612720220000
>>>>>>>>>>>>> 2021-02-07 10:50:20,012 main DEBUG Found 0 eligible files,
>>>>> max is
>>>>>>>>>>>> 2147483647
>>>>>>>>>>>>> 2021-02-07 10:50:20,012 main TRACE
>>>>>>> DirectWriteRolloverStrategy.purge()
>>>>>>>>>>>> took 0.0 milliseconds
>>>>>>>>>>>>> 2021-02-07 10:50:20,012 main DEBUG OutputStream closed
>>>>>>>>>>>>> 2021-02-07 10:50:20,012 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720220011,
>>>>>>>>>>>> prevFileTime=1612720219000, nextFileTime=1612720220000
>>>>>>>>>>>>> 2021-02-07 10:50:20,013 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=true, currentFileTime=1612720220011,
>>>>>>>>>>>> prevFileTime=1612720219000, nextFileTime=1612720220000
>>>>>>>>>>>>> 2021-02-07 10:50:20,013 main DEBUG Now writing to
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-20.log
>>>>> at
>>>>>>>>>>>> 2021-02-07T10:50:20.013-0700
>>>>>>>>>>>>> 2021-02-07 10:50:21,021 main TRACE
>>>>> PatternProcessor.getNextTime
>>>>>>>>>>>> returning 2021/02/07-10:50:22.000,
>>>>>>> nextFileTime=2021/02/07-10:50:21.000,
>>>>>>>>>>>> prevFileTime=2021/02/07-10:50:20.000,
>>>>>>> current=2021/02/07-10:50:21.021,
>>>>>>>>>>>> freq=EVERY_SECOND
>>>>>>>>>>>>> 2021-02-07 10:50:21,021 main DEBUG Rolling
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-20.log
>>>>>>>>>>>>> 2021-02-07 10:50:21,021 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720221021,
>>>>>>>>>>>> prevFileTime=1612720220000, nextFileTime=1612720221000
>>>>>>>>>>>>> 2021-02-07 10:50:21,022 main DEBUG Found 0 eligible files,
>>>>> max is
>>>>>>>>>>>> 2147483647
>>>>>>>>>>>>> 2021-02-07 10:50:21,022 main TRACE
>>>>>>> DirectWriteRolloverStrategy.purge()
>>>>>>>>>>>> took 0.0 milliseconds
>>>>>>>>>>>>> 2021-02-07 10:50:21,022 main DEBUG OutputStream closed
>>>>>>>>>>>>> 2021-02-07 10:50:21,022 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720221021,
>>>>>>>>>>>> prevFileTime=1612720220000, nextFileTime=1612720221000
>>>>>>>>>>>>> 2021-02-07 10:50:21,022 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=true, currentFileTime=1612720221021,
>>>>>>>>>>>> prevFileTime=1612720220000, nextFileTime=1612720221000
>>>>>>>>>>>>> 2021-02-07 10:50:21,022 main DEBUG Now writing to
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-21.log
>>>>> at
>>>>>>>>>>>> 2021-02-07T10:50:21.022-0700
>>>>>>>>>>>>> 2021-02-07 10:50:22,022 main TRACE
>>>>> PatternProcessor.getNextTime
>>>>>>>>>>>> returning 2021/02/07-10:50:23.000,
>>>>>>> nextFileTime=2021/02/07-10:50:22.000,
>>>>>>>>>>>> prevFileTime=2021/02/07-10:50:21.000,
>>>>>>> current=2021/02/07-10:50:22.022,
>>>>>>>>>>>> freq=EVERY_SECOND
>>>>>>>>>>>>> 2021-02-07 10:50:22,022 main DEBUG Rolling
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-21.log
>>>>>>>>>>>>> 2021-02-07 10:50:22,022 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720222022,
>>>>>>>>>>>> prevFileTime=1612720221000, nextFileTime=1612720222000
>>>>>>>>>>>>> 2021-02-07 10:50:22,022 main DEBUG Found 0 eligible files,
>>>>> max is
>>>>>>>>>>>> 2147483647
>>>>>>>>>>>>> 2021-02-07 10:50:22,022 main TRACE
>>>>>>> DirectWriteRolloverStrategy.purge()
>>>>>>>>>>>> took 0.0 milliseconds
>>>>>>>>>>>>> 2021-02-07 10:50:22,023 main DEBUG OutputStream closed
>>>>>>>>>>>>> 2021-02-07 10:50:22,023 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720222022,
>>>>>>>>>>>> prevFileTime=1612720221000, nextFileTime=1612720222000
>>>>>>>>>>>>> 2021-02-07 10:50:22,023 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=true, currentFileTime=1612720222022,
>>>>>>>>>>>> prevFileTime=1612720221000, nextFileTime=1612720222000
>>>>>>>>>>>>> 2021-02-07 10:50:22,023 main DEBUG Now writing to
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-22.log
>>>>> at
>>>>>>>>>>>> 2021-02-07T10:50:22.023-0700
>>>>>>>>>>>>> 2021-02-07 10:50:23,033 main TRACE
>>>>> PatternProcessor.getNextTime
>>>>>>>>>>>> returning 2021/02/07-10:50:24.000,
>>>>>>> nextFileTime=2021/02/07-10:50:23.000,
>>>>>>>>>>>> prevFileTime=2021/02/07-10:50:22.000,
>>>>>>> current=2021/02/07-10:50:23.033,
>>>>>>>>>>>> freq=EVERY_SECOND
>>>>>>>>>>>>> 2021-02-07 10:50:23,033 main DEBUG Rolling
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-22.log
>>>>>>>>>>>>> 2021-02-07 10:50:23,033 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720223033,
>>>>>>>>>>>> prevFileTime=1612720222000, nextFileTime=1612720223000
>>>>>>>>>>>>> 2021-02-07 10:50:23,034 main DEBUG Found 0 eligible files,
>>>>> max is
>>>>>>>>>>>> 2147483647
>>>>>>>>>>>>> 2021-02-07 10:50:23,034 main TRACE
>>>>>>> DirectWriteRolloverStrategy.purge()
>>>>>>>>>>>> took 0.0 milliseconds
>>>>>>>>>>>>> 2021-02-07 10:50:23,034 main DEBUG OutputStream closed
>>>>>>>>>>>>> 2021-02-07 10:50:23,034 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=false, currentFileTime=1612720223033,
>>>>>>>>>>>> prevFileTime=1612720222000, nextFileTime=1612720223000
>>>>>>>>>>>>> 2021-02-07 10:50:23,034 main DEBUG Formatting file name.
>>>>>>>>>>>> useCurrentTime=true, currentFileTime=1612720223033,
>>>>>>>>>>>> prevFileTime=1612720222000, nextFileTime=1612720223000
>>>>>>>>>>>>> 2021-02-07 10:50:23,035 main DEBUG Now writing to
>>>>>>>>>>>>
>> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-23.log
>>>>> at
>>>>>>>>>>>> 2021-02-07T10:50:23.034-0700
>>>>>>>>>>>>> Incorrect file name. Expected:
>>>>> rollingfile.2021-02-07-10-50-17.log
>>>>>>>>>>>> Actual: rollingfile.2021-02-07-10-50-18.log
>>>>>>>>>>>> expected:<...e.2021-02-07-10-50-1[7].log> but
>>>>>>>>>>>> was:<...e.2021-02-07-10-50-1[8].log>
>>>>>>>>>>>>>
>>>>>>>>>>>>> Run 6 - failed in Kafka again
>>>>>>>>>>>>> [ERROR] Failures:
>>>>>>>>>>>>> [ERROR] ConfigurationBuilderTest.testXmlConstructing:116
>>>>>>>>>>>> expected:<<?xml version="1.0" [?>
>>>>>>>>>>>>> ]<Configuration name=...> but was:<<?xml version="1.0"
>>>>>>>>>>>> [encoding="UTF-8"?>]<Configuration name=…>
>>>>>>>>>>>>>
>>>>>>>>>>>>> Ralph
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>
>>>>>
>>
