Service Test flaky with runtime/vm/thread.cc:157: error: expected: !isolate->HasMutatorThread()

[iposva-google]

From http://build.chromium.org/p/client.dart/builders/vm-linux-debug-ia32-be/builds/4843/steps/tests/logs/stdio :

FAILED: none-vm debug_ia32 service/pause_on_start_and_exit_test
Expected: Pass
Actual: RuntimeError
CommandOutput[vm]:

stdout:
** Launching out/DebugIA32/dart --trace-service --pause-isolates-on-start --pause-isolates-on-exit --error_on_bad_type --error_on_bad_override --ignore-unrecognized-flags --package-root=out/DebugIA32/packages/ --enable-vm-service:0 /mnt/data/b/build/slave/vm-linux-debug-ia32-be/build/sdk/runtime/observatory/tests/service/pause_on_start_and_exit_test.dart --testee-mode
vm-service: Booting dart:vmservice library.
vm-service: Registering running isolates.
vm-service: Isolate pause_on_start_and_exit_test.dart$main-743971132 743971132 registered.
** Signaled to run test queries on 57502
Observatory listening on http://127.0.0.1:57502
vm-service: Dropping event of type PauseStart (pause_on_start_and_exit_test.dart$main-743971132)
vm-service: starting stream 'Isolate'
vm-service: starting stream 'Debug'
vm-service: starting stream '_Graph'
Isolate vm-service processing service request getVM
Isolate vm-service processed service request getVM in 84 us.
Running pause_on_start_and_exit_test.dart [1/1]
Getting stream...
Subscribing...
Subscribed. Pause event is ServiceEvent(owner='isolates/743971132', kind='PauseStart')
Subscription cancelled.
Done waiting for pause event.
Isolate pause_on_start_and_exit_test.dart$main-743971132 processing service request getIsolate
Isolate pause_on_start_and_exit_test.dart$main-743971132 processed service request getIsolate in 1116 us.
Isolate pause_on_start_and_exit_test.dart$main-743971132 processing service request getIsolate
Isolate pause_on_start_and_exit_test.dart$main-743971132 processed service request getIsolate in 1131 us.
VM-VERBOSE: pause_on_start_and_exit_test.dart$main reloaded. pause event= ServiceEvent(owner='isolates/743971132', kind='PauseStart')
Resuming...
VM-VERBOSE: pause_on_start_and_exit_test.dart$main _onEvent ServiceEvent(owner='isolates/743971132', kind='Resume')
VM-VERBOSE: pause_on_start_and_exit_test.dart$main pause event ServiceEvent(owner='isolates/743971132', kind='Resume')
Isolate pause_on_start_and_exit_test.dart$main-743971132 processing service request resume
vm-service: Pushing event of type Resume to stream Debug (pause_on_start_and_exit_test.dart$main-743971132)
Isolate pause_on_start_and_exit_test.dart$main-743971132 processed service request resume in 60 us.
Hello
vm-service: Pushing event of type PauseExit to stream Debug (pause_on_start_and_exit_test.dart$main-743971132)
VM-VERBOSE: pause_on_start_and_exit_test.dart$main _onEvent ServiceEvent(owner='isolates/743971132', kind='PauseExit')
VM-VERBOSE: pause_on_start_and_exit_test.dart$main pause event ServiceEvent(owner='isolates/743971132', kind='PauseExit')
Received PauseExit
runtime/vm/thread.cc:157: error: expected: !isolate->HasMutatorThread()
** Killing script

stderr:
Unhandled exception:
Uncaught Error: Testee exited with -6
Stack Trace:
#0 _TestLauncher.launch.. (file:///mnt/data/b/build/slave/vm-linux-debug-ia32-be/build/sdk/runtime/observatory/tests/service/test_helper.dart:79:11)
#1 _RootZone.runUnary (dart:async/zone.dart:1165)
#2 _Future._propagateToListeners.handleValueCallback (dart:async/future_impl.dart:502)
#3 _Future._propagateToListeners (dart:async/future_impl.dart:585)
#4 _Future._completeWithValue (dart:async/future_impl.dart:376)
#5 _Future._asyncComplete. (dart:async/future_impl.dart:430)
#6 _microtaskLoop (dart:async/schedule_microtask.dart:43)
#7 _microtaskLoopEntry (dart:async/schedule_microtask.dart:52)
#8 _runPendingImmediateCallback (dart:isolate-patch/isolate_patch.dart:96)
#9 _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:149)
#0 _rootHandleUncaughtError. (dart:async/zone.dart:894)
#1 _microtaskLoop (dart:async/schedule_microtask.dart:43)
#2 _microtaskLoopEntry (dart:async/schedule_microtask.dart:52)
#3 _runPendingImmediateCallback (dart:isolate-patch/isolate_patch.dart:96)
#4 _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:149)

