Add source information to metadata log statements (#45)

* Add source information to metadata log statements

Logger errors may be written when parsing profiles, extensions, and
instances. Duplicated metadata elements will show the source
location of the second (or third, etc.) of the element. Missing
metadata for an instance will show the instance's source location.

* Use destructuring instead of Object.assign

src/import/FSHImporter.ts

@@ -130,11 +130,14 @@ export class FSHImporter extends FSHVisitor {
   ): void {
     const seenPairs: Map<SdMetadataKey, string> = new Map();
     metaCtx
-      .map(sdMeta => this.visitSdMetadata(sdMeta))
+      .map(sdMeta => ({ ...this.visitSdMetadata(sdMeta), context: sdMeta }))
       .forEach(pair => {
         if (seenPairs.has(pair.key)) {
           logger.error(
-            `Metadata field '${pair.key}' already declared with value '${seenPairs.get(pair.key)}'.`
+            `Metadata field '${pair.key}' already declared with value '${seenPairs.get(
+              pair.key
+            )}'.`,
+            { file: this.file, location: this.extractStartStop(pair.context) }
           );
           return;
         }
@@ -162,7 +165,7 @@ export class FSHImporter extends FSHVisitor {
       this.parseInstance(instance, ctx.instanceMetadata(), ctx.fixedValueRule());
       this.doc.instances.set(instance.name, instance);
     } catch (e) {
-      logger.error(e.message);
+      logger.error(e.message, instance.sourceInfo);
     }
   }
 
@@ -173,11 +176,17 @@ export class FSHImporter extends FSHVisitor {
   ): void {
     const seenPairs: Map<InstanceMetadataKey, string> = new Map();
     metaCtx
-      .map(instanceMetadata => this.visitInstanceMetadata(instanceMetadata))
+      .map(instanceMetadata => ({
+        ...this.visitInstanceMetadata(instanceMetadata),
+        context: instanceMetadata
+      }))
       .forEach(pair => {
         if (seenPairs.has(pair.key)) {
           logger.error(
-            `Metadata field '${pair.key}' already declared with value '${seenPairs.get(pair.key)}'.`
+            `Metadata field '${pair.key}' already declared with value '${seenPairs.get(
+              pair.key
+            )}'.`,
+            { file: this.file, location: this.extractStartStop(pair.context) }
           );
           return;
         }

test/import/FSHImporter.Extension.test.ts

@@ -6,8 +6,15 @@ import {
   assertCaretValueRule
 } from '../utils/asserts';
 import { importText } from '../../src/import';
+import { logger } from '../../src/utils/FSHLogger';
 
 describe('FSHImporter', () => {
+  let mockWriter: jest.SpyInstance<boolean, [any, string, ((error: Error) => void)?]>;
+
+  beforeAll(() => {
+    mockWriter = jest.spyOn(logger.transports[0], 'write');
+  });
+
   describe('Extension', () => {
     describe('#sdMetadata', () => {
       it('should parse the simplest possible extension', () => {
@@ -78,6 +85,26 @@ describe('FSHImporter', () => {
         expect(extension.title).toBe('Some Extension');
         expect(extension.description).toBe('An extension on something');
       });
+
+      it('should log an error when encountering a duplicate metadata attribute', () => {
+        const input = `
+        Extension: SomeExtension
+        Parent: ParentExtension
+        Id: some-extension
+        Title: "Some Extension"
+        Description: "An extension on something"
+        Title: "Some Duplicate Extension"
+        Description: "A duplicated extension on something"
+        `;
+
+        importText(input, 'Dupe.fsh');
+        expect(mockWriter.mock.calls[mockWriter.mock.calls.length - 2][0].message).toMatch(
+          /File: Dupe\.fsh.*Line 7\D.*Column 9\D.*Line 7\D.*Column 41\D/s
+        );
+        expect(mockWriter.mock.calls[mockWriter.mock.calls.length - 1][0].message).toMatch(
+          /File: Dupe\.fsh.*Line 8\D.*Column 9\D.*Line 8\D.*Column 58\D/s
+        );
+      });
     });
 
     // Since Extensions use the same rule parsing code as Profiles, only do minimal tests of rules

test/import/FSHImporter.Instance.test.ts

@@ -1,8 +1,15 @@
 import { importText } from '../../src/import';
 import { assertFixedValueRule } from '../utils/asserts';
 import { FshCode } from '../../src/fshtypes';
+import { logger } from '../../src/utils/FSHLogger';
 
 describe('FSHImporter', () => {
+  let mockWriter: jest.SpyInstance<boolean, [any, string, ((error: Error) => void)?]>;
+
+  beforeAll(() => {
+    mockWriter = jest.spyOn(logger.transports[0], 'write');
+  });
+
   describe('Instance', () => {
     describe('#instanceOf', () => {
       it('should parse the simplest possible instance', () => {
@@ -46,8 +53,11 @@ describe('FSHImporter', () => {
         Title: "My Important Observation"
         `;
 
-        const result = importText(input);
+        const result = importText(input, 'Missing.fsh');
         expect(result.instances.size).toBe(0);
+        expect(mockWriter.mock.calls[mockWriter.mock.calls.length - 1][0].message).toMatch(
+          /File: Missing\.fsh.*Line 2\D.*Column 9\D.*Line 3\D.*Column 41\D/s
+        );
       });
     });
 
@@ -110,6 +120,24 @@ describe('FSHImporter', () => {
         expect(instance.instanceOf).toBe('Observation');
         expect(instance.title).toBe('My Important Observation');
       });
+
+      it('should log an error when encountering a duplicate metadata attribute', () => {
+        const input = `
+        Instance: MyObservation
+        InstanceOf: Observation
+        Title: "My Important Observation"
+        InstanceOf: DuplicateObservation
+        Title: "My Duplicate Observation"
+        `;
+
+        importText(input, 'Dupe.fsh');
+        expect(mockWriter.mock.calls[mockWriter.mock.calls.length - 2][0].message).toMatch(
+          /File: Dupe\.fsh.*Line 5\D.*Column 9\D.*Line 5\D.*Column 40\D/s
+        );
+        expect(mockWriter.mock.calls[mockWriter.mock.calls.length - 1][0].message).toMatch(
+          /File: Dupe\.fsh.*Line 6\D.*Column 9\D.*Line 6\D.*Column 41\D/s
+        );
+      });
     });
   });
 });

test/import/FSHImporter.Profile.test.ts

@@ -142,6 +142,26 @@ describe('FSHImporter', () => {
         expect(profile.title).toBe('An Observation Profile');
         expect(profile.description).toBe('A profile on Observation');
       });
+
+      it('should log an error when encountering a duplicate metadata attribute', () => {
+        const input = `
+        Profile: ObservationProfile
+        Parent: Observation
+        Id: observation-profile
+        Title: "An Observation Profile"
+        Description: "A profile on Observation"
+        Title: "Duplicate Observation Profile"
+        Description: "A duplicated profile on Observation"
+        `;
+
+        importText(input, 'Dupe.fsh');
+        expect(mockWriter.mock.calls[mockWriter.mock.calls.length - 2][0].message).toMatch(
+          /File: Dupe\.fsh.*Line 7\D.*Column 9\D.*Line 7\D.*Column 46\D/s
+        );
+        expect(mockWriter.mock.calls[mockWriter.mock.calls.length - 1][0].message).toMatch(
+          /File: Dupe\.fsh.*Line 8\D.*Column 9\D.*Line 8\D.*Column 58\D/s
+        );
+      });
     });
 
     describe('#cardRule', () => {