On master, I noticed that when I build in my IDE that lots of tests in
log4j-core fail but when I build with maven they pass. In the past, when
I've seen this on other projects it was caused by race conditions. I
wonder: are there race conditions in the tests or the code that need to be
addressed?
On Sun, Feb 7, 2021 at 1:46 PM Ralph Goers <ralph.go...@dslextreme.com>
wrote:
> Yes, that is why I am wondering why master is so flaky.
>
> Ralph
>
> > On Feb 7, 2021, at 2:34 PM, Gary Gregory <garydgreg...@gmail.com> wrote:
> >
> > FWIW but not master, I've been building release-2.x lately over and over
> > without issues aside from the rare random failure.
> >
> > G
> >
> > On Sun, Feb 7, 2021 at 2:37 PM Matt Sicker <boa...@gmail.com> wrote:
> >
> >> I'm not getting errors in log4j-api, though it's possible some test is
> >> missing a JUnit annotation which is causing that ThreadContext data
> >> corruption.
> >>
> >> I am, however, getting the same log4j-kafka test error. I'll try
> >> running the log4j-api tests a few more times to see if I can reproduce
> >> any test errors there.
> >>
> >> On Sun, 7 Feb 2021 at 12:20, Ralph Goers <ralph.go...@dslextreme.com>
> >> wrote:
> >>>
> >>> I am trying to apply patches to the release-2.x branch and make the
> >> corresponding changes in master. When I run a build in master I cannot
> get
> >> it to succeed. It randomly fails in different ways. I typically run a
> full
> >> build when I make significant changes and don’t commit unless it
> passes. So
> >> far I have spent well over an hour running the build at least 6 times
> >> trying to get a successful build with no luck.
> >>>
> >>> Run 1 fails in log4j-api
> >>> [ERROR] Failures:
> >>> [ERROR] AbstractLoggerTest.testMessageThrowsAndNullFormat:912
> >>> Expected: a string containing
> >> "org.apache.logging.log4j.spi.AbstractLogger caught
> >> java.lang.IllegalStateException logging TestMessage: "
> >>> but: was "2021-02-07 10:00:31,277 ForkJoinPool-1-worker-30 WARN
> >> Ignoring java.io.NotSerializableException: java.lang.Object for key[2]
> >> ('unserializable')"
> >>> [ERROR] CloseableThreadContextTest.canReuseCloseableThreadContext:169
> >> expected: <value> but was: <null>
> >>> [ERROR] CloseableThreadContextTest.closeIsIdempotent:203 expected:
> >> <map to keep> but was: <null>
> >>> [ERROR]
> >>
> CloseableThreadContextTest.ifTheSameKeyIsAddedTwiceTheOriginalShouldBeUsed:103
> >> expected: <innerValue> but was: <null>
> >>> [ERROR] CloseableThreadContextTest.pushAllWillPushAllValues:237
> >> expected: <key> but was: <>
> >>> [ERROR] CloseableThreadContextTest.putAllWillPutAllValues:222
> >> expected: <value> but was: <null>
> >>> [ERROR] CloseableThreadContextTest.shouldAddAnEntryToTheMap:53
> >> expected: <value> but was: <null>
> >>> [ERROR]
> >> CloseableThreadContextTest.shouldAddEntriesToBothStackAndMap:156
> expected:
> >> <value> but was: <null>
> >>> [ERROR] CloseableThreadContextTest.shouldAddTwoEntriesToTheMap:63
> >> expected: <value> but was: <null>
> >>> [ERROR] CloseableThreadContextTest.shouldNestEntries:75 expected:
> >> <value> but was: <null>
> >>> [ERROR]
> >>
> CloseableThreadContextTest.shouldPreserveOldEntriesFromTheMapWhenAutoClosed:91
> >> expected: <value> but was: <null>
> >>> [ERROR]
> >>
> CloseableThreadContextTest.shouldPushAndPopAParameterizedEntryToTheStack:137
> >> expected: <message param> but was: <>
> >>> [ERROR]
> >> CloseableThreadContextTest.shouldPushAndPopAnEntryToTheStack:113
> expected:
> >> <message> but was: <>
> >>> [ERROR]
> >> CloseableThreadContextTest.shouldPushAndPopTwoEntriesToTheStack:124
> >> expected: <message2> but was: <>
> >>> [ERROR]
> >>
> CloseableThreadContextTest.shouldRemoveAnEntryFromTheMapWhenAutoClosed:146
> >> expected: <value> but was: <null>
> >>> [INFO]
> >>>
> >>>
> >>> Run 2 fails in log4j-api
> >>> [ERROR] Failures:
> >>> [ERROR] LoggerTest.mdc:556 Test Year is null ==> expected: not <null>
> >>>
> >>> Run 3 log4j-api passes but log4j-core fails
> >>> [INFO]
> >>> [ERROR] Failures:
> >>> [ERROR] RollingDirectTimeNewDirectoryTest.streamClosedError:95 check
> >> failure
> >>>
> >>> Run 4 - log4j-api and log4j-core pass but fails in log4j-kafka
> >>> [ERROR] Failures:
> >>> [ERROR] ConfigurationBuilderTest.testXmlConstructing:116
> >> expected:<<?xml version="1.0" [?>
> >>> ]<Configuration name=...> but was:<<?xml version="1.0"
> >> [encoding="UTF-8"?>]<Configuration name=…>
> >>>
> >>> Run 5 - failure in log4j-core (I’m probably the last one to touch this
> >> so I’m the one who will most likely need to figure this one out)
> >>>
> >>> [ERROR] Failures:
> >>> [ERROR] RollingAppenderDirectWrite1906Test.testAppender:95 2021-02-07
> >> 10:50:17,478 main INFO Log4j appears to be running in a Servlet
> >> environment, but there's no log4j-web module available. If you want
> better
> >> web container support, please add the log4j-web JAR to your web archive
> or
> >> server lib directory.
> >>> 2021-02-07 10:50:17,488 main INFO Log4j appears to be running in a
> >> Servlet environment, but there's no log4j-web module available. If you
> want
> >> better web container support, please add the log4j-web JAR to your web
> >> archive or server lib directory.
> >>> 2021-02-07 10:50:17,499 main DEBUG Took 0.003727 seconds to load 3
> >> plugins from sun.misc.Launcher$AppClassLoader@4aa298b7
> >>> 2021-02-07 10:50:17,505 main DEBUG Took 0.005450 seconds to load 220
> >> plugins from sun.misc.Launcher$AppClassLoader@4aa298b7
> >>> 2021-02-07 10:50:17,506 main DEBUG Took 0.000032 seconds to load 0
> >> plugins from sun.misc.Launcher$ExtClassLoader@44f75083
> >>> 2021-02-07 10:50:17,506 main DEBUG PluginManager 'Converter' found 46
> >> plugins
> >>> 2021-02-07 10:50:17,540 main DEBUG Starting OutputStreamManager
> >> SYSTEM_OUT.false.false-1
> >>> 2021-02-07 10:50:17,541 main DEBUG Initializing Thread Context Data
> >> Service Providers
> >>> 2021-02-07 10:50:17,541 main DEBUG Thread Context Data Service Provider
> >> initialization complete
> >>> 2021-02-07 10:50:17,544 main INFO Log4j appears to be running in a
> >> Servlet environment, but there's no log4j-web module available. If you
> want
> >> better web container support, please add the log4j-web JAR to your web
> >> archive or server lib directory.
> >>> 2021-02-07 10:50:17,545 main DEBUG PluginManager 'ConfigurationFactory'
> >> found 4 plugins
> >>> 2021-02-07 10:50:17,548 main INFO Log4j appears to be running in a
> >> Servlet environment, but there's no log4j-web module available. If you
> want
> >> better web container support, please add the log4j-web JAR to your web
> >> archive or server lib directory.
> >>> 2021-02-07 10:50:17,549 main INFO Log4j appears to be running in a
> >> Servlet environment, but there's no log4j-web module available. If you
> want
> >> better web container support, please add the log4j-web JAR to your web
> >> archive or server lib directory.
> >>> 2021-02-07 10:50:17,557 main INFO Log4j appears to be running in a
> >> Servlet environment, but there's no log4j-web module available. If you
> want
> >> better web container support, please add the log4j-web JAR to your web
> >> archive or server lib directory.
> >>> 2021-02-07 10:50:17,558 main INFO Log4j appears to be running in a
> >> Servlet environment, but there's no log4j-web module available. If you
> want
> >> better web container support, please add the log4j-web JAR to your web
> >> archive or server lib directory.
> >>> 2021-02-07 10:50:17,561 main DEBUG Using configurationFactory
> >>
> org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@4387b79e
> >>> 2021-02-07 10:50:17,562 main TRACE Trying to find
> >> [log4j-rolling-direct-1906.xml] using context class loader
> >> sun.misc.Launcher$AppClassLoader@4aa298b7.
> >>> 2021-02-07 10:50:17,566 main INFO Log4j appears to be running in a
> >> Servlet environment, but there's no log4j-web module available. If you
> want
> >> better web container support, please add the log4j-web JAR to your web
> >> archive or server lib directory.
> >>> 2021-02-07 10:50:17,567 main DEBUG Closing BufferedInputStream
> >> java.io.BufferedInputStream@2cbb3d47
> >>> 2021-02-07 10:50:17,594 main DEBUG Watching configuration
> >>
> '/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml'
> >> for lastModified Sun Feb 07 10:46:58 MST 2021 (1612720018000)
> >>> 2021-02-07 10:50:17,595 main DEBUG Starting
> >>
> LoggerContext[name=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test)]
> >> from configuration at log4j-rolling-direct-1906.xml
> >>> 2021-02-07 10:50:17,595 main DEBUG Starting
> >>
> LoggerContext[name=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),
> >> org.apache.logging.log4j.core.LoggerContext@add0edd] with configuration
> >>
> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]...
> >>> 2021-02-07 10:50:17,595 main DEBUG Shutdown hook enabled. Registering a
> >> new one.
> >>> 2021-02-07 10:50:17,601 main DEBUG null null initializing configuration
> >>
> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
> >>> 2021-02-07 10:50:17,605 main DEBUG Installed 3 script engines
> >>> 2021-02-07 10:50:17,772 main DEBUG Oracle Nashorn version: 1.8.0_144,
> >> language: ECMAScript, threading: Not Thread Safe, compile: true, names:
> >> [nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript,
> ecmascript],
> >> factory class: jdk.nashorn.api.scripting.NashornScriptEngineFactory
> >>> 2021-02-07 10:50:17,807 main DEBUG BeanShell Engine version: 1.0,
> >> language: BeanShell, threading: MULTITHREADED, compile: true, names:
> >> [beanshell, bsh, java], factory class: bsh.engine.BshScriptEngineFactory
> >>> 2021-02-07 10:50:17,839 main DEBUG Groovy Scripting Engine version:
> 2.0,
> >> language: Groovy, threading: MULTITHREADED, compile: true, names:
> [groovy,
> >> Groovy], factory class:
> org.codehaus.groovy.jsr223.GroovyScriptEngineFactory
> >>> 2021-02-07 10:50:17,839 main DEBUG PluginManager 'Core' found 117
> plugins
> >>> 2021-02-07 10:50:17,839 main DEBUG PluginManager 'Level' found 1
> plugins
> >>> 2021-02-07 10:50:17,845 main DEBUG Building Plugin[name=property,
> >> class=org.apache.logging.log4j.core.config.Property].
> >>> 2021-02-07 10:50:17,865 main TRACE TypeConverterRegistry initializing.
> >>> 2021-02-07 10:50:17,865 main DEBUG PluginManager 'TypeConverter' found
> >> 26 plugins
> >>> 2021-02-07 10:50:17,873 main DEBUG createProperty(,
> >> value="target/rolling-direct-1906")
> >>> 2021-02-07 10:50:17,873 main DEBUG Building Plugin[name=properties,
> >> class=org.apache.logging.log4j.core.config.PropertiesPlugin].
> >>> 2021-02-07 10:50:17,877 main DEBUG
> >> configureSubstitutor(={baseDir=target/rolling-direct-1906},
> >>
> Configuration(/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml))
> >>> 2021-02-07 10:50:17,877 main DEBUG PluginManager 'Lookup' found 16
> >> plugins
> >>> 2021-02-07 10:50:17,878 main DEBUG Building Plugin[name=layout,
> >> class=org.apache.logging.log4j.core.layout.PatternLayout].
> >>> 2021-02-07 10:50:17,881 main TRACE Using value %d{yyyy-MM-dd-HH-mm-ss}
> >> [%level] [%c] %msg%n for option pattern
> >>> 2021-02-07 10:50:17,882 main TRACE Using default value null for option
> >> PatternSelector
> >>> 2021-02-07 10:50:17,882 main TRACE Using value
> >>
> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
> >> for option configuration
> >>> 2021-02-07 10:50:17,882 main TRACE Using default value null for option
> >> Replace
> >>> 2021-02-07 10:50:17,882 main TRACE Using default value UTF-8 for option
> >> charset
> >>> 2021-02-07 10:50:17,883 main TRACE Using default value true for option
> >> alwaysWriteExceptions
> >>> 2021-02-07 10:50:17,883 main TRACE Using default value false for option
> >> disableAnsi
> >>> 2021-02-07 10:50:17,883 main TRACE Using default value false for option
> >> noConsoleNoAnsi
> >>> 2021-02-07 10:50:17,883 main TRACE Using default value null for option
> >> header
> >>> 2021-02-07 10:50:17,884 main TRACE Using default value null for option
> >> footer
> >>> 2021-02-07 10:50:17,884 main DEBUG
> >> PatternLayout$Builder(pattern="%d{yyyy-MM-dd-HH-mm-ss} [%level] [%c]
> >> %msg%n", PatternSelector=null,
> >>
> Configuration(/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml),
> >> Replace=null, charset=null, alwaysWriteExceptions=null,
> disableAnsi=null,
> >> noConsoleNoAnsi=null, header=null, footer=null)
> >>> 2021-02-07 10:50:17,884 main DEBUG PluginManager 'Converter' found 46
> >> plugins
> >>> 2021-02-07 10:50:17,893 main DEBUG Building
> >> Plugin[name=TimeBasedTriggeringPolicy,
> >>
> class=org.apache.logging.log4j.core.appender.rolling.TimeBasedTriggeringPolicy].
> >>> 2021-02-07 10:50:17,895 main TRACE Using default value 1 for option
> >> interval
> >>> 2021-02-07 10:50:17,895 main TRACE Using default value false for option
> >> modulate
> >>> 2021-02-07 10:50:17,895 main TRACE Using default value 0 for option
> >> maxRandomDelay
> >>> 2021-02-07 10:50:17,895 main DEBUG
> >> TimeBasedTriggeringPolicy$Builder(interval=null, modulate=null,
> >> maxRandomDelay=null)
> >>> 2021-02-07 10:50:17,895 main DEBUG Building Plugin[name=Policies,
> >>
> class=org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy].
> >>> 2021-02-07 10:50:17,896 main DEBUG
> >> createPolicy(={TimeBasedTriggeringPolicy(nextRolloverMillis=0,
> interval=1,
> >> modulate=false)})
> >>> 2021-02-07 10:50:17,896 main DEBUG Building
> >> Plugin[name=DirectWriteRolloverStrategy,
> >>
> class=org.apache.logging.log4j.core.appender.rolling.DirectWriteRolloverStrategy].
> >>> 2021-02-07 10:50:17,897 main TRACE Using default value null for option
> >> maxFiles
> >>> 2021-02-07 10:50:17,898 main TRACE Using default value null for option
> >> compressionLevel
> >>> 2021-02-07 10:50:17,898 main TRACE Using value [] for option Actions
> >>> 2021-02-07 10:50:17,898 main TRACE Using default value true for option
> >> stopCustomActionsOnError
> >>> 2021-02-07 10:50:17,898 main TRACE Using default value null for option
> >> tempCompressedFilePattern
> >>> 2021-02-07 10:50:17,898 main TRACE Using value
> >>
> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
> >> for option config
> >>> 2021-02-07 10:50:17,898 main DEBUG
> >> DirectWriteRolloverStrategy$Builder(maxFiles=null,
> compressionLevel=null,
> >> ={}, stopCustomActionsOnError=null, tempCompressedFilePattern=null,
> >>
> Configuration(/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml))
> >>> 2021-02-07 10:50:17,899 main DEBUG Building Plugin[name=appender,
> >> class=org.apache.logging.log4j.core.appender.RollingFileAppender].
> >>> 2021-02-07 10:50:17,900 main TRACE Using default value null for option
> >> fileName
> >>> 2021-02-07 10:50:17,901 main TRACE Using value
> >> target/rolling-direct-1906/rollingfile.%d{yyyy-MM-dd-HH-mm-ss}.log for
> >> option filePattern
> >>> 2021-02-07 10:50:17,901 main TRACE Using default value true for option
> >> append
> >>> 2021-02-07 10:50:17,901 main TRACE Using default value false for option
> >> locking
> >>> 2021-02-07 10:50:17,902 main TRACE Using value
> >>
> CompositeTriggeringPolicy(policies=[TimeBasedTriggeringPolicy(nextRolloverMillis=0,
> >> interval=1, modulate=false)]) for option Policy
> >>> 2021-02-07 10:50:17,902 main TRACE Using value
> >> DirectWriteRolloverStrategy(maxFiles=2147483647) for option Strategy
> >>> 2021-02-07 10:50:17,902 main TRACE Using default value false for option
> >> advertise
> >>> 2021-02-07 10:50:17,902 main TRACE Using default value null for option
> >> advertiseUri
> >>> 2021-02-07 10:50:17,902 main TRACE Using default value false for option
> >> createOnDemand
> >>> 2021-02-07 10:50:17,902 main TRACE Using default value null for option
> >> filePermissions
> >>> 2021-02-07 10:50:17,903 main TRACE Using default value null for option
> >> fileOwner
> >>> 2021-02-07 10:50:17,903 main TRACE Using default value null for option
> >> fileGroup
> >>> 2021-02-07 10:50:17,903 main TRACE Using default value true for option
> >> bufferedIo
> >>> 2021-02-07 10:50:17,903 main TRACE Using default value 8192 for option
> >> bufferSize
> >>> 2021-02-07 10:50:17,903 main TRACE Using default value true for option
> >> immediateFlush
> >>> 2021-02-07 10:50:17,904 main TRACE Using default value true for option
> >> ignoreExceptions
> >>> 2021-02-07 10:50:17,904 main TRACE Using value %d{yyyy-MM-dd-HH-mm-ss}
> >> [%level] [%c] %msg%n for option Layout
> >>> 2021-02-07 10:50:17,904 main TRACE Using value RollingFile for option
> >> name
> >>> 2021-02-07 10:50:17,905 main TRACE Using value
> >>
> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
> >> for option configuration
> >>> 2021-02-07 10:50:17,905 main TRACE Using default value null for option
> >> Filter
> >>> 2021-02-07 10:50:17,905 main TRACE Using value [] for option Properties
> >>> 2021-02-07 10:50:17,905 main DEBUG
> >> RollingFileAppender$Builder(fileName=null,
> >>
> filePattern="target/rolling-direct-1906/rollingfile.%d{yyyy-MM-dd-HH-mm-ss}.log",
> >> append=null, locking=null,
> >>
> Policies(CompositeTriggeringPolicy(policies=[TimeBasedTriggeringPolicy(nextRolloverMillis=0,
> >> interval=1, modulate=false)])),
> >>
> DirectWriteRolloverStrategy(DirectWriteRolloverStrategy(maxFiles=2147483647)),
> >> advertise=null, advertiseUri=null, createOnDemand=null,
> >> filePermissions=null, fileOwner=null, fileGroup=null, bufferedIo=null,
> >> bufferSize=null, immediateFlush=null, ignoreExceptions=null,
> >> PatternLayout(%d{yyyy-MM-dd-HH-mm-ss} [%level] [%c] %msg%n),
> >> name="RollingFile",
> >>
> Configuration(/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml),
> >> Filter=null, ={})
> >>> 2021-02-07 10:50:17,908 main DEBUG Starting RollingFileManager
> >> target/rolling-direct-1906/rollingfile.%d{yyyy-MM-dd-HH-mm-ss}.log
> >>> 2021-02-07 10:50:17,909 main DEBUG PluginManager 'FileConverter' found
> 2
> >> plugins
> >>> 2021-02-07 10:50:17,914 main DEBUG Setting prev file time to
> >> 1969-12-31T17:00:00.000-0700
> >>> 2021-02-07 10:50:17,914 main DEBUG Initializing triggering policy
> >>
> CompositeTriggeringPolicy(policies=[TimeBasedTriggeringPolicy(nextRolloverMillis=0,
> >> interval=1, modulate=false)])
> >>> 2021-02-07 10:50:17,914 main DEBUG Initializing triggering policy
> >> TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=1,
> modulate=false)
> >>> 2021-02-07 10:50:17,916 main TRACE PatternProcessor.getNextTime
> >> returning 2021/02/07-10:50:18.000, nextFileTime=2021/02/07-10:50:17.000,
> >> prevFileTime=1969/12/31-17:00:00.000, current=2021/02/07-10:50:17.915,
> >> freq=EVERY_SECOND
> >>> 2021-02-07 10:50:17,917 main TRACE PatternProcessor.getNextTime
> >> returning 2021/02/07-10:50:18.000, nextFileTime=2021/02/07-10:50:17.000,
> >> prevFileTime=2021/02/07-10:50:17.000, current=2021/02/07-10:50:17.916,
> >> freq=EVERY_SECOND
> >>> 2021-02-07 10:50:17,917 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=0, prevFileTime=1612720217000,
> >> nextFileTime=1612720217000
> >>> 2021-02-07 10:50:17,919 main TRACE Using default SystemClock for
> >> timestamps.
> >>> 2021-02-07 10:50:17,920 main DEBUG
> >> org.apache.logging.log4j.core.time.internal.SystemClock does not support
> >> precise timestamps.
> >>> 2021-02-07 10:50:17,921 main DEBUG Formatting file name.
> >> useCurrentTime=true, currentFileTime=0, prevFileTime=1612720217000,
> >> nextFileTime=1612720217000
> >>> 2021-02-07 10:50:17,922 main DEBUG Building Plugin[name=appenders,
> >> class=org.apache.logging.log4j.core.config.AppendersPlugin].
> >>> 2021-02-07 10:50:17,922 main DEBUG createAppenders(={RollingFile})
> >>> 2021-02-07 10:50:17,923 main DEBUG Building Plugin[name=AppenderRef,
> >> class=org.apache.logging.log4j.core.config.AppenderRef].
> >>> 2021-02-07 10:50:17,924 main DEBUG createAppenderRef(filter=null, , )
> >>> 2021-02-07 10:50:17,924 main DEBUG Building Plugin[name=root,
> >> class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
> >>> 2021-02-07 10:50:17,927 main DEBUG createLogger(, , , ={RollingFile},
> >> ={},
> >>
> Configuration(/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml),
> >> filter=null)
> >>> 2021-02-07 10:50:17,928 main DEBUG Building Plugin[name=loggers,
> >> class=org.apache.logging.log4j.core.config.LoggersPlugin].
> >>> 2021-02-07 10:50:17,929 main DEBUG createLoggers(={root})
> >>> 2021-02-07 10:50:17,931 main DEBUG Configuration
> >>
> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
> >> initialized
> >>> 2021-02-07 10:50:17,931 main DEBUG Starting configuration
> >>
> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
> >>> 2021-02-07 10:50:17,932 main DEBUG Log4j2 ConfigurationScheduler
> >> starting 1 threads
> >>> 2021-02-07 10:50:17,932 main DEBUG Started configuration
> >>
> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml]
> >> OK.
> >>> 2021-02-07 10:50:17,933 main TRACE Stopping
> >> org.apache.logging.log4j.core.config.DefaultConfiguration@400cff1a...
> >>> 2021-02-07 10:50:17,933 main TRACE DefaultConfiguration notified 1
> >> ReliabilityStrategies that config will be stopped.
> >>> 2021-02-07 10:50:17,933 main TRACE DefaultConfiguration stopping root
> >> LoggerConfig.
> >>> 2021-02-07 10:50:17,933 main TRACE DefaultConfiguration notifying
> >> ReliabilityStrategies that appenders will be stopped.
> >>> 2021-02-07 10:50:17,934 main TRACE DefaultConfiguration stopping
> >> remaining Appenders.
> >>> 2021-02-07 10:50:17,934 main DEBUG Shutting down OutputStreamManager
> >> SYSTEM_OUT.false.false-1
> >>> 2021-02-07 10:50:17,934 main DEBUG OutputStream closed
> >>> 2021-02-07 10:50:17,934 main DEBUG Shut down OutputStreamManager
> >> SYSTEM_OUT.false.false-1, all resources released: true
> >>> 2021-02-07 10:50:17,934 main DEBUG Appender DefaultConsole-1 stopped
> >> with status true
> >>> 2021-02-07 10:50:17,934 main TRACE DefaultConfiguration stopped 1
> >> remaining Appenders.
> >>> 2021-02-07 10:50:17,934 main TRACE DefaultConfiguration cleaning
> >> Appenders from 1 LoggerConfigs.
> >>> 2021-02-07 10:50:17,934 main DEBUG Stopped
> >> org.apache.logging.log4j.core.config.DefaultConfiguration@400cff1a OK
> >>> 2021-02-07 10:50:17,989 main TRACE Reregistering MBeans after
> >> reconfigure.
> >>
> Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@65987993
> >>> 2021-02-07 10:50:17,990 main TRACE Reregistering context (1/1):
> >>
> 'testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test)'
> >> org.apache.logging.log4j.core.LoggerContext@add0edd
> >>> 2021-02-07 10:50:17,990 main TRACE Unregistering but no MBeans found
> >> matching
> >>
> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test)'
> >>> 2021-02-07 10:50:17,990 main TRACE Unregistering but no MBeans found
> >> matching
> >>
> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=StatusLogger'
> >>> 2021-02-07 10:50:17,990 main TRACE Unregistering but no MBeans found
> >> matching
> >>
> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=ContextSelector'
> >>> 2021-02-07 10:50:17,990 main TRACE Unregistering but no MBeans found
> >> matching
> >>
> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=Loggers,name=*'
> >>> 2021-02-07 10:50:17,991 main TRACE Unregistering but no MBeans found
> >> matching
> >>
> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=Appenders,name=*'
> >>> 2021-02-07 10:50:17,991 main TRACE Unregistering but no MBeans found
> >> matching
> >>
> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=AsyncAppenders,name=*'
> >>> 2021-02-07 10:50:17,991 main TRACE Unregistering but no MBeans found
> >> matching
> >>
> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=AsyncLoggerRingBuffer'
> >>> 2021-02-07 10:50:17,991 main TRACE Unregistering but no MBeans found
> >> matching
> >>
> 'org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=Loggers,name=*,subtype=RingBuffer'
> >>> 2021-02-07 10:50:17,992 main DEBUG Registering MBean
> >>
> org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test)
> >>> 2021-02-07 10:50:17,993 main DEBUG Registering MBean
> >>
> org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=StatusLogger
> >>> 2021-02-07 10:50:17,994 main DEBUG Registering MBean
> >>
> org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=ContextSelector
> >>> 2021-02-07 10:50:17,995 main DEBUG Registering MBean
> >>
> org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=Loggers,name=
> >>> 2021-02-07 10:50:17,996 main DEBUG Registering MBean
> >>
> org.apache.logging.log4j2:type=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),component=Appenders,name=RollingFile
> >>> 2021-02-07 10:50:17,996 main TRACE Using DummyNanoClock for nanosecond
> >> timestamps.
> >>> 2021-02-07 10:50:17,996 main DEBUG
> >>
> LoggerContext[name=testAppender(org.apache.logging.log4j.core.appender.rolling.RollingAppenderDirectWrite1906Test),
> >> org.apache.logging.log4j.core.LoggerContext@add0edd] started OK with
> >> configuration
> >>
> XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/logging-log4j2/log4j-core/target/test-classes/log4j-rolling-direct-1906.xml].
> >>> 2021-02-07 10:50:18,000 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=0, prevFileTime=1612720217000,
> >> nextFileTime=1612720217000
> >>> 2021-02-07 10:50:18,000 main DEBUG Formatting file name.
> >> useCurrentTime=true, currentFileTime=0, prevFileTime=1612720217000,
> >> nextFileTime=1612720217000
> >>> 2021-02-07 10:50:18,001 main DEBUG Now writing to
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-18.log at
> >> 2021-02-07T10:50:18.001-0700
> >>> 2021-02-07 10:50:18,003 main DEBUG
> >> AsyncLogger.ThreadNameStrategy=UNCACHED (user specified null, default is
> >> UNCACHED)
> >>> 2021-02-07 10:50:18,003 main TRACE Using default SystemClock for
> >> timestamps.
> >>> 2021-02-07 10:50:18,003 main DEBUG
> >> org.apache.logging.log4j.core.time.internal.SystemClock does not support
> >> precise timestamps.
> >>> 2021-02-07 10:50:18,056 main TRACE PatternProcessor.getNextTime
> >> returning 2021/02/07-10:50:19.000, nextFileTime=2021/02/07-10:50:18.000,
> >> prevFileTime=2021/02/07-10:50:17.000, current=2021/02/07-10:50:18.056,
> >> freq=EVERY_SECOND
> >>> 2021-02-07 10:50:18,056 main DEBUG Rolling
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-18.log
> >>> 2021-02-07 10:50:18,056 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720218056,
> >> prevFileTime=1612720217000, nextFileTime=1612720218000
> >>> 2021-02-07 10:50:18,057 main DEBUG Found 0 eligible files, max is
> >> 2147483647
> >>> 2021-02-07 10:50:18,057 main TRACE DirectWriteRolloverStrategy.purge()
> >> took 0.0 milliseconds
> >>> 2021-02-07 10:50:18,058 main DEBUG OutputStream closed
> >>> 2021-02-07 10:50:18,058 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720218056,
> >> prevFileTime=1612720217000, nextFileTime=1612720218000
> >>> 2021-02-07 10:50:18,058 main DEBUG Formatting file name.
> >> useCurrentTime=true, currentFileTime=1612720218056,
> >> prevFileTime=1612720217000, nextFileTime=1612720218000
> >>> 2021-02-07 10:50:18,058 main DEBUG Now writing to
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-18.log at
> >> 2021-02-07T10:50:18.058-0700
> >>> 2021-02-07 10:50:19,009 main TRACE PatternProcessor.getNextTime
> >> returning 2021/02/07-10:50:20.000, nextFileTime=2021/02/07-10:50:19.000,
> >> prevFileTime=2021/02/07-10:50:18.000, current=2021/02/07-10:50:19.009,
> >> freq=EVERY_SECOND
> >>> 2021-02-07 10:50:19,009 main DEBUG Rolling
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-18.log
> >>> 2021-02-07 10:50:19,010 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720219009,
> >> prevFileTime=1612720218000, nextFileTime=1612720219000
> >>> 2021-02-07 10:50:19,010 main DEBUG Found 0 eligible files, max is
> >> 2147483647
> >>> 2021-02-07 10:50:19,010 main TRACE DirectWriteRolloverStrategy.purge()
> >> took 0.0 milliseconds
> >>> 2021-02-07 10:50:19,010 main DEBUG OutputStream closed
> >>> 2021-02-07 10:50:19,011 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720219009,
> >> prevFileTime=1612720218000, nextFileTime=1612720219000
> >>> 2021-02-07 10:50:19,011 main DEBUG Formatting file name.
> >> useCurrentTime=true, currentFileTime=1612720219009,
> >> prevFileTime=1612720218000, nextFileTime=1612720219000
> >>> 2021-02-07 10:50:19,011 main DEBUG Now writing to
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-19.log at
> >> 2021-02-07T10:50:19.011-0700
> >>> 2021-02-07 10:50:20,011 main TRACE PatternProcessor.getNextTime
> >> returning 2021/02/07-10:50:21.000, nextFileTime=2021/02/07-10:50:20.000,
> >> prevFileTime=2021/02/07-10:50:19.000, current=2021/02/07-10:50:20.011,
> >> freq=EVERY_SECOND
> >>> 2021-02-07 10:50:20,011 main DEBUG Rolling
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-19.log
> >>> 2021-02-07 10:50:20,011 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720220011,
> >> prevFileTime=1612720219000, nextFileTime=1612720220000
> >>> 2021-02-07 10:50:20,012 main DEBUG Found 0 eligible files, max is
> >> 2147483647
> >>> 2021-02-07 10:50:20,012 main TRACE DirectWriteRolloverStrategy.purge()
> >> took 0.0 milliseconds
> >>> 2021-02-07 10:50:20,012 main DEBUG OutputStream closed
> >>> 2021-02-07 10:50:20,012 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720220011,
> >> prevFileTime=1612720219000, nextFileTime=1612720220000
> >>> 2021-02-07 10:50:20,013 main DEBUG Formatting file name.
> >> useCurrentTime=true, currentFileTime=1612720220011,
> >> prevFileTime=1612720219000, nextFileTime=1612720220000
> >>> 2021-02-07 10:50:20,013 main DEBUG Now writing to
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-20.log at
> >> 2021-02-07T10:50:20.013-0700
> >>> 2021-02-07 10:50:21,021 main TRACE PatternProcessor.getNextTime
> >> returning 2021/02/07-10:50:22.000, nextFileTime=2021/02/07-10:50:21.000,
> >> prevFileTime=2021/02/07-10:50:20.000, current=2021/02/07-10:50:21.021,
> >> freq=EVERY_SECOND
> >>> 2021-02-07 10:50:21,021 main DEBUG Rolling
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-20.log
> >>> 2021-02-07 10:50:21,021 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720221021,
> >> prevFileTime=1612720220000, nextFileTime=1612720221000
> >>> 2021-02-07 10:50:21,022 main DEBUG Found 0 eligible files, max is
> >> 2147483647
> >>> 2021-02-07 10:50:21,022 main TRACE DirectWriteRolloverStrategy.purge()
> >> took 0.0 milliseconds
> >>> 2021-02-07 10:50:21,022 main DEBUG OutputStream closed
> >>> 2021-02-07 10:50:21,022 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720221021,
> >> prevFileTime=1612720220000, nextFileTime=1612720221000
> >>> 2021-02-07 10:50:21,022 main DEBUG Formatting file name.
> >> useCurrentTime=true, currentFileTime=1612720221021,
> >> prevFileTime=1612720220000, nextFileTime=1612720221000
> >>> 2021-02-07 10:50:21,022 main DEBUG Now writing to
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-21.log at
> >> 2021-02-07T10:50:21.022-0700
> >>> 2021-02-07 10:50:22,022 main TRACE PatternProcessor.getNextTime
> >> returning 2021/02/07-10:50:23.000, nextFileTime=2021/02/07-10:50:22.000,
> >> prevFileTime=2021/02/07-10:50:21.000, current=2021/02/07-10:50:22.022,
> >> freq=EVERY_SECOND
> >>> 2021-02-07 10:50:22,022 main DEBUG Rolling
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-21.log
> >>> 2021-02-07 10:50:22,022 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720222022,
> >> prevFileTime=1612720221000, nextFileTime=1612720222000
> >>> 2021-02-07 10:50:22,022 main DEBUG Found 0 eligible files, max is
> >> 2147483647
> >>> 2021-02-07 10:50:22,022 main TRACE DirectWriteRolloverStrategy.purge()
> >> took 0.0 milliseconds
> >>> 2021-02-07 10:50:22,023 main DEBUG OutputStream closed
> >>> 2021-02-07 10:50:22,023 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720222022,
> >> prevFileTime=1612720221000, nextFileTime=1612720222000
> >>> 2021-02-07 10:50:22,023 main DEBUG Formatting file name.
> >> useCurrentTime=true, currentFileTime=1612720222022,
> >> prevFileTime=1612720221000, nextFileTime=1612720222000
> >>> 2021-02-07 10:50:22,023 main DEBUG Now writing to
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-22.log at
> >> 2021-02-07T10:50:22.023-0700
> >>> 2021-02-07 10:50:23,033 main TRACE PatternProcessor.getNextTime
> >> returning 2021/02/07-10:50:24.000, nextFileTime=2021/02/07-10:50:23.000,
> >> prevFileTime=2021/02/07-10:50:22.000, current=2021/02/07-10:50:23.033,
> >> freq=EVERY_SECOND
> >>> 2021-02-07 10:50:23,033 main DEBUG Rolling
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-22.log
> >>> 2021-02-07 10:50:23,033 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720223033,
> >> prevFileTime=1612720222000, nextFileTime=1612720223000
> >>> 2021-02-07 10:50:23,034 main DEBUG Found 0 eligible files, max is
> >> 2147483647
> >>> 2021-02-07 10:50:23,034 main TRACE DirectWriteRolloverStrategy.purge()
> >> took 0.0 milliseconds
> >>> 2021-02-07 10:50:23,034 main DEBUG OutputStream closed
> >>> 2021-02-07 10:50:23,034 main DEBUG Formatting file name.
> >> useCurrentTime=false, currentFileTime=1612720223033,
> >> prevFileTime=1612720222000, nextFileTime=1612720223000
> >>> 2021-02-07 10:50:23,034 main DEBUG Formatting file name.
> >> useCurrentTime=true, currentFileTime=1612720223033,
> >> prevFileTime=1612720222000, nextFileTime=1612720223000
> >>> 2021-02-07 10:50:23,035 main DEBUG Now writing to
> >> target/rolling-direct-1906/rollingfile.2021-02-07-10-50-23.log at
> >> 2021-02-07T10:50:23.034-0700
> >>> Incorrect file name. Expected: rollingfile.2021-02-07-10-50-17.log
> >> Actual: rollingfile.2021-02-07-10-50-18.log
> >> expected:<...e.2021-02-07-10-50-1[7].log> but
> >> was:<...e.2021-02-07-10-50-1[8].log>
> >>>
> >>> Run 6 - failed in Kafka again
> >>> [ERROR] Failures:
> >>> [ERROR] ConfigurationBuilderTest.testXmlConstructing:116
> >> expected:<<?xml version="1.0" [?>
> >>> ]<Configuration name=...> but was:<<?xml version="1.0"
> >> [encoding="UTF-8"?>]<Configuration name=…>
> >>>
> >>> Ralph
> >>>
> >>>
> >>>
> >>
>
>
>
