1306239 - Add pref to toggle OS X sandbox violation debugging, default on

Status: VERIFIED FIXED

(Core :: Security: Process Sandboxing, defect)

Description

[Haik Aftandilian [:haik]]

The OS X sandboxing facility logs activity that is blocked by the sandbox in the system log. These entries are also viewable in the Console.app log viewer. Here's an example.

9/29/16 1:43:16.718 AM sandboxd[368]: ([81945]) plugin-container(81945) deny file-read-data /System/Library/Frameworks/CoreServices.framework/Versions/A/Frameworks

Since some of these log entries may be unavoidable or difficult to prevent, it would improve the polish of Firefox to disable logging of sandbox violations. The messages are sometimes useful for debugging so add a pref to enable/disable the logging, make it default to off.

Comment 1

[Jim Mathies [:jimm]]

We have a couple prefs that are currently tied to windows, we should consolidate the main pref.

security.sandbox.windows.log
security.sandbox.windows.log.stackTraceDepth

Comment 2

[David Parks [:handyman]]

Attachment: WIP: Control mac sandbox violation logging with security.sandbox.log

This seems to be in the right direction.  The OSX sandbox debug setting comes from the way they handle DISABLE_SANDBOX_DENIAL_LOGGING in Chromium code [1][2].
Note that ENABLE_LOGGING in Chromium controls the "(debug deny)" command, whose removal did nothing for me.  I saw "somewhere else" that it actually controls symbolification and therefore wouldn't be related to turning logging on/off.

Following are relevant part of two logs.  First, the log when sandbox logging is NOT disabled:

-----

12/23/16 5:40:17.768 PM com.apple.xpc.launchd[1]: (com.apple.xpc.launchd.user.501.100005.Aqua) Caller not allowed to perform action: plugin-containe.32348, action = pid-local registration, code = 1: Operation not permitted, uid = 501, euid = 501, gid = 20, egid = 20, asid = 100005
12/23/16 5:40:17.785 PM appleeventsd[50]: <rdar://problem/11489077> A sandboxed application with pid 32348, "Nightly Web Content" checked in with appleeventsd, but its code signature could not be validated ( either because it was corrupt, or could not be read by appleeventsd ) and so it cannot receive AppleEvents targeted by name, bundle id, or signature. Error=ERROR: #100001  { "NSDescription"="SecCodeCopyGuestWithAttributes() returned 100001, -." }  (handleMessage()/appleEventsD.cp #2100) com.apple.root.default-qos
12/23/16 5:40:17.000 PM kernel[0]: Sandbox: plugin-container(32348) deny mach-register com.apple.tsm.portname
12/23/16 5:40:17.805 PM com.apple.xpc.launchd[1]: (com.apple.xpc.launchd.user.501.100005.Aqua) Caller not allowed to perform action: plugin-containe.32348, action = pid-local registration, code = 1: Operation not permitted, uid = 501, euid = 501, gid = 20, egid = 20, asid = 100005
12/23/16 5:40:17.000 PM kernel[0]: Sandbox: plugin-container(32348) deny mach-register com.apple.CFPasteboardClient
12/23/16 5:40:17.806 PM com.apple.xpc.launchd[1]: (com.apple.xpc.launchd.user.501.100005.Aqua) Caller not allowed to perform action: plugin-containe.32348, action = pid-local registration, code = 1: Operation not permitted, uid = 501, euid = 501, gid = 20, egid = 20, asid = 100005
12/23/16 5:40:17.806 PM plugin-container[32348]: Failed to allocate communication port for com.apple.CFPasteboardClient; this is likely due to sandbox restrictions
12/23/16 5:41:04.681 PM sandboxd[21746]: ([32348]) plugin-container(32348) deny mach-register com.apple.axserver (per-pid)
12/23/16 5:41:04.696 PM sandboxd[21746]: ([50]) appleeventsd(50) deny file-read-data /Users/davidp/mozilla/obj-debug/dist/NightlyDebug.app/Contents/MacOS/plugin-container.app
12/23/16 5:41:04.701 PM sandboxd[21746]: ([50]) appleeventsd(50) deny file-read-metadata /Users/davidp/mozilla/obj-debug/dist/NightlyDebug.app/Contents/MacOS/plugin-container.app/Contents
12/23/16 5:41:04.705 PM sandboxd[21746]: ([50]) appleeventsd(50) deny file-read-metadata /Users/davidp/mozilla/obj-debug/dist/NightlyDebug.app/Contents/MacOS/plugin-container.app
12/23/16 5:41:04.710 PM sandboxd[21746]: ([50]) appleeventsd(50) deny file-read-data /Users/davidp/mozilla/obj-debug/dist/NightlyDebug.app/Contents/MacOS/plugin-container.app/Contents/MacOS/plugin-container
12/23/16 5:41:04.734 PM sandboxd[21746]: ([32348]) plugin-container(32348) deny mach-lookup com.apple.system.opendirectoryd.membership
12/23/16 5:41:04.745 PM sandboxd[21746]: ([32348]) plugin-container(32348) deny mach-lookup com.apple.bsd.dirhelper
12/23/16 5:41:04.754 PM sandboxd[21746]: ([32348]) plugin-container(32348) deny network-outbound /private/var/run/syslog

