Skip to content

Commit dd10e21

Browse files
authored
TECH_DEBT: Structured CQL debug output for measureeval $evaluate (#1668)
* Add DebugSections enum and MeasureEvaluationResult DTO Adds two model classes that will support structured debug output from measure evaluation. * Plumb DebugSections through evaluator and controller Wires the new DebugSections type through the measure-evaluation call path and switches the $evaluate endpoint to return MeasureEvaluationResult. * Capture and emit structured CQL debug info on $evaluate Wires the real debug data capture into the MeasureEvaluator. * Drop javassist exception dependency and add DebugSections tests Polish to finish the debug-logging series. * Add integration tests for the $evaluate debug capture path * Cap trace tree size and log debug activations * Add Spring converter, dev docs, and clarify cache bypass Three small follow-up improvements bundled together since each is independently small and they share theme (developer ergonomics around the new debug parameter). * Address review feedback: sanitize logs, omit null debugInfo, guard null subjects * Preserve bare MeasureReport response shape when debug is empty
1 parent befb693 commit dd10e21

12 files changed

Lines changed: 1412 additions & 19 deletions

File tree

Java/measureeval/DEBUG-LOGGING.md

Lines changed: 154 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,154 @@
1+
# Measure Evaluation Debug Output
2+
3+
The `$evaluate` endpoint on the Measure Definition API can return structured debug data
4+
alongside the standard FHIR `MeasureReport`. This is intended for measure authoring and
5+
troubleshooting — not for production monitoring or analytics.
6+
7+
## Endpoint
8+
9+
```
10+
POST /api/measureeval/measure-definition/{id}/$evaluate?debug={sections}
11+
```
12+
13+
Request body: the same FHIR `Parameters` resource as a non-debug evaluation
14+
(`periodStart`, `periodEnd`, `subject`, `additionalData`).
15+
16+
## The `debug` query parameter
17+
18+
`debug` is a comma-separated list of sections to populate. Spring binds the value through
19+
a custom converter so the controller receives a `Set<DebugSections>` directly.
20+
21+
| Value | Meaning |
22+
|---------------------------------------|----------------------------------|
23+
| _(parameter omitted)_ | No debug data (fast path) |
24+
| `false` or empty | No debug data (fast path) |
25+
| `true` or `all` | Every section |
26+
| `groups` | Population counts + errors |
27+
| `expressions` | CQL expression → result map |
28+
| `librarydebug` | Per-library node-level results |
29+
| `messages` | CQL engine messages |
30+
| `traces` | Hierarchical execution trace |
31+
| `debuglog` | Human-readable rendered log |
32+
| `expressions,traces` (any combination)| Just those sections |
33+
34+
Token matching is case-insensitive and tolerates surrounding whitespace.
35+
Unknown tokens are silently ignored; the recognised ones around them still parse.
36+
37+
## Response shape
38+
39+
Without debug — bare FHIR `MeasureReport`, unchanged from the pre-debug behaviour:
40+
41+
```json
42+
{ "resourceType": "MeasureReport", ... }
43+
```
44+
45+
With debug — wrapper object carrying the report alongside the requested debug sections:
46+
47+
```json
48+
{
49+
"measureReport": { "resourceType": "MeasureReport", ... },
50+
"debugInfo": {
51+
"groups": [
52+
{
53+
"id": "group-1",
54+
"populations": [
55+
{ "type": "initial-population", "count": 1, "subjects": ["Patient/p1"] }
56+
]
57+
}
58+
],
59+
"expressionResults": { "Initial Population": "[Encounter/enc-1]" },
60+
"traces": [ ... ],
61+
"truncated": true
62+
}
63+
}
64+
```
65+
66+
Sections that weren't requested (or that the engine didn't produce data for) are omitted
67+
from `debugInfo` rather than emitted as `null`.
68+
69+
The `truncated` flag is present and set to `true` only if a section had to be capped to
70+
protect the response from runaway memory use. Currently this only happens when the trace
71+
tree exceeds `MeasureEvaluator.MAX_TRACE_FRAMES` (10,000 frames).
72+
73+
## Wire-format compatibility
74+
75+
The default response (no `debug` query parameter) is unchanged: clients continue to receive
76+
a bare FHIR `MeasureReport`. The wrapper envelope is only emitted when callers opt in by
77+
passing `debug=...`, so existing consumers do not need to migrate.
78+
79+
## Performance considerations
80+
81+
- **Without debug**: identical to the pre-change behaviour. Uses
82+
`R4MultiMeasureService.evaluate(...)` and returns immediately.
83+
- **With debug**: routes through `R4MultiMeasureService.evaluateSingleMeasureCaptureDef(...)`
84+
to capture the underlying `EvaluationResult` map. There is some overhead in this path even
85+
when only the `groups` section is requested.
86+
- **With `traces` or `all`**: the CQL engine's tracing flags are turned on, which adds
87+
per-expression instrumentation cost. On a realistic measure, this can multiply evaluation
88+
time several-fold and produce response payloads in the MB range. Use only against
89+
representative test inputs, not full production patient bundles.
90+
- The 10,000-frame trace cap (`MeasureEvaluator.MAX_TRACE_FRAMES`) is a soft floor against
91+
pathological cases. If you hit it routinely on legitimate measures, raise the constant or
92+
request only a subset of debug sections.
93+
94+
## Examples
95+
96+
```bash
97+
# Fast path (production behaviour)
98+
curl -X POST -H "Authorization: Bearer ..." \
99+
-H "Content-Type: application/json" \
100+
-d @parameters.json \
101+
https://.../api/measureeval/measure-definition/my-measure/\$evaluate
102+
103+
# Just see population counts plus the report
104+
curl -X POST -H "Authorization: Bearer ..." \
105+
-H "Content-Type: application/json" \
106+
-d @parameters.json \
107+
"https://.../api/measureeval/measure-definition/my-measure/\$evaluate?debug=groups"
108+
109+
# Everything (use sparingly)
110+
curl -X POST -H "Authorization: Bearer ..." \
111+
-H "Content-Type: application/json" \
112+
-d @parameters.json \
113+
"https://.../api/measureeval/measure-definition/my-measure/\$evaluate?debug=all"
114+
115+
# Targeted: expression results plus a human-readable log
116+
curl -X POST -H "Authorization: Bearer ..." \
117+
-H "Content-Type: application/json" \
118+
-d @parameters.json \
119+
"https://.../api/measureeval/measure-definition/my-measure/\$evaluate?debug=expressions,debuglog"
120+
```
121+
122+
## Observability
123+
124+
When `debug` is non-empty, the controller emits an INFO log line at the start of the
125+
request identifying the measure id and the requested sections:
126+
127+
```
128+
Measure evaluation requested with debug sections [EXPRESSIONS, TRACES] for measure my-measure
129+
```
130+
131+
This is silent on the fast path so production logs aren't polluted.
132+
133+
## Caching note
134+
135+
The `MeasureEvaluatorCache` keeps compiled evaluators keyed by measure id, but the
136+
controller intentionally bypasses the cached evaluator's `evaluate(...)` method on the
137+
debug path. The cached evaluator was compiled with the service-wide `link.cql-debug` flag
138+
baked in; the request-specific `debug` parameter may differ. So the controller looks the
139+
measure up via the cache (for the side effect of registering the libraries with the
140+
`LibraryResolver`, used by `CqlLogAppender`), then calls
141+
`MeasureEvaluator.compileAndEvaluate(...)` which produces a per-request evaluator with the
142+
correct engine flags. This costs an extra compile per request — acceptable because debug
143+
is opt-in and rare.
144+
145+
## Related code
146+
147+
| File | Role |
148+
|---------------------------------------------------|------------------------------------------------------------|
149+
| `models/DebugSections.java` | Enum of available sections + `parse(String)` |
150+
| `models/MeasureEvaluationResult.java` | Response DTO (`measureReport` + optional `debugInfo`) |
151+
| `converters/DebugSectionsConverter.java` | Spring MVC `String``Set<DebugSections>` converter |
152+
| `configs/WebMvcConfig.java` | Registers the converter with the formatter registry |
153+
| `controllers/MeasureDefinitionController.java` | `$evaluate` endpoint |
154+
| `services/MeasureEvaluator.java` | Compile + evaluate + `buildDebugInfo` + `buildTraceTree` |
Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,25 @@
1+
package com.lantanagroup.link.measureeval.configs;
2+
3+
import com.lantanagroup.link.measureeval.converters.DebugSectionsConverter;
4+
import org.springframework.context.annotation.Configuration;
5+
import org.springframework.format.FormatterRegistry;
6+
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
7+
8+
/**
9+
* Registers project-specific Spring MVC converters/formatters so controllers can declare
10+
* strongly-typed request parameters instead of taking raw Strings and parsing inline.
11+
*/
12+
@Configuration
13+
public class WebMvcConfig implements WebMvcConfigurer {
14+
15+
private final DebugSectionsConverter debugSectionsConverter;
16+
17+
public WebMvcConfig(DebugSectionsConverter debugSectionsConverter) {
18+
this.debugSectionsConverter = debugSectionsConverter;
19+
}
20+
21+
@Override
22+
public void addFormatters(FormatterRegistry registry) {
23+
registry.addConverter(debugSectionsConverter);
24+
}
25+
}

