vmpstr@: Do you have any idea what I could to avoid this issue?

+CC nasko@: FYI. This is the issue I talked about today.

vmpstr@:
  Do you have any update?
  You wrote the reentrancy CHECK in UpdateLifecyclePhases, LayoutTest::CompositeWithRaster() and DWriteFontProxy::FindFamilly. That's why I think you have an opinion on this and probably had the same issue in the past.

Sorry I absolutely missed this.

It looks like we're doing a composite with raster form layout test controller/runner, which I don't think is something we want to do here. 

Do you know if this is something that happens without the layout tests?
FWIW, my comment there was just a refactor, we always had a re-entrancy protection with NOTREACHED() inside. 

+masonfreed as well who worked in the layout test driver code recently. 

Also, AFAIK CompositeWithRaster should only be happening when the test is over and we're trying to capture pixel output. I wonder if the test should be waiting for some condition before capturing pixels (although that might just hide the problem)

Mason, if this consistently reproduces, could you see if the same issue happens with the display compositor pixel dumps?

Re #5:
> Do you know if this is something that happens without the layout tests?
> FWIW, my comment there was just a refactor, we always had a re-entrancy protection with NOTREACHED() inside.

As I said in #1 I am able to see it from time to time when I apply this patch:
https://chromium-review.googlesource.com/c/chromium/src/+/1172290
The goal is to make URLLoaderClient::OnStartLoadingResponseBody(body_data_pipe) to be called earlier, to improve performances.
My guess is that there is a latent bug and my CL causes it to happens more often.

This reproduce only on Windows, because of DWriteFontProxy.
This reproduce very rarely per tests, but it can happen on a wide range of them.
Because of these I was never able to reproduce it locally. Only the trybots were able.

So if I understand correctly we should guarantee that:
1) DWriteFontProxy.FindFamilly() is never called after the end of the Layout Test.
2) LayoutTest::CompositeWithRaster() is called   after the end of the Layout Test.

If we have 1 and 2, then this bug can't happens. 2 looks okay, but 1 is probably less okay.

I'm starting to take a look at this now. It will be hard if it only rarely reproduces, and only on Windows. (I have a separate open ticket that I'm unable to locally run layout tests on my windows box. :-( )

One thing - CompositeWithRaster() should currently only get called at the end of the test, to capture the pixel output. But that's required for layout tests, and AFAIK currently only happens after the test is complete, so I think #2 should already be true. I'll try to verify in this case. But that leaves #1 as the action item here.

One question: do you have (a few?) other example tests that you believe to be flaky in this way, when applying your CL? The one you referenced, virtual/video-surface-layer/media/controls-focus-ring.html, was already in TestExpectations as a Failure. I see that your CL adds a Crash there, but it'd be nice (not necessary) to have a "clean" test that shows the problem. Let me know. 

...by the way, vmpstr@, the virtual/video-surface-layer suite already adds the --enable-display-compositor-pixel-dump flag.

Adding mlamouri@ to make sure he doesn't already know what's going on here.

Ok, I can duplicate this issue on Windows. (Not on Linux, after 1000 retries, as your previously stated.) I believe your explanation of the source of the re-entrancy is correct. There are multiple overlapping calls to UpdateLifecyclePhases, which cause re-entrancy depending on luck/timing.

One of the calls is the stack trace you mention, originating from the synchronous Mojo call from content::DWriteFontCollectionProxy::FindFamilyName(). The other is, I believe, an asynchronous call that gets to run while the synchronous FindFamilyName() is waiting on a response. There are a number of call paths (I counted 7 distinct stack traces) that could be the one causing the problem, but my suspicion is that it is this one:

 [1] #1 blink::LocalFrameView::UpdateLifecyclePhases()
    ...
 [1] #13  content::LayerTreeView::SynchronouslyComposite() 
 [1] #14  content::LayerTreeView::SynchronouslyCompositeNoRasterForTesting()
 [1] #15  blink::WebViewImpl::UpdateAllLifecyclePhasesAndCompositeForTesting()
 [1] #16 test_runner::WebWidgetTestClient::AnimateNow()