-----

Second, a similar log with logging disabled:

-----

12/23/16 5:42:25.178 PM com.apple.xpc.launchd[1]: (com.apple.xpc.launchd.user.501.100005.Aqua) Caller not allowed to perform action: plugin-containe.32374, action = pid-local registration, code = 1: Operation not permitted, uid = 501, euid = 501, gid = 20, egid = 20, asid = 100005
12/23/16 5:42:25.203 PM appleeventsd[50]: <rdar://problem/11489077> A sandboxed application with pid 32374, "Nightly Web Content" checked in with appleeventsd, but its code signature could not be validated ( either because it was corrupt, or could not be read by appleeventsd ) and so it cannot receive AppleEvents targeted by name, bundle id, or signature. Error=ERROR: #100001  { "NSDescription"="SecCodeCopyGuestWithAttributes() returned 100001, -." }  (handleMessage()/appleEventsD.cp #2100) com.apple.root.default-qos
12/23/16 5:42:25.210 PM com.apple.xpc.launchd[1]: (com.apple.xpc.launchd.user.501.100005.Aqua) Caller not allowed to perform action: plugin-containe.32374, action = pid-local registration, code = 1: Operation not permitted, uid = 501, euid = 501, gid = 20, egid = 20, asid = 100005
12/23/16 5:42:25.210 PM com.apple.xpc.launchd[1]: (com.apple.xpc.launchd.user.501.100005.Aqua) Caller not allowed to perform action: plugin-containe.32374, action = pid-local registration, code = 1: Operation not permitted, uid = 501, euid = 501, gid = 20, egid = 20, asid = 100005
12/23/16 5:42:25.210 PM plugin-container[32374]: Failed to allocate communication port for com.apple.CFPasteboardClient; this is likely due to sandbox restrictions
12/23/16 5:42:25.638 PM sandboxd[21746]: ([50]) appleeventsd(50) deny file-read-data /Users/davidp/mozilla/obj-debug/dist/NightlyDebug.app/Contents/MacOS/plugin-container.app
12/23/16 5:42:25.643 PM sandboxd[21746]: ([50]) appleeventsd(50) deny file-read-metadata /Users/davidp/mozilla/obj-debug/dist/NightlyDebug.app/Contents/MacOS/plugin-container.app/Contents
12/23/16 5:42:25.648 PM sandboxd[21746]: ([50]) appleeventsd(50) deny file-read-metadata /Users/davidp/mozilla/obj-debug/dist/NightlyDebug.app/Contents/MacOS/plugin-container.app
12/23/16 5:42:25.652 PM sandboxd[21746]: ([50]) appleeventsd(50) deny file-read-data /Users/davidp/mozilla/obj-debug/dist/NightlyDebug.app/Contents/MacOS/plugin-container.app/Contents/MacOS/plugin-container

