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

@@ -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

examples/profiling/.dockerignore

@@ -0,0 +1,2 @@
+node_modules
+package-lock.json

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="<realm>"
+export SPLUNK_ACCESS_TOKEN="<your 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.

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]

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

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);

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"
+  }
+}

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

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);
       }
     });
   }

src/profiling/index.ts

@@ -38,17 +38,20 @@ 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();
 }
 
 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<ProfilingOptions> = {}) {
 
 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
     );
   }

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

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

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

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.`);
+});

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'
+    }
+  }
+];