The WebWidgetTestClient::AnimateNow() calls keep coming, even after the BlinkTestRunner::TestFinished() call has come and gone. I think perhaps the way to "fix" this problem is to stop the animation loop on WebWidgetTestClient once the test completes, and before the LayoutTestRenderFrameObserver::CompositeWithRaster() call comes in to capture the layout. I don't know if a) that makes sense, or b) it is easily do-able. But that's the path I'm currently going down, in case somebody knows that it's wrong.

Ok, I'm beginning to wonder if there's a "good" way to solve this, other than removing the synchronous Mojo call from content::DWriteFontCollectionProxy::FindFamilyName. That seems like it is probably either impossible or a large project, but I don't know. I'm cc'ing sammc@, who Mojo-ified dwrite_font_proxy.mojom in January. sammc@ - is that possible to do?

The problem is that there are 7 code paths getting to UpdateLifecyclePhases, and I think any of them could trigger this reentrancy, if they're unlucky enough to catch a previous call that is stuck in FindFamilyName() waiting for a synchronous response. I've listed the call stacks below, in case that helps at all. I don't know if there are any other such synchronous calls to the browser process that happen during LocalFrameView::UpdateLifecyclePhases? If there are, it would seem that they could suffer from this same problem. So I'm guessing there aren't many/any?

I thought about just early-outing from UpdateLifecyclePhases if we detect reentrancy, instead of calling NOTREACHED(). That should solve the crash problem. And it's likely how this doesn't cause an issue in real-world usage, because in non-debug builds, that is what happens. But the issue would then be that in some cases, the lifecycle would not run when it is needed, for example when called in LayoutTestRenderFrameObserver::CompositeWithRaster, to raster the final results for the layout test image capture. My guess is that this would just change the test to flaky based on incomplete layout/paint, rather than flaky based on a crash, so not really a fix. Perhaps since there are so many calls to UpdateLifecyclePhases happening anyway, the layout would be complete anyway? Based on the fact that one call is clearly waiting for font information, I kind of doubt it. And anyway this feels like a hack, but it may be the best solution, if it isn't possible to convert the Font synchronous call to async.

Any thoughts or other ideas?



Call stacks getting to LocalFrameView::UpdateLifecyclePhases (all are in the renderer process):

*** This happens periodically throughout, including AFTER the TestFinished() stack at the bottom
#1 blink::LocalFrameView::UpdateLifecyclePhases()
#13  content::LayerTreeView::SynchronouslyComposite() 
#14  content::LayerTreeView::SynchronouslyCompositeNoRasterForTesting()
#15  blink::WebViewImpl::UpdateAllLifecyclePhasesAndCompositeForTesting()
#16 test_runner::WebWidgetTestClient::AnimateNow()

*** This happens periodically throughout, including AFTER the TestFinished() stack at the bottom
#1 blink::LocalFrameView::UpdateLifecyclePhases()
#2 blink::LocalFrameView::UpdateAllLifecyclePhasesExceptPaint()
#3 blink::SVGImage::ServiceAnimations()
#4 blink::SVGImageChromeClient::AnimationTimerFired()

*** This only happens a few times, presumably while test is executing JS
#1  blink::LocalFrameView::UpdateLifecyclePhases()\n
#2  blink::LocalFrameView::UpdateAllLifecyclePhasesExceptPaint()\n
#3  blink::PageAnimator::UpdateAllLifecyclePhasesExceptPaint()\n
#4  blink::PageWidgetDelegate::UpdateLifecycle()\n
#5  blink::WebViewImpl::UpdateLifecycle()\n
#6  test_runner::EventSender::KeyDown()\n
#7  test_runner::EventSenderBindings::KeyDown()\n

*** This only happens a few times, presumably while test is executing JS
#1 blink::LocalFrameView::UpdateLifecyclePhases()
#2 blink::LocalFrameView::UpdateAllLifecyclePhasesExceptPaint()
#3 blink::LayoutView::HitTest()
#16 content::WidgetInputHandlerImpl::DispatchEvent()

