/* * 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.core.util.internal; import static java.nio.charset.StandardCharsets.US_ASCII; import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.api.Assertions.assertThatCode; import java.io.IOException; import java.nio.file.Files; import java.nio.file.Path; import java.time.Duration; import java.util.List; import java.util.Random; import java.util.concurrent.CountDownLatch; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; import java.util.concurrent.Future; import java.util.concurrent.TimeUnit; import java.util.function.BiFunction; import java.util.stream.Collectors; import java.util.stream.IntStream; import org.apache.logging.log4j.core.Logger; import org.apache.logging.log4j.core.LoggerContext; import org.apache.logging.log4j.message.MessageFactory; import org.apache.logging.log4j.message.ParameterizedMessageFactory; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.TestInfo; import org.junit.jupiter.api.io.CleanupMode; import org.junit.jupiter.api.io.TempDir; /** * Stresses {@link InternalLoggerRegistry} with high contention to spot deadlocks. * * @see #3399 */ class InternalLoggerRegistryConcurrencyTest { private static final Random RANDOM = new Random(0); private static final MessageFactory MESSAGE_FACTORY = ParameterizedMessageFactory.INSTANCE; private static final List LOGGER_NAMES = createLoggerNames(); private static final InternalLoggerRegistry REGISTRY = new InternalLoggerRegistry(); @SuppressWarnings("SameParameterValue") private static List createLoggerNames() { // High cardinality in logger names creates GC pressure due to lack of a mechanism to expunge stale entries[1]. // High GC pressure might void the contention this test is supposed to deliver. // Hence, intentionally keeping the logger name cardinality low. // // [1] https://github.com/apache/logging-log4j2/issues/3430 final int cardinality = 4096; final int maxFormattedLoggerIndexLength = String.format("%x", cardinality - 1).length(); return IntStream.range(0, cardinality) .mapToObj(loggerIndex -> String.format("com.example.Foo_%0" + maxFormattedLoggerIndexLength + "x", loggerIndex)) .collect(Collectors.toList()); } @Test void stress_InternalLoggerRegistry(TestInfo testInfo, @TempDir(cleanup = CleanupMode.ALWAYS) Path tempDir) throws Exception { // Choose a "good enough" concurrency final int concurrency = Math.max(32, 2 * Runtime.getRuntime().availableProcessors()); // Create worker thread resources try (final LoggerContext loggerContext = new LoggerContext(testInfo.getDisplayName()); final BlackHole blackHole = new BlackHole(tempDir.resolve("blackHole.out"))) { final ExecutorService executor = Executors.newFixedThreadPool(concurrency); final BiFunction loggerSupplier = createLoggerSupplier(loggerContext, blackHole, executor); // Start worker threads final CountDownLatch threadCompletionLatch = new CountDownLatch(concurrency); long durationSeconds = 30; final long maxInstantNanos = System.nanoTime() + Duration.ofSeconds(durationSeconds).toNanos(); final int maxFormattedThreadIndexLength = String.format("%x", concurrency - 1).length(); final List threads = IntStream.range(0, concurrency) .mapToObj(threadIndex -> { final String threadName = String.format( "%s-Stressor-%0" + maxFormattedThreadIndexLength + "x", testInfo, threadIndex); final Runnable threadTask = () -> doRegistryOpUntil(blackHole, loggerSupplier, threadCompletionLatch, maxInstantNanos); Thread thread = new Thread(threadTask, threadName); thread.setDaemon(true); // Avoid blocking JVM exit thread.start(); return thread; }) .collect(Collectors.toList()); // Verify completion in time, that is, no deadlocks, etc. try { long awaitThresholdSeconds = 1; long awaitDurationSeconds = durationSeconds + awaitThresholdSeconds; boolean completed = threadCompletionLatch.await(awaitDurationSeconds, TimeUnit.SECONDS); assertThat(completed) .as( "Have worker threads allowed to run for %d seconds, completed in %d seconds?", durationSeconds, awaitDurationSeconds) .isTrue(); } // Stop threads finally { threads.forEach(Thread::interrupt); executor.shutdownNow(); } } } private static BiFunction createLoggerSupplier( final LoggerContext loggerContext, final BlackHole blackHole, final ExecutorService executor) { return (loggerName, messageFactory) -> { // Imitate circular `computeIfAbsent()` code paths *using a different thread* final Future otherLoggerFuture = executor.submit(() -> { String otherLoggerName; do { otherLoggerName = chooseLoggerName(); } while (otherLoggerName.equals(loggerName)); final Logger otherLogger = loggerContext.getLogger(otherLoggerName, MESSAGE_FACTORY); blackHole.consume(otherLogger); }); assertThatCode(() -> otherLoggerFuture.get(3, TimeUnit.SECONDS)).doesNotThrowAnyException(); // Create the logger return new Logger(loggerContext, loggerName, messageFactory) {}; }; } private static void doRegistryOpUntil( final BlackHole blackHole, final BiFunction loggerSupplier, final CountDownLatch completionLatch, final long maxInstantNanos) { while (System.nanoTime() < maxInstantNanos) { doRegistryOp(blackHole, loggerSupplier); } completionLatch.countDown(); } private static void doRegistryOp( final BlackHole blackHole, final BiFunction loggerSupplier) { final boolean readOnly = RANDOM.nextFloat() < 0.95; // 95% chance for reads if (readOnly) { doRegistryRead(blackHole); } else { doRegistryWrite(blackHole, loggerSupplier); } } private static void doRegistryRead(final BlackHole blackHole) { final String loggerName = chooseLoggerName(); // All other read-only operations delegate to `getLogger()` eventually. // Hence it is okay to only have `getLogger()` as the one and only read-only operation. final Logger logger = REGISTRY.getLogger(loggerName, MESSAGE_FACTORY); blackHole.consume(logger); } private static void doRegistryWrite( final BlackHole blackHole, final BiFunction loggerSupplier) { final String loggerName = chooseLoggerName(); final Logger logger = REGISTRY.computeIfAbsent(loggerName, MESSAGE_FACTORY, loggerSupplier); blackHole.consume(logger); } private static String chooseLoggerName() { final int loggerNameIndex = RANDOM.nextInt(LOGGER_NAMES.size()); return LOGGER_NAMES.get(loggerNameIndex); } /** * A very shameful attempt for cloning JMH black holes. */ @SuppressWarnings("NonAtomicOperationOnVolatileField") // Accuracy is not a concern private static final class BlackHole implements AutoCloseable { private volatile int sum = 0; private final Path filePath; private BlackHole(Path filePath) { this.filePath = filePath; } private void consume(final Logger logger) { sum += logger != null && logger.getMessageFactory() == MESSAGE_FACTORY ? 1 : 2; } @Override public void close() throws IOException { Files.write(filePath, ("" + sum).getBytes(US_ASCII)); } } }