From 0ab46ce7fc605e99aee341a855577c54d287e70a Mon Sep 17 00:00:00 2001 From: UltraDev Date: Wed, 24 Aug 2022 10:40:05 +0200 Subject: [PATCH 1/3] Implement log functionality --- gradle.properties | 2 +- src/SourcePlusPlus.ts | 2 +- src/control/ContextReceiver.ts | 12 +- src/control/LiveInstrumentRemote.ts | 141 +++++++++++---------- src/model/LiveInstrument.ts | 7 + src/model/error/LiveInstrumentException.ts | 13 ++ src/model/instruments/LiveLog.ts | 26 +++- test/LiveLogTest.js | 58 +++++++++ test/TestUtils.js | 40 +++++- test/test.js | 3 +- 10 files changed, 219 insertions(+), 85 deletions(-) create mode 100644 src/model/error/LiveInstrumentException.ts create mode 100644 test/LiveLogTest.js diff --git a/gradle.properties b/gradle.properties index a31388d..35c5ebf 100644 --- a/gradle.properties +++ b/gradle.properties @@ -1,4 +1,4 @@ kotlin.code.style=official probeGroup=plus.sourceplus.probe -projectVersion=0.6.3-SNAPSHOT +projectVersion=0.6.8-SNAPSHOT diff --git a/src/SourcePlusPlus.ts b/src/SourcePlusPlus.ts index 6d313f1..2dfbdc1 100644 --- a/src/SourcePlusPlus.ts +++ b/src/SourcePlusPlus.ts @@ -130,7 +130,7 @@ namespace SourcePlusPlus { async function sendConnected(eventBus: EventBus): Promise { let probeMetadata = { language: 'nodejs', - probe_version: '1.0.0', // TODO + probe_version: '1.0.3', // TODO nodejs_version: process.version, service: config.serviceName, service_instance: config.serviceInstance, diff --git a/src/control/ContextReceiver.ts b/src/control/ContextReceiver.ts index ab7e7c4..7b91a25 100644 --- a/src/control/ContextReceiver.ts +++ b/src/control/ContextReceiver.ts @@ -89,17 +89,17 @@ namespace ContextReceiver { activeSpan.stop(); } - export function applyLog(liveLogId: string, logFormat: string, logArguments: string[], variables) { + export function applyLog(liveLogId: string, logFormat: string, logArguments: any) { let logTags = new LogTags(); logTags.addData(new KeyStringValuePair().setKey('log_id').setValue(liveLogId)); logTags.addData(new KeyStringValuePair().setKey('level').setValue('Live')); logTags.addData(new KeyStringValuePair().setKey('thread').setValue('n/a')); - for (let varName of logArguments) { - let variable = tryFindVariable(varName, variables); - let value = variable ? variable.value : "null"; // TODO: Properly toString the variable (or encode it) - if (variable) { - logTags.addData(new KeyStringValuePair().setKey(`argument.${varName}`).setValue(value)); + if (logArguments) { + for (const varName in logArguments) { + logTags.addData(new KeyStringValuePair() + .setKey(`argument.${varName}`) + .setValue(logArguments[varName])); } } diff --git a/src/control/LiveInstrumentRemote.ts b/src/control/LiveInstrumentRemote.ts index f0aa562..689959a 100644 --- a/src/control/LiveInstrumentRemote.ts +++ b/src/control/LiveInstrumentRemote.ts @@ -93,84 +93,85 @@ export default class LiveInstrumentRemote { })); } - let instrumentIds = this.breakpointIdToInstrumentIds.get(message.params.hitBreakpoints[0]); // TODO: Handle multiple hit breakpoints - if (!instrumentIds) { - this.removeBreakpoint(message.params.hitBreakpoints[0]); - return; - } + message.params.hitBreakpoints.forEach(breakpointId => { // There should only be a single breakpoint, but handle multiple just in case + let instrumentIds = this.breakpointIdToInstrumentIds.get(breakpointId); + if (!instrumentIds) { + this.removeBreakpoint(message.params.hitBreakpoints[0]); + return; + } - let instruments = instrumentIds.map(id => this.instruments.get(id)); - let conditionsSatisfied = Promise.all(instruments.map(instrument => { - if (instrument.condition === undefined || instrument.condition === null) - return true; - - return new Promise((resolve, reject) => { - this.session.post("Debugger.evaluateOnCallFrame", { - callFrameId: frame.callFrameId, - expression: instrument.condition, - silent: false, - throwOnSideEffect: true - }, (err, res) => { - if (err) { - console.log(`Error evaluating condition (${instrument.condition}): ${err}`); - resolve(false); - } else { - if (res.result.type === 'object' && res.result.subtype === 'error') { - if (res.result.className === 'EvalError') { - console.log(`Could not evaluate condition (${instrument.condition}) due to possible side effects`); + let instruments = instrumentIds.map(id => this.instruments.get(id)); + let dataGathered = Promise.all(instruments.map(instrument => { + return new Promise((resolve, reject) => { + this.session.post("Debugger.evaluateOnCallFrame", { + callFrameId: frame.callFrameId, + expression: instrument.createExpression(), + silent: false, // In case of an exception, don't affect the program flow + throwOnSideEffect: true, // Disallow side effects + returnByValue: true // Return the entire JSON object rather than just the remote id + }, (err, res) => { + if (err) { + console.log(`Error evaluating condition (${instrument.condition}): ${err}`); + resolve({success: false}); + } else { + console.log(res.result); + + if (res.result.type === 'object' && res.result.subtype === 'error') { + if (res.result.className === 'EvalError') { + console.log(`Could not evaluate condition (${instrument.condition}) due to possible side effects`); + } else { + console.log(`Error evaluating condition (${instrument.condition}): ${res.result.description}`); + } + resolve({success: false}); + } else if (res.result.type !== 'object') { + console.log("Invalid condition for instrument id: " + instrument.id + ": " + instrument.condition, res.result); + resolve({success: false}); } else { - console.log(`Error evaluating condition (${instrument.condition}): ${res.result.description}`); + resolve(res.result.value); } - resolve(false); - } else if (res.result.type !== 'boolean') { - console.log("Invalid condition for instrument id: " + instrument.id + ": " + instrument.condition, res.result); - resolve(false); - } else { - resolve(res.result.value); } - } + }); }); - }); - })); - - Promise.all(promises).then(() => conditionsSatisfied) - .then(conditions => { - for (let i = 0; i < instruments.length; i++) { - if (conditions[i]) { - let instrument = instruments[i]; - if (!instrument) { - continue; - } + })); + + Promise.all(promises).then(() => dataGathered) + .then(data => { + for (let i = 0; i < instruments.length; i++) { + if (data[i].success) { + let instrument = instruments[i]; + if (!instrument) { + continue; + } - if (instrument.type == LiveInstrumentType.BREAKPOINT) { - ContextReceiver.applyBreakpoint( - instrument.id, - instrument.location.source, - instrument.location.line, - message.params.callFrames, - variables - ); - } else if (instrument.type == LiveInstrumentType.LOG) { - let logInstrument = instrument; - ContextReceiver.applyLog( - instrument.id, - logInstrument.logFormat, - logInstrument.logArguments, - variables - ); - } else if (instrument.type == LiveInstrumentType.METER) { - let meterInstrument = instrument; - ContextReceiver.applyMeter( - instrument.id, - variables - ); - } - if (instrument.isFinished()) { - this.removeBreakpoint(instrument.id); + if (instrument.type == LiveInstrumentType.BREAKPOINT) { + ContextReceiver.applyBreakpoint( + instrument.id, + instrument.location.source, + instrument.location.line, + message.params.callFrames, + variables + ); + } else if (instrument.type == LiveInstrumentType.LOG) { + let logInstrument = instrument; + ContextReceiver.applyLog( + instrument.id, + logInstrument.logFormat, + data[i].logArguments + ); + } else if (instrument.type == LiveInstrumentType.METER) { + let meterInstrument = instrument; + ContextReceiver.applyMeter( + instrument.id, + variables + ); + } + if (instrument.isFinished()) { + this.removeBreakpoint(instrument.id); + } } } - } - }); + }); + }); }); } diff --git a/src/model/LiveInstrument.ts b/src/model/LiveInstrument.ts index 10e245e..611686a 100644 --- a/src/model/LiveInstrument.ts +++ b/src/model/LiveInstrument.ts @@ -40,4 +40,11 @@ export default class LiveInstrument { meta: this.meta }; } + + createExpression() { + if (this.condition == null) { + return `(() => { return {success: true} })()`; + } + return `(() => { return {success: ${this.condition}} })()`; + } } diff --git a/src/model/error/LiveInstrumentException.ts b/src/model/error/LiveInstrumentException.ts new file mode 100644 index 0000000..645ba93 --- /dev/null +++ b/src/model/error/LiveInstrumentException.ts @@ -0,0 +1,13 @@ +export class LiveInstrumentException { + type: ErrorType; + message: string; + + toEventBusString(): string { + return `EventBusException:LiveInstrumentException[${ErrorType[this.type]}]: ${this.message}`; + } +} + +export enum ErrorType { + CLASS_NOT_FOUND, + CONDITIONAL_FAILED +} diff --git a/src/model/instruments/LiveLog.ts b/src/model/instruments/LiveLog.ts index 23eaed5..54c464e 100644 --- a/src/model/instruments/LiveLog.ts +++ b/src/model/instruments/LiveLog.ts @@ -1,11 +1,31 @@ import LiveInstrument from "../LiveInstrument"; -import LiveSourceLocation from "../LiveSourceLocation"; -import InstrumentThrottle from "../throttle/InstrumentThrottle"; import LiveInstrumentType from "../LiveInstrumentType"; -import HitThrottle from "../throttle/HitThrottle"; export default class LiveLog extends LiveInstrument { type = LiveInstrumentType.LOG; logFormat: string logArguments: string[] + + createExpression(): string { + let logArgumentsExpression = this.logArguments + .map(arg => `data['${arg}'] = ${arg}.toString()`) + .join(';'); + if (this.condition == null) { + return `(() => { + let data = {success: true}; + (data => {${logArgumentsExpression}})(data); + return data; + })()`; + } else { + return `(() => { + if (${this.condition}) { + let data = {success: true}; + (data => {${logArgumentsExpression}})(data); + returndata; + } else { + return {success: false}; + } + })()`; + } + } } \ No newline at end of file diff --git a/test/LiveLogTest.js b/test/LiveLogTest.js new file mode 100644 index 0000000..41e3528 --- /dev/null +++ b/test/LiveLogTest.js @@ -0,0 +1,58 @@ +const assert = require('assert'); +const TestUtils = require("./TestUtils.js"); + +module.exports = function () { + function simplePrimitives() { + let i = 1 + let c = 'h' + let s = "hi" + let f = 1.0 + let bool = true + TestUtils.addLineLabel("done", () => TestUtils.getLineNumber()) + } + + it('add live log', async function () { + simplePrimitives() //setup labels + + await TestUtils.addLiveLog({ + "source": TestUtils.getFilename()(), + "line": TestUtils.getLineLabelNumber("done") + }, null, 1, "test log", []).then(function (res) { + assert.equal(res.status, 200); + simplePrimitives(); //trigger breakpoint + }).catch(function (err) { + assert.fail(err) + }); + }); + + it('verify log data', async function () { + this.timeout(2000) + + setTimeout(() => simplePrimitives(), 1000); + + let event = await TestUtils.awaitMarkerEvent("LOG_HIT"); + console.log(event); + // assert.equal(event.stackTrace.elements[0].method, 'simplePrimitives'); + // let variables = event.stackTrace.elements[0].variables; + // + // let iVar = TestUtils.locateVariable("i", variables); + // assert.equal(iVar.liveClazz, "number"); + // assert.equal(iVar.value, 1); + // + // let cVar = TestUtils.locateVariable("c", variables); + // assert.equal(cVar.liveClazz, "string"); + // assert.equal(cVar.value, "h"); + // + // let sVar = TestUtils.locateVariable("s", variables); + // assert.equal(sVar.liveClazz, "string"); + // assert.equal(sVar.value, "hi"); + // + // let fVar = TestUtils.locateVariable("f", variables); + // assert.equal(fVar.liveClazz, "number"); + // assert.equal(fVar.value, 1.0); + // + // let boolVar = TestUtils.locateVariable("bool", variables); + // assert.equal(boolVar.liveClazz, "boolean"); + // assert.equal(boolVar.value, true); + }); +}; \ No newline at end of file diff --git a/test/TestUtils.js b/test/TestUtils.js index 2b82662..a91c526 100644 --- a/test/TestUtils.js +++ b/test/TestUtils.js @@ -23,6 +23,13 @@ class TestUtils { assert.fail(err); }); + await TestUtils.setupMarker(); + + // Without waiting long enough, the spp.probe.command.live-instrument-remote counter isn't incremented + await new Promise(resolve => setTimeout(resolve, 10000)); + } + + static async setupMarker() { TestUtils.markerEventBus = new EventBus(host + "/marker/eventbus"); TestUtils.markerEventBus.enableReconnect(true); await new Promise((resolve, reject) => { @@ -42,6 +49,7 @@ class TestUtils { TestUtils.markerEventBus.registerHandler("spp.service.live-instrument.subscriber:system", { "auth-token": await tokenPromise }, function (err, message) { + console.log(message); if (!err) { if (TestUtils.markerListeners[message.body.eventType]) { TestUtils.markerListeners[message.body.eventType] @@ -54,9 +62,6 @@ class TestUtils { }); } }); - - // Without waiting long enough, the spp.probe.command.live-instrument-remote counter isn't incremented - await new Promise(resolve => setTimeout(resolve, 10000)); } static async teardownProbe() { @@ -64,6 +69,10 @@ class TestUtils { TestUtils.markerEventBus.close(); } + static async teardownMarker() { + TestUtils.markerEventBus.close(); + } + static addLineLabel(label, lineNumberFunc) { TestUtils.lineLabels[label] = lineNumberFunc.call(); } @@ -110,6 +119,31 @@ class TestUtils { return axios.request(options); } + static async addLiveLog(location, condition, hitLimit, logFormat, logArguments) { + const options = { + method: 'POST', + url: `${host}/graphql/spp`, + headers: { + 'Content-Type': 'application/json', + Authorization: 'Bearer ' + await tokenPromise + }, + data: { + "query": "mutation ($input: LiveLogInput!) { addLiveLog(input: $input) { id logFormat logArguments location { source line } condition expiresAt hitLimit applyImmediately applied pending throttle { limit step } } }", + "variables": { + "input": { + "logFormat": logFormat, + "logArguments": logArguments, + "location": location, + "condition": condition, + "hitLimit": hitLimit, + "applyImmediately": true, + } + } + } + }; + return axios.request(options); + } + static getLineNumber() { var e = new Error(); if (!e.stack) try { diff --git a/test/test.js b/test/test.js index db1fea4..1097a5c 100644 --- a/test/test.js +++ b/test/test.js @@ -4,4 +4,5 @@ before(TestUtils.setupProbe); after(TestUtils.teardownProbe); describe("test simple primitives", require("./SimplePrimitivesLiveInstrumentTest")); -describe("test simple collections", require("./SimpleCollectionsLiveInstrumentTest")); \ No newline at end of file +describe("test simple collections", require("./SimpleCollectionsLiveInstrumentTest")); +describe("test live log", require("./LiveLogTest")); \ No newline at end of file From 7780e664ca1e78827754c8c01886054bac41b150 Mon Sep 17 00:00:00 2001 From: UltraDev Date: Wed, 24 Aug 2022 11:40:51 +0200 Subject: [PATCH 2/3] Add error handling --- src/control/LiveInstrumentRemote.ts | 23 +++++++++++++++++------ 1 file changed, 17 insertions(+), 6 deletions(-) diff --git a/src/control/LiveInstrumentRemote.ts b/src/control/LiveInstrumentRemote.ts index 689959a..474a51d 100644 --- a/src/control/LiveInstrumentRemote.ts +++ b/src/control/LiveInstrumentRemote.ts @@ -111,20 +111,22 @@ export default class LiveInstrumentRemote { returnByValue: true // Return the entire JSON object rather than just the remote id }, (err, res) => { if (err) { - console.log(`Error evaluating condition (${instrument.condition}): ${err}`); + this.handleConditionalFailed(instrument, + `Error evaluating condition (${instrument.condition}): ${err}`); resolve({success: false}); } else { - console.log(res.result); - if (res.result.type === 'object' && res.result.subtype === 'error') { if (res.result.className === 'EvalError') { - console.log(`Could not evaluate condition (${instrument.condition}) due to possible side effects`); + this.handleConditionalFailed(instrument, + `Could not evaluate condition (${instrument.condition}) due to possible side effects`); } else { - console.log(`Error evaluating condition (${instrument.condition}): ${res.result.description}`); + this.handleConditionalFailed(instrument, + `Error evaluating condition (${instrument.condition}): ${res.result.description}`); } resolve({success: false}); } else if (res.result.type !== 'object') { - console.log("Invalid condition for instrument id: " + instrument.id + ": " + instrument.condition, res.result); + this.handleConditionalFailed(instrument, + `Invalid condition for instrument id: ${instrument.id}: ${instrument.condition} ==> ${res.result}`); resolve({success: false}); } else { resolve(res.result.value); @@ -333,6 +335,15 @@ export default class LiveInstrumentRemote { } } + handleConditionalFailed(instrument: LiveInstrument, error: string) { + this.removeInstrument(instrument.id); + this.eventBus.publish("spp.processor.status.live-instrument-removed", { + occurredAt: Date.now(), + instrument: JSON.stringify(instrument.toJson()), + cause: `EventBusException:LiveInstrumentException[CONDITIONAL_FAILED]: ${error}` + }); + } + // TODO: Call this regularly to clean up old instruments // TODO: Ensure the cache doesn't get too large private cleanCache() { From 44d6046c2a611b9111700c0373879a4f90e2a36a Mon Sep 17 00:00:00 2001 From: UltraDev Date: Wed, 24 Aug 2022 13:12:31 +0200 Subject: [PATCH 3/3] Initialize ContextReceiver.logReport after loading config --- src/control/ContextReceiver.ts | 12 ++++++++---- src/control/LiveInstrumentRemote.ts | 2 ++ 2 files changed, 10 insertions(+), 4 deletions(-) diff --git a/src/control/ContextReceiver.ts b/src/control/ContextReceiver.ts index 7b91a25..f365826 100644 --- a/src/control/ContextReceiver.ts +++ b/src/control/ContextReceiver.ts @@ -10,10 +10,14 @@ import VariableUtil from "../util/VariableUtil"; import ProbeMemory from "../ProbeMemory"; namespace ContextReceiver { - let logReport = new LogReportServiceClient( - config.collectorAddress, - config.secure ? grpc.credentials.createSsl() : grpc.credentials.createInsecure() - ); + let logReport; + + export function initialize() { + logReport = new LogReportServiceClient( + config.collectorAddress, + config.secure ? grpc.credentials.createSsl() : grpc.credentials.createInsecure() + ); + } function tryFindVariable(varName, variables) { for (let scope in variables) { diff --git a/src/control/LiveInstrumentRemote.ts b/src/control/LiveInstrumentRemote.ts index 474a51d..d73577f 100644 --- a/src/control/LiveInstrumentRemote.ts +++ b/src/control/LiveInstrumentRemote.ts @@ -43,6 +43,8 @@ export default class LiveInstrumentRemote { } this.sourceMapper = new SourceMapper(this.scriptLoaded.bind(this)); + + ContextReceiver.initialize(); } async start(): Promise {