Log stack traces on data nodes before they are cleared for transport #125732

benchaplin · 2025-03-26T21:53:28Z

#118266 cleared stack traces on data nodes before transport back to the coordinating node when error_trace=false. However, all logging of exceptions happens on the coordinating node. This change made it impossible to debug errors via stack trace when error_trace=false.

Here, I've logged the exception on the data node right before the stack trace is cleared. It's prefixed with [nodeId][indexName][shard] to match the rest.suppressed shard failures log on the coordinating node, allowing for easy error tracing from the coordinating node to the responsible data node.

Might this flood the (debug level) logs?
This change has the potential to log [# of shards] times for each index in a search. However, this log:

elasticsearch/server/src/main/java/org/elasticsearch/action/search/AbstractSearchAsyncAction.java

Line 405 in 937bcd9

    
           logger.debug(() -> format("%s: Failed to execute [%s] lastShard [%s]", shard, request, lastShard), e);

on the coordinating node already logs [# of shards]*[# of replicas] times at the debug level. And before #118266, each included a stack trace. Therefore, per node, this change does not increase logs by any order of magnitude.

elasticsearchmachine · 2025-03-26T21:55:18Z

Pinging @elastic/es-search-foundations (Team:Search Foundations)

elasticsearchmachine · 2025-03-26T21:56:42Z

Hi @benchaplin, I've created a changelog YAML for you.

benwtrent · 2025-03-27T11:52:13Z

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

    ) {
        boolean header = true;
-        if (version.onOrAfter(ERROR_TRACE_IN_TRANSPORT_HEADER) && threadPool.getThreadContext() != null) {
+        if (request.getChannelVersion().onOrAfter(ERROR_TRACE_IN_TRANSPORT_HEADER) && threadPool.getThreadContext() != null) {
            header = Boolean.parseBoolean(threadPool.getThreadContext().getHeaderOrDefault("error_trace", "false"));
        }
        if (header == false) {


I do not see where we are logging the trace? It seems we are only logging that its actually removed.

I am thinking we should log the exception as a WARN if:

header == false (meaning the trace wouldn't be provided user side)

the exception isn't a user exception (e.g. should be considered a 5xx)

However, I defer to @javanna here. He has much better context around what we are trying to achieve.

Passing e to the logger here outputs the stack trace. Maybe my log message isn't clear... think something like "search failed with exception:" would be better?

Interesting point on WARN - do you think a WARN log per shard for the same underlying error is acceptable here? Luca and I decided it would be difficult to dedupe these at the moment. It might become easier with batched query execution.

Ah, I see.

I think that this shouldn't be debug. Maybe debug for all exceptions. But we should log WARN for things that are 5xx, indicating the failure.

I think adding a "Clearing stack trace before...." is unnecessary. Logging isn't just for our debugging, but also for users.

I am not sure indicating that the trace is being removed is overly useful here.

I've updated the log message to be more clear for users, and raised the level WARN for 5XX. Thanks for the idea there - I think it makes sense for this new message to log at the same level as rest suppressed.

javanna

I left some comments, thanks @benchaplin !

CONTRIBUTING.md

javanna · 2025-03-27T13:35:14Z

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

            header = Boolean.parseBoolean(threadPool.getThreadContext().getHeaderOrDefault("error_trace", "false"));
        }
        if (header == false) {
            return listener.delegateResponse((l, e) -> {
+                logger.debug(
+                    () -> format("[%s]%s Clearing stack trace before transport:", clusterService.localNode().getId(), request.shardId()),


This looks like the best place to add the logging indeed, because we ensure that we do the additional logging exclusively for the cases where we suppress the stack trace, before doing so.

If we log this at debug, we are not going to see it with the default log level, are we? I think we should use warn instead at least?

The error message looks a little misleading also, all we are interested in is the error itself, so I would log the same that we'd get on the coord node, but this time we'd get the stacktrace.

There's a couple more aspects that deserve attention I think:

if we keep on logging on the coord node, we should probably only log in the data nodes when the error trace is not requested, otherwise we just add redundant logging?

if we keep on logging on the coord node, it may happen that the node acting as coord node acts as a data node as well as part of serving a search request. That would lead to duplicated logging on that node, that may be ok but not ideal.

I've updated the log message to be more clear for users and raised the level to WARN on the same condition that the rest suppressed logger logs at WARN.

Agreed, and that is the current behavior as this log is only wrapped in if (header == false) {.

That is true. I think the shard failure logs on the coord node (see my example below) are important, but an argument could be made to remove the rest suppressed log if error_trace=false. Then again rest.suppressed is only one log line. But I imagine removing any of these logs would count as a breaking change (?), as alerts out there (like our own) might rely on them.

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

javanna · 2025-03-27T13:51:28Z

...rch/src/internalClusterTest/java/org/elasticsearch/xpack/search/AsyncSearchErrorTraceIT.java

-    private BooleanSupplier transportMessageHasStackTrace;
+    @BeforeClass
+    public static void setDebugLogLevel() {
+        Configurator.setLevel("org.elasticsearch.search.SearchService", Level.DEBUG);


hopefully this is not required, if we log at WARN ?

For ITs, I found it easiest to trigger 4XX failures which I think should still log at the DEBUG level.

...rch/src/internalClusterTest/java/org/elasticsearch/xpack/search/AsyncSearchErrorTraceIT.java

javanna · 2025-03-27T14:25:57Z

...rch/src/internalClusterTest/java/org/elasticsearch/xpack/search/AsyncSearchErrorTraceIT.java

@@ -136,6 +150,106 @@ public void testAsyncSearchFailingQueryErrorTraceFalse() throws IOException, Int
        assertFalse(transportMessageHasStackTrace.getAsBoolean());
    }

+    public void testLoggingInAsyncSearchFailingQueryErrorTraceDefault() throws IOException, InterruptedException {


you could probably fold this test into the errortrace true test? You could randomly set the flag to true, otherwise not, the result should be the same?

In my view, the three potential values of error_trace (true, false, and empty) all deserve their own test so that any changes in behavior immediately lead to a test failure.

Yes I can see that, yet knowing that empty and false lead to the same, we could save some code and test runtime too perhaps.

Heard, saving code and test runtime sounds like a good tradeoff.

javanna · 2025-03-27T14:37:41Z

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

@@ -37,19 +44,27 @@ protected Collection<Class<? extends Plugin>> nodePlugins() {
        return CollectionUtils.appendToCopyNoNullElements(super.nodePlugins(), MockTransportService.TestPlugin.class);
    }

+    @BeforeClass
+    public static void setDebugLogLevel() {
+        Configurator.setLevel("org.elasticsearch.search.SearchService", Level.DEBUG);


hopefully we adjust log level and this is no longer needed.

javanna · 2025-03-27T14:37:54Z

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

@@ -108,6 +123,80 @@ public void testSearchFailingQueryErrorTraceFalse() throws IOException {
        assertFalse(hasStackTrace.getAsBoolean());
    }

+    public void testLoggingInSearchFailingQueryErrorTraceDefault() throws IOException {


you could probably fold this test into the errortrace true test? You could randomly set the flag to true, otherwise not, the result should be the same?

javanna · 2025-03-27T14:38:27Z

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

-    private void setupIndexWithDocs() {
-        createIndex("test1", "test2");
+    private int setupIndexWithDocs() {
+        int numShards = between(DEFAULT_MIN_NUM_SHARDS, DEFAULT_MAX_NUM_SHARDS);


the number of shards is already randomized if you call createIndex . See ESIntegTestCase#numberOfShards.

smalyshev · 2025-03-26T22:12:12Z

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

@@ -32,24 +41,41 @@
 public class SearchErrorTraceIT extends HttpSmokeTestCase {
    private BooleanSupplier hasStackTrace;

+    private static final String loggerName = "org.elasticsearch.search.SearchService";


I'd probably use SearchService.class here.

Good call, done.

smalyshev · 2025-03-27T00:16:07Z

...rch/src/internalClusterTest/java/org/elasticsearch/xpack/search/AsyncSearchErrorTraceIT.java

+        Map<String, Object> responseEntity = performRequestAndGetResponseEntityAfterDelay(searchRequest, TimeValue.ZERO);
+        String asyncExecutionId = (String) responseEntity.get("id");
+        Request request = new Request("GET", "/_async_search/" + asyncExecutionId);
+        while (responseEntity.get("is_running") instanceof Boolean isRunning && isRunning) {


I think you can use assertBusy here?

smalyshev · 2025-03-27T16:35:05Z

I think our main problem with this is that users are giving us (or we giving ourselves) logs with useful part of the backtrace removed. So I wonder if this patch really fixes that? Would the users see the missing part in the data node logs? Would they know how to get it and how to give it to us?

drempapis · 2025-03-28T10:10:20Z

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

@@ -552,6 +557,7 @@ static <T> ActionListener<T> maybeWrapListenerForStackTrace(
        }
        if (header == false) {
            return listener.delegateResponse((l, e) -> {
+                logger.debug(() -> format("[%s]%s: failed to execute search request", nodeId, shardId), e);


Do we need to correlate the request log on the coordinate node with the error reported on the data node? If so, is the logging information here enough?

Good question, I modeled the nodeId/shardId prefix to lead us right back to the coord node's logs. If you take a look at the example below: [CrhugeEAQNGHtZ14Y6Apjg][test][2] could be taken from the r.suppressed log and grepped across data nodes to find the new log.

I understand the nodeId/shardId combination, which associates a coord with a data node. What if there are multiple failing requests on the coord node? How can we identify the error of a single request? Is it a use case we must consider?

benchaplin · 2025-03-28T12:36:33Z

For reference, here's a brief example of what logs we have today + what I'm adding. I've thrown a NPE in SearchService to trigger. Setup: 3 nodes, 3 primary shards, 3 replicas.

(Coord node: we get 6 of these, one per shard)

[2025-03-28T08:17:51,928][DEBUG][o.e.a.s.TransportSearchAction] [runTask-0] [meJUNXYoT1iBSTnJgI6Unw][test][2]: Failed to execute [SearchRequest{searchType=QUERY_THEN_FETCH, indices=[test], indicesOptions=IndicesOptions[ignore_unavailable=false, allow_no_indices=true, expand_wildcards_open=true, expand_wildcards_closed=false, expand_wildcards_hidden=false, allow_aliases_to_multiple_indices=true, forbid_closed_indices=true, ignore_aliases=false, ignore_throttled=true, allow_selectors=true, include_failure_indices=false], routing='null', preference='null', requestCache=null, scroll=null, maxConcurrentShardRequests=0, batchedReduceSize=512, preFilterShardSize=null, allowPartialSearchResults=true, localClusterAlias=null, getOrCreateAbsoluteStartMillis=-1, ccsMinimizeRoundtrips=true, source={}}] lastShard [false] org.elasticsearch.transport.RemoteTransportException: [runTask-0][127.0.0.1:9300][indices:data/read/search[phase/query]]  
Caused by: java.lang.NullPointerException: testing123
[ no stack trace ]

(Coord node: after 6 above failures)

[2025-03-28T08:17:51,946][DEBUG][o.e.a.s.TransportSearchAction] [runTask-0] All shards failed for phase: [query] org.elasticsearch.ElasticsearchException$1: testing123
[ long stack trace for ElasticsearchException ]
Caused by: java.lang.NullPointerException: testing123
[ no stack trace ]

(Coord node: WARN level for status >= 500, DEBUG else)

[2025-03-28T08:17:51,946][WARN ][r.suppressed             ] [runTask-0] path: /test/_search, params: {index=test}, status: 500 Failed to execute phase [query], all shards failed; shardFailures {[CrhugeEAQNGHtZ14Y6Apjg][test][0]: org.elasticsearch.transport.RemoteTransportException: [runTask-1][127.0.0.1:9301][indices:data/read/search[phase/query]]  
Caused by: java.lang.NullPointerException: testing123  
}{[meJUNXYoT1iBSTnJgI6Unw][test][1]: org.elasticsearch.transport.RemoteTransportException: [runTask-0][127.0.0.1:9300][indices:data/read/search[phase/query]]  
Caused by: java.lang.NullPointerException: testing123  
}{[CrhugeEAQNGHtZ14Y6Apjg][test][2]: org.elasticsearch.transport.RemoteTransportException: [runTask-1][127.0.0.1:9301][indices:data/read/search[phase/query]]  
Caused by: java.lang.NullPointerException: testing123  
}
[ long stack trace ]
Caused by: java.lang.NullPointerException: testing123
[ no stack trace ]

(Data node: this PR's new log - we get 6 of these spread across the nodes, one per shard)

[2025-03-28T08:17:51,944][DEBUG][o.e.s.SearchService      ] [runTask-1] [CrhugeEAQNGHtZ14Y6Apjg][test][2]: failed to execute search request java.lang.NullPointerException: testing123
	at [email protected]/org.elasticsearch.search.SearchService.throwException(SearchService.java:768)
	at [email protected]/org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:802)
	at [email protected]/org.elasticsearch.search.SearchService.lambda$executeQueryPhase$6(SearchService.java:648)
... [ full stack trace ]

Edit - after b34afc1, the new log will match the level of the r.suppressed log, so it would be WARN in this example.

benwtrent · 2025-03-28T16:11:52Z

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

+                org.apache.logging.log4j.util.Supplier<String> messageSupplier = () -> format(
+                    "[%s]%s: failed to execute search request",
+                    nodeId,
+                    shardId
+                );
+                if (ExceptionsHelper.status(e).getStatus() < 500 || ExceptionsHelper.isNodeOrShardUnavailableTypeException(e)) {
+                    logger.debug(messageSupplier, e);
+                } else {
+                    logger.warn(messageSupplier, e);
+                }


Debug log stack trace before it is cleared

fdaba56

elasticsearchmachine added v9.1.0 needs:triage Requires assignment of a team area label labels Mar 26, 2025

benchaplin added >bug Team:Search Foundations Meta label for the Search Foundations team in Elasticsearch :Search Foundations/Search Catch all for Search Foundations v8.18.0 v8.19.0 and removed needs:triage Requires assignment of a team area label v9.1.0 labels Mar 26, 2025

benchaplin added the v9.0.0 label Mar 26, 2025

Update docs/changelog/125732.yaml

79a06aa

benchaplin added the auto-backport Automatically create backport pull requests when merged label Mar 26, 2025

github-actions bot deployed to docs-preview March 26, 2025 21:57 View deployment

benchaplin requested review from javanna and piergm March 26, 2025 21:58

benchaplin mentioned this pull request Mar 26, 2025

Mystery NPE on search Cannot invoke \"java.lang.Long.longValue()\" because \"value\" is null #123747

Open

benchaplin added the v9.1.0 label Mar 26, 2025

Just set log level to debug

e38d20c

github-actions bot deployed to docs-preview March 27, 2025 03:26 View deployment

benwtrent reviewed Mar 27, 2025

View reviewed changes

javanna reviewed Mar 27, 2025

View reviewed changes

smalyshev reviewed Mar 27, 2025

View reviewed changes

Reword log message, pass lighter params, address test fixes

6cb677f

github-actions bot deployed to docs-preview March 27, 2025 17:24 View deployment

Fix tests

78d58a4

github-actions bot deployed to docs-preview March 27, 2025 18:44 View deployment

drempapis reviewed Mar 28, 2025

View reviewed changes

benchaplin added v8.18.1 v9.0.1 and removed v9.0.0 v8.18.0 labels Mar 28, 2025

Log at warn level for server errors, update tests

b34afc1

github-actions bot deployed to docs-preview March 28, 2025 14:36 View deployment

Clarify tests

9f527eb

github-actions bot deployed to docs-preview March 28, 2025 15:29 View deployment

benwtrent reviewed Mar 28, 2025

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log stack traces on data nodes before they are cleared for transport #125732

Log stack traces on data nodes before they are cleared for transport #125732

benchaplin commented Mar 26, 2025

elasticsearchmachine commented Mar 26, 2025

elasticsearchmachine commented Mar 26, 2025

benwtrent Mar 27, 2025

benchaplin Mar 27, 2025

benwtrent Mar 27, 2025

benchaplin Mar 28, 2025

javanna left a comment

javanna Mar 27, 2025

benchaplin Mar 28, 2025

javanna Mar 27, 2025

benchaplin Mar 28, 2025

javanna Mar 27, 2025

benchaplin Mar 27, 2025

javanna Mar 27, 2025

benchaplin Mar 27, 2025

javanna Mar 27, 2025

javanna Mar 27, 2025

benchaplin Mar 28, 2025

javanna Mar 27, 2025

smalyshev Mar 26, 2025

benchaplin Mar 27, 2025

smalyshev Mar 27, 2025

smalyshev commented Mar 27, 2025

drempapis Mar 28, 2025

benchaplin Mar 28, 2025

drempapis Mar 28, 2025

benchaplin commented Mar 28, 2025 •

edited

Loading

benwtrent Mar 28, 2025

Log stack traces on data nodes before they are cleared for transport #125732

Are you sure you want to change the base?

Log stack traces on data nodes before they are cleared for transport #125732

Conversation

benchaplin commented Mar 26, 2025

elasticsearchmachine commented Mar 26, 2025

elasticsearchmachine commented Mar 26, 2025

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

javanna left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

smalyshev commented Mar 27, 2025

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

benchaplin commented Mar 28, 2025 • edited Loading

Choose a reason for hiding this comment

benchaplin commented Mar 28, 2025 •

edited

Loading