New issue
Advanced search Search tips

Issue 914232 link

Starred by 2 users

Issue metadata

Status: Assigned
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug
Flaky-Test: ExtensionWebRequestApiTest.WebRequestTypes

Blocking:
issue 522129



Sign in to add a comment

ExtensionWebRequestApiTest.WebRequestTypes is flaky

Project Member Reported by Findit, Dec 12

Issue description

This CL essentially makes the tab icon animation play shorter. The test shows:

[13920:13920:1211/142034.907052:INFO:CONSOLE(0)] "[FAIL] sendBeaconInFrameOnUnload: Received unexpected event 'onHeadersReceived':{
  "frameId": -1,
  "initiator": "chrome-extension://chbigaineimkgiedpecafcaejhjcdebm",
  "method": "POST",
  "parentFrameId": -1,
  "statusCode": 200,
  "statusLine": "HTTP/1.1 200 OK",
  "tabId": -1,
  "type": "ping",
  "url": "http://www.a.com:33335/slow?2.718"
}
Error
    at captureEvent (chrome-extension://chbigaineimkgiedpecafcaejhjcdebm/framework.js:365:17)
    at onHeadersReceived (chrome-extension://chbigaineimkgiedpecafcaejhjcdebm/framework.js:415:12)", source: chrome-extension://chbigaineimkgiedpecafcaejhjcdebm/test_types.html (0)

I'm not sure why a a HTTP OK would cause this test to fail. I'd assume that replacing TabIcon::ShowingLoadingAnimation() with return false; is enough to make the test fail. I'm out tomorrow though and won't be able to take a look until Thursday.
Components: Tests>Flaky
Labels: OS-Chrome
Revert pending as https://crrev.com/c/1373832 (forgot to link this bug there).

There are quite frequent failures breaking linux-chromeos-dbg. Recently:
https://ci.chromium.org/p/chromium/builders/luci.chromium.ci/linux-chromeos-dbg/9530
Project Member

Comment 3 by bugdroid1@chromium.org, Dec 13

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

commit 831dad6e5036b31b683587078db3df8e32ce4f92
Author: Peter Boström <pbos@chromium.org>
Date: Thu Dec 13 16:50:04 2018

Reland "Reland "Disable the new tab-loading animation""

This reverts commit 6921bd825e416c7b412b454f60df8b183e906943.

Reason for revert: NOTE TO SHERIFFS: Both the revert and reland of this
CL is the culprit for FindIt flakes. Context:

This CL changes the duration of the tab-icon animation ("spinner"). This
likely has some effects on test loops that RunUntilIdle or similar, so a
pending request might either have happened or not before that loop gets
idle.

For instance:  crbug.com/912543  had to be changed to ignore a favicon.ico
response. This flakiness could be reproduced by just changing
TabIcon::ShowingLoadingAnimation to "return false;" even though the test
does not have anything to do with Chrome's UI directly.

This reland will likely trigger crbug.com/914232 again, but the revert
triggered  crbug.com/914644 . It's not unlikely that they are both flaky
as they implicitly rely on tab-icon load time.

Bug: chromium:914232,  chromium:914644 

Original change's description:
> Revert "Reland "Disable the new tab-loading animation""
> 
> This reverts commit ad12d44124812f22484eb4d123e4a3b4aaac93b9.
> 
> Reason for revert:
> Findit found this to be the most likely culprit for the single_process_mash_browser_tests failures on various Linux bots:
> https://findit-for-me.appspot.com/waterfall/failure?url=https://build.chromium.org/p/chromium.memory/builders/Linux%20Chromium%20OS%20ASan%20LSan%20Tests%20%281%29/builds/30518
> 
> 
> Original change's description:
> > Reland "Disable the new tab-loading animation"
> >
> > This reverts commit 742b8857c4dd0ab4550f7b2c1f200ce5be406b9c.
> >
> > Reason for revert: Flaky tests should be fixed in r615470.
> >
> > Bug:  chromium:912543 ,  chromium:913135 ,  chromium:913784 
> >
> > Original change's description:
> > > Revert "Disable the new tab-loading animation"
> > >
> > > This reverts commit 355b8185716292a8f145c77168ee89148ecabf31.
> > >
> > > Reason for revert: Made several tests flaky:  https://crbug.com/912543 
> > >
> > > Original change's description:
> > > > Disable the new tab-loading animation
> > > >
> > > > Makes sure that a lot of animation-related code is bypassed when the
> > > > new-tab-animation flag is off. This should hopefully fix a couple of
> > > > performance regressions that have not yet been root caused so that they
> > > > don't go out with M72.
> > > >
> > > > Bug:  chromium:912328 ,  chromium:905745 ,  chromium:905918 , chromium:910265
> > > > Change-Id: Id3f131db427eb3ee1618d6c9683fd5e47dc134e8
> > > > Reviewed-on: https://chromium-review.googlesource.com/c/1364212
> > > > Reviewed-by: Sidney San Martín <sdy@chromium.org>
> > > > Commit-Queue: Peter Boström <pbos@chromium.org>
> > > > Cr-Commit-Position: refs/heads/master@{#614199}
> > >
> > > TBR=pbos@chromium.org,sdy@chromium.org
> > >
> > > Change-Id: Ib4c022a255ad085c1716d3559a7f84dcb61c2785
> > > No-Presubmit: true
> > > No-Tree-Checks: true
> > > No-Try: true
> > > Bug:  chromium:912328 ,  chromium:905745 ,  chromium:905918 , chromium:910265
> > > Reviewed-on: https://chromium-review.googlesource.com/c/1366359
> > > Reviewed-by: Jeffrey Yasskin <jyasskin@chromium.org>
> > > Commit-Queue: Jeffrey Yasskin <jyasskin@chromium.org>
> > > Cr-Commit-Position: refs/heads/master@{#614440}
> >
> > TBR=jyasskin@chromium.org,pbos@chromium.org,sdy@chromium.org
> >
> > # Not skipping CQ checks because original CL landed > 1 day ago.
> >
> > Bug:  chromium:912328 ,  chromium:905745 ,  chromium:905918 , chromium:910265
> > Change-Id: I3981455a00f743fae535de4626179dcceab9b2c4
> > Reviewed-on: https://chromium-review.googlesource.com/c/1372236
> > Reviewed-by: Peter Boström <pbos@chromium.org>
> > Commit-Queue: Peter Boström <pbos@chromium.org>
> > Cr-Commit-Position: refs/heads/master@{#615581}
> 
> TBR=jyasskin@chromium.org,pbos@chromium.org,sdy@chromium.org
> 
> Change-Id: Ib9599bb8fd44327ae756d3c9523049367409612c
> Bug:  chromium:912543 ,  chromium:913135 ,  chromium:913784 ,  chromium:912328 ,  chromium:905745 ,  chromium:905918 , chromium:910265
> Reviewed-on: https://chromium-review.googlesource.com/c/1373832
> Commit-Queue: Friedrich Horschig [CET] <fhorschig@chromium.org>
> Reviewed-by: Friedrich Horschig [CET] <fhorschig@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#615878}

TBR=jyasskin@chromium.org,pbos@chromium.org,sdy@chromium.org,fhorschig@chromium.org

# Not skipping CQ checks because original CL landed > 1 day ago.

Bug:  chromium:912543 ,  chromium:913135 ,  chromium:913784 ,  chromium:912328 ,  chromium:905745 ,  chromium:905918 , chromium:910265
Change-Id: Ib8083b1320f3e1cd5c878bd55d2a007af7bf719a
Reviewed-on: https://chromium-review.googlesource.com/c/1376030
Reviewed-by: Peter Boström <pbos@chromium.org>
Commit-Queue: Peter Boström <pbos@chromium.org>
Cr-Commit-Position: refs/heads/master@{#616334}
[modify] https://crrev.com/831dad6e5036b31b683587078db3df8e32ce4f92/chrome/browser/ui/views/tabs/tab_icon.cc
[modify] https://crrev.com/831dad6e5036b31b683587078db3df8e32ce4f92/chrome/browser/ui/views/tabs/tab_unittest.cc
[modify] https://crrev.com/831dad6e5036b31b683587078db3df8e32ce4f92/chrome/common/chrome_features.cc

Owner: pbos@chromium.org
Status: Assigned (was: Untriaged)
I'll try to diagnose this since reverting the change caused other flakes.
Seems only happening in single_process_mash_browser_tests. Not sure why this is the case but I am going to disable it in chromeos.single_process_mash.browser_tests.filter.

pbos@, would appreciate that you continue to investigate. Thanks.
Thanks, please do. I was able to get this flake locally (49/50 passed) with the CL reverted, but it seems to be a lot flakier after my disabling of the test animation.
Cc: karandeepb@chromium.org rob@robwu.nl
This is definitely weird, givne the change that supposedly broke the test (which adjusts tab animation).  Looking at the failure log from #1, it seems that we're losing the frame ID somehow (we should be expected frameId: 1 here [1], but we get frameId -1).  Same thing for tab ID.  Now, the frame is technically removed, so... that doesn't entirely strike me as wrong.  I am a little curious what changed to make it that way, though.  Karan, can you help take a look at this?  Is this something where we should be allowing either 1 or -1, or is the presence of the frame here important?

+Rob as well, since he added support for frameId in beacon requests back in revision ac7ee4ce7b8d39b22a710c58d110e0039c11cf9a.

[1] https://chromium.googlesource.com/chromium/src/+/1352fa135bc3a3b28d27ebc81519727831a5ba08/chrome/test/data/extensions/api_test/webrequest/test_types.js#627

Comment 8 by rob@robwu.nl, Dec 13

Blocking: 522129
019b53cca7c5fbd33fe122ef6c572134b8fe7949 should have fixed the frameId persistency a long time ago. So if the frameId/parentFrameId/tabId are all -1, then it seems that the request was initiated without a frame.

bug 522129 was fixed (it's only open because I wanted to re-enable some flaky tests), but it seems that this bug is suggesting that the functionality is regressing.
Cc: pbos@chromium.org
Owner: sky@chromium.org
So this was enabled recently for single_process_mash_browser_tests, see https://chromium-review.googlesource.com/c/chromium/src/+/1370174.

Assigning to sky@.
Project Member

Comment 10 by bugdroid1@chromium.org, Dec 13

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

commit 560b715b7dead9188f66391574e7891949249c7e
Author: Xiyuan Xia <xiyuan@chromium.org>
Date: Thu Dec 13 23:39:30 2018

SPM: Disable ExtensionWebRequestApiTest.WebRequestTypes

Flaky in single_process_mash_browser_tests and fails multiple
times.

Bug: 914232
Change-Id: Ibfbca97573086223c973dbb9105e867cf82139c9
Reviewed-on: https://chromium-review.googlesource.com/c/1377196
Reviewed-by: Peter Boström <pbos@chromium.org>
Commit-Queue: Xiyuan Xia <xiyuan@chromium.org>
Cr-Commit-Position: refs/heads/master@{#616492}
[modify] https://crrev.com/560b715b7dead9188f66391574e7891949249c7e/testing/buildbot/filters/chromeos.single_process_mash.browser_tests.filter

Labels: Proj-Mash-SingleProcess
*SIGH* I will revert my patch that reenabled it.
Xiyuan landed the disabling, so we're good.
The failure was on a debug build. Here's the output:

Value of: RunExtensionSubtest("webrequest", "test_types.html")
  Actual: false
Expected: true
Failed 3 of 8 tests
Stack trace:
#0 0x55cfe4d680b0 StackTraceGetter::CurrentStackTrace()
#1 0x55cfe4d899c7 testing::internal::UnitTestImpl::CurrentOsStackTraceExceptTop()
#2 0x55cfe4d88e23 testing::internal::AssertHelper::operator=()
#3 0x55cfe290ef3f extensions::ExtensionWebRequestApiTest_WebRequestTypes_Test::RunTestOnMainThread()
#4 0x55cfe9a8f6d5 content::BrowserTestBase::ProxyRunTestOnMainThreadLoop()
#5 0x55cfe0f21b4d _ZN4base8internal13FunctorTraitsIM25RenderViewContextMenuBaseFvvEvE6InvokeIS4_P21RenderViewContextMenuJEEEvT_OT0_DpOT1_
#6 0x55cfe0f21a94 _ZN4base8internal12InvokeHelperILb0EvE8MakeItSoIM25RenderViewContextMenuBaseFvvEJP21RenderViewContextMenuEEEvOT_DpOT0_
#7 0x55cfe9a92535 _ZN4base8internal7InvokerINS0_9BindStateIMN7content15BrowserTestBaseEFvvEJNS0_17UnretainedWrapperIS4_EEEEEFvvEE7RunImplIRKS6_RKNSt3__15tupleIJS8_EEEJLm0EEEEvOT_OT0_NSF_16integer_sequenceImJXspT1_EEEE
#8 0x55cfe9a9246c _ZN4base8internal7InvokerINS0_9BindStateIMN7content15BrowserTestBaseEFvvEJNS0_17UnretainedWrapperIS4_EEEEEFvvEE3RunEPNS0_13BindStateBaseE
#9 0x55cfe0f122ad _ZNKR4base17RepeatingCallbackIFvvEE3RunEv
#10 0x55cfe87c8d20 ChromeBrowserMainParts::PreMainMessageLoopRunImpl()
#11 0x55cfe87c6eb4 ChromeBrowserMainParts::PreMainMessageLoopRun()
#12 0x55cfe3e9023b chromeos::ChromeBrowserMainPartsChromeos::PreMainMessageLoopRun()
#13 0x7f92a1defcf2 content::BrowserMainLoop::PreMainMessageLoopRun()
#14 0x7f92a09ba5ad _ZN4base8internal13FunctorTraitsIMN7content12ChildProcessEFvvEvE6InvokeIS5_PS3_JEEEvT_OT0_DpOT1_
#15 0x7f92a09ba4f4 _ZN4base8internal12InvokeHelperILb0EvE8MakeItSoIMN7content12ChildProcessEFvvEJPS5_EEEvOT_DpOT0_
#16 0x7f92a1df5a75 _ZN4base8internal7InvokerINS0_9BindStateIMN7content15BrowserMainLoopEFivEJNS0_17UnretainedWrapperIS4_EEEEEFivEE7RunImplIRKS6_RKNSt3__15tupleIJS8_EEEJLm0EEEEiOT_OT0_NSF_16integer_sequenceImJXspT1_EEEE
#17 0x7f92a1df59ac _ZN4base8internal7InvokerINS0_9BindStateIMN7content15BrowserMainLoopEFivEJNS0_17UnretainedWrapperIS4_EEEEEFivEE3RunEPNS0_13BindStateBaseE
#18 0x7f92a08bf0cd _ZNKR4base17RepeatingCallbackIFvvEE3RunEv
#19 0x7f92a2dde4cd content::StartupTaskRunner::RunAllTasksNow()
#20 0x7f92a1deb84f content::BrowserMainLoop::CreateStartupTasks()
#21 0x7f92a1df80f3 content::BrowserMainRunnerImpl::Initialize()
#22 0x7f92a1de3169 content::BrowserMain()
#23 0x7f92a414d730 content::RunBrowserProcessMain()
#24 0x7f92a4150ba5 content::ContentMainRunnerImpl::RunServiceManager()
#25 0x7f92a414f769 content::ContentMainRunnerImpl::Run()
#26 0x7f92a414652c content::ContentServiceManagerMainDelegate::RunEmbedderProcess()
#27 0x7f9277a1d8c1 service_manager::Main()
#28 0x7f92a414ae45 content::ContentMain()
#29 0x55cfe9a8ec82 content::BrowserTestBase::SetUp()
#30 0x55cfe866bbcb InProcessBrowserTest::SetUp()
#31 0x55cfe8589edc extensions::ExtensionBrowserTest::SetUp()
#32 0x55cfe0f73b7e _ZN7testing8internal12InvokeHelperIRKNSt3__16vectorIPN12user_manager4UserENS2_9allocatorIS6_EEEENS2_5tupleIJEEEE12InvokeMethodIN8chromeos15MockUserManagerEMSH_KFSB_vEEESB_PT_T0_RKSD_

[13920:14049:1211/142036.979887:WARNING:discardable_shared_memory_manager.cc(410)] Some MojoDiscardableSharedMemoryManagerImpls are still alive. They will be leaked.
[13920:14599:1211/142036.984205:WARNING:internal_linux.cc(64)] Failed to read /proc/14067/stat
[13920:13920:1211/142036.994714:WARNING:pref_notifier_impl.cc(23)] Pref observer found at shutdown.
[13920:13920:1211/142036.994794:WARNING:pref_notifier_impl.cc(23)] Pref observer found at shutdown.
[  FAILED  ] ExtensionWebRequestApiTest.WebRequestTypes, where TypeParam =  and GetParam() =  (16970 ms)
Just so it's not lost above, this is also logged when running :

[153312:153312:1213/231114.550082:INFO:CONSOLE(0)] "[FAIL] sendBeaconInFrameOnUnload: Received unexpected event 'onHeadersReceived':{
  "frameId": -1,
  "initiator": "chrome-extension://fdhkpdgmkfnpiggkhjmdakfniedboabp",
  "method": "POST",
  "parentFrameId": -1,
  "statusCode": 200,
  "statusLine": "HTTP/1.1 200 OK",
  "tabId": -1,
  "type": "ping",
  "url": "http://www.a.com:40457/slow?2.718"
}

Per comment 7, frameId and tabId are expected to both have id 1. Locally I was able to make it fail both without my reland. With reland 9/50 passed, without reland 49/50 passed, so it got significantly flakier.
Labels: -Sheriff-Chromium
Owner: ----
Status: Available (was: Assigned)
I have a couple of other things on my plate before I can get to this.
It is possible that this is the same as issue 733395 

Findit shows some of the asan/msan failures along with this failure:
https://findit-for-me.appspot.com/waterfall/list-flakes?test_name=ExtensionWebRequestApiTest.WebRequestTypes

This test didn't start to time out though? Are you seeing flaky expectation fails on asan/msan?
I can reproduce this repeatedly with a Debug build with --enable-features=SingleProcessMash (but not without).

These are not timeouts, so may not be the same as  issue 73395 , I just thought it might be timing related since the failures appear to be associated with Debug or Asan builds and the test is in JS.

Cc: cduvall@chromium.org
Note: I am goetting an unexpected 'onCompleted' event, not 'onHeadersReceived':

[27322:27322:1217/135818.259000:INFO:CONSOLE(0)] "[FAIL] sendBeaconInFrameOnUnload: Received unexpected event 'onCompleted':{
  "frameId": -1,
  "fromCache": false,
  "initiator": "chrome-extension://loonmgklhmepcapaepfloljealaelhna",
  "ip": "127.0.0.1",
  "method": "POST",
  "parentFrameId": -1,
  "statusCode": 200,
  "statusLine": "HTTP/1.1 200 OK",
  "tabId": -1,
  "type": "ping",
  "url": "http://www.a.com:38033/slow?2.718"
}

+cduvall@ who most recently touched https://cs.chromium.org/chromium/src/chrome/test/data/extensions/api_test/webrequest/framework.js
This is basically a race condition of WebRequestInfo constructor and RenderFrameHost contructor.

The test case creates an iframe, removes it, and then sends beacon on unload of the iframe. In Chrome, RenderFrameHost is created, and then removed during the process of sending the beacon. WebRequest API creates the info -- WebRequestInfo -- to keep track of it.

When RenderFrameHost is created before WebRequestInfo, the info can be cached within WebRequestInfo, so the test can pass. Otherwise, WebRequestInfo misses to fetch the tabId / frameId -- in that case it always looks up with ExtensionApiFrameIdMap. Since RenderFrameHost is gone during the process, some steps (like onCompleted and onHeadersReceived) fail to look up those info, which causes to set '-1'.

It's unclear why this happens only with SingleProcessMash, but some additional asynchronousness might be the cause. Maybe the right solution would be to cache the tabid / frameid into WebRequestInfo.
Thanks for the investigation mukai@. Seems like the issue might be with the extension api as opposed to mash. 

Our frame_id->tab_id mapping is not perfect, which is an artifact of some of this info residing on the UI thread (RenderFrameHost) with the Web request api working mostly on the IO thread. 

mukai@: 
- Do we end up persisting a frame ID of -1 in this case on the WebRequestInfo (I don't think this should happen if the request originated from a render frame). 

We use the frame id to fetch the tab ID subsequently, which can fail if the RFH is now no longer alive. This should be rare, we have a TODO for this in the code- https://cs.chromium.org/chromium/src/extensions/browser/api/web_request/web_request_info.cc?sq=package:chromium&g=0&l=384
I chased the failure down to WebRequestInfo::InitializeWebViewAndFrameData [1]. The problem is related to issue 843762. When it happens, |was_cached| is false, WebRequestInfo ends up with no |frame_data|. It could also happen to classic mode too so not really mash related.

[1] https://cs.chromium.org/chromium/src/extensions/browser/api/web_request/web_request_info.cc?rcl=6de01bf77212792a1307576105fd75c0ae652e2f&l=384
Labels: -Proj-Mash-SingleProcess
Owner: karandeepb@chromium.org
Passing to karandeepb@, owner of issue 843762 and removing mash label since it happens without mash too.
The failed test case is always sendBeaconInFrameOnUnload. So we might be removing the cached data too fast ?
Labels: -Pri-1 Pri-2
Status: Assigned (was: Available)
Yeah that's what is probably happening. I'll get to this when I have some time. Reducing to P2, since this isn't a regression.

Sign in to add a comment