Repository: microsoft/ApplicationInsights-node.js
Pull request #551 (2019-09-20 20:04:07)

change(winston/console): send exception if error provided to logger
For scenarios where `winston.error` is used to log an `Error`, we will now call `trackException` instead of sending log data with `trackTrace`. A similar change is made to all other supported loggers (`console` and `bunyan`) An example:
```js
try {
  ...
} catch (e) {
  winston.error(e); // this will now send 'e' as exception telemetry instead of log telemetry
}
```
This PR also fixes the unit test reliability of `Performance.tests.ts`

hectorhdzg: Why this change is being introduced?, logger and actual errors are usually handled in different places in Applications, logger.error doesn't necessary mean there was a code Exception
markwolff: > Why this change is being introduced?, logger and actual errors are usually handled in different places in Applications, logger.error doesn't necessary mean there was a code Exception

Consistency with other language SDKs. For example, with .NET SDK, calling ILogger `logger.Log(msg, exception)` would send exception telemetry. The logs currently sent with SeverityLevel.error are not included in the App Insights curated "Failures" experiences, since no callstack is included. Also, for those who rely 100% on a single logger (e.g. winston), there is no trivial way to send exception telemetry with this SDK.

Patch:
diff --git a/AutoCollection/diagnostic-channel/bunyan.sub.ts b/AutoCollection/diagnostic-channel/bunyan.sub.ts
index f2171b6..a73a3f0 100755
--- a/AutoCollection/diagnostic-channel/bunyan.sub.ts
+++ b/AutoCollection/diagnostic-channel/bunyan.sub.ts
@@ -20,9 +20,14 @@ const bunyanToAILevelMap: {[key: number] : number} = {
 };
 
 const subscriber = (event: IStandardEvent<bunyan.IBunyanData>) => {
+    const message = event.data.result as Error | string;
     clients.forEach((client) => {
         const AIlevel = bunyanToAILevelMap[event.data.level];
-        client.trackTrace({message: event.data.result, severity: AIlevel});
+        if (message instanceof Error) {
+            client.trackException({ exception: (message) });
+        } else {
+            client.trackTrace({message: message, severity: AIlevel});
+        }
     });
 };
 
@@ -38,4 +43,9 @@ export function enable(enabled: boolean, client: TelemetryClient) {
             channel.unsubscribe("bunyan", subscriber);
         }
     }
-}
\ No newline at end of file
+}
+
+export function dispose() {
+    channel.unsubscribe("bunyan", subscriber);
+    clients = [];
+}
diff --git a/AutoCollection/diagnostic-channel/console.sub.ts b/AutoCollection/diagnostic-channel/console.sub.ts
index 71cb386..6cd98a0 100755
--- a/AutoCollection/diagnostic-channel/console.sub.ts
+++ b/AutoCollection/diagnostic-channel/console.sub.ts
@@ -10,13 +10,17 @@ import {console as consolePub} from "diagnostic-channel-publishers";
 let clients: TelemetryClient[] = [];
 
 const subscriber = (event: IStandardEvent<consolePub.IConsoleData>) => {
+    let message = event.data.message as Error | string;
     clients.forEach((client) => {
-        // Message can have a trailing newline
-        let message = event.data.message;
-        if (message.lastIndexOf("\n") == message.length - 1) {
-            message = message.substring(0, message.length - 1);
+        if (message instanceof Error) {
+            client.trackException({ exception: message});
+        } else {
+            // Message can have a trailing newline
+            if (message.lastIndexOf("\n") == message.length - 1) {
+                message = message.substring(0, message.length - 1);
+            }
+            client.trackTrace({message: message, severity: (event.data.stderr ? SeverityLevel.Warning : SeverityLevel.Information)});
         }
-        client.trackTrace({message: message, severity: (event.data.stderr ? SeverityLevel.Warning : SeverityLevel.Information)});
     });
 };
 
@@ -32,4 +36,9 @@ export function enable(enabled: boolean, client: TelemetryClient) {
             channel.unsubscribe("console", subscriber);
         }
     }
