From 1b810d19b59f008647edf25ac6756d4d28f5e2c6 Mon Sep 17 00:00:00 2001 From: Nidhi Work Date: Wed, 11 Oct 2023 16:20:34 +0100 Subject: [PATCH 1/3] feat(publish-metrics): nest request spans into scenario span --- .../lib/open-telemetry/index.js | 83 +++++++++++++++---- 1 file changed, 65 insertions(+), 18 deletions(-) diff --git a/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js b/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js index b75e117a16..12be787647 100644 --- a/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js +++ b/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js @@ -11,6 +11,7 @@ const { SpanKind, SpanStatusCode, trace, + context, metrics } = require('@opentelemetry/api'); const { Resource } = require('@opentelemetry/resources'); @@ -129,15 +130,22 @@ class OTelReporter { { type: 'beforeRequest', name: 'startOTelSpan', - hook: this.startOTelSpan.bind(this) - } - ]); - - attachScenarioHooks(script, [ + hook: this.startHTTPRequestSpan.bind(this) + }, { type: 'afterResponse', name: 'exportOTelSpan', - hook: this.exportOTelSpan.bind(this) + hook: this.endHTTPRequestSpan.bind(this) + }, + { + type: 'beforeScenario', + name: 'startScenarioSpan', + hook: this.startScenarioSpan('http').bind(this) + }, + { + type: 'afterScenario', + name: 'endScenarioSpan', + hook: this.endScenarioSpan('http').bind(this) } ]); } @@ -311,20 +319,59 @@ class OTelReporter { this.tracerProvider.register(); } - startOTelSpan(req, userContext, events, done) { + // Sets the tracer by engine type, starts the scenario span and adds it to the VU context + startScenarioSpan(engine) { + return function (userContext, ee, next) { + // get and set the tracer by engine + const tracerName = engine + 'Tracer'; + this[tracerName] = trace.getTracer(`Artillery-${engine}`); + const span = this[tracerName].startSpan( + userContext.scenario?.name || `artillery ${engine} scenario`, + Date.now() + ); + debug('Scenario span created'); + userContext.vars[`__${engine}ScenarioSpan`] = span; + if (engine === 'http') { + next(); + } else { + return span; + } + }; + } + + endScenarioSpan(engine) { + return function (userContext, ee, next) { + const span = userContext.vars[`__${engine}ScenarioSpan`]; + span.end(Date.now()); + if (engine === 'http') { + next(); + } else { + return; + } + }; + } + + startHTTPRequestSpan(req, userContext, events, done) { const startTime = Date.now(); - userContext.vars['__otlStartTime'] = startTime; + userContext.vars['__otlHTTPRequestStartTime'] = startTime; const spanName = this.traceConfig.useRequestNames && req.name ? req.name : req.method.toLowerCase(); - const span = trace.getTracer('artillery-tracer').startSpan(spanName, { - startTime, - kind: SpanKind.CLIENT - }); + + const scenarioSpan = userContext.vars['__httpScenarioSpan']; + const ctx = trace.setSpan(context.active(), scenarioSpan); + const span = this.httpTracer.startSpan( + spanName, + { + startTime, + kind: SpanKind.CLIENT + }, + ctx + ); span.addEvent('http_request_started', startTime); - userContext.vars['__otlpSpan'] = span; + userContext.vars['__otlpHTTPRequestSpan'] = span; events.on('error', (err) => { span.setStatus({ @@ -338,18 +385,19 @@ class OTelReporter { return done(); } - exportOTelSpan(req, res, userContext, events, done) { - if (!userContext.vars['__otlpSpan']) { + endHTTPRequestSpan(req, res, userContext, events, done) { + if (!userContext.vars['__otlpHTTPRequestSpan']) { return done(); } - const span = userContext.vars['__otlpSpan']; + const span = userContext.vars['__otlpHTTPRequestSpan']; let endTime; if (res.timings && res.timings.phases) { span.setAttribute('responseTimeMs', res.timings.phases.firstByte); endTime = - userContext.vars['__otlStartTime'] + res.timings.phases.firstByte; + userContext.vars['__otlHTTPRequestStartTime'] + + res.timings.phases.firstByte; span.addEvent('http_request_ended', endTime); } else { span.addEvent('http_request_ended'); @@ -371,7 +419,6 @@ class OTelReporter { if (this.traceConfig?.attributes) { span.setAttributes(this.traceConfig.attributes); } - span.end(endTime || Date.now); return done(); From 26422991fb2e8442d51ddb33c9974e3478938a18 Mon Sep 17 00:00:00 2001 From: Nidhi Work Date: Thu, 12 Oct 2023 19:32:23 +0100 Subject: [PATCH 2/3] feat(publish-metrics): implement spans for parts of request --- package-lock.json | 14 +- .../lib/open-telemetry/index.js | 134 +++++++++++------- .../package.json | 1 + 3 files changed, 97 insertions(+), 52 deletions(-) diff --git a/package-lock.json b/package-lock.json index d668afe140..93821ee5fa 100644 --- a/package-lock.json +++ b/package-lock.json @@ -4620,6 +4620,17 @@ "node": ">=14" } }, + "node_modules/@opentelemetry/context-async-hooks": { + "version": "1.17.1", + "resolved": "https://registry.npmjs.org/@opentelemetry/context-async-hooks/-/context-async-hooks-1.17.1.tgz", + "integrity": "sha512-up5I+RiQEkGrVEHtbAtmRgS+ZOnFh3shaDNHqZPBlGy+O92auL6yMmjzYpSKmJOGWowvs3fhVHePa8Exb5iHUg==", + "engines": { + "node": ">=14" + }, + "peerDependencies": { + "@opentelemetry/api": ">=1.0.0 <1.7.0" + } + }, "node_modules/@opentelemetry/core": { "version": "1.15.2", "resolved": "https://registry.npmjs.org/@opentelemetry/core/-/core-1.15.2.tgz", @@ -23025,6 +23036,7 @@ "dependencies": { "@aws-sdk/client-cloudwatch": "^3.370.0", "@opentelemetry/api": "^1.4.1", + "@opentelemetry/context-async-hooks": "^1.17.1", "@opentelemetry/exporter-metrics-otlp-grpc": "^0.41.2", "@opentelemetry/exporter-metrics-otlp-http": "^0.41.2", "@opentelemetry/exporter-metrics-otlp-proto": "^0.41.2", @@ -24347,7 +24359,7 @@ }, "packages/types": { "name": "@artilleryio/types", - "version": "0.3.0", + "version": "0.4.0", "license": "MPL-2.0", "devDependencies": { "@types/tap": "^15.0.8", diff --git a/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js b/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js index 12be787647..0e2a7c727b 100644 --- a/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js +++ b/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js @@ -19,6 +19,13 @@ const { SemanticResourceAttributes } = require('@opentelemetry/semantic-conventions'); +const { + AsyncHooksContextManager +} = require('@opentelemetry/context-async-hooks'); +const contextManager = new AsyncHooksContextManager(); +contextManager.enable(); +context.setGlobalContextManager(contextManager); + class OTelReporter { constructor(config, events, script) { this.script = script; @@ -324,11 +331,15 @@ class OTelReporter { return function (userContext, ee, next) { // get and set the tracer by engine const tracerName = engine + 'Tracer'; - this[tracerName] = trace.getTracer(`Artillery-${engine}`); + this[tracerName] = trace.getTracer(`artillery-${engine}`); const span = this[tracerName].startSpan( - userContext.scenario?.name || `artillery ${engine} scenario`, - Date.now() + userContext.scenario?.name || `artillery-${engine}-scenario`, + { + startTime: Date.now(), + kind: SpanKind.CLIENT + } ); + debug('Scenario span created'); userContext.vars[`__${engine}ScenarioSpan`] = span; if (engine === 'http') { @@ -353,35 +364,29 @@ class OTelReporter { startHTTPRequestSpan(req, userContext, events, done) { const startTime = Date.now(); - userContext.vars['__otlHTTPRequestStartTime'] = startTime; - const spanName = - this.traceConfig.useRequestNames && req.name - ? req.name - : req.method.toLowerCase(); - const scenarioSpan = userContext.vars['__httpScenarioSpan']; - const ctx = trace.setSpan(context.active(), scenarioSpan); - const span = this.httpTracer.startSpan( - spanName, - { + context.with(trace.setSpan(context.active(), scenarioSpan), () => { + const spanName = + this.traceConfig.useRequestNames && req.name + ? req.name + : req.method.toLowerCase(); + const span = this.httpTracer.startSpan(spanName, { startTime, - kind: SpanKind.CLIENT - }, - ctx - ); - - span.addEvent('http_request_started', startTime); - userContext.vars['__otlpHTTPRequestSpan'] = span; - - events.on('error', (err) => { - span.setStatus({ - code: SpanStatusCode.ERROR, - message: err.message || err + kind: SpanKind.CLIENT, + attributes: { vuId: userContext.$uuid } + }); + userContext.vars['__otlpHTTPRequestSpan'] = span; + + events.on('error', (err) => { + span.recordException(err); + span.setStatus({ + code: SpanStatusCode.ERROR, + message: err.message || err + }); + debug('Span status set as error due to the following error: \n', err); + span.end(Date.now); }); - debug('Span status set as error due to the following error: \n', err); - span.end(Date.now); }); - return done(); } @@ -395,32 +400,59 @@ class OTelReporter { if (res.timings && res.timings.phases) { span.setAttribute('responseTimeMs', res.timings.phases.firstByte); - endTime = - userContext.vars['__otlHTTPRequestStartTime'] + - res.timings.phases.firstByte; - span.addEvent('http_request_ended', endTime); - } else { - span.addEvent('http_request_ended'); + + // Child spans are created for each part of request from the timings object and named accordingly. More info here: https://github.com/sindresorhus/got/blob/main/source/core/response.ts + // Map names of parts of request that we are going to create spans for, to the timings parameters representing their start and end times for easier span creation + const timingsMap = { + dns_lookup: { start: 'socket', end: 'lookup' }, + tcp_handshake: { start: 'lookup', end: 'connect' }, + tls_negotiation: { start: 'connect', end: 'secureConnect' }, + request: { + start: res.timings.secureConnect ? 'secureConnect' : 'connect', + end: 'upload' + }, + download: { start: 'response', end: 'end' }, + firstByte: { start: 'upload', end: 'response' } + }; + + // Create child spans within the request span context + context.with(trace.setSpan(context.active(), span), () => { + for (const [name, value] of Object.entries(timingsMap)) { + if (res.timings[value.start] && res.timings[value.end]) { + this.httpTracer + .startSpan(name, { + kind: SpanKind.CLIENT, + startTime: res.timings[value.start] + }) + .end(res.timings[value.end]); + } + } + }); + endTime = res.timings.end || res.timings.error || res.timings.abort; } - const url = new URL(req.url); - span.setAttributes({ - 'url.full': url.href, - 'server.address': url.hostname, - // We set the port if it is specified, if not we set to a default port based on the protocol - 'server.port': url.port || (url.protocol === 'http' ? 80 : 443), - 'http.request.method': req.method, - 'http.response.status_code': res.statusCode - }); + try { + const url = new URL(req.url); + span.setAttributes({ + 'url.full': url.href, + 'url.path': url.pathname, + 'server.address': url.hostname, + // We set the port if it is specified, if not we set to a default port based on the protocol + 'server.port': url.port || (url.protocol === 'http' ? 80 : 443), + 'http.request.method': req.method, + 'http.response.status_code': res.statusCode + }); - if (res.statusCode >= 400) { - span.setStatus({ code: SpanStatusCode.ERROR }); - } - if (this.traceConfig?.attributes) { - span.setAttributes(this.traceConfig.attributes); + if (res.statusCode >= 400) { + span.setStatus({ code: SpanStatusCode.ERROR }); + } + if (this.traceConfig?.attributes) { + span.setAttributes(this.traceConfig.attributes); + } + span.end(endTime || Date.now()); + } catch (err) { + // We don't do anything, if error occurs at this point it will be due to us already ending the span in beforeRequest hook in case of an error. } - span.end(endTime || Date.now); - return done(); } @@ -450,7 +482,7 @@ class OTelReporter { } debug('Pending requests done'); debug('Shutting the Reader down'); - await this.theReader.shutdown(); //check if shutdown successfull + await this.theReader.shutdown(); debug('Shut down sucessfull'); } if (this.tracing) { diff --git a/packages/artillery-plugin-publish-metrics/package.json b/packages/artillery-plugin-publish-metrics/package.json index 015a07d453..0dd1273610 100644 --- a/packages/artillery-plugin-publish-metrics/package.json +++ b/packages/artillery-plugin-publish-metrics/package.json @@ -16,6 +16,7 @@ "dependencies": { "@aws-sdk/client-cloudwatch": "^3.370.0", "@opentelemetry/api": "^1.4.1", + "@opentelemetry/context-async-hooks": "^1.17.1", "@opentelemetry/exporter-metrics-otlp-grpc": "^0.41.2", "@opentelemetry/exporter-metrics-otlp-http": "^0.41.2", "@opentelemetry/exporter-metrics-otlp-proto": "^0.41.2", From 8329baf83753de622ff36c7b9fb32acf48494bd6 Mon Sep 17 00:00:00 2001 From: Nidhi Work Date: Thu, 12 Oct 2023 20:52:04 +0100 Subject: [PATCH 3/3] refactor: clean up --- .../lib/open-telemetry/index.js | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js b/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js index 0e2a7c727b..654845ffab 100644 --- a/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js +++ b/packages/artillery-plugin-publish-metrics/lib/open-telemetry/index.js @@ -373,7 +373,7 @@ class OTelReporter { const span = this.httpTracer.startSpan(spanName, { startTime, kind: SpanKind.CLIENT, - attributes: { vuId: userContext.$uuid } + attributes: { 'vu.uuid': userContext.$uuid } }); userContext.vars['__otlpHTTPRequestSpan'] = span; @@ -399,10 +399,10 @@ class OTelReporter { let endTime; if (res.timings && res.timings.phases) { - span.setAttribute('responseTimeMs', res.timings.phases.firstByte); + span.setAttribute('response.time.ms', res.timings.phases.firstByte); - // Child spans are created for each part of request from the timings object and named accordingly. More info here: https://github.com/sindresorhus/got/blob/main/source/core/response.ts - // Map names of parts of request that we are going to create spans for, to the timings parameters representing their start and end times for easier span creation + // Child spans are created for each phase of the request from the timings object and named accordingly. More info here: https://github.com/sindresorhus/got/blob/main/source/core/response.ts + // Map names of request phases to the timings parameters representing their start and end times for easier span creation const timingsMap = { dns_lookup: { start: 'socket', end: 'lookup' }, tcp_handshake: { start: 'lookup', end: 'connect' }, @@ -412,10 +412,10 @@ class OTelReporter { end: 'upload' }, download: { start: 'response', end: 'end' }, - firstByte: { start: 'upload', end: 'response' } + first_byte: { start: 'upload', end: 'response' } }; - // Create child spans within the request span context + // Create phase spans within the request span context context.with(trace.setSpan(context.active(), span), () => { for (const [name, value] of Object.entries(timingsMap)) { if (res.timings[value.start] && res.timings[value.end]) {