Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Flaky VM service tests (mismatching event timestamps) #28624

Closed
kmillikin opened this issue Feb 3, 2017 · 4 comments
Closed

Flaky VM service tests (mismatching event timestamps) #28624

kmillikin opened this issue Feb 3, 2017 · 4 comments
Assignees
Labels
area-observatory area-vm Use area-vm for VM related issues, including code coverage, and the AOT and JIT backends. gardening

Comments

@kmillikin
Copy link

@turnidge These test have been observed to be flaky (command lines are at the bottom of the dump, I dropped the first part of the dump which seemed uninteresting):

service/pause_on_start_and_exit_test

>testee>out> vm-service: starting stream 'Isolate'
>testee>out> vm-service: starting stream 'Debug'
>testee>out> vm-service: starting stream '_Graph'
>testee>out> [+792ms] Isolate vm-service processing service request getVM
>testee>out> [+792ms] Isolate vm-service processed service request getVM (85us)
Done loading VM
>testee>out> [+828ms] Isolate pause_on_start_and_exit_test.dart$main-323816863 deferring OOB interrupts
>testee>out> [+829ms] Isolate pause_on_start_and_exit_test.dart$main-323816863 restoring OOB interrupts
>testee>out> vm-service: Pushing ServiceEvent(isolate='pause_on_start_and_exit_test.dart$main-323816863', kind='IsolateRunnable') to stream Isolate
>testee>out> [+842ms] Isolate pause_on_start_and_exit_test.dart$main-323816863 processing service request getIsolate
Running pause_on_start_and_exit_test.dart [1/1]
Getting stream...
Subscribing...
Subscribed.  Pause event is Instance of 'PauseStartEvent'
Subscription cancelled.
Done waiting for pause event.
** Killing script
Unexpected exception in service tests: Expected: <1486106770187>
  Actual: <1486106770174>

package:unittest/src/matcher/expect.dart 117:5                            DefaultFailureHandler.fail
package:unittest/src/matcher/expect.dart 121:5                            DefaultFailureHandler.failMatch
package:unittest/src/matcher/expect.dart 95:20                            expect
runtime/observatory/tests/service/pause_on_start_and_exit_test.dart 52:3  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/future_impl.dart 22                                            _Completer.completeError
runtime/observatory/tests/service/pause_on_start_and_exit_test.dart 81:2  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                 _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper
runtime/observatory/tests/service/pause_on_start_and_exit_test.dart       tests.<fn>
runtime/observatory/tests/service/test_helper.dart 325:23                 _ServiceTesterRunner.run.<fn>.<async>.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                 _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper
runtime/observatory/tests/service/test_helper.dart                        _ServiceTesterRunner.run.<fn>.<async>.<fn>
package:stack_trace/src/chain.dart 87:24                                  Chain.capture.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 1503                                                 runZoned
package:stack_trace/src/chain.dart 85:12                                  Chain.capture
runtime/observatory/tests/service/test_helper.dart 297:13                 _ServiceTesterRunner.run.<fn>.<async>
dart:async/future.dart 184                                                Future.Future.microtask.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage



stderr:
Unhandled exception:
Expected: <1486106770187>
  Actual: <1486106770174>

package:unittest/src/matcher/expect.dart 117:5                            DefaultFailureHandler.fail
package:unittest/src/matcher/expect.dart 121:5                            DefaultFailureHandler.failMatch
package:unittest/src/matcher/expect.dart 95:20                            expect
runtime/observatory/tests/service/pause_on_start_and_exit_test.dart 52:3  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/future_impl.dart 22                                            _Completer.completeError
runtime/observatory/tests/service/pause_on_start_and_exit_test.dart 81:2  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                 _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper
runtime/observatory/tests/service/pause_on_start_and_exit_test.dart       tests.<fn>
runtime/observatory/tests/service/test_helper.dart 325:23                 _ServiceTesterRunner.run.<fn>.<async>.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                 _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper
runtime/observatory/tests/service/test_helper.dart                        _ServiceTesterRunner.run.<fn>.<async>.<fn>
package:stack_trace/src/chain.dart 87:24                                  Chain.capture.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 1503                                                 runZoned
package:stack_trace/src/chain.dart 85:12                                  Chain.capture
runtime/observatory/tests/service/test_helper.dart 297:13                 _ServiceTesterRunner.run.<fn>.<async>
dart:async/future.dart 184                                                Future.Future.microtask.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage


