Updates to the canonical validation resource cache in VersionSpecificWorkerContextWrapper

hapi-fhir-base/src/main/java/ca/uhn/fhir/system/HapiSystemProperties.java

@@ -19,23 +19,24 @@
  */
 package ca.uhn.fhir.system;
 
-import org.apache.commons.lang3.time.DateUtils;
+import com.google.common.annotations.VisibleForTesting;
+
+import java.util.concurrent.TimeUnit;
 
 public final class HapiSystemProperties {
 	static final String SUPPRESS_HAPI_FHIR_VERSION_LOG = "suppress_hapi_fhir_version_log";
 	static final String DISABLE_STATUS_BASED_REINDEX = "disable_status_based_reindex";
 	/**
 	 * This is provided for testing only! Use with caution as this property may change.
 	 */
-	static final String TEST_SYSTEM_PROP_VALIDATION_RESOURCE_CACHES_MS =
-			"TEST_SYSTEM_PROP_VALIDATION_RESOURCE_CACHES_MS";
+	static final String VALIDATION_RESOURCE_CACHE_TIMEOUT_MILLIS = "VALIDATION_RESOURCE_CACHE_EXPIRY_MS";
 
 	static final String UNIT_TEST_CAPTURE_STACK = "unit_test_capture_stack";
 	static final String STACKFILTER_PATTERN_PROP = "log.stackfilter.pattern";
 	static final String HAPI_CLIENT_KEEPRESPONSES = "hapi.client.keepresponses";
 	static final String TEST_MODE = "test";
 	static final String UNIT_TEST_MODE = "unit_test_mode";
-	static final long DEFAULT_TEST_SYSTEM_PROP_VALIDATION_RESOURCE_CACHES_MS = 10 * DateUtils.MILLIS_PER_SECOND;
+	static final long DEFAULT_VALIDATION_RESOURCE_CACHE_TIMEOUT_MILLIS = TimeUnit.MINUTES.toMillis(10);
 	static final String PREVENT_INVALIDATING_CONDITIONAL_MATCH_CRITERIA =
 			"hapi.storage.prevent_invalidating_conditional_match_criteria";
 
@@ -75,24 +76,31 @@ public static void setStackFilterPattern(String thePattern) {
 	/**
 	 * Set the validation resource cache expireAfterWrite timeout in milliseconds
 	 *
-	 * @param theMillis
+	 * @param theMillis the timeout value to set (in milliseconds)
 	 */
-	public static void setTestValidationResourceCachesMs(long theMillis) {
-		System.setProperty(TEST_SYSTEM_PROP_VALIDATION_RESOURCE_CACHES_MS, "" + theMillis);
+	public static void setValidationResourceCacheTimeoutMillis(long theMillis) {
+		System.setProperty(VALIDATION_RESOURCE_CACHE_TIMEOUT_MILLIS, "" + theMillis);
 	}
 
 	/**
 	 * Get the validation resource cache expireAfterWrite timeout in milliseconds.  If it has not been set, the default
 	 * value is 10 seconds.
 	 */
-	public static long getTestValidationResourceCachesMs() {
-		String property = System.getProperty(TEST_SYSTEM_PROP_VALIDATION_RESOURCE_CACHES_MS);
+	public static long getValidationResourceCacheTimeoutMillis() {
+		String property = System.getProperty(VALIDATION_RESOURCE_CACHE_TIMEOUT_MILLIS);
 		if (property == null) {
-			return DEFAULT_TEST_SYSTEM_PROP_VALIDATION_RESOURCE_CACHES_MS;
+			return DEFAULT_VALIDATION_RESOURCE_CACHE_TIMEOUT_MILLIS;
 		}
 		return Long.parseLong(property);
 	}
 
+	@VisibleForTesting
+	public static void restoreDefaultValidationResourceCacheTimeoutMillis() {
+		System.clearProperty(VALIDATION_RESOURCE_CACHE_TIMEOUT_MILLIS);
+		System.setProperty(
+				VALIDATION_RESOURCE_CACHE_TIMEOUT_MILLIS, "" + DEFAULT_VALIDATION_RESOURCE_CACHE_TIMEOUT_MILLIS);
+	}
+
 	/**
 	 * When this property is primarily used to control application shutdown behavior
 	 */

hapi-fhir-docs/src/main/resources/ca/uhn/hapi/fhir/changelog/7_6_0/6505-validation-errors-profile-cache-expiry.yaml

@@ -0,0 +1,8 @@
+---
+type: fix
+issue: 6505
+title: "Previously, when invoking a $validate operation that took more than 10s some unexpected errors 
+would be returned which suggest the profile was not applied properly or used. 
+That happens because the validation cache entry expired within the $validate call 
+and the FHIR Core Validation library expects the same object instance for the same profile to be returned.
+This has been fixed by increasing the cache expiry to 10min."

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/api/ITermReadSvc.java

@@ -56,6 +56,11 @@
  */
 public interface ITermReadSvc extends IValidationSupport {
 
+	@Override
+	default String getName() {
+		return getClass().getSimpleName() + " JPA Term Read Service";
+	}
+
 	ValueSet expandValueSet(
 			@Nullable ValueSetExpansionOptions theExpansionOptions, @Nonnull String theValueSetCanonicalUrl);
 

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

@@ -1530,7 +1530,7 @@ public void validateResource_withUnknownMetaProfileurl_validatesButLogsWarning()
 		// we have errors
 		assertFalse(errors.isEmpty());
 
-		LogbackTestExtensionAssert.assertThat(myLogbackTestExtension).hasWarnMessage("Unrecognized profile uri");
+		LogbackTestExtensionAssert.assertThat(myLogbackTestExtension).hasWarnMessage("Unrecognized resource uri");
 	}
 
 	@Test

hapi-fhir-jpaserver-test-r4/src/test/java/ca/uhn/fhir/jpa/validation/VersionSpecificWorkerContextR4Test.java

@@ -0,0 +1,202 @@
+package ca.uhn.fhir.jpa.validation;
+
+import ca.uhn.fhir.context.support.IValidationSupport;
+import ca.uhn.fhir.jpa.provider.BaseResourceProviderR4Test;
+import ca.uhn.fhir.system.HapiSystemProperties;
+import ca.uhn.fhir.util.ClasspathUtil;
+import org.apache.commons.lang3.StringUtils;
+import org.hl7.fhir.common.hapi.validation.validator.FhirInstanceValidator;
+import org.hl7.fhir.common.hapi.validation.validator.VersionSpecificWorkerContextWrapper;
+import org.hl7.fhir.r4.model.Bundle;
+import org.hl7.fhir.r4.model.CodeSystem;
+import org.hl7.fhir.r4.model.ElementDefinition;
+import org.hl7.fhir.r4.model.StructureDefinition;
+import org.hl7.fhir.r4.model.ValueSet;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Nested;
+import org.junit.jupiter.api.Test;
+import org.springframework.beans.factory.annotation.Autowired;
+
+import java.util.List;
+
+import static ca.uhn.fhir.test.utilities.validation.ValidationTestUtil.getValidationErrors;
+import static org.assertj.core.api.Assertions.assertThat;
+
+public class VersionSpecificWorkerContextR4Test extends BaseResourceProviderR4Test {
+	@Autowired
+	private FhirInstanceValidator myInstanceValidator;
+	@Autowired
+	private IValidationSupport myValidationSupport;
+
+	@Nested
+	public class ValidateWithCacheNegativeTest {
+		@BeforeEach
+		public void before() {
+			HapiSystemProperties.setValidationResourceCacheTimeoutMillis(1);
+			myInstanceValidator.resetWorkerContext();
+		}
+
+		/**
+		 * If the cache is set to expire quickly, the second retrieval of the profile will result in a different StructureDefinition instance.
+		 * The FHIR Core validation library currently expects the same instance of StructureDefinition to be returned for the same profile.
+		 * This test can be removed if the FHIR Core library is updated to use equals/hashcode but for not this is how it works.
+		 */
+		@Test
+		public void validate_returnsUnexpectedErrors() {
+			// setup
+			StructureDefinition profileProcedure = ClasspathUtil.loadResource(myFhirContext, StructureDefinition.class, "validation/practitionerrole/profile-practitionerrole.json");
+			myClient.update().resource(profileProcedure).execute();
+
+			Bundle bundle = ClasspathUtil.loadResource(myFhirContext, Bundle.class, "validation/practitionerrole/bundle-with-medicationdispense.json");
+
+			// execute and verify
+			// the cache entry for the StructureDefinition (profile) will expire at the timeout (1ms) after it is written
+			// there are multiple calls to fetch the profile within a single validate call, which means subsequent ones will get a different instance of StructureDefinition
+			List<String> errors = getValidationErrors(myClient, bundle);
+			assertThat(StringUtils.join("", errors)).contains("PractitionerRole.telecom:TelecomPhone: max allowed = 1, but found 2");
+		}
+	}
+
+	@Nested
+	public class ValidateWithCachePositiveTest {
+		@BeforeEach
+		public void before() {
+			HapiSystemProperties.restoreDefaultValidationResourceCacheTimeoutMillis();
+			myInstanceValidator.resetWorkerContext();
+		}
+
+		@Test
+		public void validate_profileResourceFetchedMultipleTimes_returnsNoErrors() {
+			// setup
+			StructureDefinition profileProcedure = ClasspathUtil.loadResource(myFhirContext, StructureDefinition.class, "validation/practitionerrole/profile-practitionerrole.json");
+			myClient.update().resource(profileProcedure).execute();
+
+			Bundle bundle = ClasspathUtil.loadResource(myFhirContext, Bundle.class, "validation/practitionerrole/bundle-with-medicationdispense.json");
+
+			// execute and verify
+			List<String> errors = getValidationErrors(myClient, bundle);
+			assertThat(errors).isEmpty();
+		}
+	}
+
+	@Nested
+	public class FetchTests {
+		private VersionSpecificWorkerContextWrapper myWorkerContext;
+
+		@BeforeEach
+		public void before() {
+			myWorkerContext = VersionSpecificWorkerContextWrapper.newVersionSpecificWorkerContextWrapper(myValidationSupport);
+		}
+
+		@Test
+		public void fetchResource_withStructureDefinition_usesCache() {
+			final String resourceUrl = createStructureDefinition();
+
+			// verify that the snapshot is generated
+			org.hl7.fhir.r5.model.StructureDefinition fetchedStructureDefinition1 = myWorkerContext.fetchResource(org.hl7.fhir.r5.model.StructureDefinition.class, resourceUrl);
+			assertThat(fetchedStructureDefinition1.hasSnapshot()).isTrue();
+
+			// verify that the sub-subsequent fetchResource returns the same resource instance from the cache
+			org.hl7.fhir.r5.model.StructureDefinition fetchedStructureDefinition2 = myWorkerContext.fetchResource(org.hl7.fhir.r5.model.StructureDefinition.class, resourceUrl);
+			assertThat(fetchedStructureDefinition2).isSameAs(fetchedStructureDefinition1);
+		}
+
+		@Test
+		public void fetchResource_withCodeSystem_cacheIsUsed() {
+			final String resourceUrl = "http://example.com/CodeSystem/example-system";
+
+			CodeSystem codeSystem = new CodeSystem();
+			codeSystem.setId("CodeSystem/example-system");
+			codeSystem.setUrl(resourceUrl);
+
+			myCodeSystemDao.create(codeSystem, mySrd);
+
+			org.hl7.fhir.r5.model.CodeSystem fetchedCodeSystem1 = myWorkerContext.fetchResource(org.hl7.fhir.r5.model.CodeSystem.class, resourceUrl);
+
+			// verify that the sub-subsequent fetchResource returns the same resource instance from the cache
+			org.hl7.fhir.r5.model.CodeSystem fetchedCodeSystem2 = myWorkerContext.fetchResource(org.hl7.fhir.r5.model.CodeSystem.class, resourceUrl);
+			assertThat(fetchedCodeSystem2).isSameAs(fetchedCodeSystem1);
+		}
+
+		@Test
+		public void fetchCodeSystem_cacheIsUsed() {
+			final String resourceUrl = "http://example.com/CodeSystem/example-system";
+
+			CodeSystem codeSystem = new CodeSystem();
+			codeSystem.setId("CodeSystem/example-system");
+			codeSystem.setUrl(resourceUrl);
+
+			myCodeSystemDao.create(codeSystem, mySrd);
+
+			org.hl7.fhir.r5.model.CodeSystem fetchedCodeSystem1 = myWorkerContext.fetchCodeSystem(resourceUrl);
+
+			// verify that the sub-subsequent fetchCodeSystem returns the same resource instance from the cache
+			org.hl7.fhir.r5.model.CodeSystem fetchedCodeSystem2 = myWorkerContext.fetchCodeSystem(resourceUrl);
+			assertThat(fetchedCodeSystem2).isSameAs(fetchedCodeSystem1);
+		}
+
+		@Test
+		public void fetchCodeSystem_usesSameCacheAsFetchResource() {
+			final String resourceUrl = "http://example.com/CodeSystem/example-system";
+
+			CodeSystem codeSystem = new CodeSystem();
+			codeSystem.setId("CodeSystem/example-system");
+			codeSystem.setUrl(resourceUrl);
+
+			myCodeSystemDao.create(codeSystem, mySrd);
+
+			org.hl7.fhir.r5.model.CodeSystem fetchedCodeSystem1 = myWorkerContext.fetchCodeSystem(resourceUrl);
+
+			// verify that the sub-subsequent fetchResource returns the same resource instance from the cache
+			org.hl7.fhir.r5.model.CodeSystem fetchedCodeSystem2 = myWorkerContext.fetchResource(org.hl7.fhir.r5.model.CodeSystem.class, resourceUrl);
+			assertThat(fetchedCodeSystem2).isSameAs(fetchedCodeSystem1);
+		}
+
+		@Test
+		public void fetchResource_withValueSet_cacheIsUsed() {
+			final String resourceUrl = "http://example.com/ValueSet/example-set";
+
+			ValueSet valueSet = new ValueSet();
+			valueSet.setId("ValueSet/example-set");
+			valueSet.setUrl(resourceUrl);
+
+			myValueSetDao.create(valueSet, mySrd);
+
+			org.hl7.fhir.r5.model.ValueSet fetchedCodeSystem1 = myWorkerContext.fetchResource(org.hl7.fhir.r5.model.ValueSet.class, resourceUrl);
+
+			// verify that the sub-subsequent fetchResource returns the same resource instance from the cache
+			org.hl7.fhir.r5.model.ValueSet fetchedCodeSystem2 = myWorkerContext.fetchResource(org.hl7.fhir.r5.model.ValueSet.class, resourceUrl);
+			assertThat(fetchedCodeSystem2).isSameAs(fetchedCodeSystem1);
+		}
+
+		@Test
+		public void fetchResource_expireCache_cacheWorksAsExpected() {
+			final String resourceUrl = createStructureDefinition();
+
+			org.hl7.fhir.r5.model.StructureDefinition fetchedStructureDefinition1 = myWorkerContext.fetchResource(org.hl7.fhir.r5.model.StructureDefinition.class, resourceUrl);
+
+			// simulate cache timeout by invalidating cache
+			myWorkerContext.invalidateCaches();
+
+			// verify that the sub-subsequent fetchResource returns a different resource instance from the cache
+			org.hl7.fhir.r5.model.StructureDefinition fetchedStructureDefinition3 = myWorkerContext.fetchResource(org.hl7.fhir.r5.model.StructureDefinition.class, resourceUrl);
+			assertThat(fetchedStructureDefinition3).isNotSameAs(fetchedStructureDefinition1);
+		}
+	}
+
+	private String createStructureDefinition() {
+		final String resourceUrl = "http://example.com/StructureDefinition/example-profile-patient";
+		StructureDefinition structureDefinition = new StructureDefinition();
+		structureDefinition.setId("StructureDefinition/example-profile-patient");
+		structureDefinition.setUrl(resourceUrl);
+		structureDefinition.setType("Patient");
+		structureDefinition.setBaseDefinition("http://hl7.org/fhir/StructureDefinition/Patient");
+		structureDefinition.setDerivation(StructureDefinition.TypeDerivationRule.CONSTRAINT);
+		ElementDefinition telecomElement = structureDefinition.getDifferential().addElement().setPath("Patient.telecom");
+		telecomElement.setMax("1");
+
+		myStructureDefinitionDao.create(structureDefinition, mySrd);
+
+		return resourceUrl;
+	}
+}

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

@@ -43,4 +43,6 @@
 	<!-- See https://docs.jboss.org/hibernate/stable/search/reference/en-US/html_single/#backend-lucene-io-writer-infostream for lucene logging
 	<logger name="org.hibernate.search.backend.lucene.infostream" level="TRACE"/>  -->
 
+	<!-- <logger name="ca.uhn.fhir.log.terminology_troubleshooting" level="TRACE"/> -->
+
 </configuration>