[LOG4J2-1649] CronTriggeringPolicy breaks awefully when using "reconfigure" of LoggerContext

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 2.7
• Fix Version/s: 2.8
• Flags: Patch
• Assignee: Ralph Goers
• Reporter: Georg Friedrich
• Created: 24/Oct/16 13:49
• Updated: 09/Jan/17 07:08
• Resolved: 09/Jan/17 07:08

Description

Hi,
I've a major problem when using CronTriggeringPolicy in Spring Boot environments.
I've tracked the problem down to Log4J2.
The following is happening:

• When the Spring context is created, getContext is called which results in creation on the Log4J context and the cron trigger is registered as normal
• After that Spring starts a reinitialization of the LoggerSystem by calling "reconfigure" of the LoggerContext of Log4J.
• This results in very weird behvaiour of Log4J:
  • Log4J finds the already created RollingFileManager in the "MAP" field in the AbstractManager class.
  • As it was already available it calls the "updateData" which in result registers the trigger again.
  • After that the "initialize" method is called on the RollingFileManager, which again registers the trigger. (The cron trigger is now scheduled 3 times! First time by the normal getContext initialization and two times more by the reconfiguration)

The good thing is: As the old configuration gets destroyed, the old scheduler is being shutdown too, but the last schedule of the first cron trigger is called nevertheless.

So basically you get 3 cron trigger calls, where 2 of them are rescheduled.

How it should be fixed (from my point of view):

• Kill old CronTriggers from scheduling when the context gets reconfigured
• Do not call initialize for the triggering policy when the RollingFileManager is updated as this is done afterwards nevertheless

Issue Links

• is related to: LOG4J2-1653 CronTriggeringPolicy uses wrong naming and produces NPE