Skip to content

Commit d2bd672

Browse files
luigidellaquilaluigidellaquila
committed
Add user name to slow log; some refactoring
1 parent 51820c9 commit d2bd672

File tree

7 files changed

+84
-64
lines changed

7 files changed

+84
-64
lines changed

x-pack/plugin/esql/src/internalClusterTest/java/org/elasticsearch/xpack/esql/action/MockAppender.java renamed to x-pack/plugin/esql/qa/testFixtures/src/main/java/org/elasticsearch/xpack/esql/MockAppender.java

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@
55
* 2.0.
66
*/
77

8-
package org.elasticsearch.xpack.esql.action;
8+
package org.elasticsearch.xpack.esql;
99

1010
import org.apache.logging.log4j.core.LogEvent;
1111
import org.apache.logging.log4j.core.appender.AbstractAppender;
@@ -24,11 +24,11 @@ public void append(LogEvent event) {
2424
lastEvent = event.toImmutable();
2525
}
2626

27-
Message lastMessage() {
27+
public Message lastMessage() {
2828
return lastEvent.getMessage();
2929
}
3030

31-
LogEvent lastEvent() {
31+
public LogEvent lastEvent() {
3232
return lastEvent;
3333
}
3434

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

Lines changed: 19 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@
1818
import org.elasticsearch.common.logging.Loggers;
1919
import org.elasticsearch.common.settings.Settings;
2020
import org.elasticsearch.core.TimeValue;
21+
import org.elasticsearch.xpack.esql.MockAppender;
2122
import org.elasticsearch.xpack.esql.VerificationException;
2223
import org.elasticsearch.xpack.esql.plugin.EsqlPlugin;
2324
import org.elasticsearch.xpack.esql.slowlog.EsqlSlowLog;
@@ -94,12 +95,20 @@ public void testSetLevel() throws Exception {
9495
testAllLevels(
9596
levels,
9697
coordinator,
97-
randomIntBetween(0, 10_000),
98+
randomIntBetween(0, 500),
9899
"FROM index-* | EVAL ip = to_ip(host) | STATS s = COUNT(*) by ip | KEEP ip | LIMIT 100",
99100
null,
100101
null
101102
);
102103
}
104+
testAllLevels(
105+
levels,
106+
coordinator,
107+
600_000,
108+
"FROM index-* | EVAL ip = to_ip(host) | STATS s = COUNT(*) by ip | KEEP ip | LIMIT 100",
109+
null,
110+
null
111+
);
103112

104113
testAllLevels(
105114
levels,
@@ -113,12 +122,20 @@ public void testSetLevel() throws Exception {
113122
testAllLevels(
114123
levels,
115124
coordinator,
116-
randomIntBetween(0, 10_000),
125+
randomIntBetween(0, 500),
117126
"FROM index-* | EVAL a = count(*) | LIMIT 100",
118127
"aggregate function [count(*)] not allowed outside STATS command",
119128
VerificationException.class.getName()
120129
);
121130
}
131+
testAllLevels(
132+
levels,
133+
coordinator,
134+
600_000,
135+
"FROM index-* | EVAL a = count(*) | LIMIT 100",
136+
"aggregate function [count(*)] not allowed outside STATS command",
137+
VerificationException.class.getName()
138+
);
122139
}
123140

124141
private static void testAllLevels(
@@ -163,7 +180,6 @@ private static void testAllLevels(
163180
long planningTookMillisExpected = planningTook / 1_000_000;
164181
long planningTookMillis = Long.valueOf(msg.get("elasticsearch.slowlog.planning.took_millis"));
165182
assertThat(planningTook, greaterThanOrEqualTo(0L));
166-
assertThat(planningTookMillis, greaterThanOrEqualTo(timeoutMillis));
167183
assertThat(planningTookMillis, is(planningTookMillisExpected));
168184
assertThat(took, greaterThan(planningTook));
169185
}

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

Lines changed: 14 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -51,6 +51,7 @@
5151
import org.elasticsearch.xpack.core.XPackPlugin;
5252
import org.elasticsearch.xpack.core.action.XPackInfoFeatureAction;
5353
import org.elasticsearch.xpack.core.action.XPackUsageFeatureAction;
54+
import org.elasticsearch.xpack.core.security.SecurityContext;
5455
import org.elasticsearch.xpack.esql.EsqlInfoTransportAction;
5556
import org.elasticsearch.xpack.esql.EsqlUsageTransportAction;
5657
import org.elasticsearch.xpack.esql.action.EsqlAsyncGetResultAction;
@@ -147,6 +148,13 @@ public class EsqlPlugin extends Plugin implements ActionPlugin {
147148
Setting.Property.Dynamic
148149
);
149150

151+
public static final Setting<Boolean> ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING = Setting.boolSetting(
152+
"esql.slowlog.include.user",
153+
false,
154+
Setting.Property.NodeScope,
155+
Setting.Property.Dynamic
156+
);
157+
150158
@Override
151159
public Collection<?> createComponents(Plugin.PluginServices services) {
152160
CircuitBreaker circuitBreaker = services.indicesService().getBigArrays().breakerService().getBreaker("request");
@@ -164,7 +172,10 @@ public Collection<?> createComponents(Plugin.PluginServices services) {
164172
new IndexResolver(services.client()),
165173
services.telemetryProvider().getMeterRegistry(),
166174
getLicenseState(),
167-
new EsqlSlowLog(services.clusterService().getClusterSettings())
175+
new EsqlSlowLog(
176+
services.clusterService().getClusterSettings(),
177+
new SecurityContext(Settings.EMPTY, services.threadPool().getThreadContext())
178+
)
168179
),
169180
new ExchangeService(
170181
services.clusterService().getSettings(),
@@ -208,7 +219,8 @@ public List<Setting<?>> getSettings() {
208219
ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING,
209220
ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING,
210221
ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING,
211-
ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING
222+
ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING,
223+
ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING
212224
);
213225
}
214226

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

Lines changed: 42 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -13,12 +13,15 @@
1313
import org.elasticsearch.common.settings.ClusterSettings;
1414
import org.elasticsearch.core.TimeValue;
1515
import org.elasticsearch.xcontent.json.JsonStringEncoder;
16+
import org.elasticsearch.xpack.core.security.SecurityContext;
17+
import org.elasticsearch.xpack.core.security.user.User;
1618
import org.elasticsearch.xpack.esql.session.Result;
1719

1820
import java.nio.charset.StandardCharsets;
1921
import java.util.HashMap;
2022
import java.util.Map;
2123

24+
import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING;
2225
import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING;
2326
import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING;
2427
import static org.elasticsearch.xpack.esql.plugin.EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING;
@@ -31,18 +34,28 @@ public final class EsqlSlowLog {
3134
public static final String SLOWLOG_PREFIX = "esql.slowlog";
3235

3336
private static final Logger queryLogger = LogManager.getLogger(SLOWLOG_PREFIX + ".query");
37+
private final SecurityContext security;
3438

3539
private volatile long queryWarnThreshold;
3640
private volatile long queryInfoThreshold;
3741
private volatile long queryDebugThreshold;
3842
private volatile long queryTraceThreshold;
3943

40-
public EsqlSlowLog(ClusterSettings settings) {
44+
private volatile boolean includeUser;
45+
46+
public EsqlSlowLog(ClusterSettings settings, SecurityContext security) {
4147
settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING, this::setQueryWarnThreshold);
4248
settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING, this::setQueryInfoThreshold);
4349
settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING, this::setQueryDebugThreshold);
4450
settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING, this::setQueryTraceThreshold);
51+
settings.initializeAndWatch(ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING, this::setIncludeUser);
4552
this.clusterSettings = settings;
53+
54+
this.security = security;
55+
}
56+
57+
public EsqlSlowLog(ClusterSettings settings) {
58+
this(settings, null);
4659
}
4760

4861
public void onQueryPhase(Result esqlResult, String query) {
@@ -51,28 +64,36 @@ public void onQueryPhase(Result esqlResult, String query) {
5164
}
5265
long tookInNanos = esqlResult.executionInfo().overallTook().nanos();
5366
if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) {
54-
queryLogger.warn(Message.of(esqlResult, query));
67+
queryLogger.warn(Message.of(esqlResult, query, user()));
5568
} else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) {
56-
queryLogger.info(Message.of(esqlResult, query));
69+
queryLogger.info(Message.of(esqlResult, query, user()));
5770

5871
} else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) {
59-
queryLogger.debug(Message.of(esqlResult, query));
72+
queryLogger.debug(Message.of(esqlResult, query, user()));
6073

6174
} else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) {
62-
queryLogger.trace(Message.of(esqlResult, query));
75+
queryLogger.trace(Message.of(esqlResult, query, user()));
6376

6477
}
6578
}
6679

