I think he's referring to the need to run mvn install once before the
IDE will pick up snapshot jars for things like annotation processing
or other fancy things. Simple way to reproduce: try running "mvn
package" without the "install" target.
On Wed, 17 Feb 2021 at 13:58, Ralph Goers <ralph.go...@dslextreme.com> wrote:
>
> Yeah, there is a very good chance if you are trying to run tests in core in
> parallel on multiple threads that they will fail. Most of them expect their
> own LoggerContext.
>
> Ralph
>
> > On Feb 17, 2021, at 12:51 PM, Tim Perry <tim.v...@gmail.com> wrote:
> >
> > 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
> >>>>>
> >>>>>
> >>>>>
> >>>>
> >>
> >>
> >>
>
>
>
