[LOG4J2-2883] Size based rolling stops working after first time base rolling - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: 2.13.3
Fix Version/s: 2.14.0
Component/s: None
Labels:
None

Description

When configuring a logger with time based rolling and size based rolling. The size based rolling fails after the first time based rolling.

Note: This is slightly related to LOG4J2-2875. With no modifications the sample code below shows the problem, but also IOExceptions occur which seems not to be related to this issue.

import java.awt.Desktop;
import java.io.File;
import java.nio.file.Files;
import java.nio.file.Path;
import static java.util.Arrays.asList;
import static java.util.Collections.sort;
import java.util.List;
import java.util.Properties;
import org.apache.logging.log4j.core.Logger;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.config.properties.PropertiesConfiguration;
import org.apache.logging.log4j.core.config.properties.PropertiesConfigurationBuilder;
import static org.junit.jupiter.api.Assertions.assertEquals;
import org.junit.jupiter.api.Test;

public class RollingTest {

  @Test
  public void sizeBasedRollingBrokenAfterTimeBasedRolling() throws Exception {
    System.setProperty("log4j2.debug", "");

    Path tempDirectory = Files.createTempDirectory("log4j2");
    System.out.println(tempDirectory);

    Properties log4j2Properties = new Properties();
    log4j2Properties.put("appender.localmsglog.type", "RollingFile");
    log4j2Properties.put("appender.localmsglog.name", "localmsglog");
    log4j2Properties.put("appender.localmsglog.filePattern", tempDirectory.toFile().getAbsolutePath() + "/%d{yyyy_MM_dd_mm}/messages-$${date:yyyy_MM_dd_HH_mm_ss_S}.log");
    log4j2Properties.put("appender.localmsglog.policies.type", "Policies");
    log4j2Properties.put("appender.localmsglog.policies.1.type", "SizeBasedTriggeringPolicy");
    log4j2Properties.put("appender.localmsglog.policies.1.size", "10KB");
    log4j2Properties.put("appender.localmsglog.policies.2.type", "TimeBasedTriggeringPolicy");

    log4j2Properties.put("rootLogger.level", "info");
    log4j2Properties.put("rootLogger.appenderRef.1.ref", "localmsglog");

    PropertiesConfiguration config = new PropertiesConfigurationBuilder()
            .setRootProperties(log4j2Properties)
            .build();

    System.out.println("Test directory: " + tempDirectory.toString());
    Desktop.getDesktop().open(tempDirectory.toFile());
    org.apache.logging.log4j.core.config.Configurator.reconfigure(config);

    LoggerContext context = LoggerContext.getContext(false);
    Logger log = context.getRootLogger();

    for (int i = 0; i < 1000; i++) {
      log.info("nHq6p9kgfvWfjzDRYbZp");
    }
    Thread.sleep(60000);
    for (int i = 0; i < 1000; i++) {
      log.info("nHq6p9kgfvWfjzDRYbZp");
    }

    File tempDirectoryAsFile = tempDirectory.toFile();
    List<File> loggingFolders = asList(tempDirectoryAsFile.listFiles());
    sort(loggingFolders);
    // Check if two folders were created
    assertEquals(2, loggingFolders.size());
    
    // Check if first folder contains 3 log files
    assertEquals(3, loggingFolders.get(0).listFiles().length);

    // Check if second folder contains 3 log files as well
    assertEquals(3, loggingFolders.get(1).listFiles().length);
  }
}

Output:

