fix(plugin-ioredis): end span on response from the server and set span status according to response (open-telemetry#239)

* feat(plugin-ioredis): enahnce response handling

- fix: end span on response from server, so duration accurately include the server processing
    and networking time
- fix: set span status to error if server response with error
- feat: add responseHook to plugin config so user can register hook to add custom attributes to
    span when successful response arrive from server

* fix: add forgotten changes

* style: fix lint

* chore: remove reponseHook from PR

* fix: remove unused import for build to pass

* chore: lint

* style: set span error with ternary

* style: fix lint

* style: fix lint

* chore: fix lint

* revert: lint change to graphql file

* test(plugin-ioredis): make new test compatible with v0.15.0

* fix(plugin-ioredis): recordException on span when server returns error

* fix: correct type for events in assertSpan

Author: Amir Blum

packages/opentelemetry-test-utils/testUtils.ts

@@ -15,7 +15,13 @@
  */
 
 import * as childProcess from 'child_process';
-import { SpanKind, Attributes, Event, Span, Status } from '@opentelemetry/api';
+import {
+  SpanKind,
+  Attributes,
+  Span,
+  Status,
+  TimedEvent,
+} from '@opentelemetry/api';
 import * as assert from 'assert';
 import { ReadableSpan } from '@opentelemetry/tracing';
 import {
@@ -78,7 +84,7 @@ export const assertSpan = (
   span: ReadableSpan,
   kind: SpanKind,
   attributes: Attributes,
-  events: Event[],
+  events: TimedEvent[],
   status: Status
 ) => {
   assert.strictEqual(span.spanContext.traceId.length, 32);

plugins/node/opentelemetry-plugin-ioredis/src/utils.ts

@@ -36,6 +36,7 @@ import {
 
 const endSpan = (span: Span, err: NodeJS.ErrnoException | null | undefined) => {
   if (err) {
+    span.recordException(err);
     span.setStatus({
       code: StatusCode.ERROR,
       message: err.message,
@@ -116,7 +117,20 @@ export const traceSendCommand = (
 
     try {
       const result = original.apply(this, arguments);
-      endSpan(span, null);
+
+      const origResolve = cmd.resolve;
+      /* eslint-disable @typescript-eslint/no-explicit-any */
+      cmd.resolve = function (result: any) {
+        endSpan(span, null);
+        origResolve(result);
+      };
+
+      const origReject = cmd.reject;
+      cmd.reject = function (err: Error) {
+        endSpan(span, err);
+        origReject(err);
+      };
+
       return result;
     } catch (error) {
       endSpan(span, error);

plugins/node/opentelemetry-plugin-ioredis/test/ioredis.test.ts

@@ -28,6 +28,7 @@ import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks';
 import * as testUtils from '@opentelemetry/test-utils';
 import {
   InMemorySpanExporter,
+  ReadableSpan,
   SimpleSpanProcessor,
 } from '@opentelemetry/tracing';
 import * as assert from 'assert';
@@ -36,6 +37,7 @@ import { IORedisPlugin, plugin } from '../src';
 import { IoredisPluginConfig, DbStatementSerializer } from '../src/types';
 import {
   DatabaseAttribute,
+  ExceptionAttribute,
   GeneralAttribute,
 } from '@opentelemetry/semantic-conventions';
 
@@ -59,6 +61,20 @@ const unsetStatus: Status = {
   code: StatusCode.UNSET,
 };
 
+const predictableStackTrace =
+  '-- Stack trace replaced by test to predictable value -- ';
+const sanitizeEventForAssertion = (span: ReadableSpan) => {
+  span.events.forEach(e => {
+    // stack trace includes data such as /user/{userName}/repos/{projectName}
+    if (e.attributes?.[ExceptionAttribute.STACKTRACE]) {
+      e.attributes[ExceptionAttribute.STACKTRACE] = predictableStackTrace;
+    }
+
+    // since time will change on each test invocation, it is being replaced to predicable value
+    e.time = [0, 0];
+  });
+};
+
 describe('ioredis', () => {
   const provider = new NodeTracerProvider();
   let ioredis: typeof ioredisTypes;
@@ -131,9 +147,11 @@ describe('ioredis', () => {
         assert.strictEqual(endedSpans.length, 3);
         assert.strictEqual(endedSpans[2].name, 'test span');
 
-        client.quit(done);
-        assert.strictEqual(endedSpans.length, 4);
-        assert.strictEqual(endedSpans[3].name, 'quit');
+        client.quit(() => {
+          assert.strictEqual(endedSpans.length, 4);
+          assert.strictEqual(endedSpans[3].name, 'quit');
+          done();
+        });
       };
       const errorHandler = (err: Error) => {
         assert.ifError(err);
@@ -263,6 +281,38 @@ describe('ioredis', () => {
         });
       });
 
+      it('should set span with error when redis return reject', async () => {
+        const span = provider.getTracer('ioredis-test').startSpan('test span');
+        await context.with(setSpan(context.active(), span), async () => {
+          await client.set('non-int-key', 'non-int-value');
+          try {
+            // should throw 'ReplyError: ERR value is not an integer or out of range'
+            // because the value im the key is not numeric and we try to increment it
+            await client.incr('non-int-key');
+          } catch (ex) {
+            const endedSpans = memoryExporter.getFinishedSpans();
+            assert.strictEqual(endedSpans.length, 2);
+            const ioredisSpan = endedSpans[1];
+            // redis 'incr' operation failed with exception, so span should indicate it
+            assert.strictEqual(ioredisSpan.status.code, StatusCode.ERROR);
+            const exceptionEvent = ioredisSpan.events[0];
+            assert.strictEqual(exceptionEvent.name, 'exception');
+            assert.strictEqual(
+              exceptionEvent.attributes?.[ExceptionAttribute.MESSAGE],
+              ex.message
+            );
+            assert.strictEqual(
+              exceptionEvent.attributes?.[ExceptionAttribute.STACKTRACE],
+              ex.stack
+            );
+            assert.strictEqual(
+              exceptionEvent.attributes?.[ExceptionAttribute.TYPE],
+              ex.name
+            );
+          }
+        });
+      });
+
       it('should create a child span for streamify scanning', done => {
         const attributes = {
           ...DEFAULT_ATTRIBUTES,
@@ -322,10 +372,10 @@ describe('ioredis', () => {
             const spanNames = [
               'connect',
               'connect',
-              'subscribe',
               'info',
               'info',
               'subscribe',
+              'subscribe',
               'publish',
               'publish',
               'unsubscribe',
@@ -377,24 +427,48 @@ describe('ioredis', () => {
 
             span.end();
             const endedSpans = memoryExporter.getFinishedSpans();
+            const evalshaSpan = endedSpans[0];
             // the script may be already cached on server therefore we get either 2 or 3 spans
             if (endedSpans.length === 3) {
               assert.strictEqual(endedSpans[2].name, 'test span');
               assert.strictEqual(endedSpans[1].name, 'eval');
               assert.strictEqual(endedSpans[0].name, 'evalsha');
+              // in this case, server returns NOSCRIPT error for evalsha,
+              // telling the client to use EVAL instead
+              sanitizeEventForAssertion(evalshaSpan);
+              testUtils.assertSpan(
+                evalshaSpan,
+                SpanKind.CLIENT,
+                attributes,
+                [
+                  {
+                    attributes: {
+                      [ExceptionAttribute.MESSAGE]:
+                        'NOSCRIPT No matching script. Please use EVAL.',
+                      [ExceptionAttribute.STACKTRACE]: predictableStackTrace,
+                      [ExceptionAttribute.TYPE]: 'ReplyError',
+                    },
+                    name: 'exception',
+                    time: [0, 0],
+                  },
+                ],
+                {
+                  code: StatusCode.ERROR,
+                }
+              );
             } else {
               assert.strictEqual(endedSpans.length, 2);
               assert.strictEqual(endedSpans[1].name, 'test span');
               assert.strictEqual(endedSpans[0].name, 'evalsha');
+              testUtils.assertSpan(
+                evalshaSpan,
+                SpanKind.CLIENT,
+                attributes,
+                [],
+                unsetStatus
+              );
             }
-            testUtils.assertSpan(
-              endedSpans[0],
-              SpanKind.CLIENT,
-              attributes,
-              [],
-              unsetStatus
-            );
-            testUtils.assertPropagation(endedSpans[0], span);
+            testUtils.assertPropagation(evalshaSpan, span);
             done();
           });
         });