Merge pull request #41 from michaelyeager-wf/myeager-wf/O11Y-1504

O11Y-1504: wo11y-dart tracer.trace spans don't end until the parent span ends
Workiva · Mar 11, 2022 · 1bfafc2 · 1bfafc2
2 parents 5547da5 + f482ad1
commit 1bfafc2
Show file tree

Hide file tree

Showing 9 changed files with 216 additions and 22 deletions.
diff --git a/lib/src/api/context/context.dart b/lib/src/api/context/context.dart
@@ -9,7 +9,7 @@
 /// requirements of immutability and being able to read and write values:
 ///
 /// - Immutable: a Zone's values are set when the Zone is created and cannot be
-/// changed aftewards.
+/// changed afterwards.
 /// - Reading and writing values: a Zone implements the `[]` operator, allowing
 /// values to be read directly from it like a [Map], and writing values is
 /// possible only by forking another Zone and providing values to add/override

diff --git a/lib/src/api/trace/nonrecording_span.dart b/lib/src/api/trace/nonrecording_span.dart
@@ -60,4 +60,7 @@ class NonRecordingSpan implements api.Span {
 
   @override
   api.InstrumentationLibrary get instrumentationLibrary => null;
+
+  @override
+  void recordException(dynamic exception, {StackTrace stackTrace}) {}
 }
diff --git a/lib/src/api/trace/noop_tracer.dart b/lib/src/api/trace/noop_tracer.dart
@@ -1,3 +1,5 @@
+import 'dart:async';
+
 import '../../../api.dart' as api;
 import '../../../sdk.dart' as sdk;
 
@@ -12,4 +14,10 @@ class NoopTracer implements api.Tracer {
     return api.NonRecordingSpan(
         (parentContext.isValid) ? parentContext : sdk.SpanContext.invalid());
   }
+
+  @override
+  FutureOr<R> trace<R>(String name, FutureOr<R> Function() fn,
+      {api.Context context}) async {
+    return await (context ?? api.Context.current).execute(fn);
+  }
 }
diff --git a/lib/src/api/trace/span.dart b/lib/src/api/trace/span.dart
@@ -50,12 +50,15 @@ abstract class Span {
   /// Retrieve metadata included on this span.
   api.Attributes get attributes;
 
-  // Retrieve the resource on this span.
+  /// Retrieve the resource on this span.
   api.Resource get resource;
 
-  // Retrieve the instrumentation library on this span.
+  /// Retrieve the instrumentation library on this span.
   api.InstrumentationLibrary get instrumentationLibrary;
 
   /// Marks the end of this span's execution.
   void end();
+
+  /// Record metadata about an exception occurring during this span.
+  void recordException(dynamic exception, {StackTrace stackTrace});
 }
diff --git a/lib/src/api/trace/tracer.dart b/lib/src/api/trace/tracer.dart
@@ -1,3 +1,5 @@
+import 'dart:async';
+
 import '../../../api.dart' as api;
 
 /// An interface for creating [api.Span]s and propagating context in-process.
@@ -9,4 +11,9 @@ abstract class Tracer {
   /// tracer's context.
   api.Span startSpan(String name,
       {api.Context context, api.Attributes attributes});
+
+  /// Records a span of the given [name] for the given function
+  /// and marks the span as errored if an exception occurs.
+  FutureOr<R> trace<R>(String name, FutureOr<R> Function() fn,
+      {api.Context context});
 }
diff --git a/lib/src/sdk/trace/span.dart b/lib/src/sdk/trace/span.dart
@@ -78,4 +78,15 @@ class Span implements api.Span {
 
   @override
   api.Attributes attributes;
+
+  @override
+  void recordException(dynamic exception, {StackTrace stackTrace}) {
+    // TODO: O11Y-1531: Consider integration of Events here.
+    setStatus(api.StatusCode.error, description: exception.toString());
+    attributes.addAll([
+      api.Attribute.fromBoolean('error', true),
+      api.Attribute.fromString('exception', exception.toString()),
+      api.Attribute.fromString('stacktrace', stackTrace.toString()),
+    ]);
+  }
 }
diff --git a/lib/src/sdk/trace/tracer.dart b/lib/src/sdk/trace/tracer.dart
@@ -53,27 +53,27 @@ class Tracer implements api.Tracer {
         attributes: attributes);
   }
 
