Details
-
Bug
-
Status: Closed
-
Major
-
Resolution: Fixed
-
2.7
-
Mac OS X 10.11.6 running Eclipse Neon 4.6.0 with JDK 1.8.0_74
-
Important
Description
If this isn't actually a bug, then I apologize for reporting it, but I cannot figure out how it could be anything else currently. Full disclosure: I am still a newbie.
I've been using the log4j 2.6.x series for a while, but noticed that the CronTriggeringPolicy when used with RollingFileAppender causes that infinite rollover bug. I noted that this bug was to be fixed in 2.7, so I downloaded that the day it was released and replaced the 2.6 version with it. Now, however, without changing anything else in my code nor in my log4j2.xml file, I am getting exceptions regarding them.
Here's the interesting bit: Since I was trying to see if the rollover would occur at midnight, I manually changed my computer's clock to just a minute before, logged some info, let it roll to past midnight, and let it log some more info. All of that info got logged into the main file; nothing rolled over. Here's the stacktrace from that execution:
2016-10-10 09:40:47,521 main DEBUG Initializing configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] 2016-10-10 09:40:47,526 main DEBUG Installed script engines 2016-10-10 09:40:47,955 main DEBUG Oracle Nashorn Version: 1.8.0_74, Language: ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript} 2016-10-10 09:40:48,307 main DEBUG AppleScriptEngine Version: 1.1, Language: AppleScript, Threading: Not Thread Safe, Compile: false, Names: {AppleScriptEngine, AppleScript, OSA} 2016-10-10 09:40:48,308 main DEBUG PluginManager 'Core' found 107 plugins 2016-10-10 09:40:48,308 main DEBUG PluginManager 'Level' found 0 plugins 2016-10-10 09:40:48,312 main DEBUG 2 starting Log4j2 ConfigurationScheduler threads 2016-10-10 09:40:48,314 main DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property]. 2016-10-10 09:40:48,323 main TRACE TypeConverterRegistry initializing. 2016-10-10 09:40:48,324 main DEBUG PluginManager 'TypeConverter' found 23 plugins 2016-10-10 09:40:48,330 main DEBUG createProperty(name="filename", value="logs/artdept.log") 2016-10-10 09:40:48,330 main DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property]. 2016-10-10 09:40:48,331 main DEBUG createProperty(name="baseDir", value="/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs") 2016-10-10 09:40:48,331 main DEBUG Building Plugin[name=properties, class=org.apache.logging.log4j.core.config.PropertiesPlugin]. 2016-10-10 09:40:48,334 main DEBUG configureSubstitutor(={filename=logs/artdept.log, baseDir=/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs}, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml)) 2016-10-10 09:40:48,335 main DEBUG PluginManager 'Lookup' found 13 plugins 2016-10-10 09:40:48,335 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout]. 2016-10-10 09:40:48,341 main DEBUG PatternLayout$Builder(pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n", PatternSelector=null, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null") 2016-10-10 09:40:48,341 main DEBUG PluginManager 'Converter' found 41 plugins 2016-10-10 09:40:48,342 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender]. 2016-10-10 09:40:48,347 main DEBUG ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n), name="Console", Filter=null) 2016-10-10 09:40:48,347 main DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false 2016-10-10 09:40:48,348 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout]. 2016-10-10 09:40:48,348 main DEBUG PatternLayout$Builder(pattern="%d %p %C{1.} [%t] %m%n", PatternSelector=null, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null") 2016-10-10 09:40:48,360 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.FileAppender]. 2016-10-10 09:40:48,364 main DEBUG FileAppender$Builder(fileName="logs/artdept.log", append="null", locking="null", advertise="null", advertiseUri="null", createOnDemand="null", Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d %p %C{1.} [%t] %m%n), name="MyFile", Filter=null) 2016-10-10 09:40:48,365 main DEBUG Starting FileManager logs/artdept.log 2016-10-10 09:40:48,366 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout]. 2016-10-10 09:40:48,366 main DEBUG PatternLayout$Builder(pattern="%d %p %C{1.} [%t] %m%n", PatternSelector=null, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null") 2016-10-10 09:40:48,367 main DEBUG Building Plugin[name=CronTriggeringPolicy, class=org.apache.logging.log4j.core.appender.rolling.CronTriggeringPolicy]. 2016-10-10 09:40:48,368 main DEBUG createPolicy(Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), evaluateOnStartup="true", schedule="0 0 0 * * ?") 2016-10-10 09:40:48,370 main DEBUG Building Plugin[name=SizeBasedTriggeringPolicy, class=org.apache.logging.log4j.core.appender.rolling.SizeBasedTriggeringPolicy]. 2016-10-10 09:40:48,371 main DEBUG createPolicy(size="250 MB") 2016-10-10 09:40:48,372 main DEBUG Building Plugin[name=Policies, class=org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy]. 2016-10-10 09:40:48,373 main DEBUG createPolicy(={CronTriggeringPolicy(schedule=0 0 0 * * ?), SizeBasedTriggeringPolicy(size=262144000)}) 2016-10-10 09:40:48,373 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.RollingFileAppender]. 2016-10-10 09:40:48,376 main DEBUG RollingFileAppender$Builder(fileName="/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log", filePattern="/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/%d{dd} - Launcher-%i.log", append="null", locking="null", Policies(CompositeTriggeringPolicy(policies=[CronTriggeringPolicy(schedule=0 0 0 * * ?), SizeBasedTriggeringPolicy(size=262144000)])), Strategy=null, advertise="null", advertiseUri="null", createOnDemand="null", Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d %p %C{1.} [%t] %m%n), name="DailyRoll", Filter=null) 2016-10-10 09:40:48,512 main TRACE New file '/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log' created = false 2016-10-10 09:40:48,515 main DEBUG Starting RollingFileManager /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log 2016-10-10 09:40:48,516 main DEBUG PluginManager 'FileConverter' found 2 plugins 2016-10-10 09:40:48,520 main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin]. 2016-10-10 09:40:48,521 main DEBUG createAppenders(={Console, MyFile, DailyRoll}) 2016-10-10 09:40:48,521 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef]. 2016-10-10 09:40:48,521 main DEBUG createAppenderRef(ref="DailyRoll", level="null", Filter=null) 2016-10-10 09:40:48,522 main DEBUG Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger]. 2016-10-10 09:40:48,522 main DEBUG createLogger(additivity="null", level="TRACE", includeLocation="null", ={DailyRoll}, ={}, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Filter=null) 2016-10-10 09:40:48,524 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin]. 2016-10-10 09:40:48,525 main DEBUG createLoggers(={root}) 2016-10-10 09:40:48,525 main DEBUG Configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] initialized 2016-10-10 09:40:48,525 main DEBUG Starting configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] 2016-10-10 09:40:48,526 main DEBUG Started configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] OK. 2016-10-10 09:40:48,526 main TRACE Stopping org.apache.logging.log4j.core.config.DefaultConfiguration@76ccd017... 2016-10-10 09:40:48,527 main TRACE DefaultConfiguration notified 1 ReliabilityStrategies that config will be stopped. 2016-10-10 09:40:48,527 main TRACE DefaultConfiguration stopping root LoggerConfig. 2016-10-10 09:40:48,527 main TRACE DefaultConfiguration notifying ReliabilityStrategies that appenders will be stopped. 2016-10-10 09:40:48,527 main TRACE DefaultConfiguration stopping remaining Appenders. 2016-10-10 09:40:48,527 main DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false-1 2016-10-10 09:40:48,528 main DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true 2016-10-10 09:40:48,528 main TRACE DefaultConfiguration stopped 1 remaining Appenders. 2016-10-10 09:40:48,528 main TRACE DefaultConfiguration cleaning Appenders from 1 LoggerConfigs. 2016-10-10 09:40:48,528 main DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@76ccd017 OK 2016-10-10 09:40:48,572 main TRACE Reregistering MBeans after reconfigure. Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@1bd4fdd 2016-10-10 09:40:48,572 main TRACE Reregistering context (1/1): '2a139a55' org.apache.logging.log4j.core.LoggerContext@55183b20 2016-10-10 09:40:48,574 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55' 2016-10-10 09:40:48,574 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=StatusLogger' 2016-10-10 09:40:48,574 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=ContextSelector' 2016-10-10 09:40:48,575 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=*' 2016-10-10 09:40:48,575 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=*' 2016-10-10 09:40:48,575 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncAppenders,name=*' 2016-10-10 09:40:48,576 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncLoggerRingBuffer' 2016-10-10 09:40:48,576 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=*,subtype=RingBuffer' 2016-10-10 09:40:48,578 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55 2016-10-10 09:40:48,580 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=StatusLogger 2016-10-10 09:40:48,581 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=ContextSelector 2016-10-10 09:40:48,582 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=Loggers,name= 2016-10-10 09:40:48,583 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=Console 2016-10-10 09:40:48,583 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=MyFile 2016-10-10 09:40:48,583 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=DailyRoll 2016-10-10 09:40:48,585 main TRACE Using default SystemClock for timestamps. 2016-10-10 09:40:48,585 main TRACE Using DummyNanoClock for nanosecond timestamps. 2016-10-10 09:40:48,585 main DEBUG Reconfiguration complete for context[name=2a139a55] at URI /Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml (org.apache.logging.log4j.core.LoggerContext@55183b20) with optional ClassLoader: null 2016-10-10 09:40:48,585 main DEBUG Shutdown hook enabled. Registering a new one. 2016-10-10 09:40:48,586 main DEBUG LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@55183b20] started OK. Debug Log menu item clicked; Logging is now true 2016-10-11 00:00:25,734 pool-1-thread-1 DEBUG Stopping LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@55183b20] 2016-10-11 00:00:25,734 pool-1-thread-1 DEBUG Stopping LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@55183b20]... 2016-10-11 00:00:25,735 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55] 2016-10-11 00:00:25,735 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=StatusLogger] 2016-10-11 00:00:25,735 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=ContextSelector] 2016-10-11 00:00:25,736 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=] 2016-10-11 00:00:25,736 pool-1-thread-1 TRACE Unregistering 3 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=MyFile, org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=Console, org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=DailyRoll] 2016-10-11 00:00:25,736 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncAppenders,name=*' 2016-10-11 00:00:25,736 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncLoggerRingBuffer' 2016-10-11 00:00:25,736 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=*,subtype=RingBuffer' 2016-10-11 00:00:25,737 pool-1-thread-1 TRACE Stopping XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml]... 2016-10-11 00:00:25,737 pool-1-thread-1 TRACE XmlConfiguration notified 2 ReliabilityStrategies that config will be stopped. 2016-10-11 00:00:25,737 pool-1-thread-1 TRACE XmlConfiguration stopping 1 LoggerConfigs. 2016-10-11 00:00:25,737 pool-1-thread-1 TRACE XmlConfiguration stopping root LoggerConfig. 2016-10-11 00:00:25,737 pool-1-thread-1 TRACE XmlConfiguration notifying ReliabilityStrategies that appenders will be stopped. 2016-10-11 00:00:25,737 pool-1-thread-1 TRACE XmlConfiguration stopping remaining Appenders. 2016-10-11 00:00:25,737 pool-1-thread-1 DEBUG Shutting down RollingFileManager /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log 2016-10-11 00:00:25,988 pool-1-thread-1 DEBUG Shut down RollingFileManager /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log, all resources released: true 2016-10-11 00:00:25,988 pool-1-thread-1 DEBUG Shutting down FileManager logs/artdept.log 2016-10-11 00:00:25,988 pool-1-thread-1 DEBUG Shut down FileManager logs/artdept.log, all resources released: true 2016-10-11 00:00:25,989 pool-1-thread-1 DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false 2016-10-11 00:00:25,989 pool-1-thread-1 DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false, all resources released: true 2016-10-11 00:00:25,989 pool-1-thread-1 TRACE XmlConfiguration stopped 3 remaining Appenders. 2016-10-11 00:00:25,989 pool-1-thread-1 TRACE XmlConfiguration cleaning Appenders from 2 LoggerConfigs. 2016-10-11 00:00:25,989 pool-1-thread-1 DEBUG Log4j2 ConfigurationScheduler shutting down threads in java.util.concurrent.ScheduledThreadPoolExecutor@11d33cbe[Running, pool size = 2, active threads = 0, queued tasks = 2, completed tasks = 7] 2016-10-11 00:00:25,989 pool-1-thread-1 DEBUG Stopped XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] OK 2016-10-11 00:00:25,990 pool-1-thread-1 DEBUG Stopped LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@55183b20]...
No exceptions recorded.
However, if I re-start the application while the computer's clock is still showing past Midnight on the following day, I am given this stacktrace, which does have exceptions recorded:
2016-10-11 00:01:02,843 main DEBUG Initializing configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] 2016-10-11 00:01:02,848 main DEBUG Installed script engines 2016-10-11 00:01:03,071 main DEBUG Oracle Nashorn Version: 1.8.0_74, Language: ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript} 2016-10-11 00:01:03,097 main DEBUG AppleScriptEngine Version: 1.1, Language: AppleScript, Threading: Not Thread Safe, Compile: false, Names: {AppleScriptEngine, AppleScript, OSA} 2016-10-11 00:01:03,097 main DEBUG PluginManager 'Core' found 107 plugins 2016-10-11 00:01:03,097 main DEBUG PluginManager 'Level' found 0 plugins 2016-10-11 00:01:03,102 main DEBUG 2 starting Log4j2 ConfigurationScheduler threads 2016-10-11 00:01:03,104 main DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property]. 2016-10-11 00:01:03,113 main TRACE TypeConverterRegistry initializing. 2016-10-11 00:01:03,114 main DEBUG PluginManager 'TypeConverter' found 23 plugins 2016-10-11 00:01:03,121 main DEBUG createProperty(name="filename", value="logs/artdept.log") 2016-10-11 00:01:03,121 main DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property]. 2016-10-11 00:01:03,122 main DEBUG createProperty(name="baseDir", value="/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs") 2016-10-11 00:01:03,122 main DEBUG Building Plugin[name=properties, class=org.apache.logging.log4j.core.config.PropertiesPlugin]. 2016-10-11 00:01:03,126 main DEBUG configureSubstitutor(={filename=logs/artdept.log, baseDir=/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs}, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml)) 2016-10-11 00:01:03,127 main DEBUG PluginManager 'Lookup' found 13 plugins 2016-10-11 00:01:03,128 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout]. 2016-10-11 00:01:03,132 main DEBUG PatternLayout$Builder(pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n", PatternSelector=null, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null") 2016-10-11 00:01:03,132 main DEBUG PluginManager 'Converter' found 41 plugins 2016-10-11 00:01:03,133 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender]. 2016-10-11 00:01:03,139 main DEBUG ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n), name="Console", Filter=null) 2016-10-11 00:01:03,139 main DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false 2016-10-11 00:01:03,140 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout]. 2016-10-11 00:01:03,140 main DEBUG PatternLayout$Builder(pattern="%d %p %C{1.} [%t] %m%n", PatternSelector=null, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null") 2016-10-11 00:01:03,150 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.FileAppender]. 2016-10-11 00:01:03,153 main DEBUG FileAppender$Builder(fileName="logs/artdept.log", append="null", locking="null", advertise="null", advertiseUri="null", createOnDemand="null", Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d %p %C{1.} [%t] %m%n), name="MyFile", Filter=null) 2016-10-11 00:01:03,154 main DEBUG Starting FileManager logs/artdept.log 2016-10-11 00:01:03,154 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout]. 2016-10-11 00:01:03,155 main DEBUG PatternLayout$Builder(pattern="%d %p %C{1.} [%t] %m%n", PatternSelector=null, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null") 2016-10-11 00:01:03,155 main DEBUG Building Plugin[name=CronTriggeringPolicy, class=org.apache.logging.log4j.core.appender.rolling.CronTriggeringPolicy]. 2016-10-11 00:01:03,157 main DEBUG createPolicy(Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), evaluateOnStartup="true", schedule="0 0 0 * * ?") 2016-10-11 00:01:03,160 main DEBUG Building Plugin[name=SizeBasedTriggeringPolicy, class=org.apache.logging.log4j.core.appender.rolling.SizeBasedTriggeringPolicy]. 2016-10-11 00:01:03,160 main DEBUG createPolicy(size="250 MB") 2016-10-11 00:01:03,161 main DEBUG Building Plugin[name=Policies, class=org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy]. 2016-10-11 00:01:03,162 main DEBUG createPolicy(={CronTriggeringPolicy(schedule=0 0 0 * * ?), SizeBasedTriggeringPolicy(size=262144000)}) 2016-10-11 00:01:03,162 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.RollingFileAppender]. 2016-10-11 00:01:03,165 main DEBUG RollingFileAppender$Builder(fileName="/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log", filePattern="/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/%d{dd} - Launcher-%i.log", append="null", locking="null", Policies(CompositeTriggeringPolicy(policies=[CronTriggeringPolicy(schedule=0 0 0 * * ?), SizeBasedTriggeringPolicy(size=262144000)])), Strategy=null, advertise="null", advertiseUri="null", createOnDemand="null", Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d %p %C{1.} [%t] %m%n), name="DailyRoll", Filter=null) 2016-10-11 00:01:03,175 main TRACE New file '/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log' created = false 2016-10-11 00:01:03,177 main DEBUG Starting RollingFileManager /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log 2016-10-11 00:01:03,178 main DEBUG PluginManager 'FileConverter' found 2 plugins 2016-10-11 00:01:03,182 main TRACE Using default SystemClock for timestamps. 2016-10-11 00:01:03,191 main TRACE DefaultRolloverStrategy.purge() took 10.0 milliseconds 2016-10-11 00:01:03,193 main DEBUG RollingFileManager executing synchronous FileRenameAction[/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log to /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/11 - Launcher-2.log, renameEmptyFiles=false] 2016-10-11 00:01:03,203 main TRACE Renamed file /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log to /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/11 - Launcher-2.log with Files.move 2016-10-11 00:01:03,205 main ERROR Unable to inject fields into builder class for plugin type class org.apache.logging.log4j.core.appender.RollingFileAppender, element RollingFile. java.lang.NullPointerException at org.apache.logging.log4j.core.appender.rolling.CronTriggeringPolicy.rollover(CronTriggeringPolicy.java:133) at org.apache.logging.log4j.core.appender.rolling.CronTriggeringPolicy.initialize(CronTriggeringPolicy.java:69) at org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy.initialize(CompositeTriggeringPolicy.java:52) at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.initialize(RollingFileManager.java:104) at org.apache.logging.log4j.core.appender.RollingFileAppender$Builder.build(RollingFileAppender.java:142) at org.apache.logging.log4j.core.appender.RollingFileAppender$Builder.build(RollingFileAppender.java:58) at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:122) at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:942) at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:882) at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:874) at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:498) at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:227) at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:239) at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:530) at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:603) at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:620) at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:226) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:242) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45) at org.apache.logging.log4j.LogManager.getContext(LogManager.java:174) at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:618) at info.chrismcgee.sky.artdept.ArtDept.<clinit>(ArtDept.java:85) 2016-10-11 00:01:03,206 main ERROR Unable to invoke factory method in class class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile. java.lang.IllegalStateException: No factory method found for class org.apache.logging.log4j.core.appender.RollingFileAppender at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.findFactoryMethod(PluginBuilder.java:224) at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:130) at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:942) at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:882) at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:874) at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:498) at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:227) at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:239) at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:530) at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:603) at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:620) at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:226) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:242) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45) at org.apache.logging.log4j.LogManager.getContext(LogManager.java:174) at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:618) at info.chrismcgee.sky.artdept.ArtDept.<clinit>(ArtDept.java:85) 2016-10-11 00:01:03,207 main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin]. 2016-10-11 00:01:03,207 main ERROR Null object returned for RollingFile in Appenders. 2016-10-11 00:01:03,207 main DEBUG createAppenders(={Console, MyFile, }) 2016-10-11 00:01:03,207 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef]. 2016-10-11 00:01:03,208 main DEBUG createAppenderRef(ref="DailyRoll", level="null", Filter=null) 2016-10-11 00:01:03,208 main DEBUG Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger]. 2016-10-11 00:01:03,209 main DEBUG createLogger(additivity="null", level="TRACE", includeLocation="null", ={DailyRoll}, ={}, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Filter=null) 2016-10-11 00:01:03,211 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin]. 2016-10-11 00:01:03,211 main DEBUG createLoggers(={root}) 2016-10-11 00:01:03,211 main ERROR Unable to locate appender "DailyRoll" for logger config "root" 2016-10-11 00:01:03,212 main DEBUG Configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] initialized 2016-10-11 00:01:03,212 main DEBUG Starting configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] 2016-10-11 00:01:03,213 main DEBUG Started configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] OK. 2016-10-11 00:01:03,214 main TRACE Stopping org.apache.logging.log4j.core.config.DefaultConfiguration@76ccd017... 2016-10-11 00:01:03,214 main TRACE DefaultConfiguration notified 1 ReliabilityStrategies that config will be stopped. 2016-10-11 00:01:03,214 main TRACE DefaultConfiguration stopping root LoggerConfig. 2016-10-11 00:01:03,214 main TRACE DefaultConfiguration notifying ReliabilityStrategies that appenders will be stopped. 2016-10-11 00:01:03,214 main TRACE DefaultConfiguration stopping remaining Appenders. 2016-10-11 00:01:03,214 main DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false-1 2016-10-11 00:01:03,215 main DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true 2016-10-11 00:01:03,215 main TRACE DefaultConfiguration stopped 1 remaining Appenders. 2016-10-11 00:01:03,215 main TRACE DefaultConfiguration cleaning Appenders from 1 LoggerConfigs. 2016-10-11 00:01:03,215 main DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@76ccd017 OK 2016-10-11 00:01:03,265 main TRACE Reregistering MBeans after reconfigure. Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@689604d9 2016-10-11 00:01:03,266 main TRACE Reregistering context (1/1): '2a139a55' org.apache.logging.log4j.core.LoggerContext@18078bef 2016-10-11 00:01:03,267 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55' 2016-10-11 00:01:03,268 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=StatusLogger' 2016-10-11 00:01:03,268 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=ContextSelector' 2016-10-11 00:01:03,268 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=*' 2016-10-11 00:01:03,269 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=*' 2016-10-11 00:01:03,269 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncAppenders,name=*' 2016-10-11 00:01:03,269 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncLoggerRingBuffer' 2016-10-11 00:01:03,269 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=*,subtype=RingBuffer' 2016-10-11 00:01:03,270 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55 2016-10-11 00:01:03,272 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=StatusLogger 2016-10-11 00:01:03,273 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=ContextSelector 2016-10-11 00:01:03,274 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=Loggers,name= 2016-10-11 00:01:03,276 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=Console 2016-10-11 00:01:03,276 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=MyFile 2016-10-11 00:01:03,276 main TRACE Using DummyNanoClock for nanosecond timestamps. 2016-10-11 00:01:03,277 main DEBUG Reconfiguration complete for context[name=2a139a55] at URI /Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml (org.apache.logging.log4j.core.LoggerContext@18078bef) with optional ClassLoader: null 2016-10-11 00:01:03,277 main DEBUG Shutdown hook enabled. Registering a new one. 2016-10-11 00:01:03,278 main DEBUG LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@18078bef] started OK. Debug Log menu item clicked; Logging is now true 2016-10-11 00:02:05,448 pool-1-thread-1 DEBUG Stopping LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@18078bef] 2016-10-11 00:02:05,449 pool-1-thread-1 DEBUG Stopping LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@18078bef]... 2016-10-11 00:02:05,449 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55] 2016-10-11 00:02:05,449 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=StatusLogger] 2016-10-11 00:02:05,449 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=ContextSelector] 2016-10-11 00:02:05,450 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=] 2016-10-11 00:02:05,450 pool-1-thread-1 TRACE Unregistering 2 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=MyFile, org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=Console] 2016-10-11 00:02:05,450 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncAppenders,name=*' 2016-10-11 00:02:05,450 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncLoggerRingBuffer' 2016-10-11 00:02:05,451 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=*,subtype=RingBuffer' 2016-10-11 00:02:05,451 pool-1-thread-1 TRACE Stopping XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml]... 2016-10-11 00:02:05,451 pool-1-thread-1 TRACE XmlConfiguration notified 2 ReliabilityStrategies that config will be stopped. 2016-10-11 00:02:05,451 pool-1-thread-1 TRACE XmlConfiguration stopping 1 LoggerConfigs. 2016-10-11 00:02:05,451 pool-1-thread-1 TRACE XmlConfiguration stopping root LoggerConfig. 2016-10-11 00:02:05,451 pool-1-thread-1 TRACE XmlConfiguration notifying ReliabilityStrategies that appenders will be stopped. 2016-10-11 00:02:05,452 pool-1-thread-1 TRACE XmlConfiguration stopping remaining Appenders. 2016-10-11 00:02:05,452 pool-1-thread-1 DEBUG Shutting down FileManager logs/artdept.log 2016-10-11 00:02:05,452 pool-1-thread-1 DEBUG Shut down FileManager logs/artdept.log, all resources released: true 2016-10-11 00:02:05,452 pool-1-thread-1 DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false 2016-10-11 00:02:05,452 pool-1-thread-1 DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false, all resources released: true 2016-10-11 00:02:05,452 pool-1-thread-1 TRACE XmlConfiguration stopped 2 remaining Appenders. 2016-10-11 00:02:05,453 pool-1-thread-1 TRACE XmlConfiguration cleaning Appenders from 2 LoggerConfigs. 2016-10-11 00:02:05,453 pool-1-thread-1 DEBUG Log4j2 ConfigurationScheduler shutting down threads in java.util.concurrent.ScheduledThreadPoolExecutor@4fba9a33[Running, pool size = 2, active threads = 0, queued tasks = 1, completed tasks = 2] 2016-10-11 00:02:05,453 pool-1-thread-1 DEBUG Stopped XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] OK 2016-10-11 00:02:05,454 pool-1-thread-1 DEBUG Stopped LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@18078bef]...
The rollover does occur, but then nothing is recorded into the current log file.
One final log. This one is taken from when I left the program running overnight. Notice what happens, close to the end of it, where the actual rollover takes place at Midnight:
2016-10-10 17:13:45,925 main DEBUG Initializing configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] 2016-10-10 17:13:45,952 main DEBUG Installed script engines 2016-10-10 17:13:46,217 main DEBUG Oracle Nashorn Version: 1.8.0_74, Language: ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript} 2016-10-10 17:13:46,650 main DEBUG AppleScriptEngine Version: 1.1, Language: AppleScript, Threading: Not Thread Safe, Compile: false, Names: {AppleScriptEngine, AppleScript, OSA} 2016-10-10 17:13:46,651 main DEBUG PluginManager 'Core' found 107 plugins 2016-10-10 17:13:46,651 main DEBUG PluginManager 'Level' found 0 plugins 2016-10-10 17:13:46,655 main DEBUG 2 starting Log4j2 ConfigurationScheduler threads 2016-10-10 17:13:46,657 main DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property]. 2016-10-10 17:13:46,687 main TRACE TypeConverterRegistry initializing. 2016-10-10 17:13:46,688 main DEBUG PluginManager 'TypeConverter' found 23 plugins 2016-10-10 17:13:46,700 main DEBUG createProperty(name="filename", value="logs/artdept.log") 2016-10-10 17:13:46,700 main DEBUG Building Plugin[name=property, class=org.apache.logging.log4j.core.config.Property]. 2016-10-10 17:13:46,700 main DEBUG createProperty(name="baseDir", value="/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs") 2016-10-10 17:13:46,701 main DEBUG Building Plugin[name=properties, class=org.apache.logging.log4j.core.config.PropertiesPlugin]. 2016-10-10 17:13:46,706 main DEBUG configureSubstitutor(={filename=logs/artdept.log, baseDir=/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs}, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml)) 2016-10-10 17:13:46,706 main DEBUG PluginManager 'Lookup' found 13 plugins 2016-10-10 17:13:46,707 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout]. 2016-10-10 17:13:46,713 main DEBUG PatternLayout$Builder(pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n", PatternSelector=null, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null") 2016-10-10 17:13:46,713 main DEBUG PluginManager 'Converter' found 41 plugins 2016-10-10 17:13:46,714 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender]. 2016-10-10 17:13:46,719 main DEBUG ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n), name="Console", Filter=null) 2016-10-10 17:13:46,719 main DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false 2016-10-10 17:13:46,720 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout]. 2016-10-10 17:13:46,720 main DEBUG PatternLayout$Builder(pattern="%d %p %C{1.} [%t] %m%n", PatternSelector=null, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null") 2016-10-10 17:13:46,732 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.FileAppender]. 2016-10-10 17:13:46,735 main DEBUG FileAppender$Builder(fileName="logs/artdept.log", append="null", locking="null", advertise="null", advertiseUri="null", createOnDemand="null", Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d %p %C{1.} [%t] %m%n), name="MyFile", Filter=null) 2016-10-10 17:13:46,736 main DEBUG Starting FileManager logs/artdept.log 2016-10-10 17:13:46,736 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout]. 2016-10-10 17:13:46,736 main DEBUG PatternLayout$Builder(pattern="%d %p %C{1.} [%t] %m%n", PatternSelector=null, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null", header="null", footer="null") 2016-10-10 17:13:46,737 main DEBUG Building Plugin[name=CronTriggeringPolicy, class=org.apache.logging.log4j.core.appender.rolling.CronTriggeringPolicy]. 2016-10-10 17:13:46,738 main DEBUG createPolicy(Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), evaluateOnStartup="true", schedule="0 0 0 * * ?") 2016-10-10 17:13:46,740 main DEBUG Building Plugin[name=SizeBasedTriggeringPolicy, class=org.apache.logging.log4j.core.appender.rolling.SizeBasedTriggeringPolicy]. 2016-10-10 17:13:46,741 main DEBUG createPolicy(size="250 MB") 2016-10-10 17:13:46,742 main DEBUG Building Plugin[name=Policies, class=org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy]. 2016-10-10 17:13:46,742 main DEBUG createPolicy(={CronTriggeringPolicy(schedule=0 0 0 * * ?), SizeBasedTriggeringPolicy(size=262144000)}) 2016-10-10 17:13:46,742 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.RollingFileAppender]. 2016-10-10 17:13:46,745 main DEBUG RollingFileAppender$Builder(fileName="/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log", filePattern="/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/%d{dd} - Launcher-%i.log", append="null", locking="null", Policies(CompositeTriggeringPolicy(policies=[CronTriggeringPolicy(schedule=0 0 0 * * ?), SizeBasedTriggeringPolicy(size=262144000)])), Strategy=null, advertise="null", advertiseUri="null", createOnDemand="null", Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d %p %C{1.} [%t] %m%n), name="DailyRoll", Filter=null) 2016-10-10 17:13:46,757 main TRACE New file '/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log' created = false 2016-10-10 17:13:46,760 main DEBUG Starting RollingFileManager /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log 2016-10-10 17:13:46,760 main DEBUG PluginManager 'FileConverter' found 2 plugins 2016-10-10 17:13:46,765 main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin]. 2016-10-10 17:13:46,765 main DEBUG createAppenders(={Console, MyFile, DailyRoll}) 2016-10-10 17:13:46,766 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef]. 2016-10-10 17:13:46,766 main DEBUG createAppenderRef(ref="DailyRoll", level="null", Filter=null) 2016-10-10 17:13:46,766 main DEBUG Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger]. 2016-10-10 17:13:46,767 main DEBUG createLogger(additivity="null", level="TRACE", includeLocation="null", ={DailyRoll}, ={}, Configuration(/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml), Filter=null) 2016-10-10 17:13:46,769 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin]. 2016-10-10 17:13:46,770 main DEBUG createLoggers(={root}) 2016-10-10 17:13:46,770 main DEBUG Configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] initialized 2016-10-10 17:13:46,770 main DEBUG Starting configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] 2016-10-10 17:13:46,771 main DEBUG Started configuration XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] OK. 2016-10-10 17:13:46,771 main TRACE Stopping org.apache.logging.log4j.core.config.DefaultConfiguration@76ccd017... 2016-10-10 17:13:46,772 main TRACE DefaultConfiguration notified 1 ReliabilityStrategies that config will be stopped. 2016-10-10 17:13:46,772 main TRACE DefaultConfiguration stopping root LoggerConfig. 2016-10-10 17:13:46,772 main TRACE DefaultConfiguration notifying ReliabilityStrategies that appenders will be stopped. 2016-10-10 17:13:46,772 main TRACE DefaultConfiguration stopping remaining Appenders. 2016-10-10 17:13:46,772 main DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false-1 2016-10-10 17:13:46,773 main DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true 2016-10-10 17:13:46,773 main TRACE DefaultConfiguration stopped 1 remaining Appenders. 2016-10-10 17:13:46,773 main TRACE DefaultConfiguration cleaning Appenders from 1 LoggerConfigs. 2016-10-10 17:13:46,773 main DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@76ccd017 OK 2016-10-10 17:13:46,816 main TRACE Reregistering MBeans after reconfigure. Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@1bd4fdd 2016-10-10 17:13:46,817 main TRACE Reregistering context (1/1): '2a139a55' org.apache.logging.log4j.core.LoggerContext@55183b20 2016-10-10 17:13:46,818 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55' 2016-10-10 17:13:46,819 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=StatusLogger' 2016-10-10 17:13:46,819 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=ContextSelector' 2016-10-10 17:13:46,820 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=*' 2016-10-10 17:13:46,820 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=*' 2016-10-10 17:13:46,820 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncAppenders,name=*' 2016-10-10 17:13:46,821 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncLoggerRingBuffer' 2016-10-10 17:13:46,821 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=*,subtype=RingBuffer' 2016-10-10 17:13:46,823 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55 2016-10-10 17:13:46,825 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=StatusLogger 2016-10-10 17:13:46,826 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=ContextSelector 2016-10-10 17:13:46,827 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=Loggers,name= 2016-10-10 17:13:46,829 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=Console 2016-10-10 17:13:46,830 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=MyFile 2016-10-10 17:13:46,830 main DEBUG Registering MBean org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=DailyRoll 2016-10-10 17:13:46,832 main TRACE Using default SystemClock for timestamps. 2016-10-10 17:13:46,832 main TRACE Using DummyNanoClock for nanosecond timestamps. 2016-10-10 17:13:46,832 main DEBUG Reconfiguration complete for context[name=2a139a55] at URI /Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml (org.apache.logging.log4j.core.LoggerContext@55183b20) with optional ClassLoader: null 2016-10-10 17:13:46,832 main DEBUG Shutdown hook enabled. Registering a new one. 2016-10-10 17:13:46,833 main DEBUG LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@55183b20] started OK. Debug Log menu item clicked; Logging is now true 2016-10-10 23:59:59,188 Log4j2-TF-3-Scheduled-2 TRACE DefaultRolloverStrategy.purge() took 53.0 milliseconds 2016-10-10 23:59:59,191 Log4j2-TF-3-Scheduled-2 DEBUG RollingFileManager executing synchronous FileRenameAction[/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log to /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/11 - Launcher-3.log, renameEmptyFiles=false] 2016-10-10 23:59:59,204 Log4j2-TF-3-Scheduled-2 TRACE Renamed file /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log to /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/11 - Launcher-3.log with Files.move 2016-10-11 00:00:00,015 Log4j2-TF-3-Scheduled-1 TRACE DefaultRolloverStrategy.purge() took 6.0 milliseconds 2016-10-11 00:00:00,016 Log4j2-TF-3-Scheduled-1 DEBUG RollingFileManager executing synchronous FileRenameAction[/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log to /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/10 - Launcher-1.log, renameEmptyFiles=false] 2016-10-11 08:38:47,589 pool-1-thread-1 DEBUG Stopping LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@55183b20] 2016-10-11 08:38:47,589 pool-1-thread-1 DEBUG Stopping LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@55183b20]... 2016-10-11 08:38:47,590 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55] 2016-10-11 08:38:47,590 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=StatusLogger] 2016-10-11 08:38:47,590 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=ContextSelector] 2016-10-11 08:38:47,590 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=] 2016-10-11 08:38:47,591 pool-1-thread-1 TRACE Unregistering 3 MBeans: [org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=MyFile, org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=Console, org.apache.logging.log4j2:type=2a139a55,component=Appenders,name=DailyRoll] 2016-10-11 08:38:47,591 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncAppenders,name=*' 2016-10-11 08:38:47,591 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=AsyncLoggerRingBuffer' 2016-10-11 08:38:47,591 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=2a139a55,component=Loggers,name=*,subtype=RingBuffer' 2016-10-11 08:38:47,592 pool-1-thread-1 TRACE Stopping XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml]... 2016-10-11 08:38:47,592 pool-1-thread-1 TRACE XmlConfiguration notified 2 ReliabilityStrategies that config will be stopped. 2016-10-11 08:38:47,592 pool-1-thread-1 TRACE XmlConfiguration stopping 1 LoggerConfigs. 2016-10-11 08:38:47,592 pool-1-thread-1 TRACE XmlConfiguration stopping root LoggerConfig. 2016-10-11 08:38:47,592 pool-1-thread-1 TRACE XmlConfiguration notifying ReliabilityStrategies that appenders will be stopped. 2016-10-11 08:38:47,592 pool-1-thread-1 TRACE XmlConfiguration stopping remaining Appenders. 2016-10-11 08:38:47,592 pool-1-thread-1 DEBUG Shutting down RollingFileManager /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log 2016-10-11 08:38:47,598 pool-1-thread-1 DEBUG Shut down RollingFileManager /Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs/apache/2016/10 - Oct/Launcher.log, all resources released: true 2016-10-11 08:38:47,598 pool-1-thread-1 DEBUG Shutting down FileManager logs/artdept.log 2016-10-11 08:38:47,598 pool-1-thread-1 DEBUG Shut down FileManager logs/artdept.log, all resources released: true 2016-10-11 08:38:47,598 pool-1-thread-1 DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false 2016-10-11 08:38:47,598 pool-1-thread-1 DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false, all resources released: true 2016-10-11 08:38:47,598 pool-1-thread-1 TRACE XmlConfiguration stopped 3 remaining Appenders. 2016-10-11 08:38:47,599 pool-1-thread-1 TRACE XmlConfiguration cleaning Appenders from 2 LoggerConfigs. 2016-10-11 08:38:47,599 pool-1-thread-1 DEBUG Log4j2 ConfigurationScheduler shutting down threads in java.util.concurrent.ScheduledThreadPoolExecutor@d1f9106[Running, pool size = 2, active threads = 0, queued tasks = 2, completed tasks = 1851] 2016-10-11 08:38:47,599 pool-1-thread-1 DEBUG Stopped XmlConfiguration[location=/Users/apache/Dropbox/eclipse/workspace/ArtDept/bin/log4j2.xml] OK 2016-10-11 08:38:47,600 pool-1-thread-1 DEBUG Stopped LoggerContext[name=2a139a55, org.apache.logging.log4j.core.LoggerContext@55183b20]...
It seems to want to rollover twice. The first rollover works, but then the second one does not. Moreover, the first one is assigning the new day's date to the rolled-over log file, which I don't want. Since all of the logs inside it are from the 10th of October, the filename should begin with 10 - Launcher, not 11 - Launcher.
This isn't that big of an issue, however, and is one we can live with; but it certainly would be nice to have it name the file appropriate to its contents. The more important issue is the exceptions that occur, which I mentioned earlier.
For reference, the code in my ArtDept.java file on line 85 (as seen in the exception violation lines in the stacktrace above) is just a simple field declaration & initialization:
static final Logger log = LogManager.getLogger(ArtDept.class.getName());
Finally, for reference, my log4j2.xml file:
<?xml version="1.0" encoding="UTF-8"?> <Configuration status="TRACE" monitorInterval="30"> <Properties> <Property name="filename">logs/artdept.log</Property> <Property name="baseDir">/Volumes/ArtDept/ArtDept/Scripts/sky-artdept/logs</Property> </Properties> <Appenders> <Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/> </Console> <File name="MyFile" fileName="${filename}"> <PatternLayout> <pattern>%d %p %C{1.} [%t] %m%n</pattern> </PatternLayout> </File> <RollingFile name="DailyRoll" fileName="${baseDir}/${env:USER}/${date:yyyy}/${date:MM} - ${date:MMM}/Launcher.log" filePattern="${baseDir}/${env:USER}/${date:yyyy}/${date:MM} - ${date:MMM}/%d{dd} - Launcher-%i.log"> <PatternLayout> <Pattern>%d %p %C{1.} [%t] %m%n</Pattern> </PatternLayout> <Policies> <CronTriggeringPolicy schedule="0 0 0 * * ?" evaluateOnStartup="true" /> <SizeBasedTriggeringPolicy size="250 MB" /> </Policies> </RollingFile> </Appenders> <Loggers> <Root level="trace"> <AppenderRef ref="DailyRoll"/> </Root> </Loggers> </Configuration>
EDIT: Provided some more detailed info and more detailed stacktraces.
EDIT 2: Provided a third stacktrace to show an unusual file renaming issue. (Possibly unrelated?)
Attachments
Issue Links
- Is contained by
-
LOG4J2-1653 CronTriggeringPolicy uses wrong naming and produces NPE
- Resolved
- is related to
-
LOG4J2-1653 CronTriggeringPolicy uses wrong naming and produces NPE
- Resolved