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