80+
private User user() {
81+
User user = null;
82+
if (includeUser && security != null) {
83+
user = security.getUser();
84+
}
85+
return user;
86+
}
87+
6788
public void onQueryFailure(String query, Exception ex, long tookInNanos) {
6889
if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) {
69-
queryLogger.warn(Message.of(query, tookInNanos, ex));
90+
queryLogger.warn(Message.of(query, tookInNanos, ex, user()));
7091
} else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) {
71-
queryLogger.info(Message.of(query, tookInNanos, ex));
92+
queryLogger.info(Message.of(query, tookInNanos, ex, user()));
7293
} else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) {
73-
queryLogger.debug(Message.of(query, tookInNanos, ex));
94+
queryLogger.debug(Message.of(query, tookInNanos, ex, user()));
7495
} else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) {
75-
queryLogger.trace(Message.of(query, tookInNanos, ex));
96+
queryLogger.trace(Message.of(query, tookInNanos, ex, user()));
7697
}
7798
}
7899

@@ -92,30 +113,37 @@ public void setQueryTraceThreshold(TimeValue queryTraceThreshold) {
92113
this.queryTraceThreshold = queryTraceThreshold.nanos();
93114
}
94115

116+
public void setIncludeUser(boolean includeUser) {
117+
this.includeUser = includeUser;
118+
}
119+
95120
static final class Message {
96121

97122
private static String escapeJson(String text) {
98123
byte[] sourceEscaped = JsonStringEncoder.getInstance().quoteAsUTF8(text);
99124
return new String(sourceEscaped, StandardCharsets.UTF_8);
100125
}
101126

102-
public static ESLogMessage of(Result esqlResult, String query) {
103-
Map<String, Object> jsonFields = prepareMap(esqlResult, query, true);
127+
public static ESLogMessage of(Result esqlResult, String query, User user) {
128+
Map<String, Object> jsonFields = prepareMap(esqlResult, query, true, user);
104129

105130
return new ESLogMessage().withFields(jsonFields);
106131
}
107132

108-
public static ESLogMessage of(String query, long took, Exception exception) {
109-
Map<String, Object> jsonFields = prepareMap(null, query, false);
133+
public static ESLogMessage of(String query, long took, Exception exception, User user) {
134+
Map<String, Object> jsonFields = prepareMap(null, query, false, user);
110135
jsonFields.put("elasticsearch.slowlog.error.message", exception.getMessage() == null ? "" : exception.getMessage());
111136
jsonFields.put("elasticsearch.slowlog.error.type", exception.getClass().getName());
112137
jsonFields.put("elasticsearch.slowlog.took", took);
113138
jsonFields.put("elasticsearch.slowlog.took_millis", took / 1_000_000);
114139
return new ESLogMessage().withFields(jsonFields);
115140
}
116141

117-
private static Map<String, Object> prepareMap(Result esqlResult, String query, boolean success) {
142+
private static Map<String, Object> prepareMap(Result esqlResult, String query, boolean success, User user) {
118143
Map<String, Object> messageFields = new HashMap<>();
144+
if (user != null) {
145+
messageFields.put("user.name", user.principal());
146+
}
119147
if (esqlResult != null) {
120148
messageFields.put("elasticsearch.slowlog.took", esqlResult.executionInfo().overallTook().nanos());
121149
messageFields.put("elasticsearch.slowlog.took_millis", esqlResult.executionInfo().overallTook().millis());

‎x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/EsqlSlowLogTests.java‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@
1717
import org.elasticsearch.common.settings.Settings;
1818
import org.elasticsearch.core.TimeValue;
1919
import org.elasticsearch.test.ESTestCase;
20+
import org.elasticsearch.xpack.esql.MockAppender;
2021
import org.elasticsearch.xpack.esql.action.EsqlExecutionInfo;
2122
import org.elasticsearch.xpack.esql.plugin.EsqlPlugin;
2223
import org.elasticsearch.xpack.esql.session.Result;
@@ -41,14 +42,16 @@ public class EsqlSlowLogTests extends ESTestCase {
4142
.put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING.getKey(), "30ms")
4243
.put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), "20ms")
4344
.put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey(), "10ms")
45+
.put(EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING.getKey(), true)
4446

4547
.build(),
4648
new HashSet<>(
4749
Arrays.asList(
4850
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING,
4951
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING,
5052
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING,
51-
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING
53+
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING,
54+
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING
5255
)
5356
)
5457
);

‎x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/slowlog/MockAppender.java‎

Lines changed: 0 additions & 40 deletions
This file was deleted.

‎x-pack/plugin/esql/src/test/java/org/elasticsearch/xpack/esql/telemetry/PlanExecutorMetricsTests.java‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -92,7 +92,8 @@ EsqlSlowLog mockSlowLog() {
9292
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING,
9393
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING,
9494
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING,
95-
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING
95+
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING,
96+
EsqlPlugin.ESQL_SLOWLOG_THRESHOLD_INCLUDE_USER_SETTING
9697
)
9798
)
9899
);

0 commit comments

Comments
 (0)