Command[app_jit]: DART_CONFIGURATION=ReleaseX64 out/ReleaseX64/dart --snapshot=/b/build/slave/app-linux-release-x64-be/build/sdk/out/ReleaseX64/generated_compilations/app_jit/runtime_observatory_tests_service_pause_on_start_and_exit_test/out.jitsnapshot --snapshot-kind=app-jit --error_on_bad_type --error_on_bad_override --ignore-unrecognized-flags --packages=/b/build/slave/app-linux-release-x64-be/build/sdk/.packages /b/build/slave/app-linux-release-x64-be/build/sdk/runtime/observatory/tests/service/pause_on_start_and_exit_test.dart
Took 0:00:02.023510

Command[vm]: DART_CONFIGURATION=ReleaseX64 out/ReleaseX64/dart --error_on_bad_type --error_on_bad_override --ignore-unrecognized-flags --packages=/b/build/slave/app-linux-release-x64-be/build/sdk/.packages /b/build/slave/app-linux-release-x64-be/build/sdk/out/ReleaseX64/generated_compilations/app_jit/runtime_observatory_tests_service_pause_on_start_and_exit_test/out.jitsnapshot
Did not run
@kmillikin kmillikin added area-observatory area-vm Use area-vm for VM related issues, including code coverage, and the AOT and JIT backends. gardening labels Feb 3, 2017
@kmillikin
Copy link
Author

Here's another:

service/pause_on_start_and_exit_test

>testee>out> vm-service: starting stream 'Isolate'
>testee>out> vm-service: starting stream 'Debug'
>testee>out> vm-service: starting stream '_Graph'
>testee>out> [+841ms] Isolate vm-service processing service request getVM
>testee>out> [+841ms] Isolate vm-service processed service request getVM (0us)
Done loading VM
>testee>out> [+873ms] Isolate pause_on_start_and_exit_test.dart$main-465497560 deferring OOB interrupts
>testee>out> [+874ms] Isolate pause_on_start_and_exit_test.dart$main-465497560 restoring OOB interrupts
>testee>out> vm-service: Pushing ServiceEvent(isolate='pause_on_start_and_exit_test.dart$main-465497560', kind='IsolateRunnable') to stream Isolate
>testee>out> [+877ms] Isolate pause_on_start_and_exit_test.dart$main-465497560 processing service request getIsolate
>testee>out> [+878ms] Isolate pause_on_start_and_exit_test.dart$main-465497560 processed service request getIsolate (1001us)
>testee>out> [+879ms] Isolate pause_on_start_and_exit_test.dart$main-465497560 deferring OOB interrupts
>testee>out> [+879ms] Isolate pause_on_start_and_exit_test.dart$main-465497560 restoring OOB interrupts
>testee>out> vm-service: Pushing ServiceEvent(isolate='pause_on_start_and_exit_test.dart$main-465497560', kind='PauseStart') to stream Debug
Running pause_on_start_and_exit_test.dart [1/1]
Getting stream...
Subscribing...
Subscribed.  Pause event is Instance of 'PauseStartEvent'
Subscription cancelled.
Done waiting for pause event.
>testee>out> [+1028ms] Isolate pause_on_start_and_exit_test.dart$main-465497560 processing service request getIsolate
>testee>out> [+1029ms] Isolate pause_on_start_and_exit_test.dart$main-465497560 processed service request getIsolate (1000us)
** Killing script
Unexpected exception in service tests: Expected: <1486107490627>
  Actual: <1486107490623>

package:unittest/src/matcher/expect.dart 117:5                            DefaultFailureHandler.fail
package:unittest/src/matcher/expect.dart 121:5                            DefaultFailureHandler.failMatch
package:unittest/src/matcher/expect.dart 95:20                            expect
runtime\observatory\tests\service\pause_on_start_and_exit_test.dart 52:3  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/future_impl.dart 22                                            _Completer.completeError
runtime\observatory\tests\service\pause_on_start_and_exit_test.dart 81:2  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                 _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper
runtime\observatory\tests\service\pause_on_start_and_exit_test.dart       tests.<fn>
runtime\observatory\tests\service\test_helper.dart 325:23                 _ServiceTesterRunner.run.<fn>.<async>.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                 _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper
runtime\observatory\tests\service\test_helper.dart                        _ServiceTesterRunner.run.<fn>.<async>.<fn>
package:stack_trace/src/chain.dart 87:24                                  Chain.capture.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 1503                                                 runZoned
package:stack_trace/src/chain.dart 85:12                                  Chain.capture
runtime\observatory\tests\service\test_helper.dart 297:13                 _ServiceTesterRunner.run.<fn>.<async>
dart:async/future.dart 184                                                Future.Future.microtask.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage



