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