Implement review suggestions

Author: luigidellaquila

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

@@ -10,13 +10,10 @@
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
-import org.elasticsearch.action.admin.cluster.settings.ClusterUpdateSettingsAction;
-import org.elasticsearch.action.admin.cluster.settings.ClusterUpdateSettingsRequest;
 import org.elasticsearch.common.logging.ESLogMessage;
 import org.elasticsearch.common.logging.Loggers;
 import org.elasticsearch.common.logging.MockAppender;
 import org.elasticsearch.common.settings.Settings;
-import org.elasticsearch.core.TimeValue;
 import org.elasticsearch.core.Tuple;
 import org.elasticsearch.xpack.esql.plugin.EsqlPlugin;
 import org.elasticsearch.xpack.esql.querylog.EsqlQueryLog;
@@ -68,6 +65,11 @@ protected boolean reuseClusters() {
         return false;
     }
 
+    @Override
+    protected Settings nodeSettings() {
+        return Settings.builder().put(super.nodeSettings()).put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING.getKey(), "0ms").build();
+    }
+
     /**
      * Tests that query logging works correctly when all remote clusters are unavailable
      * with skip_unavailable=true. This reproduces issue #142915 where NPE occurred due to
@@ -78,8 +80,6 @@ public void testQueryLoggingWithAllRemotesUnavailable() throws Exception {
         setupClusters(numClusters);
         setSkipUnavailable(REMOTE_CLUSTER_1, true);
 
-        enableQueryLogging();
-
         try {
             cluster(REMOTE_CLUSTER_1).close();
 
@@ -106,7 +106,6 @@ public void testQueryLoggingWithAllRemotesUnavailable() throws Exception {
                 assertQueryLogged(query);
             }
         } finally {
-            disableQueryLogging();
             clearSkipUnavailable(numClusters);
         }
     }
@@ -122,8 +121,6 @@ public void testQueryLoggingWithPartialRemoteFailure() throws Exception {
         setSkipUnavailable(REMOTE_CLUSTER_1, true);
         setSkipUnavailable(REMOTE_CLUSTER_2, true);
 
-        enableQueryLogging();
-
         try {
             cluster(REMOTE_CLUSTER_1).close();
 
@@ -160,7 +157,6 @@ public void testQueryLoggingWithPartialRemoteFailure() throws Exception {
                 assertQueryLogged(query);
             }
         } finally {
-            disableQueryLogging();
             clearSkipUnavailable(numClusters);
         }
     }
@@ -175,8 +171,6 @@ public void testQueryLoggingWithAllRemotesUnavailableLocalSucceeds() throws Exce
         setSkipUnavailable(REMOTE_CLUSTER_1, true);
         setSkipUnavailable(REMOTE_CLUSTER_2, true);
 
-        enableQueryLogging();
-
         try {
             cluster(REMOTE_CLUSTER_1).close();
             cluster(REMOTE_CLUSTER_2).close();
@@ -210,29 +204,10 @@ public void testQueryLoggingWithAllRemotesUnavailableLocalSucceeds() throws Exce
                 assertQueryLogged(query);
             }
         } finally {
-            disableQueryLogging();
             clearSkipUnavailable(numClusters);
         }
     }
 
-    private void enableQueryLogging() throws Exception {
-        client(LOCAL_CLUSTER).execute(
-            ClusterUpdateSettingsAction.INSTANCE,
-            new ClusterUpdateSettingsRequest(TimeValue.THIRTY_SECONDS, TimeValue.THIRTY_SECONDS).persistentSettings(
-                Settings.builder().put(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING.getKey(), "0ms")
-            )
-        ).get();
-    }
-
-    private void disableQueryLogging() throws Exception {
-        client(LOCAL_CLUSTER).execute(
-            ClusterUpdateSettingsAction.INSTANCE,
-            new ClusterUpdateSettingsRequest(TimeValue.THIRTY_SECONDS, TimeValue.THIRTY_SECONDS).persistentSettings(
-                Settings.builder().putNull(EsqlPlugin.ESQL_QUERYLOG_THRESHOLD_TRACE_SETTING.getKey())
-            )
-        ).get();
-    }
-
     private void assertQueryLogged(String expectedQuery) {
         assertThat("Query should have been logged", appender.lastEvent(), is(notNullValue()));
         var msg = (ESLogMessage) appender.lastMessage();

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

@@ -172,7 +172,7 @@ public IncludeExecutionMetadata includeExecutionMetadata() {
      */
     public void markEndQuery() {
         if (isMainPlan()) {
-            queryProfile.stop();
+            queryProfile.stopAllStartedMarkers();
         }
     }
 

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

