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

commit d48514020dc8528851c3aca84e777ebf835f1dd7
Author: Mikel Astiz <mastiz@chromium.org>
Date: Fri Apr 06 12:18:39 2018

Mark history-back-twice-with-subframes-assert.html flaky

It's flaky on Win7 Tests (dbg):
https://test-results.appspot.com/dashboards/flakiness_dashboard.html#testType=webkit_layout_tests&tests=fast%2Fhistory%2Fhistory-back-twice-with-subframes-assert.html&showFlaky=true

TBR=smcgruer@chromium.org
NOTRY=true

Bug: 829740
Change-Id: Icbe3428b6652e1bf2d701355a661acbd5d9b3cb9
Reviewed-on: https://chromium-review.googlesource.com/999483
Commit-Queue: Mikel Astiz <mastiz@chromium.org>
Reviewed-by: Mikel Astiz <mastiz@chromium.org>
Cr-Commit-Position: refs/heads/master@{#548746}
[modify] https://crrev.com/d48514020dc8528851c3aca84e777ebf835f1dd7/third_party/WebKit/LayoutTests/TestExpectations

This test is also flaky on Mac.

Based on https://cs.chromium.org/chromium/src/third_party/blink/renderer/core/frame/OWNERS?type=cs, adding Blink>Internals component and cc-ing platform-architecture-dev@

That said, it looks easy enough to fix and I may give fixing it a go myself. As #1 mentioned, onload order probably isn't guaranteed and on bad runs the iframes are probably loading before the main document. I was able to reproduce this a few times with a debug Linux build, though interestingly once I then ran a release build it started passing in both builds from then on out! (Perhaps some sort of caching.)

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

commit a550e3e2c31893045d97adad488ecb92c5cd76ca
Author: Max Morin <maxmorin@chromium.org>
Date: Fri May 11 10:51:18 2018

Mark history-back-twice-with-subframes-assert.html flaky

It's flaky on all platforms.

Tbr: smcgruer@chromium.org
No-Try: true
Bug: 829740
Change-Id: Ibcbf34bf2a999c0814cf2d5546109561093030be
Reviewed-on: https://chromium-review.googlesource.com/1054012
Commit-Queue: Max Morin <maxmorin@chromium.org>
Reviewed-by: Max Morin <maxmorin@chromium.org>
Cr-Commit-Position: refs/heads/master@{#557837}
[modify] https://crrev.com/a550e3e2c31893045d97adad488ecb92c5cd76ca/third_party/WebKit/LayoutTests/TestExpectations

Oh nevermind; I totally misread the test :(. It navigates both of the iframes after setting an onload handler. Not sure how that leaks to flake.

Logs from a hanging test run:

CONSOLE MESSAGE: line 40: initial onload iframe1
CONSOLE MESSAGE: line 44: initial onload iframe2
CONSOLE MESSAGE: line 9: runTest
CONSOLE MESSAGE: line 35: navigating
CONSOLE MESSAGE: line 16: Inside new onload function; loadCount: 2
CONSOLE MESSAGE: line 16: Inside new onload function; loadCount: 1
CONSOLE MESSAGE: line 23: Inside didGoBack conditional, calling history.go(-2)

So after calling history.go(-2), we don't get back to the added onload function (line 16) it seems.

Addendum: on line 23, we do have: "Currently, history.length: 2". So that does seem correct before the history.go(-2).

Oh! Wait, that's not right is it. From a passing Release build test run:

CONSOLE MESSAGE: line 40: initial onload iframe1
CONSOLE MESSAGE: line 44: initial onload iframe2
CONSOLE MESSAGE: line 9: runTest
CONSOLE MESSAGE: line 35: navigating
CONSOLE MESSAGE: line 16: Inside new onload function; loadCount: 2
CONSOLE MESSAGE: line 16: Inside new onload function; loadCount: 1
CONSOLE MESSAGE: line 23: Inside didGoBack conditional, calling history.go(-2). Currently, history.length: 3
CONSOLE MESSAGE: line 16: Inside new onload function; loadCount: 2
CONSOLE MESSAGE: line 16: Inside new onload function; loadCount: 1
CONSOLE MESSAGE: line 30: Notify done

Notice that the length is 3, and after checking the docs it seems that history is '1' indexed, not '0' indexed?

Failing case:

CONSOLE MESSAGE: line 38: navigating
[1:1:0511/074147.998119:INFO:render_frame_impl.cc(6633)] 0x26e5acfaf820: PrepareRenderViewForNavigation, render_view_->history_list_offset_ set to 0
[1:1:0511/074147.998366:INFO:render_frame_impl.cc(6635)] 0x26e5acfaf820: PrepareRenderViewForNavigation, render_view_->history_list_length_ set to 1
[1:1:0511/074148.018152:INFO:render_frame_impl.cc(5461)] 0x26e5acfaf820: render_view_->history_list_offset_ is now 1
[1:1:0511/074148.018370:INFO:render_frame_impl.cc(5467)] 0x26e5acfaf820: render_view_->history_list_length_ is now 2
[1:1:0511/074148.020852:INFO:render_frame_impl.cc(6633)] 0x26e5acfaee20: PrepareRenderViewForNavigation, render_view_->history_list_offset_ set to 0
[1:1:0511/074148.021059:INFO:render_frame_impl.cc(6635)] 0x26e5acfaee20: PrepareRenderViewForNavigation, render_view_->history_list_length_ set to 1
[1:1:0511/074148.043430:INFO:render_frame_impl.cc(5461)] 0x26e5acfaee20: render_view_->history_list_offset_ is now 1
[1:1:0511/074148.043624:INFO:render_frame_impl.cc(5467)] 0x26e5acfaee20: render_view_->history_list_length_ is now 2
CONSOLE MESSAGE: line 16: Inside new onload function; loadCount: 2

Working case:

CONSOLE MESSAGE: line 38: navigating
[1:1:0511/074233.983738:INFO:render_frame_impl.cc(6633)] 0xd405de0800: PrepareRenderViewForNavigation, render_view_->history_list_offset_ set to 0
[1:1:0511/074233.983799:INFO:render_frame_impl.cc(6635)] 0xd405de0800: PrepareRenderViewForNavigation, render_view_->history_list_length_ set to 1
[1:1:0511/074233.987001:INFO:render_frame_impl.cc(6633)] 0xd405ddfe00: PrepareRenderViewForNavigation, render_view_->history_list_offset_ set to 0
[1:1:0511/074233.987039:INFO:render_frame_impl.cc(6635)] 0xd405ddfe00: PrepareRenderViewForNavigation, render_view_->history_list_length_ set to 1
[1:1:0511/074234.000765:INFO:render_frame_impl.cc(5461)] 0xd405de0800: render_view_->history_list_offset_ is now 1
[1:1:0511/074234.000807:INFO:render_frame_impl.cc(5467)] 0xd405de0800: render_view_->history_list_length_ is now 2
[1:1:0511/074234.007709:INFO:render_frame_impl.cc(5461)] 0xd405ddfe00: render_view_->history_list_offset_ is now 2
[1:1:0511/074234.007744:INFO:render_frame_impl.cc(5467)] 0xd405ddfe00: render_view_->history_list_length_ is now 3
CONSOLE MESSAGE: line 16: Inside new onload function; loadCount: 2




I can't work out yet why history_list_offset_/history_list_length_ ends up at 2/3 in the working case but only 1/2 in the broken case.

Note that in both these cases there are two separate objects at play here, which suggests a likely threading/process issue.

Oh! There are two different RenderFrameImpls, but they *share* the underlying render_view_. Which is why the history count is wrong in the failing case. The threading is:

FAILING CASE:

RenderFrameImpl A, PrepareRenderViewForNavigation (reset history count to 0)
RenderFrameImpl A, UpdateNavigationHistory (increment history count to 1)
RenderFrameImpl B, PrepareRenderViewForNavigation (reset history count to 0)
RenderFrameImpl B, UpdateNavigationHistory (increment history count to 1)


PASSING CASE:

RenderFrameImpl A, PrepareRenderViewForNavigation (reset history count to 0)
RenderFrameImpl B, PrepareRenderViewForNavigation (reset history count to 0)
RenderFrameImpl A, UpdateNavigationHistory (increment history count to 1)
RenderFrameImpl B, UpdateNavigationHistory (increment history count to 2)


This actually sounds like a real bug in our implementation... though I still have no idea who would own this code :D

sounds like the navigations folks (clamy et al)?

+creis: FYI

Thanks!  Comment 12 does sound like a race bug.  It's intentional that multiple frames share the same RenderView and the same view of history.length (since there's only one view of session history for the whole tab), but obviously the order of calls shouldn't affect the outcome.

Camille, is anyone on your side able to take a look?  We're pretty swamped at the moment with M67 approaching fast.

I'm still getting back from vacation, but I should be able to find some time to look at it this week.

Thanks clamy@! Hope you don't mind, swapping our ownership since you're planning to take a look at it.

Looking into it some more, this is a known issue: we had a bigger version of this race when we didn't update the history parameters at ReadyToCommit time (but only captured them at start navigation time). The issue is if the history length changes while the CommitNavigation IPC is queued for processing in the renderer process, the processing of the IPC will reset the history length with a wrong value (ie the value it had in the browser when we issued the call). We currently don't have a way to reconcile the browser and renderer view on these.

Arthur, I can;t see to find the link to the bug for this race that you partially fixed. Could you add it here? Thanks!

There it is:
https://bugs.chromium.org/p/chromium/issues/detail?id=796561
And the fix that reduces considerably the duration when the race can happen.
https://chromium-review.googlesource.com/c/chromium/src/+/881171