Intermittent test_cpow_cookies.html | Test timed out.

RESOLVED FIXED in Firefox 57

Status

()

defect
RESOLVED FIXED
3 years ago
3 months ago

People

(Reporter: cbook, Assigned: ckerschb)

Tracking

({intermittent-failure})

unspecified
mozilla57
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox57 fixed)

Details

(Whiteboard: [stockwell fixed:logic], )

Attachments

(1 attachment)

Reporter

Description

3 years ago
https://treeherder.mozilla.org/logviewer.html#?job_id=3679275&repo=mozilla-central

 18:47:57 INFO - 44002 INFO TEST-UNEXPECTED-FAIL | dom/ipc/tests/test_cpow_cookies.html | Test timed out.

Comment 1

3 years ago
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Priority: P3 → P5
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)
This has been an infrequent failure on Android only for many months.

Beginning around September 10, failures became significantly more frequent on Android Debug; also, some failures are now seen on Windows Debug.

Recent Windows Debug failures show an assertion before the timeout:

https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=130033849&lineNumber=29023

10:35:20     INFO -  GECKO(5948) | [Child 1876] WARNING: site security information will not be persisted: file z:/build/build/src/security/manager/ssl/nsSiteSecurityService.cpp, line 553
10:35:20     INFO -  GECKO(5948) | [Child 1876] WARNING: stylo: ServoStyleSets cannot respond to document state changes yet (only matters for chrome documents). See bug 1290285.: file z:/build/build/src/layout/base/PresShell.cpp, line 4295
10:35:20     INFO -  GECKO(5948) | [Child 1876] WARNING: 'NS_FAILED(GetAccentColor(unused))', file z:/build/build/src/widget/windows/nsLookAndFeel.cpp, line 450
10:35:20     INFO -  GECKO(5948) | [Parent 5948] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file z:/build/build/src/netwerk/base/nsChannelClassifier.cpp, line 342
10:35:20     INFO -  GECKO(5948) | ++DOMWINDOW == 3 (0CA5C400) [pid = 1876] [serial = 3] [outer = 092DAC00]
10:35:20     INFO -  GECKO(5948) | [Child 1876] WARNING: stylo: Web Components not supported yet: file z:/build/build/src/dom/base/nsDocument.cpp, line 6413
10:35:20     INFO -  GECKO(5948) | [Child 1876] WARNING: stylo: Web Components not supported yet: file z:/build/build/src/dom/base/nsDocument.cpp, line 6413
10:35:20     INFO -  GECKO(5948) | [Child 1876] WARNING: stylo: ServoStyleSets cannot respond to document state changes yet (only matters for chrome documents). See bug 1290285.: file z:/build/build/src/layout/base/PresShell.cpp, line 4295
10:35:20     INFO -  GECKO(5948) | [Child 1876] WARNING: This content process hasn't received the permissions for http://mochi.test:8888 yet: file z:/build/build/src/extensions/cookie/nsPermissionManager.cpp, line 3329
10:35:21     INFO -  GECKO(5948) | Assertion failure: PermissionAvaliable(prin, aType), at z:/build/build/src/extensions/cookie/nsPermissionManager.cpp:2265
10:35:35     INFO -  GECKO(5948) | #01: nsPermissionManager::CommonTestPermissionInternal(nsIPrincipal *,nsIURI *,char const *,unsigned int *,bool,bool) [extensions/cookie/nsPermissionManager.cpp:2221]
10:35:35     INFO -  GECKO(5948) | #02: nsPermissionManager::TestPermission(nsIURI *,char const *,unsigned int *) [extensions/cookie/nsPermissionManager.cpp:2118]
10:35:35     INFO -  GECKO(5948) | #03: nsCookiePermission::CanAccess(nsIURI *,nsIChannel *,int *) [extensions/cookie/nsCookiePermission.cpp:162]
10:35:35     INFO -  GECKO(5948) | #04: nsCookieService::CheckPrefs(nsICookiePermission *,unsigned char,bool,nsIURI *,bool,char const *,int) [netwerk/cookie/nsCookieService.cpp:4198]
10:35:35     INFO -  GECKO(5948) | #05: mozilla::net::CookieServiceChild::SetCookieStringInternal(nsIURI *,nsIChannel *,char const *,char const *,bool) [netwerk/cookie/CookieServiceChild.cpp:527]
10:35:35     INFO -  GECKO(5948) | #06: mozilla::net::CookieServiceChild::SetCookieString(nsIURI *,nsIPrompt *,char const *,nsIChannel *) [netwerk/cookie/CookieServiceChild.cpp:601]
10:35:35     INFO -  GECKO(5948) | #07: nsHTMLDocument::SetCookie(nsTSubstring<char16_t> const &,mozilla::ErrorResult &) [dom/html/nsHTMLDocument.cpp:1425]
10:35:35     INFO -  GECKO(5948) | #08: mozilla::dom::HTMLDocumentBinding::set_cookie [s3:gecko-generated-sources:dabf923a208dba88f3a912d4b46c841a83a82fe2d13420b769c5f00b2de55afb547ec47df1d88138ddc40e0bf81b51150cc80f9ff28433daad20a340bd5e61b1/dom/bindings/HTMLDocumentBinding.cpp::123]
10:35:35     INFO -  GECKO(5948) | #09: mozilla::dom::GenericBindingSetter(JSContext *,unsigned int,JS::Value *) [dom/bindings/BindingUtils.cpp:3011]
10:35:35     INFO -  GECKO(5948) | #10: js::CallJSNative(JSContext *,bool (*)(JSContext *,unsigned int,JS::Value *),JS::CallArgs const &) [js/src/jscntxtinlines.h:293]
10:35:35     INFO -  GECKO(5948) | #11: js::InternalCallOrConstruct(JSContext *,JS::CallArgs const &,js::MaybeConstruct) [js/src/vm/Interpreter.cpp:495]
10:35:35     INFO -  GECKO(5948) | #12: InternalCall [js/src/vm/Interpreter.cpp:540]
10:35:35     INFO -  GECKO(5948) | #13: js::CallSetter(JSContext *,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::Handle<JS::Value>) [js/src/vm/Interpreter.cpp:688]
10:35:35     INFO -  GECKO(5948) | #14: js::SetPropertyIgnoringNamedGetter(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::Handle<JS::PropertyDescriptor>,JS::ObjectOpResult &) [js/src/proxy/BaseProxyHandler.cpp:237]
10:35:35     INFO -  GECKO(5948) | #15: js::BaseProxyHandler::set(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::ObjectOpResult &) [js/src/proxy/BaseProxyHandler.cpp:164]
10:35:35     INFO -  GECKO(5948) | #16: js::Proxy::setInternal(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::ObjectOpResult &) [js/src/proxy/Proxy.cpp:388]
10:35:35     INFO -  GECKO(5948) | #17: js::Proxy::set(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::ObjectOpResult &) [js/src/proxy/Proxy.cpp:400]
10:35:35     INFO -  GECKO(5948) | #18: JSObject::nonNativeSetProperty(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::ObjectOpResult &) [js/src/jsobj.cpp:1031]
10:35:35     INFO -  GECKO(5948) | #19: js::SetProperty(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::ObjectOpResult &) [js/src/vm/NativeObject.h:1546]
10:35:35     INFO -  GECKO(5948) | #20: js::SetPropertyIgnoringNamedGetter(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::Handle<JS::PropertyDescriptor>,JS::ObjectOpResult &) [js/src/proxy/BaseProxyHandler.cpp:182]
10:35:35     INFO -  GECKO(5948) | #21: js::BaseProxyHandler::set(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::ObjectOpResult &) [js/src/proxy/BaseProxyHandler.cpp:164]
10:35:35     INFO -  GECKO(5948) | #22: js::Proxy::setInternal(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::ObjectOpResult &) [js/src/proxy/Proxy.cpp:388]
10:35:35     INFO -  GECKO(5948) | #23: js::Proxy::set(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::ObjectOpResult &) [js/src/proxy/Proxy.cpp:400]
10:35:35     INFO -  GECKO(5948) | #24: JSObject::nonNativeSetProperty(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::ObjectOpResult &) [js/src/jsobj.cpp:1031]
10:35:35     INFO -  GECKO(5948) | #25: js::SetProperty(JSContext *,JS::Handle<JSObject *>,JS::Handle<jsid>,JS::Handle<JS::Value>,JS::Handle<JS::Value>,JS::ObjectOpResult &) [js/src/vm/NativeObject.h:1546]
10:35:35     INFO -  GECKO(5948) | #26: SetPropertyOperation [js/src/vm/Interpreter.cpp:269]
10:35:35     INFO -  GECKO(5948) | #27: Interpret [js/src/vm/Interpreter.cpp:2881]
10:35:35     INFO -  GECKO(5948) | #28: js::RunScript(JSContext *,js::RunState &) [js/src/vm/Interpreter.cpp:435]
10:35:35     INFO -  GECKO(5948) | #29: js::InternalCallOrConstruct(JSContext *,JS::CallArgs const &,js::MaybeConstruct) [js/src/vm/Interpreter.cpp:513]
10:35:35     INFO -  GECKO(5948) | #30: InternalCall [js/src/vm/Interpreter.cpp:540]
10:35:35     INFO -  GECKO(5948) | #31: js::Call(JSContext *,JS::Handle<JS::Value>,JS::Handle<JS::Value>,js::AnyInvokeArgs const &,JS::MutableHandle<JS::Value>) [js/src/vm/Interpreter.cpp:559]
10:35:35     INFO -  GECKO(5948) | #32: JS_CallFunctionValue(JSContext *,JS::Handle<JSObject *>,JS::Handle<JS::Value>,JS::HandleValueArray const &,JS::MutableHandle<JS::Value>) [js/src/jsapi.cpp:2906]
10:35:35     INFO -  GECKO(5948) | #33: nsFrameMessageManager::ReceiveMessage(nsISupports *,nsIFrameLoader *,bool,nsTSubstring<char16_t> const &,bool,mozilla::dom::ipc::StructuredCloneData *,mozilla::jsipc::CpowHolder *,nsIPrincipal *,nsTArray<mozilla::dom::ipc::StructuredCloneData> *) [dom/base/nsFrameMessageManager.cpp:1100]
10:35:35     INFO -  GECKO(5948) | #34: nsFrameMessageManager::ReceiveMessage(nsISupports *,nsIFrameLoader *,nsTSubstring<char16_t> const &,bool,mozilla::dom::ipc::StructuredCloneData *,mozilla::jsipc::CpowHolder *,nsIPrincipal *,nsTArray<mozilla::dom::ipc::StructuredCloneData> *) [dom/base/nsFrameMessageManager.cpp:911]
10:35:35     INFO -  GECKO(5948) | #35: mozilla::dom::TabChild::RecvAsyncMessage(nsTString<char16_t> const &,nsTArray<mozilla::jsipc::CpowEntry> &&,IPC::Principal const &,mozilla::dom::ClonedMessageData const &) [dom/ipc/TabChild.cpp:2332]
10:35:35     INFO -  GECKO(5948) | #36: mozilla::dom::PBrowserChild::OnMessageReceived(IPC::Message const &) [s3:gecko-generated-sources:ee267c8bd4438dbaf798a8c456bacbe69948f386221766fd7c6127f388cf4fcb4443b05bffe23aad3c7d9a87e2f3a2986c29884cbdf6ae72029a3aed165ea17e/ipc/ipdl/PBrowserChild.cpp::2681]
10:35:35     INFO -  GECKO(5948) | #37: mozilla::dom::PContentChild::OnMessageReceived(IPC::Message const &) [s3:gecko-generated-sources:aa8c1429b68a98970a291106c427da68e317cba8963cb3716f4d799c0288d3db63ecad33817d488baa4fc2838db00ab8b25b84dbee7c66cd6e4deefc7f03f653/ipc/ipdl/PContentChild.cpp::5194]
10:35:35     INFO -  GECKO(5948) | #38: mozilla::dom::ContentChild::OnMessageReceived(IPC::Message const &) [dom/ipc/ContentChild.cpp:3662]
10:35:35     INFO -  GECKO(5948) | #39: mozilla::ipc::MessageChannel::DispatchAsyncMessage(IPC::Message const &) [ipc/glue/MessageChannel.cpp:2120]
10:35:35     INFO -  GECKO(5948) | #40: mozilla::ipc::MessageChannel::DispatchMessageW(IPC::Message &&) [ipc/glue/MessageChannel.cpp:2047]
10:35:35     INFO -  GECKO(5948) | #41: mozilla::ipc::MessageChannel::RunMessage(mozilla::ipc::MessageChannel::MessageTask &) [ipc/glue/MessageChannel.cpp:1891]
10:35:35     INFO -  GECKO(5948) | #42: mozilla::ipc::MessageChannel::MessageTask::Run() [ipc/glue/MessageChannel.cpp:1925]
10:35:35     INFO -  GECKO(5948) | #43: mozilla::SchedulerGroup::Runnable::Run() [xpcom/threads/SchedulerGroup.cpp:396]
10:35:35     INFO -  GECKO(5948) | #44: nsThread::ProcessNextEvent(bool,bool *) [xpcom/threads/nsThread.cpp:1040]
10:35:35     INFO -  GECKO(5948) | #45: NS_ProcessNextEvent(nsIThread *,bool) [xpcom/threads/nsThreadUtils.cpp:521]
10:35:35     INFO -  GECKO(5948) | #46: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate *) [ipc/glue/MessagePump.cpp:125]
10:35:35     INFO -  GECKO(5948) | #47: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate *) [ipc/glue/MessagePump.cpp:301]
10:35:35     INFO -  GECKO(5948) | #48: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:326]
10:35:35     INFO -  GECKO(5948) | #49: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:320]
10:35:35     INFO -  GECKO(5948) | #50: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:300]
10:35:35     INFO -  GECKO(5948) | #51: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:160]
10:35:35     INFO -  GECKO(5948) | #52: nsAppShell::Run() [widget/windows/nsAppShell.cpp:230]
10:35:35     INFO -  GECKO(5948) | #53: XRE_RunAppShell() [toolkit/xre/nsEmbedFunctions.cpp:866]
10:35:35     INFO -  GECKO(5948) | #54: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate *) [ipc/glue/MessagePump.cpp:269]
10:35:35     INFO -  GECKO(5948) | #55: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:326]
10:35:35     INFO -  GECKO(5948) | #56: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:320]
10:35:35     INFO -  GECKO(5948) | #57: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:300]
10:35:35     INFO -  GECKO(5948) | #58: XRE_InitChildProcess(int,char * * const,XREChildData const *) [toolkit/xre/nsEmbedFunctions.cpp:695]
10:35:35     INFO -  GECKO(5948) | #59: mozilla::BootstrapImpl::XRE_InitChildProcess(int,char * * const,XREChildData const *) [toolkit/xre/Bootstrap.cpp:65]
10:35:35     INFO -  GECKO(5948) | #60: content_process_main(mozilla::Bootstrap *,int,char * * const) [ipc/contentproc/plugin-container.cpp:63]
10:35:35     INFO -  GECKO(5948) | #61: NS_internal_main(int,char * *,char * *) [browser/app/nsBrowserApp.cpp:285]
10:35:35     INFO -  GECKO(5948) | #62: wmain [toolkit/xre/nsWindowsWMain.cpp:118]
10:35:35     INFO -  GECKO(5948) | #63: __scrt_common_main_seh [f:/dd/vctools/crt/vcstartup/src/startup/exe_common.inl:253]
10:35:35     INFO -  GECKO(5948) | #64: kernel32.dll + 0x53c45
10:35:35     INFO -  GECKO(5948) | #65: ntdll.dll + 0x637f5
10:35:35     INFO -  GECKO(5948) | #66: ntdll.dll + 0x637c8


