Closed Bug 1569098 Opened 5 months ago Closed 11 days ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /fetch/metadata/redirect/redirect-https-downgrade.tentative.sub.html | Https downgrade prefetch => No headers - Test timed out

Categories

(Core :: DOM: Networking, defect, P3)

defect

Tracking

()

RESOLVED FIXED
mozilla73
Tracking Status
firefox-esr68 --- unaffected
firefox71 --- wontfix
firefox72 --- fixed
firefox73 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: apavel)

References

Details

(Keywords: intermittent-failure, regression, Whiteboard: [necko-triaged][retriggered])

Attachments

(3 files)

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=258435478&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/EiB8tGKLTla7YyDwYbjkZQ/runs/0/artifacts/public/logs/live_backing.log


[task 2019-07-26T03:12:24.196Z] 03:12:24 INFO - PID 2046 | --DOMWINDOW == 10 (0x12fa2f400) [pid = 2056] [serial = 7] [outer = 0x0] [url = about:blank]
[task 2019-07-26T03:12:40.433Z] 03:12:40 INFO -
[task 2019-07-26T03:12:40.433Z] 03:12:40 INFO - TEST-PASS | /fetch/sec-metadata/redirect/redirect-https-downgrade.tentative.sub.html | Https downgrade iframe => No headers
[task 2019-07-26T03:12:40.433Z] 03:12:40 INFO - TEST-PASS | /fetch/sec-metadata/redirect/redirect-https-downgrade.tentative.sub.html | Https downgrade top level navigation => No headers
[task 2019-07-26T03:12:40.433Z] 03:12:40 INFO - TEST-PASS | /fetch/sec-metadata/redirect/redirect-https-downgrade.tentative.sub.html | Https downgrade embed => No headers
[task 2019-07-26T03:12:40.433Z] 03:12:40 INFO - TEST-PASS | /fetch/sec-metadata/redirect/redirect-https-downgrade.tentative.sub.html | Https downgrade fetch() api => No headers
[task 2019-07-26T03:12:40.433Z] 03:12:40 INFO - TEST-PASS | /fetch/sec-metadata/redirect/redirect-https-downgrade.tentative.sub.html | Https downgrade object => No headers
[task 2019-07-26T03:12:40.433Z] 03:12:40 INFO - TEST-UNEXPECTED-TIMEOUT | /fetch/sec-metadata/redirect/redirect-https-downgrade.tentative.sub.html | Https downgrade prefetch => No headers - Test timed out
[task 2019-07-26T03:12:40.433Z] 03:12:40 INFO - TEST-INFO | expected FAIL
[task 2019-07-26T03:12:40.433Z] 03:12:40 INFO - ......
[task 2019-07-26T03:12:40.433Z] 03:12:40 INFO - TEST-TIMEOUT | /fetch/sec-metadata/redirect/redirect-https-downgrade.tentative.sub.html | took 30826ms
[task 2019-07-26T03:12:40.457Z] 03:12:40 INFO - PID 2046 | 1564110760443 Marionette INFO Stopped listening on port 50088
[task 2019-07-26T03:12:40.657Z] 03:12:40 INFO - PID 2046 | [Child 2048, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/workspace/build/src/widget/cocoa/nsAppShell.mm, line 725
[task 2019-07-26T03:12:40.657Z] 03:12:40 INFO - PID 2046 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-07-26T03:12:40.657Z] 03:12:40 INFO - PID 2046 | [Child 2049, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/workspace/build/src/widget/cocoa/nsAppShell.mm, line 725
[task 2019-07-26T03:12:40.657Z] 03:12:40 INFO - PID 2046 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-07-26T03:12:40.714Z] 03:12:40 INFO - PID 2046 | --DOCSHELL 0x11d908800 == 3 [pid = 2048] [id = {b28c2aec-df31-5f4d-8ee0-d87ed0b05121}] [url = moz-extension://15fc4cdc-f987-6846-8558-279e8755df1d/_generated_background_page.html]
[task 2019-07-26T03:12:40.714Z] 03:12:40 INFO - PID 2046 | --DOCSHELL 0x11d90f800 == 2 [pid = 2048] [id = {2576ab28-8386-234a-8c3c-ea54e334cabc}] [url = moz-extension://bc34b511-7cc0-ff4b-a348-392300bd5c54/_generated_background_page.html]
[task 2019-07-26T03:12:40.716Z] 03:12:40 INFO - PID 2046 | --DOCSHELL 0x11d90d800 == 1 [pid = 2048] [id = {f734c9c9-a888-5843-b3ab-bedf44729f23}] [url = moz-extension://34a6fab3-5a8b-ee4a-abe6-310fe0804234/_generated_background_page.html]
[task 2019-07-26T03:12:40.716Z] 03:12:40 INFO - PID 2046 | --DOCSHELL 0x11d912000 == 0 [pid = 2048] [id = {ae78041f-d1e3-2a45-9c58-1febced39a4f}] [url = moz-extension://e12e2613-9166-4142-922a-9643f54629b8/_generated_background_page.html]
[task 2019-07-26T03:12:40.716Z] 03:12:40 INFO - PID 2046 | --DOCSHELL 0x1128df800 == 0 [pid = 2049] [id = {070e4a45-514d-a14f-9d37-ed9013f59085}] [url = http://web-platform.test:8000/testharness_runner.html]
[task 2019-07-26T03:12:40.748Z] 03:12:40 INFO - PID 2046 | --DOMWINDOW == 3 (0x118445020) [pid = 2049] [serial = 1] [outer = 0x0] [url = http://web-platform.test:8000/testharness_runner.html]
[task 2019-07-26T03:12:40.749Z] 03:12:40 INFO - PID 2046 | --DOMWINDOW == 2 (0x1184f0400) [pid = 2049] [serial = 7] [outer = 0x0] [url = https://web-platform.test:8443/testharness_runner.html]
[task 2019-07-26T03:12:40.749Z] 03:12:40 INFO - PID 2046 | --DOMWINDOW == 1 (0x1191ec800) [pid = 2049] [serial = 6] [outer = 0x0] [url = http://web-platform.test:8000/testharness_runner.html]
[task 2019-07-26T03:12:40.749Z] 03:12:40 INFO - PID 2046 | --DOMWINDOW == 0 (0x1186d7400) [pid = 2049] [serial = 8] [outer = 0x0] [url = http://web-platform.test:8000/testharness_runner.html]
[task 2019-07-26T03:12:40.749Z] 03:12:40 INFO - PID 2046 | --DOMWINDOW == 7 (0x11d94e3e0) [pid = 2048] [serial = 2] [outer = 0x0] [url = moz-extension://34a6fab3-5a8b-ee4a-abe6-310fe0804234/_generated_background_page.html]

This should be taken care of in the patch for Bug 1568717: https://phabricator.services.mozilla.com/D39341

Whiteboard: [necko-triaged]
See Also: → 1570643

There are 30 failures associated to this bug in the last 7 days. These are occurring on linux32-shippable, linux64, linux64-shippable debug and opt builds.

:nhi can you take a look?

Flags: needinfo?(nhnguyen)
Whiteboard: [necko-triaged] → [stockwell needswork][necko-triaged]
See Also: → 1568717

Michal, can you take a look? Thanks!

Flags: needinfo?(nhnguyen) → needinfo?(michal.novotny)

AFAICS the failure isn't related to fetch/networking. For some reason onload event handler of the link element isn't called.

https://searchfox.org/mozilla-central/rev/ab6f4c453d15ab82147c630a8b886b40240ca72b/testing/web-platform/tests/fetch/sec-metadata/resources/redirectTestHelper.sub.js#119

EventListenerManager::HandleEvent() for the link element isn't called. I'm not familiar with this code, so I'm not able to dig more into it.

FWIW, the onload handler is called and the test succeeds when I comment out the preceding test which creates the object element.

Component: DOM: Networking → DOM: Events
Flags: needinfo?(michal.novotny)
Whiteboard: [stockwell needswork][necko-triaged] → [stockwell needswork]

tracking these failures in bug 1568717

Status: NEW → RESOLVED
Closed: 4 months ago
Resolution: --- → DUPLICATE
Duplicate of bug: 1568717

Reopening the bug because the reason why prefetch test times out isn't caused by missing implementation of fetch metadata request headers. Tests object-https-redirect and prefetch run in parallel and when the object starts to load nsPrefetchService::StopPrefetching() is called which cancels the prefetch. Is this expected?

#0 0x000008295502ecda in nsPrefetchService::StopPrefetching() (this=0x2e3032b86160) at /mnt/work/opt/moz/hg-central-dc/uriloader/prefetch/nsPrefetchService.cpp:523
#1 0x00000829550313ca in nsPrefetchService::OnStateChange(nsIWebProgress*, nsIRequest*, unsigned int, nsresult)
(this=0x2e3032b86160, aWebProgress=0x2e3032b11828, aRequest=0x2e3032b10880, progressStateFlags=720897, aStatus=nsresult::NS_OK)
at /mnt/work/opt/moz/hg-central-dc/uriloader/prefetch/nsPrefetchService.cpp:872
#2 0x0000082954fd78fb in nsDocLoader::DoFireOnStateChange(nsIWebProgress*, nsIRequest*, int&, nsresult)
(this=0x20751b65fda0, aProgress=0x2e3032b11828, aRequest=0x2e3032b10880, aStateFlags=@0x7ffc452e68f4: 720897, aStatus=nsresult::NS_OK)
at /mnt/work/opt/moz/hg-central-dc/uriloader/base/nsDocLoader.cpp:1333
#3 0x0000082954fd6ed2 in nsDocLoader::FireOnStateChange(nsIWebProgress*, nsIRequest*, int, nsresult)
(this=0x2e3032b11800, aProgress=0x2e3032b11828, aRequest=0x2e3032b10880, aStateFlags=720897, aStatus=nsresult::NS_OK)
at /mnt/work/opt/moz/hg-central-dc/uriloader/base/nsDocLoader.cpp:1296
#4 0x0000082954fd651f in nsDocLoader::doStartDocumentLoad() (this=0x2e3032b11800) at /mnt/work/opt/moz/hg-central-dc/uriloader/base/nsDocLoader.cpp:816
#5 0x0000082954fd6294 in nsDocLoader::OnStartRequest(nsIRequest*) (this=0x2e3032b11800, request=0x2e3032b10880)
at /mnt/work/opt/moz/hg-central-dc/uriloader/base/nsDocLoader.cpp:441
#6 0x0000082953926824 in mozilla::net::nsLoadGroup::AddRequest(nsIRequest*, nsISupports*) (this=0x2e3032b5df30, request=0x2e3032b10880, ctxt=0x0)
at /mnt/work/opt/moz/hg-central-dc/netwerk/base/nsLoadGroup.cpp:452
#7 0x0000082954fdf292 in nsURILoader::OpenChannel(nsIChannel*, unsigned int, nsIInterfaceRequestor*, bool, nsIStreamListener**)
(this=0x550162069fa0, channel=0x2e3032b10880, aFlags=2, aWindowContext=0x2e3032b11830, aChannelIsOpen=true, aListener=0x7ffc452e7218)
at /mnt/work/opt/moz/hg-central-dc/uriloader/base/nsURILoader.cpp:930
#8 0x0000082954fdf4ff in nsURILoader::OpenChannel(nsIChannel*, unsigned int, nsIInterfaceRequestor*, nsIStreamListener**)
(this=0x550162069fa0, channel=0x2e3032b10880, aFlags=2, aWindowContext=0x2e3032b11830, aListener=0x7ffc452e7218)
at /mnt/work/opt/moz/hg-central-dc/uriloader/base/nsURILoader.cpp:953
#9 0x0000082955b41fed in nsObjectLoadingContent::LoadObject(bool, bool, nsIRequest*) (this=0x2e3032b3bca8, aNotify=true, aForceLoad=false, aLoadingChannel=0x2e3032b10880)
at /mnt/work/opt/moz/hg-central-dc/dom/base/nsObjectLoadingContent.cpp:2135
#10 0x0000082955b4083b in nsObjectLoadingContent::OnStartRequest(nsIRequest*) (this=0x2e3032b3bca8, aRequest=0x2e3032b10880)
at /mnt/work/opt/moz/hg-central-dc/dom/base/nsObjectLoadingContent.cpp:1012
#11 0x0000082955b4fca2 in ObjectInterfaceRequestorShim::OnStartRequest(nsIRequest*) (this=0x2e3032b96220, aRequest=0x2e3032b10880)
at /mnt/work/opt/moz/hg-central-dc/dom/base/nsObjectLoadingContent.cpp:1160
#12 0x0000082953f26fc1 in mozilla::net::HttpChannelChild::DoOnStartRequest(nsIRequest*, nsISupports*) (this=0x2e3032b10800, aRequest=0x2e3032b10880, aContext=0x0)
at /mnt/work/opt/moz/hg-central-dc/netwerk/protocol/http/HttpChannelChild.cpp:683
#13 0x0000082953f2c559 in mozilla::net::HttpChannelChild::OnStartRequest(nsresult const&, mozilla::net::nsHttpResponseHead const&, bool const&, mozilla::net::nsHttpHeaderArray const&, mozilla::net::ParentLoadInfoForwarderArgs const&, bool const&, bool const&, bool const&, unsigned long const&, int const&, unsigned int const&, nsTString<char> const&, nsTString<char> const&, mozilla::net::NetAddr const&, mozilla::net::NetAddr const&, unsigned int const&, nsTString<char> const&, long const&, bool const&, bool const&, bool const&, mozilla::net::ResourceTimingStruct const&, bool const&)
(this=0x2e3032b10800, channelStatus=@0x5501620a7410: nsresult::NS_OK, responseHead=..., useResponseHead=@0x5501620a74d0: true, requestHeaders=..., loadInfoForwarder=..., isFromCache=@0x5501620a74d2: false, isRacing=@0x5501620a74d3: false, cacheEntryAvailable=@0x5501620a74d4: true, cacheEntryId=@0x5501620a74d8: 0, cacheFetchCount=@0x5501620a74e0: 0, cacheExpirationTime=@0x5501620a74e4: 0, cachedCharset=..., securityInfoSerialization=..., selfAddr=..., peerAddr=..., cacheKey=@0x5501620a75e8: 0, altDataType=..., altDataLen=@0x5501620a7600: -1, deliveringAltData=@0x5501620a7608: false, aApplyConversion=@0x5501620a74d1: true, aIsResolvedByTRR=@0x5501620a7708: false, aTiming=..., aAllRedirectsSameOrigin=@0x5501620a77a0: false) at /mnt/work/opt/moz/hg-central-dc/netwerk/protocol/http/HttpChannelChild.cpp:608

Status: RESOLVED → REOPENED
Component: DOM: Events → DOM: Core & HTML
Resolution: DUPLICATE → ---
Component: DOM: Core & HTML → DOM: Networking

Michal, could you please take a look over this when you have the time? Thank you.

Flags: needinfo?(michal.novotny)

(In reply to Cosmin Sabou [:CosminS] from comment #17)

Michal, could you please take a look over this when you have the time? Thank you.

I don't think this is a necko issue. I've summarized my investigation in comment #14 and changed the component according to my best guess. It was bounced back to "DOM: networking" component without any comment. I don't know whether the test is supposed to work correctly and we wrongly cancel the prefetch, or whether the test is badly written and our behavior is correct. In any case, I'm not going to work on this.

Flags: needinfo?(michal.novotny)
Pushed by csabou@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b489f97bfb2d
Update test expectations for frequent failures on windows. r=jgraham
Keywords: leave-open
Whiteboard: [stockwell unknown][stockwell needswork:owner]
Priority: -- → P3
Whiteboard: [necko-triaged]
Assignee: nobody → apavel

Failures are fixed by the above.

Flags: needinfo?(nhnguyen)
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /fetch/sec-metadata/redirect/redirect-https-downgrade.tentative.sub.html | Https downgrade prefetch => No headers - Test timed out → Intermittent TEST-UNEXPECTED-TIMEOUT | /fetch/metadata/redirect/redirect-https-downgrade.tentative.sub.html | Https downgrade prefetch => No headers - Test timed out
Duplicate of this bug: 1600374

please see https://bugzilla.mozilla.org/show_bug.cgi?id=1568717#c51 for a bit of overview on what's going on here from the failures point of view.

Pushed by ccoroiu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e690f23cc19b
update redirect-https-downgrade.tentative.sub.html expectation r=jmaher
Status: REOPENED → RESOLVED
Closed: 4 months ago11 days ago
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → mozilla73
You need to log in before you can comment on or make changes to this bug.