stderr:
Unhandled exception:
Expected: <1486107490627>
  Actual: <1486107490623>

package:unittest/src/matcher/expect.dart 117:5                            DefaultFailureHandler.fail
package:unittest/src/matcher/expect.dart 121:5                            DefaultFailureHandler.failMatch
package:unittest/src/matcher/expect.dart 95:20                            expect
runtime\observatory\tests\service\pause_on_start_and_exit_test.dart 52:3  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/future_impl.dart 22                                            _Completer.completeError
runtime\observatory\tests\service\pause_on_start_and_exit_test.dart 81:2  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                 _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper
runtime\observatory\tests\service\pause_on_start_and_exit_test.dart       tests.<fn>
runtime\observatory\tests\service\test_helper.dart 325:23                 _ServiceTesterRunner.run.<fn>.<async>.<fn>.<async>
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26              StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14              StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                 _rootRunUnary
dart:async/zone.dart 1037                                                 _CustomZone.runUnary
dart:async/future_impl.dart 131                                           _FutureListener.handleValue
dart:async/future_impl.dart 637                                           _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                           _Future._propagateToListeners
dart:async/future_impl.dart 477                                           _Future._completeWithValue
dart:async/future_impl.dart 528                                           _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15              StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48              StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 924                                                  _CustomZone.runGuarded
dart:async/zone.dart 951                                                  _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                 _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                      _asyncThenWrapperHelper
runtime\observatory\tests\service\test_helper.dart                        _ServiceTesterRunner.run.<fn>.<async>.<fn>
package:stack_trace/src/chain.dart 87:24                                  Chain.capture.<fn>
dart:async/zone.dart 1150                                                 _rootRun
dart:async/zone.dart 1026                                                 _CustomZone.run
dart:async/zone.dart 1503                                                 runZoned
package:stack_trace/src/chain.dart 85:12                                  Chain.capture
runtime\observatory\tests\service\test_helper.dart 297:13                 _ServiceTesterRunner.run.<fn>.<async>
dart:async/future.dart 184                                                Future.Future.microtask.<fn>
dart:async/schedule_microtask.dart 41                                     _microtaskLoop
dart:async/schedule_microtask.dart 50                                     _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                  _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                 _RawReceivePortImpl._handleMessage


Command[vm]: set DART_CONFIGURATION=ReleaseX64 & out\ReleaseX64\dart.exe --enable_asserts --enable_type_checks --error_on_bad_type --error_on_bad_override --ignore-unrecognized-flags --packages=E:\b\build\slave\vm-win-release-x64-be\build\sdk\.packages E:\b\build\slave\vm-win-release-x64-be\build\sdk\runtime\observatory\tests\service\pause_on_start_and_exit_test.dart
Took 0:00:02.045205

@kmillikin
Copy link
Author

service/pause_on_start_then_step_test

