add terminology troubleshooting log (#5439)

* init rev

* init rev

* changelog and additional logging

* changelog and additional logging

* changelog and additional logging

* spotless

* review feedback

hapi-fhir-base/src/main/java/ca/uhn/fhir/context/support/DefaultProfileValidationSupport.java

@@ -99,6 +99,11 @@ public class DefaultProfileValidationSupport implements IValidationSupport {
 		}
 	}
 
+	@Override
+	public String getName() {
+		return myCtx.getVersion().getVersion() + " FHIR Standard Profile Validation Support";
+	}
+
 	@Override
 	public List<IBaseResource> fetchAllConformanceResources() {
 		return myDelegate.fetchAllConformanceResources();

hapi-fhir-base/src/main/java/ca/uhn/fhir/context/support/IValidationSupport.java

@@ -27,6 +27,7 @@ import ca.uhn.fhir.util.UrlUtil;
 import org.apache.commons.lang3.Validate;
 import org.apache.commons.lang3.builder.EqualsBuilder;
 import org.apache.commons.lang3.builder.HashCodeBuilder;
+import org.apache.commons.lang3.builder.ToStringBuilder;
 import org.hl7.fhir.instance.model.api.IBase;
 import org.hl7.fhir.instance.model.api.IBaseCoding;
 import org.hl7.fhir.instance.model.api.IBaseParameters;
@@ -409,6 +410,13 @@ public interface IValidationSupport {
 		return null;
 	}
 
+	/**
+	 * This field is used by the Terminology Troubleshooting Log to log which validation support module was used for the operation being logged.
+	 */
+	default String getName() {
+		return "Unknown " + getFhirContext().getVersion().getVersion() + " Validation Support";
+	}
+
 	enum IssueSeverity {
 		/**
 		 * The issue caused the action to fail, and no further checking could be performed.
@@ -990,6 +998,16 @@ public interface IValidationSupport {
 		public boolean isReverse() {
 			return myReverse;
 		}
+
+		@Override
+		public String toString() {
+			return new ToStringBuilder(this)
+					.append("sourceValueSetUrl", mySourceValueSetUrl)
+					.append("targetSystemUrl", myTargetSystemUrl)
+					.append("targetValueSetUrl", myTargetValueSetUrl)
+					.append("reverse", myReverse)
+					.toString();
+		}
 	}
 
 	/**

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

@@ -28,6 +28,9 @@ public class Logs {
 	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");
 
@@ -42,6 +45,10 @@ public class Logs {
 		return ourBatchTroubleshootingLog;
 	}
 
+	public static Logger getTerminologyTroubleshootingLog() {
+		return ourTerminologyTroubleshootingLog;
+	}
+
 	public static Logger getSubscriptionTroubleshootingLog() {
 		return ourSubscriptionTroubleshootingLog;
 	}

hapi-fhir-cli/hapi-fhir-cli-api/src/main/java/ca/uhn/fhir/cli/LoadingValidationSupportDstu2.java

@@ -36,6 +36,11 @@ public class LoadingValidationSupportDstu2 implements IValidationSupport {
 	private static final org.slf4j.Logger ourLog =
 			org.slf4j.LoggerFactory.getLogger(LoadingValidationSupportDstu2.class);
 
+	@Override
+	public String getName() {
+		return "Dstu2 CLI Loading Validation Support";
+	}
+
 	@Override
 	public <T extends IBaseResource> T fetchResource(Class<T> theClass, String theUri) {
 		String resName = myCtx.getResourceType(theClass);

hapi-fhir-cli/hapi-fhir-cli-api/src/main/java/ca/uhn/fhir/cli/LoadingValidationSupportDstu3.java

@@ -35,6 +35,11 @@ public class LoadingValidationSupportDstu3 implements IValidationSupport {
 	private static final org.slf4j.Logger ourLog =
 			org.slf4j.LoggerFactory.getLogger(LoadingValidationSupportDstu3.class);
 
+	@Override
+	public String getName() {
+		return "Dstu3 CLI Loading Validation Support";
+	}
+
 	@Override
 	public <T extends IBaseResource> T fetchResource(Class<T> theClass, String theUri) {
 		String resName = myCtx.getResourceType(theClass);

hapi-fhir-docs/src/main/resources/ca/uhn/hapi/fhir/changelog/7_0_0/5439-terminology-troubleshooting-log.yaml

@@ -0,0 +1,4 @@
+---
+type: add
+issue: 5439
+title: "Added Terminology Troubleshooting Log to support troubleshooting terminology issues."

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

@@ -103,6 +103,11 @@ public class JpaPersistedResourceValidationSupport implements IValidationSupport
 		myNoMatch = myFhirContext.getResourceDefinition("Basic").newInstance();
 	}
 
+	@Override
+	public String getName() {
+		return myFhirContext.getVersion().getVersion() + " JPA Validation Support";
+	}
+
 	@Override
 	public IBaseResource fetchCodeSystem(String theSystem) {
 		if (TermReadSvcUtil.isLoincUnversionedCodeSystem(theSystem)) {

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

@@ -69,6 +69,11 @@ public class TermConceptMappingSvcImpl extends TermConceptClientMappingSvcImpl i
 	@Autowired
 	protected ITermConceptMapGroupElementTargetDao myConceptMapGroupElementTargetDao;
 
+	@Override
+	public String getName() {
+		return getFhirContext().getVersion().getVersion() + " ConceptMap Validation Support";
+	}
+
 	@Override
 	@Transactional
 	public void deleteConceptMapAndChildren(ResourceTable theResourceTable) {

hapi-fhir-validation/src/main/java/org/hl7/fhir/common/hapi/validation/support/CommonCodeSystemsTerminologyService.java

@@ -86,6 +86,11 @@ public class CommonCodeSystemsTerminologyService implements IValidationSupport {
 		myVersionCanonicalizer = new VersionCanonicalizer(theFhirContext);
 	}
 
+	@Override
+	public String getName() {
+		return myFhirContext.getVersion().getVersion() + " Common Code Systems Validation Support";
+	}
+
 	@Override
 	public CodeValidationResult validateCodeInValueSet(
 			ValidationSupportContext theValidationSupportContext,

hapi-fhir-validation/src/main/java/org/hl7/fhir/common/hapi/validation/support/DefaultProfileValidationSupportNpmStrategy.java

@@ -39,4 +39,9 @@ public class DefaultProfileValidationSupportNpmStrategy extends NpmPackageValida
 
 		ourLog.info("Loaded {} Core+Extension resources in {}", countAll(), sw);
 	}
+
+	@Override
+	public String getName() {
+		return getFhirContext().getVersion().getVersion() + " FHIR Standard Profile NPM Validation Support";
+	}
 }

hapi-fhir-validation/src/main/java/org/hl7/fhir/common/hapi/validation/support/InMemoryTerminologyServerValidationSupport.java

@@ -72,6 +72,11 @@ public class InMemoryTerminologyServerValidationSupport implements IValidationSu
 		myVersionCanonicalizer = new VersionCanonicalizer(theCtx);
 	}
 
+	@Override
+	public String getName() {
+		return myCtx.getVersion().getVersion() + " In-Memory Validation Support";
+	}
+
 	/**
 	 * This setting controls the validation issue severity to report when a code validation
 	 * finds that the code is present in the given CodeSystem, but the display name being

hapi-fhir-validation/src/main/java/org/hl7/fhir/common/hapi/validation/support/LocalFileValidationSupport.java

@@ -33,6 +33,11 @@ public class LocalFileValidationSupport extends PrePopulatedValidationSupport {
 		super(ctx);
 	}
 
+	@Override
+	public String getName() {
+		return getFhirContext().getVersion().getVersion() + " Local File Validation Support";
+	}
+
 	@Override
 	public FhirContext getFhirContext() {
 		return myCtx;

hapi-fhir-validation/src/main/java/org/hl7/fhir/common/hapi/validation/support/NpmPackageValidationSupport.java

@@ -18,7 +18,7 @@ import javax.annotation.Nonnull;
 
 /**
  * This interceptor loads and parses FHIR NPM Conformance Packages, and makes the
- * artifacts foudn within them available to the FHIR validator.
+ * artifacts found within them available to the FHIR validator.
  *
  * @since 5.5.0
  */

hapi-fhir-validation/src/main/java/org/hl7/fhir/common/hapi/validation/support/PrePopulatedValidationSupport.java

@@ -54,6 +54,11 @@ public class PrePopulatedValidationSupport extends BaseStaticResourceValidationS
 		this(theContext, new HashMap<>(), new HashMap<>(), new HashMap<>(), new HashMap<>(), new HashMap<>());
 	}
 
+	@Override
+	public String getName() {
+		return getFhirContext().getVersion().getVersion() + " Pre-populated Validation Support";
+	}
+
 	/**
 	 * Constructor
 	 *

hapi-fhir-validation/src/main/java/org/hl7/fhir/common/hapi/validation/support/RemoteTerminologyServiceValidationSupport.java

@@ -57,6 +57,11 @@ public class RemoteTerminologyServiceValidationSupport extends BaseValidationSup
 		myBaseUrl = theBaseUrl;
 	}
 
+	@Override
+	public String getName() {
+		return getFhirContext().getVersion().getVersion() + " Remote Terminology Service Validation Support";
+	}
+
 	@Override
 	public CodeValidationResult validateCode(
 			@Nonnull ValidationSupportContext theValidationSupportContext,

hapi-fhir-validation/src/main/java/org/hl7/fhir/common/hapi/validation/support/SnapshotGeneratingValidationSupport.java

@@ -179,4 +179,9 @@ public class SnapshotGeneratingValidationSupport implements IValidationSupport {
 	public FhirContext getFhirContext() {
 		return myCtx;
 	}
+
+	@Override
+	public String getName() {
+		return getFhirContext().getVersion().getVersion() + " Snapshot Generating Validation Support";
+	}
 }

hapi-fhir-validation/src/main/java/org/hl7/fhir/common/hapi/validation/support/UnknownCodeSystemWarningValidationSupport.java

@@ -33,6 +33,11 @@ public class UnknownCodeSystemWarningValidationSupport extends BaseValidationSup
 		super(theFhirContext);
 	}
 
+	@Override
+	public String getName() {
+		return getFhirContext().getVersion().getVersion() + " Unknown Code System Warning Validation Support";
+	}
+
 	@Override
 	public boolean isValueSetSupported(ValidationSupportContext theValidationSupportContext, String theValueSetUrl) {
 		return true;

hapi-fhir-validation/src/main/java/org/hl7/fhir/common/hapi/validation/support/ValidationSupportChain.java

@@ -9,9 +9,11 @@ import ca.uhn.fhir.context.support.TranslateConceptResults;
 import ca.uhn.fhir.context.support.ValidationSupportContext;
 import ca.uhn.fhir.context.support.ValueSetExpansionOptions;
 import ca.uhn.fhir.i18n.Msg;
+import ca.uhn.fhir.util.Logs;
 import org.apache.commons.lang3.Validate;
 import org.hl7.fhir.instance.model.api.IBaseResource;
 import org.hl7.fhir.instance.model.api.IPrimitiveType;
+import org.slf4j.Logger;
 
 import java.util.ArrayList;
 import java.util.HashSet;
@@ -25,6 +27,7 @@ import static org.apache.commons.lang3.StringUtils.isBlank;
 import static org.apache.commons.lang3.StringUtils.isNotBlank;
 
 public class ValidationSupportChain implements IValidationSupport {
+	static Logger ourLog = Logs.getTerminologyTroubleshootingLog();
 
 	private List<IValidationSupport> myChain;
 
@@ -66,7 +69,17 @@ public class ValidationSupportChain implements IValidationSupport {
 					retVal.setMessage(translations.getMessage());
 				}
 
-				retVal.getResults().addAll(translations.getResults());
+				if (!translations.isEmpty()) {
+					if (ourLog.isDebugEnabled()) {
+						ourLog.debug(
+								"{} found {} concept translation{} for {}",
+								next.getName(),
+								translations.size(),
+								translations.size() > 1 ? "s" : "",
+								theRequest);
+					}
+					retVal.getResults().addAll(translations.getResults());
+				}
 			}
 		}
 		return retVal;
@@ -74,6 +87,7 @@ public class ValidationSupportChain implements IValidationSupport {
 
 	@Override
 	public void invalidateCaches() {
+		ourLog.debug("Invalidating caches in {} validation support modules", myChain.size());
 		for (IValidationSupport next : myChain) {
 			next.invalidateCaches();
 		}
@@ -84,6 +98,9 @@ public class ValidationSupportChain implements IValidationSupport {
 		for (IValidationSupport next : myChain) {
 			boolean retVal = next.isValueSetSupported(theValidationSupportContext, theValueSetUrl);
 			if (retVal) {
+				if (ourLog.isDebugEnabled()) {
+					ourLog.debug("ValueSet {} found in {}", theValueSetUrl, next.getName());
+				}
 				return true;
 			}
 		}
@@ -101,6 +118,9 @@ public class ValidationSupportChain implements IValidationSupport {
 			IBaseResource retVal =
 					next.generateSnapshot(theValidationSupportContext, theInput, theUrl, theWebUrl, theProfileName);
 			if (retVal != null) {
+				if (ourLog.isDebugEnabled()) {
+					ourLog.debug("Profile snapshot for {} generated by {}", theInput.getIdElement(), next.getName());
+				}
 				return retVal;
 			}
 		}
@@ -178,6 +198,9 @@ public class ValidationSupportChain implements IValidationSupport {
 			ValueSetExpansionOutcome expanded =
 					next.expandValueSet(theValidationSupportContext, theExpansionOptions, theValueSetToExpand);
 			if (expanded != null) {
+				if (ourLog.isDebugEnabled()) {
+					ourLog.debug("ValueSet {} expanded by {}", theValueSetToExpand.getIdElement(), next.getName());
+				}
 				return expanded;
 			}
 		}
@@ -246,6 +269,13 @@ public class ValidationSupportChain implements IValidationSupport {
 		for (IValidationSupport next : myChain) {
 			IBaseResource retVal = next.fetchCodeSystem(theSystem);
 			if (retVal != null) {
+				if (ourLog.isDebugEnabled()) {
+					ourLog.debug(
+							"CodeSystem {} with System {} fetched by {}",
+							retVal.getIdElement(),
+							theSystem,
+							next.getName());
+				}
 				return retVal;
 			}
 		}
@@ -257,6 +287,10 @@ public class ValidationSupportChain implements IValidationSupport {
 		for (IValidationSupport next : myChain) {
 			IBaseResource retVal = next.fetchValueSet(theUrl);
 			if (retVal != null) {
+				if (ourLog.isDebugEnabled()) {
+					ourLog.debug(
+							"ValueSet {} with URL {} fetched by {}", retVal.getIdElement(), theUrl, next.getName());
+				}
 				return retVal;
 			}
 		}
@@ -268,6 +302,10 @@ public class ValidationSupportChain implements IValidationSupport {
 		for (IValidationSupport next : myChain) {
 			T retVal = next.fetchResource(theClass, theUri);
 			if (retVal != null) {
+				if (ourLog.isDebugEnabled()) {
+					ourLog.debug(
+							"Resource {} with URI {} fetched by {}", retVal.getIdElement(), theUri, next.getName());
+				}
 				return retVal;
 			}
 		}
@@ -279,6 +317,9 @@ public class ValidationSupportChain implements IValidationSupport {
 		for (IValidationSupport next : myChain) {
 			byte[] retVal = next.fetchBinary(key);
 			if (retVal != null) {
+				if (ourLog.isDebugEnabled()) {
+					ourLog.debug("Binary with key {} fetched by {}", key, next.getName());
+				}
 				return retVal;
 			}
 		}
@@ -290,6 +331,9 @@ public class ValidationSupportChain implements IValidationSupport {
 		for (IValidationSupport next : myChain) {
 			IBaseResource retVal = next.fetchStructureDefinition(theUrl);
 			if (retVal != null) {
+				if (ourLog.isDebugEnabled()) {
+					ourLog.debug("StructureDefinition with URL {} fetched by {}", theUrl, next.getName());
+				}
 				return retVal;
 			}
 		}
@@ -300,6 +344,9 @@ public class ValidationSupportChain implements IValidationSupport {
 	public boolean isCodeSystemSupported(ValidationSupportContext theValidationSupportContext, String theSystem) {
 		for (IValidationSupport next : myChain) {
 			if (next.isCodeSystemSupported(theValidationSupportContext, theSystem)) {
+				if (ourLog.isDebugEnabled()) {
+					ourLog.debug("CodeSystem with System {} is supported by {}", theSystem, next.getName());
+				}
 				return true;
 			}
 		}
@@ -321,6 +368,15 @@ public class ValidationSupportChain implements IValidationSupport {
 				CodeValidationResult retVal = next.validateCode(
 						theValidationSupportContext, theOptions, theCodeSystem, theCode, theDisplay, theValueSetUrl);
 				if (retVal != null) {
+					if (ourLog.isDebugEnabled()) {
+						ourLog.debug(
+								"Code {}|{} '{}' in ValueSet {} validated by {}",
+								theCodeSystem,
+								theCode,
+								theDisplay,
+								theValueSetUrl,
+								next.getName());
+					}
 					return retVal;
 				}
 			}
@@ -342,6 +398,15 @@ public class ValidationSupportChain implements IValidationSupport {
 				CodeValidationResult retVal = next.validateCodeInValueSet(
 						theValidationSupportContext, theOptions, theCodeSystem, theCode, theDisplay, theValueSet);
 				if (retVal != null) {
+					if (ourLog.isDebugEnabled()) {
+						ourLog.debug(
+								"Code {}|{} '{}' in ValueSet {} validated by {}",
+								theCodeSystem,
+								theCode,
+								theDisplay,
+								theValueSet.getIdElement(),
+								next.getName());
+					}
 					return retVal;
 				}
 			}
@@ -357,7 +422,18 @@ public class ValidationSupportChain implements IValidationSupport {
 			String theDisplayLanguage) {
 		for (IValidationSupport next : myChain) {
 			if (next.isCodeSystemSupported(theValidationSupportContext, theSystem)) {
-				return next.lookupCode(theValidationSupportContext, theSystem, theCode, theDisplayLanguage);
+				LookupCodeResult lookupCodeResult =
+						next.lookupCode(theValidationSupportContext, theSystem, theCode, theDisplayLanguage);
+				if (ourLog.isDebugEnabled()) {
+					ourLog.debug(
+							"Code {}|{}{} {} by {}",
+							theSystem,
+							theCode,
+							isBlank(theDisplayLanguage) ? "" : " (" + theDisplayLanguage + ")",
+							lookupCodeResult != null && lookupCodeResult.isFound() ? "found" : "not found",
+							next.getName());
+				}
+				return lookupCodeResult;
 			}
 		}
 		return null;