Issue/14 configurable log level

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());
 			}
 		};
 	}

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);
 		}
 	}

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);
 		}

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)

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,

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">