[e10s] Printing on OS X makes firefox unusable (window.print() hangs the content process for a while)

RESOLVED FIXED in Firefox 52

Status

()

defect
RESOLVED FIXED
3 years ago
2 years ago

People

(Reporter: mchang, Assigned: haik)

Tracking

(Depends on 1 bug, {regression})

52 Branch
mozilla53
x86
macOS
Points:
---
Dependency tree / graph
Bug Flags:
qe-verify -

Firefox Tracking Flags

(firefox50 unaffected, firefox51 unaffected, firefox52+ fixed, firefox53+ fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

STR:

1) On OS X macOS sierra, go to macrumors.com
2) Open the print preview menu
3) Push the PDF button on the bottom left, then click Open PDF in Preview
4) Browser becomes unusable for a minute.

Another STR:
1) Return an item to Amazon (Sorry :()
2) Click the "Print label and Instructions"
3) Browser becomes unusable.

This is fine in Firefox release (50), but unusable in developer (52) and nightly edition (53).
I filed Bug 1324333 which has some similar symptoms.
See Also: → 1324333
Like I said in bug 1324333, I tested this on Mac OS X 10.12 with Nightly 53.0a1(2016-12-19) and I can't reproduce it. I tried also with an MacBook 10.11 but with no success, for me it works as expected. I'm wondering what is different in my case from your and Marcia's.
(In reply to Mason Chang PTO 1/3/17 [:mchang] from comment #0)
> This is fine in Firefox release (50), but unusable in developer (52) and
> nightly edition (53).

What about 51?
Flags: needinfo?(mchang)
(In reply to Ryan VanderMeulen [:RyanVM] from comment #3)
> (In reply to Mason Chang PTO 1/3/17 [:mchang] from comment #0)
> > This is fine in Firefox release (50), but unusable in developer (52) and
> > nightly edition (53).
> 
> What about 51?

51 seems to be fine.
Flags: needinfo?(mchang)
Version: unspecified → 52 Branch
Bisection log
start - 1196bf3032e1bce1fb07a01fd9082a767426c5fb
end - b32127935d38

Testing changeset 349517:c642a065f38e (901 changesets remaining, ~9 tests)
968 files updated, 0 files merged, 274 files removed, 0 files unresolved
Bad

Testing changeset 349292:faf338a9891a (450 changesets remaining, ~8 tests)
1109 files updated, 0 files merged, 215 files removed, 0 files unresolved
Kind of good? Slow to create the pdf, but seems reasonable enough I guess

Testing changeset 349404:0277a89270ff (225 changesets remaining, ~7 tests)
969 files updated, 0 files merged, 36 files removed, 0 files unresolved
Bad

Testing changeset 349348:c46aa51a5335 (112 changesets remaining, ~6 tests)
585 files updated, 0 files merged, 85 files removed, 0 files unresolved
Good, still slow like the first one to create the pdf, but at least the menu pops up fast enough.

Testing changeset 349376:8ec375514353 (56 changesets remaining, ~5 tests)
605 files updated, 0 files merged, 3 files removed, 0 files unresolved
Bad

Testing changeset 349362:e3e01366879b (28 changesets remaining, ~4 tests)
504 files updated, 0 files merged, 75 files removed, 0 files unresolved
Bad

Testing changeset 349355:94dac74c74a6 (14 changesets remaining, ~3 tests)
9 files updated, 0 files merged, 1 files removed, 0 files unresolved
Bad

Testing changeset 349351:6ae9b39276fa (7 changesets remaining, ~2 tests)
12 files updated, 0 files merged, 0 files removed, 0 files unresolved
good

Testing changeset 349353:f3a55c57f637 (4 changesets remaining, ~2 tests)
2 files updated, 0 files merged, 0 files removed, 0 files unresolved
Bad

Testing changeset 349352:97862b6aff39 (2 changesets remaining, ~1 tests)
1 files updated, 0 files merged, 0 files removed, 0 files unresolved

The first bad revision is:
changeset:   349352:97862b6aff39
user:        Haik Aftandilian <haftandilian@mozilla.com>
date:        Tue Nov 15 22:39:00 2016 -0800
summary:     Bug 1314056 - Enable Mac content sandbox level 1 in 52. r=gcp, r=glandium, a=jcristau

Verified that setting the preference "security.sandbox.content.level" to "0", then restarting Nightly mostly fixes the issue.
Blocks: 1314056
Flags: needinfo?(haftandilian)
Duplicate of this bug: 1324333
[Tracking Requested - why for this release]: Opening the print menu shouldn't make the browser unusable.
Tracking 52/53+ - I have personally hit this bug and it is a terrible user experience.
Assignee

Comment 9

3 years ago
I can reproduce this with build 52 on Sierra 10.12.2 (16C67), visiting macrumors.com and also simple sites. In Console.app, some Sandbox violations are being logged:

  SandboxViolation: plugin-container(16952) deny network-outbound /private/var/run/cupsd
  Being triggered from nsPrintOptionsX::SerializeToPrintData() calling [NSPrinter name].

and

  SandboxViolation: plugin-container(16985) deny mach-lookup com.apple.printtool.agent
  Being triggered from nsPrintSettingsX::InitUnwriteableMargin().

I'm testing a Nightly build with those permissions added back to the content sandbox and that appears to work well so far, but still debugging.
Assignee: nobody → haftandilian
Flags: needinfo?(haftandilian)
Assignee

Comment 10

3 years ago
This patch adds back two permissions which are being used by OS X library code called from the content process in some routines for getting the printer name and page format settings. Content doesn't need these values and the relevant code needs to be reworked to avoid trying to read the values. There's an existing bug to cleanup this part of the printing code. I'm looking into the possibility of a simple fix that would not require adding back permissions to the sandbox.

Mason, does this fix the problem you're hitting? (Remember to revert security.sandbox.content.level and print.print_via_parent to the defaults. For Nightly 53, level=2, print_via_parent=true; for Aurora 52, level=1, print_via_parent=true.)
Flags: needinfo?(mchang)
(In reply to Haik Aftandilian [:haik] from comment #10)
> Created attachment 8823472 [details] [diff] [review]
> Adds back some printing permissions to the content process
> 
> This patch adds back two permissions which are being used by OS X library
> code called from the content process in some routines for getting the
> printer name and page format settings. Content doesn't need these values and
> the relevant code needs to be reworked to avoid trying to read the values.
> There's an existing bug to cleanup this part of the printing code. I'm
> looking into the possibility of a simple fix that would not require adding
> back permissions to the sandbox.
> 
> Mason, does this fix the problem you're hitting? (Remember to revert
> security.sandbox.content.level and print.print_via_parent to the defaults.
> For Nightly 53, level=2, print_via_parent=true; for Aurora 52, level=1,
> print_via_parent=true.)

Yup thanks! this seems to have fixed it!
Flags: needinfo?(mchang)
Assignee

Comment 12

3 years ago
I found that when the problem occurs, the [NSPrinter name] method in nsPrintOptionsX::SerializeToPrintData() is taking approximately 1 minute to return. This blocks the main thread in the content process and causes the hang.
Assignee

Comment 13

3 years ago
Removing all the print-API calls in the content process that cause hangs is going to take some refactoring--more than I'd like to do for this much needed fix for build 52. I'm going to move forward with adding back the necessary permissions to the content sandbox which will (apparently) allow an http connection to a cups daemon for printing. This is OK for the first version of our content sandbox on Mac.

This is an example stack of where there content process is hung.

(lldb) bt
* thread #1: tid = 0x263e32, 0x00007fffc7145232 libsystem_kernel.dylib`poll + 10, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0 libsystem_kernel.dylib`poll() 
    frame #1 libcups.2.dylib`httpAddrConnect2() 
    frame #2 libcups.2.dylib`httpReconnect2() 
    frame #3 libcups.2.dylib`httpConnect2() 
    frame #4 libcups.2.dylib`_cupsConnect() 
    frame #5 libcups.2.dylib`cupsDoIORequest() 
    frame #6 PrintCore`cpl_cupsDoFileRequest() 
    frame #7 PrintCore`CUPSPrinter::GetAttributes() 
    frame #8 PrintCore`CUPSPrinter::CopyCFStringAttribute() 
    frame #9 PrintCore`OpaquePMPrinter::GetName() 
    frame #10 AppKit`-[NSPrinter name]() 
    frame #11 AppKit`-[NSPrintInfo(NSManagedAttributes) _objectForAttributeKey:]() 
    frame #12 CoreFoundation`-[NSDictionary getObjects:andKeys:count:]() 
    frame #13 CoreFoundation`-[NSDictionary initWithDictionary:copyItems:]() 
    frame #14 CoreFoundation`+[NSDictionary dictionaryWithDictionary:]() 
    frame #15 XUL`nsPrintOptionsX::DeserializeToPrintSettings() at nsPrintOptionsX.mm:193
    frame #16 XUL`nsPrintingProxy::ShowPrintDialog() at nsPrintingProxy.cpp:119
    frame #17 XUL`nsPrintEngine::DoCommonPrint() at nsPrintEngine.cpp:615
    frame #18 XUL`nsPrintEngine::CommonPrint() at nsPrintEngine.cpp:404
    frame #19 XUL`nsPrintEngine::Print() at nsPrintEngine.cpp:787
    frame #20 XUL`nsDocumentViewer::Print() at nsDocumentViewer.cpp:3850
    frame #21 XUL`non-virtual thunk to nsDocumentViewer::Print(nsIPrintSettings*, nsIWebProgressListener*)() at nsDocumentViewer.cpp:3756
    frame #22 XUL`NS_InvokeByIndex() at xptcinvoke_asm_x86_64_unix.S:115
    frame #23 XUL`XPCWrappedNative::CallMethod() at XPCWrappedNative.cpp:2058
    frame #24 XUL`XPCWrappedNative::CallMethod() at XPCWrappedNative.cpp:1377
    frame #25 XUL`XPCWrappedNative::CallMethod() at XPCWrappedNative.cpp:1344
    frame #26 XUL`XPC_WN_CallMethod() at XPCWrappedNativeJSOps.cpp:999
    frame #27 XUL`js::InternalCallOrConstruct() at jscntxtinlines.h:239
    frame #28 XUL`js::InternalCallOrConstruct() at Interpreter.cpp:457
    frame #29 XUL`InternalCall() at Interpreter.cpp:502
    frame #30 XUL`js::CallFromStack() at Interpreter.cpp:508
    frame #31 XUL`Interpret() at Interpreter.cpp:2928
    frame #32 XUL`js::RunScript() at Interpreter.cpp:403
    frame #33 XUL`js::InternalCallOrConstruct() at Interpreter.cpp:475
    frame #34 XUL`InternalCall() at Interpreter.cpp:502
    frame #35 XUL`js::CallFromStack() at Interpreter.cpp:508
    frame #36 XUL`Interpret() at Interpreter.cpp:2928
    frame #37 XUL`js::RunScript() at Interpreter.cpp:403
    frame #38 XUL`js::InternalCallOrConstruct() at Interpreter.cpp:475
    frame #39 XUL`InternalCall() at Interpreter.cpp:502
    frame #40 XUL`js::Call() at Interpreter.cpp:521
    frame #41 XUL`JS_CallFunctionValue() at jsapi.cpp:2803
    frame #42 XUL`nsFrameMessageManager::ReceiveMessage() at nsFrameMessageManager.cpp:1066
    frame #43 XUL`nsFrameMessageManager::ReceiveMessage() at nsFrameMessageManager.cpp:875
    frame #44 XUL`mozilla::dom::TabChild::RecvAsyncMessage() at TabChild.cpp:2061
    frame #45 XUL`non-virtual thunk to mozilla::dom::TabChild::RecvAsyncMessage(nsString const&, nsTArray<mozilla::jsipc::CpowEntry>&&, IPC::Principal const&, mozilla::dom::ClonedMessageData const&)() at TabChild.cpp:2049
    frame #46 XUL`mozilla::dom::PBrowserChild::OnMessageReceived() at PBrowserChild.cpp:2819
    frame #47 XUL`mozilla::dom::PContentChild::OnMessageReceived() at PContentChild.cpp:5657
    frame #48 XUL`mozilla::ipc::MessageChannel::DispatchAsyncMessage() at MessageChannel.cpp:1750
    frame #49 XUL`mozilla::ipc::MessageChannel::DispatchMessage() at MessageChannel.cpp:1688
    frame #50 XUL`mozilla::ipc::MessageChannel::RunMessage() at MessageChannel.cpp:1572
    frame #51 XUL`mozilla::ipc::MessageChannel::MessageTask::Run() at MessageChannel.cpp:1597
    frame #52 XUL`nsThread::ProcessNextEvent() at nsThread.cpp:1213
    frame #53 XUL`NS_ProcessPendingEvents() at nsThreadUtils.cpp:323
    frame #54 XUL`nsBaseAppShell::NativeEventCallback() at nsBaseAppShell.cpp:97
    frame #55 XUL`nsAppShell::ProcessGeckoEvents() at nsAppShell.mm:392
    frame #56 CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__() 
    frame #57 CoreFoundation`__CFRunLoopDoSources0() 
    frame #58 CoreFoundation`__CFRunLoopRun() 
    frame #59 CoreFoundation`CFRunLoopRunSpecific() 
    frame #60 HIToolbox`RunCurrentEventLoopInMode() 
    frame #61 HIToolbox`ReceiveNextEventCommon() 
    frame #62 HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter() 
    frame #63 AppKit`_DPSNextEvent() 
    frame #64 AppKit`-[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:]() 
    frame #65 XUL`::-[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:](NSEventMask, NSDate *, NSString *, BOOL)() at nsAppShell.mm:128
    frame #66 AppKit`-[NSApplication run]() 
    frame #67 XUL`nsAppShell::Run() at nsAppShell.mm:666
    frame #68 XUL`::XRE_RunAppShell()() at nsEmbedFunctions.cpp:924
    frame #69 XUL`mozilla::ipc::MessagePumpForChildProcess::Run() at MessagePump.cpp:269
    frame #70 XUL`MessageLoop::RunInternal() at message_loop.cc:238
    frame #71 XUL`MessageLoop::RunHandler() at message_loop.cc:231
    frame #72 XUL`MessageLoop::Run() at message_loop.cc:211
    frame #73 XUL`::XRE_InitChildProcess(int, char **, const XREChildData *)() at nsEmbedFunctions.cpp:756
    frame #74 plugin-container`content_process_main() at plugin-container.cpp:115
    frame #75 plugin-container`main() at MozillaRuntimeMain.cpp:18
    frame #76 plugin-container`start()
Assignee

Updated

3 years ago
See Also: → 1299329
Comment hidden (mozreview-request)
Assignee

Updated

3 years ago
Attachment #8823472 - Attachment is obsolete: true

Comment 16

3 years ago
mozreview-review
Comment on attachment 8823752 [details]
Bug 1324610 - Some printing permissions still needed by content processes;

https://reviewboard.mozilla.org/r/102250/#review102986
Attachment #8823752 - Flags: review?(gpascutto) → review+
Assignee

Updated

3 years ago
Keywords: checkin-needed
Assignee

Updated

3 years ago
See Also: → 1328975
Summary: Printing on OS X makes firefox unusable → [e10s] Printing on OS X makes firefox unusable (window.print() hangs the content process for a while)

Comment 17

3 years ago
Pushed by ihsiao@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/04a0aee34567
Some printing permissions still needed by content processes; r=gcp
Keywords: checkin-needed

Comment 18

3 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/04a0aee34567
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla53
Please request Aurora approval on this when you get a chance.
Flags: needinfo?(haftandilian)
Assignee

Comment 20

3 years ago
Comment on attachment 8823752 [details]
Bug 1324610 - Some printing permissions still needed by content processes;

Approval Request Comment
[Feature/Bug causing the regression]:
Bug 1314056 - Enable Mac content sandbox level 1 in 52.

[User impact if declined]:
On Mac, trying to print causes full browser hangs for about 1 minute.

[Is this code covered by automated tests?]:
No

[Has the fix been verified in Nightly?]:
Yes

[Needs manual test from QE? If yes, steps to reproduce]: 
No

[List of other uplifts needed for the feature/fix]:
None

[Is the change risky?]:
No

[Why is the change risky/not risky?]:
It's a small change to the Mac content sandbox rules. It adds permissions and doesn't remove any.

[String changes made/needed]:
None
Flags: needinfo?(haftandilian)
Attachment #8823752 - Flags: approval-mozilla-aurora?
Comment on attachment 8823752 [details]
Bug 1324610 - Some printing permissions still needed by content processes;

relax macosx content sandbox for printing, aurora52+
Attachment #8823752 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Assignee

Updated

3 years ago
Depends on: 1330643
Setting qe-verify- based on Haik's assessment on manual testing needs (see Comment 20), but flagging this as a candidate for the community.
QA Whiteboard: [good first verify]
Flags: qe-verify-
You need to log in before you can comment on or make changes to this bug.