Add troubleshooting log for partition routing.

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

@@ -2097,6 +2097,7 @@ public enum Pointcut implements IPointcut {
 	 * This hook is an alternative to {@link #STORAGE_PARTITION_IDENTIFY_READ} and {@link #STORAGE_PARTITION_IDENTIFY_CREATE}
 	 * and can be used in cases where a partition interceptor does not need knowledge of the specific resources being
 	 * accessed/read/written in order to determine the appropriate partition.
+	 * If registered, then neither STORAGE_PARTITION_IDENTIFY_READ, nor STORAGE_PARTITION_IDENTIFY_CREATE will be called.
 	 * </p>
 	 * <p>
 	 * This hook will only be called if

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

@@ -23,30 +23,16 @@
 import org.slf4j.LoggerFactory;
 
 public class Logs {
-	private static final Logger ourBatchTroubleshootingLog =
-			LoggerFactory.getLogger("ca.uhn.fhir.log.batch_troubleshooting");
-	private static final Logger ourNarrativeGenerationTroubleshootingLog =
-			LoggerFactory.getLogger("ca.uhn.fhir.log.narrative_generation_troubleshooting");
-
-	private static final Logger ourTerminologyTroubleshootingLog =
-			LoggerFactory.getLogger("ca.uhn.fhir.log.terminology_troubleshooting");
-
-	private static final Logger ourSubscriptionTroubleshootingLog =
-			LoggerFactory.getLogger("ca.cdr.log.subscription_troubleshooting");
-
-	private static final Logger ourSubscriptionTopicLog =
-			LoggerFactory.getLogger("ca.uhn.fhir.log.subscription_topic_troubleshooting");
-
 	public static Logger getBatchTroubleshootingLog() {
 		return ourBatchTroubleshootingLog;
 	}
 
 	public static Logger getNarrativeGenerationTroubleshootingLog() {
-		return ourBatchTroubleshootingLog;
+		return ourNarrativeGenerationTroubleshootingLog;
 	}
 
-	public static Logger getTerminologyTroubleshootingLog() {
-		return ourTerminologyTroubleshootingLog;
+	public static Logger getPartitionTroubleshootingLog() {
+		return ourPartitionTroubleshootingLog;
 	}
 
 	public static Logger getSubscriptionTroubleshootingLog() {
@@ -56,4 +42,36 @@ public static Logger getSubscriptionTroubleshootingLog() {
 	public static Logger getSubscriptionTopicLog() {
 		return ourSubscriptionTopicLog;
 	}
+
+	public static Logger getTerminologyTroubleshootingLog() {
+		return ourTerminologyTroubleshootingLog;
+	}
+
+	public static final String CA_UHN_FHIR_LOG_BATCH_TROUBLESHOOTING = "ca.uhn.fhir.log.batch_troubleshooting";
+	public static final String CA_UHN_FHIR_LOG_NARRATIVE_GENERATION_TROUBLESHOOTING =
+			"ca.uhn.fhir.log.narrative_generation_troubleshooting";
+	public static final String CA_UHN_FHIR_LOG_PARTITION_TROUBLESHOOTING = "ca.uhn.fhir.log.partition_troubleshooting";
+	public static final String CA_UHN_FHIR_LOG_TERMINOLOGY_TROUBLESHOOTING =
+			"ca.uhn.fhir.log.terminology_troubleshooting";
+	public static final String CA_CDR_LOG_SUBSCRIPTION_TROUBLESHOOTING = "ca.cdr.log.subscription_troubleshooting";
+	public static final String CA_UHN_FHIR_LOG_SUBSCRIPTION_TOPIC_TROUBLESHOOTING =
+			"ca.uhn.fhir.log.subscription_topic_troubleshooting";
+
+	private static final Logger ourBatchTroubleshootingLog =
+			LoggerFactory.getLogger(CA_UHN_FHIR_LOG_BATCH_TROUBLESHOOTING);
+
+	private static final Logger ourNarrativeGenerationTroubleshootingLog =
+			LoggerFactory.getLogger(CA_UHN_FHIR_LOG_NARRATIVE_GENERATION_TROUBLESHOOTING);
+
+	private static final Logger ourPartitionTroubleshootingLog =
+			LoggerFactory.getLogger(CA_UHN_FHIR_LOG_PARTITION_TROUBLESHOOTING);
+
+	private static final Logger ourTerminologyTroubleshootingLog =
+			LoggerFactory.getLogger(CA_UHN_FHIR_LOG_TERMINOLOGY_TROUBLESHOOTING);
+
+	private static final Logger ourSubscriptionTroubleshootingLog =
+			LoggerFactory.getLogger(CA_CDR_LOG_SUBSCRIPTION_TROUBLESHOOTING);
+
+	private static final Logger ourSubscriptionTopicLog =
+			LoggerFactory.getLogger(CA_UHN_FHIR_LOG_SUBSCRIPTION_TOPIC_TROUBLESHOOTING);
 }

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

@@ -0,0 +1,4 @@
+---
+type: add
+issue: 6719
+title: "Added a troubleshooting log for request partition routing."

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

@@ -50,5 +50,7 @@
 	<logger name="org.hibernate.search.backend.lucene.infostream" level="TRACE"/>  -->
 
 	<!-- <logger name="ca.uhn.fhir.log.terminology_troubleshooting" level="TRACE"/> -->
+	 <logger name="ca.uhn.fhir.log.partition_troubleshooting" level="info"/>
+
 
 </configuration>

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

@@ -35,10 +35,12 @@
 import ca.uhn.fhir.rest.server.exceptions.UnprocessableEntityException;
 import ca.uhn.fhir.rest.server.servlet.ServletRequestDetails;
 import ca.uhn.fhir.rest.server.util.CompositeInterceptorBroadcaster;
+import ca.uhn.fhir.util.Logs;
 import jakarta.annotation.Nonnull;
 import jakarta.annotation.Nullable;
 import org.apache.commons.lang3.StringUtils;
 import org.hl7.fhir.instance.model.api.IBaseResource;
+import org.slf4j.Logger;
 import org.springframework.beans.factory.annotation.Autowired;
 
 import java.util.ArrayList;
@@ -50,6 +52,7 @@
 
 public abstract class BaseRequestPartitionHelperSvc implements IRequestPartitionHelperSvc {
 
+	public static final Logger ourLog = Logs.getPartitionTroubleshootingLog();
 	private final HashSet<Object> myNonPartitionableResourceNames;
 
 	@Autowired
@@ -61,7 +64,7 @@ public abstract class BaseRequestPartitionHelperSvc implements IRequestPartition
 	@Autowired
 	PartitionSettings myPartitionSettings;
 
-	public BaseRequestPartitionHelperSvc() {
+	protected BaseRequestPartitionHelperSvc() {
 		myNonPartitionableResourceNames = new HashSet<>();
 
 		// Infrastructure
@@ -107,6 +110,7 @@ public RequestPartitionId determineReadPartitionForRequest(
 		// SystemRequestDetails instead.
 		if (requestDetails == null) {
 			requestDetails = new SystemRequestDetails();
+			logSubstitutingDefaultSystemRequestDetails();
 		}
 
 		boolean nonPartitionableResource = isResourceNonPartitionable(resourceType);
@@ -117,33 +121,84 @@ public RequestPartitionId determineReadPartitionForRequest(
 				&& systemRequestHasExplicitPartition((SystemRequestDetails) requestDetails)
 				&& !nonPartitionableResource) {
 			requestPartitionId = getSystemRequestPartitionId((SystemRequestDetails) requestDetails, false);
+			logSystemRequestDetailsResolution((SystemRequestDetails) requestDetails);
+
 		} else if ((requestDetails instanceof SystemRequestDetails) && nonPartitionableResource) {
 			requestPartitionId = RequestPartitionId.fromPartitionId(myPartitionSettings.getDefaultPartitionId());
+			logSystemRequestDetailsResolution((SystemRequestDetails) requestDetails);
+			logNonPartitionableType(resourceType);
 		} else {
+			// TODO mb: why is this path different than create?
+			//  Here, a non-partitionable resource is still delivered to the pointcuts.
 			IInterceptorBroadcaster compositeBroadcaster =
 					CompositeInterceptorBroadcaster.newCompositeBroadcaster(myInterceptorBroadcaster, requestDetails);
 			if (compositeBroadcaster.hasHooks(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY)) {
-				// Interceptor call: STORAGE_PARTITION_IDENTIFY_ANY
-				HookParams params = new HookParams()
-						.add(RequestDetails.class, requestDetails)
-						.addIfMatchesType(ServletRequestDetails.class, requestDetails);
-				requestPartitionId = (RequestPartitionId)
-						compositeBroadcaster.callHooksAndReturnObject(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY, params);
+				requestPartitionId = callAnyPointcut(compositeBroadcaster, requestDetails);
 			} else if (compositeBroadcaster.hasHooks(Pointcut.STORAGE_PARTITION_IDENTIFY_READ)) {
-				// Interceptor call: STORAGE_PARTITION_IDENTIFY_READ
-				HookParams params = new HookParams()
-						.add(RequestDetails.class, requestDetails)
-						.addIfMatchesType(ServletRequestDetails.class, requestDetails)
-						.add(ReadPartitionIdRequestDetails.class, theDetails);
-				requestPartitionId = (RequestPartitionId)
-						compositeBroadcaster.callHooksAndReturnObject(Pointcut.STORAGE_PARTITION_IDENTIFY_READ, params);
+				requestPartitionId = callReadPointcut(compositeBroadcaster, requestDetails, theDetails);
 			}
 		}
 
 		validateRequestPartitionNotNull(
 				requestPartitionId, Pointcut.STORAGE_PARTITION_IDENTIFY_ANY, Pointcut.STORAGE_PARTITION_IDENTIFY_READ);
 
-		return validateAndNormalizePartition(requestPartitionId, requestDetails, resourceType);
+		RequestPartitionId resultRequestPartitionId =
+				validateAndNormalizePartition(requestPartitionId, requestDetails, resourceType);
+		logTroubleshootingResult("read", resourceType, theRequest, resultRequestPartitionId);
+
+		return resultRequestPartitionId;
+	}
+
+	private static RequestPartitionId callAnyPointcut(
+			IInterceptorBroadcaster compositeBroadcaster, RequestDetails requestDetails) {
+		// Interceptor call: STORAGE_PARTITION_IDENTIFY_ANY
+		HookParams params = new HookParams()
+				.add(RequestDetails.class, requestDetails)
+				.addIfMatchesType(ServletRequestDetails.class, requestDetails);
+
+		return callAndLog(compositeBroadcaster, Pointcut.STORAGE_PARTITION_IDENTIFY_ANY, params);
+	}
+
+	private static RequestPartitionId callCreatePointcut(
+			IInterceptorBroadcaster compositeBroadcaster,
+			RequestDetails requestDetails,
+			@Nonnull IBaseResource theResource) {
+		// Interceptor call: STORAGE_PARTITION_IDENTIFY_CREATE
+		HookParams params = new HookParams()
+				.add(IBaseResource.class, theResource)
+				.add(RequestDetails.class, requestDetails)
+				.addIfMatchesType(ServletRequestDetails.class, requestDetails);
+
+		return callAndLog(compositeBroadcaster, Pointcut.STORAGE_PARTITION_IDENTIFY_CREATE, params);
+	}
+
+	private static RequestPartitionId callAndLog(
+			IInterceptorBroadcaster compositeBroadcaster, Pointcut pointcut, HookParams params) {
+		RequestPartitionId result =
+				(RequestPartitionId) compositeBroadcaster.callHooksAndReturnObject(pointcut, params);
+
+		if (ourLog.isTraceEnabled()) {
+			ourLog.trace(
+					"{}: result={} hooks={}", pointcut, result, compositeBroadcaster.getInvokersForPointcut(pointcut));
+		}
+		return result;
+	}
+
+	private static RequestPartitionId callReadPointcut(
+			IInterceptorBroadcaster compositeBroadcaster,
+			RequestDetails requestDetails,
+			@Nonnull ReadPartitionIdRequestDetails theDetails) {
+		// Interceptor call: STORAGE_PARTITION_IDENTIFY_READ
+		HookParams params = new HookParams()
+				.add(RequestDetails.class, requestDetails)
+				.addIfMatchesType(ServletRequestDetails.class, requestDetails)
+				.add(ReadPartitionIdRequestDetails.class, theDetails);
+
+		return callAndLog(compositeBroadcaster, Pointcut.STORAGE_PARTITION_IDENTIFY_READ, params);
+	}
+
+	private static void logNonPartitionableType(String theResourceType) {
+		ourLog.trace("Partitioning: resource type {} must be on the DEFAULT partition.", theResourceType);
 	}
 
 	@Override
@@ -157,16 +212,12 @@ public RequestPartitionId determineGenericPartitionForRequest(RequestDetails the
 		if (theRequestDetails instanceof SystemRequestDetails
 				&& systemRequestHasExplicitPartition((SystemRequestDetails) theRequestDetails)) {
 			requestPartitionId = getSystemRequestPartitionId((SystemRequestDetails) theRequestDetails);
+			logSystemRequestDetailsResolution((SystemRequestDetails) theRequestDetails);
 		} else {
 			IInterceptorBroadcaster compositeBroadcaster = CompositeInterceptorBroadcaster.newCompositeBroadcaster(
 					myInterceptorBroadcaster, theRequestDetails);
 			if (compositeBroadcaster.hasHooks(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY)) {
-				// Interceptor call: STORAGE_PARTITION_IDENTIFY_ANY
-				HookParams params = new HookParams()
-						.add(RequestDetails.class, theRequestDetails)
-						.addIfMatchesType(ServletRequestDetails.class, theRequestDetails);
-				requestPartitionId = (RequestPartitionId)
-						compositeBroadcaster.callHooksAndReturnObject(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY, params);
+				requestPartitionId = callAnyPointcut(compositeBroadcaster, theRequestDetails);
 			}
 		}
 
@@ -175,10 +226,13 @@ && systemRequestHasExplicitPartition((SystemRequestDetails) theRequestDetails))
 		// validateRequestPartitionNotNull(requestPartitionId, Pointcut.STORAGE_PARTITION_IDENTIFY_ANY);
 
 		if (requestPartitionId != null) {
-			return validateAndNormalizePartition(
+			requestPartitionId = validateAndNormalizePartition(
 					requestPartitionId, theRequestDetails, theRequestDetails.getResourceName());
 		}
-		return null;
+
+		logTroubleshootingResult("generic", theRequestDetails.getResourceName(), theRequestDetails, requestPartitionId);
+
+		return requestPartitionId;
 	}
 
 	/**
@@ -240,37 +294,30 @@ public RequestPartitionId determineCreatePartitionForRequest(
 		// SystemRequestDetails instead.
 		if (theRequest == null) {
 			requestDetails = new SystemRequestDetails();
+			logSubstitutingDefaultSystemRequestDetails();
 		}
 
 		RequestPartitionId requestPartitionId = null;
 		if (theRequest instanceof SystemRequestDetails
 				&& systemRequestHasExplicitPartition((SystemRequestDetails) theRequest)) {
 			requestPartitionId =
 					getSystemRequestPartitionId((SystemRequestDetails) theRequest, nonPartitionableResource);
+
+			logSystemRequestDetailsResolution((SystemRequestDetails) theRequest);
 		} else {
 			IInterceptorBroadcaster compositeBroadcaster =
 					CompositeInterceptorBroadcaster.newCompositeBroadcaster(myInterceptorBroadcaster, requestDetails);
 			if (compositeBroadcaster.hasHooks(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY)) {
-				// Interceptor call: STORAGE_PARTITION_IDENTIFY_ANY
-				HookParams params = new HookParams()
-						.add(RequestDetails.class, requestDetails)
-						.addIfMatchesType(ServletRequestDetails.class, requestDetails);
-				requestPartitionId = (RequestPartitionId)
-						compositeBroadcaster.callHooksAndReturnObject(Pointcut.STORAGE_PARTITION_IDENTIFY_ANY, params);
+				requestPartitionId = callAnyPointcut(compositeBroadcaster, requestDetails);
 			} else if (compositeBroadcaster.hasHooks(Pointcut.STORAGE_PARTITION_IDENTIFY_CREATE)) {
-				// Interceptor call: STORAGE_PARTITION_IDENTIFY_CREATE
-				HookParams params = new HookParams()
-						.add(IBaseResource.class, theResource)
-						.add(RequestDetails.class, requestDetails)
-						.addIfMatchesType(ServletRequestDetails.class, requestDetails);
-				requestPartitionId = (RequestPartitionId) compositeBroadcaster.callHooksAndReturnObject(
-						Pointcut.STORAGE_PARTITION_IDENTIFY_CREATE, params);
+				requestPartitionId = callCreatePointcut(compositeBroadcaster, requestDetails, theResource);
 			}
 		}
 
 		// If the interceptors haven't selected a partition, and its a non-partitionable resource anyhow, send
 		// to DEFAULT
 		if (nonPartitionableResource && requestPartitionId == null) {
+			logNonPartitionableType(theResourceType);
 			requestPartitionId = RequestPartitionId.defaultPartition();
 		}
 
@@ -280,7 +327,12 @@ && systemRequestHasExplicitPartition((SystemRequestDetails) theRequest)) {
 				Pointcut.STORAGE_PARTITION_IDENTIFY_ANY);
 		validatePartitionForCreate(requestPartitionId, theResourceType);
 
-		return validateAndNormalizePartition(requestPartitionId, requestDetails, theResourceType);
+		RequestPartitionId resultRequestPartitionId =
+				validateAndNormalizePartition(requestPartitionId, requestDetails, theResourceType);
+
+		logTroubleshootingResult("create", theResourceType, theRequest, resultRequestPartitionId);
+
+		return resultRequestPartitionId;
 	}
 
 	private boolean systemRequestHasExplicitPartition(@Nonnull SystemRequestDetails theRequest) {
@@ -336,6 +388,8 @@ && hasDefaultPartitionId(retVal)) {
 			retVal = RequestPartitionId.fromPartitionIds(partitionIds);
 		}
 
+		ourLog.trace("Partition normalization: {} -> {}", theRequestPartitionId, retVal);
+
 		return retVal;
 	}
 
@@ -418,4 +472,28 @@ private static void validateSinglePartitionIdOrName(@Nullable List<?> thePartiti
 							+ thePartitionIds);
 		}
 	}
+
+	private static void logTroubleshootingResult(
+			String theAction,
+			String theResourceType,
+			@Nullable RequestDetails theRequest,
+			RequestPartitionId theResult) {
+		String tenantId = theRequest != null ? theRequest.getTenantId() : null;
+		ourLog.debug(
+				"Partitioning: action={} resource type={} with request tenant ID={} routed to RequestPartitionId={}",
+				theAction,
+				theResourceType,
+				tenantId,
+				theResult);
+	}
+
+	private void logSystemRequestDetailsResolution(SystemRequestDetails theRequest) {
+		ourLog.trace(
+				"Partitioning: request is a SystemRequestDetails, with RequestPartitionId={}.",
+				theRequest.getRequestPartitionId());
+	}
+
+	private static void logSubstitutingDefaultSystemRequestDetails() {
+		ourLog.trace("No RequestDetails present.  Using default SystemRequestDetails.");
+	}
 }