1329883 - about:sync-log no longer shows individual log files.

Status: RESOLVED DUPLICATE of bug 1329032

(Firefox :: Sync, defect)

Description

[Mark Hammond [:markh] [:mhammond]]

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?

Comment 1

[Boris Zbarsky [:bzbarsky]]

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...

Comment 2

[Mark Hammond [:markh] [:mhammond]]

(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.

Comment 3

[Christoph Kerschbaumer [:ckerschb]]

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
}

Comment 4

[Boris Zbarsky [:bzbarsky]]

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

Comment 5

[Mark Hammond [:markh] [:mhammond]]

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]

Comment 6

[Boris Zbarsky [:bzbarsky]]

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?

Comment 7

[Mark Hammond [:markh] [:mhammond]]

(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.

Comment 8

[Boris Zbarsky [:bzbarsky]]

> 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.

Comment 9

[Boris Zbarsky [:bzbarsky]]

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.

Comment 10

[Mark Hammond [:markh] [:mhammond]]

(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!

Comment 11

[Boris Zbarsky [:bzbarsky]]

> 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.