From dca56b5a76a7d0fe09ebaada6646c9fce1b0a38f Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Wed, 5 Mar 2025 12:12:04 +0100 Subject: [PATCH 01/19] ES|QL slow log --- distribution/src/config/log4j2.properties | 23 +++ .../elasticsearch/test/cluster/LogType.java | 1 + .../xpack/esql/action/EsqlSlowLogIT.java | 161 ++++++++++++++++++ .../xpack/esql/action/MockAppender.java | 40 +++++ .../xpack/esql/execution/PlanExecutor.java | 6 +- .../xpack/esql/plugin/EsqlPlugin.java | 54 +++++- .../xpack/esql/session/EsqlCCSUtils.java | 2 +- .../xpack/esql/slowlog/EsqlSlowLog.java | 95 +++++++++++ .../telemetry/PlanExecutorMetricsTests.java | 4 +- 9 files changed, 381 insertions(+), 5 deletions(-) create mode 100644 x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java create mode 100644 x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/MockAppender.java create mode 100644 x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java diff --git a/distribution/src/config/log4j2.properties b/distribution/src/config/log4j2.properties index bde4d9d17fc17..f0798f5a33e2f 100644 --- a/distribution/src/config/log4j2.properties +++ b/distribution/src/config/log4j2.properties @@ -129,3 +129,26 @@ logger.index_indexing_slowlog.name = index.indexing.slowlog.index logger.index_indexing_slowlog.level = trace logger.index_indexing_slowlog.appenderRef.index_indexing_slowlog_rolling.ref = index_indexing_slowlog_rolling logger.index_indexing_slowlog.additivity = false + + +######## Search ES|QL JSON #################### +appender.esql_slowlog_rolling.type = RollingFile +appender.esql_slowlog_rolling.name = esql_slowlog_rolling +appender.esql_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs\ + .cluster_name}_esql_slowlog.json +appender.esql_slowlog_rolling.layout.type = ECSJsonLayout +appender.esql_slowlog_rolling.layout.dataset = elasticsearch.esql_slowlog + +appender.esql_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs\ + .cluster_name}_esql_slowlog-%i.json.gz +appender.esql_slowlog_rolling.policies.type = Policies +appender.esql_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy +appender.esql_slowlog_rolling.policies.size.size = 1GB +appender.esql_slowlog_rolling.strategy.type = DefaultRolloverStrategy +appender.esql_slowlog_rolling.strategy.max = 4 +################################################# + +logger.esql_slowlog_rolling.name = esql.slowlog +logger.esql_slowlog_rolling.level = trace +logger.esql_slowlog_rolling.appenderRef.index_search_slowlog_rolling.ref = esql_slowlog_rolling +logger.esql_slowlog_rolling.additivity = false diff --git a/test/test-clusters/src/main/java/org/elasticsearch/test/cluster/LogType.java b/test/test-clusters/src/main/java/org/elasticsearch/test/cluster/LogType.java index 548a372964887..71dd9275e28b2 100644 --- a/test/test-clusters/src/main/java/org/elasticsearch/test/cluster/LogType.java +++ b/test/test-clusters/src/main/java/org/elasticsearch/test/cluster/LogType.java @@ -15,6 +15,7 @@ public enum LogType { AUDIT("%s_audit.json"), SEARCH_SLOW("%s_index_search_slowlog.json"), INDEXING_SLOW("%s_index_indexing_slowlog.json"), + ESQL_SLOW("%s_esql_slowlog.json"), DEPRECATION("%s_deprecation.json"); private final String filenameFormat; diff --git a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java new file mode 100644 index 0000000000000..2325fab72ba3a --- /dev/null +++ b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java @@ -0,0 +1,161 @@ +/* + * 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.elasticsearch.action.ActionListener; +import org.elasticsearch.action.admin.cluster.settings.ClusterUpdateSettingsAction; +import org.elasticsearch.action.admin.cluster.settings.ClusterUpdateSettingsRequest; +import org.elasticsearch.cluster.node.DiscoveryNode; +import org.elasticsearch.common.logging.ESLogMessage; +import org.elasticsearch.common.logging.Loggers; +import org.elasticsearch.common.settings.Settings; +import org.elasticsearch.core.TimeValue; +import org.elasticsearch.xpack.esql.plugin.EsqlPlugin; +import org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog; +import org.junit.AfterClass; +import org.junit.BeforeClass; + +import java.util.Map; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutionException; +import java.util.concurrent.TimeUnit; + +import static org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked; +import static org.hamcrest.Matchers.equalTo; +import static org.hamcrest.Matchers.greaterThan; +import static org.hamcrest.Matchers.greaterThanOrEqualTo; +import static org.hamcrest.Matchers.is; + +public class EsqlSlowLogIT extends AbstractEsqlIntegTestCase { + static MockAppender appender; + static Logger queryLog = LogManager.getLogger(EsqlSlowLog.SLOWLOG_PREFIX + ".query"); + static Level origQueryLogLevel = queryLog.getLevel(); + + @BeforeClass + public static void init() throws IllegalAccessException { + appender = new MockAppender("trace_appender"); + appender.start(); + Loggers.addAppender(queryLog, appender); + + Loggers.setLevel(queryLog, Level.TRACE); + } + + @AfterClass + public static void cleanup() { + Loggers.removeAppender(queryLog, appender); + appender.stop(); + Loggers.setLevel(queryLog, origQueryLogLevel); + } + + public void testSetLevel() throws Exception { + final String node1, node2; + if (randomBoolean()) { + internalCluster().ensureAtLeastNumDataNodes(2); + node1 = randomDataNode().getName(); + node2 = randomValueOtherThan(node1, () -> randomDataNode().getName()); + } else { + node1 = randomDataNode().getName(); + node2 = randomDataNode().getName(); + } + + int numDocs1 = randomIntBetween(1, 15); + assertAcked(client().admin().indices().prepareCreate("index-1").setMapping("host", "type=keyword")); + for (int i = 0; i < numDocs1; i++) { + client().prepareIndex("index-1").setSource("host", "192." + i).get(); + } + int numDocs2 = randomIntBetween(1, 15); + assertAcked(client().admin().indices().prepareCreate("index-2").setMapping("host", "type=keyword")); + for (int i = 0; i < numDocs2; i++) { + client().prepareIndex("index-2").setSource("host", "10." + i).get(); + } + + DiscoveryNode coordinator = randomFrom(clusterService().state().nodes().stream().toList()); + client().admin().indices().prepareRefresh("index-1", "index-2").get(); + + Map levels = Map.of( + Level.WARN, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING.getKey(), + Level.INFO, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING.getKey(), + Level.DEBUG, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), + Level.TRACE, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey() + ); + testAllLevels(levels, coordinator, 0); + for (int i = 0; i < 10; i++) { + testAllLevels(levels, coordinator, randomIntBetween(0, 10_000)); + } + } + + private static void testAllLevels(Map levels, DiscoveryNode coordinator, long timeoutMillis) throws InterruptedException, + ExecutionException { + for (Map.Entry logLevel : levels.entrySet()) { + + client().execute( + ClusterUpdateSettingsAction.INSTANCE, + new ClusterUpdateSettingsRequest(TimeValue.THIRTY_SECONDS, TimeValue.THIRTY_SECONDS).persistentSettings( + Settings.builder().put(logLevel.getValue(), timeoutMillis + "ms") + ) + ).get(); + + EsqlQueryRequest request = EsqlQueryRequest.syncEsqlQueryRequest(); + var querySource = "FROM index-* | EVAL ip = to_ip(host) | STATS s = COUNT(*) by ip | KEEP ip | LIMIT 100"; + request.query(querySource); + request.pragmas(randomPragmas()); + CountDownLatch latch = new CountDownLatch(1); + client(coordinator.getName()).execute(EsqlQueryAction.INSTANCE, request, ActionListener.running(() -> { + try { + if (appender.lastEvent() == null) { + if (timeoutMillis == 0) { + fail("Expected a slow log with timeout set to zero"); + } + return; + } + var msg = (ESLogMessage) appender.lastMessage(); + long took = Long.valueOf(msg.get("elasticsearch.slowlog.took")); + long tookMillisExpected = took / 1_000_000; + long tookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.took_millis")); + assertThat(took, greaterThan(0L)); + assertThat(tookMillis, greaterThanOrEqualTo(timeoutMillis)); + assertThat(tookMillis, is(tookMillisExpected)); + + long planningTook = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took")); + long planningTookMillisExpected = planningTook / 1_000_000; + long planningTookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took_millis")); + assertThat(planningTook, greaterThanOrEqualTo(0L)); + assertThat(planningTookMillis, greaterThanOrEqualTo(timeoutMillis)); + assertThat(planningTookMillis, is(planningTookMillisExpected)); + + assertThat(took, greaterThan(planningTook)); + + assertThat(msg.get("elasticsearch.slowlog.source"), is(querySource)); + assertThat(appender.getLastEventAndReset().getLevel(), equalTo(logLevel.getKey())); + } finally { + latch.countDown(); + } + })); + latch.await(30, TimeUnit.SECONDS); + + client().execute( + ClusterUpdateSettingsAction.INSTANCE, + new ClusterUpdateSettingsRequest(TimeValue.THIRTY_SECONDS, TimeValue.THIRTY_SECONDS).persistentSettings( + Settings.builder().putNull(logLevel.getValue()) + ) + ).get(); + } + } + + private DiscoveryNode randomDataNode() { + return randomFrom(clusterService().state().nodes().getDataNodes().values()); + } + +} diff --git a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/MockAppender.java b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/MockAppender.java new file mode 100644 index 0000000000000..35118ae1b7955 --- /dev/null +++ b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/MockAppender.java @@ -0,0 +1,40 @@ +/* + * 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.core.LogEvent; +import org.apache.logging.log4j.core.appender.AbstractAppender; +import org.apache.logging.log4j.core.filter.RegexFilter; +import org.apache.logging.log4j.message.Message; + +public class MockAppender extends AbstractAppender { + public LogEvent lastEvent; + + public 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) { + lastEvent = event.toImmutable(); + } + + Message lastMessage() { + return lastEvent.getMessage(); + } + + LogEvent lastEvent() { + return lastEvent; + } + + public LogEvent getLastEventAndReset() { + LogEvent toReturn = lastEvent; + lastEvent = null; + return toReturn; + } +} diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java index 611516fc55342..c590de9913edd 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java @@ -26,6 +26,7 @@ import org.elasticsearch.xpack.esql.session.EsqlSession; import org.elasticsearch.xpack.esql.session.IndexResolver; import org.elasticsearch.xpack.esql.session.Result; +import org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog; import org.elasticsearch.xpack.esql.telemetry.Metrics; import org.elasticsearch.xpack.esql.telemetry.PlanTelemetry; import org.elasticsearch.xpack.esql.telemetry.PlanTelemetryManager; @@ -42,8 +43,9 @@ public class PlanExecutor { private final Metrics metrics; private final Verifier verifier; private final PlanTelemetryManager planTelemetryManager; + private final EsqlSlowLog slowLog; - public PlanExecutor(IndexResolver indexResolver, MeterRegistry meterRegistry, XPackLicenseState licenseState) { + public PlanExecutor(IndexResolver indexResolver, MeterRegistry meterRegistry, XPackLicenseState licenseState, EsqlSlowLog slowLog) { this.indexResolver = indexResolver; this.preAnalyzer = new PreAnalyzer(); this.functionRegistry = new EsqlFunctionRegistry(); @@ -51,6 +53,7 @@ public PlanExecutor(IndexResolver indexResolver, MeterRegistry meterRegistry, XP this.metrics = new Metrics(functionRegistry); this.verifier = new Verifier(metrics, licenseState); this.planTelemetryManager = new PlanTelemetryManager(meterRegistry); + this.slowLog = slowLog; } public void esql( @@ -85,6 +88,7 @@ public void esql( ActionListener executeListener = wrap(x -> { planTelemetryManager.publish(planTelemetry, true); + slowLog.onQueryPhase(x, request.query()); listener.onResponse(x); }, ex -> { // TODO when we decide if we will differentiate Kibana from REST, this String value will likely come from the request diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java index 7b7b056741e27..8adac2b11a87c 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java @@ -38,6 +38,7 @@ import org.elasticsearch.compute.operator.exchange.ExchangeSinkOperator; import org.elasticsearch.compute.operator.exchange.ExchangeSourceOperator; import org.elasticsearch.compute.operator.topn.TopNOperatorStatus; +import org.elasticsearch.core.TimeValue; import org.elasticsearch.features.NodeFeature; import org.elasticsearch.license.XPackLicenseState; import org.elasticsearch.plugins.ActionPlugin; @@ -70,6 +71,7 @@ import org.elasticsearch.xpack.esql.plan.PlanWritables; import org.elasticsearch.xpack.esql.querydsl.query.SingleValueQuery; import org.elasticsearch.xpack.esql.session.IndexResolver; +import org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog; import java.lang.invoke.MethodHandles; import java.util.ArrayList; @@ -102,6 +104,42 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); + public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING = Setting.timeSetting( + "esql.slowlog.threshold.query.warn", + TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), + TimeValue.timeValueMillis(Integer.MAX_VALUE), + Setting.Property.NodeScope, + Setting.Property.Dynamic + ); + + public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING = Setting.timeSetting( + "esql.slowlog.threshold.query.info", + TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), + TimeValue.timeValueMillis(Integer.MAX_VALUE), + Setting.Property.NodeScope, + Setting.Property.Dynamic + ); + + public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING = Setting.timeSetting( + "esql.slowlog.threshold.query.debug", + TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), + TimeValue.timeValueMillis(Integer.MAX_VALUE), + Setting.Property.NodeScope, + Setting.Property.Dynamic + ); + + public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING = Setting.timeSetting( + "esql.slowlog.threshold.query.trace", + TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), + TimeValue.timeValueMillis(Integer.MAX_VALUE), + Setting.Property.NodeScope, + Setting.Property.Dynamic + ); + @Override public Collection createComponents(PluginServices services) { CircuitBreaker circuitBreaker = services.indicesService().getBigArrays().breakerService().getBreaker("request"); @@ -115,7 +153,12 @@ public Collection createComponents(PluginServices services) { var blockFactoryProvider = blockFactoryProvider(circuitBreaker, bigArrays, maxPrimitiveArrayBlockSize); setupSharedSecrets(); return List.of( - new PlanExecutor(new IndexResolver(services.client()), services.telemetryProvider().getMeterRegistry(), getLicenseState()), + new PlanExecutor( + new IndexResolver(services.client()), + services.telemetryProvider().getMeterRegistry(), + getLicenseState(), + new EsqlSlowLog(services.clusterService().getClusterSettings()) + ), new ExchangeService( services.clusterService().getSettings(), services.threadPool(), @@ -151,7 +194,14 @@ protected XPackLicenseState getLicenseState() { */ @Override public List> getSettings() { - return List.of(QUERY_RESULT_TRUNCATION_DEFAULT_SIZE, QUERY_RESULT_TRUNCATION_MAX_SIZE); + return List.of( + QUERY_RESULT_TRUNCATION_DEFAULT_SIZE, + QUERY_RESULT_TRUNCATION_MAX_SIZE, + ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, + ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, + ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, + ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING + ); } @Override diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/session/EsqlCCSUtils.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/session/EsqlCCSUtils.java index 89cd4b3d4d7cd..da34e0e397e28 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/session/EsqlCCSUtils.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/session/EsqlCCSUtils.java @@ -269,8 +269,8 @@ static boolean concreteIndexRequested(String indexExpression) { // visible for testing static void updateExecutionInfoAtEndOfPlanning(EsqlExecutionInfo execInfo) { // TODO: this logic assumes a single phase execution model, so it may need to altered once INLINESTATS is made CCS compatible + execInfo.markEndPlanning(); if (execInfo.isCrossClusterSearch()) { - execInfo.markEndPlanning(); for (String clusterAlias : execInfo.clusterAliases()) { EsqlExecutionInfo.Cluster cluster = execInfo.getCluster(clusterAlias); if (cluster.getStatus() == EsqlExecutionInfo.Cluster.Status.SKIPPED) { diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java new file mode 100644 index 0000000000000..f3e042165686c --- /dev/null +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java @@ -0,0 +1,95 @@ +/* + * 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.slowlog; + +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.elasticsearch.common.logging.ESLogMessage; +import org.elasticsearch.common.settings.ClusterSettings; +import org.elasticsearch.xcontent.ToXContent; +import org.elasticsearch.xcontent.json.JsonStringEncoder; +import org.elasticsearch.xpack.esql.session.Result; + +import java.nio.charset.StandardCharsets; +import java.util.Collections; +import java.util.HashMap; +import java.util.Map; + +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING; + +public final class EsqlSlowLog { + + private final ClusterSettings clusterSettings; + + public static final String SLOWLOG_PREFIX = "esql.slowlog"; + + private static final Logger queryLogger = LogManager.getLogger(SLOWLOG_PREFIX + ".query"); + + private static final ToXContent.Params FORMAT_PARAMS = new ToXContent.MapParams(Collections.singletonMap("pretty", "false")); + + public EsqlSlowLog(ClusterSettings settings) { + this.clusterSettings = settings; + } + + public void onQueryPhase(Result esqlResult, String query) { + if (esqlResult == null) { + return; // TODO review, it happens in some tests, not sure if it's a thing also in prod + } + long tookInNanos = esqlResult.executionInfo().overallTook().nanos(); + var queryWarnThreshold = clusterSettings.get(ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING).nanos(); + if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) { + queryLogger.warn(Message.of(esqlResult, query)); + return; + } + var queryInfoThreshold = clusterSettings.get(ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING).nanos(); + if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { + queryLogger.info(Message.of(esqlResult, query)); + return; + } + var queryDebugThreshold = clusterSettings.get(ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING).nanos(); + if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { + queryLogger.debug(Message.of(esqlResult, query)); + return; + } + var queryTraceThreshold = clusterSettings.get(ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING).nanos(); + if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { + queryLogger.trace(Message.of(esqlResult, query)); + return; + } + } + + static final class Message { + + private static String escapeJson(String text) { + byte[] sourceEscaped = JsonStringEncoder.getInstance().quoteAsUTF8(text); + return new String(sourceEscaped, StandardCharsets.UTF_8); + } + + public static ESLogMessage of(Result esqlResult, String query) { + Map jsonFields = prepareMap(esqlResult, query); + + return new ESLogMessage().withFields(jsonFields); + } + + private static Map prepareMap(Result esqlResult, String query) { + Map messageFields = new HashMap<>(); + messageFields.put("elasticsearch.slowlog.message", esqlResult.executionInfo().clusterAliases()); + messageFields.put("elasticsearch.slowlog.took", esqlResult.executionInfo().overallTook().nanos()); + messageFields.put("elasticsearch.slowlog.took_millis", esqlResult.executionInfo().overallTook().millis()); + messageFields.put("elasticsearch.slowlog.planning.took", esqlResult.executionInfo().planningTookTime().nanos()); + messageFields.put("elasticsearch.slowlog.planning.took_millis", esqlResult.executionInfo().planningTookTime().millis()); + messageFields.put("elasticsearch.slowlog.search_type", "ESQL"); + String source = escapeJson(query); + messageFields.put("elasticsearch.slowlog.source", source); + return messageFields; + } + } +} diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java index aa735e5cb6d86..c5cca627dc589 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java @@ -15,6 +15,7 @@ import org.elasticsearch.action.fieldcaps.IndexFieldCapabilities; import org.elasticsearch.action.support.IndicesOptions; import org.elasticsearch.client.internal.Client; +import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.index.IndexMode; import org.elasticsearch.indices.IndicesExpressionGrouper; import org.elasticsearch.license.XPackLicenseState; @@ -34,6 +35,7 @@ import org.elasticsearch.xpack.esql.session.EsqlSession; import org.elasticsearch.xpack.esql.session.IndexResolver; import org.elasticsearch.xpack.esql.session.Result; +import org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog; import org.junit.After; import org.junit.Before; import org.mockito.stubbing.Answer; @@ -104,7 +106,7 @@ public void testFailedMetric() { return null; }).when(esqlClient).execute(eq(EsqlResolveFieldsAction.TYPE), any(), any()); - var planExecutor = new PlanExecutor(indexResolver, MeterRegistry.NOOP, new XPackLicenseState(() -> 0L)); + var planExecutor = new PlanExecutor(indexResolver, MeterRegistry.NOOP, new XPackLicenseState(() -> 0L), new EsqlSlowLog(ClusterSettings.createBuiltInClusterSettings())); var enrichResolver = mockEnrichResolver(); var request = new EsqlQueryRequest(); From e725e079500dae4e21439c354a0e0bbe308d3fda Mon Sep 17 00:00:00 2001 From: elasticsearchmachine Date: Wed, 5 Mar 2025 13:14:58 +0000 Subject: [PATCH 02/19] [CI] Auto commit changes from spotless --- .../xpack/esql/telemetry/PlanExecutorMetricsTests.java | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java index c5cca627dc589..fbf88d255d94d 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java @@ -106,7 +106,12 @@ public void testFailedMetric() { return null; }).when(esqlClient).execute(eq(EsqlResolveFieldsAction.TYPE), any(), any()); - var planExecutor = new PlanExecutor(indexResolver, MeterRegistry.NOOP, new XPackLicenseState(() -> 0L), new EsqlSlowLog(ClusterSettings.createBuiltInClusterSettings())); + var planExecutor = new PlanExecutor( + indexResolver, + MeterRegistry.NOOP, + new XPackLicenseState(() -> 0L), + new EsqlSlowLog(ClusterSettings.createBuiltInClusterSettings()) + ); var enrichResolver = mockEnrichResolver(); var request = new EsqlQueryRequest(); From d4ed58f14937b6e5caf4a156834f3ddfce4cfa24 Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Fri, 7 Mar 2025 12:04:46 +0100 Subject: [PATCH 03/19] First round of reviews --- .../xpack/esql/action/EsqlSlowLogIT.java | 12 ++--- .../xpack/esql/plugin/EsqlPlugin.java | 8 +-- .../xpack/esql/slowlog/EsqlSlowLog.java | 51 ++++++++++++------- 3 files changed, 42 insertions(+), 29 deletions(-) diff --git a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java index 2325fab72ba3a..b94336a06f5c2 100644 --- a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java +++ b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java @@ -26,7 +26,6 @@ import java.util.Map; import java.util.concurrent.CountDownLatch; import java.util.concurrent.ExecutionException; -import java.util.concurrent.TimeUnit; import static org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked; import static org.hamcrest.Matchers.equalTo; @@ -56,14 +55,12 @@ public static void cleanup() { } public void testSetLevel() throws Exception { - final String node1, node2; + final String node1; if (randomBoolean()) { internalCluster().ensureAtLeastNumDataNodes(2); node1 = randomDataNode().getName(); - node2 = randomValueOtherThan(node1, () -> randomDataNode().getName()); } else { node1 = randomDataNode().getName(); - node2 = randomDataNode().getName(); } int numDocs1 = randomIntBetween(1, 15); @@ -137,13 +134,16 @@ private static void testAllLevels(Map levels, DiscoveryNode coord assertThat(took, greaterThan(planningTook)); - assertThat(msg.get("elasticsearch.slowlog.source"), is(querySource)); + assertThat(msg.get("elasticsearch.slowlog.query"), is(querySource)); assertThat(appender.getLastEventAndReset().getLevel(), equalTo(logLevel.getKey())); } finally { latch.countDown(); } })); - latch.await(30, TimeUnit.SECONDS); + + safeAwait(latch); + + assertEquals("All requests must respond", 0, latch.getCount()); client().execute( ClusterUpdateSettingsAction.INSTANCE, diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java index 84c4afc6b39a0..33849bd6bdb3b 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java @@ -113,7 +113,7 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING = Setting.timeSetting( "esql.slowlog.threshold.query.warn", - TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), Setting.Property.NodeScope, @@ -122,7 +122,7 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING = Setting.timeSetting( "esql.slowlog.threshold.query.info", - TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), Setting.Property.NodeScope, @@ -131,7 +131,7 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING = Setting.timeSetting( "esql.slowlog.threshold.query.debug", - TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), Setting.Property.NodeScope, @@ -140,7 +140,7 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING = Setting.timeSetting( "esql.slowlog.threshold.query.trace", - TimeValue.timeValueNanos(-1), + TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), Setting.Property.NodeScope, diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java index f3e042165686c..a96037160463c 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java @@ -11,12 +11,11 @@ import org.apache.logging.log4j.Logger; import org.elasticsearch.common.logging.ESLogMessage; import org.elasticsearch.common.settings.ClusterSettings; -import org.elasticsearch.xcontent.ToXContent; +import org.elasticsearch.core.TimeValue; import org.elasticsearch.xcontent.json.JsonStringEncoder; import org.elasticsearch.xpack.esql.session.Result; import java.nio.charset.StandardCharsets; -import java.util.Collections; import java.util.HashMap; import java.util.Map; @@ -33,9 +32,16 @@ public final class EsqlSlowLog { private static final Logger queryLogger = LogManager.getLogger(SLOWLOG_PREFIX + ".query"); - private static final ToXContent.Params FORMAT_PARAMS = new ToXContent.MapParams(Collections.singletonMap("pretty", "false")); + private volatile long queryWarnThreshold; + private volatile long queryInfoThreshold; + private volatile long queryDebugThreshold; + private volatile long queryTraceThreshold; public EsqlSlowLog(ClusterSettings settings) { + settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, this::setQueryWarnThreshold); + settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, this::setQueryInfoThreshold); + settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, this::setQueryDebugThreshold); + settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, this::setQueryTraceThreshold); this.clusterSettings = settings; } @@ -44,28 +50,36 @@ public void onQueryPhase(Result esqlResult, String query) { return; // TODO review, it happens in some tests, not sure if it's a thing also in prod } long tookInNanos = esqlResult.executionInfo().overallTook().nanos(); - var queryWarnThreshold = clusterSettings.get(ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING).nanos(); if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) { queryLogger.warn(Message.of(esqlResult, query)); - return; - } - var queryInfoThreshold = clusterSettings.get(ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING).nanos(); - if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { + } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { queryLogger.info(Message.of(esqlResult, query)); - return; - } - var queryDebugThreshold = clusterSettings.get(ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING).nanos(); - if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { + + } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { queryLogger.debug(Message.of(esqlResult, query)); - return; - } - var queryTraceThreshold = clusterSettings.get(ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING).nanos(); - if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { + + } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { queryLogger.trace(Message.of(esqlResult, query)); - return; + } } + public void setQueryWarnThreshold(TimeValue queryWarnThreshold) { + this.queryWarnThreshold = queryWarnThreshold.nanos(); + } + + public void setQueryInfoThreshold(TimeValue queryInfoThreshold) { + this.queryInfoThreshold = queryInfoThreshold.nanos(); + } + + public void setQueryDebugThreshold(TimeValue queryDebugThreshold) { + this.queryDebugThreshold = queryDebugThreshold.nanos(); + } + + public void setQueryTraceThreshold(TimeValue queryTraceThreshold) { + this.queryTraceThreshold = queryTraceThreshold.nanos(); + } + static final class Message { private static String escapeJson(String text) { @@ -81,14 +95,13 @@ public static ESLogMessage of(Result esqlResult, String query) { private static Map prepareMap(Result esqlResult, String query) { Map messageFields = new HashMap<>(); - messageFields.put("elasticsearch.slowlog.message", esqlResult.executionInfo().clusterAliases()); messageFields.put("elasticsearch.slowlog.took", esqlResult.executionInfo().overallTook().nanos()); messageFields.put("elasticsearch.slowlog.took_millis", esqlResult.executionInfo().overallTook().millis()); messageFields.put("elasticsearch.slowlog.planning.took", esqlResult.executionInfo().planningTookTime().nanos()); messageFields.put("elasticsearch.slowlog.planning.took_millis", esqlResult.executionInfo().planningTookTime().millis()); messageFields.put("elasticsearch.slowlog.search_type", "ESQL"); String source = escapeJson(query); - messageFields.put("elasticsearch.slowlog.source", source); + messageFields.put("elasticsearch.slowlog.query", source); return messageFields; } } From 895791814800c4af79c1109545a9fc74f2260f1e Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Fri, 7 Mar 2025 12:52:24 +0100 Subject: [PATCH 04/19] Fix test --- .../telemetry/PlanExecutorMetricsTests.java | 26 ++++++++++++++----- 1 file changed, 20 insertions(+), 6 deletions(-) diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java index d4cf87d4d8946..61631c32ef3b6 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java @@ -17,6 +17,7 @@ import org.elasticsearch.action.support.IndicesOptions; import org.elasticsearch.client.internal.Client; import org.elasticsearch.common.settings.ClusterSettings; +import org.elasticsearch.common.settings.Settings; import org.elasticsearch.index.IndexMode; import org.elasticsearch.indices.IndicesExpressionGrouper; import org.elasticsearch.license.XPackLicenseState; @@ -33,6 +34,7 @@ import org.elasticsearch.xpack.esql.core.expression.FoldContext; import org.elasticsearch.xpack.esql.enrich.EnrichPolicyResolver; import org.elasticsearch.xpack.esql.execution.PlanExecutor; +import org.elasticsearch.xpack.esql.plugin.EsqlPlugin; import org.elasticsearch.xpack.esql.session.EsqlSession; import org.elasticsearch.xpack.esql.session.IndexResolver; import org.elasticsearch.xpack.esql.session.Result; @@ -42,7 +44,9 @@ import org.mockito.stubbing.Answer; import java.util.ArrayList; +import java.util.Arrays; import java.util.HashMap; +import java.util.HashSet; import java.util.List; import java.util.Map; @@ -80,6 +84,21 @@ EnrichPolicyResolver mockEnrichResolver() { return enrichResolver; } + EsqlSlowLog mockSlowLog() { + ClusterSettings clusterSettings = new ClusterSettings( + Settings.EMPTY, + new HashSet<>( + Arrays.asList( + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING + ) + ) + ); + return new EsqlSlowLog(clusterSettings); + } + public void testFailedMetric() { String[] indices = new String[] { "test" }; @@ -107,12 +126,7 @@ public void testFailedMetric() { return null; }).when(esqlClient).execute(eq(EsqlResolveFieldsAction.TYPE), any(), any()); - var planExecutor = new PlanExecutor( - indexResolver, - MeterRegistry.NOOP, - new XPackLicenseState(() -> 0L), - new EsqlSlowLog(ClusterSettings.createBuiltInClusterSettings()) - ); + var planExecutor = new PlanExecutor(indexResolver, MeterRegistry.NOOP, new XPackLicenseState(() -> 0L), mockSlowLog()); var enrichResolver = mockEnrichResolver(); var request = new EsqlQueryRequest(); From 6e0b9c5f19a5b414d50ac0081a0233f9df202683 Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Fri, 7 Mar 2025 13:21:48 +0100 Subject: [PATCH 05/19] Add slowlog for failing queries --- .../xpack/esql/action/EsqlSlowLogIT.java | 85 +++++++++++++++---- .../xpack/esql/execution/PlanExecutor.java | 2 + .../xpack/esql/slowlog/EsqlSlowLog.java | 38 +++++++-- 3 files changed, 103 insertions(+), 22 deletions(-) diff --git a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java index b94336a06f5c2..bc0c85a51e3c1 100644 --- a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java +++ b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java @@ -18,6 +18,7 @@ import org.elasticsearch.common.logging.Loggers; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.core.TimeValue; +import org.elasticsearch.xpack.esql.VerificationException; import org.elasticsearch.xpack.esql.plugin.EsqlPlugin; import org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog; import org.junit.AfterClass; @@ -28,10 +29,12 @@ import java.util.concurrent.ExecutionException; import static org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked; +import static org.hamcrest.Matchers.containsString; import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.greaterThan; import static org.hamcrest.Matchers.greaterThanOrEqualTo; import static org.hamcrest.Matchers.is; +import static org.hamcrest.Matchers.nullValue; public class EsqlSlowLogIT extends AbstractEsqlIntegTestCase { static MockAppender appender; @@ -87,14 +90,53 @@ public void testSetLevel() throws Exception { Level.TRACE, EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey() ); - testAllLevels(levels, coordinator, 0); + testAllLevels( + levels, + coordinator, + 0, + "FROM index-* | EVAL ip = to_ip(host) | STATS s = COUNT(*) by ip | KEEP ip | LIMIT 100", + null, + null + ); + for (int i = 0; i < 10; i++) { + testAllLevels( + levels, + coordinator, + randomIntBetween(0, 10_000), + "FROM index-* | EVAL ip = to_ip(host) | STATS s = COUNT(*) by ip | KEEP ip | LIMIT 100", + null, + null + ); + } + + testAllLevels( + levels, + coordinator, + 0, + "FROM index-* | EVAL a = count(*) | LIMIT 100", + "aggregate function [count(*)] not allowed outside STATS command", + VerificationException.class.getName() + ); for (int i = 0; i < 10; i++) { - testAllLevels(levels, coordinator, randomIntBetween(0, 10_000)); + testAllLevels( + levels, + coordinator, + randomIntBetween(0, 10_000), + "FROM index-* | EVAL a = count(*) | LIMIT 100", + "aggregate function [count(*)] not allowed outside STATS command", + VerificationException.class.getName() + ); } } - private static void testAllLevels(Map levels, DiscoveryNode coordinator, long timeoutMillis) throws InterruptedException, - ExecutionException { + private static void testAllLevels( + Map levels, + DiscoveryNode coordinator, + long timeoutMillis, + String query, + String expectedErrorMsg, + String expectedException + ) throws InterruptedException, ExecutionException { for (Map.Entry logLevel : levels.entrySet()) { client().execute( @@ -105,8 +147,7 @@ private static void testAllLevels(Map levels, DiscoveryNode coord ).get(); EsqlQueryRequest request = EsqlQueryRequest.syncEsqlQueryRequest(); - var querySource = "FROM index-* | EVAL ip = to_ip(host) | STATS s = COUNT(*) by ip | KEEP ip | LIMIT 100"; - request.query(querySource); + request.query(query); request.pragmas(randomPragmas()); CountDownLatch latch = new CountDownLatch(1); client(coordinator.getName()).execute(EsqlQueryAction.INSTANCE, request, ActionListener.running(() -> { @@ -125,17 +166,31 @@ private static void testAllLevels(Map levels, DiscoveryNode coord assertThat(tookMillis, greaterThanOrEqualTo(timeoutMillis)); assertThat(tookMillis, is(tookMillisExpected)); - long planningTook = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took")); - long planningTookMillisExpected = planningTook / 1_000_000; - long planningTookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took_millis")); - assertThat(planningTook, greaterThanOrEqualTo(0L)); - assertThat(planningTookMillis, greaterThanOrEqualTo(timeoutMillis)); - assertThat(planningTookMillis, is(planningTookMillisExpected)); - - assertThat(took, greaterThan(planningTook)); + if (expectedException == null) { + long planningTook = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took")); + long planningTookMillisExpected = planningTook / 1_000_000; + long planningTookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took_millis")); + assertThat(planningTook, greaterThanOrEqualTo(0L)); + assertThat(planningTookMillis, greaterThanOrEqualTo(timeoutMillis)); + assertThat(planningTookMillis, is(planningTookMillisExpected)); + assertThat(took, greaterThan(planningTook)); + } - assertThat(msg.get("elasticsearch.slowlog.query"), is(querySource)); + assertThat(msg.get("elasticsearch.slowlog.query"), is(query)); assertThat(appender.getLastEventAndReset().getLevel(), equalTo(logLevel.getKey())); + + boolean success = Boolean.valueOf(msg.get("elasticsearch.slowlog.success")); + assertThat(success, is(expectedException == null)); + if (expectedErrorMsg == null) { + assertThat(msg.get("elasticsearch.slowlog.error.message"), is(nullValue())); + } else { + assertThat(msg.get("elasticsearch.slowlog.error.message"), containsString(expectedErrorMsg)); + } + if (expectedException == null) { + assertThat(msg.get("elasticsearch.slowlog.error.type"), is(nullValue())); + } else { + assertThat(msg.get("elasticsearch.slowlog.error.type"), is(expectedException)); + } } finally { latch.countDown(); } diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java index c590de9913edd..a67705fcb7368 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java @@ -86,6 +86,7 @@ public void esql( QueryMetric clientId = QueryMetric.fromString("rest"); metrics.total(clientId); + var begin = System.nanoTime(); ActionListener executeListener = wrap(x -> { planTelemetryManager.publish(planTelemetry, true); slowLog.onQueryPhase(x, request.query()); @@ -94,6 +95,7 @@ public void esql( // TODO when we decide if we will differentiate Kibana from REST, this String value will likely come from the request metrics.failed(clientId); planTelemetryManager.publish(planTelemetry, false); + slowLog.onQueryFailure(request.query(), ex, System.nanoTime() - begin); listener.onFailure(ex); }); // Wrap it in a listener so that if we have any exceptions during execution, the listener picks it up diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java index a96037160463c..58034de1ac467 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java @@ -64,6 +64,18 @@ public void onQueryPhase(Result esqlResult, String query) { } } + public void onQueryFailure(String query, Exception ex, long tookInNanos) { + if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) { + queryLogger.warn(Message.of(query, tookInNanos, ex)); + } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { + queryLogger.info(Message.of(query, tookInNanos, ex)); + } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { + queryLogger.debug(Message.of(query, tookInNanos, ex)); + } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { + queryLogger.trace(Message.of(query, tookInNanos, ex)); + } + } + public void setQueryWarnThreshold(TimeValue queryWarnThreshold) { this.queryWarnThreshold = queryWarnThreshold.nanos(); } @@ -88,19 +100,31 @@ private static String escapeJson(String text) { } public static ESLogMessage of(Result esqlResult, String query) { - Map jsonFields = prepareMap(esqlResult, query); + Map jsonFields = prepareMap(esqlResult, query, true); + + return new ESLogMessage().withFields(jsonFields); + } + public static ESLogMessage of(String query, long took, Exception exception) { + Map jsonFields = prepareMap(null, query, false); + jsonFields.put("elasticsearch.slowlog.error.message", exception.getMessage() == null ? "" : exception.getMessage()); + jsonFields.put("elasticsearch.slowlog.error.type", exception.getClass().getName()); + jsonFields.put("elasticsearch.slowlog.took", took); + jsonFields.put("elasticsearch.slowlog.took_millis", took / 1_000_000); return new ESLogMessage().withFields(jsonFields); } - private static Map prepareMap(Result esqlResult, String query) { + private static Map prepareMap(Result esqlResult, String query, boolean success) { Map messageFields = new HashMap<>(); - messageFields.put("elasticsearch.slowlog.took", esqlResult.executionInfo().overallTook().nanos()); - messageFields.put("elasticsearch.slowlog.took_millis", esqlResult.executionInfo().overallTook().millis()); - messageFields.put("elasticsearch.slowlog.planning.took", esqlResult.executionInfo().planningTookTime().nanos()); - messageFields.put("elasticsearch.slowlog.planning.took_millis", esqlResult.executionInfo().planningTookTime().millis()); - messageFields.put("elasticsearch.slowlog.search_type", "ESQL"); + if (esqlResult != null) { + messageFields.put("elasticsearch.slowlog.took", esqlResult.executionInfo().overallTook().nanos()); + messageFields.put("elasticsearch.slowlog.took_millis", esqlResult.executionInfo().overallTook().millis()); + messageFields.put("elasticsearch.slowlog.planning.took", esqlResult.executionInfo().planningTookTime().nanos()); + messageFields.put("elasticsearch.slowlog.planning.took_millis", esqlResult.executionInfo().planningTookTime().millis()); + } String source = escapeJson(query); + messageFields.put("elasticsearch.slowlog.success", success); + messageFields.put("elasticsearch.slowlog.search_type", "ESQL"); messageFields.put("elasticsearch.slowlog.query", source); return messageFields; } From 4d25aaac73dd724d0099691042c8f77d457c7e62 Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Fri, 7 Mar 2025 13:25:09 +0100 Subject: [PATCH 06/19] Cleanup --- .../elasticsearch/xpack/esql/action/EsqlSlowLogIT.java | 8 -------- 1 file changed, 8 deletions(-) diff --git a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java index bc0c85a51e3c1..e6c0353ac7471 100644 --- a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java +++ b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java @@ -58,14 +58,6 @@ public static void cleanup() { } public void testSetLevel() throws Exception { - final String node1; - if (randomBoolean()) { - internalCluster().ensureAtLeastNumDataNodes(2); - node1 = randomDataNode().getName(); - } else { - node1 = randomDataNode().getName(); - } - int numDocs1 = randomIntBetween(1, 15); assertAcked(client().admin().indices().prepareCreate("index-1").setMapping("host", "type=keyword")); for (int i = 0; i < numDocs1; i++) { From 45764f4ae234f471c8418815062aacb4e05e28a3 Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Fri, 7 Mar 2025 16:45:41 +0100 Subject: [PATCH 07/19] Cleanup --- .../org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java | 5 ----- 1 file changed, 5 deletions(-) diff --git a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java index e6c0353ac7471..4207bd456abb2 100644 --- a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java +++ b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java @@ -200,9 +200,4 @@ private static void testAllLevels( ).get(); } } - - private DiscoveryNode randomDataNode() { - return randomFrom(clusterService().state().nodes().getDataNodes().values()); - } - } From b2ae5ef855038ab1d8b0015672ce9f92bbfe9b0f Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Fri, 7 Mar 2025 16:46:37 +0100 Subject: [PATCH 08/19] Update docs/changelog/124094.yaml --- docs/changelog/124094.yaml | 5 +++++ 1 file changed, 5 insertions(+) create mode 100644 docs/changelog/124094.yaml diff --git a/docs/changelog/124094.yaml b/docs/changelog/124094.yaml new file mode 100644 index 0000000000000..b4c0f1711815f --- /dev/null +++ b/docs/changelog/124094.yaml @@ -0,0 +1,5 @@ +pr: 124094 +summary: ES|QL slow log +area: ES|QL +type: enhancement +issues: [] From cbfcf2cc43ff7947bd6b7fe849bdf10e73dc01a6 Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Mon, 10 Mar 2025 12:35:15 +0100 Subject: [PATCH 09/19] Add unit tests --- .../xpack/esql/slowlog/EsqlSlowLogTests.java | 170 ++++++++++++++++++ .../xpack/esql/slowlog/MockAppender.java | 40 +++++ 2 files changed, 210 insertions(+) create mode 100644 x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java create mode 100644 x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/MockAppender.java diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java new file mode 100644 index 0000000000000..e7b122724eb5b --- /dev/null +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java @@ -0,0 +1,170 @@ +/* + * 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.slowlog; + +import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.elasticsearch.common.ValidationException; +import org.elasticsearch.common.logging.ESLogMessage; +import org.elasticsearch.common.logging.Loggers; +import org.elasticsearch.common.settings.ClusterSettings; +import org.elasticsearch.common.settings.Settings; +import org.elasticsearch.core.TimeValue; +import org.elasticsearch.test.ESTestCase; +import org.elasticsearch.xpack.esql.action.EsqlExecutionInfo; +import org.elasticsearch.xpack.esql.plugin.EsqlPlugin; +import org.elasticsearch.xpack.esql.session.Result; +import org.junit.AfterClass; +import org.junit.BeforeClass; + +import java.util.Arrays; +import java.util.HashSet; +import java.util.List; +import java.util.concurrent.TimeUnit; + +import static org.hamcrest.Matchers.equalTo; +import static org.hamcrest.Matchers.greaterThan; +import static org.hamcrest.Matchers.is; +import static org.hamcrest.Matchers.not; +import static org.hamcrest.Matchers.nullValue; + +public class EsqlSlowLogTests extends ESTestCase { + private static ClusterSettings settings = new ClusterSettings( + Settings.builder() + .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING.getKey(), "40ms") + .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING.getKey(), "30ms") + .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), "20ms") + .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey(), "10ms") + + .build(), + new HashSet<>( + Arrays.asList( + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING + ) + ) + ); + + static MockAppender appender; + static Logger queryLog = LogManager.getLogger(EsqlSlowLog.SLOWLOG_PREFIX + ".query"); + static Level origQueryLogLevel = queryLog.getLevel(); + + @BeforeClass + public static void init() throws IllegalAccessException { + appender = new MockAppender("test_appender"); + appender.start(); + Loggers.addAppender(queryLog, appender); + + Loggers.setLevel(queryLog, Level.TRACE); + } + + @AfterClass + public static void cleanup() { + Loggers.removeAppender(queryLog, appender); + appender.stop(); + Loggers.setLevel(queryLog, origQueryLogLevel); + } + + public void testPrioritiesOnSuccess() { + EsqlSlowLog slowLog = new EsqlSlowLog(settings); + String query = "from " + randomAlphaOfLength(10); + + long[] actualTook = { + randomLongBetween(10_000_000, 20_000_000), + randomLongBetween(20_000_000, 30_000_000), + randomLongBetween(30_000_000, 40_000_000), + randomLongBetween(40_000_000, 50_000_000), + randomLongBetween(0, 9_999_999) }; + long[] actualPlanningTook = { + randomLongBetween(0, 1_000_000), + randomLongBetween(0, 1_000_000), + randomLongBetween(0, 1_000_000), + randomLongBetween(0, 1_000_000), + randomLongBetween(0, 1_000_000), }; + Level[] expectedLevel = { Level.TRACE, Level.DEBUG, Level.INFO, Level.WARN, null }; + + for (int i = 0; i < actualTook.length; i++) { + EsqlExecutionInfo warnQuery = getEsqlExecutionInfo(actualTook[i], actualPlanningTook[i]); + slowLog.onQueryPhase(new Result(List.of(), List.of(), List.of(), warnQuery), query); + if (expectedLevel[i] != null) { + assertThat(appender.lastEvent(), is(not(nullValue()))); + var msg = (ESLogMessage) appender.lastMessage(); + long took = Long.valueOf(msg.get("elasticsearch.slowlog.took")); + long tookMillisExpected = took / 1_000_000L; + long tookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.took_millis")); + assertThat(took, is(actualTook[i])); + assertThat(tookMillis, is(tookMillisExpected)); + + long planningTook = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took")); + long planningTookMillisExpected = planningTook / 1_000_000; + long planningTookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took_millis")); + assertThat(planningTook, is(actualPlanningTook[i])); + assertThat(planningTookMillis, is(planningTookMillisExpected)); + assertThat(took, greaterThan(planningTook)); + assertThat(msg.get("elasticsearch.slowlog.query"), is(query)); + assertThat(appender.getLastEventAndReset().getLevel(), equalTo(expectedLevel[i])); + } else { + assertThat(appender.lastEvent(), is(nullValue())); + } + + } + } + + public void testPrioritiesOnFailure() { + EsqlSlowLog slowLog = new EsqlSlowLog(settings); + String query = "from " + randomAlphaOfLength(10); + + long[] actualTook = { + randomLongBetween(10_000_000, 20_000_000), + randomLongBetween(20_000_000, 30_000_000), + randomLongBetween(30_000_000, 40_000_000), + randomLongBetween(40_000_000, 50_000_000), + randomLongBetween(0, 9_999_999) }; + + Level[] expectedLevel = { Level.TRACE, Level.DEBUG, Level.INFO, Level.WARN, null }; + + String validationError = randomAlphaOfLength(10); + ValidationException ex = new ValidationException().addValidationError(validationError); + for (int i = 0; i < actualTook.length; i++) { + slowLog.onQueryFailure(query, ex, actualTook[i]); + if (expectedLevel[i] != null) { + assertThat(appender.lastEvent(), is(not(nullValue()))); + var msg = (ESLogMessage) appender.lastMessage(); + long took = Long.valueOf(msg.get("elasticsearch.slowlog.took")); + long tookMillisExpected = took / 1_000_000L; + long tookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.took_millis")); + assertThat(took, is(actualTook[i])); + assertThat(tookMillis, is(tookMillisExpected)); + assertThat(msg.get("elasticsearch.slowlog.planning.took"), is(nullValue())); + assertThat(msg.get("elasticsearch.slowlog.planning.took_millis"), is(nullValue())); + assertThat(msg.get("elasticsearch.slowlog.query"), is(query)); + assertThat(appender.getLastEventAndReset().getLevel(), equalTo(expectedLevel[i])); + } else { + assertThat(appender.lastEvent(), is(nullValue())); + } + } + } + + private static EsqlExecutionInfo getEsqlExecutionInfo(long tookNanos, long planningTookNanos) { + EsqlExecutionInfo info = new EsqlExecutionInfo(false) { + @Override + public TimeValue overallTook() { + return new TimeValue(tookNanos, TimeUnit.NANOSECONDS); + } + + @Override + public TimeValue planningTookTime() { + return new TimeValue(planningTookNanos, TimeUnit.NANOSECONDS); + } + }; + return info; + } +} diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/MockAppender.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/MockAppender.java new file mode 100644 index 0000000000000..95a35c5bfdc7c --- /dev/null +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/MockAppender.java @@ -0,0 +1,40 @@ +/* + * 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.slowlog; + +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.appender.AbstractAppender; +import org.apache.logging.log4j.core.filter.RegexFilter; +import org.apache.logging.log4j.message.Message; + +public class MockAppender extends AbstractAppender { + public LogEvent lastEvent; + + public 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) { + lastEvent = event.toImmutable(); + } + + Message lastMessage() { + return lastEvent.getMessage(); + } + + LogEvent lastEvent() { + return lastEvent; + } + + public LogEvent getLastEventAndReset() { + LogEvent toReturn = lastEvent; + lastEvent = null; + return toReturn; + } +} From d2bd6728448cea1b6f107ff25b2848377090bf2b Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Mon, 10 Mar 2025 15:15:12 +0100 Subject: [PATCH 10/19] Add user name to slow log; some refactoring --- .../xpack/esql}/MockAppender.java | 6 +- .../xpack/esql/action/EsqlSlowLogIT.java | 22 +++++++- .../xpack/esql/plugin/EsqlPlugin.java | 16 +++++- .../xpack/esql/slowlog/EsqlSlowLog.java | 56 ++++++++++++++----- .../xpack/esql/slowlog/EsqlSlowLogTests.java | 5 +- .../xpack/esql/slowlog/MockAppender.java | 40 ------------- .../telemetry/PlanExecutorMetricsTests.java | 3 +- 7 files changed, 84 insertions(+), 64 deletions(-) rename x-pack/plugin/esql/{src/internalClusterTest/java/org/elasticsearch/xpack/esql/action => qa/testFixtures/src/main/java/org/elasticsearch/xpack/esql}/MockAppender.java (90%) delete mode 100644 x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/MockAppender.java diff --git a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/MockAppender.java b/x-pack/plugin/esql/qa/testFixtures/src/main/java/org/elasticsearch/xpack/esql/MockAppender.java similarity index 90% rename from x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/MockAppender.java rename to x-pack/plugin/esql/qa/testFixtures/src/main/java/org/elasticsearch/xpack/esql/MockAppender.java index 35118ae1b7955..e1a8633a01c3c 100644 --- a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/MockAppender.java +++ b/x-pack/plugin/esql/qa/testFixtures/src/main/java/org/elasticsearch/xpack/esql/MockAppender.java @@ -5,7 +5,7 @@ * 2.0. */ -package org.elasticsearch.xpack.esql.action; +package org.elasticsearch.xpack.esql; import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.appender.AbstractAppender; @@ -24,11 +24,11 @@ public void append(LogEvent event) { lastEvent = event.toImmutable(); } - Message lastMessage() { + public Message lastMessage() { return lastEvent.getMessage(); } - LogEvent lastEvent() { + public LogEvent lastEvent() { return lastEvent; } diff --git a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java index 4207bd456abb2..97ed44c248b44 100644 --- a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java +++ b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java @@ -18,6 +18,7 @@ import org.elasticsearch.common.logging.Loggers; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.core.TimeValue; +import org.elasticsearch.xpack.esql.MockAppender; import org.elasticsearch.xpack.esql.VerificationException; import org.elasticsearch.xpack.esql.plugin.EsqlPlugin; import org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog; @@ -94,12 +95,20 @@ public void testSetLevel() throws Exception { testAllLevels( levels, coordinator, - randomIntBetween(0, 10_000), + randomIntBetween(0, 500), "FROM index-* | EVAL ip = to_ip(host) | STATS s = COUNT(*) by ip | KEEP ip | LIMIT 100", null, null ); } + testAllLevels( + levels, + coordinator, + 600_000, + "FROM index-* | EVAL ip = to_ip(host) | STATS s = COUNT(*) by ip | KEEP ip | LIMIT 100", + null, + null + ); testAllLevels( levels, @@ -113,12 +122,20 @@ public void testSetLevel() throws Exception { testAllLevels( levels, coordinator, - randomIntBetween(0, 10_000), + randomIntBetween(0, 500), "FROM index-* | EVAL a = count(*) | LIMIT 100", "aggregate function [count(*)] not allowed outside STATS command", VerificationException.class.getName() ); } + testAllLevels( + levels, + coordinator, + 600_000, + "FROM index-* | EVAL a = count(*) | LIMIT 100", + "aggregate function [count(*)] not allowed outside STATS command", + VerificationException.class.getName() + ); } private static void testAllLevels( @@ -163,7 +180,6 @@ private static void testAllLevels( long planningTookMillisExpected = planningTook / 1_000_000; long planningTookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took_millis")); assertThat(planningTook, greaterThanOrEqualTo(0L)); - assertThat(planningTookMillis, greaterThanOrEqualTo(timeoutMillis)); assertThat(planningTookMillis, is(planningTookMillisExpected)); assertThat(took, greaterThan(planningTook)); } diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java index 33849bd6bdb3b..b6ae5b139f760 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java @@ -51,6 +51,7 @@ import org.elasticsearch.xpack.core.XPackPlugin; import org.elasticsearch.xpack.core.action.XPackInfoFeatureAction; import org.elasticsearch.xpack.core.action.XPackUsageFeatureAction; +import org.elasticsearch.xpack.core.security.SecurityContext; import org.elasticsearch.xpack.esql.EsqlInfoTransportAction; import org.elasticsearch.xpack.esql.EsqlUsageTransportAction; import org.elasticsearch.xpack.esql.action.EsqlAsyncGetResultAction; @@ -147,6 +148,13 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); + public static final Setting ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING = Setting.boolSetting( + "esql.slowlog.include.user", + false, + Setting.Property.NodeScope, + Setting.Property.Dynamic + ); + @Override public Collection createComponents(Plugin.PluginServices services) { CircuitBreaker circuitBreaker = services.indicesService().getBigArrays().breakerService().getBreaker("request"); @@ -164,7 +172,10 @@ public Collection createComponents(Plugin.PluginServices services) { new IndexResolver(services.client()), services.telemetryProvider().getMeterRegistry(), getLicenseState(), - new EsqlSlowLog(services.clusterService().getClusterSettings()) + new EsqlSlowLog( + services.clusterService().getClusterSettings(), + new SecurityContext(Settings.EMPTY, services.threadPool().getThreadContext()) + ) ), new ExchangeService( services.clusterService().getSettings(), @@ -208,7 +219,8 @@ public List> getSettings() { ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, - ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING + ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, + ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING ); } diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java index 58034de1ac467..a32604f0e3468 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java @@ -13,12 +13,15 @@ import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.core.TimeValue; import org.elasticsearch.xcontent.json.JsonStringEncoder; +import org.elasticsearch.xpack.core.security.SecurityContext; +import org.elasticsearch.xpack.core.security.user.User; import org.elasticsearch.xpack.esql.session.Result; import java.nio.charset.StandardCharsets; import java.util.HashMap; import java.util.Map; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING; import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING; import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING; import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING; @@ -31,18 +34,28 @@ public final class EsqlSlowLog { public static final String SLOWLOG_PREFIX = "esql.slowlog"; private static final Logger queryLogger = LogManager.getLogger(SLOWLOG_PREFIX + ".query"); + private final SecurityContext security; private volatile long queryWarnThreshold; private volatile long queryInfoThreshold; private volatile long queryDebugThreshold; private volatile long queryTraceThreshold; - public EsqlSlowLog(ClusterSettings settings) { + private volatile boolean includeUser; + + public EsqlSlowLog(ClusterSettings settings, SecurityContext security) { settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, this::setQueryWarnThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, this::setQueryInfoThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, this::setQueryDebugThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, this::setQueryTraceThreshold); + settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING, this::setIncludeUser); this.clusterSettings = settings; + + this.security = security; + } + + public EsqlSlowLog(ClusterSettings settings) { + this(settings, null); } public void onQueryPhase(Result esqlResult, String query) { @@ -51,28 +64,36 @@ public void onQueryPhase(Result esqlResult, String query) { } long tookInNanos = esqlResult.executionInfo().overallTook().nanos(); if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) { - queryLogger.warn(Message.of(esqlResult, query)); + queryLogger.warn(Message.of(esqlResult, query, user())); } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { - queryLogger.info(Message.of(esqlResult, query)); + queryLogger.info(Message.of(esqlResult, query, user())); } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { - queryLogger.debug(Message.of(esqlResult, query)); + queryLogger.debug(Message.of(esqlResult, query, user())); } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { - queryLogger.trace(Message.of(esqlResult, query)); + queryLogger.trace(Message.of(esqlResult, query, user())); } } + private User user() { + User user = null; + if (includeUser && security != null) { + user = security.getUser(); + } + return user; + } + public void onQueryFailure(String query, Exception ex, long tookInNanos) { if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) { - queryLogger.warn(Message.of(query, tookInNanos, ex)); + queryLogger.warn(Message.of(query, tookInNanos, ex, user())); } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { - queryLogger.info(Message.of(query, tookInNanos, ex)); + queryLogger.info(Message.of(query, tookInNanos, ex, user())); } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { - queryLogger.debug(Message.of(query, tookInNanos, ex)); + queryLogger.debug(Message.of(query, tookInNanos, ex, user())); } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { - queryLogger.trace(Message.of(query, tookInNanos, ex)); + queryLogger.trace(Message.of(query, tookInNanos, ex, user())); } } @@ -92,6 +113,10 @@ public void setQueryTraceThreshold(TimeValue queryTraceThreshold) { this.queryTraceThreshold = queryTraceThreshold.nanos(); } + public void setIncludeUser(boolean includeUser) { + this.includeUser = includeUser; + } + static final class Message { private static String escapeJson(String text) { @@ -99,14 +124,14 @@ private static String escapeJson(String text) { return new String(sourceEscaped, StandardCharsets.UTF_8); } - public static ESLogMessage of(Result esqlResult, String query) { - Map jsonFields = prepareMap(esqlResult, query, true); + public static ESLogMessage of(Result esqlResult, String query, User user) { + Map jsonFields = prepareMap(esqlResult, query, true, user); return new ESLogMessage().withFields(jsonFields); } - public static ESLogMessage of(String query, long took, Exception exception) { - Map jsonFields = prepareMap(null, query, false); + public static ESLogMessage of(String query, long took, Exception exception, User user) { + Map jsonFields = prepareMap(null, query, false, user); jsonFields.put("elasticsearch.slowlog.error.message", exception.getMessage() == null ? "" : exception.getMessage()); jsonFields.put("elasticsearch.slowlog.error.type", exception.getClass().getName()); jsonFields.put("elasticsearch.slowlog.took", took); @@ -114,8 +139,11 @@ public static ESLogMessage of(String query, long took, Exception exception) { return new ESLogMessage().withFields(jsonFields); } - private static Map prepareMap(Result esqlResult, String query, boolean success) { + private static Map prepareMap(Result esqlResult, String query, boolean success, User user) { Map messageFields = new HashMap<>(); + if (user != null) { + messageFields.put("user.name", user.principal()); + } if (esqlResult != null) { messageFields.put("elasticsearch.slowlog.took", esqlResult.executionInfo().overallTook().nanos()); messageFields.put("elasticsearch.slowlog.took_millis", esqlResult.executionInfo().overallTook().millis()); diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java index e7b122724eb5b..33a63bddb4d38 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java @@ -17,6 +17,7 @@ import org.elasticsearch.common.settings.Settings; import org.elasticsearch.core.TimeValue; import org.elasticsearch.test.ESTestCase; +import org.elasticsearch.xpack.esql.MockAppender; import org.elasticsearch.xpack.esql.action.EsqlExecutionInfo; import org.elasticsearch.xpack.esql.plugin.EsqlPlugin; import org.elasticsearch.xpack.esql.session.Result; @@ -41,6 +42,7 @@ public class EsqlSlowLogTests extends ESTestCase { .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING.getKey(), "30ms") .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), "20ms") .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey(), "10ms") + .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING.getKey(), true) .build(), new HashSet<>( @@ -48,7 +50,8 @@ public class EsqlSlowLogTests extends ESTestCase { EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING ) ) ); diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/MockAppender.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/MockAppender.java deleted file mode 100644 index 95a35c5bfdc7c..0000000000000 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/MockAppender.java +++ /dev/null @@ -1,40 +0,0 @@ -/* - * 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.slowlog; - -import org.apache.logging.log4j.core.LogEvent; -import org.apache.logging.log4j.core.appender.AbstractAppender; -import org.apache.logging.log4j.core.filter.RegexFilter; -import org.apache.logging.log4j.message.Message; - -public class MockAppender extends AbstractAppender { - public LogEvent lastEvent; - - public 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) { - lastEvent = event.toImmutable(); - } - - Message lastMessage() { - return lastEvent.getMessage(); - } - - LogEvent lastEvent() { - return lastEvent; - } - - public LogEvent getLastEventAndReset() { - LogEvent toReturn = lastEvent; - lastEvent = null; - return toReturn; - } -} diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java index 61631c32ef3b6..074e022ed3a3e 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java @@ -92,7 +92,8 @@ EsqlSlowLog mockSlowLog() { EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, + EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING ) ) ); From b74ea91e3fef7e9c9c69527a34fa23d9a9919269 Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Tue, 11 Mar 2025 11:17:28 +0100 Subject: [PATCH 11/19] Implement review suggestions --- .../xpack/esql/action/EsqlSlowLogIT.java | 30 +++-- .../xpack/esql/execution/PlanExecutor.java | 36 ++++-- .../xpack/esql/plugin/EsqlPlugin.java | 2 +- .../xpack/esql/slowlog/EsqlSlowLog.java | 105 ++++++++++-------- .../xpack/esql/slowlog/EsqlSlowLogTests.java | 27 +++-- 5 files changed, 117 insertions(+), 83 deletions(-) diff --git a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java index 97ed44c248b44..22dc2c5784efb 100644 --- a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java +++ b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java @@ -30,6 +30,14 @@ import java.util.concurrent.ExecutionException; import static org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_ERROR_MESSAGE; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_ERROR_TYPE; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_PLANNING_TOOK; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_QUERY; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_SUCCESS; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_TOOK; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_TOOK_MILLIS; import static org.hamcrest.Matchers.containsString; import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.greaterThan; @@ -39,7 +47,7 @@ public class EsqlSlowLogIT extends AbstractEsqlIntegTestCase { static MockAppender appender; - static Logger queryLog = LogManager.getLogger(EsqlSlowLog.SLOWLOG_PREFIX + ".query"); + static Logger queryLog = LogManager.getLogger(EsqlSlowLog.LOGGER_NAME); static Level origQueryLogLevel = queryLog.getLevel(); @BeforeClass @@ -168,36 +176,36 @@ private static void testAllLevels( return; } var msg = (ESLogMessage) appender.lastMessage(); - long took = Long.valueOf(msg.get("elasticsearch.slowlog.took")); + long took = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK)); long tookMillisExpected = took / 1_000_000; - long tookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.took_millis")); + long tookMillis = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK_MILLIS)); assertThat(took, greaterThan(0L)); assertThat(tookMillis, greaterThanOrEqualTo(timeoutMillis)); assertThat(tookMillis, is(tookMillisExpected)); if (expectedException == null) { - long planningTook = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took")); + long planningTook = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK)); long planningTookMillisExpected = planningTook / 1_000_000; - long planningTookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took_millis")); + long planningTookMillis = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS)); assertThat(planningTook, greaterThanOrEqualTo(0L)); assertThat(planningTookMillis, is(planningTookMillisExpected)); assertThat(took, greaterThan(planningTook)); } - assertThat(msg.get("elasticsearch.slowlog.query"), is(query)); + assertThat(msg.get(ELASTICSEARCH_SLOWLOG_QUERY), is(query)); assertThat(appender.getLastEventAndReset().getLevel(), equalTo(logLevel.getKey())); - boolean success = Boolean.valueOf(msg.get("elasticsearch.slowlog.success")); + boolean success = Boolean.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_SUCCESS)); assertThat(success, is(expectedException == null)); if (expectedErrorMsg == null) { - assertThat(msg.get("elasticsearch.slowlog.error.message"), is(nullValue())); + assertThat(msg.get(ELASTICSEARCH_SLOWLOG_ERROR_MESSAGE), is(nullValue())); } else { - assertThat(msg.get("elasticsearch.slowlog.error.message"), containsString(expectedErrorMsg)); + assertThat(msg.get(ELASTICSEARCH_SLOWLOG_ERROR_MESSAGE), containsString(expectedErrorMsg)); } if (expectedException == null) { - assertThat(msg.get("elasticsearch.slowlog.error.type"), is(nullValue())); + assertThat(msg.get(ELASTICSEARCH_SLOWLOG_ERROR_TYPE), is(nullValue())); } else { - assertThat(msg.get("elasticsearch.slowlog.error.type"), is(expectedException)); + assertThat(msg.get(ELASTICSEARCH_SLOWLOG_ERROR_TYPE), is(expectedException)); } } finally { latch.countDown(); diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java index a67705fcb7368..63e6a44cd7a87 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java @@ -87,22 +87,36 @@ public void esql( metrics.total(clientId); var begin = System.nanoTime(); - ActionListener executeListener = wrap(x -> { - planTelemetryManager.publish(planTelemetry, true); - slowLog.onQueryPhase(x, request.query()); - listener.onResponse(x); - }, ex -> { - // TODO when we decide if we will differentiate Kibana from REST, this String value will likely come from the request - metrics.failed(clientId); - planTelemetryManager.publish(planTelemetry, false); - slowLog.onQueryFailure(request.query(), ex, System.nanoTime() - begin); - listener.onFailure(ex); - }); + ActionListener executeListener = wrap( + x -> onQuerySuccess(request, listener, x, planTelemetry), + ex -> onQueryFailure(request, listener, ex, clientId, planTelemetry, begin) + ); // Wrap it in a listener so that if we have any exceptions during execution, the listener picks it up // and all the metrics are properly updated ActionListener.run(executeListener, l -> session.execute(request, executionInfo, planRunner, l)); } + private void onQuerySuccess(EsqlQueryRequest request, ActionListener listener, Result x, PlanTelemetry planTelemetry) { + planTelemetryManager.publish(planTelemetry, true); + slowLog.onQueryPhase(x, request.query()); + listener.onResponse(x); + } + + private void onQueryFailure( + EsqlQueryRequest request, + ActionListener listener, + Exception ex, + QueryMetric clientId, + PlanTelemetry planTelemetry, + long begin + ) { + // TODO when we decide if we will differentiate Kibana from REST, this String value will likely come from the request + metrics.failed(clientId); + planTelemetryManager.publish(planTelemetry, false); + slowLog.onQueryFailure(request.query(), ex, System.nanoTime() - begin); + listener.onFailure(ex); + } + public IndexResolver indexResolver() { return indexResolver; } diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java index b6ae5b139f760..340516256b680 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java @@ -156,7 +156,7 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { ); @Override - public Collection createComponents(Plugin.PluginServices services) { + public Collection createComponents(PluginServices services) { CircuitBreaker circuitBreaker = services.indicesService().getBigArrays().breakerService().getBreaker("request"); Objects.requireNonNull(circuitBreaker, "request circuit breaker wasn't set"); Settings settings = services.clusterService().getSettings(); diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java index a32604f0e3468..d653e83137572 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java @@ -20,6 +20,7 @@ import java.nio.charset.StandardCharsets; import java.util.HashMap; import java.util.Map; +import java.util.function.Supplier; import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING; import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING; @@ -29,12 +30,19 @@ public final class EsqlSlowLog { - private final ClusterSettings clusterSettings; + public static final String ELASTICSEARCH_SLOWLOG_PREFIX = "elasticsearch.slowlog"; + public static final String ELASTICSEARCH_SLOWLOG_ERROR_MESSAGE = ELASTICSEARCH_SLOWLOG_PREFIX + ".error.message"; + public static final String ELASTICSEARCH_SLOWLOG_ERROR_TYPE = ELASTICSEARCH_SLOWLOG_PREFIX + ".error.type"; + public static final String ELASTICSEARCH_SLOWLOG_TOOK = ELASTICSEARCH_SLOWLOG_PREFIX + ".took"; + public static final String ELASTICSEARCH_SLOWLOG_TOOK_MILLIS = ELASTICSEARCH_SLOWLOG_PREFIX + ".took_millis"; + public static final String ELASTICSEARCH_SLOWLOG_PLANNING_TOOK = ELASTICSEARCH_SLOWLOG_PREFIX + ".planning.took"; + public static final String ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS = ELASTICSEARCH_SLOWLOG_PREFIX + ".planning.took_millis"; + public static final String ELASTICSEARCH_SLOWLOG_SUCCESS = ELASTICSEARCH_SLOWLOG_PREFIX + ".success"; + public static final String ELASTICSEARCH_SLOWLOG_SEARCH_TYPE = ELASTICSEARCH_SLOWLOG_PREFIX + ".search_type"; + public static final String ELASTICSEARCH_SLOWLOG_QUERY = ELASTICSEARCH_SLOWLOG_PREFIX + ".query"; - public static final String SLOWLOG_PREFIX = "esql.slowlog"; - - private static final Logger queryLogger = LogManager.getLogger(SLOWLOG_PREFIX + ".query"); - private final SecurityContext security; + public static final String LOGGER_NAME = "esql.slowlog.query"; + private static final Logger queryLogger = LogManager.getLogger(LOGGER_NAME); private volatile long queryWarnThreshold; private volatile long queryInfoThreshold; @@ -43,13 +51,14 @@ public final class EsqlSlowLog { private volatile boolean includeUser; + private final SecurityContext security; + public EsqlSlowLog(ClusterSettings settings, SecurityContext security) { settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, this::setQueryWarnThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, this::setQueryInfoThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, this::setQueryDebugThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, this::setQueryTraceThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING, this::setIncludeUser); - this.clusterSettings = settings; this.security = security; } @@ -63,37 +72,22 @@ public void onQueryPhase(Result esqlResult, String query) { return; // TODO review, it happens in some tests, not sure if it's a thing also in prod } long tookInNanos = esqlResult.executionInfo().overallTook().nanos(); - if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) { - queryLogger.warn(Message.of(esqlResult, query, user())); - } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { - queryLogger.info(Message.of(esqlResult, query, user())); - - } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { - queryLogger.debug(Message.of(esqlResult, query, user())); - - } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { - queryLogger.trace(Message.of(esqlResult, query, user())); - - } + log(() -> Message.of(esqlResult, query, user()), tookInNanos); } - private User user() { - User user = null; - if (includeUser && security != null) { - user = security.getUser(); - } - return user; + public void onQueryFailure(String query, Exception ex, long tookInNanos) { + log(() -> Message.of(query, tookInNanos, ex, user()), tookInNanos); } - public void onQueryFailure(String query, Exception ex, long tookInNanos) { + private void log(Supplier logProducer, long tookInNanos) { if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) { - queryLogger.warn(Message.of(query, tookInNanos, ex, user())); + queryLogger.warn(logProducer.get()); } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { - queryLogger.info(Message.of(query, tookInNanos, ex, user())); + queryLogger.info(logProducer.get()); } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { - queryLogger.debug(Message.of(query, tookInNanos, ex, user())); + queryLogger.debug(logProducer.get()); } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { - queryLogger.trace(Message.of(query, tookInNanos, ex, user())); + queryLogger.trace(logProducer.get()); } } @@ -117,6 +111,14 @@ public void setIncludeUser(boolean includeUser) { this.includeUser = includeUser; } + private User user() { + User user = null; + if (includeUser && security != null) { + user = security.getUser(); + } + return user; + } + static final class Message { private static String escapeJson(String text) { @@ -125,36 +127,41 @@ private static String escapeJson(String text) { } public static ESLogMessage of(Result esqlResult, String query, User user) { - Map jsonFields = prepareMap(esqlResult, query, true, user); - + Map jsonFields = new HashMap<>(); + addGenericFields(jsonFields, query, true, user); + addResultFields(jsonFields, esqlResult); return new ESLogMessage().withFields(jsonFields); } public static ESLogMessage of(String query, long took, Exception exception, User user) { - Map jsonFields = prepareMap(null, query, false, user); - jsonFields.put("elasticsearch.slowlog.error.message", exception.getMessage() == null ? "" : exception.getMessage()); - jsonFields.put("elasticsearch.slowlog.error.type", exception.getClass().getName()); - jsonFields.put("elasticsearch.slowlog.took", took); - jsonFields.put("elasticsearch.slowlog.took_millis", took / 1_000_000); + Map jsonFields = new HashMap<>(); + addGenericFields(jsonFields, query, false, user); + addErrorFields(jsonFields, took, exception); return new ESLogMessage().withFields(jsonFields); } - private static Map prepareMap(Result esqlResult, String query, boolean success, User user) { - Map messageFields = new HashMap<>(); + private static void addGenericFields(Map fieldMap, String query, boolean success, User user) { if (user != null) { - messageFields.put("user.name", user.principal()); - } - if (esqlResult != null) { - messageFields.put("elasticsearch.slowlog.took", esqlResult.executionInfo().overallTook().nanos()); - messageFields.put("elasticsearch.slowlog.took_millis", esqlResult.executionInfo().overallTook().millis()); - messageFields.put("elasticsearch.slowlog.planning.took", esqlResult.executionInfo().planningTookTime().nanos()); - messageFields.put("elasticsearch.slowlog.planning.took_millis", esqlResult.executionInfo().planningTookTime().millis()); + fieldMap.put("user.name", user.principal()); } String source = escapeJson(query); - messageFields.put("elasticsearch.slowlog.success", success); - messageFields.put("elasticsearch.slowlog.search_type", "ESQL"); - messageFields.put("elasticsearch.slowlog.query", source); - return messageFields; + fieldMap.put(ELASTICSEARCH_SLOWLOG_SUCCESS, success); + fieldMap.put(ELASTICSEARCH_SLOWLOG_SEARCH_TYPE, "ESQL"); + fieldMap.put(ELASTICSEARCH_SLOWLOG_QUERY, source); + } + + private static void addResultFields(Map fieldMap, Result esqlResult) { + fieldMap.put(ELASTICSEARCH_SLOWLOG_TOOK, esqlResult.executionInfo().overallTook().nanos()); + fieldMap.put(ELASTICSEARCH_SLOWLOG_TOOK_MILLIS, esqlResult.executionInfo().overallTook().millis()); + fieldMap.put(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK, esqlResult.executionInfo().planningTookTime().nanos()); + fieldMap.put(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS, esqlResult.executionInfo().planningTookTime().millis()); + } + + private static void addErrorFields(Map jsonFields, long took, Exception exception) { + jsonFields.put(ELASTICSEARCH_SLOWLOG_TOOK, took); + jsonFields.put(ELASTICSEARCH_SLOWLOG_TOOK_MILLIS, took / 1_000_000); + jsonFields.put(ELASTICSEARCH_SLOWLOG_ERROR_MESSAGE, exception.getMessage() == null ? "" : exception.getMessage()); + jsonFields.put(ELASTICSEARCH_SLOWLOG_ERROR_TYPE, exception.getClass().getName()); } } } diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java index 33a63bddb4d38..68c049c65b1e8 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java @@ -29,6 +29,11 @@ import java.util.List; import java.util.concurrent.TimeUnit; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_PLANNING_TOOK; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_QUERY; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_TOOK; +import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_TOOK_MILLIS; import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.greaterThan; import static org.hamcrest.Matchers.is; @@ -57,7 +62,7 @@ public class EsqlSlowLogTests extends ESTestCase { ); static MockAppender appender; - static Logger queryLog = LogManager.getLogger(EsqlSlowLog.SLOWLOG_PREFIX + ".query"); + static Logger queryLog = LogManager.getLogger(EsqlSlowLog.LOGGER_NAME); static Level origQueryLogLevel = queryLog.getLevel(); @BeforeClass @@ -100,19 +105,19 @@ public void testPrioritiesOnSuccess() { if (expectedLevel[i] != null) { assertThat(appender.lastEvent(), is(not(nullValue()))); var msg = (ESLogMessage) appender.lastMessage(); - long took = Long.valueOf(msg.get("elasticsearch.slowlog.took")); + long took = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK)); long tookMillisExpected = took / 1_000_000L; - long tookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.took_millis")); + long tookMillis = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK_MILLIS)); assertThat(took, is(actualTook[i])); assertThat(tookMillis, is(tookMillisExpected)); - long planningTook = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took")); + long planningTook = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK)); long planningTookMillisExpected = planningTook / 1_000_000; - long planningTookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took_millis")); + long planningTookMillis = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS)); assertThat(planningTook, is(actualPlanningTook[i])); assertThat(planningTookMillis, is(planningTookMillisExpected)); assertThat(took, greaterThan(planningTook)); - assertThat(msg.get("elasticsearch.slowlog.query"), is(query)); + assertThat(msg.get(ELASTICSEARCH_SLOWLOG_QUERY), is(query)); assertThat(appender.getLastEventAndReset().getLevel(), equalTo(expectedLevel[i])); } else { assertThat(appender.lastEvent(), is(nullValue())); @@ -141,14 +146,14 @@ public void testPrioritiesOnFailure() { if (expectedLevel[i] != null) { assertThat(appender.lastEvent(), is(not(nullValue()))); var msg = (ESLogMessage) appender.lastMessage(); - long took = Long.valueOf(msg.get("elasticsearch.slowlog.took")); + long took = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK)); long tookMillisExpected = took / 1_000_000L; - long tookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.took_millis")); + long tookMillis = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK_MILLIS)); assertThat(took, is(actualTook[i])); assertThat(tookMillis, is(tookMillisExpected)); - assertThat(msg.get("elasticsearch.slowlog.planning.took"), is(nullValue())); - assertThat(msg.get("elasticsearch.slowlog.planning.took_millis"), is(nullValue())); - assertThat(msg.get("elasticsearch.slowlog.query"), is(query)); + assertThat(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK), is(nullValue())); + assertThat(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS), is(nullValue())); + assertThat(msg.get(ELASTICSEARCH_SLOWLOG_QUERY), is(query)); assertThat(appender.getLastEventAndReset().getLevel(), equalTo(expectedLevel[i])); } else { assertThat(appender.lastEvent(), is(nullValue())); From af3366f4d91e57bab575e083a254ad99e58abeb3 Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Fri, 14 Mar 2025 15:27:57 +0100 Subject: [PATCH 12/19] Refactor to use SlowLogFieldProviders --- .../index/SlowLogFieldProvider.java | 5 ++ .../elasticsearch/index/SlowLogFields.java | 9 +++ .../indices/IndicesServiceBuilder.java | 8 ++- .../elasticsearch/node/NodeConstruction.java | 64 +++++++++++++------ .../node/PluginServiceInstances.java | 6 +- .../org/elasticsearch/plugins/Plugin.java | 6 ++ .../indices/IndicesServiceTests.java | 15 ++++- .../xpack/esql/plugin/EsqlPlugin.java | 6 +- .../xpack/esql/slowlog/EsqlSlowLog.java | 43 ++++++------- .../slowlog/SecuritySlowLogFieldProvider.java | 13 ++++ 10 files changed, 125 insertions(+), 50 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/index/SlowLogFieldProvider.java b/server/src/main/java/org/elasticsearch/index/SlowLogFieldProvider.java index e93edccc83b15..dfab7e1d11e34 100644 --- a/server/src/main/java/org/elasticsearch/index/SlowLogFieldProvider.java +++ b/server/src/main/java/org/elasticsearch/index/SlowLogFieldProvider.java @@ -19,4 +19,9 @@ public interface SlowLogFieldProvider { * @param indexSettings settings for the index */ SlowLogFields create(IndexSettings indexSettings); + + /** + * Create a field provider without index level settings + */ + SlowLogFields create(); } diff --git a/server/src/main/java/org/elasticsearch/index/SlowLogFields.java b/server/src/main/java/org/elasticsearch/index/SlowLogFields.java index e018e3a4d6bb7..fe9df11e0579e 100644 --- a/server/src/main/java/org/elasticsearch/index/SlowLogFields.java +++ b/server/src/main/java/org/elasticsearch/index/SlowLogFields.java @@ -27,4 +27,13 @@ public interface SlowLogFields { * @return map of field name to value */ Map searchFields(); + + + /** + * Slow log fields for query + * @return map of field name to value + */ + default Map queryFields(){ + return Map.of(); + } } diff --git a/server/src/main/java/org/elasticsearch/indices/IndicesServiceBuilder.java b/server/src/main/java/org/elasticsearch/indices/IndicesServiceBuilder.java index 49aeba37acd42..df3ed42db37a0 100644 --- a/server/src/main/java/org/elasticsearch/indices/IndicesServiceBuilder.java +++ b/server/src/main/java/org/elasticsearch/indices/IndicesServiceBuilder.java @@ -83,7 +83,7 @@ public class IndicesServiceBuilder { QueryRewriteInterceptor queryRewriteInterceptor = null; SlowLogFieldProvider slowLogFieldProvider = new SlowLogFieldProvider() { @Override - public SlowLogFields create(IndexSettings indexSettings) { + public SlowLogFields create() { return new SlowLogFields() { @Override public Map indexFields() { @@ -96,6 +96,12 @@ public Map searchFields() { } }; } + + @Override + public SlowLogFields create(IndexSettings indexSettings) { + return create(); + } + }; public IndicesServiceBuilder settings(Settings settings) { diff --git a/server/src/main/java/org/elasticsearch/node/NodeConstruction.java b/server/src/main/java/org/elasticsearch/node/NodeConstruction.java index b6e24a23591b6..a127a1b7dabd6 100644 --- a/server/src/main/java/org/elasticsearch/node/NodeConstruction.java +++ b/server/src/main/java/org/elasticsearch/node/NodeConstruction.java @@ -114,6 +114,7 @@ import org.elasticsearch.index.IndexMode; import org.elasticsearch.index.IndexSettingProvider; import org.elasticsearch.index.IndexSettingProviders; +import org.elasticsearch.index.IndexSettings; import org.elasticsearch.index.IndexingPressure; import org.elasticsearch.index.SlowLogFieldProvider; import org.elasticsearch.index.SlowLogFields; @@ -825,28 +826,54 @@ private void construct( List slowLogFieldProviders = pluginsService.loadServiceProviders(SlowLogFieldProvider.class); // NOTE: the response of index/search slow log fields below must be calculated dynamically on every call // because the responses may change dynamically at runtime - SlowLogFieldProvider slowLogFieldProvider = indexSettings -> { - final List fields = new ArrayList<>(); - for (var provider : slowLogFieldProviders) { - fields.add(provider.create(indexSettings)); - } - return new SlowLogFields() { - @Override - public Map indexFields() { - return fields.stream() - .flatMap(f -> f.indexFields().entrySet().stream()) - .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); + SlowLogFieldProvider slowLogFieldProvider = new SlowLogFieldProvider() { + public SlowLogFields create() { + final List fields = new ArrayList<>(); + for (var provider : slowLogFieldProviders) { + fields.add(provider.create()); } + return new SlowLogFields() { + @Override + public Map indexFields() { + return fields.stream() + .flatMap(f -> f.indexFields().entrySet().stream()) + .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); + } + + @Override + public Map searchFields() { + return fields.stream() + .flatMap(f -> f.searchFields().entrySet().stream()) + .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); + } + }; + } - @Override - public Map searchFields() { - return fields.stream() - .flatMap(f -> f.searchFields().entrySet().stream()) - .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); + public SlowLogFields create(IndexSettings indexSettings) { + final List fields = new ArrayList<>(); + for (var provider : slowLogFieldProviders) { + fields.add(provider.create(indexSettings)); } - }; + return new SlowLogFields() { + @Override + public Map indexFields() { + return fields.stream() + .flatMap(f -> f.indexFields().entrySet().stream()) + .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); + } + + @Override + public Map searchFields() { + return fields.stream() + .flatMap(f -> f.searchFields().entrySet().stream()) + .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); + } + }; + } + }; + IndicesService indicesService = new IndicesServiceBuilder().settings(settings) .pluginsService(pluginsService) .nodeEnvironment(nodeEnvironment) @@ -933,7 +960,8 @@ public Map searchFields() { dataStreamGlobalRetentionSettings, documentParsingProvider, taskManager, - projectResolver + projectResolver, + slowLogFieldProviders ); Collection pluginComponents = pluginsService.flatMap(plugin -> { diff --git a/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java b/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java index 01a2017544510..225643786b7da 100644 --- a/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java +++ b/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java @@ -20,6 +20,7 @@ import org.elasticsearch.env.Environment; import org.elasticsearch.env.NodeEnvironment; import org.elasticsearch.features.FeatureService; +import org.elasticsearch.index.SlowLogFieldProvider; import org.elasticsearch.indices.IndicesService; import org.elasticsearch.indices.SystemIndices; import org.elasticsearch.plugins.Plugin; @@ -32,6 +33,8 @@ import org.elasticsearch.watcher.ResourceWatcherService; import org.elasticsearch.xcontent.NamedXContentRegistry; +import java.util.List; + public record PluginServiceInstances( Client client, ClusterService clusterService, @@ -53,5 +56,6 @@ public record PluginServiceInstances( DataStreamGlobalRetentionSettings dataStreamGlobalRetentionSettings, DocumentParsingProvider documentParsingProvider, TaskManager taskManager, - ProjectResolver projectResolver + ProjectResolver projectResolver, + List slowLogFieldProviders ) implements Plugin.PluginServices {} diff --git a/server/src/main/java/org/elasticsearch/plugins/Plugin.java b/server/src/main/java/org/elasticsearch/plugins/Plugin.java index 8844597cb5d26..004567ef87b40 100644 --- a/server/src/main/java/org/elasticsearch/plugins/Plugin.java +++ b/server/src/main/java/org/elasticsearch/plugins/Plugin.java @@ -29,6 +29,7 @@ import org.elasticsearch.features.FeatureService; import org.elasticsearch.index.IndexModule; import org.elasticsearch.index.IndexSettingProvider; +import org.elasticsearch.index.SlowLogFieldProvider; import org.elasticsearch.indices.IndicesService; import org.elasticsearch.indices.SystemIndices; import org.elasticsearch.plugins.internal.DocumentParsingProvider; @@ -180,6 +181,11 @@ public interface PluginServices { * The project resolver for the cluster. This should be used to determine the active project against which a request should execute */ ProjectResolver projectResolver(); + + /** + * Providers for additional SlowLog fields + */ + List slowLogFieldProviders(); } /** diff --git a/server/src/test/java/org/elasticsearch/indices/IndicesServiceTests.java b/server/src/test/java/org/elasticsearch/indices/IndicesServiceTests.java index f66958dd31155..d1344fbdb2d80 100644 --- a/server/src/test/java/org/elasticsearch/indices/IndicesServiceTests.java +++ b/server/src/test/java/org/elasticsearch/indices/IndicesServiceTests.java @@ -213,7 +213,7 @@ static void setFields(Map fields) { } @Override - public SlowLogFields create(IndexSettings indexSettings) { + public SlowLogFields create() { return new SlowLogFields() { @Override public Map indexFields() { @@ -226,6 +226,12 @@ public Map searchFields() { } }; } + + @Override + public SlowLogFields create(IndexSettings indexSettings) { + return create(); + } + } public static class TestAnotherSlowLogFieldProvider implements SlowLogFieldProvider { @@ -237,7 +243,7 @@ static void setFields(Map fields) { } @Override - public SlowLogFields create(IndexSettings indexSettings) { + public SlowLogFields create() { return new SlowLogFields() { @Override public Map indexFields() { @@ -250,6 +256,11 @@ public Map searchFields() { } }; } + + @Override + public SlowLogFields create(IndexSettings indexSettings) { + return create(); + } } @Override diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java index 340516256b680..ea5fbc12d1086 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java @@ -51,7 +51,6 @@ import org.elasticsearch.xpack.core.XPackPlugin; import org.elasticsearch.xpack.core.action.XPackInfoFeatureAction; import org.elasticsearch.xpack.core.action.XPackUsageFeatureAction; -import org.elasticsearch.xpack.core.security.SecurityContext; import org.elasticsearch.xpack.esql.EsqlInfoTransportAction; import org.elasticsearch.xpack.esql.EsqlUsageTransportAction; import org.elasticsearch.xpack.esql.action.EsqlAsyncGetResultAction; @@ -172,10 +171,7 @@ public Collection createComponents(PluginServices services) { new IndexResolver(services.client()), services.telemetryProvider().getMeterRegistry(), getLicenseState(), - new EsqlSlowLog( - services.clusterService().getClusterSettings(), - new SecurityContext(Settings.EMPTY, services.threadPool().getThreadContext()) - ) + new EsqlSlowLog(services.clusterService().getClusterSettings(), services.slowLogFieldProviders()) ), new ExchangeService( services.clusterService().getSettings(), diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java index d653e83137572..e93e19e58c71d 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java @@ -12,13 +12,14 @@ import org.elasticsearch.common.logging.ESLogMessage; import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.core.TimeValue; +import org.elasticsearch.index.SlowLogFieldProvider; +import org.elasticsearch.index.SlowLogFields; import org.elasticsearch.xcontent.json.JsonStringEncoder; -import org.elasticsearch.xpack.core.security.SecurityContext; -import org.elasticsearch.xpack.core.security.user.User; import org.elasticsearch.xpack.esql.session.Result; import java.nio.charset.StandardCharsets; import java.util.HashMap; +import java.util.List; import java.util.Map; import java.util.function.Supplier; @@ -43,6 +44,7 @@ public final class EsqlSlowLog { public static final String LOGGER_NAME = "esql.slowlog.query"; private static final Logger queryLogger = LogManager.getLogger(LOGGER_NAME); + private final List additionalProviders; private volatile long queryWarnThreshold; private volatile long queryInfoThreshold; @@ -51,16 +53,14 @@ public final class EsqlSlowLog { private volatile boolean includeUser; - private final SecurityContext security; - - public EsqlSlowLog(ClusterSettings settings, SecurityContext security) { + public EsqlSlowLog(ClusterSettings settings, List slowLogFieldProviders) { settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, this::setQueryWarnThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, this::setQueryInfoThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, this::setQueryDebugThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, this::setQueryTraceThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING, this::setIncludeUser); - this.security = security; + this.additionalProviders = slowLogFieldProviders.stream().map(SlowLogFieldProvider::create).toList(); } public EsqlSlowLog(ClusterSettings settings) { @@ -72,11 +72,11 @@ public void onQueryPhase(Result esqlResult, String query) { return; // TODO review, it happens in some tests, not sure if it's a thing also in prod } long tookInNanos = esqlResult.executionInfo().overallTook().nanos(); - log(() -> Message.of(esqlResult, query, user()), tookInNanos); + log(() -> Message.of(esqlResult, query, additionalProviders), tookInNanos); } public void onQueryFailure(String query, Exception ex, long tookInNanos) { - log(() -> Message.of(query, tookInNanos, ex, user()), tookInNanos); + log(() -> Message.of(query, tookInNanos, ex, additionalProviders), tookInNanos); } private void log(Supplier logProducer, long tookInNanos) { @@ -111,14 +111,6 @@ public void setIncludeUser(boolean includeUser) { this.includeUser = includeUser; } - private User user() { - User user = null; - if (includeUser && security != null) { - user = security.getUser(); - } - return user; - } - static final class Message { private static String escapeJson(String text) { @@ -126,24 +118,29 @@ private static String escapeJson(String text) { return new String(sourceEscaped, StandardCharsets.UTF_8); } - public static ESLogMessage of(Result esqlResult, String query, User user) { + public static ESLogMessage of(Result esqlResult, String query, List providers) { Map jsonFields = new HashMap<>(); - addGenericFields(jsonFields, query, true, user); + addFromProviders(providers, jsonFields); + addGenericFields(jsonFields, query, true); addResultFields(jsonFields, esqlResult); return new ESLogMessage().withFields(jsonFields); } - public static ESLogMessage of(String query, long took, Exception exception, User user) { + public static ESLogMessage of(String query, long took, Exception exception, List providers) { Map jsonFields = new HashMap<>(); - addGenericFields(jsonFields, query, false, user); + addFromProviders(providers, jsonFields); + addGenericFields(jsonFields, query, false); addErrorFields(jsonFields, took, exception); return new ESLogMessage().withFields(jsonFields); } - private static void addGenericFields(Map fieldMap, String query, boolean success, User user) { - if (user != null) { - fieldMap.put("user.name", user.principal()); + private static void addFromProviders(List providers, Map jsonFields) { + for (SlowLogFields provider : providers) { + jsonFields.putAll(provider.queryFields()); } + } + + private static void addGenericFields(Map fieldMap, String query, boolean success) { String source = escapeJson(query); fieldMap.put(ELASTICSEARCH_SLOWLOG_SUCCESS, success); fieldMap.put(ELASTICSEARCH_SLOWLOG_SEARCH_TYPE, "ESQL"); diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java index b5327b6779656..53eef9d85f8a2 100644 --- a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java +++ b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java @@ -33,6 +33,9 @@ private class SecuritySlowLogFields implements SlowLogFields { this.includeUserInIndexing = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_INCLUDE_USER_SETTING); } + SecuritySlowLogFields() { + } + @Override public Map indexFields() { if (includeUserInIndexing) { @@ -48,6 +51,11 @@ public Map searchFields() { } return Map.of(); } + + @Override + public Map queryFields() { + return plugin.getAuthContextForSlowLog(); + } } public SecuritySlowLogFieldProvider() { @@ -62,4 +70,9 @@ public SecuritySlowLogFieldProvider(Security plugin) { public SlowLogFields create(IndexSettings indexSettings) { return new SecuritySlowLogFields(indexSettings); } + + @Override + public SlowLogFields create() { + return new SecuritySlowLogFields(); + } } From bbfa89b3748086ac5af81bb249d5ad3a7c55a19a Mon Sep 17 00:00:00 2001 From: elasticsearchmachine Date: Fri, 14 Mar 2025 14:38:24 +0000 Subject: [PATCH 13/19] [CI] Auto commit changes from spotless --- .../src/main/java/org/elasticsearch/index/SlowLogFields.java | 3 +-- .../src/main/java/org/elasticsearch/node/NodeConstruction.java | 1 - .../xpack/security/slowlog/SecuritySlowLogFieldProvider.java | 3 +-- 3 files changed, 2 insertions(+), 5 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/index/SlowLogFields.java b/server/src/main/java/org/elasticsearch/index/SlowLogFields.java index fe9df11e0579e..b0d5ebd5cea81 100644 --- a/server/src/main/java/org/elasticsearch/index/SlowLogFields.java +++ b/server/src/main/java/org/elasticsearch/index/SlowLogFields.java @@ -28,12 +28,11 @@ public interface SlowLogFields { */ Map searchFields(); - /** * Slow log fields for query * @return map of field name to value */ - default Map queryFields(){ + default Map queryFields() { return Map.of(); } } diff --git a/server/src/main/java/org/elasticsearch/node/NodeConstruction.java b/server/src/main/java/org/elasticsearch/node/NodeConstruction.java index a127a1b7dabd6..b9a3eda4cdabb 100644 --- a/server/src/main/java/org/elasticsearch/node/NodeConstruction.java +++ b/server/src/main/java/org/elasticsearch/node/NodeConstruction.java @@ -873,7 +873,6 @@ public Map searchFields() { }; - IndicesService indicesService = new IndicesServiceBuilder().settings(settings) .pluginsService(pluginsService) .nodeEnvironment(nodeEnvironment) diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java index 53eef9d85f8a2..1127f75370f4a 100644 --- a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java +++ b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java @@ -33,8 +33,7 @@ private class SecuritySlowLogFields implements SlowLogFields { this.includeUserInIndexing = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_INCLUDE_USER_SETTING); } - SecuritySlowLogFields() { - } + SecuritySlowLogFields() {} @Override public Map indexFields() { From e390232deab042c60fa90d7335ee5ab7d7fc3554 Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Fri, 14 Mar 2025 16:29:30 +0100 Subject: [PATCH 14/19] Merge log field providers --- .../elasticsearch/node/NodeConstruction.java | 16 +++++++++++- .../node/PluginServiceInstances.java | 2 +- .../org/elasticsearch/plugins/Plugin.java | 4 +-- .../xpack/esql/plugin/EsqlPlugin.java | 2 +- .../xpack/esql/slowlog/EsqlSlowLog.java | 25 +++++++------------ 5 files changed, 28 insertions(+), 21 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/node/NodeConstruction.java b/server/src/main/java/org/elasticsearch/node/NodeConstruction.java index a127a1b7dabd6..3b644faeb3591 100644 --- a/server/src/main/java/org/elasticsearch/node/NodeConstruction.java +++ b/server/src/main/java/org/elasticsearch/node/NodeConstruction.java @@ -846,6 +846,13 @@ public Map searchFields() { .flatMap(f -> f.searchFields().entrySet().stream()) .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); } + + @Override + public Map queryFields() { + return fields.stream() + .flatMap(f -> f.queryFields().entrySet().stream()) + .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); + } }; } @@ -868,6 +875,13 @@ public Map searchFields() { .flatMap(f -> f.searchFields().entrySet().stream()) .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); } + + @Override + public Map queryFields() { + return fields.stream() + .flatMap(f -> f.queryFields().entrySet().stream()) + .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); + } }; } @@ -961,7 +975,7 @@ public Map searchFields() { documentParsingProvider, taskManager, projectResolver, - slowLogFieldProviders + slowLogFieldProvider ); Collection pluginComponents = pluginsService.flatMap(plugin -> { diff --git a/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java b/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java index 225643786b7da..ffe31f7312cf8 100644 --- a/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java +++ b/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java @@ -57,5 +57,5 @@ public record PluginServiceInstances( DocumentParsingProvider documentParsingProvider, TaskManager taskManager, ProjectResolver projectResolver, - List slowLogFieldProviders + SlowLogFieldProvider slowLogFieldProvider ) implements Plugin.PluginServices {} diff --git a/server/src/main/java/org/elasticsearch/plugins/Plugin.java b/server/src/main/java/org/elasticsearch/plugins/Plugin.java index 004567ef87b40..4a3990e3fd3c3 100644 --- a/server/src/main/java/org/elasticsearch/plugins/Plugin.java +++ b/server/src/main/java/org/elasticsearch/plugins/Plugin.java @@ -183,9 +183,9 @@ public interface PluginServices { ProjectResolver projectResolver(); /** - * Providers for additional SlowLog fields + * Provider for additional SlowLog fields */ - List slowLogFieldProviders(); + SlowLogFieldProvider slowLogFieldProvider(); } /** diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java index 9cd39d03bda23..8af92716984c6 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java @@ -170,7 +170,7 @@ public Collection createComponents(PluginServices services) { new IndexResolver(services.client()), services.telemetryProvider().getMeterRegistry(), getLicenseState(), - new EsqlSlowLog(services.clusterService().getClusterSettings(), services.slowLogFieldProviders()) + new EsqlSlowLog(services.clusterService().getClusterSettings(), services.slowLogFieldProvider()) ), new ExchangeService( services.clusterService().getSettings(), diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java index e93e19e58c71d..a76385c9c6d63 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java @@ -19,7 +19,6 @@ import java.nio.charset.StandardCharsets; import java.util.HashMap; -import java.util.List; import java.util.Map; import java.util.function.Supplier; @@ -44,7 +43,7 @@ public final class EsqlSlowLog { public static final String LOGGER_NAME = "esql.slowlog.query"; private static final Logger queryLogger = LogManager.getLogger(LOGGER_NAME); - private final List additionalProviders; + private final SlowLogFields additionalFields; private volatile long queryWarnThreshold; private volatile long queryInfoThreshold; @@ -53,14 +52,14 @@ public final class EsqlSlowLog { private volatile boolean includeUser; - public EsqlSlowLog(ClusterSettings settings, List slowLogFieldProviders) { + public EsqlSlowLog(ClusterSettings settings, SlowLogFieldProvider slowLogFieldProvider) { settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, this::setQueryWarnThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, this::setQueryInfoThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, this::setQueryDebugThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, this::setQueryTraceThreshold); settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING, this::setIncludeUser); - this.additionalProviders = slowLogFieldProviders.stream().map(SlowLogFieldProvider::create).toList(); + this.additionalFields = slowLogFieldProvider.create(); } public EsqlSlowLog(ClusterSettings settings) { @@ -72,11 +71,11 @@ public void onQueryPhase(Result esqlResult, String query) { return; // TODO review, it happens in some tests, not sure if it's a thing also in prod } long tookInNanos = esqlResult.executionInfo().overallTook().nanos(); - log(() -> Message.of(esqlResult, query, additionalProviders), tookInNanos); + log(() -> Message.of(esqlResult, query, includeUser ? additionalFields.queryFields() : Map.of()), tookInNanos); } public void onQueryFailure(String query, Exception ex, long tookInNanos) { - log(() -> Message.of(query, tookInNanos, ex, additionalProviders), tookInNanos); + log(() -> Message.of(query, tookInNanos, ex, includeUser ? additionalFields.queryFields() : Map.of()), tookInNanos); } private void log(Supplier logProducer, long tookInNanos) { @@ -118,28 +117,22 @@ private static String escapeJson(String text) { return new String(sourceEscaped, StandardCharsets.UTF_8); } - public static ESLogMessage of(Result esqlResult, String query, List providers) { + public static ESLogMessage of(Result esqlResult, String query, Map additionalFields) { Map jsonFields = new HashMap<>(); - addFromProviders(providers, jsonFields); + jsonFields.putAll(additionalFields); addGenericFields(jsonFields, query, true); addResultFields(jsonFields, esqlResult); return new ESLogMessage().withFields(jsonFields); } - public static ESLogMessage of(String query, long took, Exception exception, List providers) { + public static ESLogMessage of(String query, long took, Exception exception, Map additionalFields) { Map jsonFields = new HashMap<>(); - addFromProviders(providers, jsonFields); + jsonFields.putAll(additionalFields); addGenericFields(jsonFields, query, false); addErrorFields(jsonFields, took, exception); return new ESLogMessage().withFields(jsonFields); } - private static void addFromProviders(List providers, Map jsonFields) { - for (SlowLogFields provider : providers) { - jsonFields.putAll(provider.queryFields()); - } - } - private static void addGenericFields(Map fieldMap, String query, boolean success) { String source = escapeJson(query); fieldMap.put(ELASTICSEARCH_SLOWLOG_SUCCESS, success); From cec182e878478145a621452c59686018ac3bbcdb Mon Sep 17 00:00:00 2001 From: elasticsearchmachine Date: Fri, 14 Mar 2025 15:38:01 +0000 Subject: [PATCH 15/19] [CI] Auto commit changes from spotless --- .../java/org/elasticsearch/node/PluginServiceInstances.java | 2 -- 1 file changed, 2 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java b/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java index ffe31f7312cf8..aeb7646524582 100644 --- a/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java +++ b/server/src/main/java/org/elasticsearch/node/PluginServiceInstances.java @@ -33,8 +33,6 @@ import org.elasticsearch.watcher.ResourceWatcherService; import org.elasticsearch.xcontent.NamedXContentRegistry; -import java.util.List; - public record PluginServiceInstances( Client client, ClusterService clusterService, From df788dba0bed7acc04880058187d86be01dd239c Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Fri, 14 Mar 2025 18:03:06 +0100 Subject: [PATCH 16/19] Fix tests --- .../xpack/esql/slowlog/EsqlSlowLogTests.java | 32 +++++++++++++++++-- .../telemetry/PlanExecutorMetricsTests.java | 25 ++++++++++++++- 2 files changed, 54 insertions(+), 3 deletions(-) diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java index 68c049c65b1e8..b691bd269f5d6 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java @@ -16,6 +16,9 @@ import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.core.TimeValue; +import org.elasticsearch.index.IndexSettings; +import org.elasticsearch.index.SlowLogFieldProvider; +import org.elasticsearch.index.SlowLogFields; import org.elasticsearch.test.ESTestCase; import org.elasticsearch.xpack.esql.MockAppender; import org.elasticsearch.xpack.esql.action.EsqlExecutionInfo; @@ -27,6 +30,7 @@ import java.util.Arrays; import java.util.HashSet; import java.util.List; +import java.util.Map; import java.util.concurrent.TimeUnit; import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_PLANNING_TOOK; @@ -82,7 +86,7 @@ public static void cleanup() { } public void testPrioritiesOnSuccess() { - EsqlSlowLog slowLog = new EsqlSlowLog(settings); + EsqlSlowLog slowLog = new EsqlSlowLog(settings, mockFieldProvider()); String query = "from " + randomAlphaOfLength(10); long[] actualTook = { @@ -126,8 +130,32 @@ public void testPrioritiesOnSuccess() { } } + private SlowLogFieldProvider mockFieldProvider() { + return new SlowLogFieldProvider() { + @Override + public SlowLogFields create(IndexSettings indexSettings) { + return create(); + } + + @Override + public SlowLogFields create() { + return new SlowLogFields() { + @Override + public Map indexFields() { + return Map.of(); + } + + @Override + public Map searchFields() { + return Map.of(); + } + }; + } + }; + } + public void testPrioritiesOnFailure() { - EsqlSlowLog slowLog = new EsqlSlowLog(settings); + EsqlSlowLog slowLog = new EsqlSlowLog(settings, mockFieldProvider()); String query = "from " + randomAlphaOfLength(10); long[] actualTook = { diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java index 074e022ed3a3e..e8fcd68ffa825 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java @@ -19,6 +19,9 @@ import org.elasticsearch.common.settings.ClusterSettings; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.index.IndexMode; +import org.elasticsearch.index.IndexSettings; +import org.elasticsearch.index.SlowLogFieldProvider; +import org.elasticsearch.index.SlowLogFields; import org.elasticsearch.indices.IndicesExpressionGrouper; import org.elasticsearch.license.XPackLicenseState; import org.elasticsearch.telemetry.metric.MeterRegistry; @@ -97,7 +100,27 @@ EsqlSlowLog mockSlowLog() { ) ) ); - return new EsqlSlowLog(clusterSettings); + return new EsqlSlowLog(clusterSettings, new SlowLogFieldProvider() { + @Override + public SlowLogFields create(IndexSettings indexSettings) { + return create(); + } + + @Override + public SlowLogFields create() { + return new SlowLogFields() { + @Override + public Map indexFields() { + return Map.of(); + } + + @Override + public Map searchFields() { + return Map.of(); + } + }; + } + }); } public void testFailedMetric() { From 01d4c66283dd26126f9ba153bfa7bb27fe50f494 Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Mon, 17 Mar 2025 10:41:04 +0100 Subject: [PATCH 17/19] Rename as QueryLog --- distribution/src/config/log4j2.properties | 38 ++++----- ...EsqlSlowLogIT.java => EsqlQueryLogIT.java} | 50 ++++++------ .../xpack/esql/execution/PlanExecutor.java | 12 +-- .../xpack/esql/plugin/EsqlPlugin.java | 34 ++++---- .../EsqlQueryLog.java} | 80 +++++++++---------- .../EsqlQueryLogTests.java} | 64 +++++++-------- .../telemetry/PlanExecutorMetricsTests.java | 18 ++--- 7 files changed, 146 insertions(+), 150 deletions(-) rename x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/{EsqlSlowLogIT.java => EsqlQueryLogIT.java} (80%) rename x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/{slowlog/EsqlSlowLog.java => querylog/EsqlQueryLog.java} (60%) rename x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/{slowlog/EsqlSlowLogTests.java => querylog/EsqlQueryLogTests.java} (73%) diff --git a/distribution/src/config/log4j2.properties b/distribution/src/config/log4j2.properties index f0798f5a33e2f..3a393bbc7618c 100644 --- a/distribution/src/config/log4j2.properties +++ b/distribution/src/config/log4j2.properties @@ -131,24 +131,24 @@ logger.index_indexing_slowlog.appenderRef.index_indexing_slowlog_rolling.ref = i logger.index_indexing_slowlog.additivity = false -######## Search ES|QL JSON #################### -appender.esql_slowlog_rolling.type = RollingFile -appender.esql_slowlog_rolling.name = esql_slowlog_rolling -appender.esql_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs\ - .cluster_name}_esql_slowlog.json -appender.esql_slowlog_rolling.layout.type = ECSJsonLayout -appender.esql_slowlog_rolling.layout.dataset = elasticsearch.esql_slowlog - -appender.esql_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs\ - .cluster_name}_esql_slowlog-%i.json.gz -appender.esql_slowlog_rolling.policies.type = Policies -appender.esql_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy -appender.esql_slowlog_rolling.policies.size.size = 1GB -appender.esql_slowlog_rolling.strategy.type = DefaultRolloverStrategy -appender.esql_slowlog_rolling.strategy.max = 4 +######## ES|QL query log JSON #################### +appender.esql_querylog_rolling.type = RollingFile +appender.esql_querylog_rolling.name = esql_querylog_rolling +appender.esql_querylog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs\ + .cluster_name}_esql_querylog.json +appender.esql_querylog_rolling.layout.type = ECSJsonLayout +appender.esql_querylog_rolling.layout.dataset = elasticsearch.esql_querylog + +appender.esql_querylog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs\ + .cluster_name}_esql_querylog-%i.json.gz +appender.esql_querylog_rolling.policies.type = Policies +appender.esql_querylog_rolling.policies.size.type = SizeBasedTriggeringPolicy +appender.esql_querylog_rolling.policies.size.size = 1GB +appender.esql_querylog_rolling.strategy.type = DefaultRolloverStrategy +appender.esql_querylog_rolling.strategy.max = 4 ################################################# -logger.esql_slowlog_rolling.name = esql.slowlog -logger.esql_slowlog_rolling.level = trace -logger.esql_slowlog_rolling.appenderRef.index_search_slowlog_rolling.ref = esql_slowlog_rolling -logger.esql_slowlog_rolling.additivity = false +logger.esql_querylog_rolling.name = esql.querylog +logger.esql_querylog_rolling.level = trace +logger.esql_querylog_rolling.appenderRef.index_search_querylog_rolling.ref = esql_querylog_rolling +logger.esql_querylog_rolling.additivity = false diff --git a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlQueryLogIT.java similarity index 80% rename from x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java rename to x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlQueryLogIT.java index 22dc2c5784efb..bdbb4b9c67e12 100644 --- a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java +++ b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlQueryLogIT.java @@ -21,7 +21,7 @@ import org.elasticsearch.xpack.esql.MockAppender; import org.elasticsearch.xpack.esql.VerificationException; import org.elasticsearch.xpack.esql.plugin.EsqlPlugin; -import org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog; +import org.elasticsearch.xpack.esql.querylog.EsqlQueryLog; import org.junit.AfterClass; import org.junit.BeforeClass; @@ -30,14 +30,14 @@ import java.util.concurrent.ExecutionException; import static org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_ERROR_MESSAGE; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_ERROR_TYPE; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_PLANNING_TOOK; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_QUERY; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_SUCCESS; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_TOOK; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_TOOK_MILLIS; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_ERROR_MESSAGE; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_ERROR_TYPE; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_PLANNING_TOOK; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_PLANNING_TOOK_MILLIS; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_QUERY; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_SUCCESS; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_TOOK; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_TOOK_MILLIS; import static org.hamcrest.Matchers.containsString; import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.greaterThan; @@ -45,9 +45,9 @@ import static org.hamcrest.Matchers.is; import static org.hamcrest.Matchers.nullValue; -public class EsqlSlowLogIT extends AbstractEsqlIntegTestCase { +public class EsqlQueryLogIT extends AbstractEsqlIntegTestCase { static MockAppender appender; - static Logger queryLog = LogManager.getLogger(EsqlSlowLog.LOGGER_NAME); + static Logger queryLog = LogManager.getLogger(EsqlQueryLog.LOGGER_NAME); static Level origQueryLogLevel = queryLog.getLevel(); @BeforeClass @@ -83,13 +83,13 @@ public void testSetLevel() throws Exception { Map levels = Map.of( Level.WARN, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING.getKey(), + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING.getKey(), Level.INFO, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING.getKey(), + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING.getKey(), Level.DEBUG, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), Level.TRACE, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey() + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey() ); testAllLevels( levels, @@ -176,36 +176,36 @@ private static void testAllLevels( return; } var msg = (ESLogMessage) appender.lastMessage(); - long took = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK)); + long took = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_TOOK)); long tookMillisExpected = took / 1_000_000; - long tookMillis = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK_MILLIS)); + long tookMillis = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_TOOK_MILLIS)); assertThat(took, greaterThan(0L)); assertThat(tookMillis, greaterThanOrEqualTo(timeoutMillis)); assertThat(tookMillis, is(tookMillisExpected)); if (expectedException == null) { - long planningTook = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK)); + long planningTook = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_PLANNING_TOOK)); long planningTookMillisExpected = planningTook / 1_000_000; - long planningTookMillis = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS)); + long planningTookMillis = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_PLANNING_TOOK_MILLIS)); assertThat(planningTook, greaterThanOrEqualTo(0L)); assertThat(planningTookMillis, is(planningTookMillisExpected)); assertThat(took, greaterThan(planningTook)); } - assertThat(msg.get(ELASTICSEARCH_SLOWLOG_QUERY), is(query)); + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_QUERY), is(query)); assertThat(appender.getLastEventAndReset().getLevel(), equalTo(logLevel.getKey())); - boolean success = Boolean.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_SUCCESS)); + boolean success = Boolean.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_SUCCESS)); assertThat(success, is(expectedException == null)); if (expectedErrorMsg == null) { - assertThat(msg.get(ELASTICSEARCH_SLOWLOG_ERROR_MESSAGE), is(nullValue())); + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_ERROR_MESSAGE), is(nullValue())); } else { - assertThat(msg.get(ELASTICSEARCH_SLOWLOG_ERROR_MESSAGE), containsString(expectedErrorMsg)); + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_ERROR_MESSAGE), containsString(expectedErrorMsg)); } if (expectedException == null) { - assertThat(msg.get(ELASTICSEARCH_SLOWLOG_ERROR_TYPE), is(nullValue())); + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_ERROR_TYPE), is(nullValue())); } else { - assertThat(msg.get(ELASTICSEARCH_SLOWLOG_ERROR_TYPE), is(expectedException)); + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_ERROR_TYPE), is(expectedException)); } } finally { latch.countDown(); diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java index 63e6a44cd7a87..40b142e04b970 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java @@ -22,11 +22,11 @@ import org.elasticsearch.xpack.esql.optimizer.LogicalPlanOptimizer; import org.elasticsearch.xpack.esql.planner.mapper.Mapper; import org.elasticsearch.xpack.esql.plugin.TransportActionServices; +import org.elasticsearch.xpack.esql.querylog.EsqlQueryLog; import org.elasticsearch.xpack.esql.session.Configuration; import org.elasticsearch.xpack.esql.session.EsqlSession; import org.elasticsearch.xpack.esql.session.IndexResolver; import org.elasticsearch.xpack.esql.session.Result; -import org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog; import org.elasticsearch.xpack.esql.telemetry.Metrics; import org.elasticsearch.xpack.esql.telemetry.PlanTelemetry; import org.elasticsearch.xpack.esql.telemetry.PlanTelemetryManager; @@ -43,9 +43,9 @@ public class PlanExecutor { private final Metrics metrics; private final Verifier verifier; private final PlanTelemetryManager planTelemetryManager; - private final EsqlSlowLog slowLog; + private final EsqlQueryLog queryLog; - public PlanExecutor(IndexResolver indexResolver, MeterRegistry meterRegistry, XPackLicenseState licenseState, EsqlSlowLog slowLog) { + public PlanExecutor(IndexResolver indexResolver, MeterRegistry meterRegistry, XPackLicenseState licenseState, EsqlQueryLog queryLog) { this.indexResolver = indexResolver; this.preAnalyzer = new PreAnalyzer(); this.functionRegistry = new EsqlFunctionRegistry(); @@ -53,7 +53,7 @@ public PlanExecutor(IndexResolver indexResolver, MeterRegistry meterRegistry, XP this.metrics = new Metrics(functionRegistry); this.verifier = new Verifier(metrics, licenseState); this.planTelemetryManager = new PlanTelemetryManager(meterRegistry); - this.slowLog = slowLog; + this.queryLog = queryLog; } public void esql( @@ -98,7 +98,7 @@ public void esql( private void onQuerySuccess(EsqlQueryRequest request, ActionListener listener, Result x, PlanTelemetry planTelemetry) { planTelemetryManager.publish(planTelemetry, true); - slowLog.onQueryPhase(x, request.query()); + queryLog.onQueryPhase(x, request.query()); listener.onResponse(x); } @@ -113,7 +113,7 @@ private void onQueryFailure( // TODO when we decide if we will differentiate Kibana from REST, this String value will likely come from the request metrics.failed(clientId); planTelemetryManager.publish(planTelemetry, false); - slowLog.onQueryFailure(request.query(), ex, System.nanoTime() - begin); + queryLog.onQueryFailure(request.query(), ex, System.nanoTime() - begin); listener.onFailure(ex); } diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java index 8af92716984c6..ce2210b444ddc 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java @@ -69,8 +69,8 @@ import org.elasticsearch.xpack.esql.expression.ExpressionWritables; import org.elasticsearch.xpack.esql.plan.PlanWritables; import org.elasticsearch.xpack.esql.querydsl.query.SingleValueQuery; +import org.elasticsearch.xpack.esql.querylog.EsqlQueryLog; import org.elasticsearch.xpack.esql.session.IndexResolver; -import org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog; import java.lang.invoke.MethodHandles; import java.util.ArrayList; @@ -110,8 +110,8 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); - public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING = Setting.timeSetting( - "esql.slowlog.threshold.query.warn", + public static final Setting ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING = Setting.timeSetting( + "esql.querylog.threshold.query.warn", TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), @@ -119,8 +119,8 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); - public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING = Setting.timeSetting( - "esql.slowlog.threshold.query.info", + public static final Setting ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING = Setting.timeSetting( + "esql.querylog.threshold.query.info", TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), @@ -128,8 +128,8 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); - public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING = Setting.timeSetting( - "esql.slowlog.threshold.query.debug", + public static final Setting ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING = Setting.timeSetting( + "esql.querylog.threshold.query.debug", TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), @@ -137,8 +137,8 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); - public static final Setting ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING = Setting.timeSetting( - "esql.slowlog.threshold.query.trace", + public static final Setting ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING = Setting.timeSetting( + "esql.querylog.threshold.query.trace", TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), @@ -146,8 +146,8 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); - public static final Setting ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING = Setting.boolSetting( - "esql.slowlog.include.user", + public static final Setting ESQL_QUERYLOG_INCLUDE_USER_SETTING = Setting.boolSetting( + "esql.querylog.include.user", false, Setting.Property.NodeScope, Setting.Property.Dynamic @@ -170,7 +170,7 @@ public Collection createComponents(PluginServices services) { new IndexResolver(services.client()), services.telemetryProvider().getMeterRegistry(), getLicenseState(), - new EsqlSlowLog(services.clusterService().getClusterSettings(), services.slowLogFieldProvider()) + new EsqlQueryLog(services.clusterService().getClusterSettings(), services.slowLogFieldProvider()) ), new ExchangeService( services.clusterService().getSettings(), @@ -211,11 +211,11 @@ public List> getSettings() { QUERY_RESULT_TRUNCATION_DEFAULT_SIZE, QUERY_RESULT_TRUNCATION_MAX_SIZE, QUERY_ALLOW_PARTIAL_RESULTS, - ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, - ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, - ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, - ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, - ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING + ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING, + ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING, + ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING, + ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING, + ESQL_QUERYLOG_INCLUDE_USER_SETTING ); } diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLog.java similarity index 60% rename from x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java rename to x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLog.java index a76385c9c6d63..ff2a6ed8c73e4 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLog.java @@ -5,7 +5,7 @@ * 2.0. */ -package org.elasticsearch.xpack.esql.slowlog; +package org.elasticsearch.xpack.esql.querylog; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; @@ -22,26 +22,26 @@ import java.util.Map; import java.util.function.Supplier; -import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING; -import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING; -import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING; -import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING; -import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING; - -public final class EsqlSlowLog { - - public static final String ELASTICSEARCH_SLOWLOG_PREFIX = "elasticsearch.slowlog"; - public static final String ELASTICSEARCH_SLOWLOG_ERROR_MESSAGE = ELASTICSEARCH_SLOWLOG_PREFIX + ".error.message"; - public static final String ELASTICSEARCH_SLOWLOG_ERROR_TYPE = ELASTICSEARCH_SLOWLOG_PREFIX + ".error.type"; - public static final String ELASTICSEARCH_SLOWLOG_TOOK = ELASTICSEARCH_SLOWLOG_PREFIX + ".took"; - public static final String ELASTICSEARCH_SLOWLOG_TOOK_MILLIS = ELASTICSEARCH_SLOWLOG_PREFIX + ".took_millis"; - public static final String ELASTICSEARCH_SLOWLOG_PLANNING_TOOK = ELASTICSEARCH_SLOWLOG_PREFIX + ".planning.took"; - public static final String ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS = ELASTICSEARCH_SLOWLOG_PREFIX + ".planning.took_millis"; - public static final String ELASTICSEARCH_SLOWLOG_SUCCESS = ELASTICSEARCH_SLOWLOG_PREFIX + ".success"; - public static final String ELASTICSEARCH_SLOWLOG_SEARCH_TYPE = ELASTICSEARCH_SLOWLOG_PREFIX + ".search_type"; - public static final String ELASTICSEARCH_SLOWLOG_QUERY = ELASTICSEARCH_SLOWLOG_PREFIX + ".query"; - - public static final String LOGGER_NAME = "esql.slowlog.query"; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_INCLUDE_USER_SETTING; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING; + +public final class EsqlQueryLog { + + public static final String ELASTICSEARCH_QUERYLOG_PREFIX = "elasticsearch.querylog"; + public static final String ELASTICSEARCH_QUERYLOG_ERROR_MESSAGE = ELASTICSEARCH_QUERYLOG_PREFIX + ".error.message"; + public static final String ELASTICSEARCH_QUERYLOG_ERROR_TYPE = ELASTICSEARCH_QUERYLOG_PREFIX + ".error.type"; + public static final String ELASTICSEARCH_QUERYLOG_TOOK = ELASTICSEARCH_QUERYLOG_PREFIX + ".took"; + public static final String ELASTICSEARCH_QUERYLOG_TOOK_MILLIS = ELASTICSEARCH_QUERYLOG_PREFIX + ".took_millis"; + public static final String ELASTICSEARCH_QUERYLOG_PLANNING_TOOK = ELASTICSEARCH_QUERYLOG_PREFIX + ".planning.took"; + public static final String ELASTICSEARCH_QUERYLOG_PLANNING_TOOK_MILLIS = ELASTICSEARCH_QUERYLOG_PREFIX + ".planning.took_millis"; + public static final String ELASTICSEARCH_QUERYLOG_SUCCESS = ELASTICSEARCH_QUERYLOG_PREFIX + ".success"; + public static final String ELASTICSEARCH_QUERYLOG_SEARCH_TYPE = ELASTICSEARCH_QUERYLOG_PREFIX + ".search_type"; + public static final String ELASTICSEARCH_QUERYLOG_QUERY = ELASTICSEARCH_QUERYLOG_PREFIX + ".query"; + + public static final String LOGGER_NAME = "esql.querylog"; private static final Logger queryLogger = LogManager.getLogger(LOGGER_NAME); private final SlowLogFields additionalFields; @@ -52,20 +52,16 @@ public final class EsqlSlowLog { private volatile boolean includeUser; - public EsqlSlowLog(ClusterSettings settings, SlowLogFieldProvider slowLogFieldProvider) { - settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, this::setQueryWarnThreshold); - settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, this::setQueryInfoThreshold); - settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, this::setQueryDebugThreshold); - settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, this::setQueryTraceThreshold); - settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING, this::setIncludeUser); + public EsqlQueryLog(ClusterSettings settings, SlowLogFieldProvider slowLogFieldProvider) { + settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING, this::setQueryWarnThreshold); + settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING, this::setQueryInfoThreshold); + settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING, this::setQueryDebugThreshold); + settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING, this::setQueryTraceThreshold); + settings.initializeAndWatch(ESQL_QUERYLOG_INCLUDE_USER_SETTING, this::setIncludeUser); this.additionalFields = slowLogFieldProvider.create(); } - public EsqlSlowLog(ClusterSettings settings) { - this(settings, null); - } - public void onQueryPhase(Result esqlResult, String query) { if (esqlResult == null) { return; // TODO review, it happens in some tests, not sure if it's a thing also in prod @@ -135,23 +131,23 @@ public static ESLogMessage of(String query, long took, Exception exception, Map< private static void addGenericFields(Map fieldMap, String query, boolean success) { String source = escapeJson(query); - fieldMap.put(ELASTICSEARCH_SLOWLOG_SUCCESS, success); - fieldMap.put(ELASTICSEARCH_SLOWLOG_SEARCH_TYPE, "ESQL"); - fieldMap.put(ELASTICSEARCH_SLOWLOG_QUERY, source); + fieldMap.put(ELASTICSEARCH_QUERYLOG_SUCCESS, success); + fieldMap.put(ELASTICSEARCH_QUERYLOG_SEARCH_TYPE, "ESQL"); + fieldMap.put(ELASTICSEARCH_QUERYLOG_QUERY, source); } private static void addResultFields(Map fieldMap, Result esqlResult) { - fieldMap.put(ELASTICSEARCH_SLOWLOG_TOOK, esqlResult.executionInfo().overallTook().nanos()); - fieldMap.put(ELASTICSEARCH_SLOWLOG_TOOK_MILLIS, esqlResult.executionInfo().overallTook().millis()); - fieldMap.put(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK, esqlResult.executionInfo().planningTookTime().nanos()); - fieldMap.put(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS, esqlResult.executionInfo().planningTookTime().millis()); + fieldMap.put(ELASTICSEARCH_QUERYLOG_TOOK, esqlResult.executionInfo().overallTook().nanos()); + fieldMap.put(ELASTICSEARCH_QUERYLOG_TOOK_MILLIS, esqlResult.executionInfo().overallTook().millis()); + fieldMap.put(ELASTICSEARCH_QUERYLOG_PLANNING_TOOK, esqlResult.executionInfo().planningTookTime().nanos()); + fieldMap.put(ELASTICSEARCH_QUERYLOG_PLANNING_TOOK_MILLIS, esqlResult.executionInfo().planningTookTime().millis()); } private static void addErrorFields(Map jsonFields, long took, Exception exception) { - jsonFields.put(ELASTICSEARCH_SLOWLOG_TOOK, took); - jsonFields.put(ELASTICSEARCH_SLOWLOG_TOOK_MILLIS, took / 1_000_000); - jsonFields.put(ELASTICSEARCH_SLOWLOG_ERROR_MESSAGE, exception.getMessage() == null ? "" : exception.getMessage()); - jsonFields.put(ELASTICSEARCH_SLOWLOG_ERROR_TYPE, exception.getClass().getName()); + jsonFields.put(ELASTICSEARCH_QUERYLOG_TOOK, took); + jsonFields.put(ELASTICSEARCH_QUERYLOG_TOOK_MILLIS, took / 1_000_000); + jsonFields.put(ELASTICSEARCH_QUERYLOG_ERROR_MESSAGE, exception.getMessage() == null ? "" : exception.getMessage()); + jsonFields.put(ELASTICSEARCH_QUERYLOG_ERROR_TYPE, exception.getClass().getName()); } } } diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLogTests.java similarity index 73% rename from x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java rename to x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLogTests.java index b691bd269f5d6..221fbf5b41d30 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLogTests.java @@ -5,7 +5,7 @@ * 2.0. */ -package org.elasticsearch.xpack.esql.slowlog; +package org.elasticsearch.xpack.esql.querylog; import org.apache.logging.log4j.Level; import org.apache.logging.log4j.LogManager; @@ -33,40 +33,40 @@ import java.util.Map; import java.util.concurrent.TimeUnit; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_PLANNING_TOOK; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_QUERY; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_TOOK; -import static org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog.ELASTICSEARCH_SLOWLOG_TOOK_MILLIS; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_PLANNING_TOOK; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_PLANNING_TOOK_MILLIS; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_QUERY; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_TOOK; +import static org.elasticsearch.xpack.esql.querylog.EsqlQueryLog.ELASTICSEARCH_QUERYLOG_TOOK_MILLIS; import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.greaterThan; import static org.hamcrest.Matchers.is; import static org.hamcrest.Matchers.not; import static org.hamcrest.Matchers.nullValue; -public class EsqlSlowLogTests extends ESTestCase { +public class EsqlQueryLogTests extends ESTestCase { private static ClusterSettings settings = new ClusterSettings( Settings.builder() - .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING.getKey(), "40ms") - .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING.getKey(), "30ms") - .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), "20ms") - .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey(), "10ms") - .put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING.getKey(), true) + .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING.getKey(), "40ms") + .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING.getKey(), "30ms") + .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), "20ms") + .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey(), "10ms") + .put(EsqlPlugin.ESQL_QUERYLOG_INCLUDE_USER_SETTING.getKey(), true) .build(), new HashSet<>( Arrays.asList( - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING, + EsqlPlugin.ESQL_QUERYLOG_INCLUDE_USER_SETTING ) ) ); static MockAppender appender; - static Logger queryLog = LogManager.getLogger(EsqlSlowLog.LOGGER_NAME); + static Logger queryLog = LogManager.getLogger(EsqlQueryLog.LOGGER_NAME); static Level origQueryLogLevel = queryLog.getLevel(); @BeforeClass @@ -86,7 +86,7 @@ public static void cleanup() { } public void testPrioritiesOnSuccess() { - EsqlSlowLog slowLog = new EsqlSlowLog(settings, mockFieldProvider()); + EsqlQueryLog queryLog = new EsqlQueryLog(settings, mockFieldProvider()); String query = "from " + randomAlphaOfLength(10); long[] actualTook = { @@ -105,23 +105,23 @@ public void testPrioritiesOnSuccess() { for (int i = 0; i < actualTook.length; i++) { EsqlExecutionInfo warnQuery = getEsqlExecutionInfo(actualTook[i], actualPlanningTook[i]); - slowLog.onQueryPhase(new Result(List.of(), List.of(), List.of(), warnQuery), query); + queryLog.onQueryPhase(new Result(List.of(), List.of(), List.of(), warnQuery), query); if (expectedLevel[i] != null) { assertThat(appender.lastEvent(), is(not(nullValue()))); var msg = (ESLogMessage) appender.lastMessage(); - long took = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK)); + long took = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_TOOK)); long tookMillisExpected = took / 1_000_000L; - long tookMillis = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK_MILLIS)); + long tookMillis = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_TOOK_MILLIS)); assertThat(took, is(actualTook[i])); assertThat(tookMillis, is(tookMillisExpected)); - long planningTook = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK)); + long planningTook = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_PLANNING_TOOK)); long planningTookMillisExpected = planningTook / 1_000_000; - long planningTookMillis = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS)); + long planningTookMillis = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_PLANNING_TOOK_MILLIS)); assertThat(planningTook, is(actualPlanningTook[i])); assertThat(planningTookMillis, is(planningTookMillisExpected)); assertThat(took, greaterThan(planningTook)); - assertThat(msg.get(ELASTICSEARCH_SLOWLOG_QUERY), is(query)); + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_QUERY), is(query)); assertThat(appender.getLastEventAndReset().getLevel(), equalTo(expectedLevel[i])); } else { assertThat(appender.lastEvent(), is(nullValue())); @@ -155,7 +155,7 @@ public Map searchFields() { } public void testPrioritiesOnFailure() { - EsqlSlowLog slowLog = new EsqlSlowLog(settings, mockFieldProvider()); + EsqlQueryLog queryLog = new EsqlQueryLog(settings, mockFieldProvider()); String query = "from " + randomAlphaOfLength(10); long[] actualTook = { @@ -170,18 +170,18 @@ public void testPrioritiesOnFailure() { String validationError = randomAlphaOfLength(10); ValidationException ex = new ValidationException().addValidationError(validationError); for (int i = 0; i < actualTook.length; i++) { - slowLog.onQueryFailure(query, ex, actualTook[i]); + queryLog.onQueryFailure(query, ex, actualTook[i]); if (expectedLevel[i] != null) { assertThat(appender.lastEvent(), is(not(nullValue()))); var msg = (ESLogMessage) appender.lastMessage(); - long took = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK)); + long took = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_TOOK)); long tookMillisExpected = took / 1_000_000L; - long tookMillis = Long.valueOf(msg.get(ELASTICSEARCH_SLOWLOG_TOOK_MILLIS)); + long tookMillis = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_TOOK_MILLIS)); assertThat(took, is(actualTook[i])); assertThat(tookMillis, is(tookMillisExpected)); - assertThat(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK), is(nullValue())); - assertThat(msg.get(ELASTICSEARCH_SLOWLOG_PLANNING_TOOK_MILLIS), is(nullValue())); - assertThat(msg.get(ELASTICSEARCH_SLOWLOG_QUERY), is(query)); + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_PLANNING_TOOK), is(nullValue())); + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_PLANNING_TOOK_MILLIS), is(nullValue())); + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_QUERY), is(query)); assertThat(appender.getLastEventAndReset().getLevel(), equalTo(expectedLevel[i])); } else { assertThat(appender.lastEvent(), is(nullValue())); diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java index e8fcd68ffa825..55cd56186d767 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java @@ -38,10 +38,10 @@ import org.elasticsearch.xpack.esql.enrich.EnrichPolicyResolver; import org.elasticsearch.xpack.esql.execution.PlanExecutor; import org.elasticsearch.xpack.esql.plugin.EsqlPlugin; +import org.elasticsearch.xpack.esql.querylog.EsqlQueryLog; import org.elasticsearch.xpack.esql.session.EsqlSession; import org.elasticsearch.xpack.esql.session.IndexResolver; import org.elasticsearch.xpack.esql.session.Result; -import org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog; import org.junit.After; import org.junit.Before; import org.mockito.stubbing.Answer; @@ -87,20 +87,20 @@ EnrichPolicyResolver mockEnrichResolver() { return enrichResolver; } - EsqlSlowLog mockSlowLog() { + EsqlQueryLog mockQueryLog() { ClusterSettings clusterSettings = new ClusterSettings( Settings.EMPTY, new HashSet<>( Arrays.asList( - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, - EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING, + EsqlPlugin.ESQL_QUERYLOG_INCLUDE_USER_SETTING ) ) ); - return new EsqlSlowLog(clusterSettings, new SlowLogFieldProvider() { + return new EsqlQueryLog(clusterSettings, new SlowLogFieldProvider() { @Override public SlowLogFields create(IndexSettings indexSettings) { return create(); @@ -150,7 +150,7 @@ public void testFailedMetric() { return null; }).when(esqlClient).execute(eq(EsqlResolveFieldsAction.TYPE), any(), any()); - var planExecutor = new PlanExecutor(indexResolver, MeterRegistry.NOOP, new XPackLicenseState(() -> 0L), mockSlowLog()); + var planExecutor = new PlanExecutor(indexResolver, MeterRegistry.NOOP, new XPackLicenseState(() -> 0L), mockQueryLog()); var enrichResolver = mockEnrichResolver(); var request = new EsqlQueryRequest(); From fd85f06a8e237fb4d2cac82afea024ac62f00b4c Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Mon, 17 Mar 2025 10:56:18 +0100 Subject: [PATCH 18/19] Simplify cluster settings --- .../xpack/esql/action/EsqlQueryLogIT.java | 8 +++---- .../xpack/esql/plugin/EsqlPlugin.java | 24 +++++++++---------- .../xpack/esql/querylog/EsqlQueryLog.java | 16 ++++++------- .../esql/querylog/EsqlQueryLogTests.java | 16 ++++++------- .../telemetry/PlanExecutorMetricsTests.java | 8 +++---- 5 files changed, 36 insertions(+), 36 deletions(-) diff --git a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlQueryLogIT.java b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlQueryLogIT.java index bdbb4b9c67e12..60df31b1ab715 100644 --- a/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlQueryLogIT.java +++ b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlQueryLogIT.java @@ -83,13 +83,13 @@ public void testSetLevel() throws Exception { Map levels = Map.of( Level.WARN, - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING.getKey(), + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_WARN_SETTING.getKey(), Level.INFO, - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING.getKey(), + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_INFO_SETTING.getKey(), Level.DEBUG, - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_DEBUG_SETTING.getKey(), Level.TRACE, - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey() + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING.getKey() ); testAllLevels( levels, diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java index ce2210b444ddc..56773005edd5c 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java @@ -110,8 +110,8 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); - public static final Setting ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING = Setting.timeSetting( - "esql.querylog.threshold.query.warn", + public static final Setting ESQL_QUERYLOG_THRESHOLD_WARN_SETTING = Setting.timeSetting( + "esql.querylog.threshold.warn", TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), @@ -119,8 +119,8 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); - public static final Setting ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING = Setting.timeSetting( - "esql.querylog.threshold.query.info", + public static final Setting ESQL_QUERYLOG_THRESHOLD_INFO_SETTING = Setting.timeSetting( + "esql.querylog.threshold.info", TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), @@ -128,8 +128,8 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); - public static final Setting ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING = Setting.timeSetting( - "esql.querylog.threshold.query.debug", + public static final Setting ESQL_QUERYLOG_THRESHOLD_DEBUG_SETTING = Setting.timeSetting( + "esql.querylog.threshold.debug", TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), @@ -137,8 +137,8 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); - public static final Setting ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING = Setting.timeSetting( - "esql.querylog.threshold.query.trace", + public static final Setting ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING = Setting.timeSetting( + "esql.querylog.threshold.trace", TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(-1), TimeValue.timeValueMillis(Integer.MAX_VALUE), @@ -211,10 +211,10 @@ public List> getSettings() { QUERY_RESULT_TRUNCATION_DEFAULT_SIZE, QUERY_RESULT_TRUNCATION_MAX_SIZE, QUERY_ALLOW_PARTIAL_RESULTS, - ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING, - ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING, - ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING, - ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING, + ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING, + ESQL_QUERYLOG_THRESHOLD_DEBUG_SETTING, + ESQL_QUERYLOG_THRESHOLD_INFO_SETTING, + ESQL_QUERYLOG_THRESHOLD_WARN_SETTING, ESQL_QUERYLOG_INCLUDE_USER_SETTING ); } diff --git a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLog.java b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLog.java index ff2a6ed8c73e4..cd410c8eba804 100644 --- a/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLog.java +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLog.java @@ -23,10 +23,10 @@ import java.util.function.Supplier; import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_INCLUDE_USER_SETTING; -import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING; -import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING; -import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING; -import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_DEBUG_SETTING; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_INFO_SETTING; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING; +import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_WARN_SETTING; public final class EsqlQueryLog { @@ -53,10 +53,10 @@ public final class EsqlQueryLog { private volatile boolean includeUser; public EsqlQueryLog(ClusterSettings settings, SlowLogFieldProvider slowLogFieldProvider) { - settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING, this::setQueryWarnThreshold); - settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING, this::setQueryInfoThreshold); - settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING, this::setQueryDebugThreshold); - settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING, this::setQueryTraceThreshold); + settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_WARN_SETTING, this::setQueryWarnThreshold); + settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_INFO_SETTING, this::setQueryInfoThreshold); + settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_DEBUG_SETTING, this::setQueryDebugThreshold); + settings.initializeAndWatch(ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING, this::setQueryTraceThreshold); settings.initializeAndWatch(ESQL_QUERYLOG_INCLUDE_USER_SETTING, this::setIncludeUser); this.additionalFields = slowLogFieldProvider.create(); diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLogTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLogTests.java index 221fbf5b41d30..add3bf77efb00 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLogTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLogTests.java @@ -47,19 +47,19 @@ public class EsqlQueryLogTests extends ESTestCase { private static ClusterSettings settings = new ClusterSettings( Settings.builder() - .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING.getKey(), "40ms") - .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING.getKey(), "30ms") - .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), "20ms") - .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey(), "10ms") + .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_WARN_SETTING.getKey(), "40ms") + .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_INFO_SETTING.getKey(), "30ms") + .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_DEBUG_SETTING.getKey(), "20ms") + .put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING.getKey(), "10ms") .put(EsqlPlugin.ESQL_QUERYLOG_INCLUDE_USER_SETTING.getKey(), true) .build(), new HashSet<>( Arrays.asList( - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING, - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING, - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING, - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_WARN_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_INFO_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_DEBUG_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING, EsqlPlugin.ESQL_QUERYLOG_INCLUDE_USER_SETTING ) ) diff --git a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java index 55cd56186d767..36b810be72642 100644 --- a/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java @@ -92,10 +92,10 @@ EsqlQueryLog mockQueryLog() { Settings.EMPTY, new HashSet<>( Arrays.asList( - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_WARN_SETTING, - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_INFO_SETTING, - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_DEBUG_SETTING, - EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_QUERY_TRACE_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_WARN_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_INFO_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_DEBUG_SETTING, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING, EsqlPlugin.ESQL_QUERYLOG_INCLUDE_USER_SETTING ) ) From 03dbacd217334e3e25f4b7acafe19aac5c08fa28 Mon Sep 17 00:00:00 2001 From: Luigi Dell'Aquila Date: Tue, 18 Mar 2025 09:25:43 +0100 Subject: [PATCH 19/19] fix log4j config --- distribution/src/config/log4j2.properties | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/distribution/src/config/log4j2.properties b/distribution/src/config/log4j2.properties index 3a393bbc7618c..7234a0d4ceb2f 100644 --- a/distribution/src/config/log4j2.properties +++ b/distribution/src/config/log4j2.properties @@ -150,5 +150,5 @@ appender.esql_querylog_rolling.strategy.max = 4 logger.esql_querylog_rolling.name = esql.querylog logger.esql_querylog_rolling.level = trace -logger.esql_querylog_rolling.appenderRef.index_search_querylog_rolling.ref = esql_querylog_rolling +logger.esql_querylog_rolling.appenderRef.esql_querylog_rolling.ref = esql_querylog_rolling logger.esql_querylog_rolling.additivity = false