New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 915041 link

Starred by 4 users

Issue metadata

Status: Fixed
Owner:
Closed: Jan 7
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Fuchsia
Pri: 1
Type: Bug-Regression



Sign in to add a comment

OneTaskSchedulerImplTestParams/TaskSchedulerImplTest.SchedulerWorkerObserver test is flaky

Project Member Reported by w...@chromium.org, Dec 14

Issue description

We've seen instances reported of base_unittests flaking on Fuchsia with output of the form:

---
[00040.815] <== fatal exception: process /pkg/base_unittests__exec[202069] thread TaskSchedulerSingleThreadBackgr[203146]
[00040.815] <== undefined instruction, PC at 0x5f363b74b87c
[00040.816]  CS:                   0 RIP:     0x5f363b74b87c EFL:            0x10202 CR2:                  0
[00040.816]  RAX:                0xa RBX:     0x5f363b804028 RCX:     0x63ba31800828 RDX:     0x5f363b8040b4
[00040.816]  RSI:      0x9a7512426d8 RDI:     0x5f363b804028 RBP:      0x9a751242c40 RSP:      0x9a751242878
[00040.816]   R8:                  0  R9:                  0 R10:                  0 R11:              0x246
[00040.816]  R12:      0x9a751242b28 R13:      0x9a751242a08 R14:      0x9a751242da8 R15:                  0
[00040.816]  errc:                 0
[00040.816] bottom of user stack:
[00040.816] 0x000009a751242878: 3fad0690 00002d74 00000000 00000000 |...?t-..........|
[00040.816] 0x000009a751242888: 51242da8 000009a7 51242c40 000009a7 |.-$Q....@,$Q....|
[00040.816] 0x000009a751242898: 00000070 00000000 00000318 00000000 |p...............|
[00040.816] 0x000009a7512428a8: 1c9915d5 00000000 00000043 00000000 |........C.......|
[00040.816] 0x000009a7512428b8: 3f07eb22 00002d74 51242b28 000009a7 |"..?t-..(+$Q....|
[00040.816] 0x000009a7512428c8: 51242a08 000009a7 5b97af67 8202d3b6 |.*$Q....g..[....|
[00040.816] 0x000009a7512428d8: 51242c40 000009a7 51242cb0 000009a7 |@,$Q.....,$Q....|
[00040.816] 0x000009a7512428e8: 51242c48 000009a7 3f07eb3b 00002d74 |H,$Q....;..?t-..|
[00040.816] 0x000009a7512428f8: 3f07eb22 00002d74 51242c40 000009a7 |"..?t-..@,$Q....|
[00040.816] 0x000009a751242908: 3f375169 00002d74 3fda5358 00002d74 |iQ7?t-..XS.?t-..|
[00040.816] 0x000009a751242918: 3fa9fb01 00002d74 51242c40 000009a7 |...?t-..@,$Q....|
[00040.816] 0x000009a751242928: 00000043 00000000 00000008 00000030 |C...........0...|
[00040.816] 0x000009a751242938: 51242960 000009a7 51242880 000009a7 |`)$Q.....($Q....|
[00040.816] 0x000009a751242948: 51242a08 000009a7 9b7fa7f8 000053e4 |.*$Q.........S..|
[00040.816] 0x000009a751242958: 3fad1587 00002d74 3fd7a590 00002d74 |...?t-.....?t-..|
[00040.816] 0x000009a751242968: 3fa9fe8d 00002d74 00000000 00000000 |...?t-..........|
[00040.816] arch: x86_64
[00040.816] dso: id=67a9a5b689915265e28cdaf84f84dfc853b73995 base=0x780aa3361000 name=libfdio.so
[00040.816] dso: id=c2f4882d7a78c26114ded2b85bb8b07703e258de base=0x63ba317f9000 name=<vDSO>
[00040.816] dso: id=55585d12cd93db9a1105ccb59a1155ff8982147e base=0x5f363b735000 name=libc.so
[00040.816] dso: id=b8426d36179cc65d646097ad3ec03bad4316420b base=0x4549aaaee000 name=libtrace-engine.so
[00040.816] dso: id=3f13bd7ae93ac61d base=0x2d743ef61000 name=app:/pkg/base_unittests__exec
[00040.816] dso: id=5e3c55aea09e8943ae76d3603cc8c0b1ba27bfb7 base=0xc6cfdba4000 name=libasync-default.so
[00040.816] dso: id=11ea1b2cadd51f86 base=0x3d669bfe000 name=libsvc.so
[00040.816] {{{reset}}}
[00040.816] {{{module:0x34646162:<VMO#202136=libsvc.so>:elf:11ea1b2cadd51f86}}}
[00040.816] {{{mmap:0x3d669bfe000:0x6000:load:0x34646162:r:0}}}
[00040.816] {{{mmap:0x3d669c04000:0x11000:load:0x34646162:rx:0x6000}}}
[00040.816] {{{mmap:0x3d669c15000:0x4000:load:0x34646162:rw:0x17000}}}
[00040.816] {{{module:0x34646163:<VMO#202120=libasync-default.so:elf:5e3c55aea09e8943ae76d3603cc8c0b1ba27bfb7}}}
[00040.816] {{{mmap:0xc6cfdba4000:0x1000:load:0x34646163:rx:0}}}
[00040.816] {{{mmap:0xc6cfdba5000:0x1000:load:0x34646163:rw:0x1000}}}
[00040.816] {{{module:0x34646164:<VMO#202128=data:libasync-defau:elf:5e3c55aea09e8943ae76d3603cc8c0b1ba27bfb7}}}
[00040.816] {{{mmap:0xc6cfdba5000:0x1000:load:0x34646164:rx:0}}}
[00040.816] {{{mmap:0xc6cfdba6000:0x1000:load:0x34646164:rw:0x1000}}}
[00040.816] {{{module:0x34646165:<VMO#202056=/pkg/base_unittests:elf:3f13bd7ae93ac61d}}}
[00040.816] {{{mmap:0x2d743ef61000:0x413000:load:0x34646165:r:0}}}
[00040.816] {{{mmap:0x2d743f374000:0x9a3000:load:0x34646165:rx:0x413000}}}
[00040.816] {{{mmap:0x2d743fd17000:0x96000:load:0x34646165:rw:0xdb6000}}}
[00040.816] {{{module:0x34646166:<VMO#202147=libtrace-engine.so>:elf:b8426d36179cc65d646097ad3ec03bad4316420b}}}
[00040.816] {{{mmap:0x4549aaaee000:0x9000:load:0x34646166:rx:0}}}
[00040.816] {{{mmap:0x4549aaaf7000:0x2000:load:0x34646166:rw:0x9000}}}
[00040.816] {{{module:0x34646167:<VMO#202073=ld.so.1>:elf:55585d12cd93db9a1105ccb59a1155ff8982147e}}}
[00040.816] {{{mmap:0x5f363b735000:0xcb000:load:0x34646167:rx:0}}}
[00040.816] {{{mmap:0x5f363b801000:0x6000:load:0x34646167:rw:0xcc000}}}
[00040.816] {{{module:0x34646168:<VMO#1033=vdso/full>:elf:c2f4882d7a78c26114ded2b85bb8b07703e258de}}}
[00040.816] {{{mmap:0x63ba317f9000:0x7000:load:0x34646168:r:0}}}
[00040.816] {{{mmap:0x63ba31800000:0x1000:load:0x34646168:rx:0x7000}}}
[00040.816] {{{module:0x34646169:<VMO#202094=libfdio.so>:elf:67a9a5b689915265e28cdaf84f84dfc853b73995}}}
[00040.816] {{{mmap:0x780aa3361000:0x22000:load:0x34646169:rx:0}}}
[00040.816] {{{mmap:0x780aa3383000:0x5000:load:0x34646169:rw:0x22000}}}
#01: pc 0x5f363b74b87c sp 0x9a751242878 (libc.so,0x1687c)
#02: __cxa_bad_typeid at cxa_aux_runtime.cpp:?
#03: __cxxabiv1::__aligned_malloc_with_fallback(unsigned long) at fallback_malloc.cpp:?
#04: testing::internal::UntypedFunctionMockerBase::UntypedInvokeWith(void*) at gmock-spec-builders.cc:?
#05: testing::internal::FunctionMockerBase<void (int)>::InvokeWith(std::__1::tuple<int>&&) at bind_unittest.cc:?
#06: testing::internal::FunctionMocker<void ()>::Invoke() at bind_unittest.cc:?
#07: base::internal::SchedulerWorker::RunWorker() at scheduler_worker.cc:?
#08: base::internal::SchedulerWorker::RunDedicatedWorker() at scheduler_worker.cc:?
#09: base::(anonymous namespace)::ThreadFunc(void*) at platform_thread_posix.cc:?
#10: pc 0x5f363b74c636 sp 0x9a751242fd0 (libc.so,0x17636)
#11: pc 0x5f363b7bbad1 sp 0x9a751242fe0 (libc.so,0x86ad1)
#12: pc 0 sp 0x9a751243000
[00040.818] {{{bt:1:0x5f363b74b87c}}}
[00040.818] {{{bt:2:0x2d743fad0690}}}
[00040.818] {{{bt:3:0x2d743fad1587}}}
[00040.818] {{{bt:4:0x2d743fa9fe8d}}}
[00040.818] {{{bt:5:0x2d743f38963c}}}
[00040.818] {{{bt:6:0x2d743f38961c}}}
[00040.819] {{{bt:7:0x2d743fb6b84a}}}
[00040.819] {{{bt:8:0x2d743fb6b70f}}}
[00040.819] {{{bt:9:0x2d743fbccb02}}}
[00040.819] {{{bt:10:0x5f363b74c636}}}
[00040.819] {{{bt:11:0x5f363b7bbad1}}}
[00040.819] {{{bt:12:0}}}
[00041.041] [204026:204038:20181206,004403.376398:WARNING process_reader_fuchsia.cc:283] zx_thread_read_state(ZX_THREAD_STATE_GENERAL_REGS): ZX_ERR_BAD_STATE (-20)
[00041.041] [204026:204038:20181206,004403.376443:WARNING process_reader_fuchsia.cc:295] zx_thread_read_state(ZX_THREAD_STATE_VECTOR_REGS): ZX_ERR_BAD_STATE (-20)
[00041.095] [204026:204038:20181206,004403.430811:ERROR file_io_posix.cc:148] open /data/crashes/settings.dat.__lock__: File exists (17)
[00041.242] pkgsvr: pkgfs:unsupported(/packages/base_unittests/0): dir unlink "base_unittests__exec.log"
[00041.274] pkgsvr: pkgfs:unsupported(/packages/base_unittests/0): dir unlink "base_unittests__exec.log"
[3851/4037] OneTaskSchedulerImplTestParams/TaskSchedulerImplTest.IdentifiableStacks/29 (5 ms)
[3852/4037] OneTaskSchedulerImplTestParams/TaskSchedulerImplTest.IdentifiableStacks/30 (4 ms)
[3853/4037] OneTaskSchedulerImplTestParams/TaskSchedulerImplTest.IdentifiableStacks/31 (2 ms)
[3854/4037] OneTaskSchedulerImplTestParams/TaskSchedulerImplTest.IdentifiableStacks/32 (5 ms)
[3855/4037] OneTaskSchedulerImplTestParams/TaskSchedulerImplTest.IdentifiableStacks/33 (15 ms)
[3856/4037] OneTaskSchedulerImplTestParams/TaskSchedulerImplTest.IdentifiableStacks/34 (7 ms)
[3857/4037] OneTaskSchedulerImplTestParams/TaskSchedulerImplTest.IdentifiableStacks/35 (5 ms)
[3858/4037] OneTaskSchedulerImplTestParams/TaskSchedulerImplTest.SchedulerWorkerObserver/0 (8 ms)
[ RUN      ] OneTaskSchedulerImplTestParams/TaskSchedulerImplTest.SchedulerWorkerObserver/1
../../base/task/task_scheduler/task_scheduler_impl_unittest.cc:901: Failure
Actual function call count doesn't match EXPECT_CALL(observer, OnSchedulerWorkerMainExit())...
         Expected: to be called 10 times
           Actual: called 9 times - unsatisfied and active
Stack trace:
#00: testing::internal::UnitTestImpl::CurrentOsStackTraceExceptTop(int) at gtest.cc:?
#01: testing::internal::AssertHelper::operator=(testing::Message const&) const at gtest.cc:?
#02: testing::internal::GoogleTestFailureReporter::ReportFailure(testing::internal::FailureReporterInterface::FailureType, char const*, int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) at gmock-internal-utils.cc:?
#03: testing::internal::UntypedFunctionMockerBase::VerifyAndClearExpectationsLocked() at gmock-spec-builders.cc:?
#04: testing::internal::FunctionMockerBase<void ()>::~FunctionMockerBase() at bind_unittest.cc:?
#05: base::internal::test::MockSchedulerWorkerObserver::~MockSchedulerWorkerObserver() at test_utils.cc:?
#06: base::internal::TaskSchedulerImplTest_SchedulerWorkerObserver_Test::TestBody() at task_scheduler_impl_unittest.cc:?
[00041.301] pkgsvr: pkgfs:unsupported(/packages/base_unittests/0): dir unlink "base_unittests__exec.log"

Pure virtual function called!
---

It looks like the test is tearing down a mock object while there are still tasks pending which will touch it.
 
Realised this was just raciness between EXPECT_CALL and actual calls to an observer API, posted a test fix:
https://chromium-review.googlesource.com/c/chromium/src/+/1377380

Project Member

Comment 3 by bugdroid1@chromium.org, Dec 18

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/18fa9e2f6f60f6c1cbc83031549b080578afd4ad

commit 18fa9e2f6f60f6c1cbc83031549b080578afd4ad
Author: Francois Doray <fdoray@chromium.org>
Date: Tue Dec 18 21:32:25 2018

TaskScheduler: Fix races in TaskSchedulerImplTest.SchedulerWorkerObserver.

Previously, the 30 seconds detach time in
TaskSchedulerImplTest.SchedulerWorkerObserver allowed threads to detach
and call OnSchedulerWorkerMainExit() before expectations were set for
calls to this method. This CL avoids this race by changing the detach
time to TimeDelta::Max().

Also, previously, it wasn't guaranteed that DEDICATED workers had called
OnSchedulerWorkerMainExit() by the time the observer was destroyed.
Indeed, when DEDICATED tasks and |task_runners.clear()| have run,
references to DEDICATED workers in SchedulerSingleThreadTaskRunnerManager
are released (this happens before the worker calls
OnSchedulerWorkerMainExit()). JoinForTesting() doesn't join DEDICATED
workers which are not referenced in
SchedulerSingleThreadTaskRunnerManager. The test body can therefore exit
and the observer be destroyed before all DEDICATED workers have called
OnSchedulerWorkerMainExit(). This CL fixes the issue by waiting for all
expected calls to happen before exiting the test body.

Bug:  915041 
Change-Id: I57deddf4403f3028f248bf43568889d1a0e8709d
Reviewed-on: https://chromium-review.googlesource.com/c/1380969
Commit-Queue: François Doray <fdoray@chromium.org>
Reviewed-by: Gabriel Charette <gab@chromium.org>
Cr-Commit-Position: refs/heads/master@{#617627}
[modify] https://crrev.com/18fa9e2f6f60f6c1cbc83031549b080578afd4ad/base/task/task_scheduler/scheduler_worker_unittest.cc
[modify] https://crrev.com/18fa9e2f6f60f6c1cbc83031549b080578afd4ad/base/task/task_scheduler/task_scheduler_impl_unittest.cc
[modify] https://crrev.com/18fa9e2f6f60f6c1cbc83031549b080578afd4ad/base/task/task_scheduler/test_utils.cc
[modify] https://crrev.com/18fa9e2f6f60f6c1cbc83031549b080578afd4ad/base/task/task_scheduler/test_utils.h

Owner: fdoray@chromium.org
fdoray: Looks like this is Fixed?
Status: Fixed (was: Started)

Sign in to add a comment