You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@solr.apache.org by ds...@apache.org on 2023/03/07 22:31:02 UTC
[solr] branch branch_9x updated: SOLR-16676: Logs: Http2SolrClient.async() lacked MDC (#1410)
This is an automated email from the ASF dual-hosted git repository.
dsmiley pushed a commit to branch branch_9x
in repository https://gitbox.apache.org/repos/asf/solr.git
The following commit(s) were added to refs/heads/branch_9x by this push:
new 674570f3c9a SOLR-16676: Logs: Http2SolrClient.async() lacked MDC (#1410)
674570f3c9a is described below
commit 674570f3c9adc4114e455028e8e7d14f71351a2d
Author: Alex <st...@users.noreply.github.com>
AuthorDate: Tue Mar 7 14:15:24 2023 -0800
SOLR-16676: Logs: Http2SolrClient.async() lacked MDC (#1410)
Co-authored-by: David Smiley <ds...@apache.org>
---
solr/CHANGES.txt | 2 +
.../org/apache/solr/handler/TestHttpRequestId.java | 134 +++++++++++++++++++++
.../solr/client/solrj/impl/Http2SolrClient.java | 46 +++++++
.../src/java/org/apache/solr/util/LogListener.java | 13 ++
4 files changed, 195 insertions(+)
diff --git a/solr/CHANGES.txt b/solr/CHANGES.txt
index 33f8170fbdd..13252f5b62c 100644
--- a/solr/CHANGES.txt
+++ b/solr/CHANGES.txt
@@ -218,6 +218,8 @@ Bug Fixes
* SOLR-16656: rid parameter missing from query logs (Alex Deparvu)
+* SOLR-16676: Logs: Http2SolrClient.async() lacked MDC (Alex Deparvu)
+
Build
---------------------
* Upgrade forbiddenapis to 3.4 (Uwe Schindler)
diff --git a/solr/core/src/test/org/apache/solr/handler/TestHttpRequestId.java b/solr/core/src/test/org/apache/solr/handler/TestHttpRequestId.java
new file mode 100644
index 00000000000..701c998cb32
--- /dev/null
+++ b/solr/core/src/test/org/apache/solr/handler/TestHttpRequestId.java
@@ -0,0 +1,134 @@
+/*
+ * 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.util.concurrent.ArrayBlockingQueue;
+import java.util.concurrent.BlockingQueue;
+import java.util.concurrent.SynchronousQueue;
+import java.util.concurrent.ThreadPoolExecutor;
+import java.util.concurrent.TimeUnit;
+import org.apache.solr.SolrJettyTestBase;
+import org.apache.solr.client.solrj.impl.Http2SolrClient;
+import org.apache.solr.client.solrj.request.SolrPing;
+import org.apache.solr.client.solrj.util.AsyncListener;
+import org.apache.solr.common.util.ExecutorUtil;
+import org.apache.solr.common.util.NamedList;
+import org.apache.solr.common.util.SolrNamedThreadFactory;
+import org.apache.solr.common.util.SuppressForbidden;
+import org.apache.solr.util.LogLevel;
+import org.apache.solr.util.LogListener;
+import org.junit.BeforeClass;
+import org.junit.Test;
+import org.slf4j.MDC;
+
+@LogLevel("org.apache.solr.client.solrj.impl.Http2SolrClient=DEBUG")
+@SuppressForbidden(reason = "We need to use log4J2 classes directly to test MDC impacts")
+public class TestHttpRequestId extends SolrJettyTestBase {
+
+ @BeforeClass
+ public static void beforeTest() throws Exception {
+ createAndStartJetty(legacyExampleCollection1SolrHome());
+ }
+
+ @Test
+ public void mdcContextTest() throws Exception {
+ String collection = "/collection1";
+ BlockingQueue<Runnable> workQueue = new SynchronousQueue<Runnable>(false);
+ setupClientAndRun(collection, workQueue);
+ }
+
+ @Test
+ public void mdcContextFailureTest() throws Exception {
+ String collection = "/doesnotexist";
+ BlockingQueue<Runnable> workQueue = new SynchronousQueue<Runnable>(false);
+ setupClientAndRun(collection, workQueue);
+ }
+
+ @Test
+ public void mdcContextTest2() throws Exception {
+ String collection = "/collection1";
+ BlockingQueue<Runnable> workQueue = new ArrayBlockingQueue<Runnable>(10, false);
+ setupClientAndRun(collection, workQueue);
+ }
+
+ @Test
+ public void mdcContextFailureTest2() throws Exception {
+ String collection = "/doesnotexist";
+ BlockingQueue<Runnable> workQueue = new ArrayBlockingQueue<Runnable>(10, false);
+ setupClientAndRun(collection, workQueue);
+ }
+
+ private void setupClientAndRun(String collection, BlockingQueue<Runnable> workQueue) {
+ String key = "mdcContextTestKey" + System.nanoTime();
+ String value = "TestHttpRequestId" + System.nanoTime();
+
+ AsyncListener<NamedList<Object>> listener =
+ new AsyncListener<>() {
+
+ @Override
+ public void onSuccess(NamedList<Object> t) {
+ assertTrue(value, value.equals(MDC.get(key)));
+ }
+
+ @Override
+ public void onFailure(Throwable throwable) {
+ assertTrue(value, value.equals(MDC.get(key)));
+ }
+ };
+
+ try (LogListener reqLog =
+ LogListener.debug(Http2SolrClient.class).substring("response processing")) {
+
+ ThreadPoolExecutor commExecutor = null;
+ Http2SolrClient client = null;
+ try {
+ // client setup needs to be same as HttpShardHandlerFactory
+ commExecutor =
+ new ExecutorUtil.MDCAwareThreadPoolExecutor(
+ 3,
+ Integer.MAX_VALUE,
+ 1,
+ TimeUnit.SECONDS,
+ workQueue,
+ new SolrNamedThreadFactory("httpShardExecutor"),
+ false);
+ client =
+ new Http2SolrClient.Builder(jetty.getBaseUrl().toString() + collection)
+ .withExecutor(commExecutor)
+ .build();
+
+ MDC.put(key, value);
+ client.asyncRequest(new SolrPing(), null, listener);
+
+ } finally {
+ if (client != null) {
+ client.close();
+ }
+ ExecutorUtil.shutdownAndAwaitTermination(commExecutor);
+ MDC.remove(key);
+ }
+
+ // expecting 3 events: started, success|failed, completed
+ assertEquals(3, reqLog.getQueue().size());
+ while (!reqLog.getQueue().isEmpty()) {
+ var reqEvent = reqLog.getQueue().poll();
+ assertTrue(reqEvent.getContextData().containsKey(key));
+ assertEquals(value, reqEvent.getContextData().getValue(key));
+ }
+ }
+ }
+}
diff --git a/solr/solrj/src/java/org/apache/solr/client/solrj/impl/Http2SolrClient.java b/solr/solrj/src/java/org/apache/solr/client/solrj/impl/Http2SolrClient.java
index 91388da194a..742f845c4d5 100644
--- a/solr/solrj/src/java/org/apache/solr/client/solrj/impl/Http2SolrClient.java
+++ b/solr/solrj/src/java/org/apache/solr/client/solrj/impl/Http2SolrClient.java
@@ -56,6 +56,7 @@ import org.apache.solr.client.solrj.SolrRequest;
import org.apache.solr.client.solrj.SolrServerException;
import org.apache.solr.client.solrj.V2RequestSupport;
import org.apache.solr.client.solrj.embedded.SSLConfig;
+import org.apache.solr.client.solrj.impl.HttpListenerFactory.RequestResponseListener;
import org.apache.solr.client.solrj.request.RequestWriter;
import org.apache.solr.client.solrj.request.UpdateRequest;
import org.apache.solr.client.solrj.request.V2Request;
@@ -80,6 +81,7 @@ import org.eclipse.jetty.client.ProtocolHandlers;
import org.eclipse.jetty.client.api.AuthenticationStore;
import org.eclipse.jetty.client.api.Request;
import org.eclipse.jetty.client.api.Response;
+import org.eclipse.jetty.client.api.Result;
import org.eclipse.jetty.client.http.HttpClientTransportOverHTTP;
import org.eclipse.jetty.client.util.ByteBufferContentProvider;
import org.eclipse.jetty.client.util.FormContentProvider;
@@ -102,6 +104,7 @@ import org.eclipse.jetty.util.Fields;
import org.eclipse.jetty.util.ssl.SslContextFactory;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
/**
* Difference between this {@link Http2SolrClient} and {@link HttpSolrClient}:
@@ -447,7 +450,9 @@ public class Http2SolrClient extends SolrClient {
@Override
public void onHeaders(Response response) {
super.onHeaders(response);
+ log.debug("response processing started");
InputStreamResponseListener listener = this;
+ MDCCopyHelper mdcCopyHelper = new MDCCopyHelper();
executor.execute(
() -> {
InputStream is = listener.getInputStream();
@@ -455,13 +460,22 @@ public class Http2SolrClient extends SolrClient {
try {
NamedList<Object> body =
processErrorsAndResponse(solrRequest, parser, response, is);
+ mdcCopyHelper.onBegin(null);
+ log.debug("response processing success");
asyncListener.onSuccess(body);
} catch (RemoteSolrException e) {
if (SolrException.getRootCause(e) != CANCELLED_EXCEPTION) {
+ mdcCopyHelper.onBegin(null);
+ log.debug("response processing failed");
asyncListener.onFailure(e);
}
} catch (SolrServerException e) {
+ mdcCopyHelper.onBegin(null);
+ log.debug("response processing failed");
asyncListener.onFailure(e);
+ } finally {
+ log.debug("response processing completed");
+ mdcCopyHelper.onComplete(null);
}
});
}
@@ -571,12 +585,15 @@ public class Http2SolrClient extends SolrClient {
}
setBasicAuthHeader(solrRequest, req);
+ MDCCopyHelper mdcCopyHelper = new MDCCopyHelper();
+ req.onRequestBegin(mdcCopyHelper);
for (HttpListenerFactory factory : listenerFactory) {
HttpListenerFactory.RequestResponseListener listener = factory.get();
listener.onQueued(req);
req.onRequestBegin(listener);
req.onComplete(listener);
}
+ req.onComplete(mdcCopyHelper);
Map<String, String> headers = solrRequest.getHeaders();
if (headers != null) {
@@ -1273,4 +1290,33 @@ public class Http2SolrClient extends SolrClient {
return sslContextFactory;
}
+
+ /**
+ * Helper class in change of copying MDC context across all threads involved in processing a
+ * request. This does not strictly need to be a RequestResponseListener, but using it since it
+ * already provides hooks into the request processing lifecycle.
+ */
+ private static class MDCCopyHelper extends RequestResponseListener {
+ private final Map<String, String> submitterContext = MDC.getCopyOfContextMap();
+ private Map<String, String> threadContext;
+
+ @Override
+ public void onBegin(Request request) {
+ threadContext = MDC.getCopyOfContextMap();
+ updateContextMap(submitterContext);
+ }
+
+ @Override
+ public void onComplete(Result result) {
+ updateContextMap(threadContext);
+ }
+
+ private static void updateContextMap(Map<String, String> context) {
+ if (context != null && !context.isEmpty()) {
+ MDC.setContextMap(context);
+ } else {
+ MDC.clear();
+ }
+ }
+ }
}
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
index b5dea24b51b..2853fff7917 100644
--- a/solr/test-framework/src/java/org/apache/solr/util/LogListener.java
+++ b/solr/test-framework/src/java/org/apache/solr/util/LogListener.java
@@ -155,6 +155,19 @@ public final class LogListener implements Closeable, AutoCloseable {
return create(Level.INFO, logger);
}
+ /** Listens for DEBUG log messages at the ROOT logger */
+ public static LogListener debug() {
+ return debug("");
+ }
+ /** Listens for DEBUG log messages for the specified logger */
+ public static LogListener debug(final Class<?> logger) {
+ return debug(logger.getName());
+ }
+ /** Listens for DEBUG log messages for the specified logger */
+ public static LogListener debug(final String logger) {
+ return create(Level.DEBUG, logger);
+ }
+
// TODO: more factories for other levels?
// TODO: no-arg factory variants that use "" -- simpler syntax for ROOT logger?