1239536 - [e10s] Hang in Linux when printing

Status: RESOLVED WORKSFORME

(Core :: DOM: Content Processes, defect, P1)

Description

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

I tried to print a boarding pass and it hung when the print settings dialog opened. I got two stacks. The content process was sending a sync message:

#4  0x00007f9c13577e4c in mozilla::ipc::MessageChannel::Send(IPC::Message*, IPC::Message*) () from /home/billm/Downloads/firefox/libxul.so
#5  0x00007f9c13742ae2 in mozilla::net::PCookieServiceChild::SendGetCookieString(mozilla::ipc::URIParams const&, bool const&, bool const&, IPC::SerializedLoadContext const&, nsCString*) () from /home/billm/Downloads/firefox/libxul.so
#6  0x00007f9c133cbdd1 in mozilla::net::CookieServiceChild::GetCookieStringInternal(nsIURI*, nsIChannel*, char**, bool) ()
   from /home/billm/Downloads/firefox/libxul.so
#7  0x00007f9c14291031 in nsHTMLDocument::GetCookie(nsAString_internal&, mozilla::ErrorResult&) () from /home/billm/Downloads/firefox/libxul.so
#8  0x00007f9c140a2ea9 in mozilla::dom::HTMLDocumentBinding::get_cookie(JSContext*, JS::Handle<JSObject*>, nsHTMLDocument*, JSJitGetterCallArgs) ()
   from /home/billm/Downloads/firefox/libxul.so
#9  0x00007f9c13056caa in mozilla::dom::GenericBindingGetter(JSContext*, unsigned int, JS::Value*) () from /home/billm/Downloads/firefox/libxul.so
#10 0x00007f9c13223b4b in js::Invoke(JSContext*, JS::CallArgs const&, js::MaybeConstruct) () from /home/billm/Downloads/firefox/libxul.so
#11 0x00007f9c13223f7d in js::Invoke(JSContext*, JS::Value const&, JS::Value const&, unsigned int, JS::Value const*, JS::MutableHandle<JS::Value>) ()
   from /home/billm/Downloads/firefox/libxul.so


The main process was doing what appears to be some kind of GTK-internal event loop:

#0  0x00007f990b9a67eb in __libc_recv (fd=125, buf=0x7f98a71e701a, n=4, 
    flags=-1) at ../sysdeps/unix/sysv/linux/x86_64/recv.c:33
#1  0x00007f98a5f725e0 in ?? () from /usr/lib/x86_64-linux-gnu/libcups.so.2
#2  0x00007f98a5f73371 in httpRead2 ()
   from /usr/lib/x86_64-linux-gnu/libcups.so.2
#3  0x00007f98a5f78b76 in ?? () from /usr/lib/x86_64-linux-gnu/libcups.so.2
#4  0x00007f98a5f7c172 in ippReadIO ()
   from /usr/lib/x86_64-linux-gnu/libcups.so.2
#5  0x00007f98a63eeb52 in ?? ()
   from /usr/lib/x86_64-linux-gnu/gtk-3.0/3.0.0/printbackends/libprintbackend-cups.so
#6  0x00007f98a63efe81 in gtk_cups_request_read_write ()
   from /usr/lib/x86_64-linux-gnu/gtk-3.0/3.0.0/printbackends/libprintbackend-cups.so
#7  0x00007f98a63e5d64 in ?? ()
   from /usr/lib/x86_64-linux-gnu/gtk-3.0/3.0.0/printbackends/libprintbackend-cups.so
#8  0x00007f9906040a61 in g_main_context_check ()
   from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#9  0x00007f9906040f7b in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#10 0x00007f99060410ec in g_main_context_iteration ()
   from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#11 0x00007f98fd8eba8f in nsAppShell::ProcessNextNativeEvent(bool) ()
   from /home/billm/Downloads/firefox/libxul.so
#12 0x00007f98fd8eabb4 in nsBaseAppShell::OnProcessNextEvent(nsIThreadInternal*, bool) () from /home/billm/Downloads/firefox/libxul.so
#13 0x00007f98fd83654c in nsThread::ProcessNextEvent(bool, bool*) ()
   from /home/billm/Downloads/firefox/libxul.so
#14 0x00007f98fdbcc731 in NS_ProcessPendingEvents(nsIThread*, unsigned int) ()
   from /home/billm/Downloads/firefox/libxul.so
#15 0x00007f98feecc890 in nsBaseAppShell::NativeEventCallback() ()
   from /home/billm/Downloads/firefox/libxul.so
