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)
Tracking
()
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]
Comment 1•6 years ago
|
||
Comment 2•6 years ago
|
||
This should be taken care of in the patch for Bug 1568717: https://phabricator.services.mozilla.com/D39341
Comment hidden (Intermittent Failures Robot) |
Updated•6 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 6•6 years ago
|
||
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?
Comment hidden (Intermittent Failures Robot) |
Comment 8•6 years ago
|
||
Michal, can you take a look? Thanks!
Comment 9•6 years ago
|
||
AFAICS the failure isn't related to fetch/networking. For some reason onload event handler of the link element isn't called.
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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 12•6 years ago
|
||
tracking these failures in bug 1568717
Comment hidden (Intermittent Failures Robot) |
Comment 14•6 years ago
|
||
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
Updated•6 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 16•6 years ago
|
||
There are 28 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-08-27&endday=2019-09-03&tree=trunk&bug=1569098
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=264715294&repo=mozilla-central&lineNumber=26563
Comment 17•6 years ago
|
||
Michal, could you please take a look over this when you have the time? Thank you.
Comment 18•6 years ago
|
||
(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.
Comment 19•6 years ago
|
||
Comment 20•6 years ago
|
||
Updated•6 years ago
|
Comment 21•6 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Updated•6 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 31•6 years ago
|
||
Comment 32•6 years ago
|
||
Retriggered:
From this and the above, this looks like it started from the wpt sync push:
:nhi can you take a look?
Assignee | ||
Comment 33•6 years ago
|
||
Updated•6 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 35•6 years ago
|
||
recent failures here should be fixed by: https://hg.mozilla.org/integration/autoland/rev/7f12981e8bd4c0f72750c31c9528b54b67b24d66
Updated•6 years ago
|
Comment 38•6 years ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 40•6 years ago
|
||
Comment 41•6 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment 43•6 years ago
|
||
bugherder |
Assignee | ||
Updated•6 years ago
|
Updated•6 years ago
|
Comment 44•6 years ago
|
||
bugherder uplift |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Description
•