Android logcats show a similar assertion prior to the timeout.
Whiteboard: [stockwell needswork]
The new/frequent failure mode seemed to start with changes for bug 1397655, which touched this test.
Blocks: 1397655
Flags: needinfo?(ckerschb)
(In reply to Geoff Brown [:gbrown] from comment #15)
> The new/frequent failure mode seemed to start with changes for bug 1397655,
> which touched this test.

I'll have a look tomorrow - keeping ni? until then.
Comment hidden (Intermittent Failures Robot)
(In reply to Geoff Brown [:gbrown] from comment #15)
> The new/frequent failure mode seemed to start with changes for bug 1397655,
> which touched this test.

Unfortunately I have no idea what causes this permafail. The only thing we changed within Bug 1397655, is that we are loading the data: URI from an external file [1]. Honestly I don't know why that would change things. However, what we could try is to keep the data: URI and explicitly push the pref to allow top level data navigations and see if that improves things.

Smaug, would you be fine with that?

[1] https://hg.mozilla.org/mozilla-central/rev/697d93c85b77#l17.13
Flags: needinfo?(ckerschb)
Attachment #8907032 - Flags: review?(bugs)
Comment on attachment 8907032 [details] [diff] [review]
bug_1264588_cpow_cookies.patch

I guess there is some racy-ness somewhere, which might become more visible when non-data urls are used.
Attachment #8907032 - Flags: review?(bugs) → review+
Comment hidden (Intermittent Failures Robot)
https://hg.mozilla.org/mozilla-central/rev/294b732822db
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
Assignee: nobody → ckerschb
Whiteboard: [stockwell needswork:owner] → [stockwell fixed:other]
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Whiteboard: [stockwell needswork:owner] → [stockwell fixed:logic]
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.