@@ -65,6 +65,13 @@ public TimeValue timeTook() {
         return timeSpan == null ? null : timeSpan.toTimeValue();
     }
 
+    /**
+     * Returns true if this marker was started (regardless of whether it was stopped).
+     */
+    public boolean wasStarted() {
+        return timeSpanBuilder != null;
+    }
+
     public TimeValue timeSinceStarted() {
         return timeSpanBuilder != null ? timeSpanBuilder.stop().toTimeValue() : TimeValue.ZERO;
     }

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

@@ -145,7 +145,8 @@ private static void addResultFields(Map<String, Object> fieldMap, Result esqlRes
             for (TimeSpanMarker timeSpanMarker : esqlQueryProfile.timeSpanMarkers()) {
                 TimeValue timeTook = timeSpanMarker.timeTook();
                 if (timeTook == null) {
-                    logger.error("TimeSpanMarker [{}] was not stopped", timeSpanMarker.name());
+                    assert timeSpanMarker.wasStarted() == false
+                        : "TimeSpanMarker [" + timeSpanMarker.name() + "] was started but not stopped before query logging";
                     continue;
                 }
                 String namePrefix = ELASTICSEARCH_QUERYLOG_PREFIX + timeSpanMarker.name();

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

@@ -137,7 +137,6 @@ static boolean returnSuccessWithEmptyResult(EsqlExecutionInfo executionInfo, Exc
     static void updateExecutionInfoToReturnEmptyResult(EsqlExecutionInfo executionInfo, Exception e) {
         // This applies even for subplans - if we had an error and have to skip a cluster, then it will remain skipped.
         executionInfo.markEndQuery();
-        executionInfo.queryProfile().stopAllStartedMarkers();
         Exception exceptionForResponse;
         if (e instanceof ConnectTransportException) {
             // when field-caps has no field info (since no clusters could be connected to or had matching indices)

x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/querylog/EsqlQueryLogTests.java

@@ -212,44 +212,4 @@ private static TimeSpan randomTimeSpan() {
         return new TimeSpan(startNanos / 1_000_000, startNanos, stopNanos / 1_000_000, stopNanos);
     }
 
-    /**
-     * Tests that query logging does not throw NPE when some TimeSpanMarkers have null timeTook values.
-     * This can happen in scenarios like CCS queries where a remote cluster is unavailable.
-     * See <a href="https://github.com/elastic/elasticsearch/issues/142915">issue #142915</a>.
-     */
-    public void testQueryLoggingWithNullTimeSpanMarkers() {
-        EsqlQueryLog queryLog = new EsqlQueryLog(settings, mockLogFieldProvider());
-        String query = "from " + randomAlphaOfLength(10);
-
-        long tookNanos = randomLongBetween(40_000_000, 50_000_000);
-        EsqlExecutionInfo executionInfo = getEsqlExecutionInfoWithNullTimeSpans(tookNanos);
-        queryLog.onQueryPhase(
-            new Versioned<>(
-                new Result(List.of(), List.of(), EsqlTestUtils.TEST_CFG, DriverCompletionInfo.EMPTY, executionInfo),
-                TransportVersion.current()
-            ),
-            query
-        );
-
-        assertThat(appender.lastEvent(), is(not(nullValue())));
-        var msg = (ESLogMessage) appender.lastMessage();
-        long took = Long.valueOf(msg.get(ELASTICSEARCH_QUERYLOG_TOOK));
-        assertThat(took, is(tookNanos));
-        assertThat(msg.get(ELASTICSEARCH_QUERYLOG_QUERY), is(query));
-        assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.WARN));
-    }
-
-    private static EsqlExecutionInfo getEsqlExecutionInfoWithNullTimeSpans(long tookNanos) {
-        return new EsqlExecutionInfo(Predicates.always(), EsqlExecutionInfo.IncludeExecutionMetadata.CCS_ONLY) {
-            @Override
-            public TimeValue overallTook() {
-                return new TimeValue(tookNanos, TimeUnit.NANOSECONDS);
-            }
-
-            @Override
-            public EsqlQueryProfile queryProfile() {
-                return new EsqlQueryProfile(null, null, null, null, null, null, 0);
-            }
-        };
-    }
 }