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 <[email protected]> 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>
