New issue
Advanced search Search tips

Issue 684640 link

Starred by 2 users

Issue metadata

Status: Assigned
Owner:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: Bug


Sign in to add a comment

Fix improper usages of the base::Timer API

Project Member Reported by gab@chromium.org, Jan 24 2017

Issue description

Improved the impl in https://codereview.chromium.org/2491613004/ and had to comment out some thread-safety assertions as it currently fails in existing tests...

TODO re-enable assertions in timer.cc
 

Comment 1 by gab@chromium.org, Jan 25 2017

Identified problematic use cases:

SyncBrowserThreadModelWorkerTest.DoesWorkOnDatabaseThread (run #1):
[ RUN      ] SyncBrowserThreadModelWorkerTest.DoesWorkOnDatabaseThread
[6916:2808:0123/195343.636:38250883:FATAL:timer.cc(150)] Check failed: origin_sequence_checker_.CalledOnValidSequence().
Backtrace:
	base::debug::StackTrace::StackTrace [0x01DF27F7+23]
	logging::LogMessage::~LogMessage [0x01D7F221+49]
	base::Timer::Stop [0x01DD050B+91]
	testing::internal::TestFactoryImpl<syncer::`anonymous namespace'::SyncBrowserThreadModelWorkerTest_DoesWorkOnDatabaseThread_Test>::CreateTest [0x00C4A22B+458]
	base::internal::RunMixin<base::Callback<bool __cdecl(void),1,1> >::Run [0x0115609D+25]
	base::internal::FunctorTraits<void (__thiscall syncer::BrowserThreadModelWorker::*)(base::Callback<enum syncer::SyncerError __cdecl(void),1,1> const &,syncer::ScopedEventSignal,enum syncer::SyncerError *),void>::Invoke<scoped_refptr<syncer::BrowserThreadM [0x025FBBD7+41]
	base::internal::Invoker<base::internal::BindState<void (__thiscall syncer::BrowserThreadModelWorker::*)(base::Callback<enum syncer::SyncerError __cdecl(void),1,1> const &,syncer::ScopedEventSignal,enum syncer::SyncerError *),scoped_refptr<syncer::BrowserT [0x025FBC08+46]
	base::internal::Invoker<base::internal::BindState<void (__thiscall syncer::BrowserThreadModelWorker::*)(base::Callback<enum syncer::SyncerError __cdecl(void),1,1> const &,syncer::ScopedEventSignal,enum syncer::SyncerError *),scoped_refptr<syncer::BrowserT [0x025FBF14+22]
	base::debug::TaskAnnotator::RunTask [0x01E0136F+383]
	base::MessageLoop::RunTask [0x01D839CC+1228]
	base::MessageLoop::DoWork [0x01D82953+611]
	base::MessagePumpDefault::Run [0x01E0327A+106]
	base::MessageLoop::RunHandler [0x01D834F1+305]
	base::RunLoop::Run [0x01D86D54+132]
	base::Thread::Run [0x01D9F7BD+173]
	base::Thread::ThreadMain [0x01DA02DE+622]


UploadProgressTrackerTest.Completed (run #1):
[ RUN      ] UploadProgressTrackerTest.Completed
[1672:5348:0123/195348.490:32129965:FATAL:thread_task_runner_handle.cc(26)] Check failed: current.
Backtrace:
	base::debug::StackTrace::StackTrace [0x02A0CFD7+23]
	logging::LogMessage::~LogMessage [0x029B8B01+49]
	base::ThreadTaskRunnerHandle::Get [0x029C5B26+150]
	base::SequencedTaskRunnerHandle::Get [0x02A17D3E+494]
	base::Timer::PostNewScheduledTask [0x029EAD42+226]
	base::Timer::Reset [0x029EB0CF+303]
	base::Timer::Start [0x029EB3B3+131]
	base::BaseTimerMethodPointer::Start<content::UploadProgressTracker> [0x0218773E+62]
	content::UploadProgressTracker::UploadProgressTracker [0x0213A2E8+197]
	content::UploadProgressTrackerTest::UploadProgressTrackerTest [0x012906F0+182]
	testing::internal::TestFactoryImpl<content::UploadProgressTrackerTest_Completed_Test>::CreateTest [0x0128F7FC+25]
	testing::TestInfo::Run [0x02879ECE+101]
	testing::TestCase::Run [0x02879E12+133]
	testing::internal::UnitTestImpl::RunAllTests [0x0287A192+433]


MediaCodecLoopTest.TestOnKeyAdded (run #1):
[ RUN      ] MediaCodecLoopTest.TestOnKeyAdded
[3044:3616:0123/195445.416:30971346:FATAL:thread_task_runner_handle.cc(26)] Check failed: current.
Backtrace:
	base::debug::StackTrace::StackTrace [0x01790C97+23]
	logging::LogMessage::~LogMessage [0x0176EAA1+49]
	base::ThreadTaskRunnerHandle::Get [0x017859C6+150]
	base::SequencedTaskRunnerHandle::Get [0x017C12FE+494]
	base::Timer::PostNewScheduledTask [0x0179FF82+226]
	base::Timer::Reset [0x017A02FF+303]
	base::Timer::Start [0x017A05E3+131]
	base::BaseTimerMethodPointer::Start<media::RemoteRendererImpl> [0x01722F01+62]
	media::MediaCodecLoop::ManageTimer [0x0172368F+238]
	media::MediaCodecLoop::DoPendingWork [0x0172333F+63]
	media::MediaCodecLoopTest_TestOnKeyAdded_Test::TestBody [0x0171556F+125]
	testing::internal::HandleExceptionsInMethodIfSupported<testing::TestCase,void> [0x01D22E2C+32]
	testing::Test::Run [0x01D29E0B+93]
	testing::TestCase::Run [0x01D29EB7+133]
	testing::internal::UnitTestImpl::RunAllTests [0x01D2A236+433]
	testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl,bool> [0x01D22E70+32]
	testing::UnitTest::Run [0x01D2A060+133]
	base::TestSuite::Run [0x01D344A4+95]
	base::internal::RunMixin<base::Callback<bool __cdecl(void),1,1> >::Run [0x01835986+25]
	base::LaunchUnitTests [0x01D32551+77]
	main [0x0168F480+95]
	__scrt_common_main_seh [0x01D7A728+249] (f:\ddctools\crtcstartup\src\startup\exe_common.inl:253)
	BaseThreadInitThunk [0x7530336A+18]
	RtlInitializeExceptionChain [0x776A9882+99]
	RtlInitializeExceptionChain [0x776A9855+54]

Comment 2 by gab@chromium.org, Jan 25 2017

1) A racy test
2&3) Test that rely on the TaskRunner in SetTaskRunner() being the one the delay is posted to (my CL is changing that to the current SequencedTaskRunnerHandle)
Project Member

Comment 3 by bugdroid1@chromium.org, Jan 25 2017

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

commit 3c942aae9aaa0a5a04314090526d8f24560d65a6
Author: gab <gab@chromium.org>
Date: Wed Jan 25 20:10:07 2017

Don't call Timer::Stop() off-sequence in SyncBrowserThreadModelWorkerTest

Timer isn't thread-safe and this call is racy as highlighted by
https://codereview.chromium.org/2491613004/#ps420001

SyncBrowserThreadModelWorkerTest.DoesWorkOnDatabaseThread (run #1):
[ RUN      ] SyncBrowserThreadModelWorkerTest.DoesWorkOnDatabaseThread
[6916:2808:0123/195343.636:38250883:FATAL:timer.cc(150)] Check failed: origin_sequence_checker_.CalledOnValidSequence().
Backtrace:
base::debug::StackTrace::StackTrace [0x01DF27F7+23]
logging::LogMessage::~LogMessage [0x01D7F221+49]
base::Timer::Stop [0x01DD050B+91]
testing::internal::TestFactoryImpl<syncer::`anonymous namespace'::SyncBrowserThreadModelWorkerTest_DoesWorkOnDatabaseThread_Test>::CreateTest [0x00C4A22B+458]
base::internal::RunMixin<base::Callback<bool __cdecl(void),1,1> >::Run [0x0115609D+25]
base::internal::FunctorTraits<void (__thiscall syncer::BrowserThreadModelWorker::*)(base::Callback<enum syncer::SyncerError __cdecl(void),1,1> const &,syncer::ScopedEventSignal,enum syncer::SyncerError *),void>::Invoke<scoped_refptr<syncer::BrowserThreadM [0x025FBBD7+41]
base::internal::Invoker<base::internal::BindState<void (__thiscall syncer::BrowserThreadModelWorker::*)(base::Callback<enum syncer::SyncerError __cdecl(void),1,1> const &,syncer::ScopedEventSignal,enum syncer::SyncerError *),scoped_refptr<syncer::BrowserT [0x025FBC08+46]
base::internal::Invoker<base::internal::BindState<void (__thiscall syncer::BrowserThreadModelWorker::*)(base::Callback<enum syncer::SyncerError __cdecl(void),1,1> const &,syncer::ScopedEventSignal,enum syncer::SyncerError *),scoped_refptr<syncer::BrowserT [0x025FBF14+22]
base::debug::TaskAnnotator::RunTask [0x01E0136F+383]
base::MessageLoop::RunTask [0x01D839CC+1228]
base::MessageLoop::DoWork [0x01D82953+611]
base::MessagePumpDefault::Run [0x01E0327A+106]
base::MessageLoop::RunHandler [0x01D834F1+305]
base::RunLoop::Run [0x01D86D54+132]
base::Thread::Run [0x01D9F7BD+173]
base::Thread::ThreadMain [0x01DA02DE+622]
base::PlatformThread::Sleep [0x01D9E832+290]
BaseThreadInitThunk [0x7560337A+18]
RtlInitializeExceptionChain [0x775692B2+99]
RtlInitializeExceptionChain [0x77569285+54]

BUG=684640

Review-Url: https://codereview.chromium.org/2652673006
Cr-Commit-Position: refs/heads/master@{#446101}

[modify] https://crrev.com/3c942aae9aaa0a5a04314090526d8f24560d65a6/components/sync/engine/browser_thread_model_worker_unittest.cc

Project Member

Comment 4 by bugdroid1@chromium.org, Jun 1 2017

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

commit 4e844bb5f686dbd3a062c6aaf83c8a1df171a08a
Author: gab <gab@chromium.org>
Date: Thu Jun 01 16:23:36 2017

Make base::Timer sequence-friendly.

This CL was also going to fix a race condition in the existing implementation when SetTaskRunner() was used but the test-only failures caused by tests having long-lived
with the status quo are proving hard than expected to fix. The race is no worse than
before by making this code sequence-friendly (and generally healthier). Will fix
race in a follow-up CL.

Of note in this CL:
 - Patch set 1 is https://codereview.chromium.org/1433373003
   so looking at diff from 1 might be less work (especially for tests).
 - (not true anymore, postponed to race fix CL:)
   The Timer's delayed task now always lives on the sequence it was started from
   (and even SetTaskRunner() was used, a task is posted to it when the delay
    expires instead of having the Timer's delayed task live on it -- this solves
    the aforementioned race condition).
   - This required adapting tests for MediaCodecLoop and UploadProgressTracker.

BUG= 587199 ,  552633 ,  678592 , 684640,  675631 

Review-Url: https://codereview.chromium.org/2491613004
Cr-Commit-Position: refs/heads/master@{#476317}

[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/base/timer/timer.cc
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/base/timer/timer.h
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/base/timer/timer_unittest.cc
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/build/sanitizers/tsan_suppressions.cc
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/content/browser/loader/upload_progress_tracker.cc
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/content/browser/loader/upload_progress_tracker.h
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/content/browser/loader/upload_progress_tracker_unittest.cc
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/content/browser/service_worker/service_worker_browsertest.cc
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/content/browser/service_worker/service_worker_job_unittest.cc
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/media/base/android/media_codec_loop.cc
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/media/base/android/media_codec_loop.h
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/media/base/android/media_codec_loop_unittest.cc
[modify] https://crrev.com/4e844bb5f686dbd3a062c6aaf83c8a1df171a08a/media/filters/android/media_codec_audio_decoder.cc

Blocking: 736268

Comment 6 by gab@chromium.org, Mar 13 2018

Blockedon: 708584
Need to support MOCK_TIME in TestBrowserThreadBundle for this (i.e. MOCK_TIME in ScopedTaskEnvironment with MainThreadType == UI). WIP.

Comment 7 by gab@chromium.org, Mar 13 2018

Blocking: 716187

Comment 8 by gab@chromium.org, Mar 13 2018

Blocking: 786597
Blockedon: 896990
First need to make SetTaskRunner() sequence-affine (and remove undesired multi-threaded callers).
Blockedon: 587199

Sign in to add a comment