Log at warn level for server errors, update tests

Author: benchaplin

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

@@ -557,7 +557,16 @@ 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);
+                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);
+                }
                 ExceptionsHelper.unwrapCausesAndSuppressed(e, err -> {
                     err.setStackTrace(EMPTY_STACK_TRACE_ARRAY);
                     return false;

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

@@ -156,21 +156,21 @@ public void onFailure(Exception e) {
         listener.onFailure(e);
     }
 
-    public void testMaybeWrapListenerForStackTraceLogs() {
+    public void testMaybeWrapListenerForStackTraceDebugLog() {
         final String nodeId = "node";
         final String index = "index";
         ShardId shardId = new ShardId(index, index, 0);
 
         try (var mockLog = MockLog.capture(SearchService.class)) {
-            Configurator.setLevel("org.elasticsearch.search.SearchService", Level.DEBUG);
+            Configurator.setLevel(SearchService.class, Level.DEBUG);
             final String exceptionMessage = "test exception message";
             mockLog.addExpectation(
-                new MockLog.PatternAndExceptionSeenEventExpectation(
-                    format("Tracking information ([%s]%s) and exception logged before stack trace cleared", nodeId, shardId),
+                new MockLog.ExceptionSeenEventExpectation(
+                    format("\"[%s]%s: failed to execute search request\" and an exception logged", nodeId, shardId),
                     SearchService.class.getCanonicalName(),
                     Level.DEBUG,
-                    format("\\[%s\\]%s: failed to execute search request", nodeId, shardId),
-                    Exception.class,
+                    format("[%s]%s: failed to execute search request", nodeId, shardId),
+                    IllegalArgumentException.class,
                     exceptionMessage
                 )
             );
@@ -187,7 +187,45 @@ public void onFailure(Exception e) {
                     mockLog.assertAllExpectationsMatched();
                 }
             };
-            Exception e = new Exception(exceptionMessage);
+            // This is a 400-level exception, so it should only be debug logged
+            IllegalArgumentException e = new IllegalArgumentException(exceptionMessage);
+            listener = maybeWrapListenerForStackTrace(listener, TransportVersion.current(), nodeId, shardId, threadPool);
+            listener.onFailure(e);
+        }
+    }
+
+    public void testMaybeWrapListenerForStackTraceWarnLog() {
+        final String nodeId = "node";
+        final String index = "index";
+        ShardId shardId = new ShardId(index, index, 0);
+
+        try (var mockLog = MockLog.capture(SearchService.class)) {
+            final String exceptionMessage = "test exception message";
+            mockLog.addExpectation(
+                new MockLog.ExceptionSeenEventExpectation(
+                    format("\"[%s]%s: failed to execute search request\" and an exception logged", nodeId, shardId),
+                    SearchService.class.getCanonicalName(),
+                    Level.WARN,
+                    format("[%s]%s: failed to execute search request", nodeId, shardId),
+                    IllegalStateException.class,
+                    exceptionMessage
+                )
+            );
+
+            // Tests the listener has logged if it is wrapped
+            ActionListener<SearchPhaseResult> listener = new ActionListener<>() {
+                @Override
+                public void onResponse(SearchPhaseResult searchPhaseResult) {
+                    // noop - we only care about failure scenarios
+                }
+
+                @Override
+                public void onFailure(Exception e) {
+                    mockLog.assertAllExpectationsMatched();
+                }
+            };
+            // This is a 400-level exception, so it should only be debug logged
+            IllegalStateException e = new IllegalStateException(exceptionMessage);
             listener = maybeWrapListenerForStackTrace(listener, TransportVersion.current(), nodeId, shardId, threadPool);
             listener.onFailure(e);
         }

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

@@ -71,7 +71,7 @@ public static void addSeenLoggingExpectations(int numShards, MockLog mockLog, St
             mockLog.addExpectation(
                 new MockLog.PatternAndExceptionSeenEventExpectation(
                     format(
-                        "Tracking information ([%s][%s][%d]) and exception logged before stack trace cleared",
+                        "\"[%s][%s][%d]: failed to execute search request\" and an exception logged",
                         nodesDisjunction,
                         errorTriggeringIndex,
                         shard
@@ -99,7 +99,7 @@ public static void addUnseenLoggingExpectations(int numShards, MockLog mockLog,
             for (int shard = 0; shard < numShards; shard++) {
                 mockLog.addExpectation(
                     new MockLog.UnseenEventExpectation(
-                        "Tracking information ([nodeId][indexName][shard]) and exception logged before stack trace cleared",
+                        "\"[%s][%s][%d]: failed to execute search request\" and an exception logged",
                         SearchService.class.getCanonicalName(),
                         Level.DEBUG,
                         format("[%s][%s][%d]: failed to execute search request", getNodeId(nodeName), errorTriggeringIndex, shard)

test/framework/src/main/java/org/elasticsearch/test/MockLog.java

@@ -344,8 +344,10 @@ public void match(LogEvent event) {
                     && event.getThrown().getClass() == clazz
                     && event.getThrown().getMessage().equals(exceptionMessage);
 
-                if (patternMatches && exceptionMatches) {
-                    seenLatch.countDown();
+                if (exceptionMatches) {
+                    if (patternMatches) {
+                        seenLatch.countDown();
+                    }
                 }
             }
         }