#16 0x00007f98feeebb95 in nsAppShell::EventProcessorCallback(_GIOChannel*, GIOCondition, void*) () from /home/billm/Downloads/firefox/libxul.so
#17 0x00007f9906040ce5 in g_main_context_dispatch ()
   from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#18 0x00007f9906041048 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#19 0x00007f990604130a in g_main_loop_run ()
   from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#20 0x00007f9908a18a80 in gtk_dialog_run ()
   from /usr/lib/x86_64-linux-gnu/libgtk-3.so.0
#21 0x00007f98fef016ba in nsPrintDialogWidgetGTK::Run() ()
   from /home/billm/Downloads/firefox/libxul.so
#22 0x00007f98fef044b6 in nsPrintDialogServiceGTK::Show(nsIDOMWindow*, nsIPrintSettings*, nsIWebBrowserPrint*) () from /home/billm/Downloads/firefox/libxul.so
#23 0x00007f98ff32c0aa in nsPrintingPromptService::ShowPrintDialog(nsIDOMWindow*, nsIWebBrowserPrint*, nsIPrintSettings*) ()
   from /home/billm/Downloads/firefox/libxul.so
#24 0x00007f98ff32ae1b in mozilla::embedding::PrintingParent::ShowPrintDialog(mozilla::dom::PBrowserParent*, mozilla::embedding::PrintData const&, mozilla::embedding::PrintData*) () from /home/billm/Downloads/firefox/libxul.so
#25 0x00007f98ff32af27 in mozilla::embedding::PrintingParent::RecvShowPrintDialog(mozilla::embedding::PPrintSettingsDialogParent*, mozilla::dom::PBrowserParent*, mozilla::embedding::PrintData const&) ()
   from /home/billm/Downloads/firefox/libxul.so
#26 0x00007f98fdec6bc1 in mozilla::embedding::PPrintingParent::OnMessageReceived(IPC::Message const&) () from /home/billm/Downloads/firefox/libxul.so

Comment 1

[Jed Davis [:jld] ⟨⏰|UTC-7⟩ ⟦he/him⟧]

(In reply to Bill McCloskey (:billm) from comment #0)
> The main process was doing what appears to be some kind of GTK-internal
> event loop:
> 
> #0  0x00007f990b9a67eb in __libc_recv (fd=125, buf=0x7f98a71e701a, n=4, 
>     flags=-1) at ../sysdeps/unix/sysv/linux/x86_64/recv.c:33
> #1  0x00007f98a5f725e0 in ?? () from /usr/lib/x86_64-linux-gnu/libcups.so.2
> #2  0x00007f98a5f73371 in httpRead2 ()
>    from /usr/lib/x86_64-linux-gnu/libcups.so.2
> #3  0x00007f98a5f78b76 in ?? () from /usr/lib/x86_64-linux-gnu/libcups.so.2
> #4  0x00007f98a5f7c172 in ippReadIO ()
>    from /usr/lib/x86_64-linux-gnu/libcups.so.2

That looks like it's blocked on the CUPS library's HTTP client waiting for a response from the print server (after being called out of glib's event loop, so in principle there should be data there).  Is there anything we're doing to printing that might interfere with it on the level of file descriptors?  (Cf. the situation with X11, where we open the connection in the child and send a copy of the socket to the parent, which also uses it.)

Comment 2

[Wayne Mery (:wsmwk)]

FWIW there's quite a few other e10s print bugs http://mzl.la/1X3f8ZL

Comment 3

[Ting-Yu Chou [:ting] (away)]

I couldn't reproduce this, are there any specific sites I should try?

Comment 4

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

I wasn't able to reproduce it since my boarding pass is no longer valid :-). Sorry.

Comment 5

[Ting-Yu Chou [:ting] (away)]

I checked PrintData [1], but didn't see a fd that :jld was concerned in comment 1. Not sure where else I should check also.

ShowPrintDialog is an async IPC, nsPrintingProxy::ShowPrintDialog() has a nested event loop [2] waiting for the result. Bug 1090439 made the IPC from sync to async as for now e10s has single content process.

[1] https://dxr.mozilla.org/mozilla-central/rev/4c05938a64a7fde3ac2d7f4493aee1c5f2ad8a0a/embedding/components/printingui/ipc/PPrintingTypes.ipdlh#16
[2] https://dxr.mozilla.org/mozilla-central/rev/4c05938a64a7fde3ac2d7f4493aee1c5f2ad8a0a/embedding/components/printingui/ipc/nsPrintingProxy.cpp#110-114

Comment 6

[Ting-Yu Chou [:ting] (away)]

The problem actually is why libcups gets stuck in httpRead2 for reading from the socket, there's not much we can do without STR.

Comment 7

[Ting-Yu Chou [:ting] (away)]

Please reopen if there's a STR.