-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running com.amadeus.rail.utils.log4j.RollingTest
C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785
DEBUG StatusLogger Using ShutdownCallbackRegistry class org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry
DEBUG StatusLogger Not in a ServletContext environment, thus not loading WebLookup plugin.
DEBUG StatusLogger AsyncLogger.ThreadNameStrategy=UNCACHED (user specified null, default is UNCACHED)
TRACE StatusLogger Using default SystemClock for timestamps.
DEBUG StatusLogger org.apache.logging.log4j.core.util.SystemClock supports precise timestamps.
Test directory: C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785
DEBUG StatusLogger Not in a ServletContext environment, thus not loading WebLookup plugin.
DEBUG StatusLogger Not in a ServletContext environment, thus not loading WebLookup plugin.
DEBUG StatusLogger Took 0,125982 seconds to load 239 plugins from jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09
DEBUG StatusLogger PluginManager 'Converter' found 46 plugins
DEBUG StatusLogger Starting OutputStreamManager SYSTEM_OUT.false.false-1
DEBUG StatusLogger Starting LoggerContext[name=57ccce09, org.apache.logging.log4j.core.LoggerContext@f72a1a9]...
DEBUG StatusLogger Reconfiguration started for context[name=57ccce09] at URI null (org.apache.logging.log4j.core.LoggerContext@f72a1a9) with optional ClassLoader: null
DEBUG StatusLogger Not in a ServletContext environment, thus not loading WebLookup plugin.
DEBUG StatusLogger PluginManager 'ConfigurationFactory' found 5 plugins
DEBUG StatusLogger Not in a ServletContext environment, thus not loading WebLookup plugin.
DEBUG StatusLogger Not in a ServletContext environment, thus not loading WebLookup plugin.
DEBUG StatusLogger Not in a ServletContext environment, thus not loading WebLookup plugin.
DEBUG StatusLogger Missing dependencies for Yaml support, ConfigurationFactory org.apache.logging.log4j.core.config.yaml.YamlConfigurationFactory is inactive
DEBUG StatusLogger Not in a ServletContext environment, thus not loading WebLookup plugin.
DEBUG StatusLogger Missing dependencies for Json support, ConfigurationFactory org.apache.logging.log4j.core.config.json.JsonConfigurationFactory is inactive
DEBUG StatusLogger Not in a ServletContext environment, thus not loading WebLookup plugin.
DEBUG StatusLogger Using configurationFactory org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@cb49d772
TRACE StatusLogger Trying to find [log4j2-test57ccce09.properties] using context class loader jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.properties] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.properties] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.properties] using ClassLoader.getSystemResource().
TRACE StatusLogger Trying to find [log4j2-test57ccce09.properties] using context class loader jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.properties] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.properties] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.properties] using ClassLoader.getSystemResource().
TRACE StatusLogger Trying to find [log4j2-test57ccce09.yml] using context class loader jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.yml] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.yml] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.yml] using ClassLoader.getSystemResource().
TRACE StatusLogger Trying to find [log4j2-test57ccce09.yaml] using context class loader jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.yaml] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.yaml] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.yaml] using ClassLoader.getSystemResource().
TRACE StatusLogger Trying to find [log4j2-test57ccce09.json] using context class loader jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.json] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.json] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.json] using ClassLoader.getSystemResource().
TRACE StatusLogger Trying to find [log4j2-test57ccce09.jsn] using context class loader jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.jsn] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.jsn] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.jsn] using ClassLoader.getSystemResource().
TRACE StatusLogger Trying to find [log4j2-test57ccce09.xml] using context class loader jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.xml] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.xml] using jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09 class loader.
TRACE StatusLogger Trying to find [log4j2-test57ccce09.xml] using ClassLoader.getSystemResource().
TRACE StatusLogger Trying to find [log4j2-test.properties] using context class loader jdk.internal.loader.ClassLoaders$AppClassLoader@57ccce09.
DEBUG StatusLogger Not in a ServletContext environment, thus not loading WebLookup plugin.
DEBUG StatusLogger Apache Log4j Core 2.13.1 initializing configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@81c96556
DEBUG StatusLogger Installed 1 script engine
Warning: Nashorn engine is planned to be removed from a future JDK release
DEBUG StatusLogger Oracle Nashorn version: 11.0.6, language: ECMAScript, threading: Not Thread Safe, compile: true, names: [nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript], factory class: jdk.nashorn.api.scripting.NashornScriptEngineFactory
DEBUG StatusLogger PluginManager 'Core' found 133 plugins
DEBUG StatusLogger PluginManager 'Level' found 1 plugins
DEBUG StatusLogger PluginManager 'Lookup' found 15 plugins
DEBUG StatusLogger Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
TRACE StatusLogger TypeConverterRegistry initializing.
DEBUG StatusLogger PluginManager 'TypeConverter' found 26 plugins
DEBUG StatusLogger createAppenderRef(ref="consoleAppender", level="null", Filter=null)
DEBUG StatusLogger Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
DEBUG StatusLogger createAppenderRef(ref="listAppender", level="null", Filter=null)
DEBUG StatusLogger Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
DEBUG StatusLogger createLogger(additivity="null", level="INFO", includeLocation="null", ={consoleAppender, listAppender}, ={}, Configuration, Filter=null)
DEBUG StatusLogger Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
DEBUG StatusLogger createLoggers(={root})
DEBUG StatusLogger Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
DEBUG StatusLogger PatternLayout$Builder(pattern="[%d{yy-MMM-dd HH:mm:ss:SSS}] [%p] [%c{1}:%L] - %m", PatternSelector=null, Configuration, Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
DEBUG StatusLogger PluginManager 'Converter' found 46 plugins
DEBUG StatusLogger Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
DEBUG StatusLogger ConsoleAppender$Builder(target="null", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout([%d{yy-MMM-dd HH:mm:ss:SSS}] [%p] [%c{1}:%L] - %m), name="consoleAppender", Configuration, Filter=null, ={})
DEBUG StatusLogger Starting OutputStreamManager SYSTEM_OUT.false.false
DEBUG StatusLogger Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
DEBUG StatusLogger PatternLayout$Builder(pattern="%m%n", PatternSelector=null, Configuration, Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
DEBUG StatusLogger Building Plugin[name=appender, class=org.apache.logging.log4j.test.appender.ListAppender].
DEBUG StatusLogger ListAppender$Builder(name="listAppender", entryPerNewLine="null", raw="null", PatternLayout(%m%n), Filter=null)
DEBUG StatusLogger Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
DEBUG StatusLogger createAppenders(={consoleAppender, ListAppender [events=[], messages=[], data=[], newLine=false, raw=false, countDownLatch=null, getHandler()=org.apache.logging.log4j.core.appender.DefaultErrorHandler@a1fb8ca7, getLayout()=%m%n, getName()=listAppender, ignoreExceptions()=true, getFilter()=null, getState()=INITIALIZED]})
DEBUG StatusLogger Configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@81c96556 initialized
DEBUG StatusLogger Starting configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@81c96556
DEBUG StatusLogger Started configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@81c96556 OK.
TRACE StatusLogger Stopping org.apache.logging.log4j.core.config.DefaultConfiguration@98c0d638...
TRACE StatusLogger DefaultConfiguration notified 1 ReliabilityStrategies that config will be stopped.
TRACE StatusLogger DefaultConfiguration stopping root LoggerConfig.
TRACE StatusLogger DefaultConfiguration notifying ReliabilityStrategies that appenders will be stopped.
TRACE StatusLogger DefaultConfiguration stopping remaining Appenders.
DEBUG StatusLogger Shutting down OutputStreamManager SYSTEM_OUT.false.false-1
DEBUG StatusLogger OutputStream closed
DEBUG StatusLogger Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true
DEBUG StatusLogger Appender DefaultConsole-1 stopped with status true
TRACE StatusLogger DefaultConfiguration stopped 1 remaining Appenders.
TRACE StatusLogger DefaultConfiguration cleaning Appenders from 1 LoggerConfigs.
DEBUG StatusLogger Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@98c0d638 OK
TRACE StatusLogger Reregistering MBeans after reconfigure. Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@bafbb692
TRACE StatusLogger Reregistering context (1/1): '57ccce09' org.apache.logging.log4j.core.LoggerContext@f72a1a9
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=StatusLogger'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=ContextSelector'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=Loggers,name=*'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=Appenders,name=*'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=AsyncAppenders,name=*'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=AsyncLoggerRingBuffer'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=Loggers,name=*,subtype=RingBuffer'
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=57ccce09
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=57ccce09,component=StatusLogger
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=57ccce09,component=ContextSelector
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=57ccce09,component=Loggers,name=
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=57ccce09,component=Appenders,name=consoleAppender
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=57ccce09,component=Appenders,name=listAppender
TRACE StatusLogger Using default SystemClock for timestamps.
DEBUG StatusLogger org.apache.logging.log4j.core.util.SystemClock supports precise timestamps.
TRACE StatusLogger Using DummyNanoClock for nanosecond timestamps.
DEBUG StatusLogger Reconfiguration complete for context[name=57ccce09] at URI C:\dev\src\java\amadeus-bahn\log4j2-utils\target\test-classes\log4j2-test.properties (org.apache.logging.log4j.core.LoggerContext@f72a1a9) with optional ClassLoader: null
DEBUG StatusLogger Shutdown hook enabled. Registering a new one.
DEBUG StatusLogger LoggerContext[name=57ccce09, org.apache.logging.log4j.core.LoggerContext@f72a1a9] started OK.
DEBUG StatusLogger Apache Log4j Core 2.13.1 initializing configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@79534c86
DEBUG StatusLogger Installed 1 script engine
Warning: Nashorn engine is planned to be removed from a future JDK release
DEBUG StatusLogger Oracle Nashorn version: 11.0.6, language: ECMAScript, threading: Not Thread Safe, compile: true, names: [nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript], factory class: jdk.nashorn.api.scripting.NashornScriptEngineFactory
DEBUG StatusLogger PluginManager 'Core' found 133 plugins
DEBUG StatusLogger PluginManager 'Level' found 1 plugins
DEBUG StatusLogger PluginManager 'Lookup' found 15 plugins
DEBUG StatusLogger Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
DEBUG StatusLogger createAppenderRef(ref="localmsglog", level="null", Filter=null)
DEBUG StatusLogger Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
DEBUG StatusLogger createLogger(additivity="null", level="INFO", includeLocation="null", ={localmsglog}, ={}, Configuration, Filter=null)
DEBUG StatusLogger Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
DEBUG StatusLogger createLoggers(={root})
DEBUG StatusLogger Building Plugin[name=SizeBasedTriggeringPolicy, class=org.apache.logging.log4j.core.appender.rolling.SizeBasedTriggeringPolicy].
DEBUG StatusLogger createPolicy(size="10KB")
DEBUG StatusLogger Building Plugin[name=TimeBasedTriggeringPolicy, class=org.apache.logging.log4j.core.appender.rolling.TimeBasedTriggeringPolicy].
DEBUG StatusLogger TimeBasedTriggeringPolicy$Builder(interval="null", modulate="null", maxRandomDelay="null")
DEBUG StatusLogger Building Plugin[name=Policies, class=org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy].
DEBUG StatusLogger createPolicy(={SizeBasedTriggeringPolicy(size=10240), TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=1, modulate=false)})
DEBUG StatusLogger Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.RollingFileAppender].
DEBUG StatusLogger RollingFileAppender$Builder(fileName="null", filePattern="C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/%d{yyyy_MM_dd_mm}/messages-${date:yyyy_MM_dd_HH_mm_ss_S}.log", append="null", locking="null", Policies(CompositeTriggeringPolicy(policies=[SizeBasedTriggeringPolicy(size=10240), TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=1, modulate=false)])), Strategy=null, advertise="null", advertiseUri="null", createOnDemand="null", filePermissions="null", fileOwner="null", fileGroup="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", Layout=null, name="localmsglog", Configuration, Filter=null, ={})
DEBUG StatusLogger Not in a ServletContext environment, thus not loading WebLookup plugin.
DEBUG StatusLogger PluginManager 'Converter' found 46 plugins
DEBUG StatusLogger Starting OutputStreamManager SYSTEM_OUT.false.false-2
DEBUG StatusLogger Starting RollingFileManager C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/%d{yyyy_MM_dd_mm}/messages-${date:yyyy_MM_dd_HH_mm_ss_S}.log
DEBUG StatusLogger PluginManager 'FileConverter' found 2 plugins
DEBUG StatusLogger Setting prev file time to 1970-01-01T01:00:00.000+0100
DEBUG StatusLogger Initializing triggering policy CompositeTriggeringPolicy(policies=[SizeBasedTriggeringPolicy(size=10240), TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=1, modulate=false)])
DEBUG StatusLogger Initializing triggering policy SizeBasedTriggeringPolicy(size=10240)
DEBUG StatusLogger Initializing triggering policy TimeBasedTriggeringPolicy(nextRolloverMillis=0, interval=1, modulate=false)
TRACE StatusLogger PatternProcessor.getNextTime returning 2020/07/02-12:26:00.000, nextFileTime=2020/07/02-12:25:00.000, prevFileTime=1970/01/01-01:00:00.000, current=2020/07/02-12:25:52.614, freq=EVERY_MINUTE
TRACE StatusLogger PatternProcessor.getNextTime returning 2020/07/02-12:26:00.000, nextFileTime=2020/07/02-12:25:00.000, prevFileTime=2020/07/02-12:25:00.000, current=2020/07/02-12:25:52.615, freq=EVERY_MINUTE
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=0, prevFileTime=1593685500000
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=0, prevFileTime=1593685500000
DEBUG StatusLogger Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
DEBUG StatusLogger createAppenders(={localmsglog})
DEBUG StatusLogger Configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@79534c86 initialized
DEBUG StatusLogger Starting configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@79534c86
DEBUG StatusLogger Started configuration org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@79534c86 OK.
TRACE StatusLogger Stopping org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@81c96556...
TRACE StatusLogger PropertiesConfiguration notified 2 ReliabilityStrategies that config will be stopped.
TRACE StatusLogger PropertiesConfiguration stopping 1 LoggerConfigs.
TRACE StatusLogger PropertiesConfiguration stopping root LoggerConfig.
TRACE StatusLogger PropertiesConfiguration notifying ReliabilityStrategies that appenders will be stopped.
TRACE StatusLogger PropertiesConfiguration stopping remaining Appenders.
DEBUG StatusLogger Shutting down OutputStreamManager SYSTEM_OUT.false.false
DEBUG StatusLogger OutputStream closed
DEBUG StatusLogger Shut down OutputStreamManager SYSTEM_OUT.false.false, all resources released: true
DEBUG StatusLogger Appender consoleAppender stopped with status true
TRACE StatusLogger PropertiesConfiguration stopped 2 remaining Appenders.
TRACE StatusLogger PropertiesConfiguration cleaning Appenders from 2 LoggerConfigs.
DEBUG StatusLogger Stopped org.apache.logging.log4j.core.config.properties.PropertiesConfiguration@81c96556 OK
TRACE StatusLogger Reregistering MBeans after reconfigure. Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@bafbb692
TRACE StatusLogger Reregistering context (1/1): '57ccce09' org.apache.logging.log4j.core.LoggerContext@f72a1a9
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=57ccce09]
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=57ccce09,component=StatusLogger]
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=57ccce09,component=ContextSelector]
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=57ccce09,component=Loggers,name=]
TRACE StatusLogger Unregistering 2 MBeans: [org.apache.logging.log4j2:type=57ccce09,component=Appenders,name=consoleAppender, org.apache.logging.log4j2:type=57ccce09,component=Appenders,name=listAppender]
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=AsyncAppenders,name=*'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=AsyncLoggerRingBuffer'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=Loggers,name=*,subtype=RingBuffer'
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=57ccce09
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=57ccce09,component=StatusLogger
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=57ccce09,component=ContextSelector
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=57ccce09,component=Loggers,name=
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=57ccce09,component=Appenders,name=localmsglog
TRACE StatusLogger Using DummyNanoClock for nanosecond timestamps.
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=0, prevFileTime=1593685500000
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=0, prevFileTime=1593685500000
DEBUG StatusLogger Now writing to C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/2020_07_02_25/messages-2020_07_02_12_25_52_650.log at 2020-07-02T12:25:52.650+0200
DEBUG StatusLogger Rolling C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/2020_07_02_25/messages-2020_07_02_12_25_52_650.log
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=0, prevFileTime=1593685500000
DEBUG StatusLogger Found 0 eligible files, max is  2147483647
TRACE StatusLogger DirectWriteRolloverStrategy.purge() took 1.0 milliseconds
DEBUG StatusLogger OutputStream closed
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=0, prevFileTime=1593685500000
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=0, prevFileTime=1593685500000
DEBUG StatusLogger Now writing to C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/2020_07_02_25/messages-2020_07_02_12_25_52_686.log at 2020-07-02T12:25:52.686+0200
DEBUG StatusLogger Rolling C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/2020_07_02_25/messages-2020_07_02_12_25_52_686.log
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=0, prevFileTime=1593685500000
DEBUG StatusLogger Found 0 eligible files, max is  2147483647
TRACE StatusLogger DirectWriteRolloverStrategy.purge() took 1.0 milliseconds
DEBUG StatusLogger OutputStream closed
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=0, prevFileTime=1593685500000
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=0, prevFileTime=1593685500000
DEBUG StatusLogger Now writing to C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/2020_07_02_25/messages-2020_07_02_12_25_52_710.log at 2020-07-02T12:25:52.710+0200
TRACE StatusLogger PatternProcessor.getNextTime returning 2020/07/02-12:27:00.000, nextFileTime=2020/07/02-12:26:00.000, prevFileTime=2020/07/02-12:25:00.000, current=2020/07/02-12:26:52.715, freq=EVERY_MINUTE
DEBUG StatusLogger Rolling C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/2020_07_02_25/messages-2020_07_02_12_25_52_710.log
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=1593685612716, prevFileTime=1593685500000
DEBUG StatusLogger Found 0 eligible files, max is  2147483647
TRACE StatusLogger DirectWriteRolloverStrategy.purge() took 2.0 milliseconds
DEBUG StatusLogger OutputStream closed
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=1593685612716, prevFileTime=1593685500000
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=1593685612716, prevFileTime=1593685500000
DEBUG StatusLogger Now writing to C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/2020_07_02_26/messages-2020_07_02_12_26_52_716.log at 2020-07-02T12:26:52.722+0200
DEBUG StatusLogger Rolling C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/2020_07_02_26/messages-2020_07_02_12_26_52_716.log
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=1593685612716, prevFileTime=1593685560000
DEBUG StatusLogger Found 0 eligible files, max is  2147483647
TRACE StatusLogger DirectWriteRolloverStrategy.purge() took 2.0 milliseconds
DEBUG StatusLogger OutputStream closed
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=1593685612716, prevFileTime=1593685560000
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=1593685612716, prevFileTime=1593685560000
DEBUG StatusLogger Now writing to C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/2020_07_02_26/messages-2020_07_02_12_26_52_716.log at 2020-07-02T12:26:52.761+0200
DEBUG StatusLogger Rolling C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/2020_07_02_26/messages-2020_07_02_12_26_52_716.log
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=1593685612716, prevFileTime=1593685560000
DEBUG StatusLogger Found 0 eligible files, max is  2147483647
TRACE StatusLogger DirectWriteRolloverStrategy.purge() took 2.0 milliseconds
DEBUG StatusLogger OutputStream closed
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=1593685612716, prevFileTime=1593685560000
DEBUG StatusLogger Formatting file name. useCurrentTime=true. currentFileTime=1593685612716, prevFileTime=1593685560000
DEBUG StatusLogger Now writing to C:\Users\BENJAM~1.ASB\AppData\Local\Temp\log4j24342776539466181785/2020_07_02_26/messages-2020_07_02_12_26_52_716.log at 2020-07-02T12:26:52.800+0200
Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 61.866 s <<< FAILURE! - in com.amadeus.rail.utils.log4j.RollingTest
sizeBasedRollingBrokenAfterTimeBasedRolling  Time elapsed: 61.862 s  <<< FAILURE!
org.opentest4j.AssertionFailedError: expected: <3> but was: <1>
	at com.amadeus.rail.utils.log4j.RollingTest.sizeBasedRollingBrokenAfterTimeBasedRolling(RollingTest.java:68)

