[jira] [Commented] (LOG4J2-1849) Broken FixedDateFormat tests when daylight saving time starts

["shishir chaturvedi (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/LOG4J2-1849?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15922839#comment-15922839 ] 

shishir chaturvedi commented on LOG4J2-1849:
--------------------------------------------

We faced time lag while using log4j2 loggers on 03/12/2017. Log4j2 loggers were lagging 1 hour behind in log messages. This was auto corrected today(03/13/2017). I would share my findings here. 
Seems like the way FixedDateFormat is formatting the time is based on systemMillis/calcMidnightMillis is not correct. Ideally, it should consider the default Timezone. Here is my analysis of these two date patterns,
{code}
Scenario 1 - %d{DATE}
Scenario 2 - %d{dd MMM yyyy HH:mm:ss,sss} 
{code}

*Scenario 1 :*
{code:xml}
Use default literal date pattern : %d{DATE}
Log4j2 Configuration
<Property name="appenderPatternLayout">[%t] %d{DATE} %-5p %-15c{1} [%X]: %cm%n
{code}

In this log4j2 configuration, log4j2 creates a default FixedDateFormat. This class uses base reference time as midnight and all the time-based calculations are done with respect to this base time. This class is not TimeZone aware. 

These are the code snippets and class references,
{code}
org.apache.logging.log4j.core.util.datetime.FixedDateFormat#calcMidnightMillis
 - uses Calendar.getInstance()
org.apache.logging.log4j.core.util.datetime.FixedDateFormat#format(long, char[], int)

  public int format(final long time, final char[] buffer, final int startPos) {
        // Calculate values by getting the ms values first and do then
        // calculate the hour minute and second values divisions.

        // Get daytime in ms: this does fit into an int
        // int ms = (int) (time % 86400000);
        final int ms = (int) (millisSinceMidnight(time));
        writeDate(buffer, startPos);
        return writeTime(ms, buffer, startPos + dateLength) - startPos;
    }

// Profiling showed this method is important to log4j performance. Modify with care!
    // 30 bytes (allows immediate JVM inlining: <= -XX:MaxInlineSize=35 bytes)
    private long millisSinceMidnight(final long now) {
        if (now >= midnightTomorrow || now < midnightToday) {
            updateMidnightMillis(now);
        }
        return now - midnightToday;
    }
{code}


***

*Scenario 2 :*

**This approach worked for us **

{code}
Use specific date pattern : %d{dd MMM yyyy HH:mm:ss,sss}
Log4j2 Configuration
	<Property name="appenderPatternLayout">[%t] %d{dd MMM yyyy HH:mm:ss,sss} %-5p %-15c{1} [%X]: %cm%n
{code}

In this log4j2 configuration, the date-formatter is calculated based on the date pattern configured in log4j2 configuration file. This forces Log4j2 to dynamically evaluate correct date-formatter. Also, it is timezone aware and will use default timezone from system timezone.

Please refer this code snippet,

{code}

org.apache.logging.log4j.core.util.datetime.FormatCache#getInstance(java.lang.String, java.util.TimeZone, java.util.Locale)

public F getInstance(final String pattern, TimeZone timeZone, Locale locale) {
        if (pattern == null) {
            throw new NullPointerException("pattern must not be null");
        }
        if (timeZone == null) {
            timeZone = TimeZone.getDefault();
        }
        if (locale == null) {
            locale = Locale.getDefault();
        }
        final MultipartKey key = new MultipartKey(pattern, timeZone, locale);
        F format = cInstanceCache.get(key);
        if (format == null) {
            format = createInstance(pattern, timeZone, locale);
            final F previousValue = cInstanceCache.putIfAbsent(key, format);
            if (previousValue != null) {
                // another thread snuck in and did the same work
                // we should return the instance that is in ConcurrentMap
                format = previousValue;
            }
        }
        return format;
    }
{code}

Log42 document also does not state it clearly elaborate aforementioned behaviors. Please let me know your thoughts. I would be more than happy to make any contributions for improving it.
Thanks,
Shishir.

> Broken FixedDateFormat tests when daylight saving time starts
> -------------------------------------------------------------
>
>                 Key: LOG4J2-1849
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-1849
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Core
>    Affects Versions: 2.8.1
>            Reporter: Matt Sicker
>
> Today we started daylight saving time in the US, and the following tests failed:
> {noformat}
> Failed tests:
>   FixedDateFormatTest.testFormatLong:162 ABSOLUTE(HH:mm:ss,SSS)/1489305608119 expected:<0[3]:00:08,119> but was:<0[2]:00:08,119>
>   FixedDateFormatTest.testFormatLongCharArrayInt:196 ABSOLUTE(HH:mm:ss,SSS)/1489305607930 expected:<0[3]:00:07,930> but was:<0[2]:00:07,930>
>   FixedDateFormatTest.testFormatLongCharArrayInt_goingBackInTime:214 ABSOLUTE(HH:mm:ss,SSS)/1489381194091 expected:<2[3]:59:54,091> but was:<2[2]:59:54,091>
>   FixedDateFormatTest.testFormatLong_goingBackInTime:178 ABSOLUTE(HH:mm:ss,SSS)/1489381194072 expected:<2[3]:59:54,072> but was:<2[2]:59:54,072>
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.3.15#6346)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org