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/11/08 12:16:23 UTC
[logging-log4j2] branch release-2.x updated: Prefer
StringBuilderEncoder in JsonTemplateLayout whenever possible.
This is an automated email from the ASF dual-hosted git repository.
vy pushed a commit to branch release-2.x
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
The following commit(s) were added to refs/heads/release-2.x by this push:
new 95814c4 Prefer StringBuilderEncoder in JsonTemplateLayout whenever possible.
95814c4 is described below
commit 95814c41c6889a1be7c08e5672077f001b00815f
Author: Volkan Yazici <vo...@yazi.ci>
AuthorDate: Mon Nov 8 13:16:44 2021 +0100
Prefer StringBuilderEncoder in JsonTemplateLayout whenever possible.
---
.../layout/template/json/JsonTemplateLayout.java | 16 +-
.../JsonTemplateLayoutConcurrentEncodeTest.java | 320 +++++++++++----------
2 files changed, 187 insertions(+), 149 deletions(-)
diff --git a/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayout.java b/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayout.java
index 59336c8..cf8658e 100644
--- a/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayout.java
+++ b/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayout.java
@@ -29,6 +29,7 @@ import org.apache.logging.log4j.core.config.plugins.PluginElement;
import org.apache.logging.log4j.core.layout.ByteBufferDestination;
import org.apache.logging.log4j.core.layout.Encoder;
import org.apache.logging.log4j.core.layout.LockingStringBuilderEncoder;
+import org.apache.logging.log4j.core.layout.StringBuilderEncoder;
import org.apache.logging.log4j.core.util.Constants;
import org.apache.logging.log4j.core.util.StringEncoder;
import org.apache.logging.log4j.layout.template.json.resolver.EventResolverContext;
@@ -203,14 +204,21 @@ public class JsonTemplateLayout implements StringLayout {
final JsonWriter jsonWriter) {
return () -> {
final JsonWriter clonedJsonWriter = jsonWriter.clone();
- final Encoder<StringBuilder> encoder =
- Constants.ENABLE_DIRECT_ENCODERS
- ? new LockingStringBuilderEncoder(charset)
- : null;
+ final Encoder<StringBuilder> encoder = createStringBuilderEncoder(charset);
return new Context(clonedJsonWriter, encoder);
};
}
+ private static Encoder<StringBuilder> createStringBuilderEncoder(
+ final Charset charset) {
+ if (Constants.ENABLE_DIRECT_ENCODERS) {
+ return Constants.ENABLE_THREADLOCALS
+ ? new StringBuilderEncoder(charset)
+ : new LockingStringBuilderEncoder(charset);
+ }
+ return null;
+ }
+
@Override
public byte[] toByteArray(final LogEvent event) {
final String eventJson = toSerializable(event);
diff --git a/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutConcurrentEncodeTest.java b/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutConcurrentEncodeTest.java
index d62e63c..5a52785 100644
--- a/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutConcurrentEncodeTest.java
+++ b/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutConcurrentEncodeTest.java
@@ -16,110 +16,50 @@
*/
package org.apache.logging.log4j.layout.template.json;
-import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.config.Configuration;
-import org.apache.logging.log4j.core.config.DefaultConfiguration;
+import org.apache.logging.log4j.core.config.Configurator;
+import org.apache.logging.log4j.core.config.builder.api.ConfigurationBuilder;
+import org.apache.logging.log4j.core.config.builder.api.ConfigurationBuilderFactory;
import org.apache.logging.log4j.core.layout.ByteBufferDestination;
-import org.apache.logging.log4j.layout.template.json.util.RecyclerFactories;
-import org.apache.logging.log4j.layout.template.json.util.RecyclerFactory;
-import org.assertj.core.api.Assertions;
+import org.apache.logging.log4j.core.layout.StringBuilderEncoder;
+import org.apache.logging.log4j.util.Strings;
+import org.junit.jupiter.api.parallel.Execution;
+import org.junit.jupiter.api.parallel.ExecutionMode;
import org.junit.jupiter.params.ParameterizedTest;
import org.junit.jupiter.params.provider.ValueSource;
-import java.nio.ByteBuffer;
+import java.io.*;
+import java.nio.charset.StandardCharsets;
+import java.nio.file.Files;
+import java.nio.file.Path;
+import java.nio.file.Paths;
import java.util.List;
-import java.util.concurrent.atomic.AtomicInteger;
-import java.util.concurrent.atomic.AtomicLong;
-import java.util.concurrent.atomic.AtomicReference;
+import java.util.function.Consumer;
import java.util.stream.Collectors;
import java.util.stream.IntStream;
+import static org.apache.logging.log4j.layout.template.json.TestHelpers.asMap;
+import static org.apache.logging.log4j.layout.template.json.TestHelpers.writeJson;
+import static org.assertj.core.api.Assertions.assertThat;
+
+/**
+ * Tests {@link JsonTemplateLayout} doesn't exhibit unexpected behavior when accessed concurrently.
+ * <p>
+ * Earlier the test was designed to pass a specially crafted {@link ByteBufferDestination} implementation raising a flag when a concurrent access was detected.
+ * Though this doesn't play along well with the {@link ThreadLocal}s employed in {@link StringBuilderEncoder}.
+ * Those do concurrently access to {@link ByteBufferDestination} in ways with certain assumptions for the appender due to efficiency reasons.
+ * Eventually we converged to the current state of the test where the output is written to a file and is checked for any interleaved lines.
+ * </p>
+ */
+@SuppressWarnings("SameParameterValue")
+// Running tests in parallel is causing strange issues at the Log4j configuration level.
+// Falling back to sequential test run for the moment.
+@Execution(ExecutionMode.SAME_THREAD)
class JsonTemplateLayoutConcurrentEncodeTest {
- private static class ConcurrentAccessError extends RuntimeException {
-
- public static final long serialVersionUID = 0;
-
- private ConcurrentAccessError(final int concurrentAccessCount) {
- super("concurrentAccessCount=" + concurrentAccessCount);
- }
-
- }
-
- private static class ConcurrentAccessDetectingByteBufferDestination
- extends BlackHoleByteBufferDestination {
-
- private final AtomicInteger concurrentAccessCounter = new AtomicInteger(0);
-
- ConcurrentAccessDetectingByteBufferDestination() {
- super(2_000);
- }
-
- @Override
- public ByteBuffer getByteBuffer() {
- final int concurrentAccessCount = concurrentAccessCounter.incrementAndGet();
- if (concurrentAccessCount > 1) {
- throw new ConcurrentAccessError(concurrentAccessCount);
- }
- try {
- return super.getByteBuffer();
- } finally {
- concurrentAccessCounter.decrementAndGet();
- }
- }
-
- @Override
- public ByteBuffer drain(final ByteBuffer byteBuffer) {
- final int concurrentAccessCount = concurrentAccessCounter.incrementAndGet();
- if (concurrentAccessCount > 1) {
- throw new ConcurrentAccessError(concurrentAccessCount);
- }
- try {
- return super.drain(byteBuffer);
- } finally {
- concurrentAccessCounter.decrementAndGet();
- }
- }
-
- @Override
- public void writeBytes(final ByteBuffer byteBuffer) {
- final int concurrentAccessCount = concurrentAccessCounter.incrementAndGet();
- if (concurrentAccessCount > 1) {
- throw new ConcurrentAccessError(concurrentAccessCount);
- }
- try {
- super.writeBytes(byteBuffer);
- } finally {
- concurrentAccessCounter.decrementAndGet();
- }
- }
-
- @Override
- public void writeBytes(final byte[] buffer, final int offset, final int length) {
- int concurrentAccessCount = concurrentAccessCounter.incrementAndGet();
- if (concurrentAccessCount > 1) {
- throw new ConcurrentAccessError(concurrentAccessCount);
- }
- try {
- super.writeBytes(buffer, offset, length);
- } finally {
- concurrentAccessCounter.decrementAndGet();
- }
- }
-
- }
-
- private static final LogEvent[] LOG_EVENTS = createMessages();
-
- private static LogEvent[] createMessages() {
- final int messageCount = 1_000;
- final LogEvent[] logEvents = new LogEvent[messageCount];
- LogEventFixture
- .createLiteLogEvents(messageCount)
- .toArray(logEvents);
- return logEvents;
- }
-
@ParameterizedTest
@ValueSource(strings = {
"dummy",
@@ -127,79 +67,169 @@ class JsonTemplateLayoutConcurrentEncodeTest {
"queue:supplier=java.util.concurrent.ArrayBlockingQueue.new",
"queue:supplier=org.jctools.queues.MpmcArrayQueue.new"
})
- void test_concurrent_encode(final String recyclerFactorySpec) {
- final RecyclerFactory recyclerFactory = RecyclerFactories.ofSpec(recyclerFactorySpec);
- final AtomicReference<Exception> encodeFailureRef = new AtomicReference<>(null);
- produce(recyclerFactory, encodeFailureRef);
- Assertions.assertThat(encodeFailureRef.get()).isNull();
+ void test_concurrent_encode(final String recyclerFactory) throws IOException {
+ final Path appenderFilepath = createAppenderFilepath(recyclerFactory);
+ final int workerCount = 10;
+ final int messageLength = 1_000;
+ final int messageCount = 1_000;
+ try {
+ withContextFromTemplate(appenderFilepath, recyclerFactory, loggerContext -> {
+ final Logger logger = loggerContext.getLogger(JsonTemplateLayoutConcurrentEncodeTest.class);
+ runWorkers(workerCount, messageLength, messageCount, logger);
+ });
+ verifyLines(appenderFilepath, messageLength, workerCount * messageCount);
+ } catch (final Throwable error) {
+ final String message = String.format(
+ "test failure for appender pointing to file: `%s`",
+ appenderFilepath);
+ throw new AssertionError(message, error);
+ }
+ Files.delete(appenderFilepath);
+ }
+
+ private static Path createAppenderFilepath(final String recyclerFactory) {
+ final String appenderFilename = String.format(
+ "%s-%s.log",
+ JsonTemplateLayoutConcurrentEncodeTest.class.getSimpleName(),
+ recyclerFactory.replaceAll("[^A-Za-z0-9]+", ""));
+ return Paths.get(
+ System.getProperty("java.io.tmpdir"),
+ appenderFilename);
+ }
+
+ private static void withContextFromTemplate(
+ final Path appenderFilepath,
+ final String recyclerFactory,
+ final Consumer<LoggerContext> loggerContextConsumer) {
+
+ // Create the configuration builder.
+ final String configName = String.format(
+ "%s-%s",
+ JsonTemplateLayoutConcurrentEncodeTest.class.getSimpleName(),
+ recyclerFactory.replaceAll("[^A-Za-z0-9]+", ""));
+ final ConfigurationBuilder<?> configBuilder = ConfigurationBuilderFactory
+ .newConfigurationBuilder()
+ .setStatusLevel(Level.ERROR)
+ .setConfigurationName(configName);
+
+ // Create the configuration.
+ final Object eventTemplate = asMap("$resolver", "message");
+ final String eventTemplateJson = writeJson(eventTemplate);
+ final String appenderName = "File";
+ final Configuration config = configBuilder
+ .add(configBuilder
+ .newAppender(appenderName, "File")
+ .addAttribute("fileName", appenderFilepath.toAbsolutePath().toString())
+ .addAttribute("append", false)
+ .addAttribute("immediateFlush", false)
+ .addAttribute("ignoreExceptions", false)
+ .add(configBuilder
+ .newLayout("JsonTemplateLayout")
+ .addAttribute("eventTemplate", eventTemplateJson)
+ .addAttribute("recyclerFactory", recyclerFactory)))
+ .add(configBuilder
+ .newRootLogger(Level.ALL)
+ .add(configBuilder.newAppenderRef(appenderName)))
+ .build(false);
+
+ // Initialize the configuration and pass it to the consumer.
+ try (final LoggerContext loggerContext = Configurator.initialize(config)) {
+ loggerContextConsumer.accept(loggerContext);
+ }
+
}
- private void produce(
- final RecyclerFactory recyclerFactory,
- final AtomicReference<Exception> encodeFailureRef) {
- final int threadCount = 10;
- final JsonTemplateLayout layout = createLayout(recyclerFactory);
- final ByteBufferDestination destination =
- new ConcurrentAccessDetectingByteBufferDestination();
- final AtomicLong encodeCounter = new AtomicLong(0);
+ private static void runWorkers(
+ final int workerCount,
+ final int messageLength,
+ final int messageCount,
+ final Logger logger) {
final List<Thread> workers = IntStream
- .range(0, threadCount)
+ .range(0, workerCount)
.mapToObj((final int threadIndex) ->
- createWorker(
- layout,
- destination,
- encodeFailureRef,
- encodeCounter,
- threadIndex))
+ createWorker(messageLength, messageCount, logger, threadIndex))
.collect(Collectors.toList());
workers.forEach(Thread::start);
workers.forEach((final Thread worker) -> {
try {
worker.join();
} catch (final InterruptedException ignored) {
- System.err.format("join to %s interrupted%n", worker.getName());
+ Thread.currentThread().interrupt();
+ System.err.format("join to `%s` interrupted%n", worker.getName());
}
});
}
- private static JsonTemplateLayout createLayout(final RecyclerFactory recyclerFactory) {
- final Configuration config = new DefaultConfiguration();
- return JsonTemplateLayout
- .newBuilder()
- .setConfiguration(config)
- .setEventTemplate("{\"message\": \"${json:message}\"}")
- .setStackTraceEnabled(false)
- .setLocationInfoEnabled(false)
- .setRecyclerFactory(recyclerFactory)
- .build();
- }
-
- private Thread createWorker(
- final JsonTemplateLayout layout,
- final ByteBufferDestination destination,
- final AtomicReference<Exception> encodeFailureRef,
- final AtomicLong encodeCounter,
+ private static Thread createWorker(
+ final int messageLength,
+ final int messageCount,
+ final Logger logger,
final int threadIndex) {
- final int maxEncodeCount = 1_000;
+
+ // Check thread index.
+ final int maxThreadIndex = 'Z' - 'A';
+ if (threadIndex > maxThreadIndex) {
+ String message = String.format(
+ "was expecting `threadIndex <= %d`, found: %d",
+ maxThreadIndex, threadIndex);
+ throw new IndexOutOfBoundsException(message);
+ }
+
+ // Determine the message to be logged.
+ final String messageLetter = String.valueOf((char) ('A' + threadIndex));
+ final String message = Strings.repeat(messageLetter, messageLength);
+
+ // Create the worker thread.
final String threadName = String.format("Worker-%d", threadIndex);
return new Thread(
() -> {
- try {
- for (int logEventIndex = threadIndex % LOG_EVENTS.length;
- encodeFailureRef.get() == null && encodeCounter.incrementAndGet() < maxEncodeCount;
- logEventIndex = (logEventIndex + 1) % LOG_EVENTS.length) {
- final LogEvent logEvent = LOG_EVENTS[logEventIndex];
- layout.encode(logEvent, destination);
- }
- } catch (final Exception error) {
- final boolean succeeded = encodeFailureRef.compareAndSet(null, error);
- if (succeeded) {
- System.err.format("%s failed%n", threadName);
- error.printStackTrace(System.err);
- }
+ for (int i = 0; i < messageCount; i++) {
+ logger.info(message);
}
},
threadName);
+
+ }
+
+ private static void verifyLines(
+ final Path appenderFilepath,
+ final int messageLength,
+ final int messageCount) {
+ try (final InputStream inputStream = new FileInputStream(appenderFilepath.toFile());
+ final Reader reader = new InputStreamReader(inputStream, StandardCharsets.US_ASCII);
+ final BufferedReader bufferedReader = new BufferedReader(reader)) {
+ int lineCount = 0;
+ String line;
+ while ((line = bufferedReader.readLine()) != null) {
+ try {
+ verifyLine(messageLength, line);
+ } catch (final Throwable error) {
+ final String message = String.format(
+ "verification failure at line %d: `%s`",
+ (lineCount + 1), line);
+ throw new AssertionError(message, error);
+ }
+ lineCount++;
+ }
+ assertThat(lineCount).isEqualTo(messageCount);
+ } catch (final IOException error) {
+ final String message = String.format("error verifying file: `%s`", appenderFilepath);
+ throw new RuntimeException(message, error);
+ }
+ }
+
+ private static void verifyLine(final int messageLength, final String line) {
+ assertThat(line).hasSize(messageLength + 2);
+ final char c0 = line.charAt(0);
+ final char cN = line.charAt(messageLength + 1);
+ assertThat(c0).isEqualTo('"').isEqualTo(cN);
+ final char c1 = line.charAt(1);
+ for (int i = 1; i < messageLength; i++) {
+ final char c = line.charAt(1 + i);
+ assertThat(c)
+ .describedAs("character at index %d", i)
+ .isEqualTo(c1);
+ }
}
}