>testee>out> vm-service: starting stream 'Isolate'
>testee>out> vm-service: starting stream 'Debug'
>testee>out> vm-service: starting stream '_Graph'
>testee>out> [+925ms] Isolate vm-service processing service request getVM
>testee>out> [+925ms] Isolate vm-service processed service request getVM (136us)
Done loading VM
>testee>out> [+941ms] Isolate pause_on_start_then_step_test.dart$main-117590080 deferring OOB interrupts
>testee>out> [+941ms] Isolate pause_on_start_then_step_test.dart$main-117590080 restoring OOB interrupts
>testee>out> vm-service: Pushing ServiceEvent(isolate='pause_on_start_then_step_test.dart$main-117590080', kind='IsolateRunnable') to stream Isolate
>testee>out> [+962ms] Isolate pause_on_start_then_step_test.dart$main-117590080 processing service request getIsolate
>testee>out> [+967ms] Isolate pause_on_start_then_step_test.dart$main-117590080 processed service request getIsolate (5334us)
>testee>out> [+969ms] Isolate pause_on_start_then_step_test.dart$main-117590080 deferring OOB interrupts
Running pause_on_start_then_step_test.dart [1/1]
Getting stream...
Subscribing...
Subscribed.  Pause event is Instance of 'PauseStartEvent'
Subscription cancelled.
Done waiting for pause event.
>testee>out> [+973ms] Isolate pause_on_start_then_step_test.dart$main-117590080 restoring OOB interrupts
>testee>out> vm-service: Pushing ServiceEvent(isolate='pause_on_start_then_step_test.dart$main-117590080', kind='PauseStart') to stream Debug
>testee>out> [+1102ms] Isolate pause_on_start_then_step_test.dart$main-117590080 processing service request getIsolate
>testee>out> [+1103ms] Isolate pause_on_start_then_step_test.dart$main-117590080 processed service request getIsolate (898us)
** Killing script
Unexpected exception in service tests: Expected: <1486107445512>
  Actual: <1486107445501>

package:unittest/src/matcher/expect.dart 117:5                             DefaultFailureHandler.fail
package:unittest/src/matcher/expect.dart 121:5                             DefaultFailureHandler.failMatch
package:unittest/src/matcher/expect.dart 95:20                             expect
runtime/observatory/tests/service/pause_on_start_then_step_test.dart 52:3  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                       _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26               StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14               StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                  _rootRunUnary
dart:async/zone.dart 1037                                                  _CustomZone.runUnary
dart:async/future_impl.dart 131                                            _FutureListener.handleValue
dart:async/future_impl.dart 637                                            _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                            _Future._propagateToListeners
dart:async/future_impl.dart 477                                            _Future._completeWithValue
dart:async/future_impl.dart 528                                            _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48               StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                  _rootRun
dart:async/zone.dart 1026                                                  _CustomZone.run
dart:async/zone.dart 924                                                   _CustomZone.runGuarded
dart:async/zone.dart 951                                                   _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                      _microtaskLoop
dart:async/schedule_microtask.dart 50                                      _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                   _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                  _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/future_impl.dart 22                                             _Completer.completeError
runtime/observatory/tests/service/pause_on_start_then_step_test.dart 84:2  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                       _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26               StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14               StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                  _rootRunUnary
dart:async/zone.dart 1037                                                  _CustomZone.runUnary
dart:async/future_impl.dart 131                                            _FutureListener.handleValue
dart:async/future_impl.dart 637                                            _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                            _Future._propagateToListeners
dart:async/future_impl.dart 477                                            _Future._completeWithValue
dart:async/future_impl.dart 528                                            _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48               StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                  _rootRun
dart:async/zone.dart 1026                                                  _CustomZone.run
dart:async/zone.dart 924                                                   _CustomZone.runGuarded
dart:async/zone.dart 951                                                   _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                      _microtaskLoop
dart:async/schedule_microtask.dart 50                                      _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                   _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                  _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                  _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                       _asyncThenWrapperHelper
runtime/observatory/tests/service/pause_on_start_then_step_test.dart       tests.<fn>
runtime/observatory/tests/service/test_helper.dart 325:23                  _ServiceTesterRunner.run.<fn>.<async>.<fn>.<async>
dart:async-patch/async_patch.dart 27                                       _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26               StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14               StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                  _rootRunUnary
dart:async/zone.dart 1037                                                  _CustomZone.runUnary
dart:async/future_impl.dart 131                                            _FutureListener.handleValue
dart:async/future_impl.dart 637                                            _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                            _Future._propagateToListeners
dart:async/future_impl.dart 477                                            _Future._completeWithValue
dart:async/future_impl.dart 528                                            _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48               StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                  _rootRun
dart:async/zone.dart 1026                                                  _CustomZone.run
dart:async/zone.dart 924                                                   _CustomZone.runGuarded
dart:async/zone.dart 951                                                   _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                      _microtaskLoop
dart:async/schedule_microtask.dart 50                                      _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                   _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                  _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                  _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                       _asyncThenWrapperHelper
runtime/observatory/tests/service/test_helper.dart                         _ServiceTesterRunner.run.<fn>.<async>.<fn>
package:stack_trace/src/chain.dart 87:24                                   Chain.capture.<fn>
dart:async/zone.dart 1150                                                  _rootRun
dart:async/zone.dart 1026                                                  _CustomZone.run
dart:async/zone.dart 1503                                                  runZoned
package:stack_trace/src/chain.dart 85:12                                   Chain.capture
runtime/observatory/tests/service/test_helper.dart 297:13                  _ServiceTesterRunner.run.<fn>.<async>
dart:async/future.dart 184                                                 Future.Future.microtask.<fn>
dart:async/schedule_microtask.dart 41                                      _microtaskLoop
dart:async/schedule_microtask.dart 50                                      _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                   _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                  _RawReceivePortImpl._handleMessage



