Skip to content

Commit 45fac1d

Browse files
author
Philip Z
committed
feat: align unified SQL logging contract (#90)
1 parent 77b5c98 commit 45fac1d

12 files changed

Lines changed: 295 additions & 44 deletions

File tree

‎examples/conformance/src/main/java/com/teaql/runtimeexampleconformanceservice/App.java‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -137,6 +137,17 @@ public CommandLineRunner teaQLConsoleStartup(
137137
require(listed.size() == 1, "Q API must return one typed work item");
138138
System.out.println("PASS Q API (typed SmartList<WorkItem>)");
139139

140+
WorkItem withPlatform = Q.workItems()
141+
.withTitleIs("Initial title")
142+
.selectPlatformWith(Q.platforms().selectName())
143+
.comment("what: load work item with platform")
144+
.purpose("why: prove generated relation trace inheritance")
145+
.executeForOne(context);
146+
require(withPlatform != null && withPlatform.getPlatform() != null
147+
&& "Runtime Example".equals(withPlatform.getPlatform().getName()),
148+
"Forward Platform relation was not loaded");
149+
System.out.println("PASS relation query (typed Platform and inherited trace intent)");
150+
140151
WorkItem full = listed.get(0);
141152
require("Initial title".equals(E.workItem(full).getTitle().eval()), "E loaded title mismatch");
142153
require("N/A".equals(E.workItem(full).getDescription().orIfNull("N/A")),

‎teaql-core/src/main/java/io/teaql/core/ExecutionMetadata.java‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,8 @@ public final class ExecutionMetadata {
1818
private String debugQuery;
1919
private List<TraceNode> traceChain;
2020
private String comment;
21+
private String purpose;
22+
private String auditReason;
2123

2224
public String getBackend() { return backend; }
2325
public void setBackend(String backend) { this.backend = backend; }
@@ -62,6 +64,12 @@ public void setParameters(List<Object> parameters) {
6264
public String getComment() { return comment; }
6365
public void setComment(String comment) { this.comment = comment; }
6466

67+
public String getPurpose() { return purpose; }
68+
public void setPurpose(String purpose) { this.purpose = purpose; }
69+
70+
public String getAuditReason() { return auditReason; }
71+
public void setAuditReason(String auditReason) { this.auditReason = auditReason; }
72+
6573
private long elapsedUs;
6674
private String resultSummary;
6775

‎teaql-core/src/main/java/io/teaql/core/TraceKind.java‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,13 @@
1+
package io.teaql.core;
2+
3+
public enum TraceKind {
4+
OPERATION,
5+
REQUEST,
6+
RELATION,
7+
ENTITY,
8+
PROVIDER,
9+
SQL,
10+
COMMENT,
11+
PURPOSE,
12+
AUDIT_REASON
13+
}

‎teaql-core/src/main/java/io/teaql/core/TraceNode.java‎

Lines changed: 13 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,18 +1,30 @@
11
package io.teaql.core;
22

33
public class TraceNode {
4+
private final TraceKind kind;
5+
private final String name;
46
private final String comment;
57

68
public TraceNode(String comment) {
9+
this(TraceKind.ENTITY, "", comment);
10+
}
11+
12+
public TraceNode(TraceKind kind, String name, String comment) {
13+
this.kind = kind;
14+
this.name = name;
715
this.comment = comment;
816
}
917

18+
public TraceKind getKind() { return kind; }
19+
20+
public String getName() { return name; }
21+
1022
public String getComment() {
1123
return comment;
1224
}
1325

1426
@Override
1527
public String toString() {
16-
return comment;
28+
return kind + ":" + name + "=" + comment;
1729
}
1830
}

‎teaql-core/src/main/java/io/teaql/core/UserContext.java‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -146,6 +146,10 @@ default <T extends Entity> T initializeEntity(String entityName, T entity) {
146146

147147
void pushTrace(String comment);
148148

149+
default void pushTrace(TraceKind kind, String name, String value) {
150+
pushTrace(value);
151+
}
152+
149153
List<TraceNode> getTraceChain();
150154

151155
void popTrace();
@@ -159,6 +163,14 @@ default boolean isExecutionLoggingEnabled() {
159163
return true;
160164
}
161165

166+
default boolean isQueryExecutionLoggingEnabled() {
167+
return isExecutionLoggingEnabled();
168+
}
169+
170+
default boolean isMutationExecutionLoggingEnabled() {
171+
return isExecutionLoggingEnabled();
172+
}
173+
162174
void recordExecutionMetadata(ExecutionMetadata metadata);
163175

164176
// Business-facing API

‎teaql-data-service-sql/src/main/java/io/teaql/dataservice/sql/SqlDataServiceExecutor.java‎

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -140,13 +140,13 @@ public java.util.List<java.util.Map<String, Object>> getTableColumns(String tabl
140140

141141
@Override
142142
public java.util.List<java.util.Map<String, Object>> query(io.teaql.core.UserContext context, String sql, Object[] args) {
143-
boolean logging = context.isExecutionLoggingEnabled();
143+
boolean logging = context.isQueryExecutionLoggingEnabled();
144144
long start = logging ? System.nanoTime() : 0L;
145145
java.util.List<java.util.Map<String, Object>> res = executionAdapter.queryForList(sql, args);
146146
if (!logging) return res;
147147
long elapsed = (System.nanoTime() - start) / 1000;
148148
io.teaql.core.ExecutionMetadata meta = new io.teaql.core.ExecutionMetadata();
149-
meta.setBackend("SQL-" + name);
149+
meta.setBackend(debugDatabaseKind.toLowerCase(java.util.Locale.ROOT));
150150
meta.setOperation(io.teaql.core.DataServiceOperation.QUERY);
151151
meta.setElapsedUs(elapsed);
152152
meta.setResultCount(res.size());
@@ -162,13 +162,13 @@ public java.util.List<java.util.Map<String, Object>> query(io.teaql.core.UserCon
162162
public <T extends io.teaql.core.Entity> java.util.List<T> query(
163163
io.teaql.core.UserContext context, String sql, Object[] args,
164164
io.teaql.core.CompiledRowMapper<T> rowMapper) {
165-
boolean logging = context.isExecutionLoggingEnabled();
165+
boolean logging = context.isQueryExecutionLoggingEnabled();
166166
long start = logging ? System.nanoTime() : 0L;
167167
java.util.List<T> res = executionAdapter.query(sql, args, rowMapper);
168168
if (!logging) return res;
169169
long elapsed = (System.nanoTime() - start) / 1000;
170170
io.teaql.core.ExecutionMetadata meta = new io.teaql.core.ExecutionMetadata();
171-
meta.setBackend("SQL-" + name);
171+
meta.setBackend(debugDatabaseKind.toLowerCase(java.util.Locale.ROOT));
172172
meta.setOperation(io.teaql.core.DataServiceOperation.QUERY);
173173
meta.setElapsedUs(elapsed);
174174
meta.setResultCount(res.size());
@@ -182,13 +182,13 @@ public <T extends io.teaql.core.Entity> java.util.List<T> query(
182182

183183
@Override
184184
public int executeUpdate(io.teaql.core.UserContext context, String sql, Object[] args) {
185-
boolean logging = context.isExecutionLoggingEnabled();
185+
boolean logging = context.isMutationExecutionLoggingEnabled();
186186
long start = logging ? System.nanoTime() : 0L;
187187
int res = executionAdapter.update(sql, args);
188188
if (!logging) return res;
189189
long elapsed = (System.nanoTime() - start) / 1000;
190190
io.teaql.core.ExecutionMetadata meta = new io.teaql.core.ExecutionMetadata();
191-
meta.setBackend("SQL-" + name);
191+
meta.setBackend(debugDatabaseKind.toLowerCase(java.util.Locale.ROOT));
192192
meta.setOperation(io.teaql.core.DataServiceOperation.MUTATION);
193193
meta.setElapsedUs(elapsed);
194194
meta.setAffectedRows((long) res);
@@ -202,7 +202,7 @@ public int executeUpdate(io.teaql.core.UserContext context, String sql, Object[]
202202

203203
@Override
204204
public int[] batchUpdate(io.teaql.core.UserContext context, String sql, java.util.List<Object[]> batchArgs) {
205-
boolean logging = context.isExecutionLoggingEnabled();
205+
boolean logging = context.isMutationExecutionLoggingEnabled();
206206
long start = logging ? System.nanoTime() : 0L;
207207
int[] res = executionAdapter.batchUpdate(sql, batchArgs);
208208
if (!logging) return res;
@@ -216,7 +216,7 @@ public int[] batchUpdate(io.teaql.core.UserContext context, String sql, java.uti
216216
}
217217
}
218218
io.teaql.core.ExecutionMetadata meta = new io.teaql.core.ExecutionMetadata();
219-
meta.setBackend("SQL-" + name);
219+
meta.setBackend(debugDatabaseKind.toLowerCase(java.util.Locale.ROOT));
220220
meta.setOperation(io.teaql.core.DataServiceOperation.MUTATION);
221221
meta.setElapsedUs(elapsed);
222222
meta.setAffectedRows((long) total);
@@ -230,13 +230,13 @@ public int[] batchUpdate(io.teaql.core.UserContext context, String sql, java.uti
230230

231231
@Override
232232
public void execute(io.teaql.core.UserContext context, String sql) {
233-
boolean logging = context.isExecutionLoggingEnabled();
233+
boolean logging = context.isMutationExecutionLoggingEnabled();
234234
long start = logging ? System.nanoTime() : 0L;
235235
executionAdapter.execute(sql);
236236
if (!logging) return;
237237
long elapsed = (System.nanoTime() - start) / 1000;
238238
io.teaql.core.ExecutionMetadata meta = new io.teaql.core.ExecutionMetadata();
239-
meta.setBackend("SQL-" + name);
239+
meta.setBackend(debugDatabaseKind.toLowerCase(java.util.Locale.ROOT));
240240
meta.setOperation(io.teaql.core.DataServiceOperation.SCHEMA);
241241
meta.setElapsedUs(elapsed);
242242
meta.setResultSummary("Executed");

‎teaql-runtime-log/src/main/java/io/teaql/runtime/log/HumanReaderFormatter.java‎

Lines changed: 11 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -13,8 +13,11 @@ private String formatTraceChain(List<TraceNode> traceChain) {
1313
if (traceChain == null || traceChain.isEmpty()) {
1414
return "";
1515
}
16-
return traceChain.stream()
17-
.map(t -> (CharSequence) t.getComment())
16+
return java.util.stream.IntStream.range(0, traceChain.size())
17+
.mapToObj(i -> {
18+
TraceNode t = traceChain.get(i);
19+
return i + ":" + t.getKind() + ":" + t.getName() + "=" + t.getComment();
20+
})
1821
.collect(Collectors.joining(" -> "));
1922
}
2023

@@ -24,9 +27,12 @@ public String formatExecutionLog(io.teaql.core.ExecutionMetadata metadata) {
2427
String traceStr = formatTraceChain(metadata.getTraceChain());
2528
String traceDisplay = traceStr.isEmpty() ? "" : " - [" + traceStr + "]";
2629

27-
String cleanQuery = metadata.getDebugQuery() == null ? "" : metadata.getDebugQuery().replace('\n', ' ');
28-
return String.format("[%s]-[%5dµs]-[DEBUG]-ExecutionLog%s - [%s]\n %s",
29-
ts, metadata.getElapsedUs(), traceDisplay, metadata.getResultSummary(), cleanQuery);
30+
String parameterized = metadata.getParameterizedQuery() == null ? "" : metadata.getParameterizedQuery().replace('\n', ' ');
31+
String debug = metadata.getDebugQuery() == null ? "" : metadata.getDebugQuery().replace('\n', ' ');
32+
return String.format("[%s]-[%5dµs]-[DEBUG]-ExecutionLog%s - [%s] comment=%s purpose=%s auditReason=%s\n Parameterized SQL: %s params=%s\n Debug SQL: %s",
33+
ts, metadata.getElapsedUs(), traceDisplay, metadata.getResultSummary(),
34+
metadata.getComment(), metadata.getPurpose(), metadata.getAuditReason(),
35+
parameterized, metadata.getParameters(), debug);
3036
}
3137

3238
@Override

‎teaql-runtime-log/src/main/java/io/teaql/runtime/log/JsonReaderFormatter.java‎

Lines changed: 12 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,9 @@ private String formatTraceChain(List<TraceNode> traceChain) {
1010
return "[]";
1111
}
1212
return "[" + traceChain.stream()
13-
.map(t -> (CharSequence)("\"" + escapeJson(t.getComment()) + "\""))
13+
.map(t -> (CharSequence)("{\"kind\":\"" + t.getKind()
14+
+ "\",\"name\":\"" + escapeJson(t.getName())
15+
+ "\",\"value\":\"" + escapeJson(t.getComment()) + "\"}"))
1416
.collect(Collectors.joining(",")) + "]";
1517
}
1618

@@ -21,11 +23,19 @@ private String escapeJson(String text) {
2123

2224
@Override
2325
public String formatExecutionLog(io.teaql.core.ExecutionMetadata metadata) {
24-
return String.format("{\"type\":\"EXEC_LOG\",\"trace\":%s,\"backend\":\"%s\",\"elapsedUs\":%d,\"summary\":\"%s\",\"query\":\"%s\"}",
26+
return String.format("{\"type\":\"EXEC_LOG\",\"tracePath\":%s,\"backend\":\"%s\",\"operation\":\"%s\",\"comment\":\"%s\",\"purpose\":\"%s\",\"auditReason\":\"%s\",\"elapsedUs\":%d,\"resultCount\":%s,\"affectedRows\":%s,\"summary\":\"%s\",\"parameterizedSQL\":\"%s\",\"parameters\":\"%s\",\"debugSQL\":\"%s\"}",
2527
formatTraceChain(metadata.getTraceChain()),
2628
escapeJson(metadata.getBackend()),
29+
metadata.getOperation(),
30+
escapeJson(metadata.getComment()),
31+
escapeJson(metadata.getPurpose()),
32+
escapeJson(metadata.getAuditReason()),
2733
metadata.getElapsedUs(),
34+
metadata.getResultCount(),
35+
metadata.getAffectedRows(),
2836
escapeJson(metadata.getResultSummary()),
37+
escapeJson(metadata.getParameterizedQuery()),
38+
escapeJson(String.valueOf(metadata.getParameters())),
2939
escapeJson(metadata.getDebugQuery()));
3040
}
3141

‎teaql-runtime/src/main/java/io/teaql/runtime/DefaultTextRuntimeLogSink.java‎

Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,44 @@
1+
package io.teaql.runtime;
2+
3+
import io.teaql.core.ExecutionMetadata;
4+
import io.teaql.core.TraceNode;
5+
import io.teaql.core.UserContext;
6+
import java.util.List;
7+
import java.util.stream.IntStream;
8+
9+
/** Default value-bearing diagnostic SQL destination. */
10+
public final class DefaultTextRuntimeLogSink implements RuntimeLogSink {
11+
@Override
12+
public void writeExecutionLog(UserContext context, ExecutionMetadata metadata) {
13+
System.err.printf(
14+
"[TeaQL SQL][%s][%dus] %s comment=%s purpose=%s auditReason=%s tracePath=%s%n"
15+
+ "Parameterized SQL: %s params=%s%nDebug SQL: %s%n",
16+
metadata.getOperation() == null ? "unknown" : metadata.getOperation().name().toLowerCase(),
17+
metadata.getElapsedUs(), resultSummary(metadata),
18+
nullToEmpty(metadata.getComment()), nullToEmpty(metadata.getPurpose()),
19+
nullToEmpty(metadata.getAuditReason()), formatTrace(metadata.getTraceChain()),
20+
nullToEmpty(metadata.getParameterizedQuery()), metadata.getParameters(),
21+
nullToEmpty(metadata.getDebugQuery()));
22+
}
23+
24+
private static String formatTrace(List<TraceNode> nodes) {
25+
if (nodes == null) return "[]";
26+
return "[" + IntStream.range(0, nodes.size())
27+
.mapToObj(index -> index + ":" + nodes.get(index))
28+
.reduce((left, right) -> left + " -> " + right).orElse("") + "]";
29+
}
30+
31+
private static String nullToEmpty(String value) {
32+
return value == null ? "" : value;
33+
}
34+
35+
private static String resultSummary(ExecutionMetadata metadata) {
36+
if (metadata.getResultCount() != null) {
37+
return metadata.getResultCount() + " rows returned";
38+
}
39+
if (metadata.getAffectedRows() != null) {
40+
return metadata.getAffectedRows() + " rows affected";
41+
}
42+
return nullToEmpty(metadata.getResultSummary());
43+
}
44+
}

‎teaql-runtime/src/main/java/io/teaql/runtime/DefaultUserContext.java‎

Lines changed: 56 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -233,6 +233,11 @@ public void pushTrace(String comment) {
233233
traceChain.add(new TraceNode(comment));
234234
}
235235

236+
@Override
237+
public void pushTrace(TraceKind kind, String name, String value) {
238+
traceChain.add(new TraceNode(kind, name, value));
239+
}
240+
236241
@Override
237242
public void popTrace() {
238243
if (!traceChain.isEmpty()) {
@@ -250,16 +255,67 @@ public boolean isExecutionLoggingEnabled() {
250255
return runtime == null || runtime.isExecutionLoggingEnabled();
251256
}
252257

258+
@Override
259+
public boolean isQueryExecutionLoggingEnabled() {
260+
return runtime == null || runtime.isQueryExecutionLoggingEnabled();
261+
}
262+
263+
@Override
264+
public boolean isMutationExecutionLoggingEnabled() {
265+
return runtime == null || runtime.isMutationExecutionLoggingEnabled();
266+
}
267+
253268
@Override
254269
public void recordExecutionMetadata(io.teaql.core.ExecutionMetadata metadata) {
255270
if (metadata.getTraceChain() == null || metadata.getTraceChain().isEmpty()) {
256271
metadata.setTraceChain(getTraceChain());
257272
}
273+
if (metadata.getTraceChain() != null) {
274+
for (TraceNode node : metadata.getTraceChain()) {
275+
if (node.getKind() == TraceKind.COMMENT) metadata.setComment(node.getComment());
276+
if (node.getKind() == TraceKind.PURPOSE) metadata.setPurpose(node.getComment());
277+
if (node.getKind() == TraceKind.AUDIT_REASON) metadata.setAuditReason(node.getComment());
278+
}
279+
}
280+
java.util.List<TraceNode> canonical = new java.util.ArrayList<>();
281+
if (metadata.getTraceChain() != null) {
282+
metadata.getTraceChain().stream()
283+
.filter(node -> node.getKind() != TraceKind.COMMENT
284+
&& node.getKind() != TraceKind.PURPOSE
285+
&& node.getKind() != TraceKind.AUDIT_REASON
286+
&& node.getKind() != TraceKind.PROVIDER
287+
&& node.getKind() != TraceKind.SQL)
288+
.forEach(canonical::add);
289+
}
290+
String backend = metadata.getBackend() == null ? "unknown" : metadata.getBackend();
291+
canonical.add(new TraceNode(TraceKind.PROVIDER, backend, backend));
292+
String sqlOperation = sqlOperation(metadata);
293+
canonical.add(new TraceNode(TraceKind.SQL, sqlOperation, sqlOperation));
294+
metadata.setTraceChain(canonical);
258295
if (runtime != null) {
259296
runtime.recordExecutionMetadata(this, metadata);
260297
}
261298
}
262299

300+
private static String sqlOperation(io.teaql.core.ExecutionMetadata metadata) {
301+
String sql = metadata.getParameterizedQuery();
302+
if (sql != null) {
303+
String normalized = sql.stripLeading();
304+
while (normalized.startsWith("/*")) {
305+
int end = normalized.indexOf("*/");
306+
if (end < 0) break;
307+
normalized = normalized.substring(end + 2).stripLeading();
308+
}
309+
int boundary = normalized.indexOf(' ');
310+
String keyword = (boundary < 0 ? normalized : normalized.substring(0, boundary))
311+
.replaceAll("[^A-Za-z]", "").toLowerCase(java.util.Locale.ROOT);
312+
if (!keyword.isEmpty()) return keyword;
313+
}
314+
return metadata.getOperation() == null
315+
? "sql"
316+
: metadata.getOperation().name().toLowerCase(java.util.Locale.ROOT);
317+
}
318+
263319
@SuppressWarnings("unchecked")
264320
@Override
265321
public final <T> T evaluate(String expression, Object... args) {

0 commit comments

Comments
 (0)