Skip to content

Commit 20a1c56

Browse files
michaelabuckleymichaelabuckley
authored
Add troubleshooting log for partition routing. (hapifhir#6719)
* Create new log and docs. * Implement start of logging. * add to logback * spotless * Fix refactor error * spotless * Add details to SRD logs * Add details to SRD logs * Commit to trigger fresh build
1 parent 5153ac7 commit 20a1c56

File tree

5 files changed

+157
-54
lines changed

5 files changed

+157
-54
lines changed

‎hapi-fhir-base/src/main/java/ca/uhn/fhir/interceptor/api/Pointcut.java

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2097,6 +2097,7 @@ public enum Pointcut implements IPointcut {
20972097
* This hook is an alternative to {@link #STORAGE_PARTITION_IDENTIFY_READ} and {@link #STORAGE_PARTITION_IDENTIFY_CREATE}
20982098
* and can be used in cases where a partition interceptor does not need knowledge of the specific resources being
20992099
* accessed/read/written in order to determine the appropriate partition.
2100+
* If registered, then neither STORAGE_PARTITION_IDENTIFY_READ, nor STORAGE_PARTITION_IDENTIFY_CREATE will be called.
21002101
* </p>
21012102
* <p>
21022103
* This hook will only be called if

‎hapi-fhir-base/src/main/java/ca/uhn/fhir/util/Logs.java

Lines changed: 35 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -23,30 +23,16 @@
2323
import org.slf4j.LoggerFactory;
2424

2525
public class Logs {
26-
private static final Logger ourBatchTroubleshootingLog =
27-
LoggerFactory.getLogger("ca.uhn.fhir.log.batch_troubleshooting");
28-
private static final Logger ourNarrativeGenerationTroubleshootingLog =
29-
LoggerFactory.getLogger("ca.uhn.fhir.log.narrative_generation_troubleshooting");
30-
31-
private static final Logger ourTerminologyTroubleshootingLog =
32-
LoggerFactory.getLogger("ca.uhn.fhir.log.terminology_troubleshooting");
33-
34-
private static final Logger ourSubscriptionTroubleshootingLog =
35-
LoggerFactory.getLogger("ca.cdr.log.subscription_troubleshooting");
36-
37-
private static final Logger ourSubscriptionTopicLog =
38-
LoggerFactory.getLogger("ca.uhn.fhir.log.subscription_topic_troubleshooting");
39-
4026
public static Logger getBatchTroubleshootingLog() {
4127
return ourBatchTroubleshootingLog;
4228
}
4329

4430
public static Logger getNarrativeGenerationTroubleshootingLog() {
45-
return ourBatchTroubleshootingLog;
31+
return ourNarrativeGenerationTroubleshootingLog;
4632
}
4733

48-
public static Logger getTerminologyTroubleshootingLog() {
49-
return ourTerminologyTroubleshootingLog;
34+
public static Logger getPartitionTroubleshootingLog() {
35+
return ourPartitionTroubleshootingLog;
5036
}
5137

5238
public static Logger getSubscriptionTroubleshootingLog() {
@@ -56,4 +42,36 @@ public static Logger getSubscriptionTroubleshootingLog() {
5642
public static Logger getSubscriptionTopicLog() {
5743
return ourSubscriptionTopicLog;
5844
}
45+
46+
public static Logger getTerminologyTroubleshootingLog() {
47+
return ourTerminologyTroubleshootingLog;
48+
}
49+
50+
public static final String CA_UHN_FHIR_LOG_BATCH_TROUBLESHOOTING = "ca.uhn.fhir.log.batch_troubleshooting";
51+
public static final String CA_UHN_FHIR_LOG_NARRATIVE_GENERATION_TROUBLESHOOTING =
52+
"ca.uhn.fhir.log.narrative_generation_troubleshooting";
53+
public static final String CA_UHN_FHIR_LOG_PARTITION_TROUBLESHOOTING = "ca.uhn.fhir.log.partition_troubleshooting";
54+
public static final String CA_UHN_FHIR_LOG_TERMINOLOGY_TROUBLESHOOTING =
55+
"ca.uhn.fhir.log.terminology_troubleshooting";
56+
public static final String CA_CDR_LOG_SUBSCRIPTION_TROUBLESHOOTING = "ca.cdr.log.subscription_troubleshooting";
57+
public static final String CA_UHN_FHIR_LOG_SUBSCRIPTION_TOPIC_TROUBLESHOOTING =
58+
"ca.uhn.fhir.log.subscription_topic_troubleshooting";
59+
60+
private static final Logger ourBatchTroubleshootingLog =
61+
LoggerFactory.getLogger(CA_UHN_FHIR_LOG_BATCH_TROUBLESHOOTING);
62+
63+
private static final Logger ourNarrativeGenerationTroubleshootingLog =
64+
LoggerFactory.getLogger(CA_UHN_FHIR_LOG_NARRATIVE_GENERATION_TROUBLESHOOTING);
65+
66+
private static final Logger ourPartitionTroubleshootingLog =
67+
LoggerFactory.getLogger(CA_UHN_FHIR_LOG_PARTITION_TROUBLESHOOTING);
68+
69+
private static final Logger ourTerminologyTroubleshootingLog =
70+
LoggerFactory.getLogger(CA_UHN_FHIR_LOG_TERMINOLOGY_TROUBLESHOOTING);
71+
72+
private static final Logger ourSubscriptionTroubleshootingLog =
73+
LoggerFactory.getLogger(CA_CDR_LOG_SUBSCRIPTION_TROUBLESHOOTING);
74+
75+
private static final Logger ourSubscriptionTopicLog =
76+
LoggerFactory.getLogger(CA_UHN_FHIR_LOG_SUBSCRIPTION_TOPIC_TROUBLESHOOTING);
5977
}

‎hapi-fhir-docs/src/main/resources/ca/uhn/hapi/fhir/changelog/8_2_0/6719-partition-troubleshooting-log.yaml

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,4 @@
1+
---
2+
type: add
3+
issue: 6719
4+
title: "Added a troubleshooting log for request partition routing."

‎hapi-fhir-jpaserver-test-r4/src/test/resources/logback-test.xml

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -50,5 +50,7 @@
5050
<logger name="org.hibernate.search.backend.lucene.infostream" level="TRACE"/> -->
5151

5252
<!-- <logger name="ca.uhn.fhir.log.terminology_troubleshooting" level="TRACE"/> -->
53+
<logger name="ca.uhn.fhir.log.partition_troubleshooting" level="info"/>
54+
5355

5456
</configuration>

‎hapi-fhir-storage/src/main/java/ca/uhn/fhir/jpa/partition/BaseRequestPartitionHelperSvc.java

Lines changed: 115 additions & 37 deletions
Original file line numberDiff line numberDiff line change
@@ -35,10 +35,12 @@
3535
import ca.uhn.fhir.rest.server.exceptions.UnprocessableEntityException;
3636
import ca.uhn.fhir.rest.server.servlet.ServletRequestDetails;
3737
import ca.uhn.fhir.rest.server.util.CompositeInterceptorBroadcaster;
38+
import ca.uhn.fhir.util.Logs;
3839
import jakarta.annotation.Nonnull;
3940
import jakarta.annotation.Nullable;
4041
import org.apache.commons.lang3.StringUtils;
4142
import org.hl7.fhir.instance.model.api.IBaseResource;
43+
import org.slf4j.Logger;
4244
import org.springframework.beans.factory.annotation.Autowired;
4345

4446
import java.util.ArrayList;
@@ -50,6 +52,7 @@
5052

5153
public abstract class BaseRequestPartitionHelperSvc implements IRequestPartitionHelperSvc {
5254

55+
public static final Logger ourLog = Logs.getPartitionTroubleshootingLog();
5356
private final HashSet<Object> myNonPartitionableResourceNames;
5457

5558
@Autowired
@@ -61,7 +64,7 @@ public abstract class BaseRequestPartitionHelperSvc implements IRequestPartition
6164
@Autowired
6265
PartitionSettings myPartitionSettings;
6366

64-
public BaseRequestPartitionHelperSvc() {
67+
protected BaseRequestPartitionHelperSvc() {
6568
myNonPartitionableResourceNames = new HashSet<>();
6669

6770
// Infrastructure
@@ -107,6 +110,7 @@ public RequestPartitionId determineReadPartitionForRequest(
107110
// SystemRequestDetails instead.
108111
if (requestDetails == null) {
109112
requestDetails = new SystemRequestDetails();
113+
logSubstitutingDefaultSystemRequestDetails();
110114
}
111115

112116
boolean nonPartitionableResource = isResourceNonPartitionable(resourceType);
@@ -117,33 +121,84 @@ public RequestPartitionId determineReadPartitionForRequest(
117121
&& systemRequestHasExplicitPartition((SystemRequestDetails) requestDetails)
118122
&& !nonPartitionableResource) {
119123
requestPartitionId = getSystemRequestPartitionId((SystemRequestDetails) requestDetails, false);
124+
logSystemRequestDetailsResolution((SystemRequestDetails) requestDetails);
125+
120126
} else if ((requestDetails instanceof SystemRequestDetails) && nonPartitionableResource) {
121127
requestPartitionId = RequestPartitionId.fromPartitionId(myPartitionSettings.getDefaultPartitionId());
128+
logSystemRequestDetailsResolution((SystemRequestDetails) requestDetails);
129+
logNonPartitionableType(resourceType);
122130
} else {
131+
// TODO mb: why is this path different than create?
132+
// Here, a non-partitionable resource is still delivered to the pointcuts.
123133
IInterceptorBroadcaster compositeBroadcaster =
124134
CompositeInterceptorBroadcaster.newCompositeBroadcaster(myInterceptorBroadcaster, requestDetails);
125135
if (compositeBroadcaster.hasHooks(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY)) {
126-
// Interceptor call: STORAGE_PARTITION_IDENTIFY_ANY
127-
HookParams params = new HookParams()
128-
.add(RequestDetails.class, requestDetails)
129-
.addIfMatchesType(ServletRequestDetails.class, requestDetails);
130-
requestPartitionId = (RequestPartitionId)
131-
compositeBroadcaster.callHooksAndReturnObject(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY, params);
136+
requestPartitionId = callAnyPointcut(compositeBroadcaster, requestDetails);
132137
} else if (compositeBroadcaster.hasHooks(Pointcut.STORAGE_PARTITION_IDENTIFY_READ)) {
133-
// Interceptor call: STORAGE_PARTITION_IDENTIFY_READ
134-
HookParams params = new HookParams()
135-
.add(RequestDetails.class, requestDetails)
136-
.addIfMatchesType(ServletRequestDetails.class, requestDetails)
137-
.add(ReadPartitionIdRequestDetails.class, theDetails);
138-
requestPartitionId = (RequestPartitionId)
139-
compositeBroadcaster.callHooksAndReturnObject(Pointcut.STORAGE_PARTITION_IDENTIFY_READ, params);
138+
requestPartitionId = callReadPointcut(compositeBroadcaster, requestDetails, theDetails);
140139
}
141140
}
142141

143142
validateRequestPartitionNotNull(
144143
requestPartitionId, Pointcut.STORAGE_PARTITION_IDENTIFY_ANY, Pointcut.STORAGE_PARTITION_IDENTIFY_READ);
145144

146-
return validateAndNormalizePartition(requestPartitionId, requestDetails, resourceType);
145+
RequestPartitionId resultRequestPartitionId =
146+
validateAndNormalizePartition(requestPartitionId, requestDetails, resourceType);
147+
logTroubleshootingResult("read", resourceType, theRequest, resultRequestPartitionId);
148+
149+
return resultRequestPartitionId;
150+
}
151+
152+
private static RequestPartitionId callAnyPointcut(
153+
IInterceptorBroadcaster compositeBroadcaster, RequestDetails requestDetails) {
154+
// Interceptor call: STORAGE_PARTITION_IDENTIFY_ANY
155+
HookParams params = new HookParams()
156+
.add(RequestDetails.class, requestDetails)
157+
.addIfMatchesType(ServletRequestDetails.class, requestDetails);
158+
159+
return callAndLog(compositeBroadcaster, Pointcut.STORAGE_PARTITION_IDENTIFY_ANY, params);
160+
}
161+
162+
private static RequestPartitionId callCreatePointcut(
163+
IInterceptorBroadcaster compositeBroadcaster,
164+
RequestDetails requestDetails,
165+
@Nonnull IBaseResource theResource) {
166+
// Interceptor call: STORAGE_PARTITION_IDENTIFY_CREATE
167+
HookParams params = new HookParams()
168+
.add(IBaseResource.class, theResource)
169+
.add(RequestDetails.class, requestDetails)
170+
.addIfMatchesType(ServletRequestDetails.class, requestDetails);
171+
172+
return callAndLog(compositeBroadcaster, Pointcut.STORAGE_PARTITION_IDENTIFY_CREATE, params);
173+
}
174+
175+
private static RequestPartitionId callAndLog(
176+
IInterceptorBroadcaster compositeBroadcaster, Pointcut pointcut, HookParams params) {
177+
RequestPartitionId result =
178+
(RequestPartitionId) compositeBroadcaster.callHooksAndReturnObject(pointcut, params);
179+
180+
if (ourLog.isTraceEnabled()) {
181+
ourLog.trace(
182+
"{}: result={} hooks={}", pointcut, result, compositeBroadcaster.getInvokersForPointcut(pointcut));
183+
}
184+
return result;
185+
}
186+
187+
private static RequestPartitionId callReadPointcut(
188+
IInterceptorBroadcaster compositeBroadcaster,
189+
RequestDetails requestDetails,
190+
@Nonnull ReadPartitionIdRequestDetails theDetails) {
191+
// Interceptor call: STORAGE_PARTITION_IDENTIFY_READ
192+
HookParams params = new HookParams()
193+
.add(RequestDetails.class, requestDetails)
194+
.addIfMatchesType(ServletRequestDetails.class, requestDetails)
195+
.add(ReadPartitionIdRequestDetails.class, theDetails);
196+
197+
return callAndLog(compositeBroadcaster, Pointcut.STORAGE_PARTITION_IDENTIFY_READ, params);
198+
}
199+
200+
private static void logNonPartitionableType(String theResourceType) {
201+
ourLog.trace("Partitioning: resource type {} must be on the DEFAULT partition.", theResourceType);
147202
}
148203

149204
@Override
@@ -157,16 +212,12 @@ public RequestPartitionId determineGenericPartitionForRequest(RequestDetails the
157212
if (theRequestDetails instanceof SystemRequestDetails
158213
&& systemRequestHasExplicitPartition((SystemRequestDetails) theRequestDetails)) {
159214
requestPartitionId = getSystemRequestPartitionId((SystemRequestDetails) theRequestDetails);
215+
logSystemRequestDetailsResolution((SystemRequestDetails) theRequestDetails);
160216
} else {
161217
IInterceptorBroadcaster compositeBroadcaster = CompositeInterceptorBroadcaster.newCompositeBroadcaster(
162218
myInterceptorBroadcaster, theRequestDetails);
163219
if (compositeBroadcaster.hasHooks(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY)) {
164-
// Interceptor call: STORAGE_PARTITION_IDENTIFY_ANY
165-
HookParams params = new HookParams()
166-
.add(RequestDetails.class, theRequestDetails)
167-
.addIfMatchesType(ServletRequestDetails.class, theRequestDetails);
168-
requestPartitionId = (RequestPartitionId)
169-
compositeBroadcaster.callHooksAndReturnObject(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY, params);
220+
requestPartitionId = callAnyPointcut(compositeBroadcaster, theRequestDetails);
170221
}
171222
}
172223

@@ -175,10 +226,13 @@ && systemRequestHasExplicitPartition((SystemRequestDetails) theRequestDetails))
175226
// validateRequestPartitionNotNull(requestPartitionId, Pointcut.STORAGE_PARTITION_IDENTIFY_ANY);
176227

177228
if (requestPartitionId != null) {
178-
return validateAndNormalizePartition(
229+
requestPartitionId = validateAndNormalizePartition(
179230
requestPartitionId, theRequestDetails, theRequestDetails.getResourceName());
180231
}
181-
return null;
232+
233+
logTroubleshootingResult("generic", theRequestDetails.getResourceName(), theRequestDetails, requestPartitionId);
234+
235+
return requestPartitionId;
182236
}
183237

184238
/**
@@ -240,37 +294,30 @@ public RequestPartitionId determineCreatePartitionForRequest(
240294
// SystemRequestDetails instead.
241295
if (theRequest == null) {
242296
requestDetails = new SystemRequestDetails();
297+
logSubstitutingDefaultSystemRequestDetails();
243298
}
244299

245300
RequestPartitionId requestPartitionId = null;
246301
if (theRequest instanceof SystemRequestDetails
247302
&& systemRequestHasExplicitPartition((SystemRequestDetails) theRequest)) {
248303
requestPartitionId =
249304
getSystemRequestPartitionId((SystemRequestDetails) theRequest, nonPartitionableResource);
305+
306+
logSystemRequestDetailsResolution((SystemRequestDetails) theRequest);
250307
} else {
251308
IInterceptorBroadcaster compositeBroadcaster =
252309
CompositeInterceptorBroadcaster.newCompositeBroadcaster(myInterceptorBroadcaster, requestDetails);
253310
if (compositeBroadcaster.hasHooks(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY)) {
254-
// Interceptor call: STORAGE_PARTITION_IDENTIFY_ANY
255-
HookParams params = new HookParams()
256-
.add(RequestDetails.class, requestDetails)
257-
.addIfMatchesType(ServletRequestDetails.class, requestDetails);
258-
requestPartitionId = (RequestPartitionId)
259-
compositeBroadcaster.callHooksAndReturnObject(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY, params);
311+
requestPartitionId = callAnyPointcut(compositeBroadcaster, requestDetails);
260312
} else if (compositeBroadcaster.hasHooks(Pointcut.STORAGE_PARTITION_IDENTIFY_CREATE)) {
261-
// Interceptor call: STORAGE_PARTITION_IDENTIFY_CREATE
262-
HookParams params = new HookParams()
263-
.add(IBaseResource.class, theResource)
264-
.add(RequestDetails.class, requestDetails)
265-
.addIfMatchesType(ServletRequestDetails.class, requestDetails);
266-
requestPartitionId = (RequestPartitionId) compositeBroadcaster.callHooksAndReturnObject(
267-
Pointcut.STORAGE_PARTITION_IDENTIFY_CREATE, params);
313+
requestPartitionId = callCreatePointcut(compositeBroadcaster, requestDetails, theResource);
268314
}
269315
}
270316

271317
// If the interceptors haven't selected a partition, and its a non-partitionable resource anyhow, send
272318
// to DEFAULT
273319
if (nonPartitionableResource && requestPartitionId == null) {
320+
logNonPartitionableType(theResourceType);
274321
requestPartitionId = RequestPartitionId.defaultPartition();
275322
}
276323

@@ -280,7 +327,12 @@ && systemRequestHasExplicitPartition((SystemRequestDetails) theRequest)) {
280327
Pointcut.STORAGE_PARTITION_IDENTIFY_ANY);
281328
validatePartitionForCreate(requestPartitionId, theResourceType);
282329

283-
return validateAndNormalizePartition(requestPartitionId, requestDetails, theResourceType);
330+
RequestPartitionId resultRequestPartitionId =
331+
validateAndNormalizePartition(requestPartitionId, requestDetails, theResourceType);
332+
333+
logTroubleshootingResult("create", theResourceType, theRequest, resultRequestPartitionId);
334+
335+
return resultRequestPartitionId;
284336
}
285337

286338
private boolean systemRequestHasExplicitPartition(@Nonnull SystemRequestDetails theRequest) {
@@ -336,6 +388,8 @@ && hasDefaultPartitionId(retVal)) {
336388
retVal = RequestPartitionId.fromPartitionIds(partitionIds);
337389
}
338390

391+
ourLog.trace("Partition normalization: {} -> {}", theRequestPartitionId, retVal);
392+
339393
return retVal;
340394
}
341395

@@ -418,4 +472,28 @@ private static void validateSinglePartitionIdOrName(@Nullable List<?> thePartiti
418472
+ thePartitionIds);
419473
}
420474
}
475+
476+
private static void logTroubleshootingResult(
477+
String theAction,
478+
String theResourceType,
479+
@Nullable RequestDetails theRequest,
480+
RequestPartitionId theResult) {
481+
String tenantId = theRequest != null ? theRequest.getTenantId() : null;
482+
ourLog.debug(
483+
"Partitioning: action={} resource type={} with request tenant ID={} routed to RequestPartitionId={}",
484+
theAction,
485+
theResourceType,
486+
tenantId,
487+
theResult);
488+
}
489+
490+
private void logSystemRequestDetailsResolution(SystemRequestDetails theRequest) {
491+
ourLog.trace(
492+
"Partitioning: request is a SystemRequestDetails, with RequestPartitionId={}.",
493+
theRequest.getRequestPartitionId());
494+
}
495+
496+
private static void logSubstitutingDefaultSystemRequestDetails() {
497+
ourLog.trace("No RequestDetails present. Using default SystemRequestDetails.");
498+
}
421499
}

0 commit comments

Comments
 (0)