stderr:
Unhandled exception:
Expected: <1486107445512>
  Actual: <1486107445501>

package:unittest/src/matcher/expect.dart 117:5                             DefaultFailureHandler.fail
package:unittest/src/matcher/expect.dart 121:5                             DefaultFailureHandler.failMatch
package:unittest/src/matcher/expect.dart 95:20                             expect
runtime/observatory/tests/service/pause_on_start_then_step_test.dart 52:3  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                       _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26               StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14               StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                  _rootRunUnary
dart:async/zone.dart 1037                                                  _CustomZone.runUnary
dart:async/future_impl.dart 131                                            _FutureListener.handleValue
dart:async/future_impl.dart 637                                            _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                            _Future._propagateToListeners
dart:async/future_impl.dart 477                                            _Future._completeWithValue
dart:async/future_impl.dart 528                                            _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48               StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                  _rootRun
dart:async/zone.dart 1026                                                  _CustomZone.run
dart:async/zone.dart 924                                                   _CustomZone.runGuarded
dart:async/zone.dart 951                                                   _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                      _microtaskLoop
dart:async/schedule_microtask.dart 50                                      _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                   _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                  _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/future_impl.dart 22                                             _Completer.completeError
runtime/observatory/tests/service/pause_on_start_then_step_test.dart 84:2  tests.<fn>.<async>
dart:async-patch/async_patch.dart 27                                       _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26               StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14               StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                  _rootRunUnary
dart:async/zone.dart 1037                                                  _CustomZone.runUnary
dart:async/future_impl.dart 131                                            _FutureListener.handleValue
dart:async/future_impl.dart 637                                            _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                            _Future._propagateToListeners
dart:async/future_impl.dart 477                                            _Future._completeWithValue
dart:async/future_impl.dart 528                                            _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48               StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                  _rootRun
dart:async/zone.dart 1026                                                  _CustomZone.run
dart:async/zone.dart 924                                                   _CustomZone.runGuarded
dart:async/zone.dart 951                                                   _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                      _microtaskLoop
dart:async/schedule_microtask.dart 50                                      _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                   _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                  _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                  _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                       _asyncThenWrapperHelper
runtime/observatory/tests/service/pause_on_start_then_step_test.dart       tests.<fn>
runtime/observatory/tests/service/test_helper.dart 325:23                  _ServiceTesterRunner.run.<fn>.<async>.<fn>.<async>
dart:async-patch/async_patch.dart 27                                       _asyncThenWrapperHelper.<fn>
package:stack_trace/src/stack_zone_specification.dart 135:26               StackZoneSpecification.registerUnaryCallback.<fn>.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 135:14               StackZoneSpecification.registerUnaryCallback.<fn>
dart:async/zone.dart 1158                                                  _rootRunUnary
dart:async/zone.dart 1037                                                  _CustomZone.runUnary
dart:async/future_impl.dart 131                                            _FutureListener.handleValue
dart:async/future_impl.dart 637                                            _Future._propagateToListeners.handleValueCallback
dart:async/future_impl.dart 667                                            _Future._propagateToListeners
dart:async/future_impl.dart 477                                            _Future._completeWithValue
dart:async/future_impl.dart 528                                            _Future._asyncComplete.<fn>
package:stack_trace/src/stack_zone_specification.dart 206:15               StackZoneSpecification._run
package:stack_trace/src/stack_zone_specification.dart 125:48               StackZoneSpecification.registerCallback.<fn>
dart:async/zone.dart 1150                                                  _rootRun
dart:async/zone.dart 1026                                                  _CustomZone.run
dart:async/zone.dart 924                                                   _CustomZone.runGuarded
dart:async/zone.dart 951                                                   _CustomZone.bindCallback.<fn>
dart:async/schedule_microtask.dart 41                                      _microtaskLoop
dart:async/schedule_microtask.dart 50                                      _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                   _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                  _RawReceivePortImpl._handleMessage
===== asynchronous gap ===========================
dart:async/zone.dart 1073                                                  _CustomZone.registerUnaryCallback
dart:async-patch/async_patch.dart 27                                       _asyncThenWrapperHelper
runtime/observatory/tests/service/test_helper.dart                         _ServiceTesterRunner.run.<fn>.<async>.<fn>
package:stack_trace/src/chain.dart 87:24                                   Chain.capture.<fn>
dart:async/zone.dart 1150                                                  _rootRun
dart:async/zone.dart 1026                                                  _CustomZone.run
dart:async/zone.dart 1503                                                  runZoned
package:stack_trace/src/chain.dart 85:12                                   Chain.capture
runtime/observatory/tests/service/test_helper.dart 297:13                  _ServiceTesterRunner.run.<fn>.<async>
dart:async/future.dart 184                                                 Future.Future.microtask.<fn>
dart:async/schedule_microtask.dart 41                                      _microtaskLoop
dart:async/schedule_microtask.dart 50                                      _startMicrotaskLoop
dart:isolate-patch/isolate_patch.dart 96                                   _runPendingImmediateCallback
dart:isolate-patch/isolate_patch.dart 149                                  _RawReceivePortImpl._handleMessage


