Remove infinite loops in cases with circular dependencies (#79)

* Push structure definitions after setting metadata, fix tests * Add tests for circular references * Add debug statement when structure definition is not complete * Add break to debug case in incrementCounts * Address feedback from review * Add warning when parent is incomplete * Fix merge issues in test after rebase * Add tests to ensure circular issues are logged Also adds enhancements to loggerSpy to support this. Co-authored-by: Chris Moesel <[email protected]>
FHIR · Jan 17, 2020 · 8b27587 · 8b27587
1 parent da32b92
commit 8b27587
Show file tree

Hide file tree

Showing 8 changed files with 272 additions and 5 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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;
   }
 }
 

diff --git 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
@@ -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
@@ -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;
+  }
+}