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