> My guess is that the default file locking level is different > between JVM's or OS's.
My understanding with Windows is that when you open a file, you have exclusive access by default. If you try to delete a file that another application has open(or possibly even your application?), you'll get an error. On Linux, this isn't the case - unless you explicitly lock the file, it's available for everybody. You can happily delete a file on Linux, and the FD that you can read/write to won't become invalid, even if you can't open it anymore on the filesystem. -Robert Middleton On Thu, Feb 18, 2021 at 9:02 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 > > > >> > > > >>>>> > > > >> > > > >>>>> > > > >> > > > >>>>> > > > >> > > > >>>> > > > >> > > > >> > > > >> > > > >> > > > >> > > > >> > > > >> > > > > > > >> > > > > > > >> > > > > > > >> > > > > > >> > > > > > >> > > > >> > >