You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by vy...@apache.org on 2021/05/21 12:12:48 UTC
[logging-log4j2] 01/01: LOG4J2-3075 Fix formatting of nanoseconds
in JsonTemplateLayout.
This is an automated email from the ASF dual-hosted git repository.
vy pushed a commit to branch LOG4J2-3075
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
commit 01959e488d8a704af3f030f1e52a6b8c88dfeb40
Author: Volkan Yazici <vo...@gmail.com>
AuthorDate: Fri May 21 14:12:05 2021 +0200
LOG4J2-3075 Fix formatting of nanoseconds in JsonTemplateLayout.
---
log4j-core/revapi.json | 6 +
.../logging/log4j/core/time/MutableInstant.java | 77 ++++-
.../log4j/core/time/MutableInstantTest.java | 55 +--
.../template/json/resolver/TimestampResolver.java | 105 +++---
.../template/json/util/InstantFormatter.java | 376 +++++++++++++++++++++
.../template/json/JsonTemplateLayoutTest.java | 23 +-
.../json/resolver/TimestampResolverTest.java | 65 ----
.../template/json/util/InstantFormatterTest.java | 47 +++
.../log4j/perf/jmh/DateTimeFormatBenchmark.java | 122 +++++++
src/changes/changes.xml | 3 +
10 files changed, 722 insertions(+), 157 deletions(-)
diff --git a/log4j-core/revapi.json b/log4j-core/revapi.json
index d809da3..af702c0 100644
--- a/log4j-core/revapi.json
+++ b/log4j-core/revapi.json
@@ -146,6 +146,12 @@
"new": "parameter org.apache.logging.log4j.core.net.ssl.SslConfiguration org.apache.logging.log4j.core.net.ssl.SslConfiguration::createSSLConfiguration(java.lang.String, org.apache.logging.log4j.core.net.ssl.KeyStoreConfiguration, org.apache.logging.log4j.core.net.ssl.TrustStoreConfiguration, ===boolean===)",
"annotation": "@org.apache.logging.log4j.core.config.plugins.PluginElement(\"verifyHostName\")",
"justification": "LOG4J2-TODO"
+ },
+ {
+ "code": "java.class.defaultSerializationChanged",
+ "old": "class org.apache.logging.log4j.core.time.MutableInstant",
+ "new": "class org.apache.logging.log4j.core.time.MutableInstant",
+ "justification": "LOG4J2-3075 MutableInstant extends from TemporalAccessor"
}
]
}
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/time/MutableInstant.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/time/MutableInstant.java
index 4d1216a..b752966 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/time/MutableInstant.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/time/MutableInstant.java
@@ -20,6 +20,19 @@ import org.apache.logging.log4j.core.util.Clock;
import org.apache.logging.log4j.util.PerformanceSensitive;
import java.io.Serializable;
+import java.time.temporal.ChronoField;
+import java.time.temporal.TemporalAccessor;
+import java.time.temporal.TemporalField;
+import java.time.temporal.TemporalQueries;
+import java.time.temporal.TemporalQuery;
+import java.time.temporal.UnsupportedTemporalTypeException;
+import java.time.temporal.ValueRange;
+
+import static java.time.temporal.ChronoField.INSTANT_SECONDS;
+import static java.time.temporal.ChronoField.MICRO_OF_SECOND;
+import static java.time.temporal.ChronoField.MILLI_OF_SECOND;
+import static java.time.temporal.ChronoField.NANO_OF_SECOND;
+import static java.time.temporal.ChronoUnit.NANOS;
/**
* An instantaneous point on the time line, used for high-precision log event timestamps.
@@ -32,7 +45,7 @@ import java.io.Serializable;
* @since 2.11
*/
@PerformanceSensitive("allocation")
-public class MutableInstant implements Instant, Serializable {
+public class MutableInstant implements Instant, Serializable, TemporalAccessor {
private static final int MILLIS_PER_SECOND = 1000;
private static final int NANOS_PER_MILLI = 1000_000;
@@ -127,6 +140,67 @@ public class MutableInstant implements Instant, Serializable {
}
@Override
+ public boolean isSupported(final TemporalField field) {
+ if (field instanceof ChronoField) {
+ return field == INSTANT_SECONDS ||
+ field == NANO_OF_SECOND ||
+ field == MICRO_OF_SECOND ||
+ field == MILLI_OF_SECOND;
+ }
+ return field != null && field.isSupportedBy(this);
+ }
+
+ @Override
+ public long getLong(final TemporalField field) {
+ if (field instanceof ChronoField) {
+ switch ((ChronoField) field) {
+ case NANO_OF_SECOND: return nanoOfSecond;
+ case MICRO_OF_SECOND: return nanoOfSecond / 1000;
+ case MILLI_OF_SECOND: return nanoOfSecond / 1000_000;
+ case INSTANT_SECONDS: return epochSecond;
+ }
+ throw new UnsupportedTemporalTypeException("Unsupported field: " + field);
+ }
+ return field.getFrom(this);
+ }
+
+ @Override
+ public ValueRange range(final TemporalField field) {
+ return TemporalAccessor.super.range(field);
+ }
+
+ @Override
+ public int get(final TemporalField field) {
+ if (field instanceof ChronoField) {
+ switch ((ChronoField) field) {
+ case NANO_OF_SECOND: return nanoOfSecond;
+ case MICRO_OF_SECOND: return nanoOfSecond / 1000;
+ case MILLI_OF_SECOND: return nanoOfSecond / 1000_000;
+ case INSTANT_SECONDS: INSTANT_SECONDS.checkValidIntValue(epochSecond);
+ }
+ throw new UnsupportedTemporalTypeException("Unsupported field: " + field);
+ }
+ return range(field).checkValidIntValue(field.getFrom(this), field);
+ }
+
+ @Override
+ public <R> R query(final TemporalQuery<R> query) {
+ if (query == TemporalQueries.precision()) {
+ return (R) NANOS;
+ }
+ // inline TemporalAccessor.super.query(query) as an optimization
+ if (query == TemporalQueries.chronology() ||
+ query == TemporalQueries.zoneId() ||
+ query == TemporalQueries.zone() ||
+ query == TemporalQueries.offset() ||
+ query == TemporalQueries.localDate() ||
+ query == TemporalQueries.localTime()) {
+ return null;
+ }
+ return query.queryFrom(this);
+ }
+
+ @Override
public boolean equals(final Object object) {
if (object == this) {
return true;
@@ -157,4 +231,5 @@ public class MutableInstant implements Instant, Serializable {
public void formatTo(final StringBuilder buffer) {
buffer.append("MutableInstant[epochSecond=").append(epochSecond).append(", nano=").append(nanoOfSecond).append("]");
}
+
}
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/time/MutableInstantTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/time/MutableInstantTest.java
index 4a6e9c4..d9fa068 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/time/MutableInstantTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/time/MutableInstantTest.java
@@ -19,12 +19,15 @@ package org.apache.logging.log4j.core.time;
import org.apache.logging.log4j.core.time.internal.FixedPreciseClock;
import org.junit.jupiter.api.Test;
+import java.time.ZoneId;
+import java.time.format.DateTimeFormatter;
+
import static org.junit.jupiter.api.Assertions.*;
-public class MutableInstantTest {
+class MutableInstantTest {
@Test
- public void testGetEpochSecond() {
+ void testGetEpochSecond() {
MutableInstant instant = new MutableInstant();
assertEquals(0, instant.getEpochSecond(), "initial");
@@ -42,7 +45,7 @@ public class MutableInstantTest {
}
@Test
- public void testGetNanoOfSecond() {
+ void testGetNanoOfSecond() {
MutableInstant instant = new MutableInstant();
assertEquals(0, instant.getNanoOfSecond(), "initial");
@@ -60,7 +63,7 @@ public class MutableInstantTest {
}
@Test
- public void testGetEpochMillisecond() {
+ void testGetEpochMillisecond() {
MutableInstant instant = new MutableInstant();
assertEquals(0, instant.getEpochMillisecond(), "initial");
@@ -78,7 +81,7 @@ public class MutableInstantTest {
}
@Test
- public void getGetNanoOfMillisecond() {
+ void getGetNanoOfMillisecond() {
MutableInstant instant = new MutableInstant();
assertEquals(0, instant.getNanoOfMillisecond(), "initial");
@@ -96,12 +99,12 @@ public class MutableInstantTest {
}
@Test
- public void testInitFromInstantRejectsNull() {
+ void testInitFromInstantRejectsNull() {
assertThrows(NullPointerException.class, () -> new MutableInstant().initFrom((Instant) null));
}
@Test
- public void testInitFromInstantCopiesValues() {
+ void testInitFromInstantCopiesValues() {
MutableInstant other = new MutableInstant();
other.initFromEpochSecond(788, 456);
assertEquals(788, other.getEpochSecond(), "epochSec");
@@ -115,7 +118,7 @@ public class MutableInstantTest {
}
@Test
- public void testInitFromEpochMillis() {
+ void testInitFromEpochMillis() {
MutableInstant instant = new MutableInstant();
instant.initFromEpochMilli(123456, 789012);
assertEquals(123, instant.getEpochSecond(), "epochSec");
@@ -125,26 +128,26 @@ public class MutableInstantTest {
}
@Test
- public void testInitFromEpochMillisRejectsNegativeNanoOfMilli() {
+ void testInitFromEpochMillisRejectsNegativeNanoOfMilli() {
MutableInstant instant = new MutableInstant();
assertThrows(IllegalArgumentException.class, () -> instant.initFromEpochMilli(123456, -1));
}
@Test
- public void testInitFromEpochMillisRejectsTooLargeNanoOfMilli() {
+ void testInitFromEpochMillisRejectsTooLargeNanoOfMilli() {
MutableInstant instant = new MutableInstant();
assertThrows(IllegalArgumentException.class, () -> instant.initFromEpochMilli(123456, 1000_000));
}
@Test
- public void testInitFromEpochMillisAcceptsTooMaxNanoOfMilli() {
+ void testInitFromEpochMillisAcceptsTooMaxNanoOfMilli() {
MutableInstant instant = new MutableInstant();
instant.initFromEpochMilli(123456, 999_999);
assertEquals(999_999, instant.getNanoOfMillisecond(), "NanoOfMilli");
}
@Test
- public void testInitFromEpochSecond() {
+ void testInitFromEpochSecond() {
MutableInstant instant = new MutableInstant();
instant.initFromEpochSecond(123, 456789012);
assertEquals(123, instant.getEpochSecond(), "epochSec");
@@ -154,26 +157,26 @@ public class MutableInstantTest {
}
@Test
- public void testInitFromEpochSecondRejectsNegativeNanoOfMilli() {
+ void testInitFromEpochSecondRejectsNegativeNanoOfMilli() {
MutableInstant instant = new MutableInstant();
assertThrows(IllegalArgumentException.class, () -> instant.initFromEpochSecond(123456, -1));
}
@Test
- public void testInitFromEpochSecondRejectsTooLargeNanoOfMilli() {
+ void testInitFromEpochSecondRejectsTooLargeNanoOfMilli() {
MutableInstant instant = new MutableInstant();
assertThrows(IllegalArgumentException.class, () -> instant.initFromEpochSecond(123456, 1000_000_000));
}
@Test
- public void testInitFromEpochSecondAcceptsTooMaxNanoOfMilli() {
+ void testInitFromEpochSecondAcceptsTooMaxNanoOfMilli() {
MutableInstant instant = new MutableInstant();
instant.initFromEpochSecond(123456, 999_999_999);
assertEquals(999_999_999, instant.getNanoOfSecond(), "NanoOfSec");
}
@Test
- public void testInstantToMillisAndNanos() {
+ void testInstantToMillisAndNanos() {
long[] values = new long[2];
MutableInstant.instantToMillisAndNanos(123456, 999_999_999, values);
assertEquals(123456_999, values[0]);
@@ -181,7 +184,7 @@ public class MutableInstantTest {
}
@Test
- public void testInitFromClock() {
+ void testInitFromClock() {
MutableInstant instant = new MutableInstant();
PreciseClock clock = new FixedPreciseClock(123456, 789012);
@@ -194,7 +197,7 @@ public class MutableInstantTest {
}
@Test
- public void testEquals() {
+ void testEquals() {
MutableInstant instant = new MutableInstant();
instant.initFromEpochSecond(123, 456789012);
@@ -205,7 +208,7 @@ public class MutableInstantTest {
}
@Test
- public void testHashCode() {
+ void testHashCode() {
MutableInstant instant = new MutableInstant();
instant.initFromEpochSecond(123, 456789012);
@@ -220,7 +223,7 @@ public class MutableInstantTest {
}
@Test
- public void testToString() {
+ void testToString() {
MutableInstant instant = new MutableInstant();
instant.initFromEpochSecond(123, 456789012);
assertEquals("MutableInstant[epochSecond=123, nano=456789012]", instant.toString());
@@ -228,4 +231,16 @@ public class MutableInstantTest {
instant.initFromEpochMilli(123456, 789012);
assertEquals("MutableInstant[epochSecond=123, nano=456789012]", instant.toString());
}
+
+ @Test
+ void testTemporalAccessor() {
+ java.time.Instant javaInstant = java.time.Instant.parse("2020-05-10T22:09:04.123456789Z");
+ MutableInstant log4jInstant = new MutableInstant();
+ log4jInstant.initFromEpochSecond(javaInstant.getEpochSecond(), javaInstant.getNano());
+ DateTimeFormatter formatter = DateTimeFormatter
+ .ofPattern("yyyy-MM-dd'T'HH:mm:ss.SSSSSSSSS'Z'")
+ .withZone(ZoneId.of("UTC"));
+ assertEquals(formatter.format(javaInstant), formatter.format(log4jInstant));
+ }
+
}
diff --git a/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/resolver/TimestampResolver.java b/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/resolver/TimestampResolver.java
index fe0e2ca..0b70d15 100644
--- a/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/resolver/TimestampResolver.java
+++ b/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/resolver/TimestampResolver.java
@@ -18,11 +18,10 @@ package org.apache.logging.log4j.layout.template.json.resolver;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.time.Instant;
-import org.apache.logging.log4j.core.util.datetime.FastDateFormat;
import org.apache.logging.log4j.layout.template.json.JsonTemplateLayoutDefaults;
+import org.apache.logging.log4j.layout.template.json.util.InstantFormatter;
import org.apache.logging.log4j.layout.template.json.util.JsonWriter;
-import java.util.Calendar;
import java.util.Locale;
import java.util.TimeZone;
@@ -209,52 +208,42 @@ public final class TimestampResolver implements EventResolver {
}
return epochProvided
? createEpochResolver(config)
- : createFormatResolver(config);
+ : createPatternResolver(config);
}
- /**
- * Context for GC-free formatted timestamp resolver.
- */
- private static final class FormatResolverContext {
+ private static final class PatternResolverContext {
- private final FastDateFormat timestampFormat;
+ private final InstantFormatter formatter;
- private final Calendar calendar;
+ private final StringBuilder lastFormattedInstantBuffer = new StringBuilder();
- private final StringBuilder formattedTimestampBuilder;
+ private Instant lastFormattedInstant;
- private FormatResolverContext(
+ private PatternResolverContext(
+ final String pattern,
final TimeZone timeZone,
- final Locale locale,
- final FastDateFormat timestampFormat) {
- this.timestampFormat = timestampFormat;
- this.formattedTimestampBuilder = new StringBuilder();
- this.calendar = Calendar.getInstance(timeZone, locale);
+ final Locale locale) {
+ this.formatter = InstantFormatter
+ .newBuilder()
+ .setPattern(pattern)
+ .setTimeZone(timeZone)
+ .setLocale(locale)
+ .build();
}
- private static FormatResolverContext fromConfig(
+ private static PatternResolverContext fromConfig(
final TemplateResolverConfig config) {
- final String format = readFormat(config);
+ final String pattern = readPattern(config);
final TimeZone timeZone = readTimeZone(config);
final Locale locale = config.getLocale(new String[]{"pattern", "locale"});
- final FastDateFormat fastDateFormat =
- FastDateFormat.getInstance(format, timeZone, locale);
- return new FormatResolverContext(timeZone, locale, fastDateFormat);
+ return new PatternResolverContext(pattern, timeZone, locale);
}
- private static String readFormat(final TemplateResolverConfig config) {
+ private static String readPattern(final TemplateResolverConfig config) {
final String format = config.getString(new String[]{"pattern", "format"});
- if (format == null) {
- return JsonTemplateLayoutDefaults.getTimestampFormatPattern();
- }
- try {
- FastDateFormat.getInstance(format);
- } catch (final IllegalArgumentException error) {
- throw new IllegalArgumentException(
- "invalid timestamp format: " + config,
- error);
- }
- return format;
+ return format != null
+ ? format
+ : JsonTemplateLayoutDefaults.getTimestampFormatPattern();
}
private static TimeZone readTimeZone(final TemplateResolverConfig config) {
@@ -278,15 +267,12 @@ public final class TimestampResolver implements EventResolver {
}
- /**
- * GC-free formatted timestamp resolver.
- */
- private static final class FormatResolver implements EventResolver {
+ private static final class PatternResolver implements EventResolver {
- private final FormatResolverContext formatResolverContext;
+ private final PatternResolverContext patternResolverContext;
- private FormatResolver(final FormatResolverContext formatResolverContext) {
- this.formatResolverContext = formatResolverContext;
+ private PatternResolver(final PatternResolverContext patternResolverContext) {
+ this.patternResolverContext = patternResolverContext;
}
@Override
@@ -295,24 +281,26 @@ public final class TimestampResolver implements EventResolver {
final JsonWriter jsonWriter) {
// Format timestamp if it doesn't match the last cached one.
- final long timestampMillis = logEvent.getTimeMillis();
- if (formatResolverContext.formattedTimestampBuilder.length() == 0 || formatResolverContext.calendar.getTimeInMillis() != timestampMillis) {
+ if (patternResolverContext.lastFormattedInstant == null ||
+ !patternResolverContext.formatter.isInstantMatching(
+ patternResolverContext.lastFormattedInstant,
+ logEvent.getInstant())) {
// Format the timestamp.
- formatResolverContext.formattedTimestampBuilder.setLength(0);
- formatResolverContext.calendar.setTimeInMillis(timestampMillis);
- formatResolverContext.timestampFormat.format(
- formatResolverContext.calendar,
- formatResolverContext.formattedTimestampBuilder);
+ patternResolverContext.lastFormattedInstantBuffer.setLength(0);
+ patternResolverContext.lastFormattedInstant = logEvent.getInstant();
+ patternResolverContext.formatter.format(
+ patternResolverContext.lastFormattedInstant,
+ patternResolverContext.lastFormattedInstantBuffer);
// Write the formatted timestamp.
final StringBuilder jsonWriterStringBuilder = jsonWriter.getStringBuilder();
final int startIndex = jsonWriterStringBuilder.length();
- jsonWriter.writeString(formatResolverContext.formattedTimestampBuilder);
+ jsonWriter.writeString(patternResolverContext.lastFormattedInstantBuffer);
// Cache the written value.
- formatResolverContext.formattedTimestampBuilder.setLength(0);
- formatResolverContext.formattedTimestampBuilder.append(
+ patternResolverContext.lastFormattedInstantBuffer.setLength(0);
+ patternResolverContext.lastFormattedInstantBuffer.append(
jsonWriterStringBuilder,
startIndex,
jsonWriterStringBuilder.length());
@@ -322,18 +310,18 @@ public final class TimestampResolver implements EventResolver {
// Write the cached formatted timestamp.
else {
jsonWriter.writeRawString(
- formatResolverContext.formattedTimestampBuilder);
+ patternResolverContext.lastFormattedInstantBuffer);
}
}
}
- private static EventResolver createFormatResolver(
+ private static EventResolver createPatternResolver(
final TemplateResolverConfig config) {
- final FormatResolverContext formatResolverContext =
- FormatResolverContext.fromConfig(config);
- return new FormatResolver(formatResolverContext);
+ final PatternResolverContext patternResolverContext =
+ PatternResolverContext.fromConfig(config);
+ return new PatternResolver(patternResolverContext);
}
private static EventResolver createEpochResolver(
@@ -490,11 +478,4 @@ public final class TimestampResolver implements EventResolver {
internalResolver.resolve(logEvent, jsonWriter);
}
- /**
- * Visible for tests
- */
- Calendar getCalendar() {
- return ((FormatResolver) internalResolver).formatResolverContext.calendar;
- }
-
}
diff --git a/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatter.java b/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatter.java
new file mode 100644
index 0000000..a0695cf
--- /dev/null
+++ b/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatter.java
@@ -0,0 +1,376 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache license, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the license for the specific language governing permissions and
+ * limitations under the license.
+ */
+package org.apache.logging.log4j.layout.template.json.util;
+
+import org.apache.logging.log4j.core.time.Instant;
+import org.apache.logging.log4j.core.time.MutableInstant;
+import org.apache.logging.log4j.core.util.datetime.FastDateFormat;
+import org.apache.logging.log4j.core.util.datetime.FixedDateFormat;
+import org.apache.logging.log4j.util.Strings;
+
+import java.time.format.DateTimeFormatter;
+import java.util.Arrays;
+import java.util.Calendar;
+import java.util.Locale;
+import java.util.Objects;
+import java.util.TimeZone;
+
+/**
+ * A composite {@link Instant} formatter trying to employ either
+ * {@link FixedDateFormat}, {@link FastDateFormat}, or {@link DateTimeFormatter}
+ * in the given order due to performance reasons.
+ * <p>
+ * Note that {@link FixedDateFormat} and {@link FastDateFormat} only support
+ * millisecond precision. If the pattern asks for a higher precision,
+ * {@link DateTimeFormatter} will be employed, which is significantly slower.
+ */
+public final class InstantFormatter {
+
+ /**
+ * The list of formatter factories in decreasing efficiency order.
+ */
+ private static final FormatterFactory[] FORMATTER_FACTORIES = {
+ new Log4jFixedFormatterFactory(),
+ new Log4jFastFormatterFactory(),
+ new JavaDateTimeFormatterFactory()
+ };
+
+ private final Formatter formatter;
+
+ private InstantFormatter(final Builder builder) {
+ this.formatter = Arrays
+ .stream(FORMATTER_FACTORIES)
+ .map(formatterFactory -> formatterFactory.createIfSupported(
+ builder.getPattern(),
+ builder.getLocale(),
+ builder.getTimeZone()))
+ .filter(Objects::nonNull)
+ .findFirst()
+ .orElseThrow(() -> new AssertionError("could not find a matching formatter"));
+ }
+
+ public String format(final Instant instant) {
+ Objects.requireNonNull(instant, "instant");
+ final StringBuilder stringBuilder = new StringBuilder();
+ formatter.format(instant, stringBuilder);
+ return stringBuilder.toString();
+ }
+
+ public void format(final Instant instant, final StringBuilder stringBuilder) {
+ Objects.requireNonNull(instant, "instant");
+ Objects.requireNonNull(stringBuilder, "stringBuilder");
+ formatter.format(instant, stringBuilder);
+ }
+
+ /**
+ * Checks if the given {@link Instant}s are equal from the point of view of
+ * the employed formatter.
+ * <p>
+ * This method should be preferred over {@link Instant#equals(Object)}. For
+ * instance, {@link FixedDateFormat} and {@link FastDateFormat} discard
+ * nanoseconds, hence, from their point of view, two different
+ * {@link Instant}s are equal if they match up to millisecond precision.
+ */
+ public boolean isInstantMatching(final Instant instant1, final Instant instant2) {
+ return formatter.isInstantMatching(instant1, instant2);
+ }
+
+ public Class<?> getInternalImplementationClass() {
+ return formatter.getInternalImplementationClass();
+ }
+
+ public static Builder newBuilder() {
+ return new Builder();
+ }
+
+ public static final class Builder {
+
+ private String pattern;
+
+ private Locale locale = Locale.getDefault();
+
+ private TimeZone timeZone = TimeZone.getDefault();
+
+ private Builder() {}
+
+ public String getPattern() {
+ return pattern;
+ }
+
+ public Builder setPattern(final String pattern) {
+ this.pattern = pattern;
+ return this;
+ }
+
+ public Locale getLocale() {
+ return locale;
+ }
+
+ public Builder setLocale(final Locale locale) {
+ this.locale = locale;
+ return this;
+ }
+
+ public TimeZone getTimeZone() {
+ return timeZone;
+ }
+
+ public Builder setTimeZone(final TimeZone timeZone) {
+ this.timeZone = timeZone;
+ return this;
+ }
+
+ public InstantFormatter build() {
+ validate();
+ return new InstantFormatter(this);
+ }
+
+ private void validate() {
+ if (Strings.isBlank(pattern)) {
+ throw new IllegalArgumentException("blank pattern");
+ }
+ Objects.requireNonNull(locale, "locale");
+ Objects.requireNonNull(timeZone, "timeZone");
+ }
+
+ }
+
+ private interface FormatterFactory {
+
+ Formatter createIfSupported(
+ String pattern,
+ Locale locale,
+ TimeZone timeZone);
+
+ }
+
+ private interface Formatter {
+
+ Class<?> getInternalImplementationClass();
+
+ void format(Instant instant, StringBuilder stringBuilder);
+
+ boolean isInstantMatching(Instant instant1, Instant instant2);
+
+ }
+
+ private static final class JavaDateTimeFormatterFactory implements FormatterFactory {
+
+ @Override
+ public Formatter createIfSupported(
+ final String pattern,
+ final Locale locale,
+ final TimeZone timeZone) {
+ return new JavaDateTimeFormatter(pattern, locale, timeZone);
+ }
+
+ }
+
+ private static final class JavaDateTimeFormatter implements Formatter {
+
+ private final DateTimeFormatter formatter;
+
+ private final MutableInstant mutableInstant;
+
+ private JavaDateTimeFormatter(
+ final String pattern,
+ final Locale locale,
+ final TimeZone timeZone) {
+ this.formatter = DateTimeFormatter
+ .ofPattern(pattern)
+ .withLocale(locale)
+ .withZone(timeZone.toZoneId());
+ this.mutableInstant = new MutableInstant();
+ }
+
+ @Override
+ public Class<?> getInternalImplementationClass() {
+ return DateTimeFormatter.class;
+ }
+
+ @Override
+ public void format(
+ final Instant instant,
+ final StringBuilder stringBuilder) {
+ if (instant instanceof MutableInstant) {
+ formatMutableInstant((MutableInstant) instant, stringBuilder);
+ } else {
+ formatInstant(instant, stringBuilder);
+ }
+ }
+
+ private void formatMutableInstant(
+ final MutableInstant instant,
+ final StringBuilder stringBuilder) {
+ formatter.formatTo(instant, stringBuilder);
+ }
+
+ private void formatInstant(
+ final Instant instant,
+ final StringBuilder stringBuilder) {
+ mutableInstant.initFromEpochSecond(
+ instant.getEpochSecond(),
+ instant.getNanoOfSecond());
+ formatMutableInstant(mutableInstant, stringBuilder);
+ }
+
+ @Override
+ public boolean isInstantMatching(final Instant instant1, final Instant instant2) {
+ return instant1.getEpochSecond() == instant2.getEpochSecond() &&
+ instant1.getNanoOfSecond() == instant2.getNanoOfSecond();
+ }
+
+ }
+
+ private static final class Log4jFastFormatterFactory implements FormatterFactory {
+
+ @Override
+ public Formatter createIfSupported(
+ final String pattern,
+ final Locale locale,
+ final TimeZone timeZone) {
+ final Log4jFastFormatter formatter =
+ new Log4jFastFormatter(pattern, locale, timeZone);
+ final boolean patternSupported =
+ patternSupported(pattern, locale, timeZone, formatter);
+ return patternSupported ? formatter : null;
+ }
+
+ }
+
+ private static final class Log4jFastFormatter implements Formatter {
+
+ private final FastDateFormat formatter;
+
+ private final Calendar calendar;
+
+ private Log4jFastFormatter(
+ final String pattern,
+ final Locale locale,
+ final TimeZone timeZone) {
+ this.formatter = FastDateFormat.getInstance(pattern, timeZone, locale);
+ this.calendar = Calendar.getInstance(timeZone, locale);
+ }
+
+ @Override
+ public Class<?> getInternalImplementationClass() {
+ return FastDateFormat.class;
+ }
+
+ @Override
+ public void format(
+ final Instant instant,
+ final StringBuilder stringBuilder) {
+ calendar.setTimeInMillis(instant.getEpochMillisecond());
+ formatter.format(calendar, stringBuilder);
+ }
+
+ @Override
+ public boolean isInstantMatching(final Instant instant1, final Instant instant2) {
+ return instant1.getEpochMillisecond() == instant2.getEpochMillisecond();
+ }
+
+ }
+
+ private static final class Log4jFixedFormatterFactory implements FormatterFactory {
+
+ @Override
+ public Formatter createIfSupported(
+ final String pattern,
+ final Locale locale,
+ final TimeZone timeZone) {
+ final FixedDateFormat internalFormatter =
+ FixedDateFormat.createIfSupported(pattern, timeZone.getID());
+ if (internalFormatter == null) {
+ return null;
+ }
+ final Log4jFixedFormatter formatter =
+ new Log4jFixedFormatter(internalFormatter);
+ final boolean patternSupported =
+ patternSupported(pattern, locale, timeZone, formatter);
+ return patternSupported ? formatter : null;
+ }
+
+ }
+
+ private static final class Log4jFixedFormatter implements Formatter {
+
+ @SuppressWarnings("OptionalGetWithoutIsPresent")
+ private static final int MAX_FORMATTED_INSTANT_LENGTH = Arrays
+ .stream(FixedDateFormat.FixedFormat.values())
+ .mapToInt(format -> format.getPattern().length())
+ .max()
+ .getAsInt();
+
+ private final FixedDateFormat formatter;
+
+ private final char[] buffer;
+
+ private Log4jFixedFormatter(final FixedDateFormat formatter) {
+ this.formatter = formatter;
+ this.buffer = new char[MAX_FORMATTED_INSTANT_LENGTH];
+ }
+
+ @Override
+ public Class<?> getInternalImplementationClass() {
+ return FixedDateFormat.class;
+ }
+
+ @Override
+ public void format(
+ final Instant instant,
+ final StringBuilder stringBuilder) {
+ final int length = formatter.formatInstant(instant, buffer, 0);
+ stringBuilder.append(buffer, 0, length);
+ }
+
+ @Override
+ public boolean isInstantMatching(final Instant instant1, final Instant instant2) {
+ return instant1.getEpochMillisecond() == instant2.getEpochMillisecond();
+ }
+
+ }
+
+ /**
+ * Checks if the provided formatter output matches with the one generated by
+ * {@link DateTimeFormatter}.
+ */
+ private static boolean patternSupported(
+ final String pattern,
+ final Locale locale,
+ final TimeZone timeZone,
+ final Formatter formatter) {
+ final DateTimeFormatter javaFormatter = DateTimeFormatter
+ .ofPattern(pattern)
+ .withLocale(locale)
+ .withZone(timeZone.toZoneId());
+ final MutableInstant instant = new MutableInstant();
+ instant.initFromEpochSecond(
+ // 2021-05-17 21:41:10
+ 1621280470,
+ // Using the highest nanosecond precision possible to
+ // differentiate formatters only supporting millisecond
+ // precision.
+ 123_456_789);
+ final String expectedFormat = javaFormatter.format(instant);
+ final StringBuilder stringBuilder = new StringBuilder();
+ formatter.format(instant, stringBuilder);
+ final String actualFormat = stringBuilder.toString();
+ return expectedFormat.equals(actualFormat);
+ }
+
+}
diff --git a/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutTest.java b/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutTest.java
index 190f695..a0c4321 100644
--- a/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutTest.java
+++ b/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutTest.java
@@ -66,8 +66,9 @@ import java.net.ServerSocket;
import java.net.Socket;
import java.nio.ByteBuffer;
import java.nio.charset.Charset;
-import java.text.SimpleDateFormat;
import java.time.Instant;
+import java.time.temporal.ChronoField;
+import java.time.temporal.TemporalAccessor;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.Collections;
@@ -205,20 +206,22 @@ class JsonTemplateLayoutTest {
}
@Test
- void test_inline_template() throws Exception {
+ void test_inline_template() {
// Create the log event.
final SimpleMessage message = new SimpleMessage("Hello, World");
- final String timestamp = "2017-09-28T17:13:29.098+02:00";
- final long timeMillis = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss.SSSXXX")
- .parse(timestamp)
- .getTime();
+ final String formattedInstant = "2017-09-28T17:13:29.098Z";
+ final TemporalAccessor instantAccessor = Instant.parse(formattedInstant);
+ final long instantEpochSeconds = instantAccessor.getLong(ChronoField.INSTANT_SECONDS);
+ final int instantEpochSecondsNanos = instantAccessor.get(ChronoField.NANO_OF_SECOND);
+ final MutableInstant instant = new MutableInstant();
+ instant.initFromEpochSecond(instantEpochSeconds, instantEpochSecondsNanos);
final LogEvent logEvent = Log4jLogEvent
.newBuilder()
.setLoggerName(LOGGER_NAME)
.setLevel(Level.INFO)
.setMessage(message)
- .setTimeMillis(timeMillis)
+ .setInstant(instant)
.build();
// Create the event template.
@@ -228,7 +231,9 @@ class JsonTemplateLayoutTest {
final String eventTemplate = writeJson(asMap(
timestampFieldName, asMap(
"$resolver", "timestamp",
- "pattern", asMap("timeZone", "Europe/Amsterdam")),
+ "pattern", asMap(
+ "format", "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'",
+ "timeZone", "UTC")),
staticFieldName, staticFieldValue));
// Create the layout.
@@ -240,7 +245,7 @@ class JsonTemplateLayoutTest {
// Check the serialized event.
usingSerializedLogEventAccessor(layout, logEvent, accessor -> {
- assertThat(accessor.getString(timestampFieldName)).isEqualTo(timestamp);
+ assertThat(accessor.getString(timestampFieldName)).isEqualTo(formattedInstant);
assertThat(accessor.getString(staticFieldName)).isEqualTo(staticFieldValue);
});
diff --git a/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/resolver/TimestampResolverTest.java b/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/resolver/TimestampResolverTest.java
deleted file mode 100644
index 522c62f..0000000
--- a/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/resolver/TimestampResolverTest.java
+++ /dev/null
@@ -1,65 +0,0 @@
-/*
- * Licensed to the Apache Software Foundation (ASF) under one or more
- * contributor license agreements. See the NOTICE file distributed with
- * this work for additional information regarding copyright ownership.
- * The ASF licenses this file to You under the Apache license, Version 2.0
- * (the "License"); you may not use this file except in compliance with
- * the License. You may obtain a copy of the License at
- *
- * http://www.apache.org/licenses/LICENSE-2.0
- *
- * Unless required by applicable law or agreed to in writing, software
- * distributed under the License is distributed on an "AS IS" BASIS,
- * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
- * See the license for the specific language governing permissions and
- * limitations under the license.
- */
-package org.apache.logging.log4j.layout.template.json.resolver;
-
-import org.apache.logging.log4j.Level;
-import org.apache.logging.log4j.core.LogEvent;
-import org.apache.logging.log4j.core.impl.Log4jLogEvent;
-import org.apache.logging.log4j.layout.template.json.util.JsonWriter;
-import org.apache.logging.log4j.message.SimpleMessage;
-import org.junit.jupiter.api.Test;
-
-import java.util.Collections;
-
-import static org.assertj.core.api.Assertions.assertThat;
-
-class TimestampResolverTest
-{
- private static final TemplateResolverConfig TEMPLATE_RESOLVER_CONFIG = new TemplateResolverConfig(
- Collections.singletonMap("pattern", Collections.singletonMap("format", "yyyy-MM-dd")));
-
- /**
- * Tests LOG4J2-3087 race when creating layout on the same instant as the log event would result in an unquoted date in the JSON
- */
- @Test
- void test_timestamp_pattern_race() {
- JsonWriter jsonWriter = JsonWriter.newBuilder()
- .setMaxStringLength(32)
- .setTruncatedStringSuffix("…")
- .build();
-
- final TimestampResolver resolver = new TimestampResolver(TEMPLATE_RESOLVER_CONFIG);
-
- final LogEvent logEvent = createLogEvent(resolver.getCalendar().getTimeInMillis() );
-
- resolver.resolve(logEvent, jsonWriter);
-
- assertThat(jsonWriter.getStringBuilder().toString()).matches("\"\\d{4}-\\d{2}-\\d{2}\"");
- }
-
- private static LogEvent createLogEvent(final long timeMillis) {
- return Log4jLogEvent
- .newBuilder()
- .setLoggerName("a.B")
- .setLoggerFqcn("f.q.c.n")
- .setLevel(Level.DEBUG)
- .setMessage(new SimpleMessage("LogEvent message"))
- .setTimeMillis(timeMillis)
- .setNanoTime(timeMillis * 2)
- .build();
- }
-}
diff --git a/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatterTest.java b/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatterTest.java
new file mode 100644
index 0000000..762b3df
--- /dev/null
+++ b/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatterTest.java
@@ -0,0 +1,47 @@
+package org.apache.logging.log4j.layout.template.json.util;
+
+import org.apache.logging.log4j.core.time.MutableInstant;
+import org.assertj.core.api.Assertions;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.params.ParameterizedTest;
+import org.junit.jupiter.params.provider.CsvSource;
+
+import java.util.TimeZone;
+
+class InstantFormatterTest {
+
+ @ParameterizedTest
+ @CsvSource({
+ "yyyy-MM-dd'T'HH:mm:ss.SSS" + ",FixedDateFormat",
+ "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'" + ",FastDateFormat",
+ "yyyy-MM-dd'T'HH:mm:ss.SSSSSSSSS'Z'" + ",DateTimeFormatter"
+ })
+ void all_internal_implementations_should_be_used(
+ final String pattern,
+ final String className) {
+ final InstantFormatter formatter = InstantFormatter
+ .newBuilder()
+ .setPattern(pattern)
+ .build();
+ Assertions
+ .assertThat(formatter.getInternalImplementationClass())
+ .asString()
+ .describedAs("pattern=%s", pattern)
+ .endsWith("." + className);
+ }
+
+ @Test
+ void nanoseconds_should_be_formatted() {
+ final InstantFormatter formatter = InstantFormatter
+ .newBuilder()
+ .setPattern("yyyy-MM-dd'T'HH:mm:ss.SSSSSSSSS'Z'")
+ .setTimeZone(TimeZone.getTimeZone("UTC"))
+ .build();
+ MutableInstant instant = new MutableInstant();
+ instant.initFromEpochSecond(0, 123_456_789);
+ Assertions
+ .assertThat(formatter.format(instant))
+ .isEqualTo("1970-01-01T00:00:00.123456789Z");
+ }
+
+}
diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/DateTimeFormatBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/DateTimeFormatBenchmark.java
new file mode 100644
index 0000000..3134326
--- /dev/null
+++ b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/DateTimeFormatBenchmark.java
@@ -0,0 +1,122 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache license, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the license for the specific language governing permissions and
+ * limitations under the license.
+ */
+package org.apache.logging.log4j.perf.jmh;
+
+import org.apache.logging.log4j.core.time.MutableInstant;
+import org.apache.logging.log4j.core.util.datetime.FastDatePrinter;
+import org.apache.logging.log4j.core.util.datetime.FixedDateFormat;
+import org.openjdk.jmh.annotations.Benchmark;
+import org.openjdk.jmh.annotations.Scope;
+import org.openjdk.jmh.annotations.State;
+import org.openjdk.jmh.infra.Blackhole;
+
+import java.time.Instant;
+import java.time.format.DateTimeFormatter;
+import java.util.*;
+import java.util.stream.IntStream;
+
+/**
+ * Compares {@link MutableInstant} formatting efficiency of
+ * {@link FastDatePrinter}, {@link FixedDateFormat}, and {@link DateTimeFormatter}.
+ * <p>
+ * The major formatting efficiency is mostly provided by caching, i.e.,
+ * reusing the earlier formatter output if timestamps match. We deliberately
+ * exclude this optimization, since it is applicable to all formatters. This
+ * benchmark rather focuses on only and only the formatting efficiency.
+ */
+@State(Scope.Thread)
+public class DateTimeFormatBenchmark {
+
+ /**
+ * The pattern to be tested.
+ * <p>
+ * Note that neither {@link FastDatePrinter}, nor {@link FixedDateFormat}
+ * supports nanosecond precision.
+ */
+ private static final String PATTERN = "yyyy-MM-dd'T'HH:mm:ss.SSS";
+
+ private static final Locale LOCALE = Locale.US;
+
+ private static final TimeZone TIME_ZONE = TimeZone.getTimeZone("UTC");
+
+ private static final Instant INIT_INSTANT = Instant.parse("2020-05-14T10:44:23.901Z");
+
+ private static final MutableInstant[] INSTANTS = IntStream
+ .range(0, 1_000)
+ .mapToObj((final int index) -> {
+ final MutableInstant instant = new MutableInstant();
+ instant.initFromEpochSecond(
+ Math.addExact(INIT_INSTANT.getEpochSecond(), index),
+ Math.addExact(INIT_INSTANT.getNano(), index));
+ return instant;
+ })
+ .toArray(MutableInstant[]::new);
+
+ private static final Calendar[] CALENDARS = Arrays
+ .stream(INSTANTS)
+ .map((final MutableInstant instant) -> {
+ final Calendar calendar = Calendar.getInstance(TIME_ZONE, LOCALE);
+ calendar.setTimeInMillis(instant.getEpochMillisecond());
+ return calendar;
+ })
+ .toArray(Calendar[]::new);
+
+ private static final FastDatePrinter FAST_DATE_PRINTER =
+ new FastDatePrinter(PATTERN, TIME_ZONE, LOCALE) {};
+
+ private static final FixedDateFormat FIXED_DATE_FORMAT =
+ Objects.requireNonNull(
+ FixedDateFormat.createIfSupported(PATTERN, TIME_ZONE.getID()),
+ "couldn't create FixedDateTime for pattern " + PATTERN + " and time zone " + TIME_ZONE.getID());
+
+ private static final DateTimeFormatter DATE_TIME_FORMATTER =
+ DateTimeFormatter
+ .ofPattern(PATTERN)
+ .withZone(TIME_ZONE.toZoneId())
+ .withLocale(LOCALE);
+
+ private final StringBuilder stringBuilder = new StringBuilder(PATTERN.length() * 2);
+
+ private final char[] charBuffer = new char[stringBuilder.capacity()];
+
+ @Benchmark
+ public void fastDatePrinter(final Blackhole blackhole) {
+ for (final Calendar calendar : CALENDARS) {
+ stringBuilder.setLength(0);
+ FAST_DATE_PRINTER.format(calendar, stringBuilder);
+ blackhole.consume(stringBuilder.length());
+ }
+ }
+
+ @Benchmark
+ public void fixedDateFormat(final Blackhole blackhole) {
+ for (final MutableInstant instant : INSTANTS) {
+ final int length = FIXED_DATE_FORMAT.formatInstant(instant, charBuffer, 0);
+ blackhole.consume(length);
+ }
+ }
+
+ @Benchmark
+ public void dateTimeFormatter(final Blackhole blackhole) {
+ for (final MutableInstant instant : INSTANTS) {
+ stringBuilder.setLength(0);
+ DATE_TIME_FORMATTER.formatTo(instant, stringBuilder);
+ blackhole.consume(stringBuilder.length());
+ }
+ }
+
+}
diff --git a/src/changes/changes.xml b/src/changes/changes.xml
index cfdaa03..c310dc9 100644
--- a/src/changes/changes.xml
+++ b/src/changes/changes.xml
@@ -69,6 +69,9 @@
Allow a PatternSelector to be specified on GelfLayout.
</action>
<!-- FIXES -->
+ <action issue="LOG4J2-3075" dev="vy" type="fix">
+ Fix formatting of nanoseconds in JsonTemplateLayout.
+ </action>
<action issue="LOG4J2-3087" dev="vy" type="fix" due-to="Anton Klarén">
Fix race in JsonTemplateLayout where a timestamp could end up unquoted.
</action>