Open Bug 420534 Opened 16 years ago Updated 2 years ago

dump() on OS X ends up in /var/log/system.log

Categories

(Core :: General, defect)

Product:
Core
Component:
General
Platform:
x86
macOS
Type:
defect

Tracking

()

People

(Reporter: Dolske, Unassigned)

Details

(Whiteboard: [Snappy]) 

I noticed my CPU peg, and top revealed it to be syslogd. I took a look over in /var/log, and was rather surprised to find lots of Firefox spewage in system.log. EG:

Mar  1 00:56:02 Justin-Dolske-MBP [0x0-0x715715].org.mozilla.firefox[20369]: Login Manager: domEventListener: got event DOMContentLoaded

This only happens when Firefix is launched from the Dock. When run from a terminal, nothing appears in system.log. I confirmed this is coming from dump() and not nsIConsoleService.logStringMessage() [which login manager also calls]. I'm guessing that OS X just magically redirects stderr/stdout to system.log when launched this way.

This is probably ok for most native apps, because console output from them wouldn't really be expected. But for a cross-platform app like Mozilla, this seems like a rather unintended side effect. For example, Firebug liberally uses dump(), and today alone I have 43MB of output in /var/log/system.log.

Not sure what the best fix is here, since for development having dump() show up in the terminal is desirable. Maybe there's a way to determine, at run time, how the app was launched and selectively disable output? A second best option would be to have a pref to control this (off by default).

Setting browser.dom.window.dump.enabled to false didn't seem to help here, I suppose chrome's dump() is going through a different path?
The pref only affects the nsGlobalWindow dump() - the JS component dump() doesn't check a pref.
classically one could consider istty(), but that may or may not do what one wants (if i'm redirecting 2> xpcom-error.log, i'd be upset if i got nothing).
Just now my fans started making noises like crazy on my mac book air running Lion that was idling.
Turns out that it was that logrotate thing bzip2'ing my system.log.0, which had grown to 1.3G over the course of a day!

Looking into the log, it was almost entirely made up from Nightly logging like:
Mar  9 06:04:33 nmaier firefox[88342]: CGContextSaveGState: invalid context 0x0
Mar  9 06:04:33 nmaier [0x0-0x1652651].org.mozilla.nightly[88342]: Mar  9 06:04:33 nmaier.local firefox[88342] <Error>: CGContextSaveGState: invalid context 0x0
Mar  9 06:04:33 nmaier [0x0-0x1652651].org.mozilla.nightly[88342]: Mar  9 06:04:33 nmaier.local firefox[88342] <Error>: CGContextScaleCTM: invalid context 0x0
Mar  9 06:04:33 nmaier firefox[88342]: CGContextScaleCTM: invalid context 0x0
Mar  9 06:04:33 nmaier firefox[88342]: CGContextSaveGState: invalid context 0x0
Mar  9 06:04:33 nmaier firefox[88342]: CGContextGetCTM: invalid context 0x0
Mar  9 06:04:33 nmaier firefox[88342]: CGContextRestoreGState: invalid context 0x0
Mar  9 06:04:33 nmaier [0x0-0x1652651].org.mozilla.nightly[88342]: Mar  9 06:04:33 nmaier.local firefox[88342] <Error>: CGContextSaveGState: invalid context 0x0
Mar  9 06:04:33: --- last message repeated 1 time ---

Independent from what was logged... Having my machine burn for a couple of minutes during logrotate and all the I/O required to write all these entries in the first place does make this bug qualify for [Snappy] /methinks. I think I would have noticed it earlier if this machine didn't use an SSD. Also, filling up the users disk is a little rude to begin with... :p
Whiteboard: [Snappy]
Those are not dump() messages. Please file a new bug.
(In reply to Justin Dolske [:Dolske] from comment #5)
> Those are not dump() messages. Please file a new bug.

Bug 849787
Where else than /var/log/system.log should dump() messages be written?  This isn't a bug but a feature :-)  This bug is awfully close to being INVALID.

But though this should clearly be the default setting, you could argue that there should be a way to redirect the output.  Nonetheless I think we've got lots more bugs to deal that are more urgent than this one.
Severity: normal → trivial
The problem here stems from the surprise that dump() on OS X stores a permanent entry in system.log, whereas on Windows and Linux it just disappears into the aether. Doubly so for add-ons that whose author is unfamiliar with this OS X subtly. Quadruply so if you're in private browsing mode and this leaks sensitive info (like URLs) into the log.

The suggestion in comment 0 / comment 3 is to only have dump() output when it's going to a terminal (perhaps with a pref to keep the current behavior if that's found to be useful).
> The problem here stems from the surprise that dump() on OS X stores
> a permanent entry in system.log, whereas on Windows and Linux it
> just disappears into the aether.

I didn't realize that dump() output doesn't go into the system log on
Linux, and I haven't tested that ... but I'll take your word for it.

And now that I think about it, it *is* kind of odd that in a syslogd
logging system, output can get into the system log without any app
having called syslog().  Because that does seem to be happening -- as
best I can tell, any output sent by an app or framework or library to
STDERR (or perhaps to STDOUT) ends up in the system log.

Yes.  As I just found out, this happens with *every* executable on OS
X (not just Firefox).  You can see this for yourself by testing with
my interpose library from bug 816976 comment #44.  So whatever kind of
bug this is, it's an Apple bug, and there's probably nothing we can do
about it.

