[LOG4J2-3195] Discrepancy between threads upon default timezone changing.

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Information Provided
• Affects Version/s: 2.13.3
• Component/s: Appenders
• Assignee: Unassigned
• Reporter: Jean-Luc VANNIERE
• Created: 22/Nov/21 19:09
• Updated: 25/Nov/21 00:05
• Resolved: 23/Nov/21 06:07

Description

Let's consider the following use case:

• Start a process with the following layout in the console appender (<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSSZ} %-5p %c (%t) %m%n"/>

• Initialize the logs in a given timezone (eg: Europe/Paris so GMT+0100)
• Log something in a thread #1, 
  logger.info("Before TimeZone switch") -->
  2021-11-22 19:32:09.533+0100 INFO  com.calypso.log.timezone.TestTZ (thread1) Before TimeZone Switch
• Change the defaut timezone (eg to America/New_York so GMT-0500)
• Log something in another thread #2 which has never log so far
  logger.info("After TimeZone switch") --> 
  2021-11-22 13:32:09.534-0500 INFO  com.calypso.log.timezone.TestTZ (thread2) After TimeZone Switch
• Log something in thread #1
  logger.info("After TimeZone switch") --> 
  2021-11-22 19:32:09.535+0100 INFO  com.calypso.log.timezone.TestTZ (thread1) After TimeZone Switch

Thread #1, and any other thread that has logged before the default TimeZone switch, will continue to log in the previous time zone.

Thread #2 (and any other  thread that has not logged priror to the time zone switch), will log in the new time zone.

And some of our customers are complaining about this discrepancy which cause their logs to switch constantly between 2 time zones.

The root cause of this issue is due to the fact that (in DatePatternConverter.formatWithoutAllocation()) the DatePatternConverter records the formatter into a thread-local and this formatter contains the timezone at the moment of its creation. In other words, the first time the thread logs, it creates the formatter with the current timezone and records it into a thread local storage for further reuse. The problem is that if the default timezone change afterwards this latest is ignored by the thread.

A solution would be either not recording the timezone when no timezone is given to the logging, either providing an adapter which extends TimeZone and delegates systematically to the current default timezone (as bellow in DatePatternConverter). That way the date formatter would always use the current default time zone.

private static Formatter createNonFixedFormatter(final String[] options) {
   ....
   // if the option list contains a TZ option, then set it.
   TimeZone tz = null;
   if (options.length > 1 && options[1] != null) {
      tz = TimeZone.getTimeZone(options[1]);
   } 
   else {
      tz = new TimeZoneAdapter(); // set tz to adapter
   }