Skip to content

Commit 6cb677f

Browse files
benchaplinbenchaplin
committed
Reword log message, pass lighter params, address test fixes
1 parent e38d20c commit 6cb677f

File tree

8 files changed

+92
-144
lines changed

8 files changed

+92
-144
lines changed

‎CONTRIBUTING.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -467,7 +467,7 @@ expensive messages that will usually be discarded:
467467

468468
Logging is an important behaviour of the system and sometimes deserves its own
469469
unit tests, especially if there is complex logic for computing what is logged
470-
and when to log it. You can use a `org.elasticsearch.test.MockLog` to
470+
and when to log it. You can use a `org.elasticsearch.test.MockLogAppender` to
471471
make assertions about the logs that are being emitted.
472472

473473
Logging is a powerful diagnostic technique, but it is not the only possibility.

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

Lines changed: 11 additions & 50 deletions
Original file line numberDiff line numberDiff line change
@@ -46,7 +46,7 @@ protected Collection<Class<? extends Plugin>> nodePlugins() {
4646

4747
@BeforeClass
4848
public static void setDebugLogLevel() {
49-
Configurator.setLevel("org.elasticsearch.search.SearchService", Level.DEBUG);
49+
Configurator.setLevel(SearchService.class, Level.DEBUG);
5050
}
5151

5252
@Before
@@ -55,7 +55,7 @@ public void setupMessageListener() {
5555
}
5656

5757
private int setupIndexWithDocs() {
58-
int numShards = between(DEFAULT_MIN_NUM_SHARDS, DEFAULT_MAX_NUM_SHARDS);
58+
int numShards = numberOfShards();
5959
createIndex("test1", Settings.builder().put(IndexMetadata.SETTING_NUMBER_OF_SHARDS, numShards).build());
6060
createIndex("test2", Settings.builder().put(IndexMetadata.SETTING_NUMBER_OF_SHARDS, numShards).build());
6161
indexRandom(
@@ -123,30 +123,6 @@ public void testSearchFailingQueryErrorTraceFalse() throws IOException {
123123
assertFalse(hasStackTrace.getAsBoolean());
124124
}
125125

126-
public void testLoggingInSearchFailingQueryErrorTraceDefault() throws IOException {
127-
int numShards = setupIndexWithDocs();
128-
129-
Request searchRequest = new Request("POST", "/_search");
130-
searchRequest.setJsonEntity("""
131-
{
132-
"query": {
133-
"simple_query_string" : {
134-
"query": "foo",
135-
"fields": ["field"]
136-
}
137-
}
138-
}
139-
""");
140-
141-
String errorTriggeringIndex = "test2";
142-
try (var mockLog = MockLog.capture(SearchService.class)) {
143-
ErrorTraceHelper.addSeenLoggingExpectations(numShards, mockLog, errorTriggeringIndex);
144-
145-
getRestClient().performRequest(searchRequest);
146-
mockLog.assertAllExpectationsMatched();
147-
}
148-
}
149-
150126
public void testNoLoggingInSearchFailingQueryErrorTraceTrue() throws IOException {
151127
int numShards = setupIndexWithDocs();
152128

@@ -191,7 +167,10 @@ public void testLoggingInSearchFailingQueryErrorTraceFalse() throws IOException
191167
try (var mockLog = MockLog.capture(SearchService.class)) {
192168
ErrorTraceHelper.addSeenLoggingExpectations(numShards, mockLog, errorTriggeringIndex);
193169

194-
searchRequest.addParameter("error_trace", "false");
170+
// error_trace defaults to false so we can test both cases with some randomization
171+
if (randomBoolean()) {
172+
searchRequest.addParameter("error_trace", "false");
173+
}
195174
getRestClient().performRequest(searchRequest);
196175
mockLog.assertAllExpectationsMatched();
197176
}
@@ -248,28 +227,6 @@ public void testMultiSearchFailingQueryErrorTraceFalse() throws IOException {
248227
assertFalse(hasStackTrace.getAsBoolean());
249228
}
250229

251-
public void testLoggingInMultiSearchFailingQueryErrorTraceDefault() throws IOException {
252-
int numShards = setupIndexWithDocs();
253-
254-
XContentType contentType = XContentType.JSON;
255-
MultiSearchRequest multiSearchRequest = new MultiSearchRequest().add(
256-
new SearchRequest("test*").source(new SearchSourceBuilder().query(simpleQueryStringQuery("foo").field("field")))
257-
);
258-
Request searchRequest = new Request("POST", "/_msearch");
259-
byte[] requestBody = MultiSearchRequest.writeMultiLineFormat(multiSearchRequest, contentType.xContent());
260-
searchRequest.setEntity(
261-
new NByteArrayEntity(requestBody, ContentType.create(contentType.mediaTypeWithoutParameters(), (Charset) null))
262-
);
263-
264-
String errorTriggeringIndex = "test2";
265-
try (var mockLog = MockLog.capture(SearchService.class)) {
266-
ErrorTraceHelper.addSeenLoggingExpectations(numShards, mockLog, errorTriggeringIndex);
267-
268-
getRestClient().performRequest(searchRequest);
269-
mockLog.assertAllExpectationsMatched();
270-
}
271-
}
272-
273230
public void testLoggingInMultiSearchFailingQueryErrorTraceTrue() throws IOException {
274231
int numShards = setupIndexWithDocs();
275232

@@ -306,7 +263,11 @@ public void testLoggingInMultiSearchFailingQueryErrorTraceFalse() throws IOExcep
306263
searchRequest.setEntity(
307264
new NByteArrayEntity(requestBody, ContentType.create(contentType.mediaTypeWithoutParameters(), (Charset) null))
308265
);
309-
searchRequest.addParameter("error_trace", "false");
266+
267+
// error_trace defaults to false so we can test both cases with some randomization
268+
if (randomBoolean()) {
269+
searchRequest.addParameter("error_trace", "false");
270+
}
310271

311272
String errorTriggeringIndex = "test2";
312273
try (var mockLog = MockLog.capture(SearchService.class)) {

‎server/src/main/java/org/elasticsearch/action/search/SearchTransportService.java‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -456,7 +456,8 @@ public static void registerRequestHandler(TransportService transportService, Sea
456456
(request, channel, task) -> searchService.executeQueryPhase(
457457
request,
458458
(SearchShardTask) task,
459-
new ChannelActionListener<>(channel)
459+
new ChannelActionListener<>(channel),
460+
channel.getVersion()
460461
)
461462
);
462463
TransportActionProxy.registerProxyAction(transportService, QUERY_ID_ACTION_NAME, true, QuerySearchResult::new);
@@ -468,7 +469,8 @@ public static void registerRequestHandler(TransportService transportService, Sea
468469
(request, channel, task) -> searchService.executeQueryPhase(
469470
request,
470471
(SearchShardTask) task,
471-
new ChannelActionListener<>(channel)
472+
new ChannelActionListener<>(channel),
473+
channel.getVersion()
472474
)
473475
);
474476
TransportActionProxy.registerProxyAction(transportService, QUERY_SCROLL_ACTION_NAME, true, ScrollQuerySearchResult::new);

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

Lines changed: 54 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@
1818
import org.apache.lucene.search.TopDocs;
1919
import org.elasticsearch.ElasticsearchException;
2020
import org.elasticsearch.ExceptionsHelper;
21+
import org.elasticsearch.TransportVersion;
2122
import org.elasticsearch.action.ActionListener;
2223
import org.elasticsearch.action.ActionRunnable;
2324
import org.elasticsearch.action.ResolvedIndices;
@@ -537,27 +538,26 @@ protected void doClose() {
537538
*
538539
* @param <T> the type of the response
539540
* @param listener the action listener to be wrapped
540-
* @param request the shard request being executed
541+
* @param version channel version of the request
542+
* @param nodeId id of the current node
543+
* @param shardId id of the shard being searched
541544
* @param threadPool with context where to write the new header
542-
* @param clusterService the cluster service
543545
* @return the wrapped action listener
544546
*/
545547
static <T> ActionListener<T> maybeWrapListenerForStackTrace(
546548
ActionListener<T> listener,
547-
ShardSearchRequest request,
548-
ThreadPool threadPool,
549-
ClusterService clusterService
549+
TransportVersion version,
550+
String nodeId,
551+
ShardId shardId,
552+
ThreadPool threadPool
550553
) {
551554
boolean header = true;
552-
if (request.getChannelVersion().onOrAfter(ERROR_TRACE_IN_TRANSPORT_HEADER) && threadPool.getThreadContext() != null) {
555+
if (version.onOrAfter(ERROR_TRACE_IN_TRANSPORT_HEADER) && threadPool.getThreadContext() != null) {
553556
header = Boolean.parseBoolean(threadPool.getThreadContext().getHeaderOrDefault("error_trace", "false"));
554557
}
555558
if (header == false) {
556559
return listener.delegateResponse((l, e) -> {
557-
logger.debug(
558-
() -> format("[%s]%s Clearing stack trace before transport:", clusterService.localNode().getId(), request.shardId()),
559-
e
560-
);
560+
logger.debug(() -> format("[%s]%s: failed to execute search request", nodeId, shardId), e);
561561
ExceptionsHelper.unwrapCausesAndSuppressed(e, err -> {
562562
err.setStackTrace(EMPTY_STACK_TRACE_ARRAY);
563563
return false;
@@ -569,7 +569,13 @@ static <T> ActionListener<T> maybeWrapListenerForStackTrace(
569569
}
570570

571571
public void executeDfsPhase(ShardSearchRequest request, SearchShardTask task, ActionListener<SearchPhaseResult> listener) {
572-
listener = maybeWrapListenerForStackTrace(listener, request, threadPool, clusterService);
572+
listener = maybeWrapListenerForStackTrace(
573+
listener,
574+
request.getChannelVersion(),
575+
clusterService.localNode().getId(),
576+
request.shardId(),
577+
threadPool
578+
);
573579
final IndexShard shard = getShard(request);
574580
rewriteAndFetchShardRequest(shard, request, listener.delegateFailure((l, rewritten) -> {
575581
// fork the execution in the search thread pool
@@ -613,7 +619,13 @@ public void executeQueryPhase(ShardSearchRequest request, CancellableTask task,
613619
rewriteAndFetchShardRequest(
614620
shard,
615621
request,
616-
maybeWrapListenerForStackTrace(listener, request, threadPool, clusterService).delegateFailure((l, orig) -> {
622+
maybeWrapListenerForStackTrace(
623+
listener,
624+
request.getChannelVersion(),
625+
clusterService.localNode().getId(),
626+
request.shardId(),
627+
threadPool
628+
).delegateFailure((l, orig) -> {
617629
// check if we can shortcut the query phase entirely.
618630
if (orig.canReturnNullResponseIfMatchNoDocs()) {
619631
assert orig.scroll() == null;
@@ -813,7 +825,13 @@ private SearchPhaseResult executeQueryPhase(ShardSearchRequest request, Cancella
813825
public void executeRankFeaturePhase(RankFeatureShardRequest request, SearchShardTask task, ActionListener<RankFeatureResult> listener) {
814826
final ReaderContext readerContext = findReaderContext(request.contextId(), request);
815827
final ShardSearchRequest shardSearchRequest = readerContext.getShardSearchRequest(request.getShardSearchRequest());
816-
listener = maybeWrapListenerForStackTrace(listener, shardSearchRequest, threadPool, clusterService);
828+
listener = maybeWrapListenerForStackTrace(
829+
listener,
830+
shardSearchRequest.getChannelVersion(),
831+
clusterService.localNode().getId(),
832+
shardSearchRequest.shardId(),
833+
threadPool
834+
);
817835
final Releasable markAsUsed = readerContext.markAsUsed(getKeepAlive(shardSearchRequest));
818836
runAsync(getExecutor(readerContext.indexShard()), () -> {
819837
try (SearchContext searchContext = createContext(readerContext, shardSearchRequest, task, ResultsType.RANK_FEATURE, false)) {
@@ -859,11 +877,17 @@ private QueryFetchSearchResult executeFetchPhase(ReaderContext reader, SearchCon
859877
public void executeQueryPhase(
860878
InternalScrollSearchRequest request,
861879
SearchShardTask task,
862-
ActionListener<ScrollQuerySearchResult> listener
880+
ActionListener<ScrollQuerySearchResult> listener,
881+
TransportVersion version
863882
) {
864883
final LegacyReaderContext readerContext = (LegacyReaderContext) findReaderContext(request.contextId(), request);
865-
final ShardSearchRequest shardSearchRequest = readerContext.getShardSearchRequest(null);
866-
listener = maybeWrapListenerForStackTrace(listener, shardSearchRequest, threadPool, clusterService);
884+
listener = maybeWrapListenerForStackTrace(
885+
listener,
886+
version,
887+
clusterService.localNode().getId(),
888+
readerContext.indexShard().shardId(),
889+
threadPool
890+
);
867891
final Releasable markAsUsed;
868892
try {
869893
markAsUsed = readerContext.markAsUsed(getScrollKeepAlive(request.scroll()));
@@ -873,6 +897,7 @@ public void executeQueryPhase(
873897
throw e;
874898
}
875899
runAsync(getExecutor(readerContext.indexShard()), () -> {
900+
final ShardSearchRequest shardSearchRequest = readerContext.getShardSearchRequest(null);
876901
try (SearchContext searchContext = createContext(readerContext, shardSearchRequest, task, ResultsType.QUERY, false);) {
877902
var opsListener = searchContext.indexShard().getSearchOperationListener();
878903
final long beforeQueryTime = System.nanoTime();
@@ -904,10 +929,21 @@ public void executeQueryPhase(
904929
* It is the responsibility of the caller to ensure that the ref count is correctly decremented
905930
* when the object is no longer needed.
906931
*/
907-
public void executeQueryPhase(QuerySearchRequest request, SearchShardTask task, ActionListener<QuerySearchResult> listener) {
932+
public void executeQueryPhase(
933+
QuerySearchRequest request,
934+
SearchShardTask task,
935+
ActionListener<QuerySearchResult> listener,
936+
TransportVersion version
937+
) {
908938
final ReaderContext readerContext = findReaderContext(request.contextId(), request.shardSearchRequest());
909939
final ShardSearchRequest shardSearchRequest = readerContext.getShardSearchRequest(request.shardSearchRequest());
910-
listener = maybeWrapListenerForStackTrace(listener, shardSearchRequest, threadPool, clusterService);
940+
listener = maybeWrapListenerForStackTrace(
941+
listener,
942+
version,
943+
clusterService.localNode().getId(),
944+
shardSearchRequest.shardId(),
945+
threadPool
946+
);
911947
final Releasable markAsUsed = readerContext.markAsUsed(getKeepAlive(shardSearchRequest));
912948
rewriteAndFetchShardRequest(readerContext.indexShard(), shardSearchRequest, listener.delegateFailure((l, rewritten) -> {
913949
// fork the execution in the search thread pool

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

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2630,7 +2630,8 @@ public void testDfsQueryPhaseRewrite() {
26302630
service.executeQueryPhase(
26312631
new QuerySearchRequest(null, context.id(), request, new AggregatedDfs(Map.of(), Map.of(), 10)),
26322632
new SearchShardTask(42L, "", "", "", null, emptyMap()),
2633-
plainActionFuture
2633+
plainActionFuture,
2634+
TransportVersion.current()
26342635
);
26352636

26362637
plainActionFuture.actionGet();

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

Lines changed: 8 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515
import org.apache.lucene.search.IndexSearcher;
1616
import org.apache.lucene.search.SortField;
1717
import org.apache.lucene.util.BytesRef;
18+
import org.elasticsearch.TransportVersion;
1819
import org.elasticsearch.action.ActionListener;
1920
import org.elasticsearch.action.OriginalIndices;
2021
import org.elasticsearch.action.search.SearchRequest;
@@ -63,7 +64,6 @@
6364

6465
import static org.elasticsearch.common.Strings.format;
6566
import static org.elasticsearch.search.SearchService.maybeWrapListenerForStackTrace;
66-
import static org.elasticsearch.test.ClusterServiceUtils.createClusterService;
6767
import static org.hamcrest.CoreMatchers.is;
6868
import static org.hamcrest.Matchers.not;
6969

@@ -129,18 +129,7 @@ public Type getType() {
129129
}
130130

131131
public void testMaybeWrapListenerForStackTrace() {
132-
ShardSearchRequest shardRequest = new ShardSearchRequest(
133-
OriginalIndices.NONE,
134-
new SearchRequest().allowPartialSearchResults(false).source(new SearchSourceBuilder().query(new MatchAllQueryBuilder())),
135-
new ShardId("index", "index", 0),
136-
0,
137-
1,
138-
AliasFilter.EMPTY,
139-
1.0f,
140-
0,
141-
null
142-
);
143-
132+
ShardId shardId = new ShardId("index", "index", 0);
144133
// Tests that the same listener has stack trace if is not wrapped or does not have stack trace if it is wrapped.
145134
AtomicBoolean isWrapped = new AtomicBoolean(false);
146135
ActionListener<SearchPhaseResult> listener = new ActionListener<>() {
@@ -162,35 +151,25 @@ public void onFailure(Exception e) {
162151
e.fillInStackTrace();
163152
assertThat(e.getStackTrace().length, is(not(0)));
164153
listener.onFailure(e);
165-
listener = maybeWrapListenerForStackTrace(listener, shardRequest, threadPool, createClusterService(threadPool));
154+
listener = maybeWrapListenerForStackTrace(listener, TransportVersion.current(), "node", shardId, threadPool);
166155
isWrapped.set(true);
167156
listener.onFailure(e);
168157
}
169158

170159
public void testMaybeWrapListenerForStackTraceLogs() {
160+
final String nodeId = "node";
171161
final String index = "index";
172-
final int shardId = 0;
173-
ShardSearchRequest shardRequest = new ShardSearchRequest(
174-
OriginalIndices.NONE,
175-
new SearchRequest().allowPartialSearchResults(false).source(new SearchSourceBuilder().query(new MatchAllQueryBuilder())),
176-
new ShardId(index, index, shardId),
177-
0,
178-
1,
179-
AliasFilter.EMPTY,
180-
1.0f,
181-
0,
182-
null
183-
);
162+
ShardId shardId = new ShardId(index, index, 0);
184163

185164
try (var mockLog = MockLog.capture(SearchService.class)) {
186165
Configurator.setLevel("org.elasticsearch.search.SearchService", Level.DEBUG);
187166
final String exceptionMessage = "test exception message";
188167
mockLog.addExpectation(
189168
new MockLog.PatternAndExceptionSeenEventExpectation(
190-
format("Tracking information ([node][%s][%d]) and exception logged before stack trace cleared", index, shardId),
169+
format("Tracking information ([%s]%s) and exception logged before stack trace cleared", nodeId, shardId),
191170
SearchService.class.getCanonicalName(),
192171
Level.DEBUG,
193-
format("\\[node\\]\\[%s\\]\\[%d\\] Clearing stack trace before transport:", index, shardId),
172+
format("\\[%s\\]%s: failed to execute search request", nodeId, shardId),
194173
Exception.class,
195174
exceptionMessage
196175
)
@@ -209,7 +188,7 @@ public void onFailure(Exception e) {
209188
}
210189
};
211190
Exception e = new Exception(exceptionMessage);
212-
listener = maybeWrapListenerForStackTrace(listener, shardRequest, threadPool, createClusterService(threadPool));
191+
listener = maybeWrapListenerForStackTrace(listener, TransportVersion.current(), nodeId, shardId, threadPool);
213192
listener.onFailure(e);
214193
}
215194
}

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

Lines changed: 2 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -78,12 +78,7 @@ public static void addSeenLoggingExpectations(int numShards, MockLog mockLog, St
7878
),
7979
SearchService.class.getCanonicalName(),
8080
Level.DEBUG,
81-
format(
82-
"\\[%s\\]\\[%s\\]\\[%d\\] Clearing stack trace before transport:",
83-
nodesDisjunction,
84-
errorTriggeringIndex,
85-
shard
86-
),
81+
format("\\[%s\\]\\[%s\\]\\[%d\\]: failed to execute search request", nodesDisjunction, errorTriggeringIndex, shard),
8782
QueryShardException.class,
8883
"failed to create query: For input string: \"foo\""
8984
)
@@ -107,7 +102,7 @@ public static void addUnseenLoggingExpectations(int numShards, MockLog mockLog,
107102
"Tracking information ([nodeId][indexName][shard]) and exception logged before stack trace cleared",
108103
SearchService.class.getCanonicalName(),
109104
Level.DEBUG,
110-
format("[%s][%s][%d] Clearing stack trace before transport:", getNodeId(nodeName), errorTriggeringIndex, shard)
105+
format("[%s][%s][%d]: failed to execute search request", getNodeId(nodeName), errorTriggeringIndex, shard)
111106
)
112107
);
113108
}

0 commit comments

Comments
 (0)