Raw sql revincludes (#5001)

* start building tests

* add test

* Basic test and fix bug

* remove tests, fix existing test

* fix up tests

* fix up tests

---------

Co-authored-by: Ken Stevens <ken@smilecdr.com>

hapi-fhir-docs/src/main/resources/ca/uhn/hapi/fhir/changelog/6_8_0/5000-revincludes-not-tracked-in-sql-tracing.yaml

@@ -0,0 +1,4 @@
+---
+type: fix
+issue: 5000
+title: "Previously, the JPA_PERFTRACE_RAW_SQL was not firing for raw sql that occurred during a `revinclude` or `include`. This has been corrected."

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

@@ -67,7 +67,6 @@ import ca.uhn.fhir.jpa.searchparam.util.LastNParameterHelper;
 import ca.uhn.fhir.jpa.util.BaseIterator;
 import ca.uhn.fhir.jpa.util.CurrentThreadCaptureQueriesListener;
 import ca.uhn.fhir.jpa.util.QueryChunker;
-import ca.uhn.fhir.jpa.util.QueryParameterUtils;
 import ca.uhn.fhir.jpa.util.SqlQueryList;
 import ca.uhn.fhir.model.api.IQueryParameterType;
 import ca.uhn.fhir.model.api.Include;
@@ -1149,7 +1148,9 @@ public class SearchBuilder implements ISearchBuilder<JpaPid> {
 		String searchIdOrDescription = theParameters.getSearchIdOrDescription();
 		List<String> desiredResourceTypes = theParameters.getDesiredResourceTypes();
 		boolean hasDesiredResourceTypes = desiredResourceTypes != null && !desiredResourceTypes.isEmpty();
-
+		if (CompositeInterceptorBroadcaster.hasHooks(Pointcut.JPA_PERFTRACE_RAW_SQL, myInterceptorBroadcaster, theParameters.getRequestDetails())) {
+			CurrentThreadCaptureQueriesListener.startCapturing();
+		}
 		if (matches.size() == 0) {
 			return new HashSet<>();
 		}
@@ -1395,6 +1396,11 @@ public class SearchBuilder implements ISearchBuilder<JpaPid> {
 
 		ourLog.info("Loaded {} {} in {} rounds and {} ms for search {}", allAdded.size(), reverseMode ? "_revincludes" : "_includes", roundCounts, w.getMillisAndRestart(), searchIdOrDescription);
 
+
+
+		if (CompositeInterceptorBroadcaster.hasHooks(Pointcut.JPA_PERFTRACE_RAW_SQL, myInterceptorBroadcaster, request)) {
+			callRawSqlHookWithCurrentThreadQueries(request);
+		}
 		// Interceptor call: STORAGE_PREACCESS_RESOURCES
 		// This can be used to remove results from the search result details before
 		// the user has a chance to know that they were in the results
@@ -1423,6 +1429,19 @@ public class SearchBuilder implements ISearchBuilder<JpaPid> {
 		return allAdded;
 	}
 
+	/**
+	 * Given a
+	 * @param request
+	 */
+	private void callRawSqlHookWithCurrentThreadQueries(RequestDetails request) {
+		SqlQueryList capturedQueries = CurrentThreadCaptureQueriesListener.getCurrentQueueAndStopCapturing();
+		HookParams params = new HookParams()
+			.add(RequestDetails.class, request)
+			.addIfMatchesType(ServletRequestDetails.class, request)
+			.add(SqlQueryList.class, capturedQueries);
+		CompositeInterceptorBroadcaster.doCallHooks(myInterceptorBroadcaster, request, Pointcut.JPA_PERFTRACE_RAW_SQL, params);
+	}
+
 	@Nullable
 	private static Set<String> computeTargetResourceTypes(Include nextInclude, RuntimeSearchParam param) {
 		String targetResourceType = defaultString(nextInclude.getParamTargetType(), null);
@@ -1865,12 +1884,7 @@ public class SearchBuilder implements ISearchBuilder<JpaPid> {
 			} finally {
 				// search finished - fire hooks
 				if (myHaveRawSqlHooks) {
-					SqlQueryList capturedQueries = CurrentThreadCaptureQueriesListener.getCurrentQueueAndStopCapturing();
+					callRawSqlHookWithCurrentThreadQueries(myRequest);
-					HookParams params = new HookParams()
-						.add(RequestDetails.class, myRequest)
-						.addIfMatchesType(ServletRequestDetails.class, myRequest)
-						.add(SqlQueryList.class, capturedQueries);
-					CompositeInterceptorBroadcaster.doCallHooks(myInterceptorBroadcaster, myRequest, Pointcut.JPA_PERFTRACE_RAW_SQL, params);
 				}
 			}
 

hapi-fhir-jpaserver-test-r4/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4QueryCountTest.java

@@ -258,6 +258,7 @@ public class FhirResourceDaoR4QueryCountTest extends BaseResourceProviderR4Test
 		assertEquals(0, myCaptureQueriesListener.getDeleteQueriesForCurrentThread().size());
 	}
 
+
 	/**
 	 * See the class javadoc before changing the counts in this test!
 	 */

hapi-fhir-jpaserver-test-r4/src/test/java/ca/uhn/fhir/jpa/dao/r4/SearchWithInterceptorR4Test.java

@@ -24,6 +24,7 @@ public class SearchWithInterceptorR4Test extends BaseJpaR4Test {
 	private static final org.slf4j.Logger ourLog = org.slf4j.LoggerFactory.getLogger(SearchWithInterceptorR4Test.class);
 
 
+
 	@Test
 	public void testRawSql_Search() {
 		myStorageSettings.setAdvancedHSearchIndexing(false);

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

@@ -8,7 +8,6 @@ import ca.uhn.fhir.jpa.dao.data.ISearchDao;
 import ca.uhn.fhir.jpa.entity.Search;
 import ca.uhn.fhir.jpa.model.entity.NormalizedQuantitySearchLevel;
 import ca.uhn.fhir.jpa.model.entity.ResourceHistoryTable;
-import ca.uhn.fhir.jpa.model.entity.ResourceIndexedSearchParamToken;
 import ca.uhn.fhir.jpa.model.entity.ResourceIndexedSearchParamUri;
 import ca.uhn.fhir.jpa.model.entity.StorageSettings;
 import ca.uhn.fhir.jpa.model.util.JpaConstants;
@@ -279,7 +278,6 @@ public class ResourceProviderR4Test extends BaseResourceProviderR4Test {
 		searchParameter.setXpathUsage(SearchParameter.XPathUsageType.NORMAL);
 		searchParameter.setStatus(Enumerations.PublicationStatus.ACTIVE);
 		myClient.create().resource(searchParameter).execute();
-
 		mySearchParamRegistry.forceRefresh();
 
 		HttpGet get = new HttpGet(myServerBase + "/Procedure?focalAccess.a%20ne%20e");

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

@@ -0,0 +1,115 @@
+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.provider.BaseResourceProviderR4Test;
+import ca.uhn.fhir.jpa.util.SqlQuery;
+import ca.uhn.fhir.jpa.util.SqlQueryList;
+import ca.uhn.fhir.model.api.Include;
+import ca.uhn.fhir.rest.api.CacheControlDirective;
+import ca.uhn.fhir.rest.api.server.RequestDetails;
+import ca.uhn.fhir.util.BundleUtil;
+import org.hl7.fhir.instance.model.api.IBaseResource;
+import org.hl7.fhir.instance.model.api.IIdType;
+import org.hl7.fhir.r4.model.Bundle;
+import org.hl7.fhir.r4.model.CareTeam;
+import org.hl7.fhir.r4.model.Condition;
+import org.hl7.fhir.r4.model.DetectedIssue;
+import org.hl7.fhir.r4.model.Group;
+import org.hl7.fhir.r4.model.Patient;
+import org.hl7.fhir.r4.model.Reference;
+import org.junit.jupiter.api.Test;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.springframework.test.context.jdbc.Sql;
+
+import java.util.ArrayList;
+import java.util.List;
+import java.util.regex.Pattern;
+
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.Matchers.hasSize;
+import static org.hamcrest.Matchers.matchesPattern;
+import static org.junit.jupiter.api.Assertions.assertEquals;
+
+public class ResourceProviderRevIncludeTest extends BaseResourceProviderR4Test {
+
+	private static final Logger ourLog = LoggerFactory.getLogger(ResourceProviderRevIncludeTest.class);
+
+
+
+	class SqlCapturingInterceptor {
+		SqlQueryList queryList = null;
+		@Hook(Pointcut.JPA_PERFTRACE_RAW_SQL)
+		public void trackRequest(RequestDetails theRequestDetails, SqlQueryList theQueryList) {
+			if (queryList == null) {
+				queryList = theQueryList;
+			} else {
+				queryList.addAll(theQueryList);
+			}
+		}
+
+		public SqlQueryList getQueryList() {
+			return queryList;
+		}
+	}
+
+	@Test
+	public void testRevincludeIterate() {
+		// /Patient?_id=123&_revinclude:iterate=CareTeam:subject:Group&_revinclude=Group:member:Patient&_revinclude=DetectedIssue:patient
+
+		Patient p = new Patient();
+		String methodName = "testRevincludeIterate";
+		p.addName().setFamily(methodName);
+		IIdType pid = myClient.create().resource(p).execute().getId().toUnqualifiedVersionless();
+		ourLog.info("Created patient: {}", pid.getValue()); // 1
+
+		Group g = new Group();
+		g.addMember().setEntity(new Reference(pid));
+		IIdType gid = myClient.create().resource(g).execute().getId().toUnqualifiedVersionless();
+		ourLog.info("Created group: {}", gid.getValue()); // 2
+
+		CareTeam ct = new CareTeam();
+		ct.getSubject().setReferenceElement(gid);
+		IIdType ctid = myClient.create().resource(ct).execute().getId().toUnqualifiedVersionless();
+		ourLog.info("Created care team: {}", ctid.getValue()); // 3
+
+		List<IIdType> dids = new ArrayList<>();
+		for (int i = 0; i < 100; ++i){
+			DetectedIssue di = new DetectedIssue();
+			di.getPatient().setReferenceElement(pid);
+			IIdType diid = myClient.create().resource(di).execute().getId().toUnqualifiedVersionless();
+			ourLog.info("Created detected issue: {}", diid.getValue()); // 4...103
+			dids.add(diid);
+		}
+		SqlCapturingInterceptor sqlCapturingInterceptor = new SqlCapturingInterceptor();
+		myCaptureQueriesListener.clear();
+		myInterceptorRegistry.registerInterceptor(sqlCapturingInterceptor);
+		Bundle bundle = myClient.search()
+			.forResource(Patient.class)
+			.count(200)
+			.where(Patient.RES_ID.exactly().codes(pid.getIdPart()))
+			.revInclude(new Include("CareTeam:subject:Group").setRecurse(true))
+//			.revInclude(new Include("CareTeam:subject:Group"))
+			.revInclude(new Include("Group:member:Patient"))
+			.revInclude(DetectedIssue.INCLUDE_PATIENT)
+			.returnBundle(Bundle.class)
+			.execute();
+
+		List<IBaseResource> foundResources = BundleUtil.toListOfResources(myFhirContext, bundle);
+		Patient patient = (Patient) foundResources.get(0);
+		Group group = (Group) foundResources.get(1);
+		CareTeam careTeam = (CareTeam) foundResources.get(2);
+		DetectedIssue detectedIssue = (DetectedIssue) foundResources.get(3);
+		assertEquals(pid.getIdPart(), patient.getIdElement().getIdPart());
+		assertEquals(gid.getIdPart(), group.getIdElement().getIdPart());
+		assertEquals(ctid.getIdPart(), careTeam.getIdElement().getIdPart());
+		assertEquals(methodName, patient.getName().get(0).getFamily());
+
+		//Ensure that the revincludes are included in the query list of the sql trace.
+		//TODO GGG/KHS reduce this to something less than 6 by smarter iterating and getting the resource types earlier when needed.
+		assertEquals(6, sqlCapturingInterceptor.getQueryList().size());
+		myInterceptorRegistry.unregisterInterceptor(sqlCapturingInterceptor);
+	}
+
+}