Java/measureeval/src/main/java/com/lantanagroup/link/measureeval/controllers/MeasureDefinitionController.java

Lines changed: 38 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,8 @@
33
import ca.uhn.fhir.context.FhirContext;
44
import com.fasterxml.jackson.annotation.JsonView;
55
import com.lantanagroup.link.measureeval.entities.MeasureDefinition;
6+
import com.lantanagroup.link.measureeval.models.DebugSections;
7+
import com.lantanagroup.link.measureeval.models.MeasureEvaluationResult;
68
import com.lantanagroup.link.measureeval.models.RelatedArtifactInfo;
79
import com.lantanagroup.link.measureeval.repositories.MeasureDefinitionRepository;
810
import com.lantanagroup.link.measureeval.services.MeasureDefinitionBundleValidator;
@@ -15,10 +17,8 @@
1517
import io.opentelemetry.api.trace.Span;
1618
import io.swagger.v3.oas.annotations.Operation;
1719
import io.swagger.v3.oas.annotations.Parameter;
18-
import javassist.NotFoundException;
1920
import org.apache.commons.text.StringEscapeUtils;
2021
import org.hl7.fhir.r4.model.Bundle;
21-
import org.hl7.fhir.r4.model.MeasureReport;
2222
import org.hl7.fhir.r4.model.Parameters;
2323
import org.slf4j.Logger;
2424
import org.slf4j.LoggerFactory;
@@ -30,6 +30,7 @@
3030
import org.springframework.web.server.ResponseStatusException;
3131

