This doesn't seem to be caused by https://codereview.chromium.org/2033863003 , but rather by https://codereview.chromium.org/1911023002 which added the failing DCHECK.

This DCHECK prevents a ThreadTaskRunnerHandle to be set on a thread that already has a SequencedTaskRunnerHandle. In this case, it prevents a MessageLoop from being instantiated on a blocking pool (SequencedWorkerPool) thread.

Running a MessageLoop on a SequencedWorkerPool thread should probably not be allowed:
- The thread can't be used to run other sequenced tasks while it runs the MessageLoop (In FinancialPing::PingServer, an async request would avoid wasting 1/3 threads of the blocking pool for up to 5 minutes https://cs.chromium.org/chromium/src/rlz/lib/financial_ping.cc?q=financialping::pingserver&sq=package:chromium&dr=CSs&l=335)
- It breaks this invariant: ThreadTaskRunnerHandle::Get() != nullptr -> ThreadTaskRunnerHandle::Get() == SequencedTaskRunnerHandle::Get() 

rogerta@: Would it be feasible to refactor FinancialPing::PingServer to avoid instantiating a MessageLoop in the blocking pool?

woops sorry for finger pointing :)

base/task_scheduler team will own this.

this only happens if an RLZ ping is scheduled which only happens if there is a brand code, so only really happens if you're testing an official stable channel release replica with dchecks enabled, so probably why it snuck through. I'm surprised the rlz unittests don't trigger this though...?

For now I am just disabling rlz ping in my tests.

hello, I wonder if any progress was being made on this bug, or if there was a CL I could revert so the DCHECK no longer hits.

Will: assuming you're looking for a local patch? You can safely comment out that DCHECK locally in this case. We have thought of ways to handle the use case caught here but the DCHECK itself needs to stay.

I'm confused by #6 - surely if the DCHECK is hitting then either what causes the DCHECK needs to be fixed or the DCHECK needs to be removed - I don't think we should have random DCHECKs hitting and developers having to comment them out to do development work.

The DCHECK is correct, this is catching something that needs to be fixed but it was implemented before the DCHECK was added and happens to work okay for its specific use case.

Here's what's happening:

0) Fact: (Thread|Sequenced)TaskRunnerHandle are not meant to stack (that is what the DCHECK verifies.
1) The code hitting the DCHECK happens to create a MessageLoop on a SequencedWorkerPool thread. MessageLoop registers a ThreadTaskRunnerHandle on a thread where the SequencedWorkerPool already has a SequencedTaskRunnerHandle.

This is *wrong* because a component asking for a SequencedTaskRunnerHandle and a ThreadTaskRunnerHandle in that scope will get *different* TaskRunners and neither is truly the right one:

A) Posting to the SequencedWorkerPool's TaskRunner will not run the posted task until the sequence is given back to the pool (i.e. after the task running the nested MessageLoop completes) which could result in preventing the very async condition meant to terminate the MessageLoop.

B) Posting to the MessageLoop's TaskRunner could result in the task never running as the MessageLoop could be terminated the minute its async condition is satisfied. Components using TaskRunnerHandle however are not supposed to have to be aware that it's bounded to a short-lived MessageLoop.


It so happens that the code DCHECK'ing doesn't appear to use TaskRunnerHandle nor use components that do, so there isn't a bug per se in practice in this very use case, but it doesn't make it less wrong and the DCHECK definitely needs to stay.


We could prevent B (and "fix" DCHECK) by adding the notion of a "private" MessageLoop that doesn't register a ThreadTaskRunnerHandle and is only meant to watch for completion of async work, but A is still a problem if required for said completion.


The TaskScheduler will support this use case (nested RunLoops will be allowed from SEQUENCED/SINGLE_THREADED contexts, they won't register an extra TaskRunnerHandle but will continue to pump the current sequence's tasks: preventing both A/B).


Given that this will soon be supported, we'd rather not introduce a new MessageLoop type whose usage we might regret later.


tl;dr; the DCHECK needs to stay, the pattern in the code is wrong but happens to work in practice. The pattern will be fixed in TaskScheduler migration. Until then I agree that keeping a DCHECK in the code is undesirable. We could make some kind of temporary base::ScopedAllowNestedTaskRunnerHandles but if you are the only one hitting this in a specific test scenario maybe we can just wait until migration?