DEBUG StatusLogger Stopping LoggerContext[name=57ccce09, org.apache.logging.log4j.core.LoggerContext@f72a1a9]
DEBUG StatusLogger Stopping LoggerContext[name=57ccce09, org.apache.logging.log4j.core.LoggerContext@f72a1a9]...
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=57ccce09]
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=57ccce09,component=StatusLogger]
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=57ccce09,component=ContextSelector]
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=57ccce09,component=Loggers,name=]
TRACE StatusLogger Unregistering 1 MBeans: [org.apache.logging.log4j2:type=57ccce09,component=Appenders,name=localmsglog]
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=AsyncAppenders,name=*'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=57ccce09,component=AsyncLoggerRingBuffer'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:typ[e=57ccce09,coImNpFoOne]n t=
L
oggers,name=*,subtype=R[ingBIuNfFfOe] rR'
es
ults:

Failures: 
  RollingTest.sizeBasedRollingBrokenAfterTimeBasedRolling:68 expected: <3> but was: <1>

Tests run: 1, Failures: 1, Errors: 0, Skipped: 0

------------------------------------------------------------------------
BUILD FAILURE
------------------------------------------------------------------------

Attachments

Issue Links

is related to

LOG4J2-2897 Error creating rolling file with dated folder

Closed

relates to

LOG4J2-2875 StreamClosed IOException after first time based rolling

Resolved

Activity

People

Assignee:: Unassigned

Reporter:: Benjamin Asbach

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 02/Jul/20 09:55

Updated:: 02/Aug/20 20:05

Resolved:: 31/Jul/20 04:21