microsoft
/
ApplicationInsights-node.js
зеркало из https://github.com/microsoft/ApplicationInsights-node.js.git
1
0
Форкнуть 0
Код Задачи Пакеты Проекты Релизы Вики Активность

Add msgId property in Diagnostic Logs (#1010) 

* Add msgId property in Diagnostic Logs

* Improve test reliability for InternalAzureLogger

* Update

* Update
This commit is contained in:
Hector Hernandez 2022-09-09 16:22:20 -07:00 коммит произвёл GitHub
Родитель c507448f1f
Коммит b5317d42d0
Не найден ключ, соответствующий данной подписи
Идентификатор ключа GPG: 4AEE18F83AFDEB23
8 изменённых файлов: 190 добавлений и 129 удалений
Показать статистику Скачать Patch файл Скачать Diff файл Показать все файлы Свернуть все файлы

16
Bootstrap/DataModel.ts
Просмотреть файл

@ -3,6 +3,16 @@ export interface AgentLogger {
error(message?: any, ...optional: any[]): void;
}
export const DiagnosticMessageId = {
"attachSuccessful": "3000",
"sdkExists": "3001",
"missingIkey": "3002",
"setupAlreadyCalled": "3003",
"prefixFailed": "3004",
"aadEnabled": "3005",
"unknownError": "3006",
}
export const enum SeverityLevel {
ERROR = "ERROR",
WARN = "WARN",
@ -13,17 +23,17 @@ export interface DiagnosticLog {
/**
* UTC
*/
time: string;
time?: string;
/**
* Log severity, INFO, WARN, ERROR
*/
level: SeverityLevel;
level?: SeverityLevel;
/**
* The logger writing this message. Usually the fully-qualified class or package name
*/
logger: string;
logger?: string;
/**
* The log message

57
Bootstrap/Default.ts
Просмотреть файл

@ -6,6 +6,7 @@ import Constants = require("../Declarations/Constants");
import { StatusLogger } from "./StatusLogger";
import { DiagnosticLogger } from "./DiagnosticLogger";
import Config = require("../Library/Config");
import { DiagnosticLog, DiagnosticMessageId } from "./DataModel";
// Private configuration vars
let _appInsights: typeof types | null;
@ -51,17 +52,22 @@ export function setupAndStart(aadTokenCredential?: azureCore.TokenCredential): t
...StatusLogger.DEFAULT_STATUS,
AgentInitializedSuccessfully: false,
SDKPresent: true,
Reason: "SDK already exists"
Reason: "Application Insights SDK already exists."
})
return null;
}
if (!defaultConfig.instrumentationKey) {
const message = "Application Insights wanted to be started, but no Connection String was provided";
_logger.logError(message);
const diagnosticLog: DiagnosticLog = {
message: "Application Insights wanted to be started, but no Connection String was provided",
properties: {
"msgId": DiagnosticMessageId.missingIkey
}
};
_logger.logError(diagnosticLog);
_statusLogger.logStatus({
...StatusLogger.DEFAULT_STATUS,
AgentInitializedSuccessfully: false,
Reason: message
Reason: diagnosticLog.message
});
return null;
}
@ -70,7 +76,13 @@ export function setupAndStart(aadTokenCredential?: azureCore.TokenCredential): t
_appInsights = require("../applicationinsights");
if (_appInsights.defaultClient) {
// setupAndStart was already called, return the result
_logger.logError("Setup was attempted on the Application Insights Client multiple times. Aborting and returning the first client instance");
const diagnosticLog: DiagnosticLog = {
message: "Setup was attempted on the Application Insights Client multiple times. Aborting and returning the first client instance.",
properties: {
"msgId": DiagnosticMessageId.setupAlreadyCalled
}
};
_logger.logError(diagnosticLog);
return _appInsights;
}
@ -79,7 +91,14 @@ export function setupAndStart(aadTokenCredential?: azureCore.TokenCredential): t
var appInsightsSDKVersion = _appInsights.defaultClient.context.keys.internalSdkVersion;
envelope.tags[appInsightsSDKVersion] = _prefix + envelope.tags[appInsightsSDKVersion];
} catch (e) {
_logger.logError("Error prefixing SDK version", e);
const diagnosticLog: DiagnosticLog = {
message: "Error prefixing SDK version.",
exception: e,
properties: {
"msgId": DiagnosticMessageId.prefixFailed
}
};
_logger.logError(diagnosticLog);
}
return true;
}
@ -101,7 +120,13 @@ export function setupAndStart(aadTokenCredential?: azureCore.TokenCredential): t
_appInsights.defaultClient.addTelemetryProcessor(prefixInternalSdkVersion);
_appInsights.defaultClient.addTelemetryProcessor(copyOverPrefixInternalSdkVersionToHeartBeatMetric);
if (aadTokenCredential) {
_logger.logMessage("Using AAD Token Credential");
const diagnosticLog: DiagnosticLog = {
message: "Application Insights using AAD Token Credential.",
properties: {
"msgId": DiagnosticMessageId.aadEnabled
}
};
_logger.logMessage(diagnosticLog);
_appInsights.defaultClient.config.aadTokenCredential = aadTokenCredential;
}
@ -113,13 +138,26 @@ export function setupAndStart(aadTokenCredential?: azureCore.TokenCredential): t
}
// Agent successfully instrumented the SDK
_logger.logMessage("Application Insights was started");
const diagnosticLog: DiagnosticLog = {
message: "Application Insights was started succesfully.",
properties: {
"msgId": DiagnosticMessageId.attachSuccessful
}
};
_logger.logMessage(diagnosticLog);
_statusLogger.logStatus({
...StatusLogger.DEFAULT_STATUS,
AgentInitializedSuccessfully: true
});
} catch (e) {
_logger.logError("Error setting up Application Insights", e);
const diagnosticLog: DiagnosticLog = {
message: "Error setting up Application Insights.",
exception: e,
properties: {
"msgId": DiagnosticMessageId.unknownError
}
};
_logger.logError(diagnosticLog);
_statusLogger.logStatus({
...StatusLogger.DEFAULT_STATUS,
AgentInitializedSuccessfully: false,
@ -128,3 +166,4 @@ export function setupAndStart(aadTokenCredential?: azureCore.TokenCredential): t
}
return _appInsights;
}

80
Bootstrap/DiagnosticLogger.ts
Просмотреть файл

@ -2,66 +2,54 @@
import * as path from "path";
import * as DataModel from "./DataModel";
import { FileWriter } from "./FileWriter";
import { homedir } from "./Helpers/FileHelpers";
import { APPLICATION_INSIGHTS_SDK_VERSION } from "../Declarations/Constants";
import Util = require("../Library/Util");
const LOGGER_NAME = "applicationinsights.extension.diagnostics";
export class DiagnosticLogger {
public static readonly DEFAULT_FILE_NAME: string = "application-insights-extension.log";
public static readonly DEFAULT_LOG_DIR: string = process.env.APPLICATIONINSIGHTS_LOGDIR || path.join(homedir, "LogFiles/ApplicationInsights");
public static DefaultEnvelope: DataModel.DiagnosticLog = {
message: null,
level: null,
time: null,
logger: "applicationinsights.extension.diagnostics",
properties: {
language: "nodejs",
operation: "Startup",
siteName: process.env.WEBSITE_SITE_NAME,
ikey: "unknown",
extensionVersion: process.env.ApplicationInsightsAgent_EXTENSION_VERSION,
sdkVersion: APPLICATION_INSIGHTS_SDK_VERSION,
subscriptionId: process.env.WEBSITE_OWNER_NAME ? process.env.WEBSITE_OWNER_NAME.split("+")[0] : null
}
private _defaultProperties: { [key: string]: string } = {
language: "nodejs",
operation: "Startup",
siteName: process.env.WEBSITE_SITE_NAME,
ikey: "unknown",
extensionVersion: process.env.ApplicationInsightsAgent_EXTENSION_VERSION,
sdkVersion: APPLICATION_INSIGHTS_SDK_VERSION,
subscriptionId: process.env.WEBSITE_OWNER_NAME ? process.env.WEBSITE_OWNER_NAME.split("+")[0] : null
}
constructor(private _writer: DataModel.AgentLogger = console, instrumentationKey: string = "unknown") {
DiagnosticLogger.DefaultEnvelope.properties.ikey = instrumentationKey;
this._defaultProperties.ikey = instrumentationKey;
}
logMessage(message: DataModel.DiagnosticLog | string) {
if (typeof message === "string") {
const diagnosticMessage: DataModel.DiagnosticLog = {
...DiagnosticLogger.DefaultEnvelope,
message,
level: DataModel.SeverityLevel.INFO,
time: new Date().toISOString()
};
this._writer.log(diagnosticMessage);
} else {
if (message.level === DataModel.SeverityLevel.ERROR) {
this._writer.error(message);
} else {
this._writer.log(message);
}
}
logMessage(diagnosticLog: DataModel.DiagnosticLog) {
let props = Object.assign({}, this._defaultProperties, diagnosticLog.properties);
const diagnosticMessage: DataModel.DiagnosticLog = {
properties: props,
logger: LOGGER_NAME,
message: diagnosticLog.message,
level: DataModel.SeverityLevel.INFO,
time: new Date().toUTCString()
};
this._writer.log(diagnosticMessage);
}
logError(message: DataModel.DiagnosticLog | string, err?: Error) {
if (err) {
message += ` ${Util.dumpObj(err)}`;
}
if (typeof message === "string") {
const diagnosticMessage: DataModel.DiagnosticLog = {
...DiagnosticLogger.DefaultEnvelope,
message,
level: DataModel.SeverityLevel.ERROR,
time: new Date().toUTCString()
};
this._writer.error(diagnosticMessage);
} else {
this._writer.error(message);
logError(diagnosticLog: DataModel.DiagnosticLog) {
let message: string = diagnosticLog.message;
if (diagnosticLog.exception) {
message += ` Error: ${Util.dumpObj(diagnosticLog.exception)}`;
}
let props = Object.assign({}, this._defaultProperties, diagnosticLog.properties);
const diagnosticMessage: DataModel.DiagnosticLog = {
properties: props,
logger: LOGGER_NAME,
message: message,
level: DataModel.SeverityLevel.ERROR,
time: new Date().toUTCString()
};
this._writer.error(diagnosticMessage);
}
}

14
Bootstrap/Helpers.ts
Просмотреть файл

@ -1,3 +1,4 @@
import { DiagnosticLog, DiagnosticMessageId } from "./DataModel";
import { DiagnosticLogger } from "./DiagnosticLogger";
export function sdkAlreadyExists(_logger: DiagnosticLogger): boolean {
@ -13,10 +14,13 @@ export function sdkAlreadyExists(_logger: DiagnosticLogger): boolean {
}
// If loaded instance is in Azure machine home path do not attach the SDK, this means customer already instrumented their app
if (appInstance.indexOf("home") > -1) {
_logger.logMessage(
"applicationinsights module is already installed in this application; not re-attaching. Installed SDK location: " +
appInstance
);
const diagnosticLog: DiagnosticLog = {
message: "Application Insights SDK already exists. Module is already installed in this application; not re-attaching. Installed SDK location: " + appInstance,
properties: {
"msgId": DiagnosticMessageId.sdkExists
}
};
_logger.logError(diagnosticLog);
return true;
}
else {
@ -27,4 +31,4 @@ export function sdkAlreadyExists(_logger: DiagnosticLogger): boolean {
// crashed while trying to resolve "applicationinsights", so SDK does not exist. Attach appinsights
return false;
}
}
}

12
Library/InternalAzureLogger.ts
Просмотреть файл

@ -98,12 +98,16 @@ class InternalAzureLogger {
try {
await FileSystemHelper.accessAsync(this._fileFullPath, fs.constants.F_OK);
}
catch (err) {
catch (appendError) {
// No file create one
await FileSystemHelper.appendFileAsync(this._fileFullPath, data).catch((appendError) => {
try {
await FileSystemHelper.appendFileAsync(this._fileFullPath, data);
return;
}
catch (err) {
console.log(this.TAG, "Failed to put log into file: " + (appendError && appendError.message));
});
return;
return;
}
}
try {
// Check size

6
Tests/Bootstrap/Default.spec.ts
Просмотреть файл

@ -48,9 +48,9 @@ describe("#setupAndStart()", () => {
env["ApplicationInsightsAgent_EXTENSION_VERSION"] = "~2";
env["APPLICATIONINSIGHTS_CONNECTION_STRING"] = "InstrumentationKey=1aa11111-bbbb-1ccc-8ddd-eeeeffff3333;IngestionEndpoint=https://centralus-0.in.applicationinsights.azure.com/";
process.env = env;
sandbox.stub(Helpers, "sdkAlreadyExists", () => false);
// Test
const Default = require("../../Bootstrap/Default") as typeof DefaultTypes;
sandbox.stub(Helpers, "sdkAlreadyExists", () => false);
Default.setLogger(new DiagnosticLogger(logger));
const instance1 = Default.setupAndStart();
assert.ok(instance1.defaultClient);
@ -71,10 +71,10 @@ describe("#setupAndStart()", () => {
env["ApplicationInsightsAgent_EXTENSION_VERSION"] = "~2";
env["APPLICATIONINSIGHTS_CONNECTION_STRING"] = "InstrumentationKey=1aa11111-bbbb-1ccc-8ddd-eeeeffff3333;IngestionEndpoint=https://centralus-0.in.applicationinsights.azure.com/";
process.env = env;
sandbox.stub(Helpers, "sdkAlreadyExists", () => false);
// Test
const Default = require("../../Bootstrap/Default") as typeof DefaultTypes;
sandbox.stub(Helpers, "sdkAlreadyExists", () => false);
Default.setLogger(new DiagnosticLogger(logger));
const instance = Default.setupAndStart();
assert.deepEqual(instance, appInsights);
@ -97,9 +97,9 @@ describe("#setupAndStart()", () => {
env["ApplicationInsightsAgent_EXTENSION_VERSION"] = "~2";
process.env = env;
sinon.stub(Helpers, "sdkAlreadyExists", () => false);
// Test
const Default = require("../../Bootstrap/Default") as typeof DefaultTypes;
sinon.stub(Helpers, "sdkAlreadyExists", () => false);
Default.setLogger(new DiagnosticLogger(logger));
let result = Default.setupAndStart();

13
Tests/Bootstrap/DiagnosticLogger.spec.ts
Просмотреть файл

@ -18,7 +18,7 @@ class TestWriter implements AgentLogger {
}
describe("DiagnosticLogger", () => {
const logger = new DiagnosticLogger(new NoopLogger());
const logger = new DiagnosticLogger(new NoopLogger(), "1aa11111-bbbb-1ccc-8ddd-eeeeffff3333");
const stub = sinon.stub(logger["_writer"], "log");
const version = require("../../../package.json").version;
@ -26,16 +26,16 @@ describe("DiagnosticLogger", () => {
stub.reset();
})
describe("#DiagnosticLogger.DefaultEnvelope", () => {
describe("#DiagnosticLogger.DefaultProperties", () => {
it("should have the correct version string", () => {
assert.equal(DiagnosticLogger.DefaultEnvelope.properties.sdkVersion, version);
assert.equal(logger["_defaultProperties"].sdkVersion, version);
});
});
describe("#DiagnosticLogger.logMessage", () => {
it("should log all required fields", () => {
const expectedDate = new Date().toISOString();
logger.logMessage("Some message");
const expectedDate = new Date().toUTCString();
logger.logMessage({ message: "Some message", properties: { "msgId": "4123"} });
assert.deepEqual(stub.args[0][0], {
level: DataModel.SeverityLevel.INFO,
message: "Some message",
@ -45,10 +45,11 @@ describe("DiagnosticLogger", () => {
language: "nodejs",
operation: "Startup",
siteName: undefined,
ikey: "unknown",
ikey: "1aa11111-bbbb-1ccc-8ddd-eeeeffff3333",
extensionVersion: undefined,
sdkVersion: version,
subscriptionId: null,
msgId: "4123",
}
} as DataModel.DiagnosticLog)
})

121
Tests/Library/InternalAzureLogger.tests.ts
Просмотреть файл

@ -8,106 +8,121 @@ import FileSystemHelper = require("../../Library/FileSystemHelper");
describe("Library/InternalAzureLogger", () => {
var sandbox: sinon.SinonSandbox;
let originalEnv: NodeJS.ProcessEnv;
let internalLogger: InternalAzureLogger = null;
before(() => {
sandbox = sinon.sandbox.create();
});
beforeEach(() => {
originalEnv = process.env;
InternalAzureLogger["_instance"] = null;
internalLogger = InternalAzureLogger.getInstance();
InternalAzureLogger["_fileCleanupTimer"] = setInterval(() => { }, 0);
});
afterEach(() => {
process.env = originalEnv;
sandbox.restore();
internalLogger = null;
});
describe("Write to file", () => {
let internalLogger: InternalAzureLogger = null;
var originalEnv = process.env["APPLICATIONINSIGHTS_LOG_DESTINATION"];
before(() => {
process.env["APPLICATIONINSIGHTS_LOG_DESTINATION"] = "file";
internalLogger = InternalAzureLogger.getInstance();
});
after(() => {
process.env["APPLICATIONINSIGHTS_LOG_DESTINATION"] = originalEnv;
})
it("should log message to file", (done) => {
var writeSpy = sandbox.spy(FileSystemHelper, "appendFileAsync");
let confirmDirStub = sandbox.stub(FileSystemHelper, "confirmDirExists", async (directory: string) => {
// Fake directory creation
});
var appendFileAsyncStub = sandbox.stub(FileSystemHelper, "appendFileAsync");
internalLogger["_logToFile"] = true;
internalLogger["_storeToDisk"]("testMessage").then(() => {
assert.ok(writeSpy.called);
assert.ok(writeSpy.lastCall.args[0].indexOf("applicationinsights.log") > 0);
assert.equal(writeSpy.lastCall.args[1], "testMessage\r\n");
assert.ok(confirmDirStub.called, "confirmDirStub called");
assert.ok(appendFileAsyncStub.called, "writeStub called"); // File creation was called
assert.ok(
appendFileAsyncStub.lastCall.args[0].toString().indexOf("applicationinsights.log") > 0
);
assert.equal(appendFileAsyncStub.lastCall.args[1], "testMessage\r\n");
done();
}).catch((error) => { done(error); });
});
it("should create backup file", (done) => {
var writeSpy = sandbox.spy(FileSystemHelper, "writeFileAsync");
var readSpy = sandbox.spy(FileSystemHelper, "readFileAsync");
internalLogger.maxSizeBytes = 0;
sandbox.stub(FileSystemHelper, "confirmDirExists", async (directory: string) => { });
sandbox.stub(FileSystemHelper, "accessAsync", async (directory: string) => { });
sandbox.stub(FileSystemHelper, "getShallowFileSize", async (path: string) => {
// Fake file size check
return 123;
});
internalLogger["maxSizeBytes"] = 122;
var writeStub = sandbox.stub(FileSystemHelper, "writeFileAsync");
var appendStub = sandbox.stub(FileSystemHelper, "appendFileAsync");
var readStub = sandbox.stub(FileSystemHelper, "readFileAsync");
internalLogger["_logToFile"] = true;
internalLogger["_storeToDisk"]("backupTestMessage").then(() => {
assert.ok(readSpy.calledOnce);
assert.ok(writeSpy.calledTwice);
//assert.equal(writeSpy.args[0][0], "C:\Users\hectorh\AppData\Local\Temp\appInsights-node\1636481017787.applicationinsights.log"); // Backup file format
assert.ok(typeof writeSpy.args[0][1]);
//assert.equal(writeSpy.args[1][0], "C:\Users\hectorh\AppData\Local\Temp\appInsights-node\applicationinsights.log"); // Main file format
assert.equal(writeSpy.args[1][1], "backupTestMessage\r\n");
assert.ok(readStub.calledOnce, "readStub calledOnce"); // Read content to create backup
assert.ok(appendStub.notCalled, "appendStub notCalled");
assert.ok(writeStub.calledTwice, "writeStub calledTwice");
assert.ok(writeStub.args[0][0].toString().indexOf(".applicationinsights.log") > 0, ".applicationinsights.log present in backup file name"); // First call is for backup file
assert.equal(writeStub.args[1][1], "backupTestMessage\r\n");
done();
}).catch((error) => { done(error); });
});
it("should create multiple backup files", (done) => {
var writeSpy = sandbox.spy(FileSystemHelper, "writeFileAsync");
var readSpy = sandbox.spy(FileSystemHelper, "readFileAsync");
internalLogger.maxSizeBytes = 0;
internalLogger.maxHistory = 2;
sandbox.stub(FileSystemHelper, "confirmDirExists", async (directory: string) => { });
sandbox.stub(FileSystemHelper, "accessAsync", async (directory: string) => { });
sandbox.stub(FileSystemHelper, "getShallowFileSize", async (path: string) => {
// Fake file size check
return 123;
});
var writeStub = sandbox.stub(FileSystemHelper, "writeFileAsync");
var readStub = sandbox.stub(FileSystemHelper, "readFileAsync");
internalLogger["maxSizeBytes"] = 122;
internalLogger["_logToFile"] = true;
internalLogger["_storeToDisk"]("testMessage").then(() => {
internalLogger["_storeToDisk"]("testMessage").then(() => {
assert.equal(writeSpy.callCount, 4);
assert.ok(readSpy.calledTwice);
assert.equal(writeStub.callCount, 4);
assert.ok(readStub.calledTwice);
done();
}).catch((error) => { done(error); });
}).catch((error) => { done(error); });
});
it("should start file cleanup task", () => {
InternalAzureLogger["_instance"] = null;
InternalAzureLogger["_fileCleanupTimer"] = null;
const env = <{ [id: string]: string }>{};
env["APPLICATIONINSIGHTS_LOG_DESTINATION"] = "file";
process.env = env;
var setIntervalSpy = sandbox.spy(global, "setInterval");
internalLogger = InternalAzureLogger.getInstance();
assert.ok(setIntervalSpy.called);
assert.ok(InternalAzureLogger["_fileCleanupTimer"]);
});
it("should remove backup files", (done) => {
var unlinkSpy = sandbox.spy(FileSystemHelper, "unlinkAsync");
internalLogger.maxHistory = 0;
internalLogger["_fileCleanupTask"]().then(() => {
assert.ok(unlinkSpy.called);
FileSystemHelper.readdirAsync(internalLogger["_tempDir"]).then((files) => {
assert.equal(files.length, 1);
done();
});
sandbox.stub(FileSystemHelper, "readdirAsync", async (path: string) => {
return ["applicationinsights.log", "123.applicationinsights.log", "456.applicationinsights.log"];
});
internalLogger["maxHistory"] = 0;
var unlinkStub = sandbox.stub(FileSystemHelper, "unlinkAsync");
internalLogger["_fileCleanupTask"]().then(() => {
assert.ok(unlinkStub.calledTwice, "unlinkStub calledTwice");
done();
}).catch((error) => { done(error); });
});
it("cleanup should keep configured number of backups", (done) => {
var unlinkSpy = sandbox.spy(FileSystemHelper, "unlinkAsync");
internalLogger.maxHistory = 1;
internalLogger.maxSizeBytes = 0;
internalLogger["_storeToDisk"]("testMessage").then(() => {
internalLogger["_storeToDisk"]("testMessage").then(() => {
internalLogger["_fileCleanupTask"]().then(() => {
assert.ok(unlinkSpy.called);
FileSystemHelper.readdirAsync(internalLogger["_tempDir"]).then((files) => {
assert.equal(files.length, 2);
done();
}).catch((error) => { done(error); });
}).catch((error) => { done(error); });
}).catch((error) => { done(error); });
sandbox.stub(FileSystemHelper, "readdirAsync", async (path: string) => {
return ["applicationinsights.log", "123.applicationinsights.log", "456.applicationinsights.log"];
});
internalLogger["maxHistory"] = 1;
var unlinkStub = sandbox.stub(FileSystemHelper, "unlinkAsync");
internalLogger["_fileCleanupTask"]().then(() => {
assert.ok(unlinkStub.calledOnce, "unlinkStub calledOnce");
assert.ok(unlinkStub.args[0][0].toString().indexOf("123.applicationinsights.log") > 0, "Oldest file is deleted");
done();
}).catch((error) => { done(error); });
});
});