Repository: FHIR/sushi
Pull request #79 (2020-01-09 16:20:29)

Remove infinite loops in cases with circular dependencies
This task removes infinite loops in the event of circular dependencies occurring. It does so by allowing a structure definition to be read even when it is incomplete, only containing its metadata. This technically leaves the possibility for a structure definition to be accessed when it is incomplete and needs more than just its metadata, but this chance is incredibly slim.

In order to test this, run the tests as usual (since I've added a couple of circular tests). In order to test an actual implementation, first run `master` of this repository against `master of `fsh-mcode`. You should either notice errors that the maximum call stack size was exceeded, or notice that the execution hangs and doesn't complete (depending on your OS, I believe). Then, run this branch of this repository against `master` of `fsh-mcode` and notice that the errors are resolved (other irrelevant errors will still remain, though) and the execution completes.

When reviewing this, please note that I added a debug statement for when elements are unfolded. That is, I believe, the only current instance of our code where the `resolve` function is used and requires more than just the metadata. If you know of other instances where this happens, please let me know, and I'll add a debug statement in those locations, as well.

cmoesel: Rebased on master and fixed related issues.  Also added new tests to ensure that debug messages are actually getting logged.  This required a few changes to loggerSpy and a new test helper function.

The last two commits (with me as author) are the relevant changes.  @kjmahalingam -- can you review those?

Patch:
diff --git a/src/app.ts b/src/app.ts
index 76b8eff..e704649 100644
--- a/src/app.ts
+++ b/src/app.ts
@@ -19,12 +19,15 @@ async function app() {
     .name('sushi')
     .usage('<path-to-fsh-defs> [options]')
     .option('-o, --out <out>', 'the path to the output folder', path.join('.', 'build'))
+    .option('-d, --debug', 'output extra debugging information')
     .arguments('<path-to-fsh-defs>')
     .action(function(pathToFshDefs) {
       input = pathToFshDefs;
     })
     .parse(process.argv);
 
+  if (program.debug) logger.level = 'debug';
+
   // Check that input folder is specified
   if (!input) {
     logger.error('Missing path to FSH definition folder.');
diff --git a/src/export/StructureDefinitionExporter.ts b/src/export/StructureDefinitionExporter.ts
index 5d6956f..87ac08d 100644
--- a/src/export/StructureDefinitionExporter.ts
+++ b/src/export/StructureDefinitionExporter.ts
@@ -187,16 +187,31 @@ export class StructureDefinitionExporter implements Fishable {
     }
 
     const structDef = StructureDefinition.fromJSON(json);
+    if (structDef.inProgress) {
+      logger.warn(
+        `The definition of ${fshDefinition.name} may be incomplete because there is a circular ` +
+          `dependency with its parent ${parentName} causing the parent to be used before the ` +
+          'parent has been fully processed.'
+      );
+    }
+
+    structDef.inProgress = true;
+
     this.setMetadata(structDef, fshDefinition);
-    this.setRules(structDef, fshDefinition);
-    this.validateStructureDefinition(structDef);
 
+    // These are being pushed now in order to allow for
+    // incomplete definitions to be used to resolve circular reference issues.
     if (structDef.type === 'Extension') {
       this.pkg.extensions.push(structDef);
     } else {
       this.pkg.profiles.push(structDef);
     }
 
+    this.setRules(structDef, fshDefinition);
+    this.validateStructureDefinition(structDef);
+
+    structDef.inProgress = false;
+
     return structDef;
   }
 
diff --git a/src/fhirtypes/ElementDefinition.ts b/src/fhirtypes/ElementDefinition.ts
index 9d80442..2ec40c1 100644
--- a/src/fhirtypes/ElementDefinition.ts
+++ b/src/fhirtypes/ElementDefinition.ts
@@ -21,7 +21,7 @@ import {
   InvalidMaxOfSliceError
 } from '../errors';
 import { setPropertyOnDefinitionInstance } from './common';
-import { Fishable, Type, Metadata } from '../utils/Fishable';
+import { Fishable, Type, Metadata, logger } from '../utils';
 
 export class ElementDefinitionType {
   private _code: string;
@@ -1405,6 +1405,11 @@ export class ElementDefinition {
         );
         if (json) {
           const def = StructureDefinition.fromJSON(json);
+          if (def.inProgress) {
+            logger.debug(
+              `Warning: Circular relationship detected between ${this.structDef?.name} and ${def.name}. As a result, it is possible that the definition of ${this.structDef?.name} may be based on incomplete components of ${def.name}.`
+            );
+          }
           newElements = def.elements.slice(1).map(e => {
             const eClone = e.clone();
             eClone.id = eClone.id.replace(def.type, `${this.id}`);
diff --git a/src/fhirtypes/StructureDefinition.ts b/src/fhirtypes/StructureDefinition.ts
index 0903c3d..bd62e66 100644
--- a/src/fhirtypes/StructureDefinition.ts
+++ b/src/fhirtypes/StructureDefinition.ts
@@ -59,8 +59,17 @@ export class StructureDefinition {
    */
   elements: ElementDefinition[];
 
+  /**
+   * A StructureDefinition instance of StructureDefinition itself.  Needed for supporting escape syntax.
+   */
   private _sdStructureDefinition: StructureDefinition;
 
+  /**
+   * A flag indicating if the StructureDefinition is currently being processed.
+   * This allows us to log messages when processing might be affected by circular dependencies.
+   */
+  public inProgress?: boolean;
+
   /**
    * Constructs a StructureDefinition with a root element.
    */
@@ -302,6 +311,15 @@ export class StructureDefinition {
       element: this.elements.filter(e => e.hasDiff()).map(e => e.calculateDiff().toJSON())
     };
 
+    // If the StructureDefinition is in progress, we want to persist that in the JSON so that when
+    // the Fisher retrieves it from a package and converts to JSON, the inProgress state will be
+    // preserved.  But do NOT persist it when it is false.
+    // NOTE: This should be safe because StructureDefinitions should never be inProgress by the
+    // time we do the final export.
+    if (this.inProgress) {
+      j.inProgress = true;
+    }
+
     return j;
   }
 
@@ -332,6 +350,10 @@ export class StructureDefinition {
         sd.elements.push(ed);
       }
     }
+    // And finally add back the inProgress field if it's there
+    if (json.inProgress) {
+      sd.inProgress = true;
+    }
     return sd;
   }
 
@@ -572,6 +594,7 @@ interface LooseStructDefJSON {
   derivation?: string;
   snapshot?: { element: any[] };
   differential?: { element: any[] };
+  inProgress?: boolean;
   // [key: string]: any;
 }
 
diff --git a/src/utils/FSHLogger.ts b/src/utils/FSHLogger.ts
index 3baa01d..68a778d 100644
--- a/src/utils/FSHLogger.ts
+++ b/src/utils/FSHLogger.ts
@@ -28,6 +28,9 @@ const incrementCounts = format(info => {
     case 'error':
       stats.numError++;
       break;
+    case 'debug':
+      stats.numDebug++;
+      break;
     default:
       break;
   }
@@ -44,11 +47,13 @@ class LoggerStats {
   public numInfo = 0;
   public numWarn = 0;
   public numError = 0;
+  public numDebug = 0;
 
   reset(): void {
     this.numInfo = 0;
     this.numWarn = 0;
     this.numError = 0;
+    this.numDebug = 0;
   }
 }
 


Test patch:
diff --git a/test/export/StructureDefinitionExporter.test.ts b/test/export/StructureDefinitionExporter.test.ts
index e561655..08d818a 100644
--- a/test/export/StructureDefinitionExporter.test.ts
+++ b/test/export/StructureDefinitionExporter.test.ts
@@ -21,6 +21,8 @@ import {
 import { loggerSpy, TestFisher } from '../testhelpers';
 import { ElementDefinitionType } from '../../src/fhirtypes';
 import path from 'path';
+import { logger } from '../../src/utils';
+import { withDebugLogging } from '../testhelpers/withDebugLogging';
 
 describe('StructureDefinitionExporter', () => {
   let defs: FHIRDefinitions;
@@ -655,6 +657,187 @@ describe('StructureDefinitionExporter', () => {
     );
   });
 
+  it('should apply correct OnlyRules on circular FSHy choices', () => {
+    const profile1 = new Profile('Foo');
+    profile1.parent = 'Observation';
+    doc.profiles.set(profile1.name, profile1);
+    const profile2 = new Profile('Bar');
+    profile2.parent = 'Observation';
+    doc.profiles.set(profile2.name, profile2);
+
+    const rule1 = new OnlyRule('hasMember[Observation]');
+    rule1.types = [{ type: 'Bar', isReference: true }];
+    const rule2 = new OnlyRule('hasMember[Observation]');
+    rule2.types = [{ type: 'Foo', isReference: true }];
+    profile1.rules.push(rule1);
+    profile2.rules.push(rule2);
+
+    withDebugLogging(() => exporter.export());
+    loggerSpy.getAllMessages().forEach(m => {
+      expect(m).not.toMatch(/circular/i);
+    });
+
+    const sdFoo = pkg.profiles.find(def => def.id === 'Foo');
+    const sdBar = pkg.profiles.find(def => def.id === 'Bar');
+    const baseStructDef = fisher.fishForStructureDefinition('Observation');
+
+    const baseHasMember = baseStructDef.findElement('Observation.hasMember');
+    const constrainedHasMemberFoo = sdFoo.findElement('Observation.hasMember');
+    const constrainedHasMemberBar = sdBar.findElement('Observation.hasMember');
+
+    expect(baseHasMember.type).toHaveLength(1);
+    expect(baseHasMember.type[0]).toEqual(
+      new ElementDefinitionType('Reference').withTargetProfiles(
+        'http://hl7.org/fhir/StructureDefinition/Observation',
+        'http://hl7.org/fhir/StructureDefinition/QuestionnaireResponse',
+        'http://hl7.org/fhir/StructureDefinition/MolecularSequence'
+      )
+    );
+
+    expect(constrainedHasMemberFoo.type).toHaveLength(1);
+    expect(constrainedHasMemberFoo.type[0]).toEqual(
+      new ElementDefinitionType('Reference').withTargetProfiles(
+        'http://example.com/StructureDefinition/Bar',
+        'http://hl7.org/fhir/StructureDefinition/QuestionnaireResponse',
+        'http://hl7.org/fhir/StructureDefinition/MolecularSequence'
+      )
+    );
+
+    expect(constrainedHasMemberBar.type).toHaveLength(1);
+    expect(constrainedHasMemberBar.type[0]).toEqual(
+      new ElementDefinitionType('Reference').withTargetProfiles(
+        'http://example.com/StructureDefinition/Foo',
+        'http://hl7.org/fhir/StructureDefinition/QuestionnaireResponse',
+        'http://hl7.org/fhir/StructureDefinition/MolecularSequence'
+      )
+    );
+  });
+
+  it('should safely apply correct OnlyRule with circular FSHy parent', () => {
+    const profile1 = new Profile('Foo');
+    profile1.parent = 'Observation';
+    doc.profiles.set(profile1.name, profile1);
+    const profile2 = new Profile('Bar');
+    profile2.parent = 'Foo';
+    doc.profiles.set(profile2.name, profile2);
+
+    const rule = new OnlyRule('hasMember[Observation]');
+    rule.types = [{ type: 'Bar', isReference: true }];
+    profile1.rules.push(rule);
+
+    withDebugLogging(() => exporter.export());
+    loggerSpy.getAllMessages().forEach(m => {
+      expect(m).not.toMatch(/circular/i);
+    });
+
+    const sdFoo = pkg.profiles.find(def => def.id === 'Foo');
+    const sdBar = pkg.profiles.find(def => def.id === 'Bar');
+    const baseStructDef = fisher.fishForStructureDefinition('Observation');
+
+    expect(sdFoo.baseDefinition).toBe('http://hl7.org/fhir/StructureDefinition/Observation');
+    expect(sdBar.baseDefinition).toBe('http://example.com/StructureDefinition/Foo');
+
+    const baseHasMember = baseStructDef.findElement('Observation.hasMember');
+    const constrainedHasMemberFoo = sdFoo.findElement('Observation.hasMember');
+    const constrainedHasMemberBar = sdBar.findElement('Observation.hasMember');
+
+    expect(baseHasMember.type).toHaveLength(1);
+    expect(baseHasMember.type[0]).toEqual(
+      new ElementDefinitionType('Reference').withTargetProfiles(
+        'http://hl7.org/fhir/StructureDefinition/Observation',
+        'http://hl7.org/fhir/StructureDefinition/QuestionnaireResponse',
+        'http://hl7.org/fhir/StructureDefinition/MolecularSequence'
+      )
+    );
+
+    expect(constrainedHasMemberFoo.type).toHaveLength(1);
+    expect(constrainedHasMemberFoo.type[0]).toEqual(
+      new ElementDefinitionType('Reference').withTargetProfiles(
+        'http://example.com/StructureDefinition/Bar',
+        'http://hl7.org/fhir/StructureDefinition/QuestionnaireResponse',
+        'http://hl7.org/fhir/StructureDefinition/MolecularSequence'
+      )
+    );
+
+    expect(constrainedHasMemberBar.type).toHaveLength(1);
+    expect(constrainedHasMemberBar.type[0]).toEqual(
+      new ElementDefinitionType('Reference').withTargetProfiles(
+        'http://example.com/StructureDefinition/Bar',
+        'http://hl7.org/fhir/StructureDefinition/QuestionnaireResponse',
+        'http://hl7.org/fhir/StructureDefinition/MolecularSequence'
+      )
+    );
+  });
+
+  it('should log a debug message when we detect a circular dependency in OnlyRules that might result in incomplete definitions', () => {
+    const profile1 = new Profile('FooQuantity');
+    profile1.parent = 'Quantity';
+    const p1ContainsRule = new ContainsRule('extension');
+    p1ContainsRule.items.push('QuantityExtension');
+    const p1OnlyRule = new OnlyRule('extension[QuantityExtension].valueQuantity');
+    p1OnlyRule.types = [{ type: 'BarQuantity' }];
+    const p1FixedValueRule = new FixedValueRule('extension[QuantityExtension].valueQuantity.code');
+    p1FixedValueRule.fixedValue = new FshCode('mg');
+    profile1.rules = [p1ContainsRule, p1OnlyRule, p1FixedValueRule];
+    doc.profiles.set(profile1.name, profile1);
+
+    const profile2 = new Profile('BarQuantity');
+    profile2.parent = 'Quantity';
+    const p2ContainsRule = new ContainsRule('extension');
+    p2ContainsRule.items.push('QuantityExtension');
+    const p2OnlyRule = new OnlyRule('extension[QuantityExtension].valueQuantity');
+    p2OnlyRule.types = [{ type: 'FooQuantity' }];
+    const p2FixedValueRule = new FixedValueRule('extension[QuantityExtension].valueQuantity.code');
+    p2FixedValueRule.fixedValue = new FshCode('mg');
+    profile2.rules = [p2ContainsRule, p2OnlyRule, p2FixedValueRule];
+    doc.profiles.set(profile2.name, profile2);
+
+    const extension = new Extension('QuantityExtension');
+    const extOnlyRule = new OnlyRule('value[x]');
+    extOnlyRule.types = [{ type: 'Quantity' }];
+    extension.rules = [extOnlyRule];
+    doc.extensions.set(extension.name, extension);
+
+    withDebugLogging(() => exporter.export());
+
+    const lastLog = loggerSpy.getLastLog();
+    expect(lastLog.level).toMatch(/debug/);
+    expect(lastLog.message).toMatch(/Warning: Circular .* BarQuantity and FooQuantity/);
+
+    expect(loggerSpy.getLastMessage()).toMatch(/Warning: Circular .* BarQuantity and FooQuantity/);
+  });
+
+  it('should log a warning message when we detect a circular dependency that causes an incomplete parent', () => {
+    const profile1 = new Profile('FooQuantity');
+    profile1.parent = 'BarQuantity';
+    doc.profiles.set(profile1.name, profile1);
+
+    const profile2 = new Profile('BarQuantity');
+    profile2.parent = 'Quantity';
+    const p2ContainsRule = new ContainsRule('extension');
+    p2ContainsRule.items.push('QuantityExtension');
+    const p2OnlyRule = new OnlyRule('extension[QuantityExtension].valueQuantity');
+    p2OnlyRule.types = [{ type: 'FooQuantity' }];
+    const p2FixedValueRule = new FixedValueRule('extension[QuantityExtension].valueQuantity.code');
+    p2FixedValueRule.fixedValue = new FshCode('mg');
+    profile2.rules = [p2ContainsRule, p2OnlyRule, p2FixedValueRule];
+    doc.profiles.set(profile2.name, profile2);
+
+    const extension = new Extension('QuantityExtension');
+    const extOnlyRule = new OnlyRule('value[x]');
+    extOnlyRule.types = [{ type: 'Quantity' }];
+    extension.rules = [extOnlyRule];
+    doc.extensions.set(extension.name, extension);
+
+    exporter.export();
+
+    const lastLog = loggerSpy.getLastLog();
+    expect(lastLog.level).toMatch(/warn/);
+    expect(lastLog.message).toMatch(
+      /The definition of FooQuantity may be incomplete .* BarQuantity/
+    );
+  });
+
   it('should not apply an incorrect OnlyRule', () => {
     const profile = new Profile('Foo');
     profile.parent = 'Observation';
diff --git a/test/testhelpers/loggerSpy.ts b/test/testhelpers/loggerSpy.ts
index 8455460..49995de 100644
--- a/test/testhelpers/loggerSpy.ts
+++ b/test/testhelpers/loggerSpy.ts
@@ -1,11 +1,32 @@
 import { logger } from '../../src/utils/FSHLogger';
+import { LogEntry } from 'winston';
 
 class LoggerSpy {
   private mockWriter = jest.spyOn(logger.transports[0], 'write');
 
-  getMessageAtIndex(index: number): string {
+  getAllLogs(): LogEntry[] {
+    return this.mockWriter.mock.calls.map(m => m[0]);
+  }
+
+  getLogAtIndex(index: number): LogEntry {
     const i = index < 0 ? this.mockWriter.mock.calls.length + index : index;
-    return this.mockWriter.mock.calls[i][0].message;
+    return this.mockWriter.mock.calls[i]?.[0];
+  }
+
+  getFirstLog(): LogEntry {
+    return this.getLogAtIndex(0);
+  }
+
+  getLastLog(): LogEntry {
+    return this.getLogAtIndex(-1);
+  }
+
+  getAllMessages(): string[] {
+    return this.getAllLogs().map(l => l.message);
+  }
+
+  getMessageAtIndex(index: number): string {
+    return this.getLogAtIndex(index).message;
   }
 
   getFirstMessage(): string {
diff --git a/test/testhelpers/withDebugLogging.ts b/test/testhelpers/withDebugLogging.ts
new file mode 100644
index 0000000..e192111
--- /dev/null
+++ b/test/testhelpers/withDebugLogging.ts
@@ -0,0 +1,12 @@
+import { logger } from '../../src/utils';
+
+export function withDebugLogging(fn: () => any) {
+  const originalLevel = logger.level;
+  logger.level = 'debug';
+  try {
+    fn();
+  } finally {
+    // make sure we set the logger back so we don't mess up other tests
+    logger.level = originalLevel;
+  }
+}