diff --git a/distribution/src/config/log4j2.properties b/distribution/src/config/log4j2.properties index bde4d9d17fc17..7234a0d4ceb2f 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 + + +######## 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_querylog_rolling.name = esql.querylog +logger.esql_querylog_rolling.level = trace +logger.esql_querylog_rolling.appenderRef.esql_querylog_rolling.ref = esql_querylog_rolling +logger.esql_querylog_rolling.additivity = false 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: [] 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..b0d5ebd5cea81 100644 --- a/server/src/main/java/org/elasticsearch/index/SlowLogFields.java +++ b/server/src/main/java/org/elasticsearch/index/SlowLogFields.java @@ -27,4 +27,12 @@ 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 ee21ffdc2d48b..28c18792611f1 100644 --- a/server/src/main/java/org/elasticsearch/node/NodeConstruction.java +++ b/server/src/main/java/org/elasticsearch/node/NodeConstruction.java @@ -112,6 +112,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; @@ -806,26 +807,65 @@ 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 queryFields() { + return fields.stream() + .flatMap(f -> f.queryFields().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)); + } + + @Override + public Map queryFields() { + return fields.stream() + .flatMap(f -> f.queryFields().entrySet().stream()) + .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)); + } + }; + } + }; IndicesService indicesService = new IndicesServiceBuilder().settings(settings) @@ -914,7 +954,8 @@ public Map searchFields() { dataStreamGlobalRetentionSettings, documentParsingProvider, taskManager, - projectResolver + projectResolver, + 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 01a2017544510..aeb7646524582 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; @@ -53,5 +54,6 @@ public record PluginServiceInstances( DataStreamGlobalRetentionSettings dataStreamGlobalRetentionSettings, DocumentParsingProvider documentParsingProvider, TaskManager taskManager, - ProjectResolver projectResolver + ProjectResolver projectResolver, + 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 8844597cb5d26..4a3990e3fd3c3 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(); + + /** + * Provider for additional SlowLog fields + */ + SlowLogFieldProvider slowLogFieldProvider(); } /** 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/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/qa/testFixtures/src/main/java/org/elasticsearch/xpack/esql/MockAppender.java b/x-pack/plugin/esql/qa/testFixtures/src/main/java/org/elasticsearch/xpack/esql/MockAppender.java new file mode 100644 index 0000000000000..e1a8633a01c3c --- /dev/null +++ b/x-pack/plugin/esql/qa/testFixtures/src/main/java/org/elasticsearch/xpack/esql/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; + +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(); + } + + public Message lastMessage() { + return lastEvent.getMessage(); + } + + public LogEvent lastEvent() { + return lastEvent; + } + + public LogEvent getLastEventAndReset() { + LogEvent toReturn = lastEvent; + lastEvent = null; + return toReturn; + } +} 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 new file mode 100644 index 0000000000000..60df31b1ab715 --- /dev/null +++ b/x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlQueryLogIT.java @@ -0,0 +1,227 @@ +/* + * 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.MockAppender; +import org.elasticsearch.xpack.esql.VerificationException; +import org.elasticsearch.xpack.esql.plugin.EsqlPlugin; +import org.elasticsearch.xpack.esql.querylog.EsqlQueryLog; +import org.junit.AfterClass; +import org.junit.BeforeClass; + +import java.util.Map; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutionException; + +import static org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked; +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; +import static org.hamcrest.Matchers.greaterThanOrEqualTo; +import static org.hamcrest.Matchers.is; +import static org.hamcrest.Matchers.nullValue; + +public class EsqlQueryLogIT extends AbstractEsqlIntegTestCase { + static MockAppender appender; + static Logger queryLog = LogManager.getLogger(EsqlQueryLog.LOGGER_NAME); + 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 { + 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_QUERYLOG_THRESHOLD_WARN_SETTING.getKey(), + Level.INFO, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_INFO_SETTING.getKey(), + Level.DEBUG, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_DEBUG_SETTING.getKey(), + Level.TRACE, + EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING.getKey() + ); + 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, 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, + 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, 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( + Map levels, + DiscoveryNode coordinator, + long timeoutMillis, + String query, + String expectedErrorMsg, + String expectedException + ) 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(); + request.query(query); + 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_QUERYLOG_TOOK)); + long tookMillisExpected = took / 1_000_000; + 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_QUERYLOG_PLANNING_TOOK)); + long planningTookMillisExpected = planningTook / 1_000_000; + 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_QUERYLOG_QUERY), is(query)); + assertThat(appender.getLastEventAndReset().getLevel(), equalTo(logLevel.getKey())); + + boolean success = Boolean.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_SUCCESS)); + assertThat(success, is(expectedException == null)); + if (expectedErrorMsg == null) { + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_ERROR_MESSAGE), is(nullValue())); + } else { + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_ERROR_MESSAGE), containsString(expectedErrorMsg)); + } + if (expectedException == null) { + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_ERROR_TYPE), is(nullValue())); + } else { + assertThat(msg.get(ELASTICSEARCH_QUERYLOG_ERROR_TYPE), is(expectedException)); + } + } finally { + latch.countDown(); + } + })); + + safeAwait(latch); + + assertEquals("All requests must respond", 0, latch.getCount()); + + client().execute( + ClusterUpdateSettingsAction.INSTANCE, + new ClusterUpdateSettingsRequest(TimeValue.THIRTY_SECONDS, TimeValue.THIRTY_SECONDS).persistentSettings( + Settings.builder().putNull(logLevel.getValue()) + ) + ).get(); + } + } +} 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..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,6 +22,7 @@ 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; @@ -42,8 +43,9 @@ public class PlanExecutor { private final Metrics metrics; private final Verifier verifier; private final PlanTelemetryManager planTelemetryManager; + private final EsqlQueryLog queryLog; - public PlanExecutor(IndexResolver indexResolver, MeterRegistry meterRegistry, XPackLicenseState licenseState) { + public PlanExecutor(IndexResolver indexResolver, MeterRegistry meterRegistry, XPackLicenseState licenseState, EsqlQueryLog queryLog) { 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.queryLog = queryLog; } public void esql( @@ -83,20 +86,37 @@ public void esql( QueryMetric clientId = QueryMetric.fromString("rest"); metrics.total(clientId); - ActionListener executeListener = wrap(x -> { - planTelemetryManager.publish(planTelemetry, true); - 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); - listener.onFailure(ex); - }); + var begin = System.nanoTime(); + 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); + queryLog.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); + queryLog.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 c864c4b99d6d8..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 @@ -37,6 +37,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; @@ -68,6 +69,7 @@ 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 java.lang.invoke.MethodHandles; @@ -108,6 +110,49 @@ public class EsqlPlugin extends Plugin implements ActionPlugin { Setting.Property.Dynamic ); + 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), + Setting.Property.NodeScope, + Setting.Property.Dynamic + ); + + 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), + Setting.Property.NodeScope, + Setting.Property.Dynamic + ); + + 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), + Setting.Property.NodeScope, + Setting.Property.Dynamic + ); + + 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), + Setting.Property.NodeScope, + Setting.Property.Dynamic + ); + + public static final Setting ESQL_QUERYLOG_INCLUDE_USER_SETTING = Setting.boolSetting( + "esql.querylog.include.user", + false, + Setting.Property.NodeScope, + Setting.Property.Dynamic + ); + @Override public Collection createComponents(PluginServices services) { CircuitBreaker circuitBreaker = services.indicesService().getBigArrays().breakerService().getBreaker("request"); @@ -121,7 +166,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 EsqlQueryLog(services.clusterService().getClusterSettings(), services.slowLogFieldProvider()) + ), new ExchangeService( services.clusterService().getSettings(), services.threadPool(), @@ -157,7 +207,16 @@ protected XPackLicenseState getLicenseState() { */ @Override public List> getSettings() { - return List.of(QUERY_RESULT_TRUNCATION_DEFAULT_SIZE, QUERY_RESULT_TRUNCATION_MAX_SIZE, QUERY_ALLOW_PARTIAL_RESULTS); + return List.of( + QUERY_RESULT_TRUNCATION_DEFAULT_SIZE, + QUERY_RESULT_TRUNCATION_MAX_SIZE, + QUERY_ALLOW_PARTIAL_RESULTS, + 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 + ); } @Override 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 new file mode 100644 index 0000000000000..cd410c8eba804 --- /dev/null +++ b/x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLog.java @@ -0,0 +1,153 @@ +/* + * 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.querylog; + +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.core.TimeValue; +import org.elasticsearch.index.SlowLogFieldProvider; +import org.elasticsearch.index.SlowLogFields; +import org.elasticsearch.xcontent.json.JsonStringEncoder; +import org.elasticsearch.xpack.esql.session.Result; + +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_QUERYLOG_INCLUDE_USER_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 { + + 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; + + private volatile long queryWarnThreshold; + private volatile long queryInfoThreshold; + private volatile long queryDebugThreshold; + private volatile long queryTraceThreshold; + + private volatile boolean includeUser; + + public EsqlQueryLog(ClusterSettings settings, SlowLogFieldProvider slowLogFieldProvider) { + 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(); + } + + 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(); + 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, includeUser ? additionalFields.queryFields() : Map.of()), tookInNanos); + } + + private void log(Supplier logProducer, long tookInNanos) { + if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) { + queryLogger.warn(logProducer.get()); + } else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) { + queryLogger.info(logProducer.get()); + } else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) { + queryLogger.debug(logProducer.get()); + } else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) { + queryLogger.trace(logProducer.get()); + } + } + + 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(); + } + + public void setIncludeUser(boolean includeUser) { + this.includeUser = includeUser; + } + + 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 additionalFields) { + Map jsonFields = new HashMap<>(); + 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, Map additionalFields) { + Map jsonFields = new HashMap<>(); + jsonFields.putAll(additionalFields); + addGenericFields(jsonFields, query, false); + addErrorFields(jsonFields, took, exception); + return new ESLogMessage().withFields(jsonFields); + } + + private static void addGenericFields(Map fieldMap, String query, boolean success) { + String source = escapeJson(query); + 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_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_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/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/test/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLogTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLogTests.java new file mode 100644 index 0000000000000..add3bf77efb00 --- /dev/null +++ b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLogTests.java @@ -0,0 +1,206 @@ +/* + * 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.querylog; + +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.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; +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.Map; +import java.util.concurrent.TimeUnit; + +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 EsqlQueryLogTests extends ESTestCase { + private static ClusterSettings settings = new ClusterSettings( + Settings.builder() + .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_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 + ) + ) + ); + + static MockAppender appender; + static Logger queryLog = LogManager.getLogger(EsqlQueryLog.LOGGER_NAME); + 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() { + EsqlQueryLog queryLog = new EsqlQueryLog(settings, mockFieldProvider()); + 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]); + 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_QUERYLOG_TOOK)); + long tookMillisExpected = took / 1_000_000L; + 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_QUERYLOG_PLANNING_TOOK)); + long planningTookMillisExpected = planningTook / 1_000_000; + 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_QUERYLOG_QUERY), is(query)); + assertThat(appender.getLastEventAndReset().getLevel(), equalTo(expectedLevel[i])); + } else { + assertThat(appender.lastEvent(), is(nullValue())); + } + + } + } + + 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() { + EsqlQueryLog queryLog = new EsqlQueryLog(settings, mockFieldProvider()); + 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++) { + 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_QUERYLOG_TOOK)); + long tookMillisExpected = took / 1_000_000L; + long tookMillis = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_TOOK_MILLIS)); + assertThat(took, is(actualTook[i])); + assertThat(tookMillis, is(tookMillisExpected)); + 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())); + } + } + } + + 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/telemetry/PlanExecutorMetricsTests.java b/x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java index 6c3995302767f..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 @@ -16,7 +16,12 @@ 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.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; @@ -32,6 +37,8 @@ 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.querylog.EsqlQueryLog; import org.elasticsearch.xpack.esql.session.EsqlSession; import org.elasticsearch.xpack.esql.session.IndexResolver; import org.elasticsearch.xpack.esql.session.Result; @@ -40,7 +47,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; @@ -78,6 +87,42 @@ EnrichPolicyResolver mockEnrichResolver() { return enrichResolver; } + EsqlQueryLog mockQueryLog() { + ClusterSettings clusterSettings = new ClusterSettings( + Settings.EMPTY, + new HashSet<>( + Arrays.asList( + 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 + ) + ) + ); + return new EsqlQueryLog(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() { String[] indices = new String[] { "test" }; @@ -105,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)); + var planExecutor = new PlanExecutor(indexResolver, MeterRegistry.NOOP, new XPackLicenseState(() -> 0L), mockQueryLog()); var enrichResolver = mockEnrichResolver(); var request = new EsqlQueryRequest(); 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..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,6 +33,8 @@ private class SecuritySlowLogFields implements SlowLogFields { this.includeUserInIndexing = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_INCLUDE_USER_SETTING); } + SecuritySlowLogFields() {} + @Override public Map indexFields() { if (includeUserInIndexing) { @@ -48,6 +50,11 @@ public Map searchFields() { } return Map.of(); } + + @Override + public Map queryFields() { + return plugin.getAuthContextForSlowLog(); + } } public SecuritySlowLogFieldProvider() { @@ -62,4 +69,9 @@ public SecuritySlowLogFieldProvider(Security plugin) { public SlowLogFields create(IndexSettings indexSettings) { return new SecuritySlowLogFields(indexSettings); } + + @Override + public SlowLogFields create() { + return new SecuritySlowLogFields(); + } }