From a16441c6c6cbf8c3983722edc075fcfe193b928c Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Thu, 21 Jul 2022 15:37:35 +0300 Subject: [PATCH] test: e2e test enabling profiling (#514) * test: create a script for npm installing in all examples * feat: add debug logging for profiling * test: implement a basic e2e test for profiling * test: turn profiling test on in CI * feat: explicitly start and stop profiling in the example * feat: debug log exporter sends * test: improve the example * style: intent with spaces * docs: add readme for the example * docs: better wording in the readme --- .github/workflows/ci.yml | 6 ++++ examples/profiling/.dockerignore | 2 ++ examples/profiling/README.md | 27 +++++++++++++++++ examples/profiling/collector-config.yml | 33 +++++++++++++++++++++ examples/profiling/docker-compose.yml | 13 +++++++++ examples/profiling/index.js | 39 +++++++++++++++++++++++++ examples/profiling/package.json | 13 +++++++++ scripts/examples-npm-install | 12 ++++++++ src/profiling/OTLPProfilingExporter.ts | 3 +- src/profiling/index.ts | 6 +++- test/examples/Dockerfile_app | 18 ++++++------ test/examples/profiling.override.yml | 8 +++++ test/examples/profiling/app.env | 4 +++ test/examples/profiling/index.js | 14 +++++++++ test/examples/profiling/snapshot.js | 18 ++++++++++++ 15 files changed, 205 insertions(+), 11 deletions(-) create mode 100644 examples/profiling/.dockerignore create mode 100644 examples/profiling/README.md create mode 100644 examples/profiling/collector-config.yml create mode 100644 examples/profiling/docker-compose.yml create mode 100644 examples/profiling/index.js create mode 100644 examples/profiling/package.json create mode 100755 scripts/examples-npm-install create mode 100644 test/examples/profiling.override.yml create mode 100644 test/examples/profiling/app.env create mode 100644 test/examples/profiling/index.js create mode 100644 test/examples/profiling/snapshot.js diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index ae606de7..78041a72 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -178,6 +178,9 @@ jobs: - name: Test log-injection example working-directory: test/examples run: docker-compose -f e2e.docker-compose.yml -f log-injection.override.yml -f published.override.yml up --exit-code-from test + - name: Test profiling example + working-directory: test/examples + run: docker-compose -f e2e.docker-compose.yml -f profiling.override.yml -f published.override.yml up --exit-code-from test e2e-local: runs-on: ubuntu-latest @@ -197,3 +200,6 @@ jobs: - name: Test log-injection example working-directory: test/examples run: docker-compose -f e2e.docker-compose.yml -f log-injection.override.yml up --exit-code-from test + - name: Test profiling example + working-directory: test/examples + run: docker-compose -f e2e.docker-compose.yml -f profiling.override.yml up --exit-code-from test diff --git a/examples/profiling/.dockerignore b/examples/profiling/.dockerignore new file mode 100644 index 00000000..d5f19d89 --- /dev/null +++ b/examples/profiling/.dockerignore @@ -0,0 +1,2 @@ +node_modules +package-lock.json diff --git a/examples/profiling/README.md b/examples/profiling/README.md new file mode 100644 index 00000000..d74c63e4 --- /dev/null +++ b/examples/profiling/README.md @@ -0,0 +1,27 @@ +# Profiling Example + +> :warning: Profiling is still an experimental feature + +This example showcases enabling profiling for Splunk APM. There's no official support for profiling in OTel, so profiling requires working with some Splunk-specific components. +By default, the example requires the OTel Collector to run with the OTLP receiver listening for logs on `localhost:4317`. To export profiling data to APM, you must set up `splunk_hec` exporter in the Collector. See [the example collector config](./collector-config.yml). + +```shell +# Replace <...> with the correct values +export SPLUNK_REALM="" +export SPLUNK_ACCESS_TOKEN="" +# Docker Compose configuration has been provided for convenience: +docker compose up +``` + +Then run the script in a separate terminal: + +```shell +# Optional. To set the environment: +export OTEL_SERVICE_NAME='profiling-example' +export OTEL_RESOURCE_ATTRIBUTES='deployment.environment=dev' +export OTEL_LOG_LEVEL='DEBUG' +# Run the example: +npm start +``` + +The script will then export to collector on shutdown and the collector will take care of transforming the payload into `splunk_hec` format. diff --git a/examples/profiling/collector-config.yml b/examples/profiling/collector-config.yml new file mode 100644 index 00000000..96730b77 --- /dev/null +++ b/examples/profiling/collector-config.yml @@ -0,0 +1,33 @@ +receivers: + otlp: + protocols: + grpc: + signalfx: + +exporters: + otlphttp: + traces_endpoint: "https://ingest.${SPLUNK_REALM}.signalfx.com/v2/trace/otlp" + headers: + X-SF-TOKEN: "${SPLUNK_ACCESS_TOKEN}" + splunk_hec: + token: "${SPLUNK_ACCESS_TOKEN}" + endpoint: "https://ingest.${SPLUNK_REALM}.signalfx.com/v1/log" + logging/debug: + loglevel: debug + +processors: + batch: + +service: + telemetry: + logs: + level: "debug" + pipelines: + traces: + receivers: [otlp] + processors: [batch] + exporters: [logging/debug, otlphttp] + logs/profiling: + receivers: [otlp] + processors: [batch] + exporters: [logging/debug, splunk_hec] diff --git a/examples/profiling/docker-compose.yml b/examples/profiling/docker-compose.yml new file mode 100644 index 00000000..0abccb7b --- /dev/null +++ b/examples/profiling/docker-compose.yml @@ -0,0 +1,13 @@ +version: "3" +services: + otel-collector: + image: otel/opentelemetry-collector-contrib:0.50.0 + environment: + - SPLUNK_ACCESS_TOKEN + - SPLUNK_REALM + command: ["--config=/etc/otel-collector-config.yml"] + volumes: + - ./collector-config.yml:/etc/otel-collector-config.yml + ports: + - "9943:9943" # signalfx + - "4317:4317" # otlp diff --git a/examples/profiling/index.js b/examples/profiling/index.js new file mode 100644 index 00000000..72b4f340 --- /dev/null +++ b/examples/profiling/index.js @@ -0,0 +1,39 @@ +const { start, stop } = require('@splunk/otel'); +const { diag, DiagConsoleLogger, DiagLogLevel, trace, SpanStatusCode, context } = require('@opentelemetry/api'); + +// If OTEL_LOG_LEVEL env var is set, configure logger +if (process.env.OTEL_LOG_LEVEL) { + diag.setLogger(new DiagConsoleLogger(), DiagLogLevel[process.env.OTEL_LOG_LEVEL]); +} + +// Profiling is still experimental and has to be enabled explicitly +start({ + // Tracing is enabled by default and is required for profiling + profiling: { + callstackInterval: 100, + collectionDuration: 1_000, + }, +}); + +const doWork = () => { + const start = Date.now(); + while (Date.now() - start < 2000) {} +}; + +// setTimeout has to be here because profiling is currently started asyncronously to avoid blocking the runtime. +// If we didn't we'd run stop before the profiling has started in the background. +setTimeout(() => { + const tracer = trace.getTracer('splunk-otel-example-profiling'); + const span = tracer.startSpan('main'); + const spanContext = trace.setSpan(context.active(), span); + + console.log('starting spinning'); + // Span and Trace IDs are attached to the profiling samples + context.with(spanContext, doWork); + + console.log('done!'); + span.end(); + + // Stop profiling to flush the collected samples + stop(); +}, 10); diff --git a/examples/profiling/package.json b/examples/profiling/package.json new file mode 100644 index 00000000..87009e0a --- /dev/null +++ b/examples/profiling/package.json @@ -0,0 +1,13 @@ +{ + "name": "splunk-otel-example-profiling", + "private": true, + "version": "1.0.0", + "main": "index.js", + "scripts": { + "start": "node index.js" + }, + "dependencies": { + "@opentelemetry/api": "^1.1.0", + "@splunk/otel": "1.1.0" + } +} diff --git a/scripts/examples-npm-install b/scripts/examples-npm-install new file mode 100755 index 00000000..f35cb77d --- /dev/null +++ b/scripts/examples-npm-install @@ -0,0 +1,12 @@ +#!/usr/bin/env sh + +PKG=$1 +echo "Installing in all examples: $PKG" + +for d in ./examples/*/ ; do + echo "$d" + ( + cd "$d"; + npm install $PKG + ) +done diff --git a/src/profiling/OTLPProfilingExporter.ts b/src/profiling/OTLPProfilingExporter.ts index 9cf4670c..827f732b 100644 --- a/src/profiling/OTLPProfilingExporter.ts +++ b/src/profiling/OTLPProfilingExporter.ts @@ -143,6 +143,7 @@ export class OTLPProfilingExporter implements ProfilingExporter { send(profile: ProfilingData) { const { stacktraces } = profile; + diag.debug(`profiling: Exporting ${stacktraces?.length} samples`); const { callstackInterval } = this._options; const attributes = [ { @@ -191,7 +192,7 @@ export class OTLPProfilingExporter implements ProfilingExporter { }; this._client.export(payload, new grpc.Metadata(), (err: unknown) => { if (err) { - diag.error('Error exporting profiling data', err); + diag.error('profiling: Error exporting profiling data', err); } }); } diff --git a/src/profiling/index.ts b/src/profiling/index.ts index 2b35ca0e..25293efd 100644 --- a/src/profiling/index.ts +++ b/src/profiling/index.ts @@ -38,6 +38,7 @@ export { ProfilingOptions }; /* The following are wrappers around native functions to give more context to profiling samples. */ function extStopProfiling(extension: ProfilingExtension) { + diag.debug('profiling: Stopping'); return extension.stop(); } @@ -45,10 +46,12 @@ function extStartProfiling( extension: ProfilingExtension, opts: ProfilingStartOptions ) { + diag.debug('profiling: Starting'); extension.start(opts); } function extCollectSamples(extension: ProfilingExtension) { + diag.debug('profiling: Collecting samples'); return extension.collect(); } @@ -126,10 +129,11 @@ export function startProfiling(opts: Partial = {}) { export function loadExtension(): ProfilingExtension | undefined { try { + diag.debug('profiling: Starting'); return require('../native_ext').profiling; } catch (e) { diag.error( - 'Unable to load profiling extension. Profiling data will not be reported', + 'profiling: Unable to load extension. Profiling data will not be reported', e ); } diff --git a/test/examples/Dockerfile_app b/test/examples/Dockerfile_app index 51232727..2bf601c4 100644 --- a/test/examples/Dockerfile_app +++ b/test/examples/Dockerfile_app @@ -7,7 +7,13 @@ ENV TZ=UTC RUN mkdir /home/node/app WORKDIR /home/node/app -COPY --chown=node:node ["binding.gyp", "package*.json", "*.lock", "./"] +COPY --chown=node:node [ \ + "binding.gyp", \ + "package*.json", \ + "*.lock", \ + "./" \ +] +COPY --chown=node:node ["./scripts/examples-npm-install", "./scripts/examples-npm-install"] COPY --chown=node:node ["./src/native_ext", "./src/native_ext"] RUN npm install --omit peer @@ -17,10 +23,7 @@ COPY --chown=node:node ./ . # Install deps for examples FROM base as published -RUN cd examples/basic && npm install -RUN cd examples/express && npm install -RUN cd examples/log-injection && npm install -RUN cd examples/mixed && npm install +RUN ./scripts/examples-npm-install ## Project root doesn't have start script defined ## Working dir(-w) must be provided to one of the example dirs @@ -34,7 +37,4 @@ FROM published as compiled RUN npm run prebuild:current RUN npm run compile RUN mv `npm pack` /tmp/splunk-otel.tgz -RUN cd examples/basic && npm i /tmp/splunk-otel.tgz -RUN cd examples/express && npm i /tmp/splunk-otel.tgz -RUN cd examples/log-injection && npm i /tmp/splunk-otel.tgz -RUN cd examples/mixed && npm i /tmp/splunk-otel.tgz +RUN ./scripts/examples-npm-install /tmp/splunk-otel.tgz diff --git a/test/examples/profiling.override.yml b/test/examples/profiling.override.yml new file mode 100644 index 00000000..b0136801 --- /dev/null +++ b/test/examples/profiling.override.yml @@ -0,0 +1,8 @@ +services: + app: + working_dir: /home/node/app/examples/profiling + env_file: ./profiling/app.env + test: + command: node ./profiling + environment: + COLLECTOR_URL: http://collector:8378 diff --git a/test/examples/profiling/app.env b/test/examples/profiling/app.env new file mode 100644 index 00000000..0dfe2daf --- /dev/null +++ b/test/examples/profiling/app.env @@ -0,0 +1,4 @@ +OTEL_SERVICE_NAME='profiling-example' +OTEL_RESOURCE_ATTRIBUTES='deployment.environment=dev' +OTEL_LOG_LEVEL='DEBUG' +OTEL_EXPORTER_OTLP_ENDPOINT=collector:4317 diff --git a/test/examples/profiling/index.js b/test/examples/profiling/index.js new file mode 100644 index 00000000..05befd07 --- /dev/null +++ b/test/examples/profiling/index.js @@ -0,0 +1,14 @@ +const { + assertSpans, + logSpanTable, + request, + waitSpans, +} = require('../utils.js'); +const snapshot = require('./snapshot.js'); + +waitSpans(snapshot.length).then((data) => { + logSpanTable(data); + return assertSpans(data, snapshot); +}).then((validatedSpans) => { + console.log(`${validatedSpans} spans validated.`); +}); diff --git a/test/examples/profiling/snapshot.js b/test/examples/profiling/snapshot.js new file mode 100644 index 00000000..a2ded860 --- /dev/null +++ b/test/examples/profiling/snapshot.js @@ -0,0 +1,18 @@ +// a console.log from a previous run +module.exports = [ + { + traceId: 'SugyaoARxWUXXGW7OE6nXg==', + id: 'B4g4YngKBnM=', + startTime: '2022-06-03T13:04:28.087011840Z', + name: 'main', + kind: 'internal', + parentSpanId: undefined, + parent: undefined, + references: undefined, + status: { code: undefined }, + attributes: { + 'otel.library.name': 'splunk-otel-example-profiling', + 'span.kind': 'internal' + } + } +];