Command[vm]: DART_CONFIGURATION=ReleaseX64 out/ReleaseX64/dart --enable_asserts --enable_type_checks --error_on_bad_type --error_on_bad_override --ignore-unrecognized-flags --packages=/mnt/data/b/build/slave/vm-linux-release-x64-be/build/sdk/.packages /mnt/data/b/build/slave/vm-linux-release-x64-be/build/sdk/runtime/observatory/tests/service/pause_on_start_then_step_test.dart
Took 0:00:02.102673

kmillikin pushed a commit that referenced this issue Feb 3, 2017
These test have (unexpectedly) different event timestamps.  This is
issue #28624.

BUG=
R=dmitryas@google.com

Review-Url: https://codereview.chromium.org/2671613007 .
@jensjoha
Copy link
Contributor

jensjoha commented Feb 3, 2017

I started getting this a lot locally so I investigated a bit.

I inserted some more debug printing and got this:

>testee>out> [+952ms] Isolate out.dill$main-78118322 processing service request getIsolate
>testee>out> Set timestamp to 1486130145994 (from 4)
>testee>out> Adding pauseEvent at 2
>testee>out> Returning timestamp: 1486130145994
>testee>out> [+955ms] Isolate out.dill$main-78118322 processed service request getIsolate (3731us)
>testee>out> [+955ms] Isolate vm-service deferring OOB interrupts
>testee>out> Set timestamp to 1486130145995 (from 3)
>testee>out> Returning timestamp: 1486130145995
>testee>out> [+956ms] Isolate vm-service restoring OOB interrupts
>testee>out> vm-service: Pushing ServiceEvent(isolate='out.dill$main-78118322', kind='PauseStart') to stream Debug
Running out.dill [1/1]
Getting stream...
Subscribing...
Subscribed.  Pause event is Instance of 'PauseStartEvent'
Subscription cancelled.
Done waiting for pause event.
>testee>out> [+965ms] Isolate vm-service deferring OOB interrupts
>testee>out> [+965ms] Isolate vm-service restoring OOB interrupts
>testee>out> [+994ms] Isolate out.dill$main-78118322 processing service request getIsolate
>testee>out> Set timestamp to 1486130145995 (from 3)
>testee>out> Adding pauseEvent at 2
>testee>out> Returning timestamp: 1486130145995
>testee>out> [+994ms] Isolate out.dill$main-78118322 processed service request getIsolate (421us)
** Killing script
Unexpected exception in service tests: Expected: <1486130145995>
  Actual: <1486130145994>

The important parts seems to be:

Set timestamp to 1486130145994 (from 4)
Adding pauseEvent at 2
Set timestamp to 1486130145995 (from 3)
Set timestamp to 1486130145995 (from 3)
Adding pauseEvent at 2

