ES|QL query log by luigidellaquila · Pull Request #124094 · elastic/elasticsearch

luigidellaquila · 2025-03-05T13:05:41Z

Adding Query Log to ES|QL.

It can be configured at cluster level, using the following cluster settings (TimeValue):

esql.querylog.threshold.trace    // time period, threshold to log the query at trace level, -1 by default (disabled)
esql.querylog.threshold.debug   // time period, threshold to log the query at debug level, -1 by default (disabled)
esql.querylog.threshold.info    // time period, threshold to log the query at info level, -1 by default (disabled)
esql.querylog.threshold.warn     // time period, threshold to log the query at warn level, -1 by default (disabled)
esql.querylog.include.user    // include user data, false by default

By default, queries will be logged to

logs/runTask_esql_querylog.json

Example log in case of success:

{
    "@timestamp": "2025-03-11T08:39:50.076Z",
    "log.level": "TRACE",
    "auth.type": "REALM",
    "elasticsearch.querylog.planning.took": 3108666,
    "elasticsearch.querylog.planning.took_millis": 3,
    "elasticsearch.querylog.query": "from index | limit 100",
    "elasticsearch.querylog.search_type": "ESQL",
    "elasticsearch.querylog.success": true,
    "elasticsearch.querylog.took": 8050416,
    "elasticsearch.querylog.took_millis": 8,
    "user.name": "elastic-admin",
    "user.realm": "default_file",
    "ecs.version": "1.2.0",
    "service.name": "ES_ECS",
    "event.dataset": "elasticsearch.esql_querylog",
    "process.thread.name": "elasticsearch[runTask-0][esql_worker][T#12]",
    "log.logger": "esql.querylog.query",
    "elasticsearch.cluster.uuid": "KZo1V7TcQM-O6fnqMm1t_g",
    "elasticsearch.node.id": "uPgRE2TrSfa9IvnUpNT1Uw",
    "elasticsearch.node.name": "runTask-0",
    "elasticsearch.cluster.name": "runTask"
}

Example log in case of failure:

{
    "@timestamp": "2025-03-11T08:41:54.172Z",
    "log.level": "TRACE",
    "auth.type": "REALM",
    "elasticsearch.querylog.error.message": "line 1:15: mismatched input 'limitxyz' expecting {DEV_CHANGE_POINT, 'enrich', 'dissect', 'eval', 'grok', 'limit', 'sort', 'stats', 'where', DEV_INLINESTATS, DEV_FORK, 'lookup', DEV_JOIN_LEFT, DEV_JOIN_RIGHT, DEV_LOOKUP, 'mv_expand', 'drop', 'keep', DEV_INSIST, 'rename'}",
    "elasticsearch.querylog.error.type": "org.elasticsearch.xpack.esql.parser.ParsingException",
    "elasticsearch.querylog.query": "from person | limitxyz 100",
    "elasticsearch.querylog.search_type": "ESQL",
    "elasticsearch.querylog.success": false,
    "elasticsearch.querylog.took": 963750,
    "elasticsearch.querylog.took_millis": 0,
    "user.name": "elastic-admin",
    "user.realm": "default_file",
    "ecs.version": "1.2.0",
    "service.name": "ES_ECS",
    "event.dataset": "elasticsearch.esql_querylog",
    "process.thread.name": "elasticsearch[runTask-0][search][T#16]",
    "log.logger": "esql.querylog.query",
    "elasticsearch.cluster.uuid": "KZo1V7TcQM-O6fnqMm1t_g",
    "elasticsearch.node.id": "uPgRE2TrSfa9IvnUpNT1Uw",
    "elasticsearch.node.name": "runTask-0",
    "elasticsearch.cluster.name": "runTask"
}

TODO

docs

idegtiarenko · 2025-03-06T09:43:18Z

x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java

