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:47 UTC
[logging-log4j2] branch LOG4J2-3075 created (now 01959e4)
This is an automated email from the ASF dual-hosted git repository.
vy pushed a change to branch LOG4J2-3075
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git.
at 01959e4 LOG4J2-3075 Fix formatting of nanoseconds in JsonTemplateLayout.
This branch includes the following new commits:
new 01959e4 LOG4J2-3075 Fix formatting of nanoseconds in JsonTemplateLayout.
The 1 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails. The revisions
listed as "add" were already present in the repository and have only
been added to this reference.
[logging-log4j2] 01/01: LOG4J2-3075 Fix formatting of nanoseconds
in JsonTemplateLayout.
Posted by vy...@apache.org.
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>