You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Remko Popma (JIRA)" <ji...@apache.org> on 2018/01/22 14:51:00 UTC
[jira] [Issue Comment Deleted] (LOG4J2-1883) Support precise
timestamps (microsecond and nanosecond level)
[ https://issues.apache.org/jira/browse/LOG4J2-1883?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Remko Popma updated LOG4J2-1883:
--------------------------------
Comment: was deleted
(was: Note to self (please ignore)
{code}
Index: log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java (revision )
+++ log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java (revision )
@@ -284,7 +284,7 @@
public Log4jLogEvent() {
this(Strings.EMPTY, null, Strings.EMPTY, null, null, (Throwable) null, null, null, null, 0, null,
- 0, null, CLOCK.currentTimeMillis(), 0, nanoClock.nanoTime());
+ 0, null, CLOCK, nanoClock.nanoTime());
}
/**
@@ -328,13 +328,12 @@
final Message message, final List<Property> properties, final Throwable t) {
this(loggerName, marker, loggerFQCN, level, message, t, null, createContextData(properties),
ThreadContext.getDepth() == 0 ? null : ThreadContext.cloneStack(), // mutable copy
- 0, // thread name
- null, // stack trace element
- 0,
- null, // LOG4J2-628 use log4j.Clock for timestamps
- // LOG4J2-744 unless TimestampMessage already has one
- message instanceof TimestampMessage ? ((TimestampMessage) message).getTimestamp() :
- CLOCK.currentTimeMillis(), 0, nanoClock.nanoTime());
+ 0, // thread id
+ null, // thread name
+ 0, // thread priority
+ null, // StackTraceElement source
+ CLOCK, //
+ nanoClock.nanoTime());
}
/**
@@ -415,6 +414,29 @@
final StringMap contextData, final ThreadContext.ContextStack contextStack, final long threadId,
final String threadName, final int threadPriority, final StackTraceElement source,
final long timestampMillis, final int nanoOfMillisecond, final long nanoTime) {
+ this(loggerName, marker, loggerFQCN, level, message, thrown, thrownProxy, contextData, contextStack, threadId, threadName, threadPriority, source, nanoTime);
+ long millis = message instanceof TimestampMessage
+ ? ((TimestampMessage) message).getTimestamp()
+ : timestampMillis;
+ this.instant.initFromEpochMilli(millis, nanoOfMillisecond);
+ }
+ private Log4jLogEvent(final String loggerName, final Marker marker, final String loggerFQCN, final Level level,
+ final Message message, final Throwable thrown, final ThrowableProxy thrownProxy,
+ final StringMap contextData, final ThreadContext.ContextStack contextStack, final long threadId,
+ final String threadName, final int threadPriority, final StackTraceElement source,
+ final Clock clock, final long nanoTime) {
+ this(loggerName, marker, loggerFQCN, level, message, thrown, thrownProxy, contextData, contextStack, threadId, threadName, threadPriority, source, nanoTime);
+ if (message instanceof TimestampMessage) {
+ instant.initFromEpochMilli(((TimestampMessage) message).getTimestamp(), 0);
+ } else {
+ instant.initFrom(clock);
+ }
+ }
+ private Log4jLogEvent(final String loggerName, final Marker marker, final String loggerFQCN, final Level level,
+ final Message message, final Throwable thrown, final ThrowableProxy thrownProxy,
+ final StringMap contextData, final ThreadContext.ContextStack contextStack, final long threadId,
+ final String threadName, final int threadPriority, final StackTraceElement source,
+ final long nanoTime) {
this.loggerName = loggerName;
this.marker = marker;
this.loggerFqcn = loggerFQCN;
@@ -424,10 +446,6 @@
this.thrownProxy = thrownProxy;
this.contextData = contextData == null ? ContextDataFactory.createContextData() : contextData;
this.contextStack = contextStack == null ? ThreadContext.EMPTY_STACK : contextStack;
- long millis = message instanceof TimestampMessage
- ? ((TimestampMessage) message).getTimestamp()
- : timestampMillis;
- this.instant.initFromEpochMilli(millis, nanoOfMillisecond);
this.threadId = threadId;
this.threadName = threadName;
this.threadPriority = threadPriority;
@@ -437,7 +455,6 @@
}
this.nanoTime = nanoTime;
}
-
private static StringMap createContextData(final Map<String, String> contextMap) {
final StringMap result = ContextDataFactory.createContextData();
if (contextMap != null) {
Index: log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormat.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormat.java (revision )
+++ log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormat.java (revision )
@@ -43,73 +43,73 @@
/**
* ABSOLUTE time format: {@code "HH:mm:ss,SSS"}.
*/
- ABSOLUTE("HH:mm:ss,SSS", null, 0, ':', 1, ',', 1),
+ ABSOLUTE("HH:mm:ss,SSS", null, 0, ':', 1, ',', 1, 3),
/**
* ABSOLUTE time format with microsecond precision: {@code "HH:mm:ss,nnnnnn"}.
*/
- ABSOLUTE_MICROS("HH:mm:ss,nnnnnn", null, 0, ':', 1, ',', 1),
+ ABSOLUTE_MICROS("HH:mm:ss,nnnnnn", null, 0, ':', 1, ',', 1, 6),
/**
* ABSOLUTE time format with nanosecond precision: {@code "HH:mm:ss,nnnnnnnnn"}.
*/
- ABSOLUTE_NANOS("HH:mm:ss,nnnnnnnnn", null, 0, ':', 1, ',', 1),
+ ABSOLUTE_NANOS("HH:mm:ss,nnnnnnnnn", null, 0, ':', 1, ',', 1, 9),
/**
* ABSOLUTE time format variation with period separator: {@code "HH:mm:ss.SSS"}.
*/
- ABSOLUTE_PERIOD("HH:mm:ss.SSS", null, 0, ':', 1, '.', 1),
+ ABSOLUTE_PERIOD("HH:mm:ss.SSS", null, 0, ':', 1, '.', 1, 3),
/**
* COMPACT time format: {@code "yyyyMMddHHmmssSSS"}.
*/
- COMPACT("yyyyMMddHHmmssSSS", "yyyyMMdd", 0, ' ', 0, ' ', 0),
+ COMPACT("yyyyMMddHHmmssSSS", "yyyyMMdd", 0, ' ', 0, ' ', 0, 3),
/**
* DATE_AND_TIME time format: {@code "dd MMM yyyy HH:mm:ss,SSS"}.
*/
- DATE("dd MMM yyyy HH:mm:ss,SSS", "dd MMM yyyy ", 0, ':', 1, ',', 1),
+ DATE("dd MMM yyyy HH:mm:ss,SSS", "dd MMM yyyy ", 0, ':', 1, ',', 1, 3),
/**
* DATE_AND_TIME time format variation with period separator: {@code "dd MMM yyyy HH:mm:ss.SSS"}.
*/
- DATE_PERIOD("dd MMM yyyy HH:mm:ss.SSS", "dd MMM yyyy ", 0, ':', 1, '.', 1),
+ DATE_PERIOD("dd MMM yyyy HH:mm:ss.SSS", "dd MMM yyyy ", 0, ':', 1, '.', 1, 3),
/**
* DEFAULT time format: {@code "yyyy-MM-dd HH:mm:ss,SSS"}.
*/
- DEFAULT("yyyy-MM-dd HH:mm:ss,SSS", "yyyy-MM-dd ", 0, ':', 1, ',', 1),
+ DEFAULT("yyyy-MM-dd HH:mm:ss,SSS", "yyyy-MM-dd ", 0, ':', 1, ',', 1, 3),
/**
* DEFAULT time format with microsecond precision: {@code "yyyy-MM-dd HH:mm:ss,nnnnnn"}.
*/
- DEFAULT_MICROS("yyyy-MM-dd HH:mm:ss,nnnnnn", "yyyy-MM-dd ", 0, ':', 1, ',', 1),
+ DEFAULT_MICROS("yyyy-MM-dd HH:mm:ss,nnnnnn", "yyyy-MM-dd ", 0, ':', 1, ',', 1, 6),
/**
* DEFAULT time format with nanosecond precision: {@code "yyyy-MM-dd HH:mm:ss,nnnnnnnnn"}.
*/
- DEFAULT_NANOS("yyyy-MM-dd HH:mm:ss,nnnnnnnnn", "yyyy-MM-dd ", 0, ':', 1, ',', 1),
+ DEFAULT_NANOS("yyyy-MM-dd HH:mm:ss,nnnnnnnnn", "yyyy-MM-dd ", 0, ':', 1, ',', 1, 9),
/**
* DEFAULT time format variation with period separator: {@code "yyyy-MM-dd HH:mm:ss.SSS"}.
*/
- DEFAULT_PERIOD("yyyy-MM-dd HH:mm:ss.SSS", "yyyy-MM-dd ", 0, ':', 1, '.', 1),
+ DEFAULT_PERIOD("yyyy-MM-dd HH:mm:ss.SSS", "yyyy-MM-dd ", 0, ':', 1, '.', 1, 3),
/**
* ISO8601_BASIC time format: {@code "yyyyMMdd'T'HHmmss,SSS"}.
*/
- ISO8601_BASIC("yyyyMMdd'T'HHmmss,SSS", "yyyyMMdd'T'", 2, ' ', 0, ',', 1),
+ ISO8601_BASIC("yyyyMMdd'T'HHmmss,SSS", "yyyyMMdd'T'", 2, ' ', 0, ',', 1, 3),
/**
* ISO8601_BASIC time format: {@code "yyyyMMdd'T'HHmmss.SSS"}.
*/
- ISO8601_BASIC_PERIOD("yyyyMMdd'T'HHmmss.SSS", "yyyyMMdd'T'", 2, ' ', 0, '.', 1),
+ ISO8601_BASIC_PERIOD("yyyyMMdd'T'HHmmss.SSS", "yyyyMMdd'T'", 2, ' ', 0, '.', 1, 3),
/**
* ISO8601 time format: {@code "yyyy-MM-dd'T'HH:mm:ss,SSS"}.
*/
- ISO8601("yyyy-MM-dd'T'HH:mm:ss,SSS", "yyyy-MM-dd'T'", 2, ':', 1, ',', 1),
+ ISO8601("yyyy-MM-dd'T'HH:mm:ss,SSS", "yyyy-MM-dd'T'", 2, ':', 1, ',', 1, 3),
/**
* ISO8601 time format: {@code "yyyy-MM-dd'T'HH:mm:ss.SSS"}.
*/
- ISO8601_PERIOD("yyyy-MM-dd'T'HH:mm:ss.SSS", "yyyy-MM-dd'T'", 2, ':', 1, '.', 1);
+ ISO8601_PERIOD("yyyy-MM-dd'T'HH:mm:ss.SSS", "yyyy-MM-dd'T'", 2, ':', 1, '.', 1, 3);
private static final String DEFAULT_SECOND_FRACTION_PATTERN = "SSS";
private static final int MILLI_FRACTION_DIGITS = DEFAULT_SECOND_FRACTION_PATTERN.length();
@@ -122,9 +122,11 @@
private final int timeSeparatorLength;
private final char millisSeparatorChar;
private final int millisSeparatorLength;
+ private final int secondFractionDigits;
FixedFormat(final String pattern, final String datePattern, final int escapeCount, final char timeSeparator,
- final int timeSepLength, final char millisSeparator, final int millisSepLength) {
+ final int timeSepLength, final char millisSeparator, final int millisSepLength,
+ final int secondFractionDigits) {
this.timeSeparatorChar = timeSeparator;
this.timeSeparatorLength = timeSepLength;
this.millisSeparatorChar = millisSeparator;
@@ -132,6 +134,7 @@
this.pattern = Objects.requireNonNull(pattern);
this.datePattern = datePattern; // may be null
this.escapeCount = escapeCount;
+ this.secondFractionDigits = secondFractionDigits;
}
/**
@@ -230,6 +233,14 @@
public FastDateFormat getFastDateFormat(final TimeZone tz) {
return getDatePattern() == null ? null : FastDateFormat.getInstance(getDatePattern(), tz);
}
+
+ /**
+ * Returns the number of digits specifying the fraction of the second to show
+ * @return 3 for millisecond precision, 6 for microsecond precision or 9 for nanosecond precision
+ */
+ public int getSecondFractionDigits() {
+ return secondFractionDigits;
+ }
}
private final FixedFormat fixedFormat;
@@ -264,7 +275,7 @@
* @param tz time zone
*/
FixedDateFormat(final FixedFormat fixedFormat, final TimeZone tz) {
- this(fixedFormat, tz, FixedFormat.DEFAULT_SECOND_FRACTION_PATTERN.length());
+ this(fixedFormat, tz, fixedFormat.getSecondFractionDigits());
}
/**
Index: log4j-core/src/main/java/org/apache/logging/log4j/core/util/Instant.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- log4j-core/src/main/java/org/apache/logging/log4j/core/util/Instant.java (revision )
+++ log4j-core/src/main/java/org/apache/logging/log4j/core/util/Instant.java (revision )
@@ -16,6 +16,8 @@
*/
package org.apache.logging.log4j.core.util;
+import org.apache.logging.log4j.util.StringBuilderFormattable;
+
/**
* Models a point in time, suitable for event timestamps.
* <p>
@@ -31,7 +33,7 @@
* </p>
* @since 2.11
*/
-public interface Instant {
+public interface Instant extends StringBuilderFormattable {
/**
* Gets the number of seconds from the Java epoch of 1970-01-01T00:00:00Z.
* <p>
Index: log4j-core/src/main/java/org/apache/logging/log4j/core/util/ClockFactory.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- log4j-core/src/main/java/org/apache/logging/log4j/core/util/ClockFactory.java (revision )
+++ log4j-core/src/main/java/org/apache/logging/log4j/core/util/ClockFactory.java (revision )
@@ -80,21 +80,27 @@
final String userRequest = PropertiesUtil.getProperties().getStringProperty(PROPERTY_NAME);
if (userRequest == null) {
LOGGER.trace("Using default SystemClock for timestamps.");
- return new SystemClock();
+ return logSupportedPrecision(new SystemClock());
}
Supplier<Clock> specified = aliases().get(userRequest);
if (specified != null) {
LOGGER.trace("Using specified {} for timestamps.", userRequest);
- return specified.get();
+ return logSupportedPrecision(specified.get());
}
try {
final Clock result = Loader.newCheckedInstanceOf(userRequest, Clock.class);
LOGGER.trace("Using {} for timestamps.", result.getClass().getName());
- return result;
+ return logSupportedPrecision(result);
} catch (final Exception e) {
final String fmt = "Could not create {}: {}, using default SystemClock for timestamps.";
LOGGER.error(fmt, userRequest, e);
- return new SystemClock();
+ return logSupportedPrecision(new SystemClock());
}
}
+
+ private static Clock logSupportedPrecision(Clock clock) {
+ String support = clock instanceof PreciseClock ? "supports" : "does not support";
+ LOGGER.debug("{} {} precise timestamps.", clock.getClass().getName(), support);
+ return clock;
+ }
}
Index: log4j-core/src/main/java/org/apache/logging/log4j/core/util/MutableInstant.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- log4j-core/src/main/java/org/apache/logging/log4j/core/util/MutableInstant.java (revision )
+++ log4j-core/src/main/java/org/apache/logging/log4j/core/util/MutableInstant.java (revision )
@@ -17,6 +17,7 @@
package org.apache.logging.log4j.core.util;
import org.apache.logging.log4j.util.PerformanceSensitive;
+import org.apache.logging.log4j.util.StringBuilderFormattable;
import java.io.Serializable;
@@ -31,7 +32,7 @@
* @since 2.11
*/
@PerformanceSensitive("allocation")
-public class MutableInstant implements Instant, Serializable {
+public class MutableInstant implements Instant, Serializable, StringBuilderFormattable {
private static final int MILLIS_PER_SECOND = 1000;
private static final int NANOS_PER_MILLI = 1000_000;
@@ -147,6 +148,13 @@
@Override
public String toString() {
- return "MutableInstant[epochSecond=" + epochSecond + ", nano=" + nanoOfSecond + "]";
+ StringBuilder sb = new StringBuilder(32);
+ formatTo(sb);
+ return sb.toString();
+ }
+
+ @Override
+ public void formatTo(StringBuilder buffer) {
+ buffer.append("MutableInstant[epochSecond=").append(epochSecond).append(", nano=").append(nanoOfSecond).append("]");
}
}
Index: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java (revision )
+++ log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java (revision )
@@ -104,7 +104,7 @@
void formatToBuffer(final Instant instant, final StringBuilder destination) {
final long epochSecond = instant.getEpochSecond();
final int nanoOfSecond = instant.getNanoOfSecond();
- if (previousTime != epochSecond && nanos != nanoOfSecond) {
+ if (previousTime != epochSecond || nanos != nanoOfSecond) {
length = fixedDateFormat.formatInstant(instant, cachedBuffer, 0);
previousTime = epochSecond;
nanos = nanoOfSecond;
{code})
> Support precise timestamps (microsecond and nanosecond level)
> -------------------------------------------------------------
>
> Key: LOG4J2-1883
> URL: https://issues.apache.org/jira/browse/LOG4J2-1883
> Project: Log4j 2
> Issue Type: Bug
> Components: Configurators
> Environment: Linux with any JDK including JDK1.8
> Reporter: Madhava Dass
> Assignee: Remko Popma
> Priority: Critical
>
> Used log4j and 'log4j2.xml' to configure timestamp format as:
> {code}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration status="WARN">
> <Appenders>
> <Console name="Console" target="SYSTEM_OUT">
> <PatternLayout pattern="[%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX}{UTC}][%level][%logger{36}]:%msg%n"/>
> </Console>
> </Appenders>
> <Loggers>
> <Root level="DEBUG">
> <AppenderRef ref="Console"/>
> </Root>
> </Loggers>
> </Configuration>
> {code}
> This pattern produces the time stamp as:
> {code}
> [2017-03-29T13:55:28.363000][null]:[Thread-1]: - <message>
> {code}
> The desired output is:
> {code}
> [2017-03-29T13:55:28.363701-07:00][null]:[Thread-1]: - <message>
> {code}
> Different versions of JDKs were tried including JDK 1.8. It does not seem to make any difference in the outcome.
> Is there a way to get the desired time stamp through pattern matching configuration in the '*.xml' file?
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)