+
+        private static Map<String, Object> prepareMap(Result esqlResult, String query) {
+            Map<String, Object> messageFields = new HashMap<>();
+            messageFields.put("elasticsearch.slowlog.message", esqlResult.executionInfo().clusterAliases());


This looks a bit surprising, message contains cluster aliases, is it intentional?

I'm not sure we need that at all.
SearchSlowLog has searchContext.indexShard().shardId() in there, maybe we want something different

I'm removing it for now, in case we'll reintroduce it

idegtiarenko · 2025-03-06T09:45:08Z

x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java

+            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);


I think source is a bit ambiguous. Should we call it query here?

Yeah, I don't like it very much, query would be much better.
I'm using source only because it's what Search does, but I'm not sure we want to be consistent with it

I thought about this, source for _search is the actual request body, while in our case it's only the query string.
I'll rename it as "query" for now.

idegtiarenko · 2025-03-06T09:48:42Z

x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java

+            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();


NIT: org.elasticsearch.common.settings.Setting#get logic is a bit tricky.
We should copy the value to the field and watch for updates using org.elasticsearch.common.settings.AbstractScopedSettings#initializeAndWatch

idegtiarenko · 2025-03-06T09:51:42Z

...gin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java

+        final String node1, node2;
+        if (randomBoolean()) {
+            internalCluster().ensureAtLeastNumDataNodes(2);
+            node1 = randomDataNode().getName();
+            node2 = randomValueOtherThan(node1, () -> randomDataNode().getName());
+        } else {
+            node1 = randomDataNode().getName();
+            node2 = randomDataNode().getName();
+        }


Seems unused

ivancea

Looks good! Added some comments/questions

ivancea · 2025-03-06T10:13:20Z

x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/plugin/EsqlPlugin.java

+        TimeValue.timeValueNanos(-1),
+        TimeValue.timeValueMillis(-1),


Is there some reason for the default to be -1ns instead of -1ms? I guess both would work the same, right?

I think it's the same. let me change it

ivancea · 2025-03-06T10:16:14Z

x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/session/EsqlCCSUtils.java

        // 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();


Was this a bug? Was it working when not CCS?

Not really.
This method was introduced with CCS implementation, and planningTookTime was only used in that contex.
Now we need it also for other purposes, so I'll set it also for non-CCS queries.

ivancea · 2025-03-06T10:45:02Z

...gin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/EsqlSlowLogIT.java

+                    latch.countDown();
+                }
+            }));
+            latch.await(30, TimeUnit.SECONDS);


Are we failing the test if the countdown isn't 0? I think await() does nothing about it, right?
Not sure what will happen here exactly if the query fails.

I see other test doing an assert like:

assertEquals("All requests must respond, requests: " + requests, 0, latch.getCount());

Please use safeAwait(latch); instead. It should handle correctly the cases when operation times out.

I see other test doing an assert like:

One more assert won't hurt, I'm adding it.

ivancea · 2025-03-06T10:49:52Z

x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java

+
+    private static final Logger queryLogger = LogManager.getLogger(SLOWLOG_PREFIX + ".query");
+
+    private static final ToXContent.Params FORMAT_PARAMS = new ToXContent.MapParams(Collections.singletonMap("pretty", "false"));


Are we using this?

elasticsearchmachine · 2025-03-07T15:46:38Z

Pinging @elastic/es-analytical-engine (Team:Analytics)

elasticsearchmachine · 2025-03-07T15:46:38Z

Hi @luigidellaquila, I've created a changelog YAML for you.

…/slowlog

costin

Left some comments.
It would be really useful to see an example of what the esql slow logs looks like (I assume it will be part of the doc).

costin · 2025-03-10T19:34:07Z

x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/execution/PlanExecutor.java

            planTelemetryManager.publish(planTelemetry, true);
+            slowLog.onQueryPhase(x, request.query());


To help with encapsulation, please create two internal methods called when the query is successfully executed or is failing and move the metrics, telemetry and now the slow log there (e.g. onQuerySuccesful(), onQueryFailure())

