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