-  /// Records a span of the given [name] for the given function and marks the
-  /// span as errored if an exception occurs.
+  /// Records a span of the given [name] for the given function
+  /// and marks the span as errored if an exception occurs.
+  @override
   FutureOr<R> trace<R>(String name, FutureOr<R> Function() fn,
-      {api.Context context}) {
-    final operationContext = context ?? api.Context.current;
+      {api.Context context}) async {
+    context ??= api.Context.current;
+    final span = startSpan(name, context: context);
 
-    return operationContext.execute(() async {
-      final span = startSpan(name, context: operationContext);
-      try {
-        return await operationContext.withSpan(span).execute(fn);
-      } catch (e, s) {
-        span.setStatus(api.StatusCode.error, description: e.toString());
-        span.attributes.addAll([
-          api.Attribute.fromBoolean('error', true),
-          api.Attribute.fromString('exception', e.toString()),
-          api.Attribute.fromString('stacktrace', s.toString()),
-        ]);
-        rethrow;
-      } finally {
-        span.end();
+    try {
+      var result = context.withSpan(span).execute(fn);
+      if (result is Future) {
+        // Operation must be awaited here to ensure the catch block intercepts
+        // errors thrown by [fn].
+        result = await result;
       }
-    });
+      return result;
+    } catch (e, s) {
+      span.recordException(e, stackTrace: s);
+      rethrow;
+    } finally {
+      span.end();
+    }
   }
 }
diff --git a/test/integration/sdk/span_test.dart b/test/integration/sdk/span_test.dart
@@ -125,4 +125,26 @@ void main() {
       expect(span.attributes.get(key), equals(value));
     });
   });
+
+  test('span record error', () {
+    final span = sdk.Span(
+        'foo',
+        sdk.SpanContext(api.TraceId([1, 2, 3]), api.SpanId([7, 8, 9]),
+            api.TraceFlags.none, sdk.TraceState.empty()),
+        api.SpanId([4, 5, 6]),
+        [],
+        sdk.Resource(api.Attributes.empty()),
+        sdk.InstrumentationLibrary('library_name', 'library_version'));
+
+    try {
+      throw Exception('Oh noes!');
+    } catch (e, s) {
+      span.recordException(e, stackTrace: s);
+    }
+
+    expect(span.status.code, equals(api.StatusCode.error));
+    expect(span.status.description, equals('Exception: Oh noes!'));
+    expect(span.attributes.get('error'), isTrue);
+    expect(span.attributes.get('exception'), equals('Exception: Oh noes!'));
+  });
 }
diff --git a/test/integration/sdk/tracer_test.dart b/test/integration/sdk/tracer_test.dart
@@ -1,3 +1,5 @@
+import 'dart:async';
+
 import 'package:opentelemetry/api.dart' as api;
 import 'package:opentelemetry/sdk.dart' as sdk;
 import 'package:test/test.dart';
@@ -39,4 +41,142 @@ void main() {
     expect(childSpan.spanContext.spanId,
         allOf([isNotNull, isNot(equals(parentSpan.spanContext.spanId))]));
   });