costin · 2025-03-10T19:36:16Z

x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java

+        this(settings, null);
+    }
+
+    public void onQueryPhase(Result esqlResult, String query) {


This method and onQueryFailure are very similar - same code should be reused across both of them.

costin · 2025-03-10T19:43:46Z

x-pack/plugin/esql/src/main/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLog.java

+            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<String, Object> prepareMap(Result esqlResult, String query, boolean success, User user) {
+            Map<String, Object> 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());
+                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;


Extract constants out of these repetitive strings including during their construction, such as the common prefix ("elasticsearch.slowlog")

Also there's a repetition on took/took_millis, which seems to be overridden always in of method.

luigidellaquila · 2025-03-11T10:25:08Z

Thanks for the feedback folks!

@costin I added two examples of slow log output to the PR description.
Docs will need a separate PR on https://github.com/elastic/docs-content

jfreden

Looks good! Just a comment on combining the SlowLogFieldProviders.

jfreden · 2025-03-14T14:58:54Z

...ity/src/main/java/org/elasticsearch/xpack/security/slowlog/SecuritySlowLogFieldProvider.java

        }
+
+        @Override
+        public Map<String, String> queryFields() {


jfreden · 2025-03-14T15:08:22Z

server/src/main/java/org/elasticsearch/node/NodeConstruction.java

-                    return fields.stream()
-                        .flatMap(f -> f.indexFields().entrySet().stream())
-                        .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue));
+        SlowLogFieldProvider slowLogFieldProvider = new SlowLogFieldProvider() {


The point of this is that it will merge all field providers provided by the plugins into one (in practice I think that's only the one in the security plugin). So this should ideally have an implementation for merging queryFields too and then this instance should be passed to the PluginService (instead of the list of providers).

If you don't want to implement the merge for indexFields and searchFields in the provider without index settings you could add an empty default implementation in the interface in the same way you did for queryFields.

jfreden

Thanks for implementing the suggested changes. LGTM pending CI and the comment I left above.

…/slowlog

luigidellaquila · 2025-03-14T15:30:48Z

Thanks @jfreden!

…/slowlog

luigidellaquila · 2025-03-17T09:44:25Z

SlowLog -> QueryLog

The intention is to make it more generic in the future, so that we can log queries not based on the execution time, but also based on other criteria.

luigidellaquila · 2025-03-18T10:51:14Z

Docs PR here elastic/docs-content#816

elasticsearchmachine · 2025-03-18T15:33:23Z

💔 Backport failed

Status	Branch	Result
❌	8.x	Commit could not be cherrypicked due to conflicts

You can use sqren/backport to manually backport by running backport --upstream elastic/elasticsearch --pr 124094

ES|QL slow log

dca56b5

elasticsearchmachine added the v9.1.0 label Mar 5, 2025

[CI] Auto commit changes from spotless

e725e07

idegtiarenko reviewed Mar 6, 2025

View reviewed changes

idegtiarenko approved these changes Mar 6, 2025

View reviewed changes

ivancea reviewed Mar 6, 2025

View reviewed changes

luigidellaquila added 6 commits March 7, 2025 11:38

Merge branch 'main' into esql/slowlog

4746cd4

First round of reviews

d4ed58f

Fix test

8957918

Add slowlog for failing queries

6e0b9c5

Cleanup

4d25aaa

Cleanup

45764f4

luigidellaquila marked this pull request as ready for review March 7, 2025 15:45

luigidellaquila requested a review from a team as a code owner March 7, 2025 15:45

luigidellaquila added :Analytics/ES|QL AKA ESQL >enhancement labels Mar 7, 2025

elasticsearchmachine added the Team:Analytics Meta label for analytical engine team (ESQL/Aggs/Geo) label Mar 7, 2025

Update docs/changelog/124094.yaml

b2ae5ef

luigidellaquila added 4 commits March 10, 2025 11:02

Merge branch 'main' into esql/slowlog

2eb589a

Add unit tests

cbfcf2c

Merge remote-tracking branch 'luigidellaquila/esql/slowlog' into esql…

51820c9

…/slowlog

Add user name to slow log; some refactoring

d2bd672

costin reviewed Mar 10, 2025

View reviewed changes

Implement review suggestions

b74ea91

Merge branch 'main' into esql/slowlog

bbc11c5

jfreden reviewed Mar 14, 2025

View reviewed changes

jfreden approved these changes Mar 14, 2025

View reviewed changes

luigidellaquila added 2 commits March 14, 2025 16:29

Merge log field providers

e390232

Merge remote-tracking branch 'luigidellaquila/esql/slowlog' into esql…

694ff2e

…/slowlog

elasticsearchmachine and others added 6 commits March 14, 2025 15:38

[CI] Auto commit changes from spotless

cec182e

Merge branch 'main' into esql/slowlog

44ea6fc

Fix tests

df788db

Merge remote-tracking branch 'luigidellaquila/esql/slowlog' into esql…

a970fc5

…/slowlog

Merge branch 'main' into esql/slowlog

e4202af

Rename as QueryLog

01d4c66

luigidellaquila changed the title ~~ES|QL slow log~~ ES|QL query log Mar 17, 2025

luigidellaquila added 3 commits March 17, 2025 10:56

Simplify cluster settings

fd85f06

fix log4j config

03dbacd

Merge branch 'main' into esql/slowlog

6cdb1b3

luigidellaquila added v8.19.0 auto-backport Automatically create backport pull requests when merged labels Mar 18, 2025

luigidellaquila merged commit f3ed9b3 into elastic:main Mar 18, 2025
17 checks passed

elasticsearchmachine added the backport pending label Mar 18, 2025

luigidellaquila added a commit to luigidellaquila/elasticsearch that referenced this pull request Mar 18, 2025

ES|QL query log (elastic#124094)

ea8008a

luigidellaquila mentioned this pull request Mar 18, 2025

ES|QL query log (#124094) #125120

Merged

elasticsearchmachine pushed a commit that referenced this pull request Mar 18, 2025

ES|QL query log (#124094) (#125120)

fdf062b

omricohenn pushed a commit to omricohenn/elasticsearch that referenced this pull request Mar 28, 2025

ES|QL query log (elastic#124094)

658b548

This was referenced Apr 1, 2025

[Filebeat] Create new data set for ES|QL query logs elastic/beats#43622

Open

[Elasticsearch]: Create new data set for ES|QL query logs elastic/integrations#13374

Open

nik9000 mentioned this pull request Apr 7, 2025

ESQL: Slow logs #107698

Closed


		private static final Logger queryLogger = LogManager.getLogger(SLOWLOG_PREFIX + ".query");

		private static final ToXContent.Params FORMAT_PARAMS = new ToXContent.MapParams(Collections.singletonMap("pretty", "false"));

		planTelemetryManager.publish(planTelemetry, true);
		slowLog.onQueryPhase(x, request.query());

Comments

Conversation

luigidellaquila commented Mar 5, 2025 • edited by tylerperk Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

luigidellaquila Mar 6, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ivancea left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

elasticsearchmachine commented Mar 7, 2025

Uh oh!

elasticsearchmachine commented Mar 7, 2025

Uh oh!

costin left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

luigidellaquila commented Mar 11, 2025

Uh oh!

jfreden left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jfreden left a comment

Choose a reason for hiding this comment

Uh oh!

luigidellaquila commented Mar 14, 2025

Uh oh!

luigidellaquila commented Mar 17, 2025

Uh oh!

luigidellaquila commented Mar 18, 2025

Uh oh!

Uh oh!

elasticsearchmachine commented Mar 18, 2025

💔 Backport failed

Uh oh!

Reviewers

luigidellaquila commented Mar 5, 2025 •

edited by tylerperk

Loading

luigidellaquila Mar 6, 2025 •

edited

Loading