-}
\ No newline at end of file
+}
+
+export function dispose() {
+    channel.unsubscribe("console", subscriber);
+    clients = [];
+}
diff --git a/AutoCollection/diagnostic-channel/initialization.ts b/AutoCollection/diagnostic-channel/initialization.ts
index 05fc216..aac22cd 100755
--- a/AutoCollection/diagnostic-channel/initialization.ts
+++ b/AutoCollection/diagnostic-channel/initialization.ts
@@ -25,7 +25,7 @@ if (IsInitialized) {
     };
     for (const mod in modules) {
         if (unpatchedModules.indexOf(mod) === -1) {
-           modules[mod].enable();
+            modules[mod].enable();
         }
     }
 }
diff --git a/AutoCollection/diagnostic-channel/winston.sub.ts b/AutoCollection/diagnostic-channel/winston.sub.ts
index a8d28ac..ba45e41 100644
--- a/AutoCollection/diagnostic-channel/winston.sub.ts
+++ b/AutoCollection/diagnostic-channel/winston.sub.ts
@@ -33,7 +33,7 @@ const winstonToAILevelMap: { [key: string]: (og: string) => number } = {
             debug: SeverityLevel.Verbose,
             silly: SeverityLevel.Verbose
         };
-        
+
         return map[og] === undefined ? SeverityLevel.Information : map[og];
     },
     unknown(og: string) {
@@ -42,14 +42,21 @@ const winstonToAILevelMap: { [key: string]: (og: string) => number } = {
 };
 
 const subscriber = (event: IStandardEvent<winston.IWinstonData>) => {
+    const message = event.data.message as Error | string;
     clients.forEach((client) => {
-        const AIlevel = winstonToAILevelMap[event.data.levelKind](event.data.level);
-        client.trackTrace(
-            {
-                message: event.data.message,
+        if (message instanceof Error) {
+            client.trackException({
+                exception: message,
+                properties: event.data.meta
+            });
+        } else {
+            const AIlevel = winstonToAILevelMap[event.data.levelKind](event.data.level);
+            client.trackTrace({
+                message: message,
                 severity: AIlevel,
                 properties: event.data.meta
             });
+        }
     });
 };
 
@@ -66,3 +73,8 @@ export function enable(enabled: boolean, client: TelemetryClient) {
         }
     }
 }
+
+export function dispose() {
+    channel.unsubscribe("winston", subscriber);
+    clients = [];
+}
\ No newline at end of file


Test patch:
diff --git a/Tests/AutoCollection/Console.tests.ts b/Tests/AutoCollection/Console.tests.ts
index 4605c58..2f75cb0 100644
--- a/Tests/AutoCollection/Console.tests.ts
+++ b/Tests/AutoCollection/Console.tests.ts
@@ -4,6 +4,10 @@ import Console = require("../../AutoCollection/Console")
 
 import AppInsights = require("../../applicationinsights");
 
+import { channel, IStandardEvent } from "diagnostic-channel";
+import { enable, dispose as disable } from "../../AutoCollection/diagnostic-channel/console.sub";
+import { console } from "diagnostic-channel-publishers";
+
 describe("AutoCollection/Console", () => {
     afterEach(() => {
         AppInsights.dispose();
@@ -22,4 +26,42 @@ describe("AutoCollection/Console", () => {
             assert.equal(enableConsoleRequestsSpy.getCall(1).args[0], false);
         });
     });
-});
\ No newline at end of file
+
+    describe("#log and #error()", () => {
+        it("should call trackException for errors and trackTrace for logs", () => {
+            var appInsights = AppInsights.setup("key");
+            appInsights.start();
+
+            const trackExceptionStub = sinon.stub(AppInsights.defaultClient, "trackException");
+            const trackTraceStub = sinon.stub(AppInsights.defaultClient, "trackTrace");
+
+            disable();
+            enable(true, AppInsights.defaultClient);
+            const logEvent: console.IConsoleData = {
+                message: "test log",
+                stderr: true // should log as MessageData regardless of this setting
+            };
+            const dummyError = new Error("test error");
+            const errorEvent: console.IConsoleData = {
+                message: dummyError as any,
+                stderr: false, // log() should still log as ExceptionData
+            };
+
+            channel.publish("console", logEvent);
+            assert.ok(trackExceptionStub.notCalled);
+            assert.ok(trackTraceStub.calledOnce);
+            assert.deepEqual(trackTraceStub.args[0][0].message, "test log");
+            trackExceptionStub.reset();
+            trackTraceStub.reset();
+
+            channel.publish("console", errorEvent);
+            assert.ok(trackExceptionStub.calledOnce);
+            assert.ok(trackTraceStub.notCalled);
+            assert.deepEqual(trackExceptionStub.args[0][0].exception, dummyError);
+
+            disable();
+            trackExceptionStub.restore();
+            trackTraceStub.restore();
+        });
+    });
+});
diff --git a/Tests/AutoCollection/Performance.tests.ts b/Tests/AutoCollection/Performance.tests.ts
index e44ce75..764473d 100644
--- a/Tests/AutoCollection/Performance.tests.ts
+++ b/Tests/AutoCollection/Performance.tests.ts
@@ -24,7 +24,7 @@ describe("AutoCollection/Performance", () => {
     });
 
     describe("#trackNetwork()", () => {
-        it("should not produce incorrect metrics because of multiple instances of Performance class", () => {
+        it("should not produce incorrect metrics because of multiple instances of Performance class", (done) => {
             const setIntervalStub = sinon.stub(global, "setInterval", () => ({ unref: () => {}}));
             const clearIntervalSpy = sinon.spy(global, "clearInterval");
             const appInsights = AppInsights.setup("key").setAutoCollectPerformance(false).start();
@@ -54,19 +54,26 @@ describe("AutoCollection/Performance", () => {
 
             stub1.reset();
             stub2.reset();
-            performance1["_trackNetwork"]();
-            performance2["_trackNetwork"]();
-            assert.equal(stub2.args[1][0].value, stub1.args[1][0].value);
-            assert.equal(stub1.args[1][0].value, (5000) / 1, "request duration average should be 5000");
 
-            appInsights.setAutoCollectPerformance(true); // set back to default of true so tests expecting the default can pass
-            Performance.INSTANCE.dispose();
-            performance1.dispose();
-            performance2.dispose();
-            stub1.restore()
-            stub2.restore();
-            setIntervalStub.restore();
-            clearIntervalSpy.restore();
+            setTimeout(() => {
+                // need to wait at least 1 ms so trackNetwork has valid elapsedMs value
+                performance1["_trackNetwork"]();
+                performance2["_trackNetwork"]();
+                assert.equal(stub1.callCount, 2, "calls trackMetric for the 2 standard metrics");
+                assert.equal(stub2.callCount, 3, "calls trackMetric for the 3 live metric counters");
+                assert.equal(stub2.args[1][0].value, stub1.args[1][0].value);
+                assert.equal(stub1.args[1][0].value, (5000) / 1, "request duration average should be 5000");
+
+                appInsights.setAutoCollectPerformance(true); // set back to default of true so tests expecting the default can pass
+                Performance.INSTANCE.dispose();
+                performance1.dispose();
+                performance2.dispose();
+                stub1.restore()
+                stub2.restore();
+                setIntervalStub.restore();
+                clearIntervalSpy.restore();
+                done();
+            }, 1);
         });
     });
 });
diff --git a/Tests/AutoCollection/bunyan.tests.ts b/Tests/AutoCollection/bunyan.tests.ts
new file mode 100644
index 0000000..89a0ff1
--- /dev/null
+++ b/Tests/AutoCollection/bunyan.tests.ts
@@ -0,0 +1,47 @@
+import assert = require("assert");
+import sinon = require("sinon");
+import AppInsights = require("../../applicationinsights");
+import { channel, IStandardEvent } from "diagnostic-channel";
+import { enable, dispose as disable } from "../../AutoCollection/diagnostic-channel/bunyan.sub";
+import { bunyan } from "diagnostic-channel-publishers";
+
+describe("diagnostic-channel/bunyan", () => {
+    afterEach(() => {
+        AppInsights.dispose();
+        disable();
+    });
+    it("should call trackException for errors, trackTrace for logs", () => {
+        AppInsights.setup("key");
+        AppInsights.start();
+
+        const trackExceptionStub = sinon.stub(AppInsights.defaultClient, "trackException");
+        const trackTraceStub = sinon.stub(AppInsights.defaultClient, "trackTrace");
+
+        disable();
+        enable(true, AppInsights.defaultClient);
+        const logEvent: bunyan.IBunyanData = {
+            result: "test log",
+            level: 50 // Error should still log as MessageData
+        };
+        const dummyError = new Error("test error");
+        const errorEvent: bunyan.IBunyanData = {
+            result: dummyError as any,
+            level: 10, // Verbose should still log as ExceptionData
+        };
+
+        channel.publish("bunyan", logEvent);
+        assert.ok(trackExceptionStub.notCalled);
+        assert.ok(trackTraceStub.calledOnce);
+        assert.deepEqual(trackTraceStub.args[0][0].message, "test log");
+        trackExceptionStub.reset();
+        trackTraceStub.reset();
+
+        channel.publish("bunyan", errorEvent);
+        assert.ok(trackExceptionStub.calledOnce);
+        assert.ok(trackTraceStub.notCalled);
+        assert.deepEqual(trackExceptionStub.args[0][0].exception, dummyError);
+
+        trackExceptionStub.restore();
+        trackTraceStub.restore();
+    });
+});
diff --git a/Tests/AutoCollection/winston.tests.ts b/Tests/AutoCollection/winston.tests.ts
new file mode 100644
index 0000000..d89bad3
--- /dev/null
+++ b/Tests/AutoCollection/winston.tests.ts
@@ -0,0 +1,51 @@
+import assert = require("assert");
+import sinon = require("sinon");
+import AppInsights = require("../../applicationinsights");
+import { channel, IStandardEvent } from "diagnostic-channel";
+import { enable, dispose as disable } from "../../AutoCollection/diagnostic-channel/winston.sub";
+import { winston } from "diagnostic-channel-publishers";
+
+describe("diagnostic-channel/winston", () => {
+    afterEach(() => {
+        AppInsights.dispose();
+        disable();
+    });
+    it("should call trackException for errors, trackTrace for logs", () => {
+        AppInsights.setup("key");
+        AppInsights.start();
+
+        const trackExceptionStub = sinon.stub(AppInsights.defaultClient, "trackException");
+        const trackTraceStub = sinon.stub(AppInsights.defaultClient, "trackTrace");
+
+        disable();
+        enable(true, AppInsights.defaultClient);
+        const logEvent: winston.IWinstonData = {
+            message: "test log",
+            meta: {},
+            level: "foo",
+            levelKind: "npm"
+        };
+        const dummyError = new Error("test error");
+        const errorEvent: winston.IWinstonData = {
+            message: dummyError as any,
+            meta: {},
+            level: "foo",
+            levelKind: "npm"
+        };
+
+        channel.publish("winston", logEvent);
+        assert.ok(trackExceptionStub.notCalled);
+        assert.ok(trackTraceStub.calledOnce);
+        assert.deepEqual(trackTraceStub.args[0][0].message, "test log");
+        trackExceptionStub.reset();
+        trackTraceStub.reset();
+
+        channel.publish("winston", errorEvent);
+        assert.ok(trackExceptionStub.calledOnce);
+        assert.ok(trackTraceStub.notCalled);
+        assert.deepEqual(trackExceptionStub.args[0][0].exception, dummyError);
+
+        trackExceptionStub.restore();
+        trackTraceStub.restore();
+    });
+});