*** This happens (the call to TestFinished) exactly once, near the end.
#1 blink::LocalFrameView::UpdateLifecyclePhases()
#2 blink::LocalFrameView::UpdateAllLifecyclePhases()
#3 blink::PageAnimator::UpdateAllLifecyclePhases()
#4 blink::PageWidgetDelegate::UpdateLifecycle()
#5 blink::WebViewImpl::UpdateLifecycle()
#6 blink::WebViewFrameWidget::UpdateLifecycle()
#7 blink::WebWidget::UpdateAllLifecyclePhases()
#8 content::BlinkTestRunner::TestFinished()

*** Follow-on to previous call (for layout dump this time)
#1 blink::LocalFrameView::UpdateLifecyclePhases()
#2 blink::LocalFrameView::UpdateAllLifecyclePhasesExceptPaint()
#3 blink::ExternalRepresentation()
#4 blink::WebFrameContentDumper::DumpLayoutTreeAsText()
#5 test_runner::DumpLayout()
#6 test_runner::TestRunner::DumpLayout()
#7 content::BlinkTestRunner::CaptureLocalLayoutDump()
#8 content::BlinkTestRunner::TestFinished()

*** AFTER the previous 2 calls, there are several more AnimateXyz calls, then this one, the one that is re-entrant in the bug report. And this is the one capturing the layout, so we shouldn't just early-out of this UpdateLifecyclePhases call.
#1 blink::LocalFrameView::UpdateLifecyclePhases()
#2 blink::LocalFrameView::UpdateAllLifecyclePhases()
#3 blink::PageAnimator::UpdateAllLifecyclePhases()
#4 blink::PageWidgetDelegate::UpdateLifecycle()
#5 blink::WebViewImpl::UpdateLifecycle()
#6 blink::WebViewFrameWidget::UpdateLifecycle()
#7 content::RenderWidget::UpdateVisualState()
#8 content::LayerTreeView::UpdateLayerTreeHost()
#9 cc::LayerTreeHost::RequestMainFrameUpdate()
#10 cc::SingleThreadProxy::DoBeginMainFrame()
#11 cc::SingleThreadProxy::CompositeImmediately()
#12 cc::LayerTreeHost::Composite()
#13 content::LayerTreeView::SynchronouslyComposite()
#14 content::LayerTreeView::CompositeWithRasterForTesting()
#15 blink::WebFrameWidgetBase::CompositeWithRasterForTesting()
#16 content::LayoutTestRenderFrameObserver::CompositeWithRaster()

Another thought, perhaps easier (vmpstr@?), would be to change  LayoutTestControl::CompositeWithRaster to be an async call, not synchronous. That, I think, should cause that call to wait for the FindFamilyName() synchronous call to complete before executing. And that's only called one place, here:

https://cs.chromium.org/chromium/src/content/shell/browser/layout_test/blink_test_controller.cc?rcl=9131e23fce5e06ca617ba7a47952e592889d4d3e&l=586

Maybe that's a lower hanging fruit to convert to async?

I think that's doable. We can't do a CopyFromSurface until all frames have composited, but we can certainly yield the thread to other work that needs to happen in the mean time.

It should be pretty easy to try this out, it's just a matter of changing the code you pointed to to wait for all frames to be finished. One complication might be that right now the composite callbacks are depth first. To be honest, I'm not sure if it's important or whether a parent frame can intelligently wait until the children frames have composited. If not, then each call to a child would have to yield until it finishes and before asking the parent to composite.

Anyway, these just some thoughts, but I do think this is doable. If this solves the problem, then that would certainly be a better approach rather than mucking with actual blink code.

Ok, tomorrow (when I can test on the Windows box) I'll check to make sure that this will fix the crash problem, and then take a look at implementing it for real. Doesn't sound too bad, assuming I can work out the synchronization of the depth first traversal. But at least that's all in one place.

Thanks vmpstr@!

Ok, very tentatively it appears that this will fix the crash problem on Windows. I'm going to convert LayoutTestControl::CompositeWithRaster to an async call now.

Yep, this seems to do the trick. Here is the CL:

https://chromium-review.googlesource.com/c/chromium/src/+/1252141

