Skip to content

Commit 6cce5eb

Browse files
authored
ESQL: Switch log level for cancelled query (#138389)
When a `Driver` hits an error running a query it logs it at `ERROR` which is great. But cancelled queries also show up as errors: ``` ERROR org.elasticsearch.tasks.TaskCancelledException: http channel [Netty4HttpChannel{...}] closed ``` That's too noisy. This switches these logs to DEBUG. We can log them if we need, but otherwise they are quiet.
1 parent 6137e22 commit 6cce5eb

File tree

2 files changed

+40
-0
lines changed
  • x-pack/plugin/esql

2 files changed

+40
-0
lines changed

x-pack/plugin/esql/compute/src/main/java/org/elasticsearch/compute/operator/Driver.java

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -192,6 +192,9 @@ SubscribableListener<Void> run(TimeValue maxTime, int maxIterations, LongSupplie
192192
} catch (DriverEarlyTerminationException unused) {
193193
closeEarlyFinishedOperators(activeOperators.listIterator(activeOperators.size()));
194194
assert isFinished() : "not finished after early termination";
195+
} catch (TaskCancelledException e) {
196+
LOGGER.debug("Cancelling running driver [{}]", shortDescription, e);
197+
throw e;
195198
} catch (RuntimeException e) {
196199
LOGGER.error(Strings.format("Error running driver [%s]", shortDescription), e);
197200
throw e;

x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlActionTaskIT.java

Lines changed: 37 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,8 @@
77

88
package org.elasticsearch.xpack.esql.action;
99

10+
import org.apache.logging.log4j.Level;
11+
import org.apache.logging.log4j.core.LogEvent;
1012
import org.apache.lucene.search.DocIdSetIterator;
1113
import org.elasticsearch.ExceptionsHelper;
1214
import org.elasticsearch.action.ActionFuture;
@@ -16,11 +18,13 @@
1618
import org.elasticsearch.client.internal.Client;
1719
import org.elasticsearch.common.Strings;
1820
import org.elasticsearch.common.collect.Iterators;
21+
import org.elasticsearch.common.logging.Loggers;
1922
import org.elasticsearch.common.settings.Settings;
2023
import org.elasticsearch.common.util.CollectionUtils;
2124
import org.elasticsearch.common.util.concurrent.AbstractRunnable;
2225
import org.elasticsearch.compute.lucene.LuceneSourceOperator;
2326
import org.elasticsearch.compute.lucene.read.ValuesSourceReaderOperatorStatus;
27+
import org.elasticsearch.compute.operator.Driver;
2428
import org.elasticsearch.compute.operator.DriverStatus;
2529
import org.elasticsearch.compute.operator.DriverTaskRunner;
2630
import org.elasticsearch.compute.operator.OperatorStatus;
@@ -39,9 +43,12 @@
3943
import org.elasticsearch.threadpool.ThreadPool;
4044
import org.elasticsearch.transport.TransportService;
4145
import org.elasticsearch.xpack.esql.EsqlTestUtils;
46+
import org.elasticsearch.xpack.esql.MockAppender;
4247
import org.elasticsearch.xpack.esql.plugin.QueryPragmas;
4348
import org.hamcrest.Matcher;
49+
import org.junit.AfterClass;
4450
import org.junit.Before;
51+
import org.junit.BeforeClass;
4552

4653
import java.io.IOException;
4754
import java.util.ArrayList;
@@ -66,6 +73,7 @@
6673
import static org.hamcrest.Matchers.in;
6774
import static org.hamcrest.Matchers.lessThanOrEqualTo;
6875
import static org.hamcrest.Matchers.not;
76+
import static org.hamcrest.Matchers.startsWith;
6977

7078
/**
7179
* Tests that we expose a reasonable task status.
@@ -78,6 +86,25 @@ public class EsqlActionTaskIT extends AbstractPausableIntegTestCase {
7886

7987
private static final Logger LOGGER = LogManager.getLogger(EsqlActionTaskIT.class);
8088

89+
static MockAppender driverMockAppender;
90+
static org.apache.logging.log4j.Logger driverLog = org.apache.logging.log4j.LogManager.getLogger(Driver.class);
91+
static Level origDriverLogLevel = driverLog.getLevel();
92+
93+
@BeforeClass
94+
public static void init() throws IllegalAccessException {
95+
driverMockAppender = new MockAppender("mock_appender");
96+
driverMockAppender.start();
97+
Loggers.addAppender(driverLog, driverMockAppender);
98+
Loggers.setLevel(driverLog, Level.DEBUG);
99+
}
100+
101+
@AfterClass
102+
public static void cleanup() {
103+
Loggers.removeAppender(driverLog, driverMockAppender);
104+
driverMockAppender.stop();
105+
Loggers.setLevel(driverLog, origDriverLogLevel);
106+
}
107+
81108
private Boolean nodeLevelReduction;
82109

83110
/**
@@ -214,6 +241,7 @@ public void testCancelRead() throws Exception {
214241
} finally {
215242
scriptPermits.release(numberOfDocs());
216243
}
244+
assertCancelledLog();
217245
}
218246

219247
public void testCancelMerge() throws Exception {
@@ -226,6 +254,7 @@ public void testCancelMerge() throws Exception {
226254
} finally {
227255
scriptPermits.release(numberOfDocs());
228256
}
257+
assertCancelledLog();
229258
}
230259

231260
public void testCancelEsqlTask() throws Exception {
@@ -244,6 +273,14 @@ public void testCancelEsqlTask() throws Exception {
244273
} finally {
245274
scriptPermits.release(numberOfDocs());
246275
}
276+
assertCancelledLog();
277+
}
278+
279+
private void assertCancelledLog() {
280+
LogEvent event = driverMockAppender.getLastEventAndReset();
281+
assertThat(event.getLevel(), equalTo(Level.DEBUG));
282+
assertThat(event.getMessage().getFormattedMessage(), startsWith("Cancelling running driver ["));
283+
assertThat(event.getThrown().getClass(), equalTo(TaskCancelledException.class));
247284
}
248285

249286
private ActionFuture<EsqlQueryResponse> startEsql() {

0 commit comments

Comments
 (0)