[iposva-google]

cc @kodandersson @turnidge @rmacnak-google

[iposva-google]

Split from #24222

[kodandersson]

Managed to get a core dump of this happening on debug ia32.

When examining it with gdb, isolate->mutator_thread_ is actually 0x0, which suggests there is a race between isolate entry/exit, i.e., the store of isolate->ClearMutatorThread() in Thread::ExitIsolate is not yet observed by the thread entering the same isolate.

[kodandersson]

(gdb) bt
#0 0xf779f440 in __kernel_vsyscall ()
#1 0xf747c607 in raise () from /lib/i386-linux-gnu/libc.so.6
#2 0xf747fa33 in abort () from /lib/i386-linux-gnu/libc.so.6
#3 0x081d37c5 in dart::DynamicAssertionHelper::Fail (this=this@entry=0xf692b1f4, format=format@entry=0x873dae8 "expected: %s") at runtime/platform/assert.cc:41
#4 0x0850280d in dart::Thread::EnterIsolate (isolate=isolate@entry=0xa0bed70) at runtime/vm/thread.cc:157
#5 0x08373db7 in StartIsolateScope (new_isolate=0xa0bed70, this=) at runtime/vm/isolate.h:994
#6 dart::MessageHandler::HandleMessages (this=this@entry=0xa08d508, allow_normal_messages=allow_normal_messages@entry=true,
allow_multiple_normal_messages=allow_multiple_normal_messages@entry=true) at runtime/vm/message_handler.cc:150
#7 0x08374390 in dart::MessageHandler::TaskCallback (this=0xa08d508) at runtime/vm/message_handler.cc:281
#8 0x08504dce in dart::ThreadPool::Worker::Loop (this=this@entry=0xa07ce88) at runtime/vm/thread_pool.cc:277
#9 0x08504fe8 in dart::ThreadPool::Worker::Main (args=args@entry=168283784) at runtime/vm/thread_pool.cc:320
#10 0x084089bd in dart::ThreadStart (data_ptr=0xa07cee8) at runtime/vm/os_thread_linux.cc:94
#11 0xf775cf70 in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
#12 0xf7539bee in clone () from /lib/i386-linux-gnu/libc.so.6