3232
import java.util.List;
33+
import java.util.Set;
3334

3435
@RestController
3536
@RequestMapping("/api/measureeval/measure-definition")
@@ -136,7 +137,7 @@ public String getMeasureLibraryCQL(
136137

137138
try {
138139
return CqlUtils.getCql(measureDefinition.getBundle(), libraryId, range);
139-
} catch (NotFoundException e) {
140+
} catch (CqlUtils.ResourceNotFoundException e) {
140141
throw new ResponseStatusException(HttpStatus.NOT_FOUND, e.getMessage(), e);
141142
}
142143
}
@@ -146,24 +147,53 @@ public String getMeasureLibraryCQL(
146147
@Operation(summary = "Evaluate a measure against data in request body", tags = {"Measure Definitions"})
147148
@Parameter(name = "id", description = "The ID of the measure definition", required = true)
148149
@Parameter(name = "parameters", description = "The parameters to use in the evaluation", required = true)
149-
@Parameter(name = "debug", description = "Whether to log CQL debugging information during evaluation", required = false)
150-
public MeasureReport evaluate(@AuthenticationPrincipal PrincipalUser user, @PathVariable String id, @RequestBody Parameters parameters, @RequestParam(required = false, defaultValue = "false") boolean debug) {
150+
@Parameter(name = "debug",
151+
description = "Which debug sections to populate on the response. " +
152+
"Accepts `true`/`all` (every section), `false`/empty (no sections), " +
153+
"or a comma-separated list of: groups, expressions, librarydebug, messages, traces, debuglog.",
154+
required = false)
155+
public Object evaluate(
156+
@AuthenticationPrincipal PrincipalUser user,
157+
@PathVariable String id,
158+
@RequestBody Parameters parameters,
159+
@RequestParam(required = false, defaultValue = "false") Set<DebugSections> debug) {
151160

152161
if (user != null){
153162
Span currentSpan = Span.current();
154163
currentSpan.setAttribute("user", user.getEmailAddress());
155164
}
156165

157-
// Ensure that a measure evaluator is cached (so that CQL logging can use it)
166+
// Resolve the cached evaluator. Two things this gives us:
167+
// 1. A cheap existence check for the measure (returns null -> 404).
168+
// 2. Side effect: ensures the measure's libraries are registered with
169+
// MeasureEvaluatorCache's LibraryResolver, which CqlLogAppender uses
170+
// to translate CQL log locators back to source ranges.
171+
// We intentionally do NOT call evaluator.evaluate(...) here. The cached
172+
// evaluator was compiled once at first-use time with `linkConfig.cqlDebug`
173+
// baked in as its only debug flag; reusing it would either log too much or
174+
// too little relative to the per-request `debug` parameter. So we always
175+
// recompile via compileAndEvaluate(...) with the explicit per-request
176+
// section set, which sets the engine's debug/tracing flags correctly for
177+
// this specific call.
158178
MeasureEvaluator evaluator = evaluatorCache.get(id);
159179

160180
if (evaluator == null) {
161181
throw new ResponseStatusException(HttpStatus.NOT_FOUND, "Measure definition not found");
162182
}
163183

184+
if (!debug.isEmpty()) {
185+
_logger.info("Measure evaluation requested with debug sections {} for measure {}",
186+
StringEscapeUtils.escapeJava(String.valueOf(debug)),
187+
StringEscapeUtils.escapeJava(id));
188+
}
189+
164190
try {
165-
// But recompile the bundle every time because the debug flag may not match what's in the cache
166-
return MeasureEvaluator.compileAndEvaluate(FhirContext.forR4(), evaluator.getBundle(), parameters, debug);
191+
MeasureEvaluationResult result = MeasureEvaluator.compileAndEvaluate(
192+
FhirContext.forR4(), evaluator.getBundle(), parameters, debug);
193+
// Preserve the original wire contract: when no debug sections are
194+
// requested, return a bare MeasureReport. Only emit the wrapper for
195+
// callers who opted in via the `debug` query parameter.
196+
return debug.isEmpty() ? result.getMeasureReport() : result;
167197
} catch (Exception e) {
168198
throw new ResponseStatusException(HttpStatus.BAD_REQUEST, e.getMessage(), e);
169199
}
Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,24 @@
1+
package com.lantanagroup.link.measureeval.converters;
2+
3+
import com.lantanagroup.link.measureeval.models.DebugSections;
4+
import org.springframework.core.convert.converter.Converter;
5+
import org.springframework.stereotype.Component;
6+
7+
import java.util.Set;
8+
9+
/**
10+
* Adapts the {@code ?debug=...} query parameter from raw String to {@code Set<DebugSections>}
11+
* at the Spring MVC request-binding edge. Lets controllers declare the strongly-typed parameter
12+
* directly instead of parsing the value inline.
13+
*
14+
* <p>Registered via {@link com.lantanagroup.link.measureeval.configs.WebMvcConfig}.
15+
* Delegates parsing to {@link DebugSections#parse(String)} so the wire contract stays in one place.
16+
*/
17+
@Component
18+
public class DebugSectionsConverter implements Converter<String, Set<DebugSections>> {
19+
20+
@Override
21+
public Set<DebugSections> convert(String source) {
22+
return DebugSections.parse(source);
23+
}
24+
}
Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,52 @@
1+
package com.lantanagroup.link.measureeval.models;
2+
3+
import java.util.*;
4+
5+
public enum DebugSections {
6+
GROUPS,
7+
EXPRESSIONS,
8+
LIBRARY_DEBUG,
9+
MESSAGES,
10+
TRACES,
11+
DEBUG_LOG;
12+
13+
private static final Map<String, DebugSections> ALIASES = Map.of(
14+
"groups", GROUPS,
15+
"expressions", EXPRESSIONS,
16+
"librarydebug", LIBRARY_DEBUG,
17+
"messages", MESSAGES,
18+
"traces", TRACES,
19+
"debuglog", DEBUG_LOG
20+
);
21+
22+
public static Set<DebugSections> parse(String input) {
23+
if (input == null || input.isBlank() || "false".equalsIgnoreCase(input.trim())) {
24+
return EnumSet.noneOf(DebugSections.class);
25+
}
26+
String trimmed = input.trim();
27+
if ("true".equalsIgnoreCase(trimmed) || "all".equalsIgnoreCase(trimmed)) {
28+
return EnumSet.allOf(DebugSections.class);
29+
}
30+
Set<DebugSections> result = EnumSet.noneOf(DebugSections.class);
31+
for (String token : trimmed.split(",")) {
32+
String key = token.trim().toLowerCase(Locale.ROOT);
33+
DebugSections section = ALIASES.get(key);
34+
if (section != null) {
35+
result.add(section);
36+
}
37+
}
38+
return result;
39+
}
40+
41+
public static boolean needsDebugLogging(Set<DebugSections> sections) {
42+
return sections.contains(EXPRESSIONS)
43+
|| sections.contains(LIBRARY_DEBUG)
44+
|| sections.contains(MESSAGES)
45+
|| sections.contains(DEBUG_LOG);
46+
}
47+
48+
public static boolean needsTracing(Set<DebugSections> sections) {
49+
return sections.contains(TRACES)
50+
|| sections.contains(DEBUG_LOG);
51+
}
52+
}

0 commit comments

Comments
 (0)