+
+  test('trace synchronous execution', () {
+    final tracer = sdk.Tracer([],
+        sdk.Resource(api.Attributes.empty()),
+        sdk.AlwaysOnSampler(),
+        sdk.IdGenerator(),
+        sdk.InstrumentationLibrary('name', 'version'));
+    sdk.Span span;
+
+    tracer.trace('syncTrace', () {
+      span = api.Context.current.span;
+    });
+
+    expect(span.endTime, lessThan(DateTime.now().microsecondsSinceEpoch));
+  });
+
+  test('trace synchronous looped execution timing', () {
+    final tracer = sdk.Tracer([],
+        sdk.Resource(api.Attributes.empty()),
+        sdk.AlwaysOnSampler(),
+        sdk.IdGenerator(),
+        sdk.InstrumentationLibrary('name', 'version'));
+    final spans = <sdk.Span>[];
+
+    for (var i = 0; i < 5; i++) {
+      tracer.trace('syncTrace', () {
+        spans.add(api.Context.current.span);
+      });
+    }
+
+    for (var i = 1; i < spans.length; i++) {
+      expect(spans[i].startTime, greaterThan(spans[i - 1].startTime));
+      expect(spans[i].endTime, greaterThan(spans[i - 1].endTime));
+    }
+  });
+
+  test('trace synchronous execution with error', () {
+    final tracer = sdk.Tracer([],
+        sdk.Resource(api.Attributes.empty()),
+        sdk.AlwaysOnSampler(),
+        sdk.IdGenerator(),
+        sdk.InstrumentationLibrary('name', 'version'));
+    sdk.Span span;
+
+    expect(
+        () => tracer.trace('syncTrace', () {
+              span = api.Context.current.span;
+              throw Exception('Oh noes!');
+            }),
+        throwsException);
+    expect(span.endTime, isNotNull);
+    expect(span.status.code, equals(api.StatusCode.error));
+    expect(span.status.description, equals('Exception: Oh noes!'));
+    expect(span.attributes.get('error'), isTrue);
+    expect(span.attributes.get('exception'), equals('Exception: Oh noes!'));
+  });
+
+  test('trace asynchronous execution', () async {
+    final tracer = sdk.Tracer([],
+        sdk.Resource(api.Attributes.empty()),
+        sdk.AlwaysOnSampler(),
+        sdk.IdGenerator(),
+        sdk.InstrumentationLibrary('name', 'version'));
+    sdk.Span span;
+
+    await tracer.trace('asyncTrace', () async {
+      span = api.Context.current.span;
+    });
+
+    expect(span.endTime, lessThan(DateTime.now().microsecondsSinceEpoch));
+  });
+
+  test('trace asynchronous looped execution timing', () async {
+    final tracer = sdk.Tracer([],
+        sdk.Resource(api.Attributes.empty()),
+        sdk.AlwaysOnSampler(),
+        sdk.IdGenerator(),
+        sdk.InstrumentationLibrary('name', 'version'));
+    final spans = <sdk.Span>[];
+
+    for (var i = 0; i < 5; i++) {
+      await tracer.trace('asyncTrace', () async {
+        spans.add(api.Context.current.span);
+      });
+    }
+
+    for (var i = 1; i < spans.length; i++) {
+      expect(spans[i].startTime, greaterThan(spans[i - 1].startTime));
+      expect(spans[i].endTime, greaterThan(spans[i - 1].endTime));
+    }
+  });
+
+  test('trace asynchronous execution with thrown error', () async {
+    final tracer = sdk.Tracer([],
+        sdk.Resource(api.Attributes.empty()),
+        sdk.AlwaysOnSampler(),
+        sdk.IdGenerator(),
+        sdk.InstrumentationLibrary('name', 'version'));
+    sdk.Span span;
+
+    try {
+      await tracer.trace('asyncTrace', () async {
+        span = api.Context.current.span;
+        throw Exception('Oh noes!');
+      });
+    } catch (e) {
+      expect(e.toString(), equals('Exception: Oh noes!'));
+    }
+    expect(span.endTime, isNotNull);
+    expect(span.status.code, equals(api.StatusCode.error));
+    expect(span.status.description, equals('Exception: Oh noes!'));
+    expect(span.attributes.get('error'), isTrue);
+    expect(span.attributes.get('exception'), equals('Exception: Oh noes!'));
+  });
+
+  test('trace asynchronous execution completes with error', () async {
+    final tracer = sdk.Tracer([],
+        sdk.Resource(api.Attributes.empty()),
+        sdk.AlwaysOnSampler(),
+        sdk.IdGenerator(),
+        sdk.InstrumentationLibrary('name', 'version'));
+    sdk.Span span;
+
+    try {
+      await tracer.trace('asyncTrace', () async {
+        span = api.Context.current.span;
+        return Future.error(Exception('Oh noes!'));
+      });
+    } catch (e) {
+      expect(e.toString(), equals('Exception: Oh noes!'));
+    }
+
+    expect(span.endTime, isNotNull);
+    expect(span.status.code, equals(api.StatusCode.error));
+    expect(span.status.description, equals('Exception: Oh noes!'));
+    expect(span.attributes.get('error'), isTrue);
+    expect(span.attributes.get('exception'), equals('Exception: Oh noes!'));
+  });
 }