I have a fork of log4j2 master that builds on windows here: https://github.com/perry2of5/logging-log4j2
For log4j-core, I close the StatusLogger using StatusLogger.getLogger().reset() to LoggerContext.stop(...). Now log4j2-core tests pass. (Usually). I doubt this is the best solution, but it shows that closing the logger does in fact allow the test to complete correctly. https://github.com/perry2of5/logging-log4j2/commit/9f5b083956ca7e5de8e7acc3b2e7397cb770b186 For log4j-layout-template-json, I had to change the hard-coded port in JsonTemplateLayoutNullEventDelimiterTest in log4j-layout-template-json to get the tests to run. I don't know why, but changing the port to 35514 worked. https://github.com/perry2of5/logging-log4j2/commit/5ca4fba8aaa1879d48619d1f23631ae81c37ec6d I had to update the expected XML in the Kafka ConfigurationBuilderTest to match what windows outputs. Obviously we need to make this conditional based on the OS it is running under... https://github.com/perry2of5/logging-log4j2/commit/dec236a4d358b9847ad7710f668749241a1b50e5 On Fri, Feb 19, 2021 at 10:26 AM Tim Perry <tim.v...@gmail.com> wrote: > The simplest fix is to add "StatusLogger.getLogger().reset();" to the very > end of LoggerContext.stop(timeout, timeUnit). > > However, I'm not sure that is a great idea -- all status messages after > that point would be lost. > > Perhaps we want to have some logic that updates the LoggerContext to have > one StatusConsoleListener writing to stdout or stderr and remove the rest. > If there is a StatusConsoleListener, which there always is with the current > code, check if it is writing to a file and is so mutate it's destination to > stdout or stderr and close the file stream. Then remove any other > StatusListeners and it should cleanly shut down. The problem here is that > now some of the status messages went to a log file and some went to > standard out. I'm not sure that is avoidable. > > > > > On Thu, Feb 18, 2021 at 7:57 PM Ralph Goers <ralph.go...@dslextreme.com> > wrote: > >> 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 >> >>>>>>>>>>>>> >> >>>>>>>>>>>>> >> >>>>>>>>>>>>> >> >>>>>>>>>>>> >> >>>>>>>>>> >> >>>>>>>>>> >> >>>>>>>>>> >> >>>>>>>> >> >>>>>>>> >> >>>>>>>> >> >>>>>>> >> >>>>>>> >> >>>>> >> >>>>> >> >> >> >> >>
