ESQL: Log queries at debug level (#108257)

Previously we were logging all ESQL queries. That's a lot! Plus maybe
there's PII in there or something. Let's not do that unless you ask for
it. This changes the query logging to the `debug` log level you can
still get at these if you want them, but you don't have them by default.
you have to turn it on.
This commit is contained in:
Nik Everett 2024-05-06 11:19:02 -04:00 committed by GitHub
parent 0378a77b43
commit d8d25ebdd7
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
5 changed files with 75 additions and 8 deletions

View file

@ -0,0 +1,5 @@
pr: 108257
summary: "ESQL: Log queries at debug level"
area: ES|QL
type: enhancement
issues: []

View file

@ -14,15 +14,18 @@ import org.elasticsearch.Build;
import org.elasticsearch.client.Request;
import org.elasticsearch.client.Response;
import org.elasticsearch.client.ResponseException;
import org.elasticsearch.common.io.Streams;
import org.elasticsearch.common.settings.Settings;
import org.elasticsearch.test.TestClustersThreadFilter;
import org.elasticsearch.test.cluster.ElasticsearchCluster;
import org.elasticsearch.test.cluster.LogType;
import org.elasticsearch.xpack.esql.qa.rest.RestEsqlTestCase;
import org.hamcrest.Matchers;
import org.junit.Assert;
import org.junit.ClassRule;
import java.io.IOException;
import java.io.InputStream;
import java.nio.charset.StandardCharsets;
import java.util.Arrays;
import java.util.List;
@ -31,6 +34,7 @@ import java.util.Map;
import static org.hamcrest.Matchers.containsString;
import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.not;
import static org.hamcrest.core.Is.is;
@ThreadLeakFilters(filters = TestClustersThreadFilter.class)
@ -105,6 +109,58 @@ public class RestEsqlIT extends RestEsqlTestCase {
assertThat(EntityUtils.toString(re.getResponse().getEntity()), containsString("[pragma] only allowed in snapshot builds"));
}
public void testDoNotLogWithInfo() throws IOException {
try {
setLoggingLevel("INFO");
RequestObjectBuilder builder = requestObjectBuilder().query("ROW DO_NOT_LOG_ME = 1");
Map<String, Object> result = runEsql(builder);
assertEquals(2, result.size());
Map<String, String> colA = Map.of("name", "DO_NOT_LOG_ME", "type", "integer");
assertEquals(List.of(colA), result.get("columns"));
assertEquals(List.of(List.of(1)), result.get("values"));
try (InputStream log = cluster.getNodeLog(0, LogType.SERVER)) {
Streams.readAllLines(log, line -> { assertThat(line, not(containsString("DO_NOT_LOG_ME"))); });
}
} finally {
setLoggingLevel(null);
}
}
public void testDoLogWithDebug() throws IOException {
try {
setLoggingLevel("DEBUG");
RequestObjectBuilder builder = requestObjectBuilder().query("ROW DO_LOG_ME = 1");
Map<String, Object> result = runEsql(builder);
assertEquals(2, result.size());
Map<String, String> colA = Map.of("name", "DO_LOG_ME", "type", "integer");
assertEquals(List.of(colA), result.get("columns"));
assertEquals(List.of(List.of(1)), result.get("values"));
try (InputStream log = cluster.getNodeLog(0, LogType.SERVER)) {
boolean[] found = new boolean[] { false };
Streams.readAllLines(log, line -> {
if (line.contains("DO_LOG_ME")) {
found[0] = true;
}
});
assertThat(found[0], equalTo(true));
}
} finally {
setLoggingLevel(null);
}
}
private void setLoggingLevel(String level) throws IOException {
Request request = new Request("PUT", "/_cluster/settings");
request.setJsonEntity("""
{
"persistent": {
"logger.org.elasticsearch.xpack.esql.action": $LEVEL$
}
}
""".replace("$LEVEL$", level == null ? "null" : '"' + level + '"'));
client().performRequest(request);
}
public void testIncompatibleMappingsErrors() throws IOException {
// create first index
Request request = new Request("PUT", "/index1");

View file

@ -154,13 +154,20 @@ public final class EsqlResponseListener extends RestRefCountedChunkedToXContentL
}
/**
* Log the execution time and query when handling an ES|QL response.
* Log internal server errors all the time and log queries if debug is enabled.
*/
public ActionListener<EsqlQueryResponse> wrapWithLogging() {
ActionListener<EsqlQueryResponse> listener = ActionListener.wrap(this::onResponse, ex -> {
logOnFailure(LOGGER, ex);
onFailure(ex);
});
if (LOGGER.isDebugEnabled() == false) {
return listener;
}
return ActionListener.wrap(r -> {
onResponse(r);
listener.onResponse(r);
// At this point, the StopWatch should already have been stopped, so we log a consistent time.
LOGGER.info(
LOGGER.debug(
"Finished execution of ESQL query.\nQuery string: [{}]\nExecution time: [{}]ms",
esqlQuery,
stopWatch.stop().getMillis()
@ -168,9 +175,8 @@ public final class EsqlResponseListener extends RestRefCountedChunkedToXContentL
}, ex -> {
// In case of failure, stop the time manually before sending out the response.
long timeMillis = stopWatch.stop().getMillis();
LOGGER.info("Failed execution of ESQL query.\nQuery string: [{}]\nExecution time: [{}]ms", esqlQuery, timeMillis);
logOnFailure(LOGGER, ex);
onFailure(ex);
LOGGER.debug("Failed execution of ESQL query.\nQuery string: [{}]\nExecution time: [{}]ms", esqlQuery, timeMillis);
listener.onFailure(ex);
});
}
}

View file

@ -47,7 +47,7 @@ public class RestEsqlAsyncQueryAction extends BaseRestHandler {
}
RestEsqlQueryAction.defaultVersionForOldClients(esqlRequest, request);
LOGGER.info("Beginning execution of ESQL async query.\nQuery string: [{}]", esqlRequest.query());
LOGGER.debug("Beginning execution of ESQL async query.\nQuery string: [{}]", esqlRequest.query());
return channel -> {
RestCancellableNodeClient cancellableClient = new RestCancellableNodeClient(client, request.getHttpChannel());

View file

@ -47,7 +47,7 @@ public class RestEsqlQueryAction extends BaseRestHandler {
}
defaultVersionForOldClients(esqlRequest, request);
LOGGER.info("Beginning execution of ESQL query.\nQuery string: [{}]", esqlRequest.query());
LOGGER.debug("Beginning execution of ESQL query.\nQuery string: [{}]", esqlRequest.query());
return channel -> {
RestCancellableNodeClient cancellableClient = new RestCancellableNodeClient(client, request.getHttpChannel());