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 <[email protected]>
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;
- }
- }
}