It is running trybots now, but from my local testing it seems to work. I ran 1000 iterations of the previously-failing test on Windows, and they all passed. (Well, actually they Failed because of an image mismatch on the controls-focus-ring test, which hasn't been rebaselined for a while. But it no longer crashes.)

Thank you so much Mason!

I rebased my patch on top of yours and the previously flaky tests passed.
(I have one more that regressed in the meantime, but it has nothing to do with this issue).

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

commit 44a4cec290f35fb5976d8e99091dd4b628877545
Author: Mason Freed <masonfreed@chromium.org>
Date: Tue Oct 02 16:06:21 2018

Increase stack trace depth on non-Windows architectures

There is a Windows-only limit on stack trace depth of 62. It seems to only
apply to Server 2003 and XP, though it might exist for later OSes. See
https://msdn.microsoft.com/en-us/library/bb204633.aspx for reference. I've
left the limit at 62 for all of Windows in this CL.

This limit does not (seem to) apply to other operating systems, so I've
relaxed the limit to 250. The prior 62 limit does impede some real debugging
efforts, as our stack depth can grow significantly past 62 in some cases,
for example when performing layout on a deeply nested page. For example,
see  crbug.com/877093 , which quotes the 62/63 limit.

In addition, testing seems to show that Android has a problem with larger
limits also, so I've left the Android limit at 62.

Bug:  877093 
Change-Id: Ie6521aa5da5e577cf28a312791fba873df6930cc
Reviewed-on: https://chromium-review.googlesource.com/1252002
Commit-Queue: Mason Freed <masonfreed@chromium.org>
Reviewed-by: Lei Zhang <thestig@chromium.org>
Cr-Commit-Position: refs/heads/master@{#595860}
[modify] https://crrev.com/44a4cec290f35fb5976d8e99091dd4b628877545/base/debug/stack_trace.h

No problem Arthur, I'm glad it looks like it fixes the issue. The CL is waiting on one last review and then I can land it and close this bug.

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

commit d0b2ebaf1f6b47fca493e82da45eedf671cf6bf5
Author: Mason Freed <masonfreed@chromium.org>
Date: Tue Oct 02 20:58:57 2018

Convert LayoutTestControl::CompositeWithRaster to asynchronous

Previous to this CL, there were corner case crashes occurring when another
call to LocalFrameView::UpdateLifecyclePhases needed to call synchronously
back to the browser process, for example to gather Font information. In
those cases, if CompositeWithRaster was called (synchronously), it would
be allowed to run by Mojo, which would cause a re-entrant call to
LocalFrameView::UpdateLifecyclePhases. By converting this method to
asynchronous, Mojo will block it and wait for existing synchronous calls
to complete, avoiding the re-entrancy.

Bug:  877093 
Change-Id: Ide4036f485662bc576aaf661fb227f59955ac026
Reviewed-on: https://chromium-review.googlesource.com/c/1252141
Reviewed-by: Sam McNally <sammc@chromium.org>
Reviewed-by: John Abd-El-Malek <jam@chromium.org>
Reviewed-by: vmpstr <vmpstr@chromium.org>
Commit-Queue: Mason Freed <masonfreed@chromium.org>
Cr-Commit-Position: refs/heads/master@{#595975}
[modify] https://crrev.com/d0b2ebaf1f6b47fca493e82da45eedf671cf6bf5/content/shell/browser/layout_test/blink_test_controller.cc
[modify] https://crrev.com/d0b2ebaf1f6b47fca493e82da45eedf671cf6bf5/content/shell/browser/layout_test/blink_test_controller.h
[modify] https://crrev.com/d0b2ebaf1f6b47fca493e82da45eedf671cf6bf5/content/shell/common/layout_test.mojom
[modify] https://crrev.com/d0b2ebaf1f6b47fca493e82da45eedf671cf6bf5/mojo/public/cpp/bindings/sync_call_restrictions.h
[modify] https://crrev.com/d0b2ebaf1f6b47fca493e82da45eedf671cf6bf5/third_party/WebKit/LayoutTests/TestExpectations

Landed and fixed.