You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Peter Steele <ps...@maxiscale.com> on 2008/10/19 22:12:27 UTC
Timestamps and time zones
We've noticed somewhat undersirable logging behavior when we change the
time zone our appllicaton is running under. When the application starts,
the timestamps used in our log files match the current local time,
albeit without an explicit time zone identifier included in the time,
but that's okay. However, if we change the time zone, e.g. from 8:00 am
PDT to 8:00 am EDT, while the local time simply starts displaying the
new time zone identifier, the log timestamps get shifted by the
difference in the time zones. In this specific case, the log timestamps
would get shifted to 5:00 am.
If we then stop and restart the application, the timestamps are then
based again on the local time (8:00 am instead of 5:00 am). This is what
we want of course, but we want this to happen dynamically as well and
not have to restart the application to get the timestamps in sync with
the local time. How can we accomplish this? We want the timestamps to
match whatever the local time is, regardless of the time zone, even
after a time zone change. Is there a logger call we can make?
RE: Timestamps and time zones
Posted by Peter Steele <ps...@maxiscale.com>.
>Shouldn't need to build log4j just extras. I filed a bug (46046) and
>committed the early changes. If there is a problem, we can back it
>out. To build, download Maven 2.0.9 from http://maven.apache.org/ and
>unzip and place on path. After that, building extras should be as
>simple as:
>
>svn co
http://svn.apache.org/repos/asf/logging/log4j/companions/extras/trunk
extras
>cd extras
>maven package
That did the trick. I installed the extras companion on one of the
systems in our distributed cluster and changed the log4j xml file to use
the EnhancedPatternLayout instead of PatternLayout. I didn't make any
other change to the actual pattern. I left the other systems untouched.
I then run up the GUI and changed the time zone. The system using the
EnhancedPatternLayout kept in sync with local time whereas the other
systems did not. Keeping the timestamps in sync with local time is the
behavior we're looking for.
Thanks very much for the help. This will make QA very happy. :-)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Timestamps and time zones
Posted by Curt Arnold <ca...@apache.org>.
On Oct 20, 2008, at 5:19 PM, Peter Steele wrote:
>> The following patch to the extras companion should allow
>> an %d pattern in an EnhancedPatternLayout without a explicit timezone
>> to follow changes to the default timezone without an undue
>> performance
>
>> hit. The timezone should be updated at most once a second, since
>> CachedDateFormat should handle the more frequent calls. I've run
>> the
>
>> standard unit tests against it and it didn't break anything, but I
>> haven't attempted to test it while changing the system timezone.
>>
>> I'd appreciate your feedback. If the works for you, we could
>> consider
>
>> this for the next release of the extras companion.
>
> I'll give this a try. I've never built log4j from src before, which
> means
> I've never tried this companions module before either. I'll see what I
> can
> do to get a new jar file build with your patched code and then give
> it a
> try in our app. Thanks for the help.
Shouldn't need to build log4j just extras. I filed a bug (46046) and
committed the early changes. If there is a problem, we can back it
out. To build, download Maven 2.0.9 from http://maven.apache.org/ and
unzip and place on path. After that, building extras should be as
simple as:
svn co http://svn.apache.org/repos/asf/logging/log4j/companions/extras/trunk
extras
cd extras
maven package
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
RE: Timestamps and time zones
Posted by Peter Steele <ps...@maxiscale.com>.
>The following patch to the extras companion should allow
>an %d pattern in an EnhancedPatternLayout without a explicit timezone
>to follow changes to the default timezone without an undue performance
>hit. The timezone should be updated at most once a second, since
>CachedDateFormat should handle the more frequent calls. I've run the
>standard unit tests against it and it didn't break anything, but I
>haven't attempted to test it while changing the system timezone.
>
>I'd appreciate your feedback. If the works for you, we could consider
>this for the next release of the extras companion.
I'll give this a try. I've never built log4j from src before, which
means
I've never tried this companions module before either. I'll see what I
can
do to get a new jar file build with your patched code and then give it a
try in our app. Thanks for the help.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Timestamps and time zones
Posted by Curt Arnold <ca...@apache.org>.
On Oct 20, 2008, at 1:39 PM, Peter Steele wrote:
>> If you are changing from 8:00 AM PDT to 8:00 AM EDT, you are not just
>> changing the time zone, but you are also changing the time.
>
> Yes, that's correct, both the time zone and time are being set in one
> operation.
>
>> Are you changing the timezone using a operating system utility
>> (control panel etc) or by using a call to TimeZone.setDefault()?
>
> We are using TimeZone.setDefault(). The user sets the time and time
> zone
> in our
> GUI and hits an Apply button to invoke the change.
>
>> Different JVM's may have different approaches to how a change in the
>> operating system timezone becomes visible in the JDK. If the JDK
>> only
>
>> checks the default timezone at start up, there is nothing log4j can
>> do. Knowing the vendor and version of the OS and JVM in use and the
>> exact method of making the timezone change would be helpful to
>> understand your observed behavior. It does appear that you are
>> seeing
>
>> an immediate effect from changing the time, but the timezone is not
>> immediately updated in the app by the manner you are making the
>> change.
>
> We are using JDK 1.5 on FreeBSD 7.0. The code we execute does take
> immediate effect
> on the system itself as far as the local time is concerned, e.g., the
> date command
> shows the same date/time/time zone as the user sets in the GUI. The
> logger timestamps
> however still show the time in the original time zone.
>
>> I'd suggest using the EnhancedPatternLayout in the extras companion
>> and output the time in a fixed timezone. Something like:
>>
>> %d{yyyy-MM-dd HH:mm:ss}{UTC}Z - %c - %m%n
>>
>> You could also output the time in local time for convenience, but
>> you'd always have the time in a known timezone.
>
> I will check this out but I'm not sure if it will solve the problem.
> Ideally, when we
> change the time from say 8:00 PDT to 8:00 EDT, we'd like the log
> timestamps to also
> show 8:00, but what we get is 5:00, at least until we restart the
> application. We could
> add the explicit time zone but will it just end up showing 5:00 EDT
> instead of 8:00 EDT?
> Is there a log4j function we could call to force it to resync with the
> current local time,
> similar to what it must be doing when an application starts?
>
>
When the PatternLayout is created during configuration, an instance of
java.text.SimpleDateFormat (or a log4j-provided DateFormat if you
specify %d{ISO8601} or similar) and this format is used for the
lifetime of PatternLayout. java.text.SimpleDateFormat apparently
caches the default timezone at the time of creation (at least in your
JDK's implementation) and does not monitor any subsequent changes.
Date formatting can be a time consuming part of logging. log4j 1.2
has a decent amount code (problematic code though) to cache the
results of previous format requests for potential reuse. The caching
and design is much cleaner in the EnhancedPatternLayout in the extras
companion. The following patch to the extras companion should allow
an %d pattern in an EnhancedPatternLayout without a explicit timezone
to follow changes to the default timezone without an undue performance
hit. The timezone should be updated at most once a second, since
CachedDateFormat should handle the more frequent calls. I've run the
standard unit tests against it and it didn't break anything, but I
haven't attempted to test it while changing the system timezone.
I'd appreciate your feedback. If the works for you, we could consider
this for the next release of the extras companion.
Index: src/main/java/org/apache/log4j/pattern/DatePatternConverter.java
===================================================================
--- src/main/java/org/apache/log4j/pattern/DatePatternConverter.java
(revision 702979)
+++ src/main/java/org/apache/log4j/pattern/DatePatternConverter.java
(working copy)
@@ -21,6 +21,9 @@
import org.apache.log4j.spi.LoggingEvent;
import java.text.SimpleDateFormat;
+import java.text.DateFormat;
+import java.text.FieldPosition;
+import java.text.ParsePosition;
import java.util.Date;
import java.util.TimeZone;
@@ -63,6 +66,41 @@
*/
private final CachedDateFormat df;
+ /**
+ * This class wraps a DateFormat and forces the time zone to the
+ * default time zone before each format and parse request.
+ */
+ private class DefaultZoneDateFormat extends DateFormat {
+ /**
+ * Wrapped instance of DateFormat.
+ */
+ private final DateFormat dateFormat;
+
+ /**
+ * Construct new instance.
+ * @param format format, may not be null.
+ */
+ public DefaultZoneDateFormat(final DateFormat format) {
+ dateFormat = format;
+ }
+
+ /**
+ * @{inheritDoc}
+ */
+ public StringBuffer format(Date date, StringBuffer toAppendTo,
FieldPosition fieldPosition) {
+ dateFormat.setTimeZone(TimeZone.getDefault());
+ return dateFormat.format(date, toAppendTo, fieldPosition);
+ }
+
+ /**
+ * @{inheritDoc}
+ */
+ public Date parse(String source, ParsePosition pos) {
+ dateFormat.setTimeZone(TimeZone.getDefault());
+ return dateFormat.parse(source, pos);
+ }
+ }
+
/**
* Private constructor.
* @param options options, may be null.
@@ -95,7 +133,7 @@
}
int maximumCacheValidity = 1000;
- SimpleDateFormat simpleFormat = null;
+ DateFormat simpleFormat = null;
try {
simpleFormat = new SimpleDateFormat(pattern);
@@ -113,6 +151,8 @@
if ((options != null) && (options.length > 1)) {
TimeZone tz = TimeZone.getTimeZone((String) options[1]);
simpleFormat.setTimeZone(tz);
+ } else {
+ simpleFormat = new DefaultZoneDateFormat(simpleFormat);
}
df = new CachedDateFormat(simpleFormat, maximumCacheValidity);
as it is and there is a fair bit of logic (much better in the
EnhancedPatternLayout in extras than in log4j) to cache previous
formatted results and reuse them
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
RE: Timestamps and time zones
Posted by Peter Steele <ps...@maxiscale.com>.
>If you are changing from 8:00 AM PDT to 8:00 AM EDT, you are not just
>changing the time zone, but you are also changing the time.
Yes, that's correct, both the time zone and time are being set in one
operation.
>Are you changing the timezone using a operating system utility
>(control panel etc) or by using a call to TimeZone.setDefault()?
We are using TimeZone.setDefault(). The user sets the time and time zone
in our
GUI and hits an Apply button to invoke the change.
>Different JVM's may have different approaches to how a change in the
>operating system timezone becomes visible in the JDK. If the JDK only
>checks the default timezone at start up, there is nothing log4j can
>do. Knowing the vendor and version of the OS and JVM in use and the
>exact method of making the timezone change would be helpful to
>understand your observed behavior. It does appear that you are seeing
>an immediate effect from changing the time, but the timezone is not
>immediately updated in the app by the manner you are making the change.
We are using JDK 1.5 on FreeBSD 7.0. The code we execute does take
immediate effect
on the system itself as far as the local time is concerned, e.g., the
date command
shows the same date/time/time zone as the user sets in the GUI. The
logger timestamps
however still show the time in the original time zone.
>I'd suggest using the EnhancedPatternLayout in the extras companion
>and output the time in a fixed timezone. Something like:
>
>%d{yyyy-MM-dd HH:mm:ss}{UTC}Z - %c - %m%n
>
>You could also output the time in local time for convenience, but
>you'd always have the time in a known timezone.
I will check this out but I'm not sure if it will solve the problem.
Ideally, when we
change the time from say 8:00 PDT to 8:00 EDT, we'd like the log
timestamps to also
show 8:00, but what we get is 5:00, at least until we restart the
application. We could
add the explicit time zone but will it just end up showing 5:00 EDT
instead of 8:00 EDT?
Is there a log4j function we could call to force it to resync with the
current local time,
similar to what it must be doing when an application starts?
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Timestamps and time zones
Posted by Curt Arnold <ca...@apache.org>.
On Oct 19, 2008, at 3:12 PM, Peter Steele wrote:
> We've noticed somewhat undersirable logging behavior when we change
> the
> time zone our appllicaton is running under. When the application
> starts,
> the timestamps used in our log files match the current local time,
> albeit without an explicit time zone identifier included in the time,
> but that's okay. However, if we change the time zone, e.g. from 8:00
> am
> PDT to 8:00 am EDT, while the local time simply starts displaying the
> new time zone identifier, the log timestamps get shifted by the
> difference in the time zones. In this specific case, the log
> timestamps
> would get shifted to 5:00 am.
>
>
> If we then stop and restart the application, the timestamps are then
> based again on the local time (8:00 am instead of 5:00 am). This is
> what
> we want of course, but we want this to happen dynamically as well and
> not have to restart the application to get the timestamps in sync with
> the local time. How can we accomplish this? We want the timestamps to
> match whatever the local time is, regardless of the time zone, even
> after a time zone change. Is there a logger call we can make?
>
If you are changing from 8:00 AM PDT to 8:00 AM EDT, you are not just
changing the time zone, but you are also changing the time. If you
are using a timestamp (milliseconds since the epoch), then they value
would change when you changed the time though it should not be
affected if you just changed the timezone.
Are you changing the timezone using a operating system utility
(control panel etc) or by using a call to TimeZone.setDefault()?
Different JVM's may have different approaches to how a change in the
operating system timezone becomes visible in the JDK. If the JDK only
checks the default timezone at start up, there is nothing log4j can
do. Knowing the vendor and version of the OS and JVM in use and the
exact method of making the timezone change would be helpful to
understand your observed behavior. It does appear that you are seeing
an immediate effect from changing the time, but the timezone is not
immediately updated in the app by the manner you are making the change.
I'd suggest using the EnhancedPatternLayout in the extras companion
and output the time in a fixed timezone. Something like:
%d{yyyy-MM-dd HH:mm:ss}{UTC}Z - %c - %m%n
You could also output the time in local time for convenience, but
you'd always have the time in a known timezone.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org