`FixedDateFormat` incorrectly calculates DST for `America/Santiago` time zone

[Raghu-icon]

Description

After DST time change in Chile , the logs are not showing the correct time with plain %d date pattern on September 8th but after midnight of 9th September the logs are printing correct date without having to change anything but when we use date format with time zone it shows correct date on 8th September also .

Configuration

Version: 2.24

Operating system: RHEL

JDK: openJDK17

Logs

[Stacktraces, errors, etc. relevant applications logs.]

Reproduction

[An isolated test reproducing the test. JUnit tests similar to the ones in the code base are extremely appreciated.]

Here’s the steps to reproduce it:

1. Set the date on the server to September 8, with the time any time after 2am.
2. Use a plain %d date format in log4j config file .

Here is the java code and config file : import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import java.util.TimeZone;

public class SimpleLog4jExample {

// Create a logger instance
private static final Logger logger = LogManager.getLogger(SimpleLog4jExample.class);

public static void main(String[] args) {
    // Log messages of different levels
     String tzid = "America/Santiago";
   // tzid = readln("Enter time zone ID [" + tzid + "]: ", tzid);
    TimeZone tz = TimeZone.getTimeZone(tzid);
    TimeZone.setDefault(tz);
    logger.info("This is an info message");
    logger.warn("This is a warning message");
    logger.error("This is an error message");
}

}

log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>

[ppkarwasz]

@Raghu-icon,

This is probably a JDK or operating system update problem. Do you have the latest version of JDK 17? Some countries have stable daylight saving time rules and the JDK and operating system know them for years in advance. Other countries decide the dates of the change between winter and summer time at the last moment and you need for that data to be included in the JDK and OS.

[Raghu-icon]

@ppkarwasz Thank you for the response . When we print the time in Java program / date command in RHEL both shows correct the date with DST change , but the log timestamp is incorrect . Additionally when we use the date format , its showing correct date .

[ppkarwasz]

Can you show us your configuration file?

[Raghu-icon]

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d %-5p %c{1}:%L - %m%n"/>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="Console"/>
        </Root>
    </Loggers>
</Configuration>

[ppkarwasz]

@Raghu-icon,

When you use %d Log4j uses a very performant FixedDateFormatter, which computes the "date" part of a timestamp only once a day and caches it. The class is DST-aware and thoroughly tested, but we might have missed some edge case. Can you tell us:

• The exact day and hour DST started in Chile this year?
• Which part of the timestamp was wrong: did the "date" part fail to be updated when DST started or did the "time" part fail to switch?

Even better, could your provide a test case? The test cases for America/Chicago are in FixedDateFormatter.

[Raghu-icon]

1) Chile DST changes were applied on 8th September 2024 00:00 hours . 2) The timestamp part was incorrect on 8th September , its still uses earlier timestamp , and importantly this issue is only on 8th September , once the time reached to 9th September 00:00 hours , it automatically started printing correct timestamp accounting the DST .

As of now I have this simple java class to reproduce the issue . Please note to reproduce this you have to change the system date / time to 8th September midnight to 9th September midnight . If you require test case I may need some time . Thanks you !

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import java.util.TimeZone;

public class SimpleLog4jExample {

// Create a logger instance
private static final Logger logger = LogManager.getLogger(SimpleLog4jExample.class);

public static void main(String[] args) {
    // Log messages of different levels
     String tzid = "America/Santiago";
   // tzid = readln("Enter time zone ID [" + tzid + "]: ", tzid);
    TimeZone tz = TimeZone.getTimeZone(tzid);
    TimeZone.setDefault(tz);
    logger.info("This is an info message");
    logger.warn("This is a warning message");
    logger.error("This is an error message");
}

[ppkarwasz]

I confirmed the bug using two additional test cases in our FixedDateFormatTest:

https://github.com/apache/logging-log4j2/blob/ef34c994febbc75ea008786432d912dbaf5b1eb1/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormatTest.java#L280-L308

The modified test is available in the fix/2.x/2943_dst_on_midnight branch. We have quite a lot on our TODO list right now, but we'll try to dig into it before the next DST change.

We are of course happy if someone can provide a PR.

[vy]

Yet another FixedDateFormat DST failure:

• Time zone: America/Jujuy
• Instant: 657122073.258197325
• Pattern: HH:mm:ss,SSSSSS
• Expected: 10:54:33,258197
• Output: 09:54:33,258197

[ppkarwasz]

This seems to follow the same pattern as America/Santiago: if the change occurs at midnight local time, the FixedDateFormat caching is off.