From 378595db49bfb155784df2924fe090859ebcbabf Mon Sep 17 00:00:00 2001 From: Nik Everett Date: Mon, 9 Jun 2025 10:04:14 -0400 Subject: [PATCH 1/6] ESQL: Log partial failures Now that ESQL has `allow_partial_results` we can reply with a `200` even though some nodes failed to run ESQL. This could happen because the node is restarting. Or because of a bug. Or a disconnect. All kinds of things. This logs those partial failures so an operator can look at them and get a sense of why they are happening. --- .../org/elasticsearch/rest/RestResponse.java | 26 ++--- .../esql/action/EsqlResponseListener.java | 11 ++ .../action/EsqlResponseListenerTests.java | 101 ++++++++++++++++++ 3 files changed, 125 insertions(+), 13 deletions(-) create mode 100644 x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java diff --git a/server/src/main/java/org/elasticsearch/rest/RestResponse.java b/server/src/main/java/org/elasticsearch/rest/RestResponse.java index 0c359e0a4a053..7697235e53836 100644 --- a/server/src/main/java/org/elasticsearch/rest/RestResponse.java +++ b/server/src/main/java/org/elasticsearch/rest/RestResponse.java @@ -9,9 +9,9 @@ package org.elasticsearch.rest; +import org.apache.logging.log4j.Level; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; -import org.apache.logging.log4j.util.Supplier; import org.elasticsearch.ElasticsearchException; import org.elasticsearch.ExceptionsHelper; import org.elasticsearch.common.bytes.BytesArray; @@ -126,18 +126,8 @@ public RestResponse(RestChannel channel, RestStatus status, Exception e) throws this.status = status; ToXContent.Params params = channel.request(); if (e != null) { - Supplier messageSupplier = () -> String.format( - Locale.ROOT, - "path: %s, params: %s, status: %d", - channel.request().rawPath(), - channel.request().params(), - status.getStatus() - ); - if (status.getStatus() < 500 || ExceptionsHelper.isNodeOrShardUnavailableTypeException(e)) { - SUPPRESSED_ERROR_LOGGER.debug(messageSupplier, e); - } else { - SUPPRESSED_ERROR_LOGGER.warn(messageSupplier, e); - } + Level level = status.getStatus() < 500 || ExceptionsHelper.isNodeOrShardUnavailableTypeException(e) ? Level.DEBUG : Level.WARN; + suppressedError(level, channel.request().rawPath(), channel.request().params(), status, e); } // if "error_trace" is turned on in the request, we want to render it in the rest response // for that the REST_EXCEPTION_SKIP_STACK_TRACE flag that if "true" omits the stack traces is @@ -254,4 +244,14 @@ public Map> filterHeaders(Map> headers public void close() { Releasables.closeExpectNoException(releasable); } + + public static void suppressedError(Level level, String rawPath, Map params, RestStatus status, Exception e) { + if (SUPPRESSED_ERROR_LOGGER.isEnabled(level)) { + SUPPRESSED_ERROR_LOGGER.log( + level, + String.format(Locale.ROOT, "path: %s, params: %s, status: %d", rawPath, params, status.getStatus()), + e + ); + } + } } diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java index 3d38b697dc5be..6b10bc36eb3a9 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java @@ -9,6 +9,7 @@ import org.elasticsearch.ExceptionsHelper; import org.elasticsearch.action.ActionListener; +import org.elasticsearch.action.search.ShardSearchFailure; import org.elasticsearch.core.Releasable; import org.elasticsearch.core.Releasables; import org.elasticsearch.core.TimeValue; @@ -30,6 +31,7 @@ import java.io.IOException; import java.util.Locale; +import java.util.Map; import java.util.concurrent.TimeUnit; import java.util.function.Consumer; @@ -121,6 +123,7 @@ private EsqlResponseListener(RestChannel channel, RestRequest restRequest, Strin @Override protected void processResponse(EsqlQueryResponse esqlQueryResponse) throws IOException { + logPartialResponseErrors(channel.request().rawPath(), channel.request().params(), esqlQueryResponse.getExecutionInfo()); channel.sendResponse(buildResponse(esqlQueryResponse)); } @@ -229,4 +232,12 @@ private void checkDelimiter() { throw new IllegalArgumentException(message); } } + + static void logPartialResponseErrors(String rawPath, Map params, EsqlExecutionInfo exeuctionInfo) { + for (EsqlExecutionInfo.Cluster cluster : exeuctionInfo.getClusters().values()) { + for (ShardSearchFailure failure : cluster.getFailures()) { + RestResponse.suppressedError(org.apache.logging.log4j.Level.WARN, rawPath, params, RestStatus.OK, failure); + } + } + } } diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java new file mode 100644 index 0000000000000..f76463df606f5 --- /dev/null +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java @@ -0,0 +1,101 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the Elastic License + * 2.0; you may not use this file except in compliance with the Elastic License + * 2.0. + */ + +package org.elasticsearch.xpack.esql.action; + +import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.appender.AbstractAppender; +import org.apache.logging.log4j.core.config.Configurator; +import org.apache.logging.log4j.core.filter.RegexFilter; +import org.elasticsearch.action.search.ShardSearchFailure; +import org.elasticsearch.common.logging.Loggers; +import org.elasticsearch.core.TimeValue; +import org.elasticsearch.index.shard.ShardId; +import org.elasticsearch.search.SearchShardTarget; +import org.elasticsearch.test.ESTestCase; +import org.elasticsearch.transport.RemoteClusterAware; +import org.junit.AfterClass; +import org.junit.BeforeClass; + +import java.util.ArrayList; +import java.util.List; +import java.util.Map; + +import static org.hamcrest.Matchers.equalTo; + +public class EsqlResponseListenerTests extends ESTestCase { + private final String LOCAL_CLUSTER_ALIAS = RemoteClusterAware.LOCAL_CLUSTER_GROUP_KEY; + + private static MockAppender appender; + static Logger restSuppressedLogger = LogManager.getLogger("rest.suppressed"); + + @BeforeClass + public static void init() throws IllegalAccessException { + appender = new MockAppender("testAppender"); + appender.start(); + Configurator.setLevel(restSuppressedLogger, Level.DEBUG); + Loggers.addAppender(restSuppressedLogger, appender); + } + + @AfterClass + public static void cleanup() { + appender.stop(); + Loggers.removeAppender(restSuppressedLogger, appender); + } + + public void testLogPartialResponseErrors() { + EsqlExecutionInfo executionInfo = new EsqlExecutionInfo(false); + executionInfo.swapCluster( + LOCAL_CLUSTER_ALIAS, + (k, v) -> new EsqlExecutionInfo.Cluster( + LOCAL_CLUSTER_ALIAS, + "idx", + false, + EsqlExecutionInfo.Cluster.Status.SUCCESSFUL, + 10, + 10, + 3, + 0, + List.of( + new ShardSearchFailure(new Exception("dummy"), target(0)), + new ShardSearchFailure(new Exception("error"), target(1)) + ), + new TimeValue(4444L) + ) + ); + EsqlResponseListener.logPartialResponseErrors("/_query", Map.of(), executionInfo); + + LogEvent logEvent = appender.events.get(0); + assertThat(logEvent.getLevel(), equalTo(Level.WARN)); + assertThat(logEvent.getMessage().getFormattedMessage(), equalTo("path: /_query, params: {}, status: 200")); + assertThat(logEvent.getThrown().getCause().getMessage(), equalTo("dummy")); + logEvent = appender.events.get(1); + assertThat(logEvent.getLevel(), equalTo(Level.WARN)); + assertThat(logEvent.getMessage().getFormattedMessage(), equalTo("path: /_query, params: {}, status: 200")); + assertThat(logEvent.getThrown().getCause().getMessage(), equalTo("error")); + } + + private SearchShardTarget target(int shardId) { + return new SearchShardTarget("node", new ShardId("idx", "uuid", 0), LOCAL_CLUSTER_ALIAS); + } + + private static class MockAppender extends AbstractAppender { + public final List events = new ArrayList<>(); + + MockAppender(final String name) throws IllegalAccessException { + super(name, RegexFilter.createFilter(".*(\n.*)*", new String[0], false, null, null), null, false); + } + + @Override + public void append(LogEvent event) { + events.add(event.toImmutable()); + } + } +} From 523cae14fee310b7818d78f09f2143e4135f900c Mon Sep 17 00:00:00 2001 From: Nik Everett Date: Mon, 9 Jun 2025 16:07:33 -0400 Subject: [PATCH 2/6] Words are good --- .../main/java/org/elasticsearch/rest/RestResponse.java | 7 +++++-- .../xpack/esql/action/EsqlResponseListener.java | 10 +++++++--- .../xpack/esql/action/EsqlResponseListenerTests.java | 2 +- 3 files changed, 13 insertions(+), 6 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/rest/RestResponse.java b/server/src/main/java/org/elasticsearch/rest/RestResponse.java index 7697235e53836..558ab23d3b62c 100644 --- a/server/src/main/java/org/elasticsearch/rest/RestResponse.java +++ b/server/src/main/java/org/elasticsearch/rest/RestResponse.java @@ -127,7 +127,7 @@ public RestResponse(RestChannel channel, RestStatus status, Exception e) throws ToXContent.Params params = channel.request(); if (e != null) { Level level = status.getStatus() < 500 || ExceptionsHelper.isNodeOrShardUnavailableTypeException(e) ? Level.DEBUG : Level.WARN; - suppressedError(level, channel.request().rawPath(), channel.request().params(), status, e); + logSuppressedError(level, channel.request().rawPath(), channel.request().params(), status, e); } // if "error_trace" is turned on in the request, we want to render it in the rest response // for that the REST_EXCEPTION_SKIP_STACK_TRACE flag that if "true" omits the stack traces is @@ -245,7 +245,10 @@ public void close() { Releasables.closeExpectNoException(releasable); } - public static void suppressedError(Level level, String rawPath, Map params, RestStatus status, Exception e) { + /** + * Log failures to the {@code rest.suppressed} logger. + */ + public static void logSuppressedError(Level level, String rawPath, Map params, RestStatus status, Exception e) { if (SUPPRESSED_ERROR_LOGGER.isEnabled(level)) { SUPPRESSED_ERROR_LOGGER.log( level, diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java index 6b10bc36eb3a9..a4cf1fb0bbdf8 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java @@ -123,7 +123,7 @@ private EsqlResponseListener(RestChannel channel, RestRequest restRequest, Strin @Override protected void processResponse(EsqlQueryResponse esqlQueryResponse) throws IOException { - logPartialResponseErrors(channel.request().rawPath(), channel.request().params(), esqlQueryResponse.getExecutionInfo()); + logPartialFailures(channel.request().rawPath(), channel.request().params(), esqlQueryResponse.getExecutionInfo()); channel.sendResponse(buildResponse(esqlQueryResponse)); } @@ -233,10 +233,14 @@ private void checkDelimiter() { } } - static void logPartialResponseErrors(String rawPath, Map params, EsqlExecutionInfo exeuctionInfo) { + /** + * Log all partial request failures to the {@code rest.suppressed} logger + * so an operator can categorize them after the fact. + */ + static void logPartialFailures(String rawPath, Map params, EsqlExecutionInfo exeuctionInfo) { for (EsqlExecutionInfo.Cluster cluster : exeuctionInfo.getClusters().values()) { for (ShardSearchFailure failure : cluster.getFailures()) { - RestResponse.suppressedError(org.apache.logging.log4j.Level.WARN, rawPath, params, RestStatus.OK, failure); + RestResponse.logSuppressedError(org.apache.logging.log4j.Level.WARN, rawPath, params, RestStatus.OK, failure); } } } diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java index f76463df606f5..8cf69ab0eaf1b 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java @@ -70,7 +70,7 @@ public void testLogPartialResponseErrors() { new TimeValue(4444L) ) ); - EsqlResponseListener.logPartialResponseErrors("/_query", Map.of(), executionInfo); + EsqlResponseListener.logPartialFailures("/_query", Map.of(), executionInfo); LogEvent logEvent = appender.events.get(0); assertThat(logEvent.getLevel(), equalTo(Level.WARN)); From 97c94b78e70137e7a75d297e10a44e906e524347 Mon Sep 17 00:00:00 2001 From: Nik Everett Date: Mon, 9 Jun 2025 16:08:07 -0400 Subject: [PATCH 3/6] Update docs/changelog/129164.yaml --- docs/changelog/129164.yaml | 5 +++++ 1 file changed, 5 insertions(+) create mode 100644 docs/changelog/129164.yaml diff --git a/docs/changelog/129164.yaml b/docs/changelog/129164.yaml new file mode 100644 index 0000000000000..0d16fdf1b239e --- /dev/null +++ b/docs/changelog/129164.yaml @@ -0,0 +1,5 @@ +pr: 129164 +summary: Log partial failures +area: ES|QL +type: feature +issues: [] From 586043e83a6cdbeb71396e72f82b38879cc04b21 Mon Sep 17 00:00:00 2001 From: Nik Everett Date: Tue, 10 Jun 2025 08:46:38 -0400 Subject: [PATCH 4/6] With cluster --- .../org/elasticsearch/rest/RestResponse.java | 21 +++++++---- .../esql/action/EsqlResponseListener.java | 16 +++++++-- .../action/EsqlResponseListenerTests.java | 36 ++++++++++++++++++- 3 files changed, 62 insertions(+), 11 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/rest/RestResponse.java b/server/src/main/java/org/elasticsearch/rest/RestResponse.java index 558ab23d3b62c..af9184037300a 100644 --- a/server/src/main/java/org/elasticsearch/rest/RestResponse.java +++ b/server/src/main/java/org/elasticsearch/rest/RestResponse.java @@ -127,7 +127,7 @@ public RestResponse(RestChannel channel, RestStatus status, Exception e) throws ToXContent.Params params = channel.request(); if (e != null) { Level level = status.getStatus() < 500 || ExceptionsHelper.isNodeOrShardUnavailableTypeException(e) ? Level.DEBUG : Level.WARN; - logSuppressedError(level, channel.request().rawPath(), channel.request().params(), status, e); + logSuppressedError(level, channel.request().rawPath(), channel.request().params(), status, null, e); } // if "error_trace" is turned on in the request, we want to render it in the rest response // for that the REST_EXCEPTION_SKIP_STACK_TRACE flag that if "true" omits the stack traces is @@ -248,13 +248,20 @@ public void close() { /** * Log failures to the {@code rest.suppressed} logger. */ - public static void logSuppressedError(Level level, String rawPath, Map params, RestStatus status, Exception e) { + public static void logSuppressedError( + Level level, + String rawPath, + Map params, + RestStatus status, + @Nullable String extra, + Exception e + ) { if (SUPPRESSED_ERROR_LOGGER.isEnabled(level)) { - SUPPRESSED_ERROR_LOGGER.log( - level, - String.format(Locale.ROOT, "path: %s, params: %s, status: %d", rawPath, params, status.getStatus()), - e - ); + String message = String.format(Locale.ROOT, "path: %s, params: %s, status: %d", rawPath, params, status.getStatus()); + if (extra != null) { + message += ", " + extra; + } + SUPPRESSED_ERROR_LOGGER.log(level, message, e); } } } diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java index a4cf1fb0bbdf8..d9c2bfaf092e8 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java @@ -22,6 +22,7 @@ import org.elasticsearch.rest.RestResponse; import org.elasticsearch.rest.RestStatus; import org.elasticsearch.rest.action.RestRefCountedChunkedToXContentListener; +import org.elasticsearch.transport.RemoteClusterAware; import org.elasticsearch.xcontent.MediaType; import org.elasticsearch.xcontent.XContentType; import org.elasticsearch.xpack.esql.arrow.ArrowFormat; @@ -237,10 +238,19 @@ private void checkDelimiter() { * Log all partial request failures to the {@code rest.suppressed} logger * so an operator can categorize them after the fact. */ - static void logPartialFailures(String rawPath, Map params, EsqlExecutionInfo exeuctionInfo) { - for (EsqlExecutionInfo.Cluster cluster : exeuctionInfo.getClusters().values()) { + static void logPartialFailures(String rawPath, Map params, EsqlExecutionInfo executionInfo) { + for (EsqlExecutionInfo.Cluster cluster : executionInfo.getClusters().values()) { for (ShardSearchFailure failure : cluster.getFailures()) { - RestResponse.logSuppressedError(org.apache.logging.log4j.Level.WARN, rawPath, params, RestStatus.OK, failure); + RestResponse.logSuppressedError( + org.apache.logging.log4j.Level.WARN, + rawPath, + params, + RestStatus.OK, + cluster.getClusterAlias().equals(RemoteClusterAware.LOCAL_CLUSTER_GROUP_KEY) + ? null + : "cluster: " + cluster.getClusterAlias(), + failure + ); } } } diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java index 8cf69ab0eaf1b..7d7a24dbd17dc 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java @@ -21,6 +21,7 @@ import org.elasticsearch.search.SearchShardTarget; import org.elasticsearch.test.ESTestCase; import org.elasticsearch.transport.RemoteClusterAware; +import org.junit.After; import org.junit.AfterClass; import org.junit.BeforeClass; @@ -29,6 +30,7 @@ import java.util.Map; import static org.hamcrest.Matchers.equalTo; +import static org.hamcrest.Matchers.hasSize; public class EsqlResponseListenerTests extends ESTestCase { private final String LOCAL_CLUSTER_ALIAS = RemoteClusterAware.LOCAL_CLUSTER_GROUP_KEY; @@ -44,13 +46,18 @@ public static void init() throws IllegalAccessException { Loggers.addAppender(restSuppressedLogger, appender); } + @After + public void clear() { + appender.events.clear(); + } + @AfterClass public static void cleanup() { appender.stop(); Loggers.removeAppender(restSuppressedLogger, appender); } - public void testLogPartialResponseErrors() { + public void testLogPartialFailures() { EsqlExecutionInfo executionInfo = new EsqlExecutionInfo(false); executionInfo.swapCluster( LOCAL_CLUSTER_ALIAS, @@ -72,6 +79,7 @@ public void testLogPartialResponseErrors() { ); EsqlResponseListener.logPartialFailures("/_query", Map.of(), executionInfo); + assertThat(appender.events, hasSize(2)); LogEvent logEvent = appender.events.get(0); assertThat(logEvent.getLevel(), equalTo(Level.WARN)); assertThat(logEvent.getMessage().getFormattedMessage(), equalTo("path: /_query, params: {}, status: 200")); @@ -82,6 +90,32 @@ public void testLogPartialResponseErrors() { assertThat(logEvent.getThrown().getCause().getMessage(), equalTo("error")); } + public void testLogPartialFailuresRemote() { + EsqlExecutionInfo executionInfo = new EsqlExecutionInfo(false); + executionInfo.swapCluster( + "remote_cluster", + (k, v) -> new EsqlExecutionInfo.Cluster( + "remote_cluster", + "idx", + false, + EsqlExecutionInfo.Cluster.Status.SUCCESSFUL, + 10, + 10, + 3, + 0, + List.of(new ShardSearchFailure(new Exception("dummy"), target(0))), + new TimeValue(4444L) + ) + ); + EsqlResponseListener.logPartialFailures("/_query", Map.of(), executionInfo); + + assertThat(appender.events, hasSize(1)); + LogEvent logEvent = appender.events.get(0); + assertThat(logEvent.getLevel(), equalTo(Level.WARN)); + assertThat(logEvent.getMessage().getFormattedMessage(), equalTo("path: /_query, params: {}, status: 200, cluster: remote_cluster")); + assertThat(logEvent.getThrown().getCause().getMessage(), equalTo("dummy")); + } + private SearchShardTarget target(int shardId) { return new SearchShardTarget("node", new ShardId("idx", "uuid", 0), LOCAL_CLUSTER_ALIAS); } From 98f85cbc3a63a468b7d61d9b7f828642901b56de Mon Sep 17 00:00:00 2001 From: Nik Everett Date: Tue, 10 Jun 2025 12:41:07 -0400 Subject: [PATCH 5/6] It's optional --- .../elasticsearch/xpack/esql/action/EsqlResponseListener.java | 3 +++ 1 file changed, 3 insertions(+) diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java index d9c2bfaf092e8..80044e9ba7fb8 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java @@ -239,6 +239,9 @@ private void checkDelimiter() { * so an operator can categorize them after the fact. */ static void logPartialFailures(String rawPath, Map params, EsqlExecutionInfo executionInfo) { + if (executionInfo == null) { + return; + } for (EsqlExecutionInfo.Cluster cluster : executionInfo.getClusters().values()) { for (ShardSearchFailure failure : cluster.getFailures()) { RestResponse.logSuppressedError( From 91353f433b4355038a262216820b58897aa5b478 Mon Sep 17 00:00:00 2001 From: Nik Everett Date: Wed, 11 Jun 2025 09:04:37 -0400 Subject: [PATCH 6/6] Different logger --- .../org/elasticsearch/rest/RestResponse.java | 36 +++++++------------ .../esql/action/EsqlResponseListener.java | 16 ++++----- .../action/EsqlResponseListenerTests.java | 27 +++++++------- 3 files changed, 34 insertions(+), 45 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/rest/RestResponse.java b/server/src/main/java/org/elasticsearch/rest/RestResponse.java index af9184037300a..0c359e0a4a053 100644 --- a/server/src/main/java/org/elasticsearch/rest/RestResponse.java +++ b/server/src/main/java/org/elasticsearch/rest/RestResponse.java @@ -9,9 +9,9 @@ package org.elasticsearch.rest; -import org.apache.logging.log4j.Level; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.util.Supplier; import org.elasticsearch.ElasticsearchException; import org.elasticsearch.ExceptionsHelper; import org.elasticsearch.common.bytes.BytesArray; @@ -126,8 +126,18 @@ public RestResponse(RestChannel channel, RestStatus status, Exception e) throws this.status = status; ToXContent.Params params = channel.request(); if (e != null) { - Level level = status.getStatus() < 500 || ExceptionsHelper.isNodeOrShardUnavailableTypeException(e) ? Level.DEBUG : Level.WARN; - logSuppressedError(level, channel.request().rawPath(), channel.request().params(), status, null, e); + Supplier messageSupplier = () -> String.format( + Locale.ROOT, + "path: %s, params: %s, status: %d", + channel.request().rawPath(), + channel.request().params(), + status.getStatus() + ); + if (status.getStatus() < 500 || ExceptionsHelper.isNodeOrShardUnavailableTypeException(e)) { + SUPPRESSED_ERROR_LOGGER.debug(messageSupplier, e); + } else { + SUPPRESSED_ERROR_LOGGER.warn(messageSupplier, e); + } } // if "error_trace" is turned on in the request, we want to render it in the rest response // for that the REST_EXCEPTION_SKIP_STACK_TRACE flag that if "true" omits the stack traces is @@ -244,24 +254,4 @@ public Map> filterHeaders(Map> headers public void close() { Releasables.closeExpectNoException(releasable); } - - /** - * Log failures to the {@code rest.suppressed} logger. - */ - public static void logSuppressedError( - Level level, - String rawPath, - Map params, - RestStatus status, - @Nullable String extra, - Exception e - ) { - if (SUPPRESSED_ERROR_LOGGER.isEnabled(level)) { - String message = String.format(Locale.ROOT, "path: %s, params: %s, status: %d", rawPath, params, status.getStatus()); - if (extra != null) { - message += ", " + extra; - } - SUPPRESSED_ERROR_LOGGER.log(level, message, e); - } - } } diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java index 80044e9ba7fb8..b432339ccf4fd 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/action/EsqlResponseListener.java @@ -244,16 +244,12 @@ static void logPartialFailures(String rawPath, Map params, EsqlE } for (EsqlExecutionInfo.Cluster cluster : executionInfo.getClusters().values()) { for (ShardSearchFailure failure : cluster.getFailures()) { - RestResponse.logSuppressedError( - org.apache.logging.log4j.Level.WARN, - rawPath, - params, - RestStatus.OK, - cluster.getClusterAlias().equals(RemoteClusterAware.LOCAL_CLUSTER_GROUP_KEY) - ? null - : "cluster: " + cluster.getClusterAlias(), - failure - ); + if (LOGGER.isWarnEnabled()) { + String clusterMessage = cluster.getClusterAlias().equals(RemoteClusterAware.LOCAL_CLUSTER_GROUP_KEY) + ? "" + : ", cluster: " + cluster.getClusterAlias(); + LOGGER.warn("partial failure at path: {}, params: {}{}", rawPath, params, clusterMessage, failure); + } } } } diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java index 7d7a24dbd17dc..c96af8b00ab99 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/action/EsqlResponseListenerTests.java @@ -36,14 +36,14 @@ public class EsqlResponseListenerTests extends ESTestCase { private final String LOCAL_CLUSTER_ALIAS = RemoteClusterAware.LOCAL_CLUSTER_GROUP_KEY; private static MockAppender appender; - static Logger restSuppressedLogger = LogManager.getLogger("rest.suppressed"); + static Logger logger = LogManager.getLogger(EsqlResponseListener.class); @BeforeClass public static void init() throws IllegalAccessException { appender = new MockAppender("testAppender"); appender.start(); - Configurator.setLevel(restSuppressedLogger, Level.DEBUG); - Loggers.addAppender(restSuppressedLogger, appender); + Configurator.setLevel(logger, Level.DEBUG); + Loggers.addAppender(logger, appender); } @After @@ -54,7 +54,7 @@ public void clear() { @AfterClass public static void cleanup() { appender.stop(); - Loggers.removeAppender(restSuppressedLogger, appender); + Loggers.removeAppender(logger, appender); } public void testLogPartialFailures() { @@ -71,8 +71,8 @@ public void testLogPartialFailures() { 3, 0, List.of( - new ShardSearchFailure(new Exception("dummy"), target(0)), - new ShardSearchFailure(new Exception("error"), target(1)) + new ShardSearchFailure(new Exception("dummy"), target(LOCAL_CLUSTER_ALIAS, 0)), + new ShardSearchFailure(new Exception("error"), target(LOCAL_CLUSTER_ALIAS, 1)) ), new TimeValue(4444L) ) @@ -82,11 +82,11 @@ public void testLogPartialFailures() { assertThat(appender.events, hasSize(2)); LogEvent logEvent = appender.events.get(0); assertThat(logEvent.getLevel(), equalTo(Level.WARN)); - assertThat(logEvent.getMessage().getFormattedMessage(), equalTo("path: /_query, params: {}, status: 200")); + assertThat(logEvent.getMessage().getFormattedMessage(), equalTo("partial failure at path: /_query, params: {}")); assertThat(logEvent.getThrown().getCause().getMessage(), equalTo("dummy")); logEvent = appender.events.get(1); assertThat(logEvent.getLevel(), equalTo(Level.WARN)); - assertThat(logEvent.getMessage().getFormattedMessage(), equalTo("path: /_query, params: {}, status: 200")); + assertThat(logEvent.getMessage().getFormattedMessage(), equalTo("partial failure at path: /_query, params: {}")); assertThat(logEvent.getThrown().getCause().getMessage(), equalTo("error")); } @@ -103,7 +103,7 @@ public void testLogPartialFailuresRemote() { 10, 3, 0, - List.of(new ShardSearchFailure(new Exception("dummy"), target(0))), + List.of(new ShardSearchFailure(new Exception("dummy"), target("remote_cluster", 0))), new TimeValue(4444L) ) ); @@ -112,12 +112,15 @@ public void testLogPartialFailuresRemote() { assertThat(appender.events, hasSize(1)); LogEvent logEvent = appender.events.get(0); assertThat(logEvent.getLevel(), equalTo(Level.WARN)); - assertThat(logEvent.getMessage().getFormattedMessage(), equalTo("path: /_query, params: {}, status: 200, cluster: remote_cluster")); + assertThat( + logEvent.getMessage().getFormattedMessage(), + equalTo("partial failure at path: /_query, params: {}, cluster: remote_cluster") + ); assertThat(logEvent.getThrown().getCause().getMessage(), equalTo("dummy")); } - private SearchShardTarget target(int shardId) { - return new SearchShardTarget("node", new ShardId("idx", "uuid", 0), LOCAL_CLUSTER_ALIAS); + private SearchShardTarget target(String clusterAlias, int shardId) { + return new SearchShardTarget("node", new ShardId("idx", "uuid", shardId), clusterAlias); } private static class MockAppender extends AbstractAppender {