Great work Tim! I can't be happier finally somebody stepping up to fix sporadic build failures on Windows due to open file related issues. Would you mind creating a PR, please? (I haven't missed one, right?) This will make it easier to review your changes and merge them.
On Mon, Feb 22, 2021 at 8:19 PM Tim Perry <tim.v...@gmail.com> wrote: > 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 > >> >>>>>>>>>>>>> > >> >>>>>>>>>>>>> > >> >>>>>>>>>>>>> > >> >>>>>>>>>>>> > >> >>>>>>>>>> > >> >>>>>>>>>> > >> >>>>>>>>>> > >> >>>>>>>> > >> >>>>>>>> > >> >>>>>>>> > >> >>>>>>> > >> >>>>>>> > >> >>>>> > >> >>>>> > >> >> > >> > >> > >> >
