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/12 18:23:53 UTC
[solr] branch main updated: SOLR-15790: SearchHandler now includes
the value in the Logging MDC for the duration of the request,
allowing custom logging configurations to include it.
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 aea698b SOLR-15790: SearchHandler now includes the value in the Logging MDC for the duration of the request, allowing custom logging configurations to include it.
aea698b is described below
commit aea698b79fc4b90a0f73b99af644c18ebdeb2ef3
Author: Chris Hostetter <ho...@apache.org>
AuthorDate: Fri Nov 12 11:23:40 2021 -0700
SOLR-15790: SearchHandler now includes the value in the Logging MDC for the duration of the request, allowing custom logging configurations to include it.
---
solr/CHANGES.txt | 3 +
.../solr/handler/component/SearchHandler.java | 16 +++-
.../org/apache/solr/handler/TestRequestId.java | 103 +++++++++++++++++++++
.../org/apache/solr/util/Log4jListAppender.java | 79 ++++++++++++++++
.../org/apache/solr/util/TestErrorLogMuter.java | 53 +----------
5 files changed, 204 insertions(+), 50 deletions(-)
diff --git a/solr/CHANGES.txt b/solr/CHANGES.txt
index 931a6a7..f3a7fc3 100644
--- a/solr/CHANGES.txt
+++ b/solr/CHANGES.txt
@@ -167,6 +167,9 @@ when told to. The admin UI now tells it to. (Nazerke Seidan, David Smiley)
* SOLR-15705: A delete-by-id command is forwarded to all shards when using the CompositeId router with a router field
and the route is missing from the command. (Michael Kosten via Christine Poerschke, David Smiley, Eric Pugh)
+* SOLR-15790: SearchHandler now includes the `rid` value in the Logging MDC for the duration of the request, allowing custom logging
+ configurations to include it. (hossman)
+
Build
---------------------
diff --git a/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java b/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java
index 0cd3db0..d3a448c 100644
--- a/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java
+++ b/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java
@@ -53,6 +53,7 @@ import org.apache.solr.util.plugin.PluginInfoInitialized;
import org.apache.solr.util.plugin.SolrCoreAware;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
import java.io.PrintWriter;
import java.io.StringWriter;
@@ -290,6 +291,8 @@ public class SearchHandler extends RequestHandlerBase implements SolrCoreAware,
if (rb.requestInfo != null) {
rb.requestInfo.setResponseBuilder(rb);
}
+
+ tagRequestWithRequestId(rb);
boolean dbg = req.getParams().getBool(CommonParams.DEBUG_QUERY, false);
rb.setDebug(dbg);
@@ -324,8 +327,6 @@ public class SearchHandler extends RequestHandlerBase implements SolrCoreAware,
final ShardHandler shardHandler1 = getAndPrepShardHandler(req, rb); // creates a ShardHandler object only if it's needed
- tagRequestWithRequestId(rb);
-
if (timer == null) {
// non-debugging prepare phase
for( SearchComponent c : components ) {
@@ -549,6 +550,17 @@ public class SearchHandler extends RequestHandlerBase implements SolrCoreAware,
final boolean ridTaggingDisabled = rb.req.getParams().getBool(CommonParams.DISABLE_REQUEST_ID, false);
if (! ridTaggingDisabled) {
String rid = getOrGenerateRequestId(rb.req);
+
+ // NOTE: SearchHandler explicitly never clears/removes this MDC value...
+ // We want it to live for the entire request, beyond the scope of SearchHandler's processing, and trust
+ // SolrDispatchFilter to clean it up at the end of the request.
+ //
+ // Examples:
+ // - ERROR logging of Exceptions propogated up to our base class
+ // - SolrCore.RequestLog
+ // - ERRORs that may be logged during response writing
+ MDC.put(CommonParams.REQUEST_ID, rid);
+
if (StringUtils.isBlank(rb.req.getParams().get(CommonParams.REQUEST_ID))) {
ModifiableSolrParams params = new ModifiableSolrParams(rb.req.getParams());
params.add(CommonParams.REQUEST_ID, rid);//add rid to the request so that shards see it
diff --git a/solr/core/src/test/org/apache/solr/handler/TestRequestId.java b/solr/core/src/test/org/apache/solr/handler/TestRequestId.java
new file mode 100644
index 0000000..ce819d2
--- /dev/null
+++ b/solr/core/src/test/org/apache/solr/handler/TestRequestId.java
@@ -0,0 +1,103 @@
+/*
+ * 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.handler;
+
+import java.lang.invoke.MethodHandles;
+
+import org.apache.solr.common.params.CommonParams;
+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.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;
+
+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")
+public class TestRequestId extends SolrTestCaseJ4 {
+
+ private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
+
+ @BeforeClass
+ public static void beforeTests() throws Exception {
+ 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();
+
+ // Sanity check that the our MDC doesn't already have some sort of rid set in it
+ assertNull(MDC.get(CommonParams.REQUEST_ID));
+
+ // simple request that should successfully be logged ...
+ assertQ("xxx", req("q", "*:*", CommonParams.REQUEST_ID, "xxx"), "//*[@numFound='0']");
+
+ // 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);
+
+ // 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();
+ }
+ }
+
+}
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
new file mode 100644
index 0000000..426df2b
--- /dev/null
+++ b/solr/test-framework/src/java/org/apache/solr/util/Log4jListAppender.java
@@ -0,0 +1,79 @@
+/*
+ * 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/test/org/apache/solr/util/TestErrorLogMuter.java b/solr/test-framework/src/test/org/apache/solr/util/TestErrorLogMuter.java
index 7fc062b..5a6696e 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
@@ -18,9 +18,6 @@
package org.apache.solr.util;
import java.lang.invoke.MethodHandles;
-import java.util.ArrayList;
-import java.util.Collections;
-import java.util.List;
import java.util.regex.Pattern;
import org.apache.solr.common.util.SuppressForbidden;
@@ -30,11 +27,7 @@ import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.apache.logging.log4j.Level;
-import org.apache.logging.log4j.core.LogEvent;
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 static org.hamcrest.core.StringContains.containsString;
@@ -46,7 +39,7 @@ public class TestErrorLogMuter extends SolrTestCaseJ4 {
@LogLevel("=WARN")
public void testErrorMutingRegex() throws Exception {
- final ListAppender rootSanityCheck = new ListAppender("sanity-checker");
+ final Log4jListAppender rootSanityCheck = new Log4jListAppender("sanity-checker");
try {
LoggerContext.getContext(false).getConfiguration().getRootLogger().addAppender(rootSanityCheck, Level.WARN, null);
LoggerContext.getContext(false).updateLoggers();
@@ -80,8 +73,8 @@ public class TestErrorLogMuter extends SolrTestCaseJ4 {
@LogLevel("=WARN")
public void testMultipleMuters() throws Exception {
- // Add a ListAppender to our ROOT logger so we can sanity check what log messages it gets
- final ListAppender rootSanityCheck = new ListAppender("sanity-checker");
+ // 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();
@@ -116,8 +109,8 @@ public class TestErrorLogMuter extends SolrTestCaseJ4 {
@LogLevel("=WARN")
public void testDeprecatedBaseClassMethods() throws Exception {
- // Add a ListAppender to our ROOT logger so we can sanity check what log messages it gets
- final ListAppender rootSanityCheck = new ListAppender("sanity-checker");
+ // 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();
@@ -149,40 +142,4 @@ public class TestErrorLogMuter extends SolrTestCaseJ4 {
assertEquals(4, rootSanityCheck.getEvents().size());
}
- /**
- * 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.
- */
- @SuppressForbidden(reason="We need to use log4J2 classes directly to check that the ErrorLogMuter is working")
- public static final class ListAppender extends AbstractAppender {
- // 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 ListAppender(final String name) {
- super(name, null, null, true, Property.EMPTY_ARRAY);
- assert null != name;
- }
-
- @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;
- }
- }
}