STR: * In a profile configured with Sync, visit about:sync-log. It should list some files - if it doesn't flip the pref "services.sync.log.appender.file.logOnSuccess" to true and perform a sync - a success log should appear. * Click on a log file name Expected: * The contents of the log file are shown. Actual: * Nothing happens. Note that this about page is created at https://dxr.mozilla.org/mozilla-central/source/services/sync/Weave.js#168 - it basically returns a file:// URI to a local directory and expects the directory viewer to do the work. mozregression tells me this was caused by bug 1182569 and a quick look there doesn't give me many clues. Christoph, do you have any ideas what specifically broke this and what we can do to fix it?

Presumably you're now failing one of the security checks under asyncOpen2. It's worth checking whether the CheckLoadURIWithPrincipal check under DoCheckLoadURIChecks in nsScriptSecurityManager.cpp fails, and if it does what aURI and aLoadInfo->TriggeringPrincipal() are in that situation. Based on a quick look at Weave.js they should both be file:// URIs and hence this test should pass, but it woudl be good to know what they are if it fails...

(In reply to Boris Zbarsky [:bz] (still a bit busy) from comment #1) > It's worth checking whether the CheckLoadURIWithPrincipal check under > DoCheckLoadURIChecks in nsScriptSecurityManager.cpp fails, Best I can tell, CheckLoadURIWithPrincipal isn't failing our file:// URLs. I am seeing the following logged to the console, but a quick play can't catch these failing calls in the debugger to help diagnose. Loading the individual file:// URLs works fine. Loading a file:// URL of any directory seems to work fine. I'm out of time for today, but this might be useful in the meantime.

After some IRC conversation with :markh we found out that the triggeringPrincipal is about:sync-log, see all arguments underneath: doContentSecurityCheck { channelURI: file:///C:/Users/skip/AppData/Roaming/Mozilla/Firefox/Profiles/dev.dev/weave/logs/error-sync-1484011293632.txt loadingPrincipal: nullptr triggeringPrincipal: about:sync-log principalToInherit: nullptr contentPolicyType: 6 securityMode: SEC_ALLOW_CROSS_ORIGIN_DATA_IS_NULL, initalSecurityChecksDone: no enforceSecurity: no }

OK, why is that? What's the C++ and JS callstack to the asyncOpen2 call involved?

Note that you should be able to reproduce this without Sync being enabled - if you create a directory weave/logs/ under your profile directory and put any file there, about:sync-log should show that file (and be unable to load it) (In reply to Boris Zbarsky [:bz] (still a bit busy) from comment #4) > OK, why is that? What's the C++ and JS callstack to the asyncOpen2 call > involved? At the time that entry is written the c++ stack is: > xul.dll!nsContentSecurityManager::doContentSecurityCheck(nsIChannel * aChannel, nsCOMPtr<nsIStreamListener> & aInAndOutListener) Line 562 C++ > xul.dll!nsBaseChannel::AsyncOpen2(nsIStreamListener * aListener) Line 703 C++ > xul.dll!nsURILoader::OpenURI(nsIChannel * channel, unsigned int aFlags, nsIInterfaceRequestor * aWindowContext) Line 837 C++ > xul.dll!nsDocShell::DoChannelLoad(nsIChannel * aChannel, nsIURILoader * aURILoader, bool aBypassClassifier) Line 11370 C++ > xul.dll!nsDocShell::DoURILoad(nsIURI * aURI, nsIURI * aOriginalURI, bool aLoadReplace, nsIURI * aReferrerURI, bool aSendReferrer, unsigned int aReferrerPolicy, nsIPrincipal * aTriggeringPrincipal, nsIPrincipal * aPrincipalToInherit, const char * aTypeHint, const nsAString_internal & aFileName, nsIInputStream * aPostData, nsIInputStream * aHeadersData, bool aFirstParty, nsIDocShell * * aDocShell, nsIRequest * * aRequest, bool aIsNewWindowTarget, bool aBypassClassifier, bool aForceAllowCookies, const nsAString_internal & aSrcdoc, nsIURI * aBaseURI, unsigned int aContentPolicyType) Line 11184 C++ > xul.dll!nsDocShell::InternalLoad(nsIURI * aURI, nsIURI * aOriginalURI, bool aLoadReplace, nsIURI * aReferrer, unsigned int aReferrerPolicy, nsIPrincipal * aTriggeringPrincipal, nsIPrincipal * aPrincipalToInherit, unsigned int aFlags, const nsAString_internal & aWindowTarget, const char * aTypeHint, const nsAString_internal & aFileName, nsIInputStream * aPostData, nsIInputStream * aHeadersData, unsigned int aLoadType, nsISHEntry * aSHEntry, bool aFirstParty, const nsAString_internal & aSrcdoc, nsIDocShell * aSourceDocShell, nsIURI * aBaseURI, bool aCheckForPrerender, nsIDocShell * * aDocShell, nsIRequest * * aRequest) Line 10672 C++ > xul.dll!nsDocShell::LoadURI(nsIURI * aURI, nsIDocShellLoadInfo * aLoadInfo, unsigned int aLoadFlags, bool aFirstParty) Line 1558 C++ > xul.dll!nsDocShell::LoadURIWithOptions(const char16_t * aURI, unsigned int aLoadFlags, nsIURI * aReferringURI, unsigned int aReferrerPolicy, nsIInputStream * aPostStream, nsIInputStream * aHeaderStream, nsIURI * aBaseURI) Line 4835 C++ > xul.dll!_NS_InvokeByIndex() Line 57 Unknown > xul.dll!CallMethodHelper::Invoke() Line 2058 C++ > xul.dll!CallMethodHelper::Call() Line 1377 C++ > xul.dll!XPCWrappedNative::CallMethod(XPCCallContext & ccx, XPCWrappedNative::CallMode mode) Line 1344 C++ > xul.dll!XPC_WN_CallMethod(JSContext * cx, unsigned int argc, JS::Value * vp) Line 999 C++ > xul.dll!js::CallJSNative(JSContext * cx, bool(*)(JSContext *, unsigned int, JS::Value *) native, const JS::CallArgs & args) Line 239 C++ > xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 457 C++ > xul.dll!InternalCall(JSContext * cx, const js::AnyInvokeArgs & args) Line 502 C++ > xul.dll!js::CallFromStack(JSContext * cx, const JS::CallArgs & args) Line 508 C++ > xul.dll!Interpret(JSContext * cx, js::RunState & state) Line 2928 C++ > xul.dll!js::RunScript(JSContext * cx, js::RunState & state) Line 403 C++ > xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 475 C++ > xul.dll!InternalCall(JSContext * cx, const js::AnyInvokeArgs & args) Line 502 C++ > xul.dll!js::Call(JSContext * cx, JS::Handle<JS::Value> fval, JS::Handle<JS::Value> thisv, const js::AnyInvokeArgs & args, JS::MutableHandle<JS::Value> rval) Line 521 C++ > xul.dll!js::Wrapper::call(JSContext * cx, JS::Handle<JSObject *> proxy, const JS::CallArgs & args) Line 165 C++ > xul.dll!js::CrossCompartmentWrapper::call(JSContext * cx, JS::Handle<JSObject *> wrapper, const JS::CallArgs & args) Line 333 C++ > xul.dll!js::Proxy::call(JSContext * cx, JS::Handle<JSObject *> proxy, const JS::CallArgs & args) Line 421 C++ > xul.dll!js::proxy_Call(JSContext * cx, unsigned int argc, JS::Value * vp) Line 662 C++ > xul.dll!js::CallJSNative(JSContext * cx, bool(*)(JSContext *, unsigned int, JS::Value *) native, const JS::CallArgs & args) Line 239 C++ > xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 445 C++ > xul.dll!InternalCall(JSContext * cx, const js::AnyInvokeArgs & args) Line 502 C++ > xul.dll!js::CallFromStack(JSContext * cx, const JS::CallArgs & args) Line 508 C++ > xul.dll!Interpret(JSContext * cx, js::RunState & state) Line 2928 C++ > xul.dll!js::RunScript(JSContext * cx, js::RunState & state) Line 403 C++ > xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 475 C++ > xul.dll!InternalCall(JSContext * cx, const js::AnyInvokeArgs & args) Line 502 C++ > xul.dll!js::CallFromStack(JSContext * cx, const JS::CallArgs & args) Line 508 C++ > xul.dll!Interpret(JSContext * cx, js::RunState & state) Line 2928 C++ > xul.dll!js::RunScript(JSContext * cx, js::RunState & state) Line 403 C++ > xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 475 C++ > xul.dll!InternalCall(JSContext * cx, const js::AnyInvokeArgs & args) Line 502 C++ > xul.dll!js::Call(JSContext * cx, JS::Handle<JS::Value> fval, JS::Handle<JS::Value> thisv, const js::AnyInvokeArgs & args, JS::MutableHandle<JS::Value> rval) Line 521 C++ > xul.dll!JS_CallFunctionValue(JSContext * cx, JS::Handle<JSObject *> obj, JS::Handle<JS::Value> fval, const JS::HandleValueArray & args, JS::MutableHandle<JS::Value> rval) Line 2787 C++ > xul.dll!nsFrameMessageManager::ReceiveMessage(nsISupports * aTarget, nsIFrameLoader * aTargetFrameLoader, bool aTargetClosed, const nsAString_internal & aMessage, bool aIsSync, mozilla::dom::ipc::StructuredCloneData * aCloneData, mozilla::jsipc::CpowHolder * aCpows, nsIPrincipal * aPrincipal, nsTArray<mozilla::dom::ipc::StructuredCloneData> * aRetVal) Line 1065 C++ with the DumpJSStack() outputting: > 0 restoreTabContent(loadArguments = [object Object], isRemotenessUpdate = true, finishCallback = () => { > // Tell SessionStore.jsm that it may want to restore some more tabs, > // since it restores a max of MAX_CONCURRENT_TAB_RESTORES at a time. > sendAsyncMessage("SessionStore:restoreTabContentComplete", {epoch, isRemotenessUpdate}); > }) ["resource:///modules/sessionstore/ContentRestore.jsm":212] > this = [object Object] > 1 bound restoreTabContent([object Object], true, () => { > // Tell SessionStore.jsm that it may want to restore some more tabs, > // since it restores a max of MAX_CONCURRENT_TAB_RESTORES at a time. > sendAsyncMessage("SessionStore:restoreTabContentComplete", {epoch, isRemotenessUpdate}); > }) ["self-hosted":933] > this = [object Object] > 2 restoreTabContent((destructured parameter) = [object Object]) ["chrome://browser/content/content-sessionStore.js":202] > this = [object Object] > 3 receiveMessage((destructured parameter) = [object Object]) ["chrome://browser/content/content-sessionStore.js":144] > this = [object Object]

Um... That looks like session history restore of a tab. That's calling nsDocShell::LoadURIWithOptions, which is expected. It passing a referrer is also kind of expected. But is it expected that this code executes when you click a filename in about:sync-log?

(In reply to Boris Zbarsky [:bz] (still a bit busy) from comment #6) > But is it expected that this code executes when you > click a filename in about:sync-log? I don't know the session restore code well enough to know for sure, but if I start Firefox without restoring a session, then hit about:sync-log, I see the same basic callstack for the about:page itself and the attempt to load the individual file - the stack in the parent includes https://dxr.mozilla.org/mozilla-central/source/browser/components/sessionstore/SessionStore.jsm#2756, and the comments there imply this path is expected even in some non-restore cases. FWIW, using the diagnostics Christoph asked me to add, the attempt to load the logfile via about:sync-log reports: doContentSecurityCheck { channelURI: file:///C:/Users/skip/AppData/Roaming/Mozilla/Firefox/Profiles/dev.dev/weave/logs/error-sync-1484011293632.txt loadingPrincipal: nullptr triggeringPrincipal: about:sync-log principalToInherit: nullptr contentPolicyType: 6 securityMode: SEC_ALLOW_CROSS_ORIGIN_DATA_IS_NULL, initalSecurityChecksDone: no enforceSecurity: no pid: 6656 } whereas pasting that URL directly results in: doContentSecurityCheck { channelURI: file:///C:/Users/skip/AppData/Roaming/Mozilla/Firefox/Profiles/dev.dev/weave/logs/error-sync-1484011293632.txt loadingPrincipal: nullptr triggeringPrincipal: SystemPrincipal principalToInherit: NullPrincipal contentPolicyType: 6 securityMode: SEC_ALLOW_CROSS_ORIGIN_DATA_IS_NULL, initalSecurityChecksDone: no enforceSecurity: no pid: 6656 } note the difference in principals. I'm not sure if that's helpful or not.

> I don't know the session restore code well enough to know for sure OK, I don't either. Maybe all loads go through there nowadays due to the process-switching we have to do sometimes. > I see the same basic callstack for the about:page itself Sure, this sort of callstack is expected for loads from the url bar. It's not expected for loads from link clicks or the like, though. That said, maybe the answer is in fact the e10s switcheroo bit: if I load about:sync-log in a non-e10s process it works fine. We recently implement a separate process for file:// loads; see bug 1147911. If so, it's possible that about:sync-log gets loaded in one process (chrome process, afaict) and then the link click tries to kick over to the file:// process and the kicking-over procedure loses the triggering principal (for reasons described in 1329032, and note that it's worth checking whether the patch in that bug helps). > note the difference in principals Sure, that's expected given all the other bits above. That difference in principals is precisely the problem. It should be SystemPrincipal in both cases, and the link-click case is screwing it up.

I _did_ just try changing the "browser.tabs.remote.separateFileUriProcess" preference to "false", and that does not seem to help this bug (and yes, this preference afaict should take effect without restart). I'm not sure what to make of it, nor what it means for my hypothesis in comment 8. But I still expect that chrome overriding the default core codepath and taking over the load itself (for whatever reason), and then, unavoidably, messing up the triggering principal is the prime suspect here. Still worth testing the patch from bug 1329032.

(In reply to Boris Zbarsky [:bz] (still a bit busy) from comment #9) > Still worth testing the patch from bug 1329032. Indeed - with that patch applied it WFM - thanks!

> I'm not sure what to make of it, nor what it means for my hypothesis in comment 8. Actually, I do know what to make of it. about:sync-log is loaded in the chrome process. The file:// links from it are always loaded in a content process; "browser.tabs.remote.separateFileUriProcess" just controls _which_ content process. So in all cases we ended up in the "hand it over to the other process" code.