Skip to content

Commit 0538958

Browse files
benchaplinbenchaplin
authored
Always log data node failures (#127420)
Log search exceptions as they occur on the data node no matter the value of error_trace.
1 parent fd93fad commit 0538958

File tree

5 files changed

+74
-167
lines changed

5 files changed

+74
-167
lines changed

‎qa/smoke-test-http/src/internalClusterTest/java/org/elasticsearch/http/SearchErrorTraceIT.java‎

Lines changed: 17 additions & 61 deletions
Original file line numberDiff line numberDiff line change
@@ -127,33 +127,7 @@ public void testSearchFailingQueryErrorTraceFalse() throws IOException {
127127
assertFalse(hasStackTrace.getAsBoolean());
128128
}
129129

130-
public void testDataNodeDoesNotLogStackTraceWhenErrorTraceTrue() throws IOException {
131-
setupIndexWithDocs();
132-
133-
Request searchRequest = new Request("POST", "/_search");
134-
searchRequest.setJsonEntity("""
135-
{
136-
"query": {
137-
"simple_query_string" : {
138-
"query": "foo",
139-
"fields": ["field"]
140-
}
141-
}
142-
}
143-
""");
144-
145-
String errorTriggeringIndex = "test2";
146-
int numShards = getNumShards(errorTriggeringIndex).numPrimaries;
147-
try (var mockLog = MockLog.capture(SearchService.class)) {
148-
ErrorTraceHelper.addUnseenLoggingExpectations(numShards, mockLog, errorTriggeringIndex);
149-
150-
searchRequest.addParameter("error_trace", "true");
151-
getRestClient().performRequest(searchRequest);
152-
mockLog.assertAllExpectationsMatched();
153-
}
154-
}
155-
156-
public void testDataNodeLogsStackTraceWhenErrorTraceFalseOrEmpty() throws IOException {
130+
public void testDataNodeLogsStackTrace() throws IOException {
157131
setupIndexWithDocs();
158132

159133
Request searchRequest = new Request("POST", "/_search");
@@ -173,10 +147,14 @@ public void testDataNodeLogsStackTraceWhenErrorTraceFalseOrEmpty() throws IOExce
173147
try (var mockLog = MockLog.capture(SearchService.class)) {
174148
ErrorTraceHelper.addSeenLoggingExpectations(numShards, mockLog, errorTriggeringIndex);
175149

176-
// error_trace defaults to false so we can test both cases with some randomization
177-
if (randomBoolean()) {
150+
// No matter the value of error_trace (empty, true, or false) we should see stack traces logged
151+
int errorTraceValue = randomIntBetween(0, 2);
152+
if (errorTraceValue == 0) {
153+
searchRequest.addParameter("error_trace", "true");
154+
} else if (errorTraceValue == 1) {
178155
searchRequest.addParameter("error_trace", "false");
179-
}
156+
} // else empty
157+
180158
getRestClient().performRequest(searchRequest);
181159
mockLog.assertAllExpectationsMatched();
182160
}
@@ -233,32 +211,7 @@ public void testMultiSearchFailingQueryErrorTraceFalse() throws IOException {
233211
assertFalse(hasStackTrace.getAsBoolean());
234212
}
235213

236-
public void testDataNodeDoesNotLogStackTraceWhenErrorTraceTrueMultiSearch() throws IOException {
237-
setupIndexWithDocs();
238-
239-
XContentType contentType = XContentType.JSON;
240-
MultiSearchRequest multiSearchRequest = new MultiSearchRequest().add(
241-
new SearchRequest("test*").source(new SearchSourceBuilder().query(simpleQueryStringQuery("foo").field("field")))
242-
);
243-
Request searchRequest = new Request("POST", "/_msearch");
244-
byte[] requestBody = MultiSearchRequest.writeMultiLineFormat(multiSearchRequest, contentType.xContent());
245-
searchRequest.setEntity(
246-
new NByteArrayEntity(requestBody, ContentType.create(contentType.mediaTypeWithoutParameters(), (Charset) null))
247-
);
248-
249-
searchRequest.addParameter("error_trace", "true");
250-
251-
String errorTriggeringIndex = "test2";
252-
int numShards = getNumShards(errorTriggeringIndex).numPrimaries;
253-
try (var mockLog = MockLog.capture(SearchService.class)) {
254-
ErrorTraceHelper.addUnseenLoggingExpectations(numShards, mockLog, errorTriggeringIndex);
255-
256-
getRestClient().performRequest(searchRequest);
257-
mockLog.assertAllExpectationsMatched();
258-
}
259-
}
260-
261-
public void testDataNodeLogsStackTraceWhenErrorTraceFalseOrEmptyMultiSearch() throws IOException {
214+
public void testDataNodeLogsStackTraceMultiSearch() throws IOException {
262215
setupIndexWithDocs();
263216

264217
XContentType contentType = XContentType.JSON;
@@ -271,16 +224,19 @@ public void testDataNodeLogsStackTraceWhenErrorTraceFalseOrEmptyMultiSearch() th
271224
new NByteArrayEntity(requestBody, ContentType.create(contentType.mediaTypeWithoutParameters(), (Charset) null))
272225
);
273226

274-
// error_trace defaults to false so we can test both cases with some randomization
275-
if (randomBoolean()) {
276-
searchRequest.addParameter("error_trace", "false");
277-
}
278-
279227
String errorTriggeringIndex = "test2";
280228
int numShards = getNumShards(errorTriggeringIndex).numPrimaries;
281229
try (var mockLog = MockLog.capture(SearchService.class)) {
282230
ErrorTraceHelper.addSeenLoggingExpectations(numShards, mockLog, errorTriggeringIndex);
283231

232+
// No matter the value of error_trace (empty, true, or false) we should see stack traces logged
233+
int errorTraceValue = randomIntBetween(0, 2);
234+
if (errorTraceValue == 0) {
235+
searchRequest.addParameter("error_trace", "true");
236+
} else if (errorTraceValue == 1) {
237+
searchRequest.addParameter("error_trace", "false");
238+
} // else empty
239+
284240
getRestClient().performRequest(searchRequest);
285241
mockLog.assertAllExpectationsMatched();
286242
}

‎server/src/main/java/org/elasticsearch/search/SearchService.java‎

Lines changed: 34 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -574,10 +574,11 @@ protected void doClose() {
574574
}
575575

576576
/**
577-
* Wraps the listener to avoid sending StackTraces back to the coordinating
578-
* node if the `error_trace` header is set to {@code false}. Upon reading we
579-
* default to {@code true} to maintain the same behavior as before the change,
580-
* due to older nodes not being able to specify whether it needs stack traces.
577+
* Wraps the listener to ensure errors are logged and to avoid sending
578+
* StackTraces back to the coordinating node if the `error_trace` header is
579+
* set to {@code false}. Upon reading, we default to {@code true} to maintain
580+
* the same behavior as before the change, due to older nodes not being able
581+
* to specify whether they need stack traces.
581582
*
582583
* @param <T> the type of the response
583584
* @param listener the action listener to be wrapped
@@ -588,44 +589,47 @@ protected void doClose() {
588589
* @param threadPool with context where to write the new header
589590
* @return the wrapped action listener
590591
*/
591-
static <T> ActionListener<T> maybeWrapListenerForStackTrace(
592+
static <T> ActionListener<T> wrapListenerForErrorHandling(
592593
ActionListener<T> listener,
593594
TransportVersion version,
594595
String nodeId,
595596
ShardId shardId,
596597
long taskId,
597598
ThreadPool threadPool
598599
) {
599-
boolean header = true;
600+
final boolean header;
600601
if (version.onOrAfter(ERROR_TRACE_IN_TRANSPORT_HEADER) && threadPool.getThreadContext() != null) {
601602
header = Boolean.parseBoolean(threadPool.getThreadContext().getHeaderOrDefault("error_trace", "false"));
602-
}
603-
if (header == false) {
604-
return listener.delegateResponse((l, e) -> {
605-
org.apache.logging.log4j.util.Supplier<String> messageSupplier = () -> format(
606-
"[%s]%s: failed to execute search request for task [%d]",
607-
nodeId,
608-
shardId,
609-
taskId
610-
);
611-
// Keep this logic aligned with that of SUPPRESSED_ERROR_LOGGER in RestResponse
612-
if (ExceptionsHelper.status(e).getStatus() < 500 || ExceptionsHelper.isNodeOrShardUnavailableTypeException(e)) {
613-
logger.debug(messageSupplier, e);
614-
} else {
615-
logger.warn(messageSupplier, e);
616-
}
603+
} else {
604+
header = true;
605+
}
606+
return listener.delegateResponse((l, e) -> {
607+
org.apache.logging.log4j.util.Supplier<String> messageSupplier = () -> format(
608+
"[%s]%s: failed to execute search request for task [%d]",
609+
nodeId,
610+
shardId,
611+
taskId
612+
);
613+
// Keep this logic aligned with that of SUPPRESSED_ERROR_LOGGER in RestResponse
614+
if (ExceptionsHelper.status(e).getStatus() < 500 || ExceptionsHelper.isNodeOrShardUnavailableTypeException(e)) {
615+
logger.debug(messageSupplier, e);
616+
} else {
617+
logger.warn(messageSupplier, e);
618+
}
619+
620+
if (header == false) {
617621
ExceptionsHelper.unwrapCausesAndSuppressed(e, err -> {
618622
err.setStackTrace(EMPTY_STACK_TRACE_ARRAY);
619623
return false;
620624
});
621-
l.onFailure(e);
622-
});
623-
}
624-
return listener;
625+
}
626+
627+
l.onFailure(e);
628+
});
625629
}
626630

627631
public void executeDfsPhase(ShardSearchRequest request, SearchShardTask task, ActionListener<SearchPhaseResult> listener) {
628-
listener = maybeWrapListenerForStackTrace(
632+
listener = wrapListenerForErrorHandling(
629633
listener,
630634
request.getChannelVersion(),
631635
clusterService.localNode().getId(),
@@ -676,7 +680,7 @@ public void executeQueryPhase(ShardSearchRequest request, CancellableTask task,
676680
rewriteAndFetchShardRequest(
677681
shard,
678682
request,
679-
maybeWrapListenerForStackTrace(
683+
wrapListenerForErrorHandling(
680684
listener,
681685
request.getChannelVersion(),
682686
clusterService.localNode().getId(),
@@ -913,7 +917,7 @@ private SearchPhaseResult executeQueryPhase(ShardSearchRequest request, Cancella
913917
public void executeRankFeaturePhase(RankFeatureShardRequest request, SearchShardTask task, ActionListener<RankFeatureResult> listener) {
914918
final ReaderContext readerContext = findReaderContext(request.contextId(), request);
915919
final ShardSearchRequest shardSearchRequest = readerContext.getShardSearchRequest(request.getShardSearchRequest());
916-
listener = maybeWrapListenerForStackTrace(
920+
listener = wrapListenerForErrorHandling(
917921
listener,
918922
shardSearchRequest.getChannelVersion(),
919923
clusterService.localNode().getId(),
@@ -970,7 +974,7 @@ public void executeQueryPhase(
970974
TransportVersion version
971975
) {
972976
final LegacyReaderContext readerContext = (LegacyReaderContext) findReaderContext(request.contextId(), request);
973-
listener = maybeWrapListenerForStackTrace(
977+
listener = wrapListenerForErrorHandling(
974978
listener,
975979
version,
976980
clusterService.localNode().getId(),
@@ -1032,7 +1036,7 @@ public void executeQueryPhase(
10321036
) {
10331037
final ReaderContext readerContext = findReaderContext(request.contextId(), request.shardSearchRequest());
10341038
final ShardSearchRequest shardSearchRequest = readerContext.getShardSearchRequest(request.shardSearchRequest());
1035-
listener = maybeWrapListenerForStackTrace(
1039+
listener = wrapListenerForErrorHandling(
10361040
listener,
10371041
version,
10381042
clusterService.localNode().getId(),

‎server/src/test/java/org/elasticsearch/search/SearchServiceTests.java‎

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -72,7 +72,7 @@
7272
import static org.elasticsearch.common.Strings.format;
7373
import static org.elasticsearch.common.util.concurrent.EsExecutors.DIRECT_EXECUTOR_SERVICE;
7474
import static org.elasticsearch.search.SearchService.isExecutorQueuedBeyondPrewarmingFactor;
75-
import static org.elasticsearch.search.SearchService.maybeWrapListenerForStackTrace;
75+
import static org.elasticsearch.search.SearchService.wrapListenerForErrorHandling;
7676
import static org.hamcrest.CoreMatchers.is;
7777
import static org.hamcrest.Matchers.not;
7878

@@ -137,7 +137,7 @@ public Type getType() {
137137
doTestCanMatch(searchRequest, sortField, true, null, false);
138138
}
139139

140-
public void testMaybeWrapListenerForStackTrace() {
140+
public void testWrapListenerForErrorHandling() {
141141
ShardId shardId = new ShardId("index", "index", 0);
142142
// Tests that the same listener has stack trace if is not wrapped or does not have stack trace if it is wrapped.
143143
AtomicBoolean isWrapped = new AtomicBoolean(false);
@@ -160,12 +160,12 @@ public void onFailure(Exception e) {
160160
e.fillInStackTrace();
161161
assertThat(e.getStackTrace().length, is(not(0)));
162162
listener.onFailure(e);
163-
listener = maybeWrapListenerForStackTrace(listener, TransportVersion.current(), "node", shardId, 123L, threadPool);
163+
listener = wrapListenerForErrorHandling(listener, TransportVersion.current(), "node", shardId, 123L, threadPool);
164164
isWrapped.set(true);
165165
listener.onFailure(e);
166166
}
167167

168-
public void testMaybeWrapListenerForStackTraceDebugLog() {
168+
public void testWrapListenerForErrorHandlingDebugLog() {
169169
final String nodeId = "node";
170170
final String index = "index";
171171
ShardId shardId = new ShardId(index, index, 0);
@@ -198,12 +198,12 @@ public void onFailure(Exception e) {
198198
}
199199
};
200200
IllegalArgumentException e = new IllegalArgumentException(exceptionMessage); // 400-level exception
201-
listener = maybeWrapListenerForStackTrace(listener, TransportVersion.current(), nodeId, shardId, taskId, threadPool);
201+
listener = wrapListenerForErrorHandling(listener, TransportVersion.current(), nodeId, shardId, taskId, threadPool);
202202
listener.onFailure(e);
203203
}
204204
}
205205

206-
public void testMaybeWrapListenerForStackTraceWarnLog() {
206+
public void testWrapListenerForErrorHandlingWarnLog() {
207207
final String nodeId = "node";
208208
final String index = "index";
209209
ShardId shardId = new ShardId(index, index, 0);
@@ -235,7 +235,7 @@ public void onFailure(Exception e) {
235235
}
236236
};
237237
IllegalStateException e = new IllegalStateException(exceptionMessage); // 500-level exception
238-
listener = maybeWrapListenerForStackTrace(listener, TransportVersion.current(), nodeId, shardId, taskId, threadPool);
238+
listener = wrapListenerForErrorHandling(listener, TransportVersion.current(), nodeId, shardId, taskId, threadPool);
239239
listener.onFailure(e);
240240
}
241241
}

‎test/framework/src/main/java/org/elasticsearch/search/ErrorTraceHelper.java‎

Lines changed: 0 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -26,7 +26,6 @@
2626
import java.util.stream.Collectors;
2727

2828
import static org.elasticsearch.common.Strings.format;
29-
import static org.elasticsearch.test.ESIntegTestCase.getNodeId;
3029
import static org.elasticsearch.test.ESIntegTestCase.internalCluster;
3130
import static org.elasticsearch.test.ESTestCase.asInstanceOf;
3231

@@ -90,32 +89,4 @@ public static void addSeenLoggingExpectations(int numShards, MockLog mockLog, St
9089
);
9190
}
9291
}
93-
94-
/**
95-
* Adds expectations for the _absence_ of debug logging of a message. An unseen expectation is added for each
96-
* combination of node in the internal cluster and shard in the index.
97-
*
98-
* @param numShards the number of shards in the index (an expectation will be added for each shard)
99-
* @param mockLog the mock log
100-
* @param errorTriggeringIndex the name of the index that will trigger the error
101-
*/
102-
public static void addUnseenLoggingExpectations(int numShards, MockLog mockLog, String errorTriggeringIndex) {
103-
for (String nodeName : internalCluster().getNodeNames()) {
104-
for (int shard = 0; shard < numShards; shard++) {
105-
mockLog.addExpectation(
106-
new MockLog.UnseenEventExpectation(
107-
format(
108-
"\"[%s][%s][%d]: failed to execute search request\" and an exception logged",
109-
getNodeId(nodeName),
110-
errorTriggeringIndex,
111-
shard
112-
),
113-
SearchService.class.getCanonicalName(),
114-
Level.DEBUG,
115-
format("[%s][%s][%d]: failed to execute search request", getNodeId(nodeName), errorTriggeringIndex, shard)
116-
)
117-
);
118-
}
119-
}
120-
}
12192
}

0 commit comments

Comments
 (0)