Add some test logging

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

@@ -1599,6 +1599,33 @@ public enum Pointcut {
 	),
 
 
+	/**
+	 * THIS IS AN EXPERIMENTAL HOOK AND MAY BE REMOVED OR CHANGED WITHOUT WARNING.
+	 *
+	 * Note that this is a performance tracing hook. Use with caution in production
+	 * systems, since calling it may (or may not) carry a cost.
+	 * <p>
+	 * This hook is invoked when a search has found an individual ID.
+	 * </p>
+	 * Hooks may accept the following parameters:
+	 * <ul>
+	 * <li>
+	 * java.lang.Integer - The query ID
+	 * </li>
+	 * <li>
+	 * java.lang.Object - The ID
+	 * </li>
+	 * </ul>
+	 * <p>
+	 * Hooks should return <code>void</code>.
+	 * </p>
+	 */
+	JPA_PERFTRACE_SEARCH_FOUND_ID(void.class,
+		"java.lang.Integer",
+		"java.lang.Object"
+	),
+
+
 	/**
 	 * Note that this is a performance tracing hook. Use with caution in production
 	 * systems, since calling it may (or may not) carry a cost.

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/SearchBuilder.java

@@ -3141,6 +3141,8 @@ public class SearchBuilder implements ISearchBuilder {
 
 		private final SearchRuntimeDetails mySearchRuntimeDetails;
 		private final RequestDetails myRequest;
+		private final boolean myHaveRawSqlHooks;
+		private final boolean myHavePerftraceFoundIdHook;
 		private boolean myFirst = true;
 		private IncludesIterator myIncludesIterator;
 		private Long myNext;
@@ -3159,13 +3161,16 @@ public class SearchBuilder implements ISearchBuilder {
 			if (myParams.getEverythingMode() != null) {
 				myStillNeedToFetchIncludes = true;
 			}
+
+			myHavePerftraceFoundIdHook =JpaInterceptorBroadcaster.hasHooks(Pointcut.JPA_PERFTRACE_SEARCH_FOUND_ID, myInterceptorBroadcaster, myRequest);
+			myHaveRawSqlHooks = JpaInterceptorBroadcaster.hasHooks(Pointcut.JPA_PERFTRACE_RAW_SQL, myInterceptorBroadcaster, myRequest);
+
 		}
 
 		private void fetchNext() {
 
-			boolean haveRawSqlHooks = JpaInterceptorBroadcaster.hasHooks(Pointcut.JPA_PERFTRACE_RAW_SQL, myInterceptorBroadcaster, myRequest);
 			try {
-				if (haveRawSqlHooks) {
+				if (myHaveRawSqlHooks) {
 					CurrentThreadCaptureQueriesListener.startCapturing();
 				}
 
@@ -3206,6 +3211,13 @@ public class SearchBuilder implements ISearchBuilder {
 					if (myNext == null) {
 						while (myResultsIterator.hasNext()) {
 							Long next = myResultsIterator.next();
+							if (myHavePerftraceFoundIdHook) {
+								HookParams params = new HookParams()
+									.add(Integer.class, System.identityHashCode(this))
+									.add(Object.class, next);
+								JpaInterceptorBroadcaster.doCallHooks(myInterceptorBroadcaster, myRequest, Pointcut.JPA_PERFTRACE_SEARCH_FOUND_ID, params);
+							}
+
 							if (next != null) {
 								if (myPidSet.add(next)) {
 									myNext = next;
@@ -3244,7 +3256,7 @@ public class SearchBuilder implements ISearchBuilder {
 				mySearchRuntimeDetails.setFoundMatchesCount(myPidSet.size());
 
 			} finally {
-				if (haveRawSqlHooks) {
+				if (myHaveRawSqlHooks) {
 					SqlQueryList capturedQueries = CurrentThreadCaptureQueriesListener.getCurrentQueueAndStopCapturing();
 					HookParams params = new HookParams()
 						.add(RequestDetails.class, myRequest)

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/provider/r4/ResourceProviderCustomSearchParamR4Test.java

@@ -1,5 +1,7 @@
 package ca.uhn.fhir.jpa.provider.r4;
 
+import ca.uhn.fhir.interceptor.api.Hook;
+import ca.uhn.fhir.interceptor.api.Pointcut;
 import ca.uhn.fhir.jpa.dao.BaseHapiFhirDao;
 import ca.uhn.fhir.jpa.dao.DaoConfig;
 import ca.uhn.fhir.jpa.entity.ResourceReindexJobEntity;
@@ -35,7 +37,6 @@ import org.springframework.transaction.TransactionStatus;
 import org.springframework.transaction.support.TransactionCallbackWithoutResult;
 import org.springframework.transaction.support.TransactionTemplate;
 
-import java.io.IOException;
 import java.util.ArrayList;
 import java.util.HashMap;
 import java.util.List;
@@ -450,6 +451,17 @@ public class ResourceProviderCustomSearchParamR4Test extends BaseResourceProvide
 	@Test
 	public void testCustomParameterMatchingManyValues() {
 
+		List<String> found = new ArrayList<>();
+
+		class Interceptor {
+			@Hook(Pointcut.JPA_PERFTRACE_SEARCH_FOUND_ID)
+			public void foundId(Integer theSearchId, Object theId) {
+				found.add(theSearchId + "/" + theId);
+			}
+		}
+		Interceptor interceptor = new Interceptor();
+		myInterceptorRegistry.registerInterceptor(interceptor);
+		try {
 			myDaoConfig.setAllowContainsSearches(true);
 
 			// Add a custom search parameter
@@ -531,6 +543,7 @@ public class ResourceProviderCustomSearchParamR4Test extends BaseResourceProvide
 
 			} while (bundle.getLink("next") != null);
 
+			ourLog.info("Found: {}", found);
 
 			runInTransaction(() -> {
 
@@ -539,6 +552,7 @@ public class ResourceProviderCustomSearchParamR4Test extends BaseResourceProvide
 				Search search = searches.get(0);
 				String message = "\nWanted: " + ids + "\n" +
 					"Actual: " + actualIds + "\n" +
+					"Found : " + found + "\n" +
 					search.toString();
 				assertEquals(message, 200, search.getNumFound());
 				assertEquals(message, 200, search.getTotalCount().intValue());
@@ -546,7 +560,9 @@ public class ResourceProviderCustomSearchParamR4Test extends BaseResourceProvide
 			});
 
 			assertEquals(200, foundCount);
-
+		} finally {
+			myInterceptorRegistry.unregisterInterceptor(interceptor);
+		}
 	}