Issue 3648 fix mdm log messages (#3649)

* fix log messages

* fix log messages

* fix log messages

* fix log messages

* fix log messages

* fix log messages

* review feedback and fix log messages

* improved logging

* improved logging
This commit is contained in:
Ken Stevens 2022-05-26 14:50:17 -04:00 committed by GitHub
parent ad3294f8e8
commit 4f4032d892
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
12 changed files with 87 additions and 52 deletions

View File

@ -98,7 +98,7 @@ public class MdmLinkDaoSvc {
mdmLink.setPartitionId(new PartitionablePartitionId(partitionId.getFirstPartitionIdOrNull(), partitionId.getPartitionDate()));
}
String message = String.format("Creating MdmLink from %s to %s.", theGoldenResource.getIdElement().toUnqualifiedVersionless(), theSourceResource.getIdElement().toUnqualifiedVersionless());
String message = String.format("Creating %s link from %s to Golden Resource %s.", mdmLink.getMatchResult(), theSourceResource.getIdElement().toUnqualifiedVersionless(), theGoldenResource.getIdElement().toUnqualifiedVersionless());
theMdmTransactionContext.addTransactionLogMessage(message);
ourLog.debug(message);
save(mdmLink);

View File

@ -21,11 +21,11 @@ package ca.uhn.fhir.jpa.mdm.svc;
*/
import ca.uhn.fhir.interceptor.model.RequestPartitionId;
import ca.uhn.fhir.jpa.mdm.svc.candidate.MdmCandidateSearchSvc;
import ca.uhn.fhir.mdm.api.IMdmMatchFinderSvc;
import ca.uhn.fhir.mdm.api.MatchedTarget;
import ca.uhn.fhir.mdm.log.Logs;
import ca.uhn.fhir.mdm.rules.svc.MdmResourceMatcherSvc;
import ca.uhn.fhir.jpa.mdm.svc.candidate.MdmCandidateSearchSvc;
import org.hl7.fhir.instance.model.api.IAnyResource;
import org.slf4j.Logger;
import org.springframework.beans.factory.annotation.Autowired;
@ -37,6 +37,8 @@ import java.util.Collection;
import java.util.List;
import java.util.stream.Collectors;
import static ca.uhn.fhir.jpa.mdm.svc.candidate.CandidateSearcher.idOrType;
@Service
public class MdmMatchFinderSvcImpl implements IMdmMatchFinderSvc {
@ -57,7 +59,7 @@ public class MdmMatchFinderSvcImpl implements IMdmMatchFinderSvc {
.map(candidate -> new MatchedTarget(candidate, myMdmResourceMatcherSvc.getMatchResult(theResource, candidate)))
.collect(Collectors.toList());
ourLog.info("Found {} matched targets for {}.", matches.size(), theResourceType);
ourLog.trace("Found {} matched targets for {}.", matches.size(), idOrType(theResource, theResourceType));
return matches;
}

View File

@ -126,7 +126,7 @@ public class MdmMatchLinkSvc {
}
private void handleMdmWithNoCandidates(IAnyResource theResource, MdmTransactionContext theMdmTransactionContext) {
log(theMdmTransactionContext, String.format("There were no matched candidates for MDM, creating a new %s.", theResource.getIdElement().getResourceType()));
log(theMdmTransactionContext, String.format("There were no matched candidates for MDM, creating a new %s Golden Resource.", theResource.getIdElement().getResourceType()));
IAnyResource newGoldenResource = myGoldenResourceHelper.createGoldenResourceFromMdmSourceResource(theResource, theMdmTransactionContext);
// TODO GGG :)
// 1. Get the right helper

View File

@ -57,7 +57,7 @@ public class MdmResourceFilteringSvc {
*/
public boolean shouldBeProcessed(IAnyResource theResource) {
if (MdmResourceUtil.isMdmManaged(theResource)) {
ourLog.debug("MDM Message handler is dropping [{}] as it is MDM-managed.", theResource.getId());
ourLog.trace("MDM Message handler is dropping [{}] as it is MDM-managed.", theResource.getId());
return false;
}

View File

@ -28,6 +28,7 @@ import ca.uhn.fhir.jpa.partition.SystemRequestDetails;
import ca.uhn.fhir.jpa.searchparam.SearchParameterMap;
import ca.uhn.fhir.mdm.api.IMdmSettings;
import ca.uhn.fhir.rest.api.server.IBundleProvider;
import org.hl7.fhir.instance.model.api.IAnyResource;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
@ -83,4 +84,11 @@ public class CandidateSearcher {
public Optional<IBundleProvider> search(String theResourceType, String theResourceCriteria) {
return this.search(theResourceType, theResourceCriteria, RequestPartitionId.allPartitions());
}
public static String idOrType(IAnyResource theResource, String theResourceType) {
if (theResource.getIdElement() == null) {
return theResourceType;
}
return theResource.getIdElement().toUnqualifiedVersionless().toString();
}
}

View File

@ -52,22 +52,22 @@ public class FindCandidateByEidSvc extends BaseCandidateFinder {
private MdmLinkDaoSvc myMdmLinkDaoSvc;
@Override
protected List<MatchedGoldenResourceCandidate> findMatchGoldenResourceCandidates(IAnyResource theBaseResource) {
protected List<MatchedGoldenResourceCandidate> findMatchGoldenResourceCandidates(IAnyResource theIncomingResource) {
List<MatchedGoldenResourceCandidate> retval = new ArrayList<>();
List<CanonicalEID> eidFromResource = myEIDHelper.getExternalEid(theBaseResource);
List<CanonicalEID> eidFromResource = myEIDHelper.getExternalEid(theIncomingResource);
if (!eidFromResource.isEmpty()) {
for (CanonicalEID eid : eidFromResource) {
Optional<IAnyResource> oFoundGoldenResource = myMdmResourceDaoSvc.searchGoldenResourceByEID(eid.getValue(), theBaseResource.getIdElement().getResourceType(), (RequestPartitionId) theBaseResource.getUserData(Constants.RESOURCE_PARTITION_ID));
Optional<IAnyResource> oFoundGoldenResource = myMdmResourceDaoSvc.searchGoldenResourceByEID(eid.getValue(), theIncomingResource.getIdElement().getResourceType(), (RequestPartitionId) theIncomingResource.getUserData(Constants.RESOURCE_PARTITION_ID));
if (oFoundGoldenResource.isPresent()) {
IAnyResource foundGoldenResource = oFoundGoldenResource.get();
// Exclude manually declared NO_MATCH links from candidates
if (isNoMatch(foundGoldenResource, theBaseResource)) {
if (isNoMatch(foundGoldenResource, theIncomingResource)) {
continue;
}
Long pidOrNull = myIdHelperService.getPidOrNull(foundGoldenResource);
MatchedGoldenResourceCandidate mpc = new MatchedGoldenResourceCandidate(new ResourcePersistentId(pidOrNull), MdmMatchOutcome.EID_MATCH);
ourLog.debug("Matched {} by EID {}", foundGoldenResource.getIdElement(), eid);
ourLog.debug("Incoming Resource {} matched Golden Resource {} by EID {}", theIncomingResource.getIdElement().toUnqualifiedVersionless(), foundGoldenResource.getIdElement().toUnqualifiedVersionless(), eid);
retval.add(mpc);
}
}

View File

@ -22,7 +22,6 @@ package ca.uhn.fhir.jpa.mdm.svc.candidate;
import ca.uhn.fhir.context.FhirContext;
import ca.uhn.fhir.interceptor.model.RequestPartitionId;
import ca.uhn.fhir.jpa.dao.index.IdHelperService;
import ca.uhn.fhir.jpa.dao.index.IJpaIdHelperService;
import ca.uhn.fhir.jpa.entity.MdmLink;
import ca.uhn.fhir.jpa.mdm.dao.MdmLinkDaoSvc;
@ -76,21 +75,39 @@ public class FindCandidateByExampleSvc extends BaseCandidateFinder {
// The data flow is as follows ->
// MatchedTargetCandidate -> Golden Resource -> MdmLink -> MatchedGoldenResourceCandidate
matchedCandidates = matchedCandidates.stream().filter(mc -> mc.isMatch() || mc.isPossibleMatch()).collect(Collectors.toList());
List<String> skippedLogMessages = new ArrayList<>();
List<String> matchedLogMessages = new ArrayList<>();
for (MatchedTarget match : matchedCandidates) {
Optional<MdmLink> optionalMdmLink = myMdmLinkDaoSvc.getMatchedLinkForSourcePid(myIdHelperService.getPidOrNull(match.getTarget()));
if (!optionalMdmLink.isPresent()) {
if (ourLog.isDebugEnabled()) {
skippedLogMessages.add(String.format("%s does not link to a Golden Resource (it may be a Golden Resource itself). Removing candidate.", match.getTarget().getIdElement().toUnqualifiedVersionless()));
}
continue;
}
MdmLink matchMdmLink = optionalMdmLink.get();
if (goldenResourcePidsToExclude.contains(matchMdmLink.getGoldenResourcePid())) {
ourLog.info("Skipping MDM on candidate Golden Resource with PID {} due to manual NO_MATCH", matchMdmLink.getGoldenResourcePid());
skippedLogMessages.add(String.format("Skipping MDM on candidate Golden Resource with PID %s due to manual NO_MATCH", matchMdmLink.getGoldenResourcePid()));
continue;
}
MatchedGoldenResourceCandidate candidate = new MatchedGoldenResourceCandidate(getResourcePersistentId(matchMdmLink.getGoldenResourcePid()), match.getMatchResult());
if (ourLog.isDebugEnabled()) {
matchedLogMessages.add(String.format("Navigating from matched resource %s to its Golden Resource %s", match.getTarget().getIdElement().toUnqualifiedVersionless(), matchMdmLink.getGoldenResource().getIdDt().toUnqualifiedVersionless()));
}
retval.add(candidate);
}
if (ourLog.isDebugEnabled()) {
for (String logMessage: skippedLogMessages) {
ourLog.debug(logMessage);
}
for (String logMessage: matchedLogMessages) {
ourLog.debug(logMessage);
}
}
return retval;
}

View File

@ -20,9 +20,8 @@ package ca.uhn.fhir.jpa.mdm.svc.candidate;
* #L%
*/
import ca.uhn.fhir.interceptor.model.RequestPartitionId;
import ca.uhn.fhir.jpa.dao.index.IdHelperService;
import ca.uhn.fhir.i18n.Msg;
import ca.uhn.fhir.interceptor.model.RequestPartitionId;
import ca.uhn.fhir.jpa.dao.index.IJpaIdHelperService;
import ca.uhn.fhir.mdm.api.IMdmSettings;
import ca.uhn.fhir.mdm.log.Logs;
@ -44,6 +43,7 @@ import java.util.Map;
import java.util.Optional;
import java.util.stream.Collectors;
import static ca.uhn.fhir.jpa.mdm.svc.candidate.CandidateSearcher.idOrType;
import static ca.uhn.fhir.mdm.api.MdmConstants.ALL_RESOURCE_SEARCH_PARAM_TYPE;
@Service
@ -93,14 +93,16 @@ public class MdmCandidateSearchSvc {
searchForIdsAndAddToMap(theResourceType, theResource, matchedPidsToResources, filterCriteria, resourceSearchParam, theRequestPartitionId);
}
}
//Obviously we don't want to consider the freshly added resource as a potential candidate.
// Obviously we don't want to consider the incoming resource as a potential candidate.
// Sometimes, we are running this function on a resource that has not yet been persisted,
// so it may not have an ID yet, precluding the need to remove it.
if (theResource.getIdElement().getIdPart() != null) {
matchedPidsToResources.remove(myJpaIdHelperService.getPidOrNull(theResource));
if (matchedPidsToResources.remove(myJpaIdHelperService.getPidOrNull(theResource)) != null) {
ourLog.debug("Removing incoming resource {} from list of candidates.", theResource.getIdElement().toUnqualifiedVersionless());
}
}
ourLog.info("Found {} resources for {}", matchedPidsToResources.size(), theResourceType);
ourLog.info("Candidate search found {} matching resources for {}", matchedPidsToResources.size(), idOrType(theResource, theResourceType));
return matchedPidsToResources.values();
}

View File

@ -76,15 +76,15 @@ public class Batch2CoordinatorIT extends BaseJpaR4Test {
JobInstanceStartRequest request = buildRequest(jobId);
myFirstStepLatch.setExpectedCount(1);
myLastStepLatch.setExpectedCount(1);
String instanceId = myJobCoordinator.startInstance(request);
myFirstStepLatch.awaitExpected();
myBatch2JobHelper.assertNoGatedStep(instanceId);
myLastStepLatch.setExpectedCount(1);
// Since there was only one chunk, the job should proceed without requiring a maintenance pass
myLastStepLatch.awaitExpected();
myBatch2JobHelper.awaitSingleChunkJobCompletion(instanceId);
myLastStepLatch.awaitExpected();
}

View File

@ -111,11 +111,7 @@ public class CanonicalEID {
@Override
public String toString() {
return "CanonicalEID{" +
"mySystem='" + mySystem + '\'' +
", myUse='" + myUse + '\'' +
", myValue='" + myValue + '\'' +
'}';
return mySystem + '|' + myValue;
}

View File

@ -20,14 +20,14 @@ package ca.uhn.fhir.mdm.rules.svc;
* #L%
*/
import ca.uhn.fhir.i18n.Msg;
import ca.uhn.fhir.context.ConfigurationException;
import ca.uhn.fhir.context.FhirContext;
import ca.uhn.fhir.i18n.Msg;
import ca.uhn.fhir.mdm.api.IMdmSettings;
import ca.uhn.fhir.mdm.api.MdmConstants;
import ca.uhn.fhir.mdm.api.MdmMatchEvaluation;
import ca.uhn.fhir.mdm.api.MdmMatchOutcome;
import ca.uhn.fhir.mdm.api.MdmMatchResultEnum;
import ca.uhn.fhir.mdm.api.IMdmSettings;
import ca.uhn.fhir.mdm.log.Logs;
import ca.uhn.fhir.mdm.rules.json.MdmFieldMatchJson;
import ca.uhn.fhir.mdm.rules.json.MdmRulesJson;
@ -130,7 +130,7 @@ public class MdmResourceMatcherSvc {
ourLog.debug("Matcher {} is not valid for resource type: {}. Skipping it.", fieldComparator.getName(), resourceType);
continue;
}
ourLog.debug("Matcher {} is valid for resource type: {}. Evaluating match.", fieldComparator.getName(), resourceType);
ourLog.trace("Matcher {} is valid for resource type: {}. Evaluating match.", fieldComparator.getName(), resourceType);
MdmMatchEvaluation matchEvaluation = fieldComparator.match(theLeftResource, theRightResource);
if (matchEvaluation.match) {
vector |= (1 << i);

View File

@ -20,13 +20,13 @@ package ca.uhn.fhir.mdm.util;
* #L%
*/
import ca.uhn.fhir.i18n.Msg;
import ca.uhn.fhir.context.BaseRuntimeChildDefinition;
import ca.uhn.fhir.context.BaseRuntimeElementCompositeDefinition;
import ca.uhn.fhir.context.FhirContext;
import ca.uhn.fhir.context.FhirVersionEnum;
import ca.uhn.fhir.context.RuntimeResourceDefinition;
import ca.uhn.fhir.fhirpath.IFhirPath;
import ca.uhn.fhir.i18n.Msg;
import ca.uhn.fhir.mdm.api.IMdmSettings;
import ca.uhn.fhir.mdm.api.IMdmSurvivorshipService;
import ca.uhn.fhir.mdm.log.Logs;
@ -94,7 +94,7 @@ public class GoldenResourceHelper {
// hapi has 2 metamodels: for children and types
BaseRuntimeChildDefinition goldenResourceIdentifier = resourceDefinition.getChildByName(FIELD_NAME_IDENTIFIER);
cloneAllExternalEidsIntoNewGoldenResource(goldenResourceIdentifier, theIncomingResource, newGoldenResource);
cloneMDMEidsIntoNewGoldenResource(goldenResourceIdentifier, theIncomingResource, newGoldenResource);
addHapiEidIfNoExternalEidIsPresent(newGoldenResource, goldenResourceIdentifier, theIncomingResource);
@ -126,24 +126,30 @@ public class GoldenResourceHelper {
cloneEidIntoResource(myFhirContext, theSourceResource, hapiEid);
}
private void cloneAllExternalEidsIntoNewGoldenResource(BaseRuntimeChildDefinition theGoldenResourceIdentifier,
IAnyResource theGoldenResource, IBase theNewGoldenResource) {
private void cloneMDMEidsIntoNewGoldenResource(BaseRuntimeChildDefinition theGoldenResourceIdentifier,
IAnyResource theIncomingResource, IBase theNewGoldenResource) {
String incomingResourceType = myFhirContext.getResourceType(theIncomingResource);
String mdmEIDSystem = myMdmSettings.getMdmRules().getEnterpriseEIDSystemForResourceType(incomingResourceType);
if (mdmEIDSystem == null) {
return;
}
// FHIR choice types - fields within fhir where we have a choice of ids
IFhirPath fhirPath = myFhirContext.newFhirPath();
List<IBase> goldenResourceIdentifiers = theGoldenResourceIdentifier.getAccessor().getValues(theGoldenResource);
List<IBase> incomingResourceIdentifiers = theGoldenResourceIdentifier.getAccessor().getValues(theIncomingResource);
for (IBase base : goldenResourceIdentifiers) {
Optional<IPrimitiveType> system = fhirPath.evaluateFirst(base, "system", IPrimitiveType.class);
if (system.isPresent()) {
String resourceType = myFhirContext.getResourceType(theGoldenResource);
String mdmSystem = myMdmSettings.getMdmRules().getEnterpriseEIDSystemForResourceType(resourceType);
String baseSystem = system.get().getValueAsString();
if (Objects.equals(baseSystem, mdmSystem)) {
ca.uhn.fhir.util.TerserUtil.cloneEidIntoResource(myFhirContext, theGoldenResourceIdentifier, base, theNewGoldenResource);
ourLog.debug("System {} differs from system in the MDM rules {}", baseSystem, mdmSystem);
for (IBase incomingResourceIdentifier : incomingResourceIdentifiers) {
Optional<IPrimitiveType> incomingIdentifierSystem = fhirPath.evaluateFirst(incomingResourceIdentifier, "system", IPrimitiveType.class);
if (incomingIdentifierSystem.isPresent()) {
String incomingIdentifierSystemString = incomingIdentifierSystem.get().getValueAsString();
if (Objects.equals(incomingIdentifierSystemString, mdmEIDSystem)) {
ourLog.debug("Incoming resource EID System {} matches EID system in the MDM rules. Copying to Golden Resource.", incomingIdentifierSystemString);
ca.uhn.fhir.util.TerserUtil.cloneEidIntoResource(myFhirContext, theGoldenResourceIdentifier, incomingResourceIdentifier, theNewGoldenResource);
} else {
ourLog.debug("Incoming resource EID System {} differs from EID system in the MDM rules {}. Not copying to Golden Resource.", incomingIdentifierSystemString, mdmEIDSystem);
}
} else {
ourLog.debug("System is missing, skipping");
ourLog.debug("No EID System in incoming resource.");
}
}
}
@ -177,13 +183,14 @@ public class GoldenResourceHelper {
}
if (goldenResourceOfficialEid.isEmpty() || !myMdmSettings.isPreventMultipleEids()) {
if (addCanonicalEidsToGoldenResourceIfAbsent(theGoldenResource, incomingSourceEid)) {
log(theMdmTransactionContext, "Incoming resource:" + theSourceResource.getIdElement().toUnqualifiedVersionless() + " + with EID " + incomingSourceEid.stream().map(CanonicalEID::toString).collect(Collectors.joining(","))
+ " is applying this EIDs to its related Source Resource, as this Source Resource does not yet have an external EID");
addCanonicalEidsToGoldenResourceIfAbsent(theGoldenResource, incomingSourceEid);
+ " is applying this EID to its related Golden Resource, as this Golden Resource does not yet have an external EID");
}
} else if (!goldenResourceOfficialEid.isEmpty() && myEIDHelper.eidMatchExists(goldenResourceOfficialEid, incomingSourceEid)) {
log(theMdmTransactionContext, "incoming resource:" + theSourceResource.getIdElement().toVersionless() + " with EIDs " + incomingSourceEid.stream().map(CanonicalEID::toString).collect(Collectors.joining(",")) + " does not need to overwrite Golden Resource, as this EID is already present");
log(theMdmTransactionContext, "Incoming resource:" + theSourceResource.getIdElement().toVersionless() + " with EIDs " + incomingSourceEid.stream().map(CanonicalEID::toString).collect(Collectors.joining(",")) + " does not need to overwrite the EID in the Golden Resource, as this EID is already present in the Golden Resource");
} else {
throw new IllegalArgumentException(Msg.code(1490) + String.format("Source EIDs %s would create a duplicate golden resource, as EIDs %s already exist!",
throw new IllegalArgumentException(Msg.code(1490) + String.format("Incoming resource EID %s would create a duplicate Golden Resource, as Golden Resource EID %s already exists!",
incomingSourceEid.toString(), goldenResourceOfficialEid.toString()));
}
return theGoldenResource;
@ -208,7 +215,7 @@ public class GoldenResourceHelper {
String mdmSystem = myMdmSettings.getMdmRules().getEnterpriseEIDSystemForResourceType(resourceType);
String baseSystem = system.get().getValueAsString();
if (Objects.equals(baseSystem, mdmSystem)) {
ourLog.debug("Found EID confirming to MDM rules {}. It should not be copied, skipping", baseSystem);
ourLog.debug("Found EID confirming to MDM rules {}. It does not need to be copied, skipping", baseSystem);
continue;
}
}
@ -237,16 +244,19 @@ public class GoldenResourceHelper {
/**
* Given a list of incoming External EIDs, and a Golden Resource, apply all the EIDs to this resource, which did not already exist on it.
* @return true if an EID was added
*/
private void addCanonicalEidsToGoldenResourceIfAbsent(IBaseResource theGoldenResource, List<CanonicalEID> theIncomingSourceExternalEids) {
private boolean addCanonicalEidsToGoldenResourceIfAbsent(IBaseResource theGoldenResource, List<CanonicalEID> theIncomingSourceExternalEids) {
List<CanonicalEID> goldenResourceExternalEids = myEIDHelper.getExternalEid(theGoldenResource);
boolean addedEid = false;
for (CanonicalEID incomingExternalEid : theIncomingSourceExternalEids) {
if (goldenResourceExternalEids.contains(incomingExternalEid)) {
continue;
}
cloneEidIntoResource(myFhirContext, theGoldenResource, incomingExternalEid);
addedEid = true;
}
return addedEid;
}
public boolean hasIdentifier(IBaseResource theResource) {