Log source info for mismatched version when fishing for best version

Also updates system lookup code for FSHCodes to avoid double-warning on mismatched version.

src/export/StructureDefinitionExporter.ts

@@ -791,7 +791,7 @@ export class StructureDefinitionExporter implements Fishable {
       if (item.type) {
         // there might be a |version appended to the type, so try to use the version but fall back
         // to any version if necessary
-        const extension = fishForFHIRBestVersion(this, item.type, Type.Extension);
+        const extension = fishForFHIRBestVersion(this, item.type, rule.sourceInfo, Type.Extension);
         if (extension == null) {
           logger.error(
             `Cannot create ${item.name} extension; unable to locate extension definition for: ${item.type}.`,

src/fhirtypes/ElementDefinition.ts

@@ -13,7 +13,15 @@ import { minify } from 'html-minifier-terser';
 import { isUri } from 'valid-url';
 import { StructureDefinition } from './StructureDefinition';
 import { CodeableConcept, Coding, Element, Quantity, Ratio, Reference } from './dataTypes';
-import { FshCanonical, FshCode, FshRatio, FshQuantity, FshReference, Invariant } from '../fshtypes';
+import {
+  FshCanonical,
+  FshCode,
+  FshRatio,
+  FshQuantity,
+  FshReference,
+  Invariant,
+  SourceInfo
+} from '../fshtypes';
 import { AddElementRule, AssignmentValueType, OnlyRule } from '../fshtypes/rules';
 import {
   AssignmentToCodeableReferenceError,
@@ -1655,7 +1663,13 @@ export class ElementDefinition {
           this.parent()?.type?.[0]?.code === 'CodeableReference'
             ? this.parent()
             : this;
-        if (!referenceConstrainingElement.typeSatisfiesTargetProfile(value.sdType, fisher)) {
+        if (
+          !referenceConstrainingElement.typeSatisfiesTargetProfile(
+            value.sdType,
+            value.sourceInfo,
+            fisher
+          )
+        ) {
           throw new InvalidTypeError(
             `Reference(${value.sdType})`,
             referenceConstrainingElement.type
@@ -1678,7 +1692,13 @@ export class ElementDefinition {
           Type.Instance
         );
         let canonicalUrl: string;
-        if (!this.typeSatisfiesTargetProfile(canonicalDefinition?.resourceType, fisher)) {
+        if (
+          !this.typeSatisfiesTargetProfile(
+            canonicalDefinition?.resourceType,
+            value.sourceInfo,
+            fisher
+          )
+        ) {
           throw new InvalidTypeError(`Canonical(${canonicalDefinition.resourceType})`, this.type);
         }
         if (canonicalDefinition?.url) {
@@ -1861,17 +1881,22 @@ export class ElementDefinition {
 
   /**
    * @param sdType - The type to check
+   * @param sourceInfo - Source information for logging purposes
    * @param fisher - A fishable implementation for finding definitions and metadata
    * @returns - False if the type does not satisfy the targetProfile, true otherwise (or if it can't be determined)
    */
-  private typeSatisfiesTargetProfile(sdType: string, fisher: Fishable): boolean {
+  private typeSatisfiesTargetProfile(
+    sdType: string,
+    sourceInfo: SourceInfo,
+    fisher: Fishable
+  ): boolean {
     // If no targetProfile is present, there is nothing to check the value against, so just allow it
     if (sdType && this.type[0].targetProfile) {
       const validTypes: string[] = [];
       this.type[0].targetProfile.forEach(tp => {
         // target profile may have a version after a | character.
         // fish for matching version, but fall back to any version if necessary.
-        const tpType = fishForMetadataBestVersion(fisher, tp)?.sdType;
+        const tpType = fishForMetadataBestVersion(fisher, tp, sourceInfo)?.sdType;
         if (tpType) {
           validTypes.push(tpType);
         }
@@ -2106,7 +2131,8 @@ export class ElementDefinition {
 
     if (code.system) {
       const csURI = code.system.split('|')[0];
-      const vsURI = fishForMetadataBestVersion(fisher, code.system, Type.ValueSet)?.url ?? '';
+      const vsURI =
+        fishForMetadataBestVersion(fisher, code.system, code.sourceInfo, Type.ValueSet)?.url ?? '';
       if (vsURI) {
         if (type === 'code' || type === 'string' || type === 'uri') {
           logger.warn(
@@ -2348,6 +2374,7 @@ export class ElementDefinition {
         let json = fishForFHIRBestVersion(
           fisher,
           type,
+          null, // no source info
           Type.Resource,
           Type.Type,
           Type.Profile,

src/fhirtypes/common.ts

@@ -855,12 +855,27 @@ export function replaceReferences<T extends AssignmentRule | CaretValueRule>(
       }
     }
   } else if (value instanceof FshCode) {
-    const codeSystem = fishInTankBestVersion(tank, value.system, Type.CodeSystem);
-    const codeSystemMeta = fishForMetadataBestVersion(fisher, value.system, Type.CodeSystem);
+    const codeSystemMeta = fishForMetadataBestVersion(
+      fisher,
+      value.system,
+      rule.sourceInfo,
+      Type.CodeSystem
+    );
     if (codeSystemMeta) {
       clone = cloneDeep(rule);
       const assignedCode = getRuleValue(clone) as FshCode;
       assignedCode.system = value.system.replace(/^[^|]+/, codeSystemMeta.url);
+
+      // Find the code system using the returned metadata to avoid duplicate warnings if version mismatches
+      const matchedCanonical = codeSystemMeta.url
+        ? `${codeSystemMeta.url}${codeSystemMeta.version ? `|${codeSystemMeta.version}` : ''}`
+        : value.system;
+      const codeSystem = fishInTankBestVersion(
+        tank,
+        matchedCanonical,
+        rule.sourceInfo,
+        Type.CodeSystem
+      );
       if (codeSystem && (codeSystem instanceof FshCodeSystem || codeSystem instanceof Instance)) {
         // if a local system was used, check to make sure the code is actually in that system
         listUndefinedLocalCodes(codeSystem, [assignedCode.code], tank, rule);

src/utils/FishingUtils.ts

@@ -9,7 +9,8 @@ import {
   FshCodeSystem,
   Invariant,
   RuleSet,
-  Mapping
+  Mapping,
+  SourceInfo
 } from '../fshtypes';
 import { getVersionFromFshDefinition } from '../fhirtypes/common';
 import { logger } from './FSHLogger';
@@ -20,6 +21,7 @@ import { Fishable, Metadata, Type } from './Fishable';
 export function fishForFHIRBestVersion(
   fisher: Fishable,
   item: string,
+  sourceInfo?: SourceInfo,
   ...types: Type[]
 ): any | undefined {
   let result = fisher.fishForFHIR(item, ...types);
@@ -30,7 +32,7 @@ export function fishForFHIRBestVersion(
     const version = versionParts.join('|') || null;
     result = fisher.fishForFHIR(base, ...types);
     if (version != null && result?.version != null && version != result.version) {
-      logger.warn(`${item} was requested, but SUSHI found ${base}|${result.version}`);
+      logger.warn(`${item} was requested, but SUSHI found ${base}|${result.version}`, sourceInfo);
     }
   }
 
@@ -42,6 +44,7 @@ export function fishForFHIRBestVersion(
 export function fishForMetadataBestVersion(
   fisher: Fishable,
   item: string,
+  sourceInfo?: SourceInfo,
   ...types: Type[]
 ): Metadata | undefined {
   if (fisher == null) {
@@ -56,7 +59,7 @@ export function fishForMetadataBestVersion(
     const version = versionParts.join('|') || null;
     metadata = fisher.fishForMetadata(base, ...types);
     if (version != null && metadata?.version != null && version != metadata.version) {
-      logger.warn(`${item} was requested, but SUSHI found ${base}|${metadata.version}`);
+      logger.warn(`${item} was requested, but SUSHI found ${base}|${metadata.version}`, sourceInfo);
     }
   }
 
@@ -68,6 +71,7 @@ export function fishForMetadataBestVersion(
 export function fishInTankBestVersion(
   tank: FSHTank,
   item: string,
+  sourceInfo?: SourceInfo,
   ...types: Type[]
 ):
   | Profile
@@ -96,7 +100,7 @@ export function fishInTankBestVersion(
         resultVersion = getVersionFromFshDefinition(result, tank.config.version);
       }
       if (version != null && resultVersion != null && version != resultVersion) {
-        logger.warn(`${item} was requested, but SUSHI found ${base}|${resultVersion}`);
+        logger.warn(`${item} was requested, but SUSHI found ${base}|${resultVersion}`, sourceInfo);
       }
     }
   }

test/export/StructureDefinitionExporter.test.ts

@@ -5982,7 +5982,9 @@ describe('StructureDefinitionExporter R4', () => {
     it('should apply a ContainsRule of an extension with a versioned URL and log a warning if the version does not match', () => {
       const profile = new Profile('MyFamilyHistory');
       profile.parent = 'FamilyMemberHistory';
-      const containsRule = new ContainsRule('extension');
+      const containsRule = new ContainsRule('extension')
+        .withFile('FSHyFile.fsh')
+        .withLocation([3, 0, 3, 45]);
       containsRule.items = [
         {
           name: 'history',
@@ -6008,7 +6010,7 @@ describe('StructureDefinitionExporter R4', () => {
         )
       ]);
       expect(loggerSpy.getLastMessage('warn')).toMatch(
-        'http://hl7.org/fhir/StructureDefinition/familymemberhistory-type|1.2.3 was requested, but SUSHI found http://hl7.org/fhir/StructureDefinition/familymemberhistory-type|4.0.1'
+        /http:\/\/hl7\.org\/fhir\/StructureDefinition\/familymemberhistory-type\|1\.2\.3 was requested, but SUSHI found http:\/\/hl7\.org\/fhir\/StructureDefinition\/familymemberhistory-type\|4\.0\.1.*File: FSHyFile\.fsh.*Line: 3\D*/s
       );
     });
 

test/utils/FishingUtils.test.ts

@@ -2,7 +2,7 @@ import { TestFisher, loggerSpy } from '../testhelpers';
 import { Package } from '../../src/export';
 import { FSHDocument, FSHTank } from '../../src/import';
 import { FHIRDefinitions } from '../../src/fhirdefs';
-import { Profile } from '../../src/fshtypes';
+import { Profile, SourceInfo } from '../../src/fshtypes';
 import { CaretValueRule } from '../../src/fshtypes/rules';
 import { minimalConfig } from './minimalConfig';
 import {
@@ -11,6 +11,11 @@ import {
   fishInTankBestVersion
 } from '../../src/utils';
 
+const someSourceInfo = {
+  file: 'SomeFile.fsh',
+  location: { startLine: 12, startColumn: 0, endLine: 12, endColumn: 35 }
+};
+
 describe('FishingUtils', () => {
   let fisher: TestFisher;
   let tank: FSHTank;
@@ -70,7 +75,18 @@ describe('FishingUtils', () => {
       expect(fishForFHIRSpy).toHaveBeenCalledTimes(2);
       expect(loggerSpy.getAllMessages()).toHaveLength(1);
       expect(loggerSpy.getLastMessage('warn')).toMatch(
-        /item|1\.0 was requested, but SUSHI found item|2\.0/i
+        /item\|1\.0 was requested, but SUSHI found item\|2\.0/
+      );
+    });
+
+    it('should fish twice if result is not found when version is provided and log a warning with source info if different version is found', () => {
+      fishForFHIRSpy.mockReturnValueOnce(undefined);
+      fishForFHIRSpy.mockReturnValueOnce({ resourceType: 'mock', version: '2.0' });
+      fishForFHIRBestVersion(fisher, 'item|1.0', someSourceInfo);
+      expect(fishForFHIRSpy).toHaveBeenCalledTimes(2);
+      expect(loggerSpy.getAllMessages()).toHaveLength(1);
+      expect(loggerSpy.getLastMessage('warn')).toMatch(
+        /item\|1\.0 was requested, but SUSHI found item\|2\.0.*File: SomeFile\.fsh.*Line: 12\D*/s
       );
     });
 
@@ -134,7 +150,18 @@ describe('FishingUtils', () => {
       expect(fishForMetadataSpy).toHaveBeenCalledTimes(2);
       expect(loggerSpy.getAllMessages()).toHaveLength(1);
       expect(loggerSpy.getLastMessage('warn')).toMatch(
-        /item|1\.0 was requested, but SUSHI found item|2\.0/i
+        /item\|1\.0 was requested, but SUSHI found item\|2\.0/
+      );
+    });
+
+    it('should fishForMetadata twice if result is not found when version is provided and log a warning with source info if different version is found', () => {
+      fishForMetadataSpy.mockReturnValueOnce(undefined);
+      fishForMetadataSpy.mockReturnValueOnce({ id: 'mock', version: '2.0' });
+      fishForMetadataBestVersion(fisher, 'item|1.0', someSourceInfo);
+      expect(fishForMetadataSpy).toHaveBeenCalledTimes(2);
+      expect(loggerSpy.getAllMessages()).toHaveLength(1);
+      expect(loggerSpy.getLastMessage('warn')).toMatch(
+        /item\|1\.0 was requested, but SUSHI found item\|2\.0.*File: SomeFile\.fsh.*Line: 12\D*/s
       );
     });
 
@@ -208,7 +235,23 @@ describe('FishingUtils', () => {
       expect(fishInTankSpy).toHaveBeenCalledTimes(2);
       expect(loggerSpy.getAllMessages()).toHaveLength(1);
       expect(loggerSpy.getLastMessage('warn')).toMatch(
-        /item|1\.0 was requested, but SUSHI found item|2\.0/i
+        /item|1\.0 was requested, but SUSHI found item|2\.0/
+      );
+    });
+
+    it('should fish in tank twice if result is not found when version is provided and log a warning with source info if different version is found', () => {
+      const mockProfile = new Profile('mock');
+      const mockProfileVersion = new CaretValueRule('');
+      mockProfileVersion.caretPath = 'version';
+      mockProfileVersion.value = '2.0';
+      mockProfile.rules.push(mockProfileVersion);
+      fishInTankSpy.mockReturnValueOnce(undefined);
+      fishInTankSpy.mockReturnValueOnce(mockProfile);
+      fishInTankBestVersion(tank, 'item|1.0', someSourceInfo);
+      expect(fishInTankSpy).toHaveBeenCalledTimes(2);
+      expect(loggerSpy.getAllMessages()).toHaveLength(1);
+      expect(loggerSpy.getLastMessage('warn')).toMatch(
+        /item\|1\.0 was requested, but SUSHI found item\|2\.0.*File: SomeFile\.fsh.*Line: 12\D*/s
       );
     });