where "Adding pauseEvent at 2" is from runtime/vm/isolate.cc, Isolate::PrintJSON, case "else if (message_handler()->is_paused_on_start() || message_handler()->should_pause_on_start())".

and Set timestamp to x (from y) is from runtime/vm/service_event.cc, ServiceEvent::ServiceEvent :

  if ((event_kind == ServiceEvent::kPauseStart) &&
      !isolate->message_handler()->is_paused_on_start()) {
    // We will pause on start but the message handler lacks a valid
    // paused timestamp because we haven't paused yet. Use the current time.
    timestamp_ = OS::GetCurrentTimeMillis();
    printf("Set timestamp to %ld (from 4)\n", timestamp_);
  } else if ((event_kind == ServiceEvent::kPauseStart) ||
             (event_kind == ServiceEvent::kPauseExit)) {
    timestamp_ = isolate->message_handler()->paused_timestamp();
    printf("Set timestamp to %ld (from 3)\n", timestamp_);
  } else if (event_kind == ServiceEvent::kResume) {
    timestamp_ = isolate->last_resume_timestamp();
    printf("Set timestamp to %ld (from 2)\n", timestamp_);
  }

so at least in this case, the test seems to have started and gone into the "I'm paused state" while the vm haven't actually paused yet ("from 4"). Then the test runs reload, the vm actually has paused ("from 3")...

@jensjoha
Copy link
Contributor

jensjoha commented May 5, 2017

Just as a note this happens quite often (at least to me) (even when not running from kernel) when run in a loop (for instance running a number of terminals with this loop). E.g. something like

 a=0; while [ 1 ]; do echo -n $'\r'$a ; out/DebugX64/dart --enable_asserts --enable_type_checks --error_on_bad_type --error_on_bad_override --ignore-unrecognized-flags --packages=.packages runtime/observatory/tests/service/pause_on_start_then_step_test.dart > /dev/null; a=$((a+1)); done

I then at least gets something like this quite often:

Unhandled exception:
Expected: <1493979402765>
  Actual: <1493979402735>

#0      _ServiceTesterRunner.run.<anonymous closure> ([...]/runtime/observatory/tests/service/test_helper.dart:341:9)
<asynchronous suspension>
#1      _rootRunBinary (dart:async/zone.dart:1144)
#2      _RootZone.runBinary (dart:async/zone.dart:1377)
#3      runZoned.<anonymous closure> (dart:async/zone.dart:1443)
#4      _CustomZone.handleUncaughtError (dart:async/zone.dart:981)
#5      _Future._propagateToListeners (dart:async/future_impl.dart:552)
#6      _Future._completeError (dart:async/future_impl.dart:486)
#7      _SyncCompleter._completeError (dart:async/future_impl.dart:55)
#8      _Completer.completeError (dart:async/future_impl.dart:27)
#9      _ServiceTesterRunner.run.<anonymous closure>.<anonymous closure> ([...]/runtime/observatory/tests/service/test_helper.dart:333:7)
<asynchronous suspension>
#10     _rootRunUnary (dart:async/zone.dart:1128)
#11     _CustomZone.runUnary (dart:async/zone.dart:1012)
#12     _FutureListener.handleValue (dart:async/future_impl.dart:129)
#13     _Future._propagateToListeners.handleValueCallback (dart:async/future_impl.dart:636)
#14     _Future._propagateToListeners (dart:async/future_impl.dart:665)
#15     _Future._completeWithValue (dart:async/future_impl.dart:478)
#16     _Future._asyncComplete.<anonymous closure> (dart:async/future_impl.dart:510)
#17     _rootRun (dart:async/zone.dart:1120)
#18     _CustomZone.run (dart:async/zone.dart:1001)
#19     _CustomZone.runGuarded (dart:async/zone.dart:901)
#20     _CustomZone.bindCallback.<anonymous closure> (dart:async/zone.dart:926)
#21     _microtaskLoop (dart:async/schedule_microtask.dart:41)
#22     _startMicrotaskLoop (dart:async/schedule_microtask.dart:50)
#23     _runPendingImmediateCallback (dart:isolate-patch/isolate_patch.dart:99)
#24     _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:152)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area-observatory area-vm Use area-vm for VM related issues, including code coverage, and the AOT and JIT backends. gardening
Projects
None yet
Development

No branches or pull requests

3 participants