From 3ddcf3109f22b28cd5f7940dfb47383b79e79e68 Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Thu, 12 Jul 2018 14:36:20 -0600 Subject: [PATCH 01/14] add traces to basic transitions --- lib/src/lifecycle_module.dart | 30 +++++++++++++++++++++++++++++- pubspec.yaml | 1 + 2 files changed, 30 insertions(+), 1 deletion(-) diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index 06168806..5df992fa 100644 --- a/lib/src/lifecycle_module.dart +++ b/lib/src/lifecycle_module.dart @@ -18,6 +18,7 @@ import 'dart:async'; import 'package:logging/logging.dart'; import 'package:meta/meta.dart' show mustCallSuper, protected, required; +import 'package:opentracing/opentracing.dart'; import 'package:w_common/disposable.dart'; import 'package:w_module/src/simple_module.dart'; @@ -58,6 +59,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { LifecycleState _previousState; LifecycleState _state = LifecycleState.instantiated; Completer _transition; + Span _span; // Lifecycle event StreamControllers StreamController _willLoadChildModuleController = @@ -127,6 +129,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable { }.forEach(_logLifecycleEvents); } + /// If this module is in a transition state, this is the Span capturing the + /// transition state. + Span get activeSpan => _span; + /// Name of the module for identification in exceptions and debug messages. // ignore: unnecessary_getters_setters String get name => _name ?? 'LifecycleModule($runtimeType)'; @@ -320,6 +326,9 @@ abstract class LifecycleModule extends SimpleModule with Disposable { reason: 'A module can only be loaded once.'); } + // TODO childOf or followsFrom + _span = globalTracer()?.startSpan('load($name)'); + _state = LifecycleState.loading; // Keep track of this load's completer @@ -330,6 +339,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable { _load().then(transition.complete).catchError((error, trace) { transition.completeError(error, trace); + _span?.setTag('error', true); + }).whenComplete(() { + _span?.finish(); + _span = null; }); return transition.future; @@ -462,6 +475,8 @@ abstract class LifecycleModule extends SimpleModule with Disposable { ]); } + _span = globalTracer()?.startSpan('suspend($name)'); + Future pendingTransition; if (_transition != null && !_transition.isCompleted) { pendingTransition = _transition.future; @@ -475,7 +490,12 @@ abstract class LifecycleModule extends SimpleModule with Disposable { .then(transition.complete) .catchError((error, trace) { transition.completeError(error, trace); + _span?.setTag('error', true); + }).whenComplete(() { + _span?.finish(); + _span = null; }); + return transition.future; } @@ -525,6 +545,8 @@ abstract class LifecycleModule extends SimpleModule with Disposable { pendingTransition = _transition.future; } + _span = globalTracer()?.startSpan('resume($name)'); + _state = LifecycleState.resuming; final transition = new Completer(); _transition = transition; @@ -533,6 +555,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable { .then(transition.complete) .catchError((error, trace) { transition.completeError(error, trace); + _span?.setTag('error', true); + }).whenComplete(() { + _span?.finish(); + _span = null; }); return _transition.future; @@ -618,6 +644,8 @@ abstract class LifecycleModule extends SimpleModule with Disposable { ]); } + _span = globalTracer()?.startSpan('unload($name)'); + Future pendingTransition; if (_transition != null && !_transition.isCompleted) { pendingTransition = _transition.future; @@ -631,7 +659,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { var unloadAndDispose = new Completer(); unloadAndDispose.complete(transition.future.then((_) => dispose())); transition.complete(_unload(pendingTransition)); - return unloadAndDispose.future; + return unloadAndDispose.future.whenComplete(_span?.finish); } //-------------------------------------------------------- diff --git a/pubspec.yaml b/pubspec.yaml index 0e1c55e7..07af98c3 100644 --- a/pubspec.yaml +++ b/pubspec.yaml @@ -23,6 +23,7 @@ dev_dependencies: dart_style: ^0.2.16 dartdoc: ^0.9.0 mockito: ^1.0.1 + opentracing: ^0.2.1 react: ^3.0.0 test: ^0.12.0 w_flux: '>=1.0.0 <3.0.0' From cabbdf602f5498cf8e4db1819074055eef19b1a7 Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Thu, 12 Jul 2018 14:54:05 -0600 Subject: [PATCH 02/14] track childOf for child modules --- lib/src/lifecycle_module.dart | 54 ++++++++++++++++++++++++++++++----- 1 file changed, 47 insertions(+), 7 deletions(-) diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index 5df992fa..a9e0e5c7 100644 --- a/lib/src/lifecycle_module.dart +++ b/lib/src/lifecycle_module.dart @@ -133,6 +133,27 @@ abstract class LifecycleModule extends SimpleModule with Disposable { /// transition state. Span get activeSpan => _span; + /// Set internally by the parent module if this module is called by [loadChildModule] + SpanContext _childOfContext; + + /// Builds a span that conditionally applies a childOf reference if this module + /// was loaded by a parent module. + /// + /// Returns `null` if no globalTracer is configured. + Span _startTransitionSpan(String operationName) { + final tracer = globalTracer(); + if (tracer == null) { + return null; + } + + List references = []; + if (_childOfContext != null) { + references.add(new Reference.childOf(_childOfContext)); + } + + return tracer.startSpan(operationName, references: references); + } + /// Name of the module for identification in exceptions and debug messages. // ignore: unnecessary_getters_setters String get name => _name ?? 'LifecycleModule($runtimeType)'; @@ -327,7 +348,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { } // TODO childOf or followsFrom - _span = globalTracer()?.startSpan('load($name)'); + _span = _startTransitionSpan('load($name)'); _state = LifecycleState.loading; @@ -405,6 +426,8 @@ abstract class LifecycleModule extends SimpleModule with Disposable { try { _childModules.add(childModule); + childModule._childOfContext = _span?.context; + await childModule.load(); await onDidLoadChildModule(childModule); _didLoadChildModuleController.add(childModule); @@ -419,6 +442,8 @@ abstract class LifecycleModule extends SimpleModule with Disposable { _didLoadChildModuleController.addError(error, stackTrace); completer.completeError(error, stackTrace); + } finally { + childModule._childOfContext = null; } }).catchError((Object error, StackTrace stackTrace) { _willLoadChildModuleController.addError(error, stackTrace); @@ -475,7 +500,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { ]); } - _span = globalTracer()?.startSpan('suspend($name)'); + _span = _startTransitionSpan('suspend($name)'); Future pendingTransition; if (_transition != null && !_transition.isCompleted) { @@ -545,7 +570,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { pendingTransition = _transition.future; } - _span = globalTracer()?.startSpan('resume($name)'); + _span = _startTransitionSpan('resume($name)'); _state = LifecycleState.resuming; final transition = new Completer(); @@ -644,7 +669,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { ]); } - _span = globalTracer()?.startSpan('unload($name)'); + _span = _startTransitionSpan('unload($name)'); Future pendingTransition; if (_transition != null && !_transition.isCompleted) { @@ -854,7 +879,12 @@ abstract class LifecycleModule extends SimpleModule with Disposable { _willResumeController.add(this); List> childResumeFutures = >[]; for (var child in _childModules.toList()) { - childResumeFutures.add(child.resume()); + childResumeFutures.add(new Future(() { + child._childOfContext = _span?.context; + return child.resume().whenComplete(() { + child._childOfContext = null; + }); + })); } await Future.wait(childResumeFutures); await onResume(); @@ -877,7 +907,12 @@ abstract class LifecycleModule extends SimpleModule with Disposable { _willSuspendController.add(this); List> childSuspendFutures = >[]; for (var child in _childModules.toList()) { - childSuspendFutures.add(child.suspend()); + childSuspendFutures.add(new Future(() async { + child._childOfContext = _span?.context; + return child.suspend().whenComplete(() { + child._childOfContext = null; + }); + })); } await Future.wait(childSuspendFutures); await onSuspend(); @@ -908,7 +943,12 @@ abstract class LifecycleModule extends SimpleModule with Disposable { shouldUnloadResult.messagesAsString()); } _willUnloadController.add(this); - await Future.wait(_childModules.toList().map((child) => child.unload())); + await Future.wait(_childModules.toList().map((child) { + child._childOfContext = _span?.context; + return child.unload().whenComplete(() { + child._childOfContext = null; + }); + })); await onUnload(); if (_state == LifecycleState.unloading) { _state = LifecycleState.unloaded; From 680c8f3ae5e5ef0b5fca6c3d51c83e3c631afc75 Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Thu, 12 Jul 2018 15:10:02 -0600 Subject: [PATCH 03/14] make opentracing a real dep --- pubspec.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pubspec.yaml b/pubspec.yaml index 07af98c3..d45c1929 100644 --- a/pubspec.yaml +++ b/pubspec.yaml @@ -14,6 +14,7 @@ dependencies: logging: ^0.11.0 meta: ^1.0.0 platform_detect: ^1.1.0 + opentracing: ^0.2.1 w_common: ^1.9.0 dev_dependencies: @@ -23,7 +24,6 @@ dev_dependencies: dart_style: ^0.2.16 dartdoc: ^0.9.0 mockito: ^1.0.1 - opentracing: ^0.2.1 react: ^3.0.0 test: ^0.12.0 w_flux: '>=1.0.0 <3.0.0' From 4f98cebe3082a939d741c809f2b49506082cbf50 Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Tue, 31 Jul 2018 09:04:38 -0600 Subject: [PATCH 04/14] example --- example/panel/modules/sample_tracer.dart | 162 +++++++++++++++++++++++ example/panel/panel_app.dart | 6 + 2 files changed, 168 insertions(+) create mode 100644 example/panel/modules/sample_tracer.dart diff --git a/example/panel/modules/sample_tracer.dart b/example/panel/modules/sample_tracer.dart new file mode 100644 index 00000000..c636944e --- /dev/null +++ b/example/panel/modules/sample_tracer.dart @@ -0,0 +1,162 @@ +import 'dart:async'; +import 'package:opentracing/opentracing.dart'; + +class SampleSpan implements Span { + static int _nextId = 0; + final int _id = _nextId++; + + @override + final List references; + + @override + final Map tags; + + @override + final List logData = []; + + @override + final String operationName; + + @override + SpanContext context; + + @override + final DateTime startTime; + DateTime _endTime; + + Completer _whenFinished = new Completer(); + + SampleSpan( + this.operationName, { + SpanContext childOf, + this.references, + DateTime startTime, + Map tags, + }) + : this.startTime = startTime ?? new DateTime.now(), + this.tags = tags ?? {} { + if (childOf != null) { + references.add(new Reference.childOf(childOf)); + } + setTag('span.kind', 'client'); + + final parent = parentContext; + if (parent != null) { + this.context = new SpanContext(spanId: _id, traceId: parent.traceId); + this.context.baggage.addAll(parent.baggage); + } else { + this.context = new SpanContext(spanId: _id, traceId: _id); + } + } + + @override + void addTags(Map newTags) => tags.addAll(newTags); + + @override + Duration get duration => _endTime?.difference(startTime); + + @override + DateTime get endTime => _endTime; + + @override + void finish({DateTime finishTime}) { + if (_whenFinished == null) { + return; + } + + _endTime = finishTime ?? new DateTime.now(); + _whenFinished.complete(this); + _whenFinished = null; + } + + @override + void log(String event, {dynamic payload, DateTime timestamp}) => + logData.add(new LogData(timestamp ?? new DateTime.now(), event, payload)); + + @override + SpanContext get parentContext => + references.isEmpty ? null : references.first.referencedContext; + + @override + void setTag(String tagName, dynamic value) => tags[tagName] = value; + + @override + Future get whenFinished => _whenFinished.future; + + @override + String toString() { + final sb = new StringBuffer('SampleSpan('); + sb + ..writeln('traceId: ${context.traceId}') + ..writeln('spanId: ${context.spanId}') + ..writeln('operationName: $operationName') + ..writeln('tags: ${tags.toString()}') + ..writeln('startTime: ${startTime.toString()}'); + + if (_endTime != null) { + sb + ..writeln('endTime: ${endTime.toString()}') + ..writeln('duration: ${duration.toString()}'); + } + + if (logData.isNotEmpty) { + sb.writeln('logData: ${logData.toString()}'); + } + + if (references.isNotEmpty) { + final reference = references.first; + sb.writeln( + 'reference: ${reference.referenceType} ${reference.referencedContext.spanId}'); + } + + sb.writeln(')'); + + return sb.toString(); + } +} + +class SampleTracer implements AbstractTracer { + @override + SampleSpan startSpan( + String operationName, { + SpanContext childOf, + List references, + DateTime startTime, + Map tags, + }) { + return new SampleSpan( + operationName, + childOf: childOf, + references: references, + startTime: startTime, + tags: tags, + ) + ..whenFinished.then((span) { + print(span.toString()); + }); + } + + @override + Reference childOf(SpanContext context) => new Reference.childOf(context); + + @override + Reference followsFrom(SpanContext context) => + new Reference.followsFrom(context); + + @override + SpanContext extract(String format, dynamic carrier) { + throw new UnimplementedError( + 'Sample tracer for example purposes does not support advanced tracing behavior.'); + } + + @override + void inject(SpanContext spanContext, String format, dynamic carrier) { + throw new UnimplementedError( + 'Sample tracer for example purposes does not support advanced tracing behavior.'); + } + + @override + Future flush() { + return null; + } +} diff --git a/example/panel/panel_app.dart b/example/panel/panel_app.dart index f092bcc2..df84df5c 100644 --- a/example/panel/panel_app.dart +++ b/example/panel/panel_app.dart @@ -22,13 +22,19 @@ import 'package:platform_detect/platform_detect.dart'; import 'package:react/react_dom.dart' as react_dom; import 'package:react/react_client.dart' as react_client; import 'package:w_module/w_module.dart' hide Event; +import 'package:opentracing/opentracing.dart'; import 'modules/panel_module.dart'; +import 'modules/sample_tracer.dart'; Future main() async { Element container = querySelector('#panel-container'); react_client.setClientConfiguration(); + final tracer = new SampleTracer(); + initGlobalTracer(tracer); + assert(globalTracer() == tracer); + // instantiate the core app module and wait for it to complete loading PanelModule panelModule = new PanelModule(); await panelModule.load(); From 40b58efd1e7ddd6d6cf510b5177073987c2db8b1 Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Tue, 31 Jul 2018 09:52:02 -0600 Subject: [PATCH 05/14] remove todo --- lib/src/lifecycle_module.dart | 1 - 1 file changed, 1 deletion(-) diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index a9e0e5c7..3c05dab4 100644 --- a/lib/src/lifecycle_module.dart +++ b/lib/src/lifecycle_module.dart @@ -347,7 +347,6 @@ abstract class LifecycleModule extends SimpleModule with Disposable { reason: 'A module can only be loaded once.'); } - // TODO childOf or followsFrom _span = _startTransitionSpan('load($name)'); _state = LifecycleState.loading; From e3e97347df4aadb65d66ae935d60f580b5d3686d Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Tue, 31 Jul 2018 10:09:34 -0600 Subject: [PATCH 06/14] make span names more generic and use span tags for module names --- lib/src/lifecycle_module.dart | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index 3c05dab4..12d2d75f 100644 --- a/lib/src/lifecycle_module.dart +++ b/lib/src/lifecycle_module.dart @@ -53,6 +53,10 @@ enum LifecycleState { /// Intended to be extended by most base module classes in order to provide a /// unified lifecycle API. abstract class LifecycleModule extends SimpleModule with Disposable { + static int _nextId = 0; + + int _instanceId = _nextId++; + List _childModules = []; Logger _logger; String _name; @@ -151,7 +155,11 @@ abstract class LifecycleModule extends SimpleModule with Disposable { references.add(new Reference.childOf(_childOfContext)); } - return tracer.startSpan(operationName, references: references); + return tracer.startSpan(operationName, references: references) + ..addTags({ + 'module.name': name, + 'module.instanceId': _instanceId, + }); } /// Name of the module for identification in exceptions and debug messages. @@ -347,7 +355,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { reason: 'A module can only be loaded once.'); } - _span = _startTransitionSpan('load($name)'); + _span = _startTransitionSpan('load_module'); _state = LifecycleState.loading; @@ -499,7 +507,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { ]); } - _span = _startTransitionSpan('suspend($name)'); + _span = _startTransitionSpan('suspend_module'); Future pendingTransition; if (_transition != null && !_transition.isCompleted) { @@ -569,7 +577,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { pendingTransition = _transition.future; } - _span = _startTransitionSpan('resume($name)'); + _span = _startTransitionSpan('resume_module'); _state = LifecycleState.resuming; final transition = new Completer(); @@ -668,7 +676,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { ]); } - _span = _startTransitionSpan('unload($name)'); + _span = _startTransitionSpan('unload_module'); Future pendingTransition; if (_transition != null && !_transition.isCompleted) { From c55f58a9259409e4cf5cee63323313d81039aa2a Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Tue, 31 Jul 2018 10:52:30 -0600 Subject: [PATCH 07/14] AF-1540 allow consumer to specify useful state time --- .../panel/modules/data_load_async_module.dart | 28 +++-- lib/src/lifecycle_module.dart | 100 +++++++++++++----- 2 files changed, 93 insertions(+), 35 deletions(-) diff --git a/example/panel/modules/data_load_async_module.dart b/example/panel/modules/data_load_async_module.dart index 6231176d..06059c30 100644 --- a/example/panel/modules/data_load_async_module.dart +++ b/example/panel/modules/data_load_async_module.dart @@ -27,12 +27,14 @@ class DataLoadAsyncModule extends Module { DataLoadAsyncActions _actions; DataLoadAsyncComponents _components; - DataLoadAsyncStore _stores; + DataLoadAsyncEvents _events; + DataLoadAsyncStore _store; DataLoadAsyncModule() { _actions = new DataLoadAsyncActions(); - _stores = new DataLoadAsyncStore(_actions); - _components = new DataLoadAsyncComponents(_actions, _stores); + _events = new DataLoadAsyncEvents(); + _store = new DataLoadAsyncStore(_actions, _events); + _components = new DataLoadAsyncComponents(_actions, _store); } @override @@ -43,6 +45,7 @@ class DataLoadAsyncModule extends Module { Future onLoad() { // trigger non-blocking async load of data _actions.loadData(); + _events.didLoadData.first.then((_) => didEnterFirstUsefulState()); return new Future.value(); } } @@ -62,15 +65,20 @@ class DataLoadAsyncActions { final Action loadData = new Action(); } +DispatchKey _dispatchKey = new DispatchKey('DataLoadAsync'); + +class DataLoadAsyncEvents { + final Event didLoadData = new Event(_dispatchKey); +} + class DataLoadAsyncStore extends Store { DataLoadAsyncActions _actions; - List _data; - bool _isLoading; + DataLoadAsyncEvents _events; + List _data = []; + bool _isLoading = false; - DataLoadAsyncStore(this._actions) { - _isLoading = false; - _data = []; - triggerOnAction(_actions.loadData, _loadData); + DataLoadAsyncStore(this._actions, this._events) { + manageActionSubscription(_actions.loadData.listen(_loadData)); } /// Public data @@ -89,6 +97,8 @@ class DataLoadAsyncStore extends Store { // trigger on return of final data _data = ['Aaron', 'Dustin', 'Evan', 'Jay', 'Max', 'Trent']; _isLoading = false; + _events.didLoadData(null, _dispatchKey); + trigger(); } } diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index 12d2d75f..683af137 100644 --- a/lib/src/lifecycle_module.dart +++ b/lib/src/lifecycle_module.dart @@ -54,7 +54,7 @@ enum LifecycleState { /// unified lifecycle API. abstract class LifecycleModule extends SimpleModule with Disposable { static int _nextId = 0; - + // Used by tracing to tell apart multiple instances of the same module int _instanceId = _nextId++; List _childModules = []; @@ -63,7 +63,11 @@ abstract class LifecycleModule extends SimpleModule with Disposable { LifecycleState _previousState; LifecycleState _state = LifecycleState.instantiated; Completer _transition; - Span _span; + Span _activeSpan; + + // Used by tracing to create a span if the consumer specifies when the module + // reaches its first useful state + DateTime _startLoadTime; // Lifecycle event StreamControllers StreamController _willLoadChildModuleController = @@ -135,7 +139,11 @@ abstract class LifecycleModule extends SimpleModule with Disposable { /// If this module is in a transition state, this is the Span capturing the /// transition state. - Span get activeSpan => _span; + Span get activeSpan => _activeSpan; + + /// Set internally by this module for the load span so it can be used as a + /// `Reference` to other spans after the span is finished. + SpanContext _loadContext; /// Set internally by the parent module if this module is called by [loadChildModule] SpanContext _childOfContext; @@ -155,17 +163,54 @@ abstract class LifecycleModule extends SimpleModule with Disposable { references.add(new Reference.childOf(_childOfContext)); } - return tracer.startSpan(operationName, references: references) - ..addTags({ - 'module.name': name, - 'module.instanceId': _instanceId, - }); + return tracer.startSpan( + operationName, + references: references, + tags: _defaultTags, + ); + } + + /// Creates a span from the start of [load] until now. + /// + /// This is different from [onLoad] as this indicates that whichever asynchronous + /// processes required to make this module interactible (such as any data needed + /// to populate its store) will be finished by this point, whereas it might + /// only be started in [onLoad]. + /// + /// Any [tags] specified will be added to the span which results from this call. + void didEnterFirstUsefulState({Map tags: const {}}) { + // Load didn't start + if (_loadContext == null || _startLoadTime == null) { + return null; + } + + final tracer = globalTracer(); + if (tracer == null) { + return null; + } + + tracer + .startSpan( + 'module_entered_first_useful_state', + references: [tracer.followsFrom(_loadContext)], + startTime: _startLoadTime, + tags: _defaultTags..addAll(tags), + ) + .finish(); + + _startLoadTime = null; } /// Name of the module for identification in exceptions and debug messages. // ignore: unnecessary_getters_setters String get name => _name ?? 'LifecycleModule($runtimeType)'; + Map get _defaultTags => { + 'span.kind': 'client', + 'module.name': name, + 'module.instanceId': _instanceId, + }; + /// Deprecated: the module name should be defined by overriding the getter in /// a subclass and it should not be mutable. @deprecated @@ -355,7 +400,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable { reason: 'A module can only be loaded once.'); } - _span = _startTransitionSpan('load_module'); + _startLoadTime = new DateTime.now(); + + _activeSpan = _startTransitionSpan('load_module'); + _loadContext = _activeSpan.context; _state = LifecycleState.loading; @@ -367,10 +415,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable { _load().then(transition.complete).catchError((error, trace) { transition.completeError(error, trace); - _span?.setTag('error', true); + _activeSpan?.setTag('error', true); }).whenComplete(() { - _span?.finish(); - _span = null; + _activeSpan?.finish(); + _activeSpan = null; }); return transition.future; @@ -433,7 +481,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { try { _childModules.add(childModule); - childModule._childOfContext = _span?.context; + childModule._childOfContext = _activeSpan?.context; await childModule.load(); await onDidLoadChildModule(childModule); @@ -507,7 +555,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { ]); } - _span = _startTransitionSpan('suspend_module'); + _activeSpan = _startTransitionSpan('suspend_module'); Future pendingTransition; if (_transition != null && !_transition.isCompleted) { @@ -522,10 +570,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable { .then(transition.complete) .catchError((error, trace) { transition.completeError(error, trace); - _span?.setTag('error', true); + _activeSpan?.setTag('error', true); }).whenComplete(() { - _span?.finish(); - _span = null; + _activeSpan?.finish(); + _activeSpan = null; }); return transition.future; @@ -577,7 +625,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { pendingTransition = _transition.future; } - _span = _startTransitionSpan('resume_module'); + _activeSpan = _startTransitionSpan('resume_module'); _state = LifecycleState.resuming; final transition = new Completer(); @@ -587,10 +635,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable { .then(transition.complete) .catchError((error, trace) { transition.completeError(error, trace); - _span?.setTag('error', true); + _activeSpan?.setTag('error', true); }).whenComplete(() { - _span?.finish(); - _span = null; + _activeSpan?.finish(); + _activeSpan = null; }); return _transition.future; @@ -676,7 +724,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { ]); } - _span = _startTransitionSpan('unload_module'); + _activeSpan = _startTransitionSpan('unload_module'); Future pendingTransition; if (_transition != null && !_transition.isCompleted) { @@ -691,7 +739,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { var unloadAndDispose = new Completer(); unloadAndDispose.complete(transition.future.then((_) => dispose())); transition.complete(_unload(pendingTransition)); - return unloadAndDispose.future.whenComplete(_span?.finish); + return unloadAndDispose.future.whenComplete(_activeSpan?.finish); } //-------------------------------------------------------- @@ -887,7 +935,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { List> childResumeFutures = >[]; for (var child in _childModules.toList()) { childResumeFutures.add(new Future(() { - child._childOfContext = _span?.context; + child._childOfContext = _activeSpan?.context; return child.resume().whenComplete(() { child._childOfContext = null; }); @@ -915,7 +963,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { List> childSuspendFutures = >[]; for (var child in _childModules.toList()) { childSuspendFutures.add(new Future(() async { - child._childOfContext = _span?.context; + child._childOfContext = _activeSpan?.context; return child.suspend().whenComplete(() { child._childOfContext = null; }); @@ -951,7 +999,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { } _willUnloadController.add(this); await Future.wait(_childModules.toList().map((child) { - child._childOfContext = _span?.context; + child._childOfContext = _activeSpan?.context; return child.unload().whenComplete(() { child._childOfContext = null; }); From cbab191e36bc6045808fa37bff86ec318d61cca8 Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Tue, 31 Jul 2018 11:05:34 -0600 Subject: [PATCH 08/14] AF-1540 make start time the same --- example/panel/modules/data_load_async_module.dart | 4 ++-- lib/src/lifecycle_module.dart | 3 +-- 2 files changed, 3 insertions(+), 4 deletions(-) diff --git a/example/panel/modules/data_load_async_module.dart b/example/panel/modules/data_load_async_module.dart index 06059c30..8c7b4e49 100644 --- a/example/panel/modules/data_load_async_module.dart +++ b/example/panel/modules/data_load_async_module.dart @@ -44,9 +44,9 @@ class DataLoadAsyncModule extends Module { @protected Future onLoad() { // trigger non-blocking async load of data - _actions.loadData(); _events.didLoadData.first.then((_) => didEnterFirstUsefulState()); - return new Future.value(); + _actions.loadData(); + return null; } } diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index 683af137..c2411db7 100644 --- a/lib/src/lifecycle_module.dart +++ b/lib/src/lifecycle_module.dart @@ -400,10 +400,9 @@ abstract class LifecycleModule extends SimpleModule with Disposable { reason: 'A module can only be loaded once.'); } - _startLoadTime = new DateTime.now(); - _activeSpan = _startTransitionSpan('load_module'); _loadContext = _activeSpan.context; + _startLoadTime = _activeSpan.startTime; _state = LifecycleState.loading; From b63cb9d68ef4e40f753cc4019ef9c361bb4ebebb Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Tue, 31 Jul 2018 11:16:36 -0600 Subject: [PATCH 09/14] AF-1541 additional timing granularity --- example/panel/modules/data_load_async_module.dart | 3 ++- lib/src/lifecycle_module.dart | 8 ++++++-- lib/w_module.dart | 1 + 3 files changed, 9 insertions(+), 3 deletions(-) diff --git a/example/panel/modules/data_load_async_module.dart b/example/panel/modules/data_load_async_module.dart index 8c7b4e49..26b52c2a 100644 --- a/example/panel/modules/data_load_async_module.dart +++ b/example/panel/modules/data_load_async_module.dart @@ -44,7 +44,8 @@ class DataLoadAsyncModule extends Module { @protected Future onLoad() { // trigger non-blocking async load of data - _events.didLoadData.first.then((_) => didEnterFirstUsefulState()); + _events.didLoadData.first + .then((_) => specifyStartupTiming(StartupTimingSpecifier.firstUseful)); _actions.loadData(); return null; } diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index c2411db7..7db84b1c 100644 --- a/lib/src/lifecycle_module.dart +++ b/lib/src/lifecycle_module.dart @@ -22,6 +22,7 @@ import 'package:opentracing/opentracing.dart'; import 'package:w_common/disposable.dart'; import 'package:w_module/src/simple_module.dart'; +import 'package:w_module/src/timing_specifiers.dart'; /// Possible states a [LifecycleModule] may occupy. enum LifecycleState { @@ -178,7 +179,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable { /// only be started in [onLoad]. /// /// Any [tags] specified will be added to the span which results from this call. - void didEnterFirstUsefulState({Map tags: const {}}) { + void specifyStartupTiming( + StartupTimingSpecifier specifier, { + Map tags: const {}, + }) { // Load didn't start if (_loadContext == null || _startLoadTime == null) { return null; @@ -191,7 +195,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { tracer .startSpan( - 'module_entered_first_useful_state', + specifier.name, references: [tracer.followsFrom(_loadContext)], startTime: _startLoadTime, tags: _defaultTags..addAll(tags), diff --git a/lib/w_module.dart b/lib/w_module.dart index 374c2e38..2467cdd5 100644 --- a/lib/w_module.dart +++ b/lib/w_module.dart @@ -26,3 +26,4 @@ export 'package:w_module/src/events_collection.dart'; export 'package:w_module/src/lifecycle_module.dart' hide LifecycleState; export 'package:w_module/src/module.dart'; export 'package:w_module/src/simple_module.dart'; +export 'package:w_module/src/timing_specifiers.dart'; From 0194c783764882aa3ae753e969985be440888d5f Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Tue, 31 Jul 2018 11:19:09 -0600 Subject: [PATCH 10/14] actually commit files --- lib/src/timing_specifiers.dart | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) create mode 100644 lib/src/timing_specifiers.dart diff --git a/lib/src/timing_specifiers.dart b/lib/src/timing_specifiers.dart new file mode 100644 index 00000000..d2cd3e14 --- /dev/null +++ b/lib/src/timing_specifiers.dart @@ -0,0 +1,16 @@ +class StartupTimingSpecifier { + final String name; + const StartupTimingSpecifier._(this.name); + + static const StartupTimingSpecifier firstComponentRender = + const StartupTimingSpecifier._('module_first_component_rendered'); + + static const StartupTimingSpecifier firstEditable = + const StartupTimingSpecifier._('module_entered_first_editable_state'); + + static const StartupTimingSpecifier firstReadable = + const StartupTimingSpecifier._('module_entered_first_readable_state'); + + static const StartupTimingSpecifier firstUseful = + const StartupTimingSpecifier._('module_entered_first_useful_state'); +} From cf5b889885e379c235ea120d012c437ec7640115 Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Wed, 1 Aug 2018 11:26:56 -0600 Subject: [PATCH 11/14] testing for tracing for everything but dispose --- lib/src/lifecycle_module.dart | 83 +++++++---- test/lifecycle_module_test.dart | 240 +++++++++++++++++++++++++++++++- test/test_tracer.dart | 166 ++++++++++++++++++++++ 3 files changed, 461 insertions(+), 28 deletions(-) create mode 100644 test/test_tracer.dart diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index 12d2d75f..94e7760a 100644 --- a/lib/src/lifecycle_module.dart +++ b/lib/src/lifecycle_module.dart @@ -63,7 +63,8 @@ abstract class LifecycleModule extends SimpleModule with Disposable { LifecycleState _previousState; LifecycleState _state = LifecycleState.instantiated; Completer _transition; - Span _span; + Span _activeSpan; + SpanContext _loadSpanContext; // Lifecycle event StreamControllers StreamController _willLoadChildModuleController = @@ -135,12 +136,12 @@ abstract class LifecycleModule extends SimpleModule with Disposable { /// If this module is in a transition state, this is the Span capturing the /// transition state. - Span get activeSpan => _span; + Span get activeSpan => _activeSpan; /// Set internally by the parent module if this module is called by [loadChildModule] SpanContext _childOfContext; - /// Builds a span that conditionally applies a childOf reference if this module + /// Builds a span that conditionally applies a followsFrom reference if this module /// was loaded by a parent module. /// /// Returns `null` if no globalTracer is configured. @@ -152,7 +153,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { List references = []; if (_childOfContext != null) { - references.add(new Reference.childOf(_childOfContext)); + references.add(new Reference.followsFrom(_childOfContext)); } return tracer.startSpan(operationName, references: references) @@ -355,7 +356,8 @@ abstract class LifecycleModule extends SimpleModule with Disposable { reason: 'A module can only be loaded once.'); } - _span = _startTransitionSpan('load_module'); + _activeSpan = _startTransitionSpan('load_module'); + _loadSpanContext = _activeSpan?.context; _state = LifecycleState.loading; @@ -367,10 +369,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable { _load().then(transition.complete).catchError((error, trace) { transition.completeError(error, trace); - _span?.setTag('error', true); + _activeSpan?.setTag('error', true); }).whenComplete(() { - _span?.finish(); - _span = null; + _activeSpan?.finish(); + _activeSpan = null; }); return transition.future; @@ -433,7 +435,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { try { _childModules.add(childModule); - childModule._childOfContext = _span?.context; + childModule._childOfContext = _loadSpanContext; await childModule.load(); await onDidLoadChildModule(childModule); @@ -507,11 +509,17 @@ abstract class LifecycleModule extends SimpleModule with Disposable { ]); } - _span = _startTransitionSpan('suspend_module'); - Future pendingTransition; if (_transition != null && !_transition.isCompleted) { - pendingTransition = _transition.future; + pendingTransition = _transition.future + // Need to `catchError` before `whenComplete` to prevent errors from + // getting thrown here when they should be handled elsewhere + .catchError((_) {}) + ..whenComplete(() { + _activeSpan = _startTransitionSpan('suspend_module'); + }); + } else { + _activeSpan = _startTransitionSpan('suspend_module'); } final transition = new Completer(); @@ -522,10 +530,12 @@ abstract class LifecycleModule extends SimpleModule with Disposable { .then(transition.complete) .catchError((error, trace) { transition.completeError(error, trace); - _span?.setTag('error', true); + assert(activeSpan != null); + _activeSpan.setTag('error', true); }).whenComplete(() { - _span?.finish(); - _span = null; + assert(activeSpan != null); + _activeSpan.finish(); + _activeSpan = null; }); return transition.future; @@ -574,11 +584,17 @@ abstract class LifecycleModule extends SimpleModule with Disposable { Future pendingTransition; if (_transition != null && !_transition.isCompleted) { - pendingTransition = _transition.future; + pendingTransition = _transition.future + // Need to `catchError` before `whenComplete` to prevent errors from + // getting thrown here when they should be handled elsewhere + .catchError((_) {}) + ..whenComplete(() { + _activeSpan = _startTransitionSpan('resume_module'); + }); + } else { + _activeSpan = _startTransitionSpan('resume_module'); } - _span = _startTransitionSpan('resume_module'); - _state = LifecycleState.resuming; final transition = new Completer(); _transition = transition; @@ -587,10 +603,10 @@ abstract class LifecycleModule extends SimpleModule with Disposable { .then(transition.complete) .catchError((error, trace) { transition.completeError(error, trace); - _span?.setTag('error', true); + _activeSpan?.setTag('error', true); }).whenComplete(() { - _span?.finish(); - _span = null; + _activeSpan?.finish(); + _activeSpan = null; }); return _transition.future; @@ -676,11 +692,18 @@ abstract class LifecycleModule extends SimpleModule with Disposable { ]); } - _span = _startTransitionSpan('unload_module'); - Future pendingTransition; if (_transition != null && !_transition.isCompleted) { pendingTransition = _transition.future; + pendingTransition + // Need to `catchError` before `whenComplete` to prevent errors from + // getting thrown here when they should be handled elsewhere + .catchError((_) {}) + .whenComplete(() { + _activeSpan = _startTransitionSpan('unload_module'); + }); + } else { + _activeSpan = _startTransitionSpan('unload_module'); } _previousState = _state; @@ -690,8 +713,13 @@ abstract class LifecycleModule extends SimpleModule with Disposable { var unloadAndDispose = new Completer(); unloadAndDispose.complete(transition.future.then((_) => dispose())); + + transition.future.catchError((e, trace) { + _activeSpan?.setTag('error', true); + }).whenComplete(_activeSpan?.finish); + transition.complete(_unload(pendingTransition)); - return unloadAndDispose.future.whenComplete(_span?.finish); + return unloadAndDispose.future; } //-------------------------------------------------------- @@ -887,7 +915,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { List> childResumeFutures = >[]; for (var child in _childModules.toList()) { childResumeFutures.add(new Future(() { - child._childOfContext = _span?.context; + child._childOfContext = _activeSpan?.context; return child.resume().whenComplete(() { child._childOfContext = null; }); @@ -915,13 +943,14 @@ abstract class LifecycleModule extends SimpleModule with Disposable { List> childSuspendFutures = >[]; for (var child in _childModules.toList()) { childSuspendFutures.add(new Future(() async { - child._childOfContext = _span?.context; + child._childOfContext = _activeSpan?.context; return child.suspend().whenComplete(() { child._childOfContext = null; }); })); } await Future.wait(childSuspendFutures); + assert(activeSpan != null); await onSuspend(); if (_state == LifecycleState.suspending) { _state = LifecycleState.suspended; @@ -951,7 +980,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { } _willUnloadController.add(this); await Future.wait(_childModules.toList().map((child) { - child._childOfContext = _span?.context; + child._childOfContext = _activeSpan?.context; return child.unload().whenComplete(() { child._childOfContext = null; }); diff --git a/test/lifecycle_module_test.dart b/test/lifecycle_module_test.dart index 112461c0..d13c968e 100644 --- a/test/lifecycle_module_test.dart +++ b/test/lifecycle_module_test.dart @@ -18,10 +18,12 @@ import 'dart:async'; import 'package:logging/logging.dart'; import 'package:meta/meta.dart' show protected; import 'package:mockito/mockito.dart'; +import 'package:opentracing/opentracing.dart'; import 'package:test/test.dart'; import 'package:w_module/src/lifecycle_module.dart'; +import 'test_tracer.dart'; import 'utils.dart'; const String shouldUnloadError = 'Mock shouldUnload false message'; @@ -135,6 +137,8 @@ class TestLifecycleModule extends LifecycleModule { if (onLoadError != null) { throw onLoadError; } + assert(activeSpan.operationName == 'load_module'); + activeSpan.setTag('custom.load.tag', 'somevalue'); eventList.add('onLoad'); } @@ -156,6 +160,8 @@ class TestLifecycleModule extends LifecycleModule { if (onUnloadError != null) { throw onUnloadError; } + assert(activeSpan.operationName == 'unload_module'); + activeSpan.setTag('custom.unload.tag', 'somevalue'); eventList.add('onUnload'); } @@ -166,6 +172,8 @@ class TestLifecycleModule extends LifecycleModule { if (onSuspendError != null) { throw onSuspendError; } + assert(activeSpan.operationName == 'suspend_module'); + activeSpan.setTag('custom.suspend.tag', 'somevalue'); eventList.add('onSuspend'); } @@ -176,6 +184,8 @@ class TestLifecycleModule extends LifecycleModule { if (onResumeError != null) { throw onResumeError; } + assert(activeSpan.operationName == 'resume_module'); + activeSpan.setTag('custom.resume.tag', 'somevalue'); eventList.add('onResume'); } @@ -281,8 +291,13 @@ void main() { Logger.root.level = Level.ALL; final StateError testError = new StateError('You should have expected this'); + final TestTracer tracer = new TestTracer(); + initGlobalTracer(tracer); + assert(globalTracer() == tracer); + group('LifecycleModule', () { TestLifecycleModule module; + List subs = []; setUp(() async { module = new TestLifecycleModule(); @@ -290,6 +305,8 @@ void main() { tearDown(() async { await module.tearDown(); + subs.forEach((sub) => sub.cancel()); + subs.clear(); }); void testInvalidTransitions( @@ -330,6 +347,17 @@ void main() { await module.load(); }); + test('should record a span', () async { + subs.add(tracer.onSpanFinish.listen(expectAsync1((span) { + expect(span.operationName, 'load_module'); + expect(span.tags['module.name'], 'TestLifecycleModule'); + expect(span.tags['custom.load.tag'], 'somevalue'); + expect(span.tags['error'], isNull); + }))); + + await module.load(); + }); + group('with an onLoad that throws', () { setUp(() { module.onLoadError = testError; @@ -347,6 +375,16 @@ void main() { expect(module.load(), throwsA(same(module.onLoadError))); }); + test('should add the `error` span tag', () async { + subs.add(tracer.onSpanFinish.listen(expectAsync1((span) { + expect(span.operationName, 'load_module'); + expect(span.tags['module.name'], 'TestLifecycleModule'); + expect(span.tags['error'], true); + }))); + + expect(module.load(), throwsA(same(module.onLoadError))); + }); + test('should not repeatedly emit that error for subsequent transitions', () async { Completer done = new Completer(); @@ -502,6 +540,20 @@ void main() { await module.unload(); }); + test('should record a span', () async { + await gotoState(module, LifecycleState.loaded); + + subs.add(tracer.onSpanFinish + .where((span) => span.operationName == 'unload_module') + .listen(expectAsync1((span) { + expect(span.tags['module.name'], 'TestLifecycleModule'); + expect(span.tags['custom.unload.tag'], 'somevalue'); + expect(span.tags['error'], isNull); + }))); + + await module.unload(); + }); + group('with an onUnload that throws', () { setUp(() async { await gotoState(module, LifecycleState.loaded); @@ -511,7 +563,7 @@ void main() { }); test('should return that error', - () => expect(module.unload(), throwsA(same(testError)))); + () => expect(module.unload, throwsA(same(testError)))); test('should add that error to didUnload stream', () { module.didUnload.listen((LifecycleModule _) {}, @@ -522,6 +574,16 @@ void main() { expect(module.unload(), throwsA(same(module.onUnloadError))); }); + test('should add the `error` span tag', () async { + subs.add(tracer.onSpanFinish + .where((span) => span.operationName == 'unload_module') + .listen(expectAsync1((span) { + expect(span.tags['error'], true); + }))); + + expect(module.unload(), throwsA(same(module.onUnloadError))); + }); + test('can still be disposed', () { final completer = new Completer(); completer.future.then(expectAsync1((_) {})); @@ -711,6 +773,17 @@ void main() { await module.suspend(); }); + test('should record a span', () async { + await gotoState(module, LifecycleState.loaded); + subs.add(tracer.onSpanFinish + .where((span) => span.operationName == 'suspend_module') + .listen((span) { + expect(span.tags['custom.suspend.tag'], 'somevalue'); + })); + + await module.suspend(); + }); + group('with an onSuspend that throws', () { setUp(() async { await gotoState(module, LifecycleState.loaded); @@ -729,6 +802,17 @@ void main() { expect(module.suspend(), throwsA(same(module.onSuspendError))); }); + test('should add the `error` span tag', () async { + await gotoState(module, LifecycleState.loaded); + subs.add(tracer.onSpanFinish + .where((span) => span.operationName == 'suspend_module') + .listen(expectAsync1((span) { + expect(span.tags['error'], true); + }))); + + expect(module.suspend(), throwsA(same(module.onSuspendError))); + }); + test('should not repeatedly emit that error for subsequent transitions', () async { Completer done = new Completer(); @@ -871,6 +955,18 @@ void main() { await module.resume(); }); + test('should record a span', () async { + await gotoState(module, LifecycleState.suspended); + + subs.add(tracer.onSpanFinish + .where((span) => span.operationName == 'resume_module') + .listen(expectAsync1((span) { + expect(span.tags['custom.resume.tag'], 'somevalue'); + }))); + + await module.resume(); + }); + group('with an onResume that throws', () { setUp(() async { await gotoState(module, LifecycleState.suspended); @@ -889,6 +985,16 @@ void main() { expect(module.resume(), throwsA(same(module.onResumeError))); }); + test('should add the `error` span tag', () async { + subs.add(tracer.onSpanFinish + .where((span) => span.operationName == 'resume_module') + .listen(expectAsync1((span) { + expect(span.tags['error'], true); + }))); + + expect(module.resume(), throwsA(same(module.onResumeError))); + }); + test('should not repeatedly emit that error for subsequent transitions', () async { Completer done = new Completer(); @@ -1267,16 +1373,34 @@ void main() { group('LifecycleModule with children', () { TestLifecycleModule childModule; TestLifecycleModule parentModule; + SpanContext parentSpanContext; + List subs = []; setUp(() async { parentModule = new TestLifecycleModule(name: 'parent'); childModule = new TestLifecycleModule(name: 'child'); + + subs.add(tracer.onSpanFinish + .where((span) => + span.operationName == 'load_module' && + span.tags['module.name'] == 'parent') + .listen((span) { + expect(parentSpanContext, isNull, + reason: + 'parentSpanContext should only be set once because the parent module should only be loaded once.'); + + parentSpanContext = span.context; + })); + await parentModule.load(); }); tearDown(() async { await parentModule.tearDown(); await childModule.tearDown(); + parentSpanContext = null; + subs.forEach((sub) => sub.cancel()); + subs.clear(); }); group('loadChildModule', () { @@ -1328,6 +1452,17 @@ void main() { await parentModule.loadChildModule(childModule); }); + test('should record a span with `followsFrom` ref', () async { + subs.add(tracer.onSpanFinish + .where((span) => span.tags['module.name'] == 'child') + .listen(expectAsync1((span) { + expect(span.parentContext.spanId, parentSpanContext.spanId); + expect(span.tags['custom.load.tag'], 'somevalue'); + }))); + + await parentModule.loadChildModule(childModule); + }); + group('with a child with an onLoad that throws', () { setUp(() { childModule.onLoadError = testError; @@ -1347,6 +1482,19 @@ void main() { expect(parentModule.loadChildModule(childModule), throwsA(same(childModule.onLoadError))); }); + + test('should record a span with `followsFrom` ref and `error` tag', + () async { + subs.add(tracer.onSpanFinish + .where((span) => span.tags['module.name'] == 'child') + .listen(expectAsync1((span) { + expect(span.parentContext.spanId, parentSpanContext.spanId); + expect(span.tags['error'], true); + }))); + + expect(parentModule.loadChildModule(childModule), + throwsA(same(childModule.onLoadError))); + }); }); group('with a parent with an onDidLoadChildModule that throws', () { @@ -1418,11 +1566,31 @@ void main() { }); group('suspend', () { + SpanContext parentSuspendContext; + setUp(() async { + subs.add(tracer.onSpanFinish + .where((span) => + span.operationName == 'suspend_module' && + span.tags['module.name'] == 'parent') + .listen(expectAsync1((span) { + parentSuspendContext = span.context; + }))); + await parentModule.loadChildModule(childModule); }); + tearDown(() { + parentSuspendContext = null; + }); + test('should suspend child modules', () async { + Completer childSpanCompleter = new Completer(); + + subs.add(tracer.onSpanFinish + .where((span) => span.tags['module.name'] == 'child') + .listen(expectAsync1(childSpanCompleter.complete))); + parentModule.eventList.clear(); childModule.eventList.clear(); await parentModule.suspend(); @@ -1430,6 +1598,13 @@ void main() { equals(['willSuspend', 'onSuspend', 'didSuspend'])); expect(childModule.eventList, equals(['willSuspend', 'onSuspend', 'didSuspend'])); + + final span = await childSpanCompleter.future; + await new Future(() {}); // wait for parent to finish suspending + + assert(parentSuspendContext?.spanId != null); + expect(span.parentContext.spanId, parentSuspendContext.spanId); + expect(span.tags['custom.suspend.tag'], 'somevalue'); }); group('with a child with an onSuspend that throws', () { @@ -1448,6 +1623,24 @@ void main() { throwsA(same(childModule.onSuspendError))); }); + test('should add `error` span tag and `followsFrom` ref', () async { + Completer childSpanCompleter = new Completer(); + + subs.add(tracer.onSpanFinish + .where((span) => span.tags['module.name'] == 'child') + .listen(expectAsync1(childSpanCompleter.complete))); + + expect(parentModule.suspend(), + throwsA(same(childModule.onSuspendError))); + + final span = await childSpanCompleter.future; + await new Future(() {}); // wait for parent to finish suspending + + assert(parentSuspendContext?.spanId != null); + expect(span.parentContext.spanId, parentSuspendContext.spanId); + expect(span.tags['error'], true); + }); + test('should still suspend other children', () async { var secondChildModule = new TestLifecycleModule(); await parentModule.loadChildModule(secondChildModule); @@ -1460,12 +1653,32 @@ void main() { }); group('resume', () { + SpanContext parentResumeContext; + setUp(() async { + subs.add(tracer.onSpanFinish + .where((span) => + span.operationName == 'resume_module' && + span.tags['module.name'] == 'parent') + .listen(expectAsync1((span) { + parentResumeContext = span.context; + }))); + await parentModule.loadChildModule(childModule); await parentModule.suspend(); }); + tearDown(() { + parentResumeContext = null; + }); + test('should resume child modules', () async { + Completer childSpanCompleter = new Completer(); + + subs.add(tracer.onSpanFinish + .where((span) => span.tags['module.name'] == 'child') + .listen(expectAsync1(childSpanCompleter.complete))); + parentModule.eventList.clear(); childModule.eventList.clear(); await parentModule.resume(); @@ -1473,6 +1686,13 @@ void main() { equals(['willResume', 'onResume', 'didResume'])); expect(childModule.eventList, equals(['willResume', 'onResume', 'didResume'])); + + final span = await childSpanCompleter.future; + await new Future(() {}); // wait for parent to finish resuming + + assert(parentResumeContext?.spanId != null); + expect(span.parentContext.spanId, parentResumeContext.spanId); + expect(span.tags['custom.resume.tag'], 'somevalue'); }); group('with a child with an onResume that throws', () { @@ -1491,6 +1711,24 @@ void main() { parentModule.resume(), throwsA(same(childModule.onResumeError))); }); + test('should add `error` span tag and `followsFrom` ref', () async { + Completer childSpanCompleter = new Completer(); + + subs.add(tracer.onSpanFinish + .where((span) => span.tags['module.name'] == 'child') + .listen(expectAsync1(childSpanCompleter.complete))); + + expect( + parentModule.resume(), throwsA(same(childModule.onResumeError))); + + final span = await childSpanCompleter.future; + await new Future(() {}); // wait for parent to finish suspending + + assert(parentResumeContext?.spanId != null); + expect(span.parentContext.spanId, parentResumeContext.spanId); + expect(span.tags['error'], true); + }); + test('should still resume other children', () async { var secondChildModule = new TestLifecycleModule(); await parentModule.loadChildModule(secondChildModule); diff --git a/test/test_tracer.dart b/test/test_tracer.dart new file mode 100644 index 00000000..ec1f5ef7 --- /dev/null +++ b/test/test_tracer.dart @@ -0,0 +1,166 @@ +import 'dart:async'; +import 'package:opentracing/opentracing.dart'; + +class TestSpan implements Span { + static int _nextId = 0; + final int _id = _nextId++; + + @override + final List references; + + @override + final Map tags; + + @override + final List logData = []; + + @override + final String operationName; + + @override + SpanContext context; + + @override + final DateTime startTime; + DateTime _endTime; + + Completer _whenFinished = new Completer(); + + TestSpan( + this.operationName, { + SpanContext childOf, + List references, + DateTime startTime, + Map tags, + }) + : this.startTime = startTime ?? new DateTime.now(), + this.tags = tags ?? {}, + this.references = references ?? {} { + if (childOf != null) { + references.add(new Reference.childOf(childOf)); + } + setTag('span.kind', 'client'); + + final parent = parentContext; + if (parent != null) { + this.context = new SpanContext(spanId: _id, traceId: parent.traceId); + this.context.baggage.addAll(parent.baggage); + } else { + this.context = new SpanContext(spanId: _id, traceId: _id); + } + } + + @override + void addTags(Map newTags) => tags.addAll(newTags); + + @override + Duration get duration => _endTime?.difference(startTime); + + @override + DateTime get endTime => _endTime; + + @override + void finish({DateTime finishTime}) { + if (_whenFinished == null) { + return; + } + + _endTime = finishTime ?? new DateTime.now(); + _whenFinished.complete(this); + _whenFinished = null; + } + + @override + void log(String event, {dynamic payload, DateTime timestamp}) => + logData.add(new LogData(timestamp ?? new DateTime.now(), event, payload)); + + @override + SpanContext get parentContext => + references.isEmpty ? null : references.first.referencedContext; + + @override + void setTag(String tagName, dynamic value) => tags[tagName] = value; + + @override + Future get whenFinished => _whenFinished.future; + + @override + String toString() { + final sb = new StringBuffer('SampleSpan('); + sb + ..writeln('traceId: ${context.traceId}') + ..writeln('spanId: ${context.spanId}') + ..writeln('operationName: $operationName') + ..writeln('tags: ${tags.toString()}') + ..writeln('startTime: ${startTime.toString()}'); + + if (_endTime != null) { + sb + ..writeln('endTime: ${endTime.toString()}') + ..writeln('duration: ${duration.toString()}'); + } + + if (logData.isNotEmpty) { + sb.writeln('logData: ${logData.toString()}'); + } + + if (references.isNotEmpty) { + final reference = references.first; + sb.writeln( + 'reference: ${reference.referenceType} ${reference.referencedContext.spanId}'); + } + + sb.writeln(')'); + + return sb.toString(); + } +} + +class TestTracer implements AbstractTracer { + // There should only ever be one of these + // ignore: close_sinks + StreamController _finishController = new StreamController.broadcast(); + + Stream get onSpanFinish => _finishController.stream; + + @override + TestSpan startSpan( + String operationName, { + SpanContext childOf, + List references, + DateTime startTime, + Map tags, + }) { + return new TestSpan( + operationName, + childOf: childOf, + references: references, + startTime: startTime, + tags: tags, + )..whenFinished.then(_finishController.add); + } + + @override + Reference childOf(SpanContext context) => new Reference.childOf(context); + + @override + Reference followsFrom(SpanContext context) => + new Reference.followsFrom(context); + + @override + SpanContext extract(String format, dynamic carrier) { + throw new UnimplementedError( + 'Sample tracer for example purposes does not support advanced tracing behavior.'); + } + + @override + void inject(SpanContext spanContext, String format, dynamic carrier) { + throw new UnimplementedError( + 'Sample tracer for example purposes does not support advanced tracing behavior.'); + } + + @override + Future flush() { + return null; + } +} From 9e1920c7e09314d3eb47a99cea578b1fadb427e6 Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Wed, 1 Aug 2018 13:31:24 -0600 Subject: [PATCH 12/14] dont trace unload --- lib/src/lifecycle_module.dart | 14 -------------- test/lifecycle_module_test.dart | 28 +--------------------------- 2 files changed, 1 insertion(+), 41 deletions(-) diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index 94e7760a..752acdb9 100644 --- a/lib/src/lifecycle_module.dart +++ b/lib/src/lifecycle_module.dart @@ -695,15 +695,6 @@ abstract class LifecycleModule extends SimpleModule with Disposable { Future pendingTransition; if (_transition != null && !_transition.isCompleted) { pendingTransition = _transition.future; - pendingTransition - // Need to `catchError` before `whenComplete` to prevent errors from - // getting thrown here when they should be handled elsewhere - .catchError((_) {}) - .whenComplete(() { - _activeSpan = _startTransitionSpan('unload_module'); - }); - } else { - _activeSpan = _startTransitionSpan('unload_module'); } _previousState = _state; @@ -713,11 +704,6 @@ abstract class LifecycleModule extends SimpleModule with Disposable { var unloadAndDispose = new Completer(); unloadAndDispose.complete(transition.future.then((_) => dispose())); - - transition.future.catchError((e, trace) { - _activeSpan?.setTag('error', true); - }).whenComplete(_activeSpan?.finish); - transition.complete(_unload(pendingTransition)); return unloadAndDispose.future; } diff --git a/test/lifecycle_module_test.dart b/test/lifecycle_module_test.dart index d13c968e..9ffd2071 100644 --- a/test/lifecycle_module_test.dart +++ b/test/lifecycle_module_test.dart @@ -160,8 +160,6 @@ class TestLifecycleModule extends LifecycleModule { if (onUnloadError != null) { throw onUnloadError; } - assert(activeSpan.operationName == 'unload_module'); - activeSpan.setTag('custom.unload.tag', 'somevalue'); eventList.add('onUnload'); } @@ -234,7 +232,7 @@ void expectInLifecycleState(LifecycleModule module, LifecycleState state) { isInState = module.isUnloading; break; } - expect(isInState, isTrue); + expect(isInState, isTrue, reason: 'state should be $state'); } Future gotoState(LifecycleModule module, LifecycleState state) async { @@ -540,20 +538,6 @@ void main() { await module.unload(); }); - test('should record a span', () async { - await gotoState(module, LifecycleState.loaded); - - subs.add(tracer.onSpanFinish - .where((span) => span.operationName == 'unload_module') - .listen(expectAsync1((span) { - expect(span.tags['module.name'], 'TestLifecycleModule'); - expect(span.tags['custom.unload.tag'], 'somevalue'); - expect(span.tags['error'], isNull); - }))); - - await module.unload(); - }); - group('with an onUnload that throws', () { setUp(() async { await gotoState(module, LifecycleState.loaded); @@ -574,16 +558,6 @@ void main() { expect(module.unload(), throwsA(same(module.onUnloadError))); }); - test('should add the `error` span tag', () async { - subs.add(tracer.onSpanFinish - .where((span) => span.operationName == 'unload_module') - .listen(expectAsync1((span) { - expect(span.tags['error'], true); - }))); - - expect(module.unload(), throwsA(same(module.onUnloadError))); - }); - test('can still be disposed', () { final completer = new Completer(); completer.future.then(expectAsync1((_) {})); From 7fc4d0f207ba7c0e39798f7bd3864044d19f89df Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Wed, 1 Aug 2018 15:18:39 -0600 Subject: [PATCH 13/14] active span can be null --- lib/src/lifecycle_module.dart | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index 752acdb9..64ba141c 100644 --- a/lib/src/lifecycle_module.dart +++ b/lib/src/lifecycle_module.dart @@ -530,11 +530,9 @@ abstract class LifecycleModule extends SimpleModule with Disposable { .then(transition.complete) .catchError((error, trace) { transition.completeError(error, trace); - assert(activeSpan != null); - _activeSpan.setTag('error', true); + _activeSpan?.setTag('error', true); }).whenComplete(() { - assert(activeSpan != null); - _activeSpan.finish(); + _activeSpan?.finish(); _activeSpan = null; }); From 1e5169cd9eae36de6be141cca273d52e8346fd3d Mon Sep 17 00:00:00 2001 From: Todd Beckman Date: Wed, 1 Aug 2018 15:19:41 -0600 Subject: [PATCH 14/14] enterFirstUsefulState should be protected --- lib/src/lifecycle_module.dart | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/src/lifecycle_module.dart b/lib/src/lifecycle_module.dart index da839b95..4dc64edc 100644 --- a/lib/src/lifecycle_module.dart +++ b/lib/src/lifecycle_module.dart @@ -178,6 +178,7 @@ abstract class LifecycleModule extends SimpleModule with Disposable { /// only be started in [onLoad]. /// /// Any [tags] specified will be added to the span which results from this call. + @protected void didEnterFirstUsefulState({Map tags: const {}}) { // Load didn't start if (_loadContext == null || _startLoadTime == null) {