Merge remote-tracking branch 'origin/issue/14_configurable_log_level'

hhund · hhund · commit b7908c6c91fa · 2025-06-18T00:15:24.000+02:00
into develop
diff --git a/src/main/java/dev/dsf/fhir/validator/implementation_guide/ValidationPackage.java b/src/main/java/dev/dsf/fhir/validator/implementation_guide/ValidationPackage.java
@@ -151,9 +151,9 @@ private Consumer<ValidationPackageEntry> doParseResources(FhirContext context, L
 	{
 		return entry ->
 		{
-			if ("package/package.json".equals(entry.getFileName())
-					|| (entry.getFileName() != null && (entry.getFileName().startsWith("package/example")
-							|| entry.getFileName().endsWith(".index.json") || !entry.getFileName().endsWith(".json"))))
+			if ("package/package.json".equals(entry.getFileName()) || (entry.getFileName() != null
+					&& (entry.getFileName().startsWith("package/example") || entry.getFileName().endsWith(".index.json")
+							|| entry.getFileName().endsWith(".schema.json") || !entry.getFileName().endsWith(".json"))))
 			{
 				logger.debug("Ignoring {}", entry.getFileName());
 				return;
@@ -187,8 +187,8 @@ else if (resource instanceof ValueSet v)
 			}
 			catch (Exception e)
 			{
-				logger.warn("Ignoring resource with error while parsing, {}: {}", e.getClass().getName(),
-						e.getMessage());
+				logger.warn("Ignoring resource with error while parsing {}, {}: {}", entry.getFileName(),
+						e.getClass().getName(), e.getMessage());
 			}
 		};
 	}
diff --git a/src/main/java/dev/dsf/fhir/validator/implementation_guide/ValidationPackageWithDepedencies.java b/src/main/java/dev/dsf/fhir/validator/implementation_guide/ValidationPackageWithDepedencies.java
@@ -256,7 +256,7 @@ private void logMissingValueSets(Set<String> neededValueSets, List<ValueSet> fou
 		if (!missingValueSets.isEmpty())
 		{
 			logger.warn(
-					"The following ValueSet are required for validation but could not be found in validation package {}|{} or its dependencies, this may result in incomplete valdidation: [{}]",
+					"The following ValueSet are required for validation but could not be found in package (incl. dependencies) {}|{}, this may result in incomplete valdidation: [{}]",
 					getName(), getVersion(), missingValueSets);
 		}
 	}
diff --git a/src/main/java/dev/dsf/fhir/validator/main/ValidationConfig.java b/src/main/java/dev/dsf/fhir/validator/main/ValidationConfig.java
@@ -17,10 +17,14 @@
 import java.util.function.Predicate;
 import java.util.stream.Collectors;
 
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.core.config.Configurator;
 import org.hl7.fhir.r4.model.CapabilityStatement;
 import org.hl7.fhir.r4.model.Enumerations.BindingStrength;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.springframework.beans.factory.InitializingBean;
 import org.springframework.beans.factory.annotation.Value;
 import org.springframework.context.annotation.Bean;
 import org.springframework.context.annotation.Configuration;
@@ -64,7 +68,7 @@
 
 @Configuration
 @PropertySource(ignoreResourceNotFound = true, value = "file:application.properties")
-public class ValidationConfig
+public class ValidationConfig implements InitializingBean
 {
 	private static final Logger logger = LoggerFactory.getLogger(ValidationConfig.class);
 
@@ -73,9 +77,30 @@ public static enum TerminologyServerConnectionTestStatus
 		OK, NOT_OK, DISABLED
 	}
 
+	public static enum LogLevel
+	{
+		TRACE(Level.TRACE), DEBUG(Level.DEBUG), INFO(Level.INFO), WARN(Level.WARN), ERROR(Level.ERROR), FATAL(
+				Level.FATAL), OFF(Level.OFF);
+
+		private final Level level;
+
+		private LogLevel(Level level)
+		{
+			this.level = level;
+		}
+
+		public Level level()
+		{
+			return level;
+		}
+	}
+
 	@Value("${dev.dsf.validation:true}")
 	private boolean validationEnabled;
 
+	@Value("${dev.dsf.validation.logLevel:INFO}")
+	private LogLevel logLevel;
+
 	@Value("#{'${dev.dsf.validation.package:}'.trim().split('(,[ ]?)|(\\n)')}")
 	private List<String> validationPackages;
 
@@ -182,6 +207,15 @@ public static enum TerminologyServerConnectionTestStatus
 	@Value("${dsf.dev.validation.proxy.password:#{null}}")
 	private char[] proxyPassword;
 
+	@Override
+	public void afterPropertiesSet() throws Exception
+	{
+		Configurator.setLevel(LogManager.getLogger("dev.dsf").getName(), logLevel.level());
+
+		if (EnumSet.of(LogLevel.ERROR, LogLevel.WARN, LogLevel.OFF).contains(logLevel))
+			Configurator.setLevel(LogManager.getRootLogger(), logLevel.level());
+	}
+
 	@Bean
 	public ObjectMapper objectMapper()
 	{
@@ -286,6 +320,7 @@ private Path cacheFolder(String cacheFolderType, String cacheFolder)
 			if (cacheFolderPath.startsWith(systemTempFolder))
 			{
 				Files.createDirectories(cacheFolderPath);
+
 				logger.debug("Cache folder for type {} created at {}", cacheFolderType,
 						cacheFolderPath.toAbsolutePath().toString());
 			}
@@ -327,6 +362,7 @@ private KeyStore trustStore(String trustStoreType, String trustCertificatesFile)
 		try
 		{
 			logger.debug("Creating trust-store for {} from {}", trustStoreType, trustCertificatesPath.toString());
+
 			List<X509Certificate> certificates = PemReader.readCertificates(trustCertificatesPath);
 			return KeyStoreCreator.jksForTrustedCertificates(certificates);
 		}
diff --git a/src/main/java/dev/dsf/fhir/validator/main/ValidationMain.java b/src/main/java/dev/dsf/fhir/validator/main/ValidationMain.java
@@ -7,6 +7,7 @@
 import java.util.Arrays;
 import java.util.List;
 import java.util.Objects;
+import java.util.function.Supplier;
 
 import org.hl7.fhir.instance.model.api.IBaseResource;
 import org.hl7.fhir.r4.model.Bundle;
@@ -138,25 +139,33 @@ private BundleValidator createBundleValidator()
 
 	public void validate(BundleValidator validator, String[] files)
 	{
-		logger.info("Using validation packages {}", validationPackageIdentifiers);
-
 		Arrays.stream(files).map(this::read).filter(r -> r != null).forEach(r ->
 		{
 			logger.info("Validating {} from {}", r.getResource().getResourceType().name(), r.getFilename());
 
-			if (r.getResource() instanceof Bundle)
+			if (r.getResource() instanceof Bundle b)
 			{
-				Bundle validationResult = validator.validate((Bundle) r.getResource());
+				Bundle validationResult = logExecutionTimeInMs(() -> validator.validate(b), "Bundle");
 				System.out.println(getOutputParser().encodeResourceToString(validationResult));
 			}
 			else
 			{
-				ValidationResult validationResult = validator.validate(r.getResource());
+				ValidationResult validationResult = logExecutionTimeInMs(() -> validator.validate(r.getResource()),
+						r.getResource().getResourceType().name());
 				System.out.println(getOutputParser().encodeResourceToString(validationResult.toOperationOutcome()));
 			}
 		});
 	}
 
+	private <T> T logExecutionTimeInMs(Supplier<T> supplier, String resourceType)
+	{
+		long t0 = System.currentTimeMillis();
+		T t = supplier.get();
+		long t1 = System.currentTimeMillis();
+		logger.debug("{} validated in {} ms", resourceType, t1 - t0);
+		return t;
+	}
+
 	private IParser getOutputParser()
 	{
 		switch (output)
@@ -188,7 +197,7 @@ private FileNameAndResource tryJson(String file)
 		try (InputStream in = Files.newInputStream(Paths.get(file)))
 		{
 			IBaseResource resource = fhirContext.newJsonParser().parseResource(in);
-			logger.info("{} read from {}", resource.getClass().getSimpleName(), file);
+			logger.debug("{} read from {}", resource.getClass().getSimpleName(), file);
 			return new FileNameAndResource(file, (Resource) resource);
 		}
 		catch (Exception e)
@@ -203,7 +212,7 @@ private FileNameAndResource tryXml(String file)
 		try (InputStream in = Files.newInputStream(Paths.get(file)))
 		{
 			IBaseResource resource = fhirContext.newXmlParser().parseResource(in);
-			logger.info("{} read from {}", resource.getClass().getSimpleName(), file);
+			logger.debug("{} read from {}", resource.getClass().getSimpleName(), file);
 			return new FileNameAndResource(file, (Resource) resource);
 		}
 		catch (Exception e)
diff --git a/src/main/java/dev/dsf/fhir/validator/service/ValidatorFactoryImpl.java b/src/main/java/dev/dsf/fhir/validator/service/ValidatorFactoryImpl.java
@@ -29,6 +29,7 @@
 import ca.uhn.fhir.context.support.DefaultProfileValidationSupport;
 import ca.uhn.fhir.context.support.IValidationSupport;
 import dev.dsf.fhir.validator.client.TerminologyServerClient;
+import dev.dsf.fhir.validator.implementation_guide.ValidationPackageIdentifier;
 import dev.dsf.fhir.validator.implementation_guide.ValidationPackageWithDepedencies;
 import dev.dsf.fhir.validator.structure_definition.SnapshotGenerator;
 import dev.dsf.fhir.validator.structure_definition.SnapshotGenerator.SnapshotWithValidationMessages;
@@ -154,27 +155,29 @@ private List<ValueSet> withExpandedValueSets(ValidationPackageWithDepedencies pa
 
 		packageWithDependencies.getValueSetsIncludingDependencies(valueSetBindingStrengths, fhirContext).forEach(v ->
 		{
-			logger.debug("Expanding ValueSet {}|{}", v.getUrl(), v.getVersion());
+			logger.debug("Expanding ValueSet {}|{} from package (incl. dependencies) {}", v.getUrl(), v.getVersion(),
+					packageWithDependencies.getIdentifier().toString());
 
 			// ValueSet uses filter or import in compose
 			if (v.hasCompose() && ((v.getCompose().hasInclude()
 					&& (v.getCompose().getInclude().stream().anyMatch(c -> c.hasFilter() || c.hasValueSet())))
 					|| (v.getCompose().hasExclude()
 							&& v.getCompose().getExclude().stream().anyMatch(c -> c.hasFilter() || c.hasValueSet()))))
 			{
-				expandExternal(expandedValueSets, v);
+				expandExternal(expandedValueSets, v, packageWithDependencies.getIdentifier());
 			}
 			else
 			{
 				// will try external expansion if internal not successful
-				expandInternal(expandedValueSets, expander, v);
+				expandInternal(expandedValueSets, expander, v, packageWithDependencies.getIdentifier());
 			}
 		});
 
 		return expandedValueSets;
 	}
 
-	private void expandExternal(List<ValueSet> expandedValueSets, ValueSet v)
+	private void expandExternal(List<ValueSet> expandedValueSets, ValueSet v,
+			ValidationPackageIdentifier validationPackageIdentifier)
 	{
 		try
 		{
@@ -184,41 +187,45 @@ private void expandExternal(List<ValueSet> expandedValueSets, ValueSet v)
 		catch (WebApplicationException e)
 		{
 			logger.warn(
-					"Error while expanding ValueSet {}|{} externally, this may result in incomplete validation: {} - {}",
-					v.getUrl(), v.getVersion(), e.getClass().getName(), e.getMessage());
+					"Unable to expand ValueSet {}|{} from package (incl. dependencies) {} externally, this may result in incomplete validation: {} - {}",
+					v.getUrl(), v.getVersion(), validationPackageIdentifier.toString(), e.getClass().getName(),
+					e.getMessage());
 			getOutcome(e).ifPresent(m -> logger.debug("Expansion error response: {}", m));
 			logger.debug("ValueSet with error while expanding: {}",
 					fhirContext.newJsonParser().encodeResourceToString(v));
 		}
 		catch (Exception e)
 		{
 			logger.warn(
-					"Error while expanding ValueSet {}|{} externally, this may result in incomplete validation: {} - {}",
-					v.getUrl(), v.getVersion(), e.getClass().getName(), e.getMessage());
+					"Unable to expand ValueSet {}|{} from package (incl. dependencies) {} externally, this may result in incomplete validation: {} - {}",
+					v.getUrl(), v.getVersion(), validationPackageIdentifier.toString(), e.getClass().getName(),
+					e.getMessage());
 			logger.debug("ValueSet with error while expanding: {}",
 					fhirContext.newJsonParser().encodeResourceToString(v));
 		}
 	}
 
-	private void expandInternal(List<ValueSet> expandedValueSets, ValueSetExpander expander, ValueSet v)
+	private void expandInternal(List<ValueSet> expandedValueSets, ValueSetExpander expander, ValueSet v,
+			ValidationPackageIdentifier validationPackageIdentifier)
 	{
 		try
 		{
 			ValueSetExpansionOutcome expansion = expander.expand(v);
 
 			if (expansion.getError() != null)
-				logger.warn("Error while expanding ValueSet {}|{} internally: {}", v.getUrl(), v.getVersion(),
-						expansion.getError());
+				logger.warn("Unable to expand ValueSet {}|{} from package (incl. dependencies) {} internally: {}",
+						v.getUrl(), v.getVersion(), validationPackageIdentifier.toString(), expansion.getError());
 			else
 				expandedValueSets.add(expansion.getValueset());
 		}
 		catch (Exception e)
 		{
 			logger.info(
-					"Error while expanding ValueSet {}|{} internally: {} - {}, trying to expand via external terminology server next",
-					v.getUrl(), v.getVersion(), e.getClass().getName(), e.getMessage());
+					"Unable to expand ValueSet {}|{} from package (incl. dependencies) {} internally: {} - {}, trying to expand via external terminology server next",
+					v.getUrl(), v.getVersion(), validationPackageIdentifier.toString(), e.getClass().getName(),
+					e.getMessage());
 
-			expandExternal(expandedValueSets, v);
+			expandExternal(expandedValueSets, v, validationPackageIdentifier);
 		}
 	}
 
@@ -250,15 +257,16 @@ private IValidationSupport withSnapshots(List<ValueSet> expandedValueSets,
 			packageWithDependencies.getValidationSupportResources().getStructureDefinitions().stream()
 					.filter(s -> s.hasDifferential() && !s.hasSnapshot())
 					.forEach(diff -> createSnapshot(packageWithDependencies, snapshotsAndExpandedValueSets, snapshots,
-							generator, diff));
+							generator, diff, packageWithDependencies.getIdentifier()));
 		}
 
 		return supportChain;
 	}
 
 	private void createSnapshot(ValidationPackageWithDepedencies packageWithDependencies,
 			ValidationSupportWithCustomResources snapshotsAndExpandedValueSets,
-			Map<String, StructureDefinition> snapshots, SnapshotGenerator generator, StructureDefinition diff)
+			Map<String, StructureDefinition> snapshots, SnapshotGenerator generator, StructureDefinition diff,
+			ValidationPackageIdentifier validationPackageIdentifier)
 	{
 		if (snapshots.containsKey(diff.getUrl() + "|" + diff.getVersion()))
 			return;
@@ -267,8 +275,8 @@ private void createSnapshot(ValidationPackageWithDepedencies packageWithDependen
 		definitions.addAll(packageWithDependencies.getStructureDefinitionDependencies(diff));
 		definitions.add(diff);
 
-		logger.debug("Generating snapshot for {}|{}, base {}, dependencies {}", diff.getUrl(), diff.getVersion(),
-				diff.getBaseDefinition(),
+		logger.debug("Generating snapshot for {}|{} from package (incl. dependencies) {}, base {}, dependencies {}",
+				diff.getUrl(), diff.getVersion(), validationPackageIdentifier.toString(), diff.getBaseDefinition(),
 				definitions.stream()
 						.filter(sd -> !sd.equals(diff) && !sd.getUrl().equals(diff.getBaseDefinition())
 								&& !(sd.getUrl() + "|" + sd.getVersion()).equals(diff.getBaseDefinition()))
@@ -284,16 +292,19 @@ private void createSnapshot(ValidationPackageWithDepedencies packageWithDependen
 
 		if (PublicationStatus.ACTIVE.equals(diff.getStatus()) && !dependenciesWithDifferentStatus.isEmpty())
 		{
-			logger.warn("StructureDefinition {}|{}, has dependencies with no active status [{}]", diff.getUrl(),
-					diff.getVersion(), dependenciesWithDifferentStatus);
+			logger.warn(
+					"StructureDefinition {}|{} from package (incl. dependencies) {}, has dependencies with no active status [{}]",
+					diff.getUrl(), diff.getVersion(), validationPackageIdentifier.toString(),
+					dependenciesWithDifferentStatus);
 		}
 
 		definitions.stream().filter(sd -> sd.hasDifferential() && !sd.hasSnapshot()
 				&& !snapshots.containsKey(sd.getUrl() + "|" + sd.getVersion())).forEach(sd ->
 				{
 					try
 					{
-						logger.debug("Generating snapshot for {}|{}", sd.getUrl(), sd.getVersion());
+						logger.debug("Generating snapshot for {}|{} from package (incl. dependencies) {}", sd.getUrl(),
+								sd.getVersion(), validationPackageIdentifier.toString());
 						SnapshotWithValidationMessages snapshot = generator.generateSnapshot(sd);
 
 						if (snapshot.getSnapshot().hasSnapshot())
@@ -304,8 +315,8 @@ private void createSnapshot(ValidationPackageWithDepedencies packageWithDependen
 						}
 						else
 							logger.error(
-									"Error while generating snapshot for {}|{}: Not snaphsot returned from generator",
-									diff.getUrl(), diff.getVersion());
+									"Error while generating snapshot for {}|{} from package (incl. dependencies) {}: Not snaphsot returned from generator",
+									diff.getUrl(), diff.getVersion(), validationPackageIdentifier.toString());
 
 						snapshot.getMessages().forEach(m ->
 						{
@@ -320,12 +331,15 @@ private void createSnapshot(ValidationPackageWithDepedencies packageWithDependen
 					}
 					catch (Exception e)
 					{
-						logger.error("Error while generating snapshot for {}|{}: {} - {}", diff.getUrl(),
-								diff.getVersion(), e.getClass().getName(), e.getMessage());
+						logger.error(
+								"Error while generating snapshot for {}|{} from package (incl. dependencies) {}: {} - {}",
+								diff.getUrl(), diff.getVersion(), validationPackageIdentifier.toString(),
+								e.getClass().getName(), e.getMessage());
 					}
 				});
 
-		logger.debug("Generating snapshot for {}|{} [Done]", diff.getUrl(), diff.getVersion());
+		logger.debug("Generating snapshot for {}|{} from package (incl. dependencies) {} [Done]", diff.getUrl(),
+				diff.getVersion(), validationPackageIdentifier.toString());
 	}
 
 	private ValidationSupportChain createSupportChain(FhirContext context,
diff --git a/src/main/resources/log4j2.xml b/src/main/resources/log4j2.xml
@@ -8,7 +8,6 @@
 
 	<Loggers>
 		<Logger name="dev.dsf" level="TRACE"/>
-		<Logger name="org.eclipse.jetty" level="INFO"/>
 		<Logger name="ca.uhn.fhir.parser.LenientErrorHandler" level="ERROR"/>
 		
 		<Root level="WARN">

Original file line number	Diff line number	Diff line change
`@@ -151,9 +151,9 @@ private Consumer<ValidationPackageEntry> doParseResources(FhirContext context, L`
`151`	`151`	`{`
`152`	`152`	`return entry ->`
`153`	`153`	`{`
`154`		`- if ("package/package.json".equals(entry.getFileName())`
`155`		`- \|\| (entry.getFileName() != null && (entry.getFileName().startsWith("package/example")`
`156`		`- \|\| entry.getFileName().endsWith(".index.json") \|\| !entry.getFileName().endsWith(".json"))))`
	`154`	`+ if ("package/package.json".equals(entry.getFileName()) \|\| (entry.getFileName() != null`
	`155`	`+ && (entry.getFileName().startsWith("package/example") \|\| entry.getFileName().endsWith(".index.json")`
	`156`	`+ \|\| entry.getFileName().endsWith(".schema.json") \|\| !entry.getFileName().endsWith(".json"))))`
`157`	`157`	`{`
`158`	`158`	`logger.debug("Ignoring {}", entry.getFileName());`
`159`	`159`	`return;`
`@@ -187,8 +187,8 @@ else if (resource instanceof ValueSet v)`
`187`	`187`	`}`
`188`	`188`	`catch (Exception e)`
`189`	`189`	`{`
`190`		`- logger.warn("Ignoring resource with error while parsing, {}: {}", e.getClass().getName(),`
`191`		`- e.getMessage());`
	`190`	`+ logger.warn("Ignoring resource with error while parsing {}, {}: {}", entry.getFileName(),`
	`191`	`+ e.getClass().getName(), e.getMessage());`
`192`	`192`	`}`
`193`	`193`	`};`
`194`	`194`	`}`
Original file line number	Diff line number	Diff line change
`@@ -256,7 +256,7 @@ private void logMissingValueSets(Set<String> neededValueSets, List<ValueSet> fou`
`256`	`256`	`if (!missingValueSets.isEmpty())`
`257`	`257`	`{`
`258`	`258`	`logger.warn(`
`259`		`- "The following ValueSet are required for validation but could not be found in validation package {}\|{} or its dependencies, this may result in incomplete valdidation: [{}]",`
	`259`	`+ "The following ValueSet are required for validation but could not be found in package (incl. dependencies) {}\|{}, this may result in incomplete valdidation: [{}]",`
`260`	`260`	`getName(), getVersion(), missingValueSets);`
`261`	`261`	`}`
`262`	`262`	`}`
Original file line number	Diff line number	Diff line change
`@@ -7,6 +7,7 @@`
`7`	`7`	`import java.util.Arrays;`
`8`	`8`	`import java.util.List;`
`9`	`9`	`import java.util.Objects;`
	`10`	`+import java.util.function.Supplier;`
`10`	`11`
`11`	`12`	`import org.hl7.fhir.instance.model.api.IBaseResource;`
`12`	`13`	`import org.hl7.fhir.r4.model.Bundle;`
`@@ -138,25 +139,33 @@ private BundleValidator createBundleValidator()`
`138`	`139`
`139`	`140`	`public void validate(BundleValidator validator, String[] files)`
`140`	`141`	`{`
`141`		`- logger.info("Using validation packages {}", validationPackageIdentifiers);`
`142`		`-`
`143`	`142`	`Arrays.stream(files).map(this::read).filter(r -> r != null).forEach(r ->`
`144`	`143`	`{`
`145`	`144`	`logger.info("Validating {} from {}", r.getResource().getResourceType().name(), r.getFilename());`
`146`	`145`
`147`		`- if (r.getResource() instanceof Bundle)`
	`146`	`+ if (r.getResource() instanceof Bundle b)`
`148`	`147`	`{`
`149`		`- Bundle validationResult = validator.validate((Bundle) r.getResource());`
	`148`	`+ Bundle validationResult = logExecutionTimeInMs(() -> validator.validate(b), "Bundle");`
`150`	`149`	`System.out.println(getOutputParser().encodeResourceToString(validationResult));`
`151`	`150`	`}`
`152`	`151`	`else`
`153`	`152`	`{`
`154`		`- ValidationResult validationResult = validator.validate(r.getResource());`
	`153`	`+ ValidationResult validationResult = logExecutionTimeInMs(() -> validator.validate(r.getResource()),`
	`154`	`+ r.getResource().getResourceType().name());`
`155`	`155`	`System.out.println(getOutputParser().encodeResourceToString(validationResult.toOperationOutcome()));`
`156`	`156`	`}`
`157`	`157`	`});`
`158`	`158`	`}`
`159`	`159`
	`160`	`+ private <T> T logExecutionTimeInMs(Supplier<T> supplier, String resourceType)`
	`161`	`+ {`
	`162`	`+ long t0 = System.currentTimeMillis();`
	`163`	`+ T t = supplier.get();`
	`164`	`+ long t1 = System.currentTimeMillis();`
	`165`	`+ logger.debug("{} validated in {} ms", resourceType, t1 - t0);`
	`166`	`+ return t;`
	`167`	`+ }`
	`168`	`+`
`160`	`169`	`private IParser getOutputParser()`
`161`	`170`	`{`
`162`	`171`	`switch (output)`
`@@ -188,7 +197,7 @@ private FileNameAndResource tryJson(String file)`
`188`	`197`	`try (InputStream in = Files.newInputStream(Paths.get(file)))`
`189`	`198`	`{`
`190`	`199`	`IBaseResource resource = fhirContext.newJsonParser().parseResource(in);`
`191`		`- logger.info("{} read from {}", resource.getClass().getSimpleName(), file);`
	`200`	`+ logger.debug("{} read from {}", resource.getClass().getSimpleName(), file);`
`192`	`201`	`return new FileNameAndResource(file, (Resource) resource);`
`193`	`202`	`}`
`194`	`203`	`catch (Exception e)`
`@@ -203,7 +212,7 @@ private FileNameAndResource tryXml(String file)`
`203`	`212`	`try (InputStream in = Files.newInputStream(Paths.get(file)))`
`204`	`213`	`{`
`205`	`214`	`IBaseResource resource = fhirContext.newXmlParser().parseResource(in);`
`206`		`- logger.info("{} read from {}", resource.getClass().getSimpleName(), file);`
	`215`	`+ logger.debug("{} read from {}", resource.getClass().getSimpleName(), file);`
`207`	`216`	`return new FileNameAndResource(file, (Resource) resource);`
`208`	`217`	`}`
`209`	`218`	`catch (Exception e)`
Original file line number	Diff line number	Diff line change
`@@ -29,6 +29,7 @@`
`29`	`29`	`import ca.uhn.fhir.context.support.DefaultProfileValidationSupport;`
`30`	`30`	`import ca.uhn.fhir.context.support.IValidationSupport;`
`31`	`31`	`import dev.dsf.fhir.validator.client.TerminologyServerClient;`
	`32`	`+import dev.dsf.fhir.validator.implementation_guide.ValidationPackageIdentifier;`
`32`	`33`	`import dev.dsf.fhir.validator.implementation_guide.ValidationPackageWithDepedencies;`
`33`	`34`	`import dev.dsf.fhir.validator.structure_definition.SnapshotGenerator;`
`34`	`35`	`import dev.dsf.fhir.validator.structure_definition.SnapshotGenerator.SnapshotWithValidationMessages;`
`@@ -154,27 +155,29 @@ private List<ValueSet> withExpandedValueSets(ValidationPackageWithDepedencies pa`
`154`	`155`
`155`	`156`	`packageWithDependencies.getValueSetsIncludingDependencies(valueSetBindingStrengths, fhirContext).forEach(v ->`
`156`	`157`	`{`
`157`		`- logger.debug("Expanding ValueSet {}\|{}", v.getUrl(), v.getVersion());`
	`158`	`+ logger.debug("Expanding ValueSet {}\|{} from package (incl. dependencies) {}", v.getUrl(), v.getVersion(),`
	`159`	`+ packageWithDependencies.getIdentifier().toString());`
`158`	`160`
`159`	`161`	`// ValueSet uses filter or import in compose`
`160`	`162`	`if (v.hasCompose() && ((v.getCompose().hasInclude()`
`161`	`163`	`&& (v.getCompose().getInclude().stream().anyMatch(c -> c.hasFilter() \|\| c.hasValueSet())))`
`162`	`164`	`\|\| (v.getCompose().hasExclude()`
`163`	`165`	`&& v.getCompose().getExclude().stream().anyMatch(c -> c.hasFilter() \|\| c.hasValueSet()))))`
`164`	`166`	`{`
`165`		`- expandExternal(expandedValueSets, v);`
	`167`	`+ expandExternal(expandedValueSets, v, packageWithDependencies.getIdentifier());`
`166`	`168`	`}`
`167`	`169`	`else`
`168`	`170`	`{`
`169`	`171`	`// will try external expansion if internal not successful`
`170`		`- expandInternal(expandedValueSets, expander, v);`
	`172`	`+ expandInternal(expandedValueSets, expander, v, packageWithDependencies.getIdentifier());`
`171`	`173`	`}`
`172`	`174`	`});`
`173`	`175`
`174`	`176`	`return expandedValueSets;`
`175`	`177`	`}`
`176`	`178`
`177`		`- private void expandExternal(List<ValueSet> expandedValueSets, ValueSet v)`
	`179`	`+ private void expandExternal(List<ValueSet> expandedValueSets, ValueSet v,`
	`180`	`+ ValidationPackageIdentifier validationPackageIdentifier)`
`178`	`181`	`{`
`179`	`182`	`try`
`180`	`183`	`{`
`@@ -184,41 +187,45 @@ private void expandExternal(List<ValueSet> expandedValueSets, ValueSet v)`
`184`	`187`	`catch (WebApplicationException e)`
`185`	`188`	`{`
`186`	`189`	`logger.warn(`
`187`		`- "Error while expanding ValueSet {}\|{} externally, this may result in incomplete validation: {} - {}",`
`188`		`- v.getUrl(), v.getVersion(), e.getClass().getName(), e.getMessage());`
	`190`	`+ "Unable to expand ValueSet {}\|{} from package (incl. dependencies) {} externally, this may result in incomplete validation: {} - {}",`
	`191`	`+ v.getUrl(), v.getVersion(), validationPackageIdentifier.toString(), e.getClass().getName(),`
	`192`	`+ e.getMessage());`
`189`	`193`	`getOutcome(e).ifPresent(m -> logger.debug("Expansion error response: {}", m));`
`190`	`194`	`logger.debug("ValueSet with error while expanding: {}",`
`191`	`195`	`fhirContext.newJsonParser().encodeResourceToString(v));`
`192`	`196`	`}`
`193`	`197`	`catch (Exception e)`
`194`	`198`	`{`
`195`	`199`	`logger.warn(`
`196`		`- "Error while expanding ValueSet {}\|{} externally, this may result in incomplete validation: {} - {}",`
`197`		`- v.getUrl(), v.getVersion(), e.getClass().getName(), e.getMessage());`
	`200`	`+ "Unable to expand ValueSet {}\|{} from package (incl. dependencies) {} externally, this may result in incomplete validation: {} - {}",`
	`201`	`+ v.getUrl(), v.getVersion(), validationPackageIdentifier.toString(), e.getClass().getName(),`
	`202`	`+ e.getMessage());`
`198`	`203`	`logger.debug("ValueSet with error while expanding: {}",`
`199`	`204`	`fhirContext.newJsonParser().encodeResourceToString(v));`
`200`	`205`	`}`
`201`	`206`	`}`
`202`	`207`
`203`		`- private void expandInternal(List<ValueSet> expandedValueSets, ValueSetExpander expander, ValueSet v)`
	`208`	`+ private void expandInternal(List<ValueSet> expandedValueSets, ValueSetExpander expander, ValueSet v,`
	`209`	`+ ValidationPackageIdentifier validationPackageIdentifier)`
`204`	`210`	`{`
`205`	`211`	`try`
`206`	`212`	`{`
`207`	`213`	`ValueSetExpansionOutcome expansion = expander.expand(v);`
`208`	`214`
`209`	`215`	`if (expansion.getError() != null)`
`210`		`- logger.warn("Error while expanding ValueSet {}\|{} internally: {}", v.getUrl(), v.getVersion(),`
`211`		`- expansion.getError());`
	`216`	`+ logger.warn("Unable to expand ValueSet {}\|{} from package (incl. dependencies) {} internally: {}",`
	`217`	`+ v.getUrl(), v.getVersion(), validationPackageIdentifier.toString(), expansion.getError());`
`212`	`218`	`else`
`213`	`219`	`expandedValueSets.add(expansion.getValueset());`
`214`	`220`	`}`
`215`	`221`	`catch (Exception e)`
`216`	`222`	`{`
`217`	`223`	`logger.info(`
`218`		`- "Error while expanding ValueSet {}\|{} internally: {} - {}, trying to expand via external terminology server next",`
`219`		`- v.getUrl(), v.getVersion(), e.getClass().getName(), e.getMessage());`
	`224`	`+ "Unable to expand ValueSet {}\|{} from package (incl. dependencies) {} internally: {} - {}, trying to expand via external terminology server next",`
	`225`	`+ v.getUrl(), v.getVersion(), validationPackageIdentifier.toString(), e.getClass().getName(),`
	`226`	`+ e.getMessage());`
`220`	`227`
`221`		`- expandExternal(expandedValueSets, v);`
	`228`	`+ expandExternal(expandedValueSets, v, validationPackageIdentifier);`
`222`	`229`	`}`
`223`	`230`	`}`
`224`	`231`
`@@ -250,15 +257,16 @@ private IValidationSupport withSnapshots(List<ValueSet> expandedValueSets,`
`250`	`257`	`packageWithDependencies.getValidationSupportResources().getStructureDefinitions().stream()`
`251`	`258`	`.filter(s -> s.hasDifferential() && !s.hasSnapshot())`
`252`	`259`	`.forEach(diff -> createSnapshot(packageWithDependencies, snapshotsAndExpandedValueSets, snapshots,`
`253`		`- generator, diff));`
	`260`	`+ generator, diff, packageWithDependencies.getIdentifier()));`
`254`	`261`	`}`
`255`	`262`
`256`	`263`	`return supportChain;`
`257`	`264`	`}`
`258`	`265`
`259`	`266`	`private void createSnapshot(ValidationPackageWithDepedencies packageWithDependencies,`
`260`	`267`	`ValidationSupportWithCustomResources snapshotsAndExpandedValueSets,`
`261`		`- Map<String, StructureDefinition> snapshots, SnapshotGenerator generator, StructureDefinition diff)`
	`268`	`+ Map<String, StructureDefinition> snapshots, SnapshotGenerator generator, StructureDefinition diff,`
	`269`	`+ ValidationPackageIdentifier validationPackageIdentifier)`
`262`	`270`	`{`
`263`	`271`	`if (snapshots.containsKey(diff.getUrl() + "\|" + diff.getVersion()))`
`264`	`272`	`return;`
`@@ -267,8 +275,8 @@ private void createSnapshot(ValidationPackageWithDepedencies packageWithDependen`
`267`	`275`	`definitions.addAll(packageWithDependencies.getStructureDefinitionDependencies(diff));`
`268`	`276`	`definitions.add(diff);`
`269`	`277`
`270`		`- logger.debug("Generating snapshot for {}\|{}, base {}, dependencies {}", diff.getUrl(), diff.getVersion(),`
`271`		`- diff.getBaseDefinition(),`
	`278`	`+ logger.debug("Generating snapshot for {}\|{} from package (incl. dependencies) {}, base {}, dependencies {}",`
	`279`	`+ diff.getUrl(), diff.getVersion(), validationPackageIdentifier.toString(), diff.getBaseDefinition(),`
`272`	`280`	`definitions.stream()`
`273`	`281`	`.filter(sd -> !sd.equals(diff) && !sd.getUrl().equals(diff.getBaseDefinition())`
`274`	`282`	`&& !(sd.getUrl() + "\|" + sd.getVersion()).equals(diff.getBaseDefinition()))`
`@@ -284,16 +292,19 @@ private void createSnapshot(ValidationPackageWithDepedencies packageWithDependen`
`284`	`292`
`285`	`293`	`if (PublicationStatus.ACTIVE.equals(diff.getStatus()) && !dependenciesWithDifferentStatus.isEmpty())`
`286`	`294`	`{`
`287`		`- logger.warn("StructureDefinition {}\|{}, has dependencies with no active status [{}]", diff.getUrl(),`
`288`		`- diff.getVersion(), dependenciesWithDifferentStatus);`
	`295`	`+ logger.warn(`
	`296`	`+ "StructureDefinition {}\|{} from package (incl. dependencies) {}, has dependencies with no active status [{}]",`
	`297`	`+ diff.getUrl(), diff.getVersion(), validationPackageIdentifier.toString(),`
	`298`	`+ dependenciesWithDifferentStatus);`
`289`	`299`	`}`
`290`	`300`
`291`	`301`	`definitions.stream().filter(sd -> sd.hasDifferential() && !sd.hasSnapshot()`
`292`	`302`	`&& !snapshots.containsKey(sd.getUrl() + "\|" + sd.getVersion())).forEach(sd ->`
`293`	`303`	`{`
`294`	`304`	`try`
`295`	`305`	`{`
`296`		`- logger.debug("Generating snapshot for {}\|{}", sd.getUrl(), sd.getVersion());`
	`306`	`+ logger.debug("Generating snapshot for {}\|{} from package (incl. dependencies) {}", sd.getUrl(),`
	`307`	`+ sd.getVersion(), validationPackageIdentifier.toString());`
`297`	`308`	`SnapshotWithValidationMessages snapshot = generator.generateSnapshot(sd);`
`298`	`309`
`299`	`310`	`if (snapshot.getSnapshot().hasSnapshot())`
`@@ -304,8 +315,8 @@ private void createSnapshot(ValidationPackageWithDepedencies packageWithDependen`
`304`	`315`	`}`
`305`	`316`	`else`
`306`	`317`	`logger.error(`
`307`		`- "Error while generating snapshot for {}\|{}: Not snaphsot returned from generator",`
`308`		`- diff.getUrl(), diff.getVersion());`
	`318`	`+ "Error while generating snapshot for {}\|{} from package (incl. dependencies) {}: Not snaphsot returned from generator",`
	`319`	`+ diff.getUrl(), diff.getVersion(), validationPackageIdentifier.toString());`
`309`	`320`
`310`	`321`	`snapshot.getMessages().forEach(m ->`
`311`	`322`	`{`
`@@ -320,12 +331,15 @@ private void createSnapshot(ValidationPackageWithDepedencies packageWithDependen`
`320`	`331`	`}`
`321`	`332`	`catch (Exception e)`
`322`	`333`	`{`
`323`		`- logger.error("Error while generating snapshot for {}\|{}: {} - {}", diff.getUrl(),`
`324`		`- diff.getVersion(), e.getClass().getName(), e.getMessage());`
	`334`	`+ logger.error(`
	`335`	`+ "Error while generating snapshot for {}\|{} from package (incl. dependencies) {}: {} - {}",`
	`336`	`+ diff.getUrl(), diff.getVersion(), validationPackageIdentifier.toString(),`
	`337`	`+ e.getClass().getName(), e.getMessage());`
`325`	`338`	`}`
`326`	`339`	`});`
`327`	`340`
`328`		`- logger.debug("Generating snapshot for {}\|{} [Done]", diff.getUrl(), diff.getVersion());`
	`341`	`+ logger.debug("Generating snapshot for {}\|{} from package (incl. dependencies) {} [Done]", diff.getUrl(),`
	`342`	`+ diff.getVersion(), validationPackageIdentifier.toString());`
`329`	`343`	`}`
`330`	`344`
`331`	`345`	`private ValidationSupportChain createSupportChain(FhirContext context,`