(gdb) frame 4
#4 0x0850280d in dart::Thread::EnterIsolate (isolate=isolate@entry=0xa0bed70) at runtime/vm/thread.cc:157
157 ASSERT(!isolate->HasMutatorThread());
(gdb) print isolate
$2 = (dart::Isolate ) 0xa0bed70
(gdb) print *isolate
$3 = {dart::BaseIsolate = {mutator_thread = 0x0, no_callback_scope_depth_ = 0}, static kStackSizeBuffer = 16384, static kNoDeoptId = -1, static kDeoptIdStep = 2,
static kDeoptIdBeforeOffset = 0, static kDeoptIdAfterOffset = 1, vm_tag_ = 1, store_buffer_ = 0xa08d180, thread_registry_ = 0xa08d1b8, class_table_ = {
static initial_capacity_ = 512, static capacity_increment_ = 256, top_ = 1721, capacity_ = 1788, table_ = 0xf4b40128, old_tables_ = 0xa08d230,
class_heap_stats_table_ = 0xa0c96c0, predefined_class_heap_stats_table_ = 0xa0c3368}, megamorphic_cache_table_ = {static kCapacityIncrement = 128,
miss_handler_function_ = 0xf5aff071, miss_handler_code_ = 0xf5aff021, capacity_ = 0, length_ = 0, table_ = 0x0}, message_notify_callback_ = 0x0,
name_ = 0xa08d590 "pause_on_start_and_exit_test.dart$main-223707640", debugger_name_ = 0xa09db88 "pause_on_start_and_exit_test.dart$main",
start_time_ = 1440707472395452, main_port_ = 223707640, origin_id_ = 223707640, pause_capability_ = 3916257114624138963, terminate_capability_ = 1641046457328255064,
errors_fatal_ = true, heap_ = 0xa0c2410, object_store_ = 0xa09dc18, top_exit_frame_info_ = 0, init_callback_data_ = 0xa07cfe8,
environment_callback_ = 0x817bde0 dart::bin::EnvironmentCallback(Dart_Handle), library_tag_handler_ = 0x81beac0
<dart::bin::DartUtils::LibraryTagHandler(Dart_LibraryTag, Dart_Handle, Dart_Handle*)>, api_state = 0xa08b888, debugger_ = 0xa09dbb8, single_step_ = false,
resume_request_ = false, last_resume_timestamp_ = 1440707472395, has_compiled_ = true, flags_ = {dart::ValueObject = {}, type_checks_ = true,
asserts_ = true, error_on_bad_type_ = true, error_on_bad_override_ = true}, random_ = {state = 5472454886535525751}, simulator = 0x0,
timer_list_ = {dart::ValueObject = {}, time_script_loading_ = {dart::ValueObject = {}, start_ = 1440707476120714,
stop_ = 1440707476121090, total_ = 723066, max_contiguous_ = 127897, report_ = false, running_ = false, message_ = 0x896de44 "Script Loading"},
time_creating_snapshot_ = {dart::ValueObject = {}, start_ = 0, stop_ = 0, total_ = 0, max_contiguous_ = 0, report_ = false, running_ = false,
message_ = 0x896de53 "Snapshot Creation"}, time_isolate_initialization_ = {dart::ValueObject = {}, start_ = 1440707472396893,
stop_ = 1440707472444822, total_ = 47929, max_contiguous_ = 47929, report_ = false, running_ = false, message_ = 0x896de65 "Isolate initialization"},
time_compilation_ = {dart::ValueObject = {}, start_ = 1440707476868604, stop_ = 1440707476868719, total_ = 683567, max_contiguous_ = 54443,
report_ = false, running_ = false, message_ = 0x896de7c "Function compilation"}, time_bootstrap_ = {dart::ValueObject = {},
start_ = 1440707472396926, stop_ = 1440707472397038, total_ = 112, max_contiguous_ = 112, report_ = false, running_ = false,
message_ = 0x896de91 "Bootstrap of core classes"}, time_dart_execution_ = {dart::ValueObject = {}, start_ = 1440707476824289,
stop_ = 1440707476869042, total_ = 1396661, max_contiguous_ = 296457, report_ = false, running_ = false, message_ = 0x896deab "Dart execution"},
time_total_runtime_ = {dart::ValueObject = {}, start_ = 1440707472444824, stop_ = 0, total_ = 0, max_contiguous_ = 0, report_ = false,
running_ = true, message_ = 0x896deba "Total runtime for isolate"}, time_gc_ = {dart::ValueObject = {}, start_ = 1440707476088993,
stop_ = 1440707476099184, total_ = 14403, max_contiguous_ = 10191, report_ = false, running_ = false, message_ = 0x896ded4 "Garbage collection"}, padding_ = false},
deopt_id_ = 0, mutex_ = 0xa08d248, stack_limit_ = 4294967290, saved_stack_limit_ = 4294967295, stack_base_ = 0, stack_overflow_flags_ = 0, stack_overflow_count_ = 0,
message_handler_ = 0xa08d508, spawn_state_ = 0x0, is_runnable_ = true, gc_prologue_callback_ = 0x0, gc_epilogue_callback_ = 0x0, defer_finalization_count_ = 0,
deopt_context_ = 0x0, edge_counter_increment_size_ = 23, compiler_stats_ = 0x0, is_service_isolate_ = false, log_ = 0xa08d268, stacktrace_ = 0x0,
stack_frame_index_ = -1, last_allocationprofile_accumulator_reset_timestamp_ = 0, last_allocationprofile_gc_timestamp_ = 0, object_id_ring_ = 0xa09dbf8,
trace_buffer_ = 0x0, profiler_data_ = 0xa07d008, profiler_data_mutex_ = {data_ = {mutex_ = {data = {lock = 0, count = 0, owner = 0, kind = 2, nusers = 0, {
d = {espins = 0, elision = 0}, list = {next = 0x0}}}, size = '\000' <repeats 12 times>, "\002\000\000\000\000\000\000\000\000\000\000",
align = 0}}, owner = 0}, vm_tag_counters = {counters = {0, 0, 1738, 0 <repeats 15 times>}}, user_tag = 16534, tag_table = 0xf5b867a9,
current_tag = 0xf5aff0b9, default_tag = 0xf5aff0b9, collected_closures = 0xf696c021, deoptimized_code_array = 0xf696c021,
pending_service_extension_calls = 0xf696c021, registered_service_extension_handlers = 0xf696c021, metrics_list_head = 0xa0c21b0, counters = {counters = {{
name = 0x0, value = 0} <repeats 1024 times>}, collision = false}, compilation_allowed = true, cha = 0x0, next = 0xa061860, pause_loop_monitor = 0x0,
AbstractType_handle = 0xa0c21fc, Array_handle = 0xa0c2204, Class_handle = 0xa0c220c, Code_handle = 0xa0c2214, Error_handle = 0xa0c221c,
ExceptionHandlers_handle_ = 0xa0c2224, Field_handle_ = 0xa0c222c, Function_handle_ = 0xa0c2234, GrowableObjectArray_handle_ = 0xa0c223c, Instance_handle_ = 0xa0c2244,
Library_handle_ = 0xa0c224c, Object_handle_ = 0xa0c2254, PcDescriptors_handle_ = 0xa0c225c, String_handle_ = 0xa0c2264, TypeArguments_handle_ = 0xa0c226c,
TypeParameter_handle_ = 0xa0c2274, reusable_AbstractType_handle_scope_active_ = false, reusable_Array_handle_scope_active_ = false,
reusable_Class_handle_scope_active_ = false, reusable_Code_handle_scope_active_ = false, reusable_Error_handle_scope_active_ = false,
reusable_ExceptionHandlers_handle_scope_active_ = false, reusable_Field_handle_scope_active_ = false, reusable_Function_handle_scope_active_ = false,
reusable_GrowableObjectArray_handle_scope_active_ = false, reusable_Instance_handle_scope_active_ = false, reusable_Library_handle_scope_active_ = false,
reusable_Object_handle_scope_active_ = false, reusable_PcDescriptors_handle_scope_active_ = false, reusable_String_handle_scope_active_ = false,
reusable_TypeArguments_handle_scope_active_ = false, reusable_TypeParameter_handle_scope_active_ = false, metric_HeapOldUsed_ = {dart::Metric = {
vptr.Metric = 0x894e718 <vtable for dart::MetricHeapOldUsed+8>, isolate = 0xa0bed70, name_ = 0x894b61d "heap.old.used", description_ = 0x0,
unit_ = dart::Metric::kByte, value_ = 0, next_ = 0x0, static vm_list_head_ = 0x8ac74e0 dart::vm_metric_IsolateCount_}, },
metric_HeapOldCapacity_ = {dart::Metric = {vptr.Metric = 0x894e730 <vtable for dart::MetricHeapOldCapacity+8>, isolate = 0xa0bed70,
name_ = 0x894b62b "heap.old.capacity", description_ = 0x0, unit_ = dart::Metric::kByte, value_ = 0, next_ = 0xa0c2110,
static vm_list_head_ = 0x8ac74e0 dart::vm_metric_IsolateCount_}, }, metric_HeapOldExternal_ = {dart::Metric = {
vptr.Metric = 0x894e748 <vtable for dart::MetricHeapOldExternal+8>, isolate = 0xa0bed70, name_ = 0x894b63d "heap.old.external", description_ = 0x0,
unit_ = dart::Metric::kByte, value_ = 0, next_ = 0xa0c2130, static vm_list_head_ = 0x8ac74e0 dart::vm_metric_IsolateCount_}, },
metric_HeapNewUsed_ = {dart::Metric = {vptr.Metric = 0x894e760 <vtable for dart::MetricHeapNewUsed+8>, isolate = 0xa0bed70, name_ = 0x894b64f "heap.new.used",
description_ = 0x0, unit_ = dart::Metric::kByte, value_ = 0, next_ = 0xa0c2150, static vm_list_head_ = 0x8ac74e0 dart::vm_metric_IsolateCount_}, },
metric_HeapNewCapacity_ = {dart::Metric = {vptr.Metric = 0x894e778 <vtable for dart::MetricHeapNewCapacity+8>, isolate = 0xa0bed70,
name_ = 0x894b65d "heap.new.capacity", description_ = 0x0, unit_ = dart::Metric::kByte, value_ = 0, next_ = 0xa0c2170,
static vm_list_head_ = 0x8ac74e0 dart::vm_metric_IsolateCount_}, }, metric_HeapNewExternal_ = {dart::Metric = {
vptr.Metric = 0x894e790 <vtable for dart::MetricHeapNewExternal+8>, isolate = 0xa0bed70, name_ = 0x894b66f "heap.new.external", description_ = 0x0,
unit_ = dart::Metric::kByte, value_ = 0, next_ = 0xa0c2190, static vm_list_head_ = 0x8ac74e0 dart::vm_metric_IsolateCount_}, }, stream_API_ = {
name_ = 0x894b681 "API", enabled_ = false}, stream_Compiler_ = {name_ = 0x894b685 "Compiler", enabled_ = false}, stream_Embedder_ = {name_ = 0x894b68e "Embedder",
enabled_ = false}, stream_GC_ = {name_ = 0x895bbd5 "GC", enabled_ = false}, stream_Isolate_ = {name_ = 0x894b8b1 "Isolate", enabled_ = false},
reusable_handles_ = {<dart::Handles<2, 64, 4>> = {zone_blocks_ = 0x0, first_scoped_block_ = {data_ = {144017992, 4137074721, 144023176, 4137074721, 144008584,
4137074721, 144014760, 4137074721, 144016200, 4137074721, 144014152, 4137074721, 144010600, 4137074721, 144009736, 4137074721, 144023496, 4137074721, 144017672,
4137074721, 144011784, 4137074721, 144008584, 4137074721, 144013288, 4137074721, 144022536, 4137074721, 144009160, 4137074721, 144019240, 4137074721,
2880154539 <repeats 33 times>, 0, 0, 0, 2113, 168569688, 4150232144, 0, 0, 2880154539 <repeats 55 times>}, next_handle_slot_ = 32, next_block_ = 0x0},
scoped_blocks_ = 0xa0c21fc}, static kOffsetOfRawPtrInHandle = 4}, static create_callback_ =
0x817c5d0 <dart::bin::CreateIsolateAndSetup(char const*, char const*, char const*, Dart_IsolateFlags*, void*, char**)>, static interrupt_callback_ = 0x0,
static unhandled_exception_callback_ = 0x0, static shutdown_callback_ = 0x817c170 dart::bin::ShutdownIsolate(void*),
static file_open_callback_ = 0x81bce60 <dart::bin::DartUtils::OpenFile(char const*, bool)>,
static file_read_callback_ = 0x81bce80 <dart::bin::DartUtils::ReadFile(unsigned char const**, int*, void*)>,
static file_write_callback_ = 0x81bd000 <dart::bin::DartUtils::WriteFile(void const*, int, void*)>,
static file_close_callback_ = 0x81bd0a0 dart::bin::DartUtils::CloseFile(void*),
static entropy_source_callback_ = 0x81bd0d0 <dart::bin::DartUtils::EntropySource(unsigned char*, int)>, static vmstats_callback_ = ,
static isolates_list_monitor_ = 0xa061278, static isolates_list_head_ = 0xf61004f8}

[kodandersson]

... no other threads are doing anything interesting (anymore).

[turnidge]

Commited 01c1d2c.

Let's watch the bots and see if this fixes it. It should.

[turnidge]

Closing. Please reopen if you see this again.