From d31e75a0d34ce5cbd40e72b1370cab64a76dc8c8 Mon Sep 17 00:00:00 2001 From: Hauke Hund Date: Wed, 18 Jun 2025 00:02:14 +0200 Subject: [PATCH 1/4] configurable log level --- .../fhir/validator/main/ValidationConfig.java | 38 ++++++++++++++++++- src/main/resources/log4j2.xml | 1 - 2 files changed, 37 insertions(+), 2 deletions(-) diff --git a/src/main/java/dev/dsf/fhir/validator/main/ValidationConfig.java b/src/main/java/dev/dsf/fhir/validator/main/ValidationConfig.java index 7d6f40d..b77d4c5 100644 --- 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.logLevel:INFO}") + private LogLevel logLevel; + @Value("#{'${dev.dsf.validation.package:}'.trim().split('(,[ ]?)|(\\n)')}") private List 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 certificates = PemReader.readCertificates(trustCertificatesPath); return KeyStoreCreator.jksForTrustedCertificates(certificates); } diff --git a/src/main/resources/log4j2.xml b/src/main/resources/log4j2.xml index bcfa82e..5f10a42 100644 --- a/src/main/resources/log4j2.xml +++ b/src/main/resources/log4j2.xml @@ -8,7 +8,6 @@ - From daa148fde998b1cd99c74306de86b2b14934fe27 Mon Sep 17 00:00:00 2001 From: Hauke Hund Date: Wed, 18 Jun 2025 00:02:23 +0200 Subject: [PATCH 2/4] log message cleanup --- .../ValidationPackage.java | 10 +-- .../ValidationPackageWithDepedencies.java | 2 +- .../fhir/validator/main/ValidationMain.java | 6 +- .../service/ValidatorFactoryImpl.java | 66 +++++++++++-------- 4 files changed, 48 insertions(+), 36 deletions(-) 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 index 486c522..c850073 100644 --- 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 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 index 7a77cbe..8c2e6c9 100644 --- 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 neededValueSets, List 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/ValidationMain.java b/src/main/java/dev/dsf/fhir/validator/main/ValidationMain.java index 4f7a1a5..d953aad 100644 --- a/src/main/java/dev/dsf/fhir/validator/main/ValidationMain.java +++ b/src/main/java/dev/dsf/fhir/validator/main/ValidationMain.java @@ -138,8 +138,6 @@ 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()); @@ -188,7 +186,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 +201,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 index 13827d3..f66a9c1 100644 --- 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,7 +155,8 @@ private List 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() @@ -162,19 +164,20 @@ private List withExpandedValueSets(ValidationPackageWithDepedencies pa || (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 expandedValueSets, ValueSet v) + private void expandExternal(List expandedValueSets, ValueSet v, + ValidationPackageIdentifier validationPackageIdentifier) { try { @@ -184,8 +187,9 @@ private void expandExternal(List 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)); @@ -193,32 +197,35 @@ private void expandExternal(List expandedValueSets, ValueSet 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 expandedValueSets, ValueSetExpander expander, ValueSet v) + private void expandInternal(List 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,7 +257,7 @@ private IValidationSupport withSnapshots(List 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; @@ -258,7 +265,8 @@ private IValidationSupport withSnapshots(List expandedValueSets, private void createSnapshot(ValidationPackageWithDepedencies packageWithDependencies, ValidationSupportWithCustomResources snapshotsAndExpandedValueSets, - Map snapshots, SnapshotGenerator generator, StructureDefinition diff) + Map 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,8 +292,10 @@ 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() @@ -293,7 +303,8 @@ private void createSnapshot(ValidationPackageWithDepedencies packageWithDependen { 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, From 4b6f9b09f88ee1d97ddb8f8eee3f6815b57b6c30 Mon Sep 17 00:00:00 2001 From: Hauke Hund Date: Wed, 18 Jun 2025 00:05:31 +0200 Subject: [PATCH 3/4] log level property name fix --- src/main/java/dev/dsf/fhir/validator/main/ValidationConfig.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/main/java/dev/dsf/fhir/validator/main/ValidationConfig.java b/src/main/java/dev/dsf/fhir/validator/main/ValidationConfig.java index b77d4c5..3f0b28c 100644 --- a/src/main/java/dev/dsf/fhir/validator/main/ValidationConfig.java +++ b/src/main/java/dev/dsf/fhir/validator/main/ValidationConfig.java @@ -98,7 +98,7 @@ public Level level() @Value("${dev.dsf.validation:true}") private boolean validationEnabled; - @Value("${dev.dsf.logLevel:INFO}") + @Value("${dev.dsf.validation.logLevel:INFO}") private LogLevel logLevel; @Value("#{'${dev.dsf.validation.package:}'.trim().split('(,[ ]?)|(\\n)')}") From 576598a7cf7df4198656f6e2a880425f53736b89 Mon Sep 17 00:00:00 2001 From: Hauke Hund Date: Wed, 18 Jun 2025 00:14:45 +0200 Subject: [PATCH 4/4] log message with validation time in ms --- .../dsf/fhir/validator/main/ValidationMain.java | 17 ++++++++++++++--- 1 file changed, 14 insertions(+), 3 deletions(-) diff --git a/src/main/java/dev/dsf/fhir/validator/main/ValidationMain.java b/src/main/java/dev/dsf/fhir/validator/main/ValidationMain.java index d953aad..0a7eb54 100644 --- 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; @@ -142,19 +143,29 @@ public void validate(BundleValidator validator, String[] files) { 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 logExecutionTimeInMs(Supplier 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)