You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@solr.apache.org by ho...@apache.org on 2021/11/24 19:27:35 UTC
[solr] branch main updated: SOLR-15807: New LogListener class for tests to use to make assertions about what Log messages should or should not be produced by a test
This is an automated email from the ASF dual-hosted git repository.
hossman pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/solr.git
The following commit(s) were added to refs/heads/main by this push:
new 67b1323 SOLR-15807: New LogListener class for tests to use to make assertions about what Log messages should or should not be produced by a test
67b1323 is described below
commit 67b1323f1c6aa451da5970daf3f4480e72bb0e38
Author: Chris Hostetter <ho...@apache.org>
AuthorDate: Wed Nov 24 12:27:24 2021 -0700
SOLR-15807: New LogListener class for tests to use to make assertions about what Log messages should or should not be produced by a test
---
solr/CHANGES.txt | 2 +
.../org/apache/solr/handler/TestRequestId.java | 71 ++-
.../java/org/apache/solr/util/ErrorLogMuter.java | 2 +
.../org/apache/solr/util/Log4jListAppender.java | 79 ----
.../src/java/org/apache/solr/util/LogListener.java | 511 +++++++++++++++++++++
.../org/apache/solr/util/TestErrorLogMuter.java | 86 ++--
6 files changed, 586 insertions(+), 165 deletions(-)
diff --git a/solr/CHANGES.txt b/solr/CHANGES.txt
index 27c3db8..1b151c1 100644
--- a/solr/CHANGES.txt
+++ b/solr/CHANGES.txt
@@ -409,6 +409,8 @@ Other Changes
* SOLR-15808: [Docker] The jattach tool is now installed with apt (janhoy)
+* SOLR-15807: New LogListener class for tests to use to make assertions about what Log messages should or should not be produced by a test (hossman)
+
Bug Fixes
---------------------
* SOLR-14546: Fix for a relatively hard to hit issue in OverseerTaskProcessor that could lead to out of order execution
diff --git a/solr/core/src/test/org/apache/solr/handler/TestRequestId.java b/solr/core/src/test/org/apache/solr/handler/TestRequestId.java
index ce819d2..8390d7f 100644
--- a/solr/core/src/test/org/apache/solr/handler/TestRequestId.java
+++ b/solr/core/src/test/org/apache/solr/handler/TestRequestId.java
@@ -24,13 +24,9 @@ import org.apache.solr.common.util.SuppressForbidden;
import org.apache.solr.common.SolrException.ErrorCode;
import org.apache.solr.core.SolrCore;
import org.apache.solr.handler.RequestHandlerBase;
-import org.apache.solr.util.LogLevel;
-import org.apache.solr.util.Log4jListAppender;
+import org.apache.solr.util.LogListener;
import org.apache.solr.SolrTestCaseJ4;
-import org.apache.logging.log4j.Level;
-import org.apache.logging.log4j.core.LoggerContext;
-
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
@@ -39,7 +35,7 @@ import org.junit.BeforeClass;
import static org.hamcrest.core.StringContains.containsString;
-@SuppressForbidden(reason="We need to use log4J2 classes directly to check that the MDC is working")
+@SuppressForbidden(reason="We need to use log4J2 classes directly to test MDC impacts")
public class TestRequestId extends SolrTestCaseJ4 {
private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
@@ -49,19 +45,9 @@ public class TestRequestId extends SolrTestCaseJ4 {
initCore("solrconfig.xml","schema.xml");
}
- // NOTE: Explicitly configuring these so we know they have a LoggerConfig we can attach an appender to...
- @LogLevel("org.apache.solr.core.SolrCore.Request=INFO;org.apache.solr.handler.RequestHandlerBase=INFO")
public void testRequestId() {
- final String reqLogName = SolrCore.class.getName() + ".Request";
- final String errLogName = RequestHandlerBase.class.getName();
-
- final Log4jListAppender reqLog = new Log4jListAppender("req-log");
- final Log4jListAppender errLog = new Log4jListAppender("err-log");
- try {
- LoggerContext.getContext(false).getConfiguration().getLoggerConfig(reqLogName).addAppender(reqLog, Level.INFO, null);
- LoggerContext.getContext(false).getConfiguration().getLoggerConfig(errLogName).addAppender(errLog, Level.ERROR, null);
- LoggerContext.getContext(false).updateLoggers();
+ try (LogListener reqLog = LogListener.info(SolrCore.class.getName() + ".Request")) {
// Sanity check that the our MDC doesn't already have some sort of rid set in it
assertNull(MDC.get(CommonParams.REQUEST_ID));
@@ -71,32 +57,35 @@ public class TestRequestId extends SolrTestCaseJ4 {
// Sanity check that the test framework didn't let our "request" MDC info "leak" out of assertQ..
assertNull(MDC.get(CommonParams.REQUEST_ID));
-
- assertEquals(1, reqLog.getEvents().size());
- assertEquals("xxx", reqLog.getEvents().get(0).getContextData().getValue("rid"));
- assertEquals(0, errLog.getEvents().size());
-
- // reques that should cause some ERROR logging...
- // NOTE: we can't just listen for errors at the 'root' logger because assertQEx will 'mute' them before appenders get them
- assertQEx("yyy", "bogus_yyy", req("q", "*:*", "sort", "bogus_yyy", CommonParams.REQUEST_ID, "yyy"), ErrorCode.BAD_REQUEST);
+ {
+ var reqEvent = reqLog.getQueue().poll();
+ assertNotNull(reqEvent);
+ assertEquals("xxx", reqEvent.getContextData().getValue("rid"));
+ assertTrue(reqLog.getQueue().isEmpty());
+ }
+
+ // request that should cause some ERROR logging...
+ // NOTE: we can't just listen for errors at the 'root' logger because assertQEx will 'mute' them before we can intercept
+ try (LogListener errLog = LogListener.error(RequestHandlerBase.class)) {
+ assertQEx("yyy", "bogus_yyy", req("q", "*:*", "sort", "bogus_yyy", CommonParams.REQUEST_ID, "yyy"), ErrorCode.BAD_REQUEST);
- // Sanity check that the test framework didn't let our "request" MDC info "leak" out of assertQEx..
- assertNull(MDC.get(CommonParams.REQUEST_ID));
-
- assertEquals(2, reqLog.getEvents().size());
- assertEquals("yyy", reqLog.getEvents().get(1).getContextData().getValue("rid"));
- assertThat(reqLog.getEvents().get(1).getMessage().getFormattedMessage(), containsString("status="+ErrorCode.BAD_REQUEST.code));
-
- assertEquals(1, errLog.getEvents().size());
- assertEquals("yyy", errLog.getEvents().get(0).getContextData().getValue("rid"));
- assertNotNull(errLog.getEvents().get(0).getThrown());
-
-
- } finally {
- LoggerContext.getContext(false).getConfiguration().getLoggerConfig(reqLogName).removeAppender(reqLog.getName());
- LoggerContext.getContext(false).getConfiguration().getLoggerConfig(errLogName).removeAppender(errLog.getName());
- LoggerContext.getContext(false).updateLoggers();
+ // Sanity check that the test framework didn't let our "request" MDC info "leak" out of assertQEx..
+ assertNull(MDC.get(CommonParams.REQUEST_ID));
+
+ {
+ var reqEvent = reqLog.getQueue().poll();
+ assertNotNull(reqEvent);
+ assertEquals("yyy", reqEvent.getContextData().getValue("rid"));
+ assertThat(reqEvent.getMessage().getFormattedMessage(), containsString("status="+ErrorCode.BAD_REQUEST.code));
+ }
+ {
+ var errEvent = errLog.getQueue().poll();
+ assertNotNull(errEvent);
+ assertEquals("yyy", errEvent.getContextData().getValue("rid"));
+ assertNotNull(errEvent.getThrown());
+ }
+ }
}
}
diff --git a/solr/test-framework/src/java/org/apache/solr/util/ErrorLogMuter.java b/solr/test-framework/src/java/org/apache/solr/util/ErrorLogMuter.java
index 089acdd..10871be 100644
--- a/solr/test-framework/src/java/org/apache/solr/util/ErrorLogMuter.java
+++ b/solr/test-framework/src/java/org/apache/solr/util/ErrorLogMuter.java
@@ -152,6 +152,8 @@ public final class ErrorLogMuter implements Closeable, AutoCloseable {
*/
@SuppressForbidden(reason="We need to use log4J2 classes directly to check that the ErrorLogMuter is working")
private static final class StringPredicateErrorOrThrowableFilter extends AbstractFilter implements CountingFilter {
+ // TODO: could probably refactor to share some code with LogListener
+
// This could probably be implemented with a combination of "LevelRangeFilter" and "ConjunctionFilter" if "ConjunctionFilter" existed
// Since it doesn't, we write our own more specialized impl instead of writing & combining multiple generalized versions
diff --git a/solr/test-framework/src/java/org/apache/solr/util/Log4jListAppender.java b/solr/test-framework/src/java/org/apache/solr/util/Log4jListAppender.java
deleted file mode 100644
index 426df2b..0000000
--- a/solr/test-framework/src/java/org/apache/solr/util/Log4jListAppender.java
+++ /dev/null
@@ -1,79 +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.solr.util;
-
-import java.lang.invoke.MethodHandles;
-import java.util.ArrayList;
-import java.util.Collections;
-import java.util.List;
-
-import org.apache.solr.common.util.SuppressForbidden;
-
-import org.apache.logging.log4j.core.LogEvent;
-import org.apache.logging.log4j.core.appender.AbstractAppender;
-import org.apache.logging.log4j.core.config.Property;
-import org.apache.logging.log4j.core.impl.MutableLogEvent;
-
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
-
-/**
- * Maintains an in memory List of log events.
- * <p>
- * Inspired by <code>org.apache.logging.log4j.core.test.appender.ListAppender</code>
- * but we have much simpler needs.
- * </p>
- *
- * TODO: Refactor into something easier to use (SOLR-15629)
- * @lucene.internal
- * @lucene.experimental
- */
-@SuppressForbidden(reason="We need to use log4J2 classes directly to check that the ErrorLogMuter is working")
-public final class Log4jListAppender extends AbstractAppender {
-
- private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
-
- // Use Collections.synchronizedList rather than CopyOnWriteArrayList because we expect
- // more frequent writes than reads.
- private final List<LogEvent> events = Collections.synchronizedList(new ArrayList<>());
- private final List<LogEvent> publicEvents = Collections.unmodifiableList(events);
-
- public Log4jListAppender(final String name) {
- super(name, null, null, true, Property.EMPTY_ARRAY);
- assert null != name;
- this.start();
- }
-
- @Override
- public void append(final LogEvent event) {
- if (event instanceof MutableLogEvent) {
- // must take snapshot or subsequent calls to logger.log() will modify this event
- events.add(((MutableLogEvent) event).createMemento());
- } else {
- events.add(event);
- }
- if (log.isDebugEnabled()) {
- log.debug("{} intercepted a log event (#{})", this.getName(), events.size());
- }
- }
-
- /** Returns an immutable view of captured log events, contents can change as events are logged */
- public List<LogEvent> getEvents() {
- return publicEvents;
- }
-}
diff --git a/solr/test-framework/src/java/org/apache/solr/util/LogListener.java b/solr/test-framework/src/java/org/apache/solr/util/LogListener.java
new file mode 100644
index 0000000..330edaf
--- /dev/null
+++ b/solr/test-framework/src/java/org/apache/solr/util/LogListener.java
@@ -0,0 +1,511 @@
+/*
+ * 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.solr.util;
+import java.lang.invoke.MethodHandles;
+
+import java.io.Closeable;
+
+import java.util.Queue;
+import java.util.regex.Pattern;
+import java.util.function.Predicate;
+
+import java.util.concurrent.ArrayBlockingQueue;
+import java.util.concurrent.atomic.AtomicInteger;
+import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.concurrent.atomic.AtomicReference;
+
+import org.apache.solr.common.util.SuppressForbidden;
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.Marker;
+import org.apache.logging.log4j.core.Filter;
+import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.Logger;
+import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.appender.AbstractAppender;
+import org.apache.logging.log4j.core.config.Property;
+import org.apache.logging.log4j.core.impl.MutableLogEvent;
+import org.apache.logging.log4j.core.config.Configuration;
+import org.apache.logging.log4j.core.config.LoggerConfig;
+import org.apache.logging.log4j.core.filter.AbstractFilter;
+import org.apache.logging.log4j.message.Message;
+
+import static junit.framework.Assert.assertEquals;
+
+/**
+ * <p>
+ * Helper code to listen for {@link LogEvent} messages (via a {@link Queue}) that you expect as a result of the things you are testing,
+ * So you can make assertions about when a particular action should/shouldn't cause Solr to produce a particular Log message
+ * </p>
+ * <code>
+ * // simplest possible usage...
+ * // Listen for any erors from the SolrCore logger, and assert that there are none...
+ * try (LogListener errLog = LogListener.error(SolrCore.class)) {
+ * // ... some test code ...
+ *
+ * assertEquals(0, errLog.getCount());
+ * }
+ *
+ * // You can also use a substring or regex to restrict the messages that are considered,
+ * // and make assertions about the LogEvent's that match...
+ * try (LogListener secWarnLog = LogListener.warn("org.apache.solr.security").substring("PKI")) {
+ * // ... some test code ...
+ *
+ * // convinience method for only dealing with Message String of the LogEvent
+ * assertThat(secWarnLog.pollMessage(), containsString("hoss"));
+ * assertThat(secWarnLog.getQueue().isEmpty()); // no other WARNings matching PKI
+ *
+ * // ... more test code ...
+ *
+ * // More structured inspection of LogEvents...
+ * var logEvent = secWarnLog.getQueue().poll();
+ * assertNotNull(logEvent);
+ * assertEquals("xyz", logEvent.getContextData().getValue("tid")); // check the MDC data
+ * }
+ * </code>
+ *
+ * <p>
+ * Each <code>LogListener</code> captures & queues matching Log events until it is {@link #close()}ed. By default the Queue is bounded
+ * at a max capacity of 100. Regardless of what Queue is used, if a Log event can't be queued (due to capacity limiting), or if events
+ * are still left in the Queue when the listener is closed, then the {@link #close()} method will cause a test failure.
+ * </p>
+ *
+ * <p>
+ * Filtering methods such {@link #substring} and {@link #regex} can be used to restrict which Log events are recorded.
+ * </p>
+ *
+ * <p>
+ * Log messages are only recorded if they <em>strictly</em> match the Level specified, but the Logger "name" specified is matched
+ * hierarchically against any child Loggers (ie: You must know exactly what Log Level you are interested in, but you can capture all
+ * messages from the Loggers under a java package, or from inner classes of a single Logger)
+ * </p>
+ *
+ * <p>
+ * <b>NOTE:</b> You Can <em>not</em> listen for ERROR messages from the root logger (<code>""</code>) If they are being "muted" by {@link ErrorLogMuter}.
+ * </p>
+ */
+@SuppressForbidden(reason="We need to use log4J2 classes directly")
+public final class LogListener implements Closeable, AutoCloseable {
+
+ // far easier to use FQN for our (one) slf4j Logger then to use a FQN every time we refe to log4j2 Logger
+ private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); // nowarn_valid_logger
+
+ private final static LoggerContext CTX = LoggerContext.getContext(false);
+
+ /** @see #createName */
+ private final static AtomicInteger ID_GEN = new AtomicInteger(0);
+ /** generate a unique name for each instance to use in it's own lifecycle logging */
+ private static String createName(final Level level) {
+ return MethodHandles.lookup().lookupClass().getSimpleName() + "-" + level + "-" + ID_GEN.incrementAndGet();
+ }
+
+ /** Listens for ERROR log messages at the ROOT logger */
+ public static LogListener error() {
+ return error("");
+ }
+ /** Listens for ERROR log messages for the specified logger */
+ public static LogListener error(final Class<?> logger) {
+ return error(logger.getName());
+ }
+ /** Listens for ERROR log messages for the specified logger */
+ public static LogListener error(final String logger) {
+ return create(Level.ERROR, logger);
+ }
+
+ /** Listens for WARN log messages at the ROOT logger */
+ public static LogListener warn() {
+ return warn("");
+ }
+ /** Listens for WARN log messages for the specified logger */
+ public static LogListener warn(final Class<?> logger) {
+ return warn(logger.getName());
+ }
+ /** Listens for WARN log messages for the specified logger */
+ public static LogListener warn(final String logger) {
+ return create(Level.WARN, logger);
+ }
+
+ /** Listens for INFO log messages at the ROOT logger */
+ public static LogListener info() {
+ return info("");
+ }
+ /** Listens for INFO log messages for the specified logger */
+ public static LogListener info(final Class<?> logger) {
+ return info(logger.getName());
+ }
+ /** Listens for INFO log messages for the specified logger */
+ public static LogListener info(final String logger) {
+ return create(Level.INFO, logger);
+ }
+
+ // TODO: more factories for other levels?
+ // TODO: no-arg factory variants that use "" -- simpler syntax for ROOT logger?
+
+ private static LogListener create(final Level level, final String logger) {
+ final String name = createName(level);
+ log.info("Creating {} for log messages from: {}", name, logger);
+ return new LogListener(name, logger, level);
+ }
+
+
+ private final String name;
+ private final String loggerName;
+ private final boolean removeLoggerConfigWhenDone;
+ private final Level resetLevelWhenDone;
+ private final AtomicBoolean closed = new AtomicBoolean(false);
+ private final MutablePredicateFilter filter;
+ private final QueueAppender loggerAppender;
+
+ private LogListener(final String name, final String loggerName, final Level level) {
+ assert null != name;
+ assert null != loggerName;
+ assert null != level;
+
+ this.name = name;
+ this.loggerName = loggerName;
+
+ final Configuration config = CTX.getConfiguration();
+
+ // This may match loggerName, or it may be the 'nearest parent' if nothing is explicitly configured for loggerName
+ LoggerConfig loggerConfig = config.getLoggerConfig(loggerName);
+
+ // if loggerConfig refers to our nearest parent logger, then we don't have an existing LoggerConfig for this specific loggerName
+ // so we have to add one (and remember to clean it up later)
+ this.removeLoggerConfigWhenDone = ! loggerName.equals(loggerConfig.getName());
+ if ( this.removeLoggerConfigWhenDone ) {
+ // NOTE: By default inherit the same level as our existing "parent" level so we don't spam our parent (nor hide less specific messages)
+ loggerConfig = new LoggerConfig(loggerName, null, true);
+ config.addLogger(loggerName, loggerConfig);
+ }
+
+ // Regardless of wether loggerConfig exactly matches loggerName, or is an ancestor, if it's level is (strictly) more specific
+ // then our configured level, it will be impossible to listen for the events we want - so track the original level and modify as needed...
+ // NOTE: can't use isMoreSpecificThan because it's not strict...
+ this.resetLevelWhenDone = loggerConfig.getLevel().intLevel() < level.intLevel() ? loggerConfig.getLevel() : null;
+ if ( null != this.resetLevelWhenDone ) {
+ log.info("{} (temporarily) increasing level of {} to {} in order to record matching logs", this.name, this.loggerName, level);
+ loggerConfig.setLevel(level);
+ }
+
+
+ // Note: we don't just pass our level to addAppender, because that would only require it be "as specifc"
+ // we use a wrapper that requres an exact level match (and other predicates can be added to this filter later)...
+ this.filter = new MutablePredicateFilter(level);
+ this.loggerAppender = new QueueAppender(name);
+
+ loggerConfig.addAppender(loggerAppender, level, filter);
+ CTX.updateLoggers();
+ }
+
+
+ public void close() {
+ if (! closed.getAndSet(true)) { // Don't muck with log4j if we accidently get a double close
+ final LoggerConfig loggerConfig = CTX.getConfiguration().getLoggerConfig(loggerName);
+ loggerConfig.removeAppender(loggerAppender.getName());
+ if ( null != resetLevelWhenDone ) {
+ loggerConfig.setLevel(resetLevelWhenDone);
+ }
+ if ( removeLoggerConfigWhenDone ) {
+ CTX.getConfiguration().removeLogger(loggerName);
+ }
+ if (log.isInfoEnabled()) {
+ log.info("Closing {} after recording {} log messages", this.name, getCount());
+ }
+ assertEquals(this.name + " processed log events that it could not record beause queue capacity was exceeded",
+ 0, loggerAppender.getNumCapacityExceeded());
+ assertEquals(this.name + " recorded log events which were not expected & removed from the queue by the test code",
+ 0, loggerAppender.getQueue().size());
+ }
+ }
+
+ /**
+ * Changes the queue that will be used to record any future events that match
+ * @see #getQueue
+ */
+ public LogListener setQueue(Queue<LogEvent> queue) {
+ loggerAppender.setQueue(queue);
+ return this;
+ }
+
+ /**
+ * Modifies this listener to filter the log events that are recorded to events that match the specified substring.
+ *
+ * <p>
+ * Log events are considered a match if their input matches either the message String, or the <code>toString</code> of an included
+ * {@link Throwable}, or any of the recursive {@link Throwable#getCause}es of an included <code>Throwable</code>.
+ * </p>
+ * <p>
+ * At most one filtering method may be used
+ * </p>
+ */
+ public LogListener substring(final String substr) {
+ setPredicate( (str) -> { return str.contains(substr); });
+ return this;
+ }
+
+ /**
+ * Modifies this listener to filter the log events that are recorded to events that match the specified regex.
+ *
+ * <p>
+ * Log events are considered a match if their input matches either the message String, or the <code>toString</code> of an included
+ * {@link Throwable}, or any of the recursive {@link Throwable#getCause}es of an included <code>Throwable</code>.
+ * </p>
+ * <p>
+ * At most one filtering method may be used
+ * </p>
+ */
+ public LogListener regex(final Pattern pat) {
+ setPredicate( (str) -> { return pat.matcher(str).find(); });
+ return this;
+ }
+
+ /**
+ * Modifies this listener to filter the log events that are recorded to events that match the specified regex.
+ *
+ * <p>
+ * Log events are considered a match if their input matches either the message String, or the <code>toString</code> of an included
+ * {@link Throwable}, or any of the recursive {@link Throwable#getCause}es of an included <code>Throwable</code>.
+ * </p>
+ * <p>
+ * At most one filtering method may be used
+ * </p>
+ */
+ public LogListener regex(final String regex) {
+ return regex(Pattern.compile(regex));
+ }
+
+ /**
+ * @see #regex
+ * @see #substring
+ * @see MutablePredicateFilter#predicate
+ */
+ private void setPredicate(Predicate<String> predicate) {
+ if ( ! this.filter.predicate.compareAndSet((Predicate<String>)null, predicate) ) {
+ throw new IllegalStateException("At most one method to set a message predicate can be called on a LogListener");
+ }
+ }
+
+ /**
+ * Direct access to the Queue of Log events that have been recorded, for {@link Queue#poll}ing messages or any other inspection/manipulation.
+ * <p>
+ * If a Log event is ever processed but can not be added to this queue (because {@link Queue#offer} returns false) then
+ * the {@link #close} method of this listener will fail the test.
+ * </p>
+ *
+ * @see #setQueue
+ * @see #pollMessage
+ */
+ public Queue<LogEvent> getQueue() {
+ return loggerAppender.getQueue();
+ }
+
+ /**
+ * Convinience method for tests that want to assert things about the (formated) message string at the head of the queue,
+ * w/o needing to know/call methods on the underlying {@link LogEvent} class.
+ *
+ * @return the formatted message string of head of the queue, or null if the queue was empty when polled.
+ * @see #getQueue
+ */
+ public String pollMessage() {
+ final LogEvent event = getQueue().poll();
+ return null == event ? null : event.getMessage().getFormattedMessage();
+ }
+
+ /**
+ * The total number of Log events so far processed by this instance, regardless of wether they have already been
+ * removed from the queue, or if they could not be added to the queue due to capacity restrictions.
+ */
+ public int getCount() {
+ return loggerAppender.getCount();
+ }
+
+ /**
+ * A Filter registered with the specified Logger to restrict what Log events we process in our {@link QueueAppender}
+ */
+ @SuppressForbidden(reason="We need to use log4J2 classes directly")
+ private static final class MutablePredicateFilter extends AbstractFilter {
+ // TODO: could probably refactor to share some code with ErrorLogMuter
+
+ // This could probably be implemented with a combination of "LevelMatchFilter" and "ConjunctionFilter" if "ConjunctionFilter" existed
+ // Since it doesn't, we write our own more specialized impl instead of writing & combining multiple generalized versions
+
+ // may be mutated in main thread while background thread is actively logging
+ public final AtomicReference<Predicate<String>> predicate = new AtomicReference<Predicate<String>>(null);
+
+ final Level level;
+
+ public MutablePredicateFilter(final Level level) {
+ super(Filter.Result.ACCEPT, Filter.Result.DENY);
+ assert null != level;
+ this.level = level;
+ }
+
+ // NOTE: This is inspired by log4j's RegexFilter, but with an eye to being more "garbage-free" friendly
+ // Oddly, StringMatchFilter does things differnetly and acts like it needs to (re?) format msgs when params are provided
+ // Since RegexFilter has tests, and StringMatchFilter doesn't, we assume RegexFilter knows what it's doing...
+
+ /** The main logic of our filter: Evaluate predicate against log msg & throwable msg(s) if and only if Level is correct; else mismatch */
+ private Filter.Result doFilter(final Level level, final String msg, final Throwable throwable) {
+ if (level.equals(this.level)) {
+ final Predicate<String> pred = predicate.get(); // read from reference once
+ if (null == pred) {
+ return getOnMatch();
+ } else {
+ if (null != msg && pred.test(msg)) {
+ return getOnMatch();
+ }
+ for (Throwable t = throwable; null != t; t = t.getCause()) {
+ if (pred.test(t.toString())) {
+ return getOnMatch();
+ }
+ }
+ }
+ }
+ return getOnMismatch();
+ }
+
+ public Result filter(Logger logger, Level level, Marker marker, String msg,
+ Object... params) {
+ return doFilter(level, msg, null);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, String msg,
+ Object p0) {
+ return doFilter(level, msg, null);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, String msg,
+ Object p0, Object p1) {
+ return doFilter(level, msg, null);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, String msg,
+ Object p0, Object p1, Object p2) {
+ return doFilter(level, msg, null);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, String msg,
+ Object p0, Object p1, Object p2, Object p3) {
+ return doFilter(level, msg, null);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, String msg,
+ Object p0, Object p1, Object p2, Object p3, Object p4) {
+ return doFilter(level, msg, null);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, String msg,
+ Object p0, Object p1, Object p2, Object p3, Object p4, Object p5) {
+ return doFilter(level,msg, null);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, String msg,
+ Object p0, Object p1, Object p2, Object p3, Object p4, Object p5, Object p6) {
+ return doFilter(level, msg, null);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, String msg,
+ Object p0, Object p1, Object p2, Object p3, Object p4,
+ Object p5, Object p6, Object p7) {
+ return doFilter(level, msg, null);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, String msg,
+ Object p0, Object p1, Object p2, Object p3, Object p4, Object p5, Object p6, Object p7, Object p8) {
+ return doFilter(level, msg, null);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, String msg,
+ Object p0, Object p1, Object p2, Object p3, Object p4, Object p5, Object p6, Object p7, Object p8, Object p9) {
+ return doFilter(level, msg, null);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, Object msg,
+ Throwable t) {
+ return doFilter(level, null == msg ? null : msg.toString(), t);
+ }
+ public Result filter(Logger logger, Level level, Marker marker, Message msg,
+ Throwable t) {
+ return doFilter(level, msg.getFormattedMessage(), t);
+ }
+ public Result filter(LogEvent event) {
+ // NOTE: For our usage, we're not worried about needing to filter LogEvents rom remote JVMs with ThrowableProxy
+ // stand ins for Throwabls that don't exist in our classloader...
+ return doFilter(event.getLevel(),
+ event.getMessage().getFormattedMessage(),
+ event.getThrown());
+ }
+ }
+
+ /**
+ * An Appender registered with the specified Logger to record the Log events that match our {@link MutablePredicateFilter}
+ *
+ * By default, we use a BlockingQueue with a capacity=100
+ */
+ @SuppressForbidden(reason="We need to use log4J2 classes directly")
+ private static final class QueueAppender extends AbstractAppender {
+
+ // may be mutated in main thread while background thread is actively logging
+ private final AtomicReference<Queue<LogEvent>> queue = new AtomicReference<>(new ArrayBlockingQueue<>(100));
+ final AtomicInteger count = new AtomicInteger(0);
+ final AtomicInteger capacityExceeded = new AtomicInteger(0);
+
+ public QueueAppender(final String name) {
+ super(name, null, null, true, Property.EMPTY_ARRAY);
+ assert null != name;
+ this.start();
+ }
+
+ @Override
+ public void append(final LogEvent event) {
+ final Queue<LogEvent> q = queue.get(); // read from reference once
+ final LogEvent memento = (event instanceof MutableLogEvent) ? ((MutableLogEvent) event).createMemento() : event;
+ final int currentCount = count.incrementAndGet();
+ if (q.offer(memento)) {
+ if (log.isDebugEnabled()) {
+ log.debug("{} recorded a log event (#{}; currentSize={})", this.getName(), currentCount, q.size());
+ }
+ } else {
+ final int currentCapacityExceeded = capacityExceeded.incrementAndGet();
+ if (log.isErrorEnabled()) {
+ log.error("{} processed a log event which exceeded capacity and could not be recorded (#{}; currentSize={}; numTimesCapacityExceeded={})",
+ this.getName(), currentCount, q.size(), currentCapacityExceeded);
+ }
+ }
+ }
+
+ /**
+ * The total number of LogEvents processed by this appender (not impacted by when/how changes are made to the queue)
+ */
+ public int getCount() {
+ return count.get();
+ }
+
+ /**
+ * Returns the number of times this appender was unable to queue a LogEvent due to exceeding capacity
+ * @see Queue#offer
+ */
+ public int getNumCapacityExceeded() {
+ return capacityExceeded.get();
+ }
+
+ /**
+ * Changes the queue that will be used for any future events that are appended
+ */
+ public void setQueue(final Queue<LogEvent> q) {
+ assert null != q;
+ this.queue.set(q);
+ }
+
+ /**
+ * Returns Raw access to the (current) queue
+ */
+ public Queue<LogEvent> getQueue() {
+ return queue.get();
+ }
+ }
+
+}
diff --git a/solr/test-framework/src/test/org/apache/solr/util/TestErrorLogMuter.java b/solr/test-framework/src/test/org/apache/solr/util/TestErrorLogMuter.java
index 5a6696e..961c8c8 100644
--- a/solr/test-framework/src/test/org/apache/solr/util/TestErrorLogMuter.java
+++ b/solr/test-framework/src/test/org/apache/solr/util/TestErrorLogMuter.java
@@ -26,9 +26,6 @@ import org.apache.solr.SolrTestCaseJ4;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
-import org.apache.logging.log4j.Level;
-import org.apache.logging.log4j.core.LoggerContext;
-
import static org.hamcrest.core.StringContains.containsString;
@SuppressForbidden(reason="We need to use log4J2 classes directly to check that the ErrorLogMuter is working")
@@ -39,10 +36,8 @@ public class TestErrorLogMuter extends SolrTestCaseJ4 {
@LogLevel("=WARN")
public void testErrorMutingRegex() throws Exception {
- final Log4jListAppender rootSanityCheck = new Log4jListAppender("sanity-checker");
- try {
- LoggerContext.getContext(false).getConfiguration().getRootLogger().addAppender(rootSanityCheck, Level.WARN, null);
- LoggerContext.getContext(false).updateLoggers();
+ try (LogListener rootWarnCheck = LogListener.warn();
+ LogListener rootErrorCheck = LogListener.error()) {
try (ErrorLogMuter x = ErrorLogMuter.regex("eRrOr\\s+Log")) {
assertEquals(0, x.getCount());
@@ -53,31 +48,27 @@ public class TestErrorLogMuter extends SolrTestCaseJ4 {
log.error("This is an {} Log msg that x should not mute", "err");
log.warn("This is an warn message, mentioning 'eRrOr Log', that should also not be muted");
assertEquals(1, x.getCount());
+ // the root logger better have gotten both of those...
+ assertThat(rootErrorCheck.pollMessage(), containsString("should not mute"));
+ assertThat(rootWarnCheck.pollMessage(), containsString("also not be muted"));
log.error("This {} because of the {} msg", "error", "thowable",
new Exception("outer", new Exception("inner eRrOr Log throwable")));
assertEquals(2, x.getCount());
}
- } finally {
- LoggerContext.getContext(false).getConfiguration().getRootLogger().removeAppender(rootSanityCheck.getName());
- LoggerContext.getContext(false).updateLoggers();
- }
- // the root loger should not have seen anything that was muted...
- assertEquals(2, rootSanityCheck.getEvents().size());
- assertThat(rootSanityCheck.getEvents().get(0).getMessage().getFormattedMessage(), containsString("should not mute"));
- assertThat(rootSanityCheck.getEvents().get(1).getMessage().getFormattedMessage(), containsString("also not be muted"));
+ // the root logger must have only gotten the non-muted messages...
+ assertEquals(1, rootErrorCheck.getCount());
+ assertEquals(1, rootWarnCheck.getCount());
+ }
}
@LogLevel("=WARN")
public void testMultipleMuters() throws Exception {
- // Add a Log4jListAppender to our ROOT logger so we can sanity check what log messages it gets
- final Log4jListAppender rootSanityCheck = new Log4jListAppender("sanity-checker");
- try {
- LoggerContext.getContext(false).getConfiguration().getRootLogger().addAppender(rootSanityCheck, Level.WARN, null);
- LoggerContext.getContext(false).updateLoggers();
+ try (LogListener rootWarnCheck = LogListener.warn().substring("xxx");
+ LogListener rootErrorCheck = LogListener.error()) {
// sanity check that muters "mute" in the order used...
// (If this fails, then it means log4j has changed the precedence order it uses when addFilter is called,
@@ -91,55 +82,60 @@ public class TestErrorLogMuter extends SolrTestCaseJ4 {
log.error("xx{} ", "x");
log.error(" yyy");
log.error("xxx yyy");
+
+ // a warning shouldn't be muted...
log.warn("xxx yyy");
+ assertEquals(rootWarnCheck.pollMessage(), "xxx yyy");
+
log.error("abc", new Exception("yyy"));
assertEquals(2, x.getCount()); // x is first, so it swallows up the "x + y" message
assertEquals(2, y.getCount()); // doesn't get anything x already got
assertEquals(0, z.getCount()); // doesn't get anything x already got
}
- } finally {
- LoggerContext.getContext(false).getConfiguration().getRootLogger().removeAppender(rootSanityCheck.getName());
- LoggerContext.getContext(false).updateLoggers();
+
+ // the root logger must have only gotten the non-muted messages...
+ assertEquals(1, rootWarnCheck.getCount());
+ assertEquals(0, rootErrorCheck.getCount());
}
-
- assertEquals(1, rootSanityCheck.getEvents().size()); // our warning
}
@LogLevel("=WARN")
public void testDeprecatedBaseClassMethods() throws Exception {
-
- // Add a Log4jListAppender to our ROOT logger so we can sanity check what log messages it gets
- final Log4jListAppender rootSanityCheck = new Log4jListAppender("sanity-checker");
- try {
- LoggerContext.getContext(false).getConfiguration().getRootLogger().addAppender(rootSanityCheck, Level.WARN, null);
- LoggerContext.getContext(false).updateLoggers();
-
+
+ // NOTE: using the same queue for both interceptors (mainly as proof that you can)
+ try (LogListener rootWarnCheck = LogListener.warn();
+ LogListener rootErrorCheck = LogListener.error().setQueue(rootWarnCheck.getQueue())) {
+
log.error("this matches the default ignore_exception pattern");
- log.error("something matching foo that should make it"); // 1
- assertEquals(1, rootSanityCheck.getEvents().size());
+ log.error("something matching foo that should make it"); // E1
+ assertEquals(1, rootErrorCheck.getCount());
+ assertThat(rootErrorCheck.pollMessage(), containsString("should make it"));
ignoreException("foo");
log.error("something matching foo that should NOT make it");
ignoreException("foo");
ignoreException("ba+r");
log.error("something matching foo that should still NOT make it");
log.error("something matching baaaar that should NOT make it");
- log.warn("A warning should be fine even if it matches ignore_exception and foo and bar"); // 2
- assertEquals(2, rootSanityCheck.getEvents().size());
+ log.warn("A warning should be fine even if it matches ignore_exception and foo and bar"); // W1
+ assertEquals(1, rootErrorCheck.getCount());
+ assertEquals(1, rootWarnCheck.getCount());
+ assertThat(rootErrorCheck.pollMessage(), containsString("should be fine"));
unIgnoreException("foo");
- log.error("another thing matching foo that should make it"); // 3
- assertEquals(3, rootSanityCheck.getEvents().size());
+ log.error("another thing matching foo that should make it"); // E2
+ assertEquals(2, rootErrorCheck.getCount());
+ assertThat(rootErrorCheck.pollMessage(), containsString("another thing"));
log.error("something matching baaaar that should still NOT make it");
+ assertEquals(2, rootErrorCheck.getCount());
resetExceptionIgnores();
log.error("this still matches the default ignore_exception pattern");
- log.error("but something matching baaaar should make it now"); // 4
- assertEquals(4, rootSanityCheck.getEvents().size());
-
- } finally {
- LoggerContext.getContext(false).getConfiguration().getRootLogger().removeAppender(rootSanityCheck.getName());
- LoggerContext.getContext(false).updateLoggers();
+ log.error("but something matching baaaar should make it now"); // E3
+ assertThat(rootErrorCheck.pollMessage(), containsString("should make it now"));
+
+ // the root logger must have only gotten the non-muted messages...
+ assertEquals(3, rootErrorCheck.getCount());
+ assertEquals(1, rootWarnCheck.getCount());
}
- assertEquals(4, rootSanityCheck.getEvents().size());
}
}