> Quadruply so if you're in private browsing mode and this leaks
> sensitive info (like URLs) into the log.

/var/log/system.log is only readable by root (its owner).  So only a
root exploit would make it visible remotely.  And in any case I think
a user or extension author would have to add custom logging for this
to happen.

But given that this bug is out of our control, we should probably
write up a doc to warn extension authors about this.
> /var/log/system.log is only readable by root (its owner)

Oops.  It's only readable by root (its owner) and admin (its group).  So breaking into an admin account would give you access.
Severity: trivial → normal
(In reply to Steven Michaud from comment #9)

> But given that this bug is out of our control, we should probably
> write up a doc to warn extension authors about this.

It's true (afaik) that what the system does with stdout/stderr is out of our control. But we do have some control over if/when we emit strings, as I said in comment 8. That's also why I asked for the issue in comment 4 to move to a separate bug -- we don't have control over strings emitted from system libraries. [Well, there is the old trick of closing/redirecting fds 1&2, which might work for that too.]

(In reply to Steven Michaud from comment #10)
> > /var/log/system.log is only readable by root (its owner)
> 
> Oops.  It's only readable by root (its owner) and admin (its group).  So
> breaking into an admin account would give you access.

Private browsing was never intended as a defense against root. It's about not recording activity that could later be found for whatever reason. Say, if an Apple Genius is fixing your system and is alarmed to discover that system.log has recorded your visit to howtosmugglepoutineintonorthkorea.com.
> But we do have some control over if/when we emit strings, as I said
> in comment 8.

I suppose we do.  And it might be reasonable to make dump() use the
infrastructure we're already using for other debug logging output
(which presumably defaults to using syslog(), but which might also be
redirected to a file, and which normally generates no output in a
non-debug build).

However, as a frequent user of dump() myself, we'd need to have the
option to preserve the current behavior -- which has it write to
STDERR/STDOUT.  We'd also need to retain
browser.dom.window.dump.enabled as an on/off switch.

I never use debug builds, just because they're incredibly noisy (and
because almost none of the noise is relevant to my current purpose,
whatever than might be).  It'd be cruel and unusual punishment to make
users of dump() use debug builds. 

Along these lines, I think I'd be able to live some kind of hack that
redirected STDERR/STDOUT to /dev/null by default on OS X for custom
debug output -- NSLog() and printf() statements that a developer like
myself adds to the tree to debug a particular problem.  But there'd
have to be some kind of on/off switch (as for dump()) that allowed it
to be turned on or off independently of debug mode.  It would be
unacceptable to turn off STDERR/STDOUT except in debug mode.

And it would be unacceptable to stop error messages from the OS from
being written to /var/log/system.log.  That would cripple our ability
to debug many kinds of problems.

I'm not sure it'd be possible to redirect one kind of message to
/dev/null and not the other.  If it's either all-on or all-off, we
shouldn't make any changes at all (and leave it all-on).  In that case
we'd just need to be sure our standard debug output doesn't include
sensitive information, and that extension authors are educated to do
the same (both of which we should be doing anyway).
(From comment #0)

> This only happens when Firefox is launched from the Dock. When run
> from a terminal, nothing appears in system.log.

This surprises me.  If it's true, we'll need to get to the bottom of
this before we can do anything on this bug.

Let me try to do a quick check.

Can you still reproduce this?
Testing with my debug logging build from bug 816976 comment #43 (which calls NSLog a bunch of times), I find that it writes to /var/log/system.log regardless of how I start it -- from a Terminal prompt or by double-clicking on its app icon.

I tested on OS X 10.8.2.
> Testing with my debug logging build from bug 816976 comment #43 ...

Actually the build is at comment #47.
(In reply to Steven Michaud from comment #14)
> Testing with my debug logging build from bug 816976 comment #43 (which calls
> NSLog a bunch of times), I find that it writes to /var/log/system.log
> regardless of how I start it -- from a Terminal prompt or by double-clicking
> on its app icon.
> 
> I tested on OS X 10.8.2.

Dump fputs to stdout and does not use NSLog.

http://mxr.mozilla.org/mozilla-central/source/js/xpconnect/loader/mozJSComponentLoader.cpp#179

When starting from Dock, stdout/stderr will be written to syslogd, but not when launched from a terminal.(In reply to Steven Michaud from comment #13)
> (From comment #0)
> 
> > This only happens when Firefox is launched from the Dock. When run
> > from a terminal, nothing appears in system.log.
> 
> This surprises me.  If it's true, we'll need to get to the bottom of
> this before we can do anything on this bug.
> 
> Let me try to do a quick check.
> 
> Can you still reproduce this?

Yes: Run this in a privileged scratchpad/web console (e.g. about config):
Components.utils.import("resource://gre/modules/Services.jsm", {}).dump("hello world\n");
// The module is just imported as a hack to get to the component dump() instead of window.dump()

When the app was launched from Dock, then this logs to syslogd. When started from terminal, this logs to the terminal stdout only.
I need to put this off for a while.

Once I get back, I'll figure out exactly what's going on with dump(), printf() and NSLog() wrt the system log, and presumably open a new bug on that subject (since more's involved than just dump()).  Then I'll try to figure out what to do about it.
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.