[
https://issues.apache.org/jira/browse/LOG4J2-1849?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15922839#comment-15922839
]
shishir chaturvedi edited comment on LOG4J2-1849 at 3/13/17 8:01 PM:
---------------------------------------------------------------------
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 clearly aforementioned behaviors. Please let
me know your thoughts. I would be more than happy to make any contributions for
improving it.
Thanks,
Shishir.
was (Author: shishirchaturvedi):
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-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
