|
| 1 | +/* |
| 2 | + * Licensed to the Apache Software Foundation (ASF) under one or more |
| 3 | + * contributor license agreements. See the NOTICE file distributed with |
| 4 | + * this work for additional information regarding copyright ownership. |
| 5 | + * The ASF licenses this file to you under the Apache License, Version 2.0 |
| 6 | + * (the "License"); you may not use this file except in compliance with |
| 7 | + * the License. You may obtain a copy of the License at |
| 8 | + * |
| 9 | + * http://www.apache.org/licenses/LICENSE-2.0 |
| 10 | + * |
| 11 | + * Unless required by applicable law or agreed to in writing, software |
| 12 | + * distributed under the License is distributed on an "AS IS" BASIS, |
| 13 | + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| 14 | + * See the License for the specific language governing permissions and |
| 15 | + * limitations under the License. |
| 16 | + */ |
| 17 | +package org.apache.logging.log4j.core.async; |
| 18 | + |
| 19 | +import static org.assertj.core.api.Assertions.assertThat; |
| 20 | + |
| 21 | +import com.lmax.disruptor.RingBuffer; |
| 22 | +import java.util.List; |
| 23 | +import java.util.Optional; |
| 24 | +import java.util.concurrent.CountDownLatch; |
| 25 | +import java.util.stream.Collectors; |
| 26 | +import org.apache.logging.log4j.Level; |
| 27 | +import org.apache.logging.log4j.Logger; |
| 28 | +import org.apache.logging.log4j.core.LoggerContext; |
| 29 | +import org.apache.logging.log4j.core.config.Configuration; |
| 30 | +import org.apache.logging.log4j.core.config.LoggerConfig; |
| 31 | +import org.apache.logging.log4j.core.test.async.BlockingAppender; |
| 32 | +import org.apache.logging.log4j.status.StatusData; |
| 33 | +import org.apache.logging.log4j.test.ListStatusListener; |
| 34 | + |
| 35 | +public abstract class QueueFullAsyncAbstractTest extends QueueFullAbstractTest { |
| 36 | + |
| 37 | + private ListStatusListener statusListener; |
| 38 | + |
| 39 | + protected static void assertAsyncLogger(final LoggerContext ctx, final int expectedBufferSize) { |
| 40 | + assertThat(ctx).isInstanceOf(AsyncLoggerContext.class); |
| 41 | + assertThat(((AsyncLoggerContext) ctx) |
| 42 | + .getAsyncLoggerDisruptor() |
| 43 | + .getRingBuffer() |
| 44 | + .getBufferSize()) |
| 45 | + .isEqualTo(expectedBufferSize); |
| 46 | + |
| 47 | + final Configuration config = ctx.getConfiguration(); |
| 48 | + assertThat(config).isNotNull(); |
| 49 | + assertThat(config.getRootLogger()).isNotInstanceOf(AsyncLoggerConfig.class); |
| 50 | + } |
| 51 | + |
| 52 | + protected static void assertAsyncLoggerConfig(final LoggerContext ctx, final int expectedBufferSize) { |
| 53 | + assertThat(ctx).isNotInstanceOf(AsyncLoggerContext.class); |
| 54 | + |
| 55 | + final Configuration config = ctx.getConfiguration(); |
| 56 | + assertThat(config).isNotNull(); |
| 57 | + assertThat(config.getRootLogger()).isInstanceOf(AsyncLoggerConfig.class); |
| 58 | + final DisruptorConfiguration disruptorConfig = config.getExtension(DisruptorConfiguration.class); |
| 59 | + final AsyncLoggerConfigDisruptor disruptor = |
| 60 | + (AsyncLoggerConfigDisruptor) disruptorConfig.getAsyncLoggerConfigDelegate(); |
| 61 | + assertThat(disruptor.getRingBuffer().getBufferSize()).isEqualTo(expectedBufferSize); |
| 62 | + } |
| 63 | + |
| 64 | + @Override |
| 65 | + protected long asyncRemainingCapacity(final Logger logger) { |
| 66 | + if (logger instanceof final AsyncLogger asyncLogger) { |
| 67 | + return Optional.ofNullable(asyncLogger.getAsyncLoggerDisruptor()) |
| 68 | + .map(AsyncLoggerDisruptor::getRingBuffer) |
| 69 | + .map(RingBuffer::remainingCapacity) |
| 70 | + .orElse(0L); |
| 71 | + } else { |
| 72 | + final LoggerConfig loggerConfig = ((org.apache.logging.log4j.core.Logger) logger).get(); |
| 73 | + if (loggerConfig instanceof final AsyncLoggerConfig asyncLoggerConfig) { |
| 74 | + return Optional.ofNullable( |
| 75 | + (AsyncLoggerConfigDisruptor) asyncLoggerConfig.getAsyncLoggerConfigDelegate()) |
| 76 | + .map(AsyncLoggerConfigDisruptor::getRingBuffer) |
| 77 | + .map(RingBuffer::remainingCapacity) |
| 78 | + .orElse(0L); |
| 79 | + } |
| 80 | + } |
| 81 | + return super.asyncRemainingCapacity(logger); |
| 82 | + } |
| 83 | + |
| 84 | + public void testLoggingFromToStringCausesOutOfOrderMessages( |
| 85 | + final LoggerContext ctx, final BlockingAppender blockingAppender) throws Exception { |
| 86 | + checkConfig(ctx); |
| 87 | + // Non-reusable messages will call `toString()` on the main thread and block it. |
| 88 | + final Logger logger = ctx.getLogger(this.getClass()); |
| 89 | + |
| 90 | + blockingAppender.countDownLatch = new CountDownLatch(1); |
| 91 | + final Unlocker unlocker = new Unlocker(new CountDownLatch(MESSAGE_COUNT - 1), blockingAppender); |
| 92 | + unlocker.start(); |
| 93 | + asyncRecursiveTest(logger, unlocker, blockingAppender); |
| 94 | + unlocker.join(); |
| 95 | + } |
| 96 | + |
| 97 | + void asyncRecursiveTest(final Logger logger, final Unlocker unlocker, final BlockingAppender blockingAppender) { |
| 98 | + for (int i = 0; i < 1; i++) { |
| 99 | + LOGGER.info( |
| 100 | + "Test logging message {}. Ring buffer capacity was {}, countdown latch was {}.", |
| 101 | + i, |
| 102 | + asyncRemainingCapacity(logger), |
| 103 | + unlocker.countDownLatch.getCount()); |
| 104 | + unlocker.countDownLatch.countDown(); |
| 105 | + final DomainObject obj = new DomainObject(logger, unlocker, MESSAGE_COUNT - 1); |
| 106 | + logger.info("Logging naughty object #{}: {}", i, obj); |
| 107 | + } |
| 108 | + |
| 109 | + LOGGER.info( |
| 110 | + "Waiting for message delivery: blockingAppender.logEvents.count={}.", |
| 111 | + blockingAppender.logEvents.size()); |
| 112 | + while (blockingAppender.logEvents.size() < MESSAGE_COUNT) { |
| 113 | + Thread.yield(); |
| 114 | + } |
| 115 | + LOGGER.info( |
| 116 | + "All {} messages have been delivered: blockingAppender.logEvents.count={}.", |
| 117 | + MESSAGE_COUNT, |
| 118 | + blockingAppender.logEvents.size()); |
| 119 | + |
| 120 | + final StatusData mostRecentStatusData = statusListener |
| 121 | + .findStatusData(Level.WARN) |
| 122 | + .reduce((ignored, data) -> data) |
| 123 | + .orElse(null); |
| 124 | + assertThat(mostRecentStatusData).isNotNull(); |
| 125 | + assertThat(mostRecentStatusData.getLevel()).isEqualTo(Level.WARN); |
| 126 | + assertThat(mostRecentStatusData.getFormattedStatus()) |
| 127 | + .contains("Log4j2 logged an event out of order to prevent deadlock caused by domain " |
| 128 | + + "objects logging from their toString method when the async queue is full"); |
| 129 | + |
| 130 | + final List<String> actual = blockingAppender.logEvents.stream() |
| 131 | + .map(e -> e.getMessage().getFormattedMessage()) |
| 132 | + .collect(Collectors.toList()); |
| 133 | + final String[] expected = new String[MESSAGE_COUNT]; |
| 134 | + for (int i = 0; i < MESSAGE_COUNT - 1; i++) { |
| 135 | + expected[i] = "Logging in toString() #" + i; |
| 136 | + } |
| 137 | + expected[MESSAGE_COUNT - 1] = "Logging naughty object #0: Who's bad?!"; |
| 138 | + assertThat(actual).hasSize(MESSAGE_COUNT).contains(expected); |
| 139 | + } |
| 140 | + |
| 141 | + protected class DomainObject { |
| 142 | + |
| 143 | + private final Logger innerLogger; |
| 144 | + private final Unlocker unlocker; |
| 145 | + private final int count; |
| 146 | + |
| 147 | + public DomainObject(final Logger innerLogger, final Unlocker unlocker, final int loggingCount) { |
| 148 | + this.innerLogger = innerLogger; |
| 149 | + this.unlocker = unlocker; |
| 150 | + this.count = loggingCount; |
| 151 | + } |
| 152 | + |
| 153 | + @Override |
| 154 | + public String toString() { |
| 155 | + for (int i = 0; i < count; i++) { |
| 156 | + LOGGER.info( |
| 157 | + "DomainObject logging message {}. Ring buffer capacity was {}, countdown latch was {}.", |
| 158 | + i, |
| 159 | + asyncRemainingCapacity(innerLogger), |
| 160 | + unlocker.countDownLatch.getCount()); |
| 161 | + unlocker.countDownLatch.countDown(); |
| 162 | + innerLogger.info("Logging in toString() #{}", i); |
| 163 | + } |
| 164 | + return "Who's bad?!"; |
| 165 | + } |
| 166 | + } |
| 167 | +} |
0 commit comments