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
>>>>>
>>>>>
>>>>>
>>>>
>>
>>
>>