(I'll assume ownership since this is my DCHECK)

I'm getting this (newly?) today at head.

c:\src\cr\src>type out\debug\args.gn
is_debug = true
is_component_build = true
enable_nacl = false
is_chrome_branded = true
symbol_level = 2
target_cpu = "x86"

I don't why I wasn't seeing it before, but I think this configuration is pretty common, so it ought to work.

Issue 690343 has been merged into this issue.

gab@: I don't think we have enough bandwidth to fix this properly anytime soon. Should we just remove the DCHECK in ThreadTaskRunnerHandle?

tl;dr; this is actually catching an existing bug in the current implementation! In practice the nested loop only ever unwinds after the 5 minute timeout or on shutdown via the 500ms shutdown heartbeat check! Therefore hogging a BlockingPool thread for a full 5 minutes on average..! (and potentially not getting to process some responses in time in fast shutdowns, etc.)


** My thoughts on this DCHECK and why it should stay (even more so after the below analysis!!) **

I don't want to remove the DCHECK in ThreadTaskRunnerHandle because it catches something which is always incorrect (stacking task runner handles makes it unclear who should run work posted to the "current context", a.k.a. *TaskRunnerHandle).

e.g. it should be a no-op to s/ThreadTaskRunnerHandle::Get()/SequencedTaskRunnerHandle::Get()/ in APIs that aren't thread affine as ThreadTaskRunnerHandle is a strict subset of SequencedTaskRunnerHandle.

However by creating a nested runloop with a ThreadTaskRunnerHandle on top of a SequencedWorkerPool sequence we create a context in which ThreadTaskRunnerHandle::Get() != SequencedTaskRunnerHandle::Get() and that's very wrong.

i.e. if the URLFetcher code was sequencified tomorrow -- a reasonable thing to do in today's world assuming it's not thread-affine -- this RLZ code would break per the QuitClosure() all of a sudden being posted to the sequence, not the nested loop, and never running per the sequence being blocked on loop.Run(), deadlock...


** Analysis of the code and discovery of the bug **

But wait... now that I'm reading this further this appears to already be the case?!?! Do we even know whether this code still works in the wild (non-dcheck builds)?!

URLFetcherDelegate::OnUrlFetchComplete() (which results in invoking the QuitClosure() in the RLZ code [0]) is invoked on |UrlFetcherCore::delegate_task_runner_| [1][2] which is initialized to SequencedTaskRunnerHandle::Get() [3] which is the SequencedWorkerPool sequence FinancialPing::PingServer is running on [4] and as such on which the RunLoop is spinning, so it's not posted to the nested loop itself, rather to the underlying sequence which is blocked by the nested loop, and I don't see how it ever unblocks :-O (well I guess the timeout task that also results in the QuitClosure() being invoked [5] will eventually unwind the RunLoop and the task will then see the successful response)...

Overall if this bug is real it doesn't prevent the RLZ ping from going out but it hogs a BlockingPool thread for 5 minutes and prevents the response from being processed by Chrome until then?

This task being SKIP_ON_SHUTDOWN though (i.e. blocks shutdown if it's running when shutdown occurs), I'd expect a number of Shutdown Hang report to be blocked on this task if this bug is real and I don't see that in practice [6]..?!

Ah ah, but wait..! There's also ShutdownCheck() running on a 500ms heartbeat [7] which prevents this from hanging on shutdown (CleanupRLZ() [8] triggers the next ShutdownCheck() to exit the RunLoop within <= 500ms and thus isn't caught by the shutdown hang watcher)..!


[0] https://cs.chromium.org/chromium/src/rlz/lib/financial_ping.cc?type=cs&q=file:financial_ping.cc+%22FinancialPingUrlFetcherDelegate+delegate(loop.QuitClosure());%22&l=315

[1] https://cs.chromium.org/chromium/src/net/url_request/url_fetcher_core.cc?rcl=72c70c9d1f6b5453aeb518610b2fa581bed511aa&l=803
[2] https://cs.chromium.org/chromium/src/net/url_request/url_fetcher_core.cc?rcl=72c70c9d1f6b5453aeb518610b2fa581bed511aa&l=727

[3] https://cs.chromium.org/chromium/src/net/url_request/url_fetcher_core.cc?rcl=72c70c9d1f6b5453aeb518610b2fa581bed511aa&l=82

[4] https://cs.chromium.org/chromium/src/components/rlz/rlz_tracker.cc?rcl=72c70c9d1f6b5453aeb518610b2fa581bed511aa&l=307

[5] https://cs.chromium.org/chromium/src/rlz/lib/financial_ping.cc?type=cs&q=file:financial_ping.cc+kTimeout&l=335

[6] https://crash.corp.google.com/browse?q=product.name%3D%27Chrome%27%20AND%20custom_data.ChromeCrashProto.ptype%3D%27browser%27%20AND%20custom_data.ChromeCrashProto.magic_signature_1.name%20CONTAINS%20%27%5BShutdown%20hang%5D%27%20OMIT%20RECORD%20IF%20SUM(thread.StackTrace.StackFrame.FunctionName%20CONTAINS%20%27FinancialPing%3A%3APingServer%27)%20%3D%200&ignore_case=false&enable_rewrite=false&omit_field_name=thread.StackTrace.StackFrame.FunctionName&omit_field_value=ModuleEnumerator%3A%3APopulateModuleInformation(ModuleEnumerator%3A%3AModule%20*)&omit_field_opt=%3D&stbtiq=&reportid=&index=0

[7] https://cs.chromium.org/chromium/src/rlz/lib/financial_ping.cc?type=cs&q=file:financial_ping.cc+ShutdownCheck&l=225

[8] https://cs.chromium.org/chromium/src/chrome/browser/browser_shutdown.cc?type=cs&sq=package:chromium&q=CleanupRlz()&l=182


** My 2c **
It would be much easier if this whole API was made to be async (even if if some platforms are sync they can still post the response async).


Cheers,
Gab

"which is initialized to SequencedTaskRunnerHandle::Get()" I did that as part of the sequencification of core APIs https://chromium.googlesource.com/chromium/src/+blame/72c70c9d1f6b5453aeb518610b2fa581bed511aa/net/url_request/url_fetcher_core.cc#82

Using SequencedTaskRunnerHandle instead of ThreadTaskRunnerHandle in URLFetcherCore is a good thing. The DCHECK in SequencedTaskRunnerHandle is also a good thing because it helped us realize that my change causes a bug in RLZ. I guess we now don't have a choice to make the RLZ code async?

Ok then at least the sum of all issues resulting in the bug is new in M&58. Let's fix RLZ in M58 then and be done with it.

This is manifesting on iOS as Issue 693711.  It broke visibly in M57 and appears to be related to https://codereview.chromium.org/2599873002.

I haven't fully understood the effects of this bug.  Is it localized to just this one RLZ task taking 5 minutes, or will every other task on that thread/runner be blocked for 5 minutes as well?

To clarify further, @gab in #14 posited exactly what we're seeing on iOS:

"Overall if this bug is real it doesn't prevent the RLZ ping from going out but it hogs a BlockingPool thread for 5 minutes and prevents the response from being processed by Chrome until then?"

On iOS in M57, we're sending the RLZ ping on first run and getting a response, but the response doesn't get processed for 5 minutes.  Since mobile sessions are often short-lived, this could potentially prevent us from ever processing the response.

Is there a fix or workaround that we could put into M57?

This bug is blocking for M57 iOS.

Note also that the same DCHECK (!SequencedTaskRunnerHandle::IsSet(), chaining up to rlz_lib::FinancialPing::PingServer) is hit on Chrome OS (in debug builds with "is_chrome_branded = true").

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

commit 533c31e78be276dcaa843dc66efd4fee697d9573
Author: fdoray <fdoray@chromium.org>
Date: Fri Feb 24 23:07:39 2017

Prefer returning a SingleThreadTaskRunner in SequencedTaskRunnerHandle::Get().

Currently:
- When a thread has a SingleThreadTaskRunner but not
  SequencedTaskRunner, SequencedTaskRunnerHandle::Get() and
  ThreadTaskRunnerHandle::Get() are equivalent.
- ThreadTaskRunnerHandle::Get() can only be called from a thread that
  has a SingleThreadTaskRunner.
- Having both a SequencedTaskRunner and a SingleThreadTaskRunner on the
  same thread is prevented by a DCHECK.
That means that replacing ThreadTaskRunnerHandle::Get() with
SequencedTaskRunnerHandle::Get() shouldn't change anything.

Unfortunately, RLZ sets a SingleThreadTaskRunner on a thread that
already has a SequencedTaskRunner.

To make the replacement of ThreadTaskRunnerHandle::Get() with
SequencedTaskRunnerHandle::Get() a true no-op under the assumption
that a SingleThreadTaskRunner can be registered on a thread that
already has a SequencedTaskRunner, this CL gives priority to the
SingleThreadTaskRunner in SequencedTaskRunnerHandle::Get().

This change will be reverted once RLZ stops setting a
SingleThreadTaskRunner on a thread that already has a
SequencedTaskRunner.

BUG=693711,  618530 

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

[modify] https://crrev.com/533c31e78be276dcaa843dc66efd4fee697d9573/base/threading/sequenced_task_runner_handle.cc

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

commit 06bad34f6516d13a5b39beea0e575431f0a803a2
Author: Francois Doray <fdoray@chromium.org>
Date: Fri Mar 03 03:57:08 2017

[merge m57] Prefer returning a SingleThreadTaskRunner in SequencedTaskRunnerHandle::Get().

Currently:
- When a thread has a SingleThreadTaskRunner but not
  SequencedTaskRunner, SequencedTaskRunnerHandle::Get() and
  ThreadTaskRunnerHandle::Get() are equivalent.
- ThreadTaskRunnerHandle::Get() can only be called from a thread that
  has a SingleThreadTaskRunner.
- Having both a SequencedTaskRunner and a SingleThreadTaskRunner on the
  same thread is prevented by a DCHECK.
That means that replacing ThreadTaskRunnerHandle::Get() with
SequencedTaskRunnerHandle::Get() shouldn't change anything.

Unfortunately, RLZ sets a SingleThreadTaskRunner on a thread that
already has a SequencedTaskRunner.

To make the replacement of ThreadTaskRunnerHandle::Get() with
SequencedTaskRunnerHandle::Get() a true no-op under the assumption
that a SingleThreadTaskRunner can be registered on a thread that
already has a SequencedTaskRunner, this CL gives priority to the
SingleThreadTaskRunner in SequencedTaskRunnerHandle::Get().

This change will be reverted once RLZ stops setting a
SingleThreadTaskRunner on a thread that already has a
SequencedTaskRunner.

BUG=693711,  618530 

Review-Url: https://codereview.chromium.org/2714813005
Cr-Commit-Position: refs/heads/master@{#452980}
(cherry picked from commit 533c31e78be276dcaa843dc66efd4fee697d9573)

Review-Url: https://codereview.chromium.org/2725873006 .
Cr-Commit-Position: refs/branch-heads/2987@{#748}
Cr-Branched-From: ad51088c0e8776e8dcd963dbe752c4035ba6dab6-refs/heads/master@{#444943}

[modify] https://crrev.com/06bad34f6516d13a5b39beea0e575431f0a803a2/base/threading/sequenced_task_runner_handle.cc

I got this DCHECK again today. Any chance this can be fixed, as it makes running a dcheck build really painful.

0:032> kv
  *** Stack trace for last set context - .thread/.cxr resets it
 # ChildEBP RetAddr  Args to Child              
00 142eedc0 67dd8679 00000a6c 142ef254 433d7374 base!base::debug::BreakDebugger+0xc (CONV: cdecl) [C:\src\chromium\src\base\debug\debugger_win.cc @ 21]
01 142ef240 67e85df7 00000003 67e4d7b0 67f0a1f8 base!logging::LogMessage::~LogMessage+0x439 (CONV: thiscall) [C:\src\chromium\src\base\logging.cc @ 783]
02 142ef30c 67deb760 00000000 1180b198 1180b198 base!base::ThreadTaskRunnerHandle::ThreadTaskRunnerHandle+0xd7 (CONV: thiscall) [C:\src\chromium\src\base\threading\thread_task_runner_handle.cc @ 88]
03 142ef3e8 67de9d7e 00000000 142ef4d0 000000b8 base!base::MessageLoop::SetThreadTaskRunnerHandle+0x130 (CONV: thiscall) [C:\src\chromium\src\base\message_loop\message_loop.cc @ 362]
04 142ef4b4 67de9686 24bc56dd 142ef4d8 0c958a10 base!base::MessageLoop::BindToCurrentThread+0x2ae (CONV: thiscall) [C:\src\chromium\src\base\message_loop\message_loop.cc @ 330]
*** WARNING: Unable to verify checksum for chrome.dll
05 142ef4cc 61b623ea 00000000 00000000 00000000 base!base::MessageLoop::MessageLoop+0x36 (CONV: thiscall) [C:\src\chromium\src\base\message_loop\message_loop.cc @ 82]
06 142ef5e8 61b64455 0c958a10 142ef5f8 116f9f00 chrome_616e0000!rlz_lib::FinancialPing::PingServer+0x78 (CONV: cdecl) [C:\src\chromium\src\rlz\lib\financial_ping.cc @ 314]
07 142ef638 62ad59a2 00000005 142ef6ac 142ef664 chrome_616e0000!rlz_lib::SendFinancialPing+0x97 (CONV: cdecl) [C:\src\chromium\src\rlz\lib\rlz_lib.cc @ 420]
08 142ef6cc 62ad5731 0570b718 142ef720 142ef708 chrome_616e0000!rlz::RLZTracker::SendFinancialPing+0xca (CONV: thiscall) [C:\src\chromium\src\components\rlz\rlz_tracker.cc @ 346]
09 142ef7e4 67d84a04 1148e6f0 142ef8b8 1148e6f0 chrome_616e0000!rlz::RLZTracker::PingNowImpl+0x189 (CONV: thiscall) [C:\src\chromium\src\components\rlz\rlz_tracker.cc @ 321]
0a 142ef8b8 67e74977 05707714 05707718 0570776c base!base::Callback<void (), base::internal::CopyMode::MoveOnly, base::internal::RepeatMode::Once>::Run+0x74 (CONV: thiscall) [C:\src\chromium\src\base\callback.h @ 91]
0b 142efa5c 67e73e4d 0c995ad0 00000001 00000000 base!base::SequencedWorkerPool::Inner::ThreadLoop+0x987 (CONV: thiscall) [C:\src\chromium\src\base\threading\sequenced_worker_pool.cc @ 1029]
0c 142efb2c 67e7dcc1 38363537 771db400 24bc56dd base!base::SequencedWorkerPool::Worker::Run+0x10d (CONV: thiscall) [C:\src\chromium\src\base\threading\sequenced_worker_pool.cc @ 615]
0d 142efb74 67e723e3 0c995ad0 00001278 00001278 base!base::SimpleThread::ThreadMain+0x101 (CONV: thiscall) [C:\src\chromium\src\base\threading\simple_thread.cc @ 68]
*** WARNING: Unable to verify checksum for KERNEL32.DLL
0e 142efb98 74d538f4 0ccb9e48 74d538d0 dc61f30a base!base::`anonymous namespace'::ThreadFunc+0xa3 (CONV: stdcall) [C:\src\chromium\src\base\threading\platform_thread_win.cc @ 92]
0f 142efbac 77205de3 0ccb9e48 eb9a9114 00000000 KERNEL32!BaseThreadInitThunk+0x24 (FPO: [Non-Fpo])
10 142efbf4 77205dae ffffffff 7722b7b1 00000000 ntdll!__RtlUserThreadStart+0x2f (FPO: [SEH])
11 142efc04 00000000 67e72340 0ccb9e48 00000000 ntdll!_RtlUserThreadStart+0x1b (FPO: [Non-Fpo])

 Product version:  60.0.3103.0

git commit - ccb40f537fbbc17772e7255a7b575661ce4353cd

I'm not sure I agree with the tl;dr;

"tl;dr; the DCHECK needs to stay, the pattern in the code is wrong but happens to work in practice. The pattern will be fixed in TaskScheduler migration. Until then I agree that keeping a DCHECK in the code is undesirable. We could make some kind of temporary base::ScopedAllowNestedTaskRunnerHandles but if you are the only one hitting this in a specific test scenario maybe we can just wait until migration?"

I think we need to either remove the DCHECK or fix the code. It's not sustainable to have a DCHECK hitting all the time.

I agree, I'll see what I can do.

rogerta's CL @ https://codereview.chromium.org/2949263003/ will also address this

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

commit c4a9c77f6e6c59b02fbb09db8da441f630b9ac54
Author: rogerta <rogerta@chromium.org>
Date: Tue Aug 01 16:40:30 2017

Remove call to GetBlockingPool in RLZ.

BUG= 667892 ,  618530 

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

[modify] https://crrev.com/c4a9c77f6e6c59b02fbb09db8da441f630b9ac54/chrome/browser/rlz/chrome_rlz_tracker_delegate.cc
[modify] https://crrev.com/c4a9c77f6e6c59b02fbb09db8da441f630b9ac54/chrome/browser/rlz/chrome_rlz_tracker_delegate.h
[modify] https://crrev.com/c4a9c77f6e6c59b02fbb09db8da441f630b9ac54/chrome/browser/rlz/chrome_rlz_tracker_delegate_unittest.cc
[modify] https://crrev.com/c4a9c77f6e6c59b02fbb09db8da441f630b9ac54/components/rlz/rlz_tracker.cc
[modify] https://crrev.com/c4a9c77f6e6c59b02fbb09db8da441f630b9ac54/components/rlz/rlz_tracker.h
[modify] https://crrev.com/c4a9c77f6e6c59b02fbb09db8da441f630b9ac54/components/rlz/rlz_tracker_delegate.h
[modify] https://crrev.com/c4a9c77f6e6c59b02fbb09db8da441f630b9ac54/components/rlz/rlz_tracker_unittest.cc
[modify] https://crrev.com/c4a9c77f6e6c59b02fbb09db8da441f630b9ac54/ios/chrome/browser/rlz/rlz_tracker_delegate_impl.cc
[modify] https://crrev.com/c4a9c77f6e6c59b02fbb09db8da441f630b9ac54/ios/chrome/browser/rlz/rlz_tracker_delegate_impl.h
[modify] https://crrev.com/c4a9c77f6e6c59b02fbb09db8da441f630b9ac54/rlz/lib/financial_ping.cc

fdoray: sequenced_task_runner_handle.cc still says

  // TODO(fdoray): Move this to the bottom once RLZ stops registering a
  // SingleThreadTaskRunner and a SequencedTaskRunner on the same thread.
  //  https://crbug.com/618530#c14 

yet this bug here is marked Fixed. Do you want to do your TODO now?

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

commit ff31ca8db7305be4cd4bb545dec1cef743c45e75
Author: Francois Doray <fdoray@chromium.org>
Date: Mon Oct 16 15:51:47 2017

Return ThreadTaskRunnerHandle::Get() last in SequencedTaskRunnerHandle::Get().

SequencedTaskRunnerHandle::Get() temporarily always returned
ThreadTaskRunnerHandle::Get() when ThreadTaskRunnerHandle::IsSet() was
true. This avoided a crash in RLZ.

Now that the RLZ code is fixed, this CL brings back
SequencedTaskRunnerHandle::Get() to its old state (i.e. only return
ThreadTaskRunnerHandle::Get() if no handle is stored in TLS and
if the call is not made from a SequencedWorkerPool).

Bug:  618530 
Change-Id: I59ac8a9e92162655ec5e151892bd222e0c3045cd
Reviewed-on: https://chromium-review.googlesource.com/721063
Reviewed-by: Nico Weber <thakis@chromium.org>
Commit-Queue: François Doray <fdoray@chromium.org>
Cr-Commit-Position: refs/heads/master@{#509061}
[modify] https://crrev.com/ff31ca8db7305be4cd4bb545dec1cef743c45e75/base/threading/sequenced_task_runner_handle.cc