-----

The pattern is clear -- the setting seems to only stop sandboxd from logging violations that aren't file related.  I don't know why this is.  I tried some random things like moving the (default deny) command below the others (in case command order mattered).  Nothing changed anything.  Haik, do you have any other suggestions?  


[1] https://github.com/adobe/chromium/blob/master/content/common/common.sb#L10
[2] https://github.com/adobe/chromium/blob/cfe5bf0b51b1f6b9fe239c2a3c2f2364da9967d7/content/common/sandbox_mac.mm#L513

Comment 3

[Haik Aftandilian [:haik]]

I was poking around the profiles in /System/Library/Sandbox/Profiles on a 10.12 system and see a few uses of (with no-log), (with no-report), and (with no-callout). Some comments in those files indicate (with no-callout) is the one to use to turn off debugging. I'd give those a try, and maybe all three together to see if that helps "(deny default (with no-callout) (with no-report) (with no-log))".

Comment 4

[David Parks [:handyman]]

Attachment: Control mac sandbox violation logging with security.sandbox.log

This is the same patch as before, just freshened and with an updated checkin message (no luck with the other sandbox commands).  After running this past Haik, we determined that the messages that we don't block are from related, but different, processes.  From the example above:

12/23/16 5:42:25.210 PM com.apple.xpc.launchd[1]: (com.apple.xpc.launchd.user.501.100005.Aqua) Caller not allowed to perform action: plugin-containe.32374, action = pid-local registration, code = 1: Operation not permitted, uid = 501, euid = 501, gid = 20, egid = 20, asid = 100005

and 

12/23/16 5:42:25.638 PM sandboxd[21746]: ([50]) appleeventsd(50) deny file-read-data /Users/davidp/mozilla/obj-debug/dist/NightlyDebug.app/Contents/MacOS/plugin-container.app

are both _about_ Firefox but not from our process (appleeventsd/launchd), while the blocked message:

12/23/16 5:41:04.734 PM sandboxd[21746]: ([32348]) plugin-container(32348) deny mach-lookup com.apple.system.opendirectoryd.membership

came from our process (plugin-container).

Installing the binary to /Applications made no difference on the amount of messages that get through.

Comment 5

[Haik Aftandilian [:haik]]

Comment on attachment 8825611 [details] [diff] [review]
Control mac sandbox violation logging with security.sandbox.log

r+ with a few nits.

I'm thinking it would be better to leave the logging turned on by default for now, while we're doing a lot of work on and making changes to the sandbox. Once it has stabilized, we could make it be off by default, but turned on in Nightly to catch new changes that introduce violations. With OS X 10.12, there is so much being logged to the console by default that I don't expect it would concern users to see a few Firefox sandbox messages.

Would it be better to define the pref in js so that it appears in about:config so it will be easier to turn on when necessary. Like security.sandbox.content.level in browser/app/profile/firefox.js. (I'm assuming it doesn't appear in about:config now.) I definitely plan to use this feature and think it would be easier if it was listed in about:config.

Lastly, run "security.sandbox.log" by :bobowen and :gcp to make sure it makes sense for Windows and Linux too.

Comment 6

[David Parks [:handyman]]

Attachment: Control mac sandbox violation logging with security.sandbox.logging.enabled (r=haik)

New patch with Haik's comments.  We settled on the name "security.sandbox.logging.enabled".

Comment 7

[David Parks [:handyman]]

Changing bug name to "default on", which the patch does (see comment 5).

Comment 8

[David Parks [:handyman]]

Tests:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=895411642bc06fa0502e81a08bf7884f4501b3e1&selectedJob=69799837

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/36e32e9299a3
Add pref to toggle OS X sandbox violation debugging, default on. r=haik

Comment 10

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/36e32e9299a3

Comment 11

[Paul Theriault [:pauljt] (no longer reading bugmail)]

Works great, thanks. Added a wiki page with a description of how to test manually: https://wiki.mozilla.org/Security/Sandbox/Testing/OSX