ARTEMIS-5132: consolidate ActiveMQQueueLogger into ActiveMQServerLogger

This commit is contained in:
Robbie Gemmell 2024-10-28 11:43:56 +00:00 committed by Justin Bertram
parent 0afab64f64
commit 422446e033
9 changed files with 179 additions and 61 deletions

View File

@ -53,5 +53,8 @@ public @interface LogMessage {
TRACE;
}
/**
* Override the default LogBundle-wide logger name for this message.
*/
String loggerName() default "";
}

View File

@ -373,6 +373,16 @@ public class LogAnnotationProcessor extends AbstractProcessor {
processedMessages.put(messageAnnotation.id(), messageAnnotation.value());
final String loggerFieldName;
if (messageAnnotation.loggerName().isBlank()) {
loggerFieldName = "logger";
} else {
loggerFieldName = "logger_" + messageAnnotation.id();
writerOutput.println(" private static final Logger " + loggerFieldName + " = LoggerFactory.getLogger(\"" + messageAnnotation.loggerName() + "\");");
writerOutput.println();
}
// This is really a debug output
writerOutput.println(" // " + encodeSpecialChars(messageAnnotation.toString()));
writerOutput.println(" @Override");
@ -420,12 +430,12 @@ public class LogAnnotationProcessor extends AbstractProcessor {
final String methodName = getLoggerOutputMethodName(messageAnnotation);
final String formattingString = encodeSpecialChars(bundleAnnotation.projectCode() + messageAnnotation.id() + ": " + messageAnnotation.value());
writerOutput.println(" if (logger." + isEnabledMethodName + "()) {");
writerOutput.println(" if (" + loggerFieldName + "." + isEnabledMethodName + "()) {");
if (hasParameters) {
writerOutput.println(" logger." + methodName + "(\"" + formattingString + "\", " + callList + ");");
writerOutput.println(" " + loggerFieldName + "." + methodName + "(\"" + formattingString + "\", " + callList + ");");
} else {
writerOutput.println(" logger." + methodName + "(\"" + formattingString + "\");");
writerOutput.println(" " + loggerFieldName + "." + methodName + "(\"" + formattingString + "\");");
}
writerOutput.println(" }");

View File

@ -82,8 +82,16 @@ public interface SimpleBundle {
@LogMessage(id = 14, value = "An Exceptional example", level = LogMessage.Level.WARN)
void onlyException(MyException e);
@GetLogger
Logger getLogger();
String LOGGER_NAME_OVERRIDE_PARAMS = "org.apache.activemq.artemis.logs.annotation.processor.SimpleBundle.OVERRIDE.PARAMS";
@LogMessage(id = 15, value = "Logger name overridden to add .OVERRIDE.PARAMS suffix. {}", loggerName = LOGGER_NAME_OVERRIDE_PARAMS, level = LogMessage.Level.WARN)
void overrideLoggerNameWithParameter(String parameter);
String LOGGER_NAME_OVERRIDE_NO_PARAMS = "org.apache.activemq.artemis.logs.annotation.processor.SimpleBundle.OVERRIDE.NO_PARAMS";
@LogMessage(id = 16, value = "Logger name overridden to add .OVERRIDE.NO_PARAMS suffix.", loggerName = LOGGER_NAME_OVERRIDE_NO_PARAMS, level = LogMessage.Level.WARN)
void overrideLoggerNameWithoutParameter();
}

View File

@ -25,10 +25,14 @@ import static org.junit.jupiter.api.Assertions.assertTrue;
import java.io.IOException;
import java.io.PrintWriter;
import java.io.StringWriter;
import java.util.List;
import java.util.UUID;
import org.junit.jupiter.api.Test;
import org.slf4j.Logger;
import org.apache.activemq.artemis.logs.AssertionLoggerHandler;
import org.apache.activemq.artemis.logs.AssertionLoggerHandler.LogEntry;
import org.apache.activemq.artemis.logs.AssertionLoggerHandler.LogLevel;
public class SimpleBundleTest {
@ -60,10 +64,31 @@ public class SimpleBundleTest {
}
@Test
public void testPrint() {
SimpleBundle.MESSAGES.printMessage();
for (int i = 0; i < 10; i++) {
SimpleBundle.MESSAGES.printMessage(i);
public void testPrint() throws IOException {
try (AssertionLoggerHandler logHandler = new AssertionLoggerHandler()) {
SimpleBundle.MESSAGES.printMessage();
for (int i = 0; i < 10; i++) {
SimpleBundle.MESSAGES.printMessage(i);
}
assertEquals(11, logHandler.getNumberOfMessages());
assertEquals(11, logHandler.countText("This is a print!!!"));
String expectedMessage1 = "TST5: This is a print!!!";
assertTrue(logHandler.findText(expectedMessage1), "message not found in logs");
String expectedMessage2prefix = "TST6: This is a print!!! ";
for (int i = 0; i < 10; i++) {
assertTrue(logHandler.findText(expectedMessage2prefix + i), "message not found in logs");
}
List<LogEntry> entries = logHandler.getLogEntries();
assertEquals(11, entries.size());
entries.forEach(entry -> {
assertEquals(SimpleBundle.class.getName(), entry.getLoggerName(), "logger name not as expected");
});
}
}
@ -141,6 +166,48 @@ public class SimpleBundleTest {
@Test
public void testGetLogger() {
assertNotNull(SimpleBundle.MESSAGES.getLogger());
Logger logger = SimpleBundle.MESSAGES.getLogger();
assertNotNull(logger);
assertEquals(SimpleBundle.class.getName(), logger.getName());
}
@Test
public void testLoggerNameOverrideWithParameters() throws Exception {
try (AssertionLoggerHandler logHandler = new AssertionLoggerHandler()) {
SimpleBundle.MESSAGES.overrideLoggerNameWithParameter("BREADCRUMB");
final String expectedMessage = "TST15: Logger name overridden to add .OVERRIDE.PARAMS suffix. BREADCRUMB";
assertTrue(logHandler.findText(expectedMessage), "message not found in logs");
assertEquals(1, logHandler.getNumberOfMessages());
List<LogEntry> entries = logHandler.getLogEntries();
assertEquals(1, entries.size());
LogEntry entry = entries.get(0);
assertEquals(expectedMessage, entry.getMessage(), "message not as expected");
assertEquals(LogLevel.WARN, entry.getLogLevel(), "level not as expected");
assertEquals(SimpleBundle.LOGGER_NAME_OVERRIDE_PARAMS, entry.getLoggerName(), "logger name not as expected");
}
}
@Test
public void testLoggerNameOverrideWithoutParameters() throws Exception {
try (AssertionLoggerHandler logHandler = new AssertionLoggerHandler()) {
SimpleBundle.MESSAGES.overrideLoggerNameWithoutParameter();
final String expectedMessage = "TST16: Logger name overridden to add .OVERRIDE.NO_PARAMS suffix.";
assertTrue(logHandler.findText(expectedMessage), "message not found in logs");
assertEquals(1, logHandler.getNumberOfMessages());
List<LogEntry> entries = logHandler.getLogEntries();
assertEquals(1, entries.size());
LogEntry entry = entries.get(0);
assertEquals(expectedMessage, entry.getMessage(), "message not as expected");
assertEquals(LogLevel.WARN, entry.getLogLevel(), "level not as expected");
assertEquals(SimpleBundle.LOGGER_NAME_OVERRIDE_NO_PARAMS, entry.getLoggerName(), "logger name not as expected");
}
}
}

View File

@ -1,40 +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.activemq.artemis.core.server;
import org.apache.activemq.artemis.logs.BundleFactory;
import org.apache.activemq.artemis.logs.annotation.LogBundle;
import org.apache.activemq.artemis.logs.annotation.LogMessage;
/**
* This is using a separate Logger specific for Queue / QueueImpl.
* It's using Queue.class.getName() as the category as it would be possible to disable this logger with log4j.
* This is sharing the codes with ActiveMQServerLogger (meaning the codes between here and ActiveMQServerLogger have to be unique).
*/
@LogBundle(projectCode = "AMQ", regexID = "22[0-9]{4}")
public interface ActiveMQQueueLogger {
ActiveMQQueueLogger LOGGER = BundleFactory.newBundle(ActiveMQQueueLogger.class, Queue.class.getName());
@LogMessage(id = 224127, value = "Message dispatch from paging is blocked. Address {}/Queue {} will not read any more messages from paging until pending messages are acknowledged. There are currently {} messages pending ({} bytes) with max reads at maxPageReadMessages({}) and maxPageReadBytes({}). Either increase reading attributes at the address-settings or change your consumers to acknowledge more often.", level = LogMessage.Level.WARN)
void warnPageFlowControl(String address,
String queue,
long messageCount,
long messageBytes,
long maxMessages,
long maxMessagesBytes);
}

View File

@ -51,9 +51,11 @@ import org.apache.activemq.artemis.spi.core.remoting.Connection;
/**
* Logger Codes 220000 - 228999
*/
@LogBundle(projectCode = "AMQ", regexID = "22[0-8][0-9]{3}", retiredIDs = {221026, 221052, 222012, 222020, 222021, 222022, 222024, 222027, 222028, 222029, 222052, 222071, 222078, 222079, 222083, 222084, 222088, 222090, 222102, 222128, 222134, 222135, 222152, 222159, 222163, 222167, 222170, 222171, 222182, 222192, 222193, 222204, 222252, 222255, 222257, 222259, 222260, 222288, 224001, 224002, 224003, 224005, 224035, 224100, 224121, 224127})
@LogBundle(projectCode = "AMQ", regexID = "22[0-8][0-9]{3}", retiredIDs = {221026, 221052, 222012, 222020, 222021, 222022, 222024, 222027, 222028, 222029, 222052, 222071, 222078, 222079, 222083, 222084, 222088, 222090, 222102, 222128, 222134, 222135, 222152, 222159, 222163, 222167, 222170, 222171, 222182, 222192, 222193, 222204, 222252, 222255, 222257, 222259, 222260, 222288, 224001, 224002, 224003, 224005, 224035, 224100, 224121})
public interface ActiveMQServerLogger {
// Note: logger ID 224127 uses "org.apache.activemq.artemis.core.server.Queue" for its logger category, rather than ActiveMQServerLogger.class.getPackage().getName()
ActiveMQServerLogger LOGGER = BundleFactory.newBundle(ActiveMQServerLogger.class, ActiveMQServerLogger.class.getPackage().getName());
@LogMessage(id = 223000, value = "Received Interrupt Exception whilst waiting for component to shutdown: {}", level = LogMessage.Level.DEBUG)
@ -1439,7 +1441,12 @@ public interface ActiveMQServerLogger {
@LogMessage(id = 224126, value = "Failure during protocol handshake on connection to {} from {}", level = LogMessage.Level.ERROR)
void failureDuringProtocolHandshake(SocketAddress localAddress, SocketAddress remoteAddress, Throwable e);
// notice loggerID=224127 is reserved as it's been used at ActiveMQQueueLogger
// Note the custom loggerName rather than the overall LogBundle-wide definition used by other methods.
@LogMessage(id = 224127, value = "Message dispatch from paging is blocked. Address {}/Queue {} will not read any more messages from paging until pending messages are acknowledged. "
+ "There are currently {} messages pending ({} bytes) with max reads at maxPageReadMessages({}) and maxPageReadBytes({}). "
+ "Either increase reading attributes at the address-settings or change your consumers to acknowledge more often.",
loggerName = "org.apache.activemq.artemis.core.server.Queue", level = LogMessage.Level.WARN)
void warnPageFlowControl(String address, String queue, long messageCount, long messageBytes, long maxMessages, long maxMessagesBytes);
@LogMessage(id = 224128, value = "Free storage space is at {} which is below the configured <min-disk-free>. System will start blocking producers.", level = LogMessage.Level.WARN)
void minDiskFreeReached(String usableSpace);

View File

@ -77,7 +77,6 @@ import org.apache.activemq.artemis.core.postoffice.impl.LocalQueueBinding;
import org.apache.activemq.artemis.core.postoffice.impl.PostOfficeImpl;
import org.apache.activemq.artemis.core.remoting.server.RemotingService;
import org.apache.activemq.artemis.core.server.ActiveMQMessageBundle;
import org.apache.activemq.artemis.core.server.ActiveMQQueueLogger;
import org.apache.activemq.artemis.core.server.ActiveMQServer;
import org.apache.activemq.artemis.core.server.ActiveMQServerLogger;
import org.apache.activemq.artemis.core.server.Consumer;
@ -3401,7 +3400,7 @@ public class QueueImpl extends CriticalComponentImpl implements Queue {
if (!pageFlowControlled && (maxReadBytes > 0 && deliveringMetrics.getPersistentSize() >= maxReadBytes || maxReadMessages > 0 && deliveringMetrics.getMessageCount() >= maxReadMessages)) {
if (System.currentTimeMillis() - pageFlowControlledLastLog > PAGE_FLOW_CONTROL_PRINT_INTERVAL) {
pageFlowControlledLastLog = System.currentTimeMillis();
ActiveMQQueueLogger.LOGGER.warnPageFlowControl(String.valueOf(address), String.valueOf(name), deliveringMetrics.getMessageCount(), deliveringMetrics.getPersistentSize(), maxReadMessages, maxReadBytes);
ActiveMQServerLogger.LOGGER.warnPageFlowControl(String.valueOf(address), String.valueOf(name), deliveringMetrics.getMessageCount(), deliveringMetrics.getPersistentSize(), maxReadMessages, maxReadBytes);
}
if (logger.isDebugEnabled()) {
logger.debug("Message dispatch from paging is blocked. Address {}/Queue{} will not read any more messages from paging " +

View File

@ -16,11 +16,16 @@
*/
package org.apache.activemq.artemis.core.server;
import static org.junit.jupiter.api.Assertions.assertEquals;
import static org.junit.jupiter.api.Assertions.assertNotEquals;
import static org.junit.jupiter.api.Assertions.assertNotNull;
import static org.junit.jupiter.api.Assertions.assertTrue;
import java.util.List;
import org.apache.activemq.artemis.api.core.ActiveMQIllegalStateException;
import org.apache.activemq.artemis.logs.AssertionLoggerHandler;
import org.apache.activemq.artemis.logs.AssertionLoggerHandler.LogEntry;
import org.apache.activemq.artemis.logs.AssertionLoggerHandler.LogLevel;
import org.junit.jupiter.api.AfterAll;
import org.junit.jupiter.api.BeforeAll;
@ -51,6 +56,18 @@ public class ServerLogBundlesTest {
ActiveMQServerLogger.LOGGER.autoRemoveAddress("addressBreadCrumb");
assertTrue(loggerHandler.findText("AMQ224113", "addressBreadCrumb"));
List<LogEntry> entries = loggerHandler.getLogEntries();
assertEquals(1, entries.size());
LogEntry entry = entries.get(0);
assertNotNull(entry.getMessage(), "message not as expected");
assertTrue(entry.getMessage().startsWith("AMQ224113"), "message not as expected");
assertEquals(LogLevel.INFO, entry.getLogLevel(), "level not as expected");
// Check that the expected ActiveMQServerLogger logger name was used.
assertEquals(SERVER_LOGGER, "org.apache.activemq.artemis.core.server");
assertEquals(SERVER_LOGGER, entry.getLoggerName(), "logger name used not as expected");
}
}
@ -66,16 +83,32 @@ public class ServerLogBundlesTest {
}
@Test
public void testActiveMQQueueLogger() throws Exception {
public void testPageFlowControlMethodWithDefinedLoggerName() throws Exception {
int messageCount = 1003;
int messageBytes = 70004;
int maxMessages = 1000;
int maxMessagesBytes = 60001;
try (AssertionLoggerHandler loggerHandler = new AssertionLoggerHandler(true)) {
ActiveMQQueueLogger.LOGGER.warnPageFlowControl("addressBreadCrumb", "queueBreadCrumb", messageCount, messageBytes, maxMessages, maxMessagesBytes);
// This method defines its own logger name, overriding the normal ActiveMQServerLogger-wide logger used
ActiveMQServerLogger.LOGGER.warnPageFlowControl("addressBreadCrumb", "queueBreadCrumb", messageCount, messageBytes, maxMessages, maxMessagesBytes);
assertTrue(loggerHandler.findText("AMQ224127", "addressBreadCrumb", "queueBreadCrumb", String.valueOf(messageCount), String.valueOf(messageBytes), String.valueOf(maxMessages), String.valueOf(maxMessagesBytes)));
List<LogEntry> entries = loggerHandler.getLogEntries();
assertEquals(1, entries.size());
LogEntry entry = entries.get(0);
assertNotNull(entry.getMessage(), "message not as expected");
assertTrue(entry.getMessage().startsWith("AMQ224127"), "message not as expected");
assertEquals(LogLevel.WARN, entry.getLogLevel(), "level not as expected");
// Check that the expected override logger name was used.
assertEquals(QUEUE_LOGGER, "org.apache.activemq.artemis.core.server.Queue");
assertEquals(QUEUE_LOGGER, entry.getLoggerName(), "logger name used not as expected");
assertNotEquals(SERVER_LOGGER, entry.getLoggerName(), "logger name used not as expected");
assertNotEquals(SERVER_LOGGER, QUEUE_LOGGER, "logger names should not be equal");
}
}
}

View File

@ -21,8 +21,10 @@ import java.io.IOException;
import java.io.PrintWriter;
import java.io.StringWriter;
import java.util.Deque;
import java.util.List;
import java.util.concurrent.ConcurrentLinkedDeque;
import java.util.regex.Pattern;
import java.util.stream.Collectors;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
@ -60,11 +62,14 @@ public class AssertionLoggerHandler extends AbstractAppender implements Closeabl
LogEntry logEntry = new LogEntry();
logEntry.message = event.getMessage().getFormattedMessage();
logEntry.level = event.getLevel();
logEntry.loggerName = event.getLoggerName();
if (captureStackTrace && event.getThrown() != null) {
StringWriter stackOutput = new StringWriter();
event.getThrown().printStackTrace(new PrintWriter(stackOutput));
logEntry.stackTrace = stackOutput.toString();
}
messages.addFirst(logEntry);
}
@ -202,13 +207,39 @@ public class AssertionLoggerHandler extends AbstractAppender implements Closeabl
messages.clear();
}
public List<LogEntry> getLogEntries() {
return messages.stream().collect(Collectors.toList());
}
public int getNumberOfMessages() {
return messages.size();
}
private static class LogEntry {
String message;
String stackTrace;
Level level;
public static class LogEntry {
private String message;
private String stackTrace;
private Level level;
private String loggerName;
public String getMessage() {
return message;
}
public LogLevel getLogLevel() {
return LogLevel.fromImplLevel(level);
}
public String getLoggerName() {
return loggerName;
}
/**
* Only useful if {@link AssertionLoggerHandler} was created with
* {@link AssertionLoggerHandler#AssertionLoggerHandler(boolean captureStackTrace)}
* to enable StackTrace collection.
*/
public String getStackTrace() {
return stackTrace;
}
}
}