[LOG4J2-1640] RollingFileAppender with CronTriggeringPolicy broken? - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Fixed
Affects Version/s: 2.7
Fix Version/s: 2.8
Component/s: Core
Labels:
Environment:

Mac OS X 10.11.6 running Eclipse Neon 4.6.0 with JDK 1.8.0_74

Flags:

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:

ArtDept.java

static final Logger log = LogManager.getLogger(ArtDept.class.getName());

Finally, for reference, my log4j2.xml file:

log4j2.xml

<?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

Activity

People

Assignee:: Unassigned

Reporter:: Chris McGee

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 10/Oct/16 12:57

Updated:: 18/Jan/17 15:20

Resolved:: 09/Jan/17 16:20