Closed Bug 1264588 Opened 5 years ago Closed 3 years ago

Intermittent test_cpow_cookies.html | Test timed out.

Categories

(Core :: DOM: Core & HTML, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla57
Tracking Status
firefox57 --- fixed

People

(Reporter: cbook, Assigned: ckerschb)

References

()

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed:logic])

Attachments

(1 file)

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.
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Priority: P3 → P5
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.
(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+
https://hg.mozilla.org/mozilla-central/rev/294b732822db
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
Assignee: nobody → ckerschb
Whiteboard: [stockwell needswork:owner] → [stockwell fixed:other]
Whiteboard: [stockwell needswork:owner] → [stockwell fixed:logic]
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.