Firefox (Nightly) spams syslogd / var/log/system.log

REOPENED
Unassigned

Status

()

--
major
REOPENED
6 years ago
a year ago

People

(Reporter: nmaier, Unassigned)

Tracking

Trunk
All
Mac OS X
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [Snappy])

(Reporter)

Description

6 years ago
Originally and mistakenly reported as in bug #420534 comment #4

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
This bug as reported is invalid.  These are system console messages -- where else should they be written than /var/log/system.log?

If you really want to control the level of messages being written to system.log, or to stop them altogether, I believe OS X gives you a low-level way to do that (I think you have to alter a config file somewhere in /etc/).  But I believe the OS already only writes the most "serious" messages there, and you shouldn't want to stop them being written altogether (that would make it harder to debug problems with your system and with any of the applications running on it).

The real bug here is that something is causing the errors that spawn those messages.  You should open a bug about that.  And when you do make sure that you include detailed, precise STR.  I myself have never seen anything like what you report, and (as part of my work for Mozilla) I look at system.log regularly.
Status: NEW → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → INVALID
(Following up comment #1)

I should add that I often see these messages, but never in large quantity.  And when I do see them, more than half the time they've been triggered by some other, non-Mozilla app.

The first thing you should try, before opening a new bug, is to restart your computer :-)
> I think you have to alter a config file somewhere in /etc/

It's /etc/syslog.conf.
> The first thing you should try, before opening a new bug, is to
> restart your computer :-)

Or better still try restarting the WindowServer:

sudo killall -9 WindowServer

Note that this will log you out and kill all the processes in your
login session.
(Reporter)

Comment 5

6 years ago
Seriously, your explanation is IMO bogus and I do not agree this bug is INVALID.
Actually it is a way to (mildly) DoS my system, maybe even remotely depending on how you can trigger excessive logging.
Also, depending on what other bugs you can find to trigger this, this might be also a privacy issue, as those logs are persistent. I might be later able to find evidence that a user visited site xyz by reading the syslog when when the user did use (PW)PBM.

(In reply to Steven Michaud from comment #2)
> (Following up comment #1)
> The first thing you should try, before opening a new bug, is to restart your
> computer :-)

Yeah, I do watch the IT crowd too :)

(In reply to Steven Michaud from comment #1)
> This bug as reported is invalid.  These are system console messages -- where
> else should they be written than /var/log/system.log?

Erm, how about "nowhere at all".
Users usually do not care about these messages, but do care about slow browsers (file I/O) and diminished disk space.

(Some) Developers care, I see that.
If you want the log output you could do that via a hidden pref or just make the it log to the terminal, like it is now.

> If you really want to control the level of messages being written to
> system.log, or to stop them altogether, I believe OS X gives you a low-level
> way to do that (I think you have to alter a config file somewhere in /etc/).

Yes, *I* could do that. But do you think regular users are also that knowledgeable?

> But I believe the OS already only writes the most "serious" messages there,
> and you shouldn't want to stop them being written altogether (that would
> make it harder to debug problems with your system and with any of the
> applications running on it).

The excerpt I gave doesn't look very "serious".

> The real bug here is that something is causing the errors that spawn those
> messages.  You should open a bug about that.  And when you do make sure that
> you include detailed, precise STR.  I myself have never seen anything like
> what you report, and (as part of my work for Mozilla) I look at system.log
> regularly.

Yes, the bug that caused this particular "spam" should be fixed. It might have been already fixed as the most recent Nightlies are a lot more quite.
As I didn't notice until "bzip2" pwned my box during logrotate I cannot be sure what the underlying bug was or what triggered it or any STR.

But the bug I'm reporting here is that any other bug that may be even specially triggered by some Bad Guy(tm) may spam your syslogd and diminish performance and/or free disk space.
Status: RESOLVED → REOPENED
Resolution: INVALID → ---
(In reply to Nils Maier [:nmaier] from comment #5)
> Also, depending on what other bugs you can find to trigger this, this might
> be also a privacy issue, as those logs are persistent. I might be later able
> to find evidence that a user visited site xyz by reading the syslog when
> when the user did use (PW)PBM.

Are there URL or private information in these logs? If so it is a privacy issue. 

We really need to be free of the CoreGraphics warnings. I'd like for us to focus on those in this bug. If there's other warnings that you're seeing we should clone a bug for those.

Do you have STR to get these logs. Can you run with a debugger attach with a break on 'NSLog'. From my experience this function is only hit when Cocoa libs are warnings us of misuse which we REALLY should fix ASAP. Ideally set the breakpoint on a build with symbols such as Nightly or better yet a custom build so it doesn't have debug info stripped.
(In reply to Steven Michaud from comment #1)
> I myself have never seen anything like
> what you report, and (as part of my work for Mozilla) I look at system.log
> regularly.

I have to admit I do see them occasionally. I've fixed a few of them but only ones that show up on startup/shutdown. I know there's a few remaining during runtime. They could be cause for example by CoreGraphics canvas and only happen on particular web pages.
Benoit:

I've seen these errors for years (and for many past and current versions of OS X).  In small numbers they don't seem to cause any trouble.  I've never seen them myself in large numbers, but there have been other reports.  Of the small numbers I see, more than half are reported for other (non-Mozilla) applications.

I strongly suspect these are caused by the WindowServer getting into a bad state, due to flakiness in the WindowServer itself.  But the only way we have to test this is for someone who sees large numbers of them to test killing/restarting the WindowServer, to see if this makes a difference.

Whoever researches this bug (not me) should also search the web on these error messages.  I think your results will be interesting.
> Are there URL or private information in these logs?

The error messages reported here don't contain any, and I've never seen any in the System console (from which you can read /var/log/system.log, even though it's not world readable).

But if there were any, that'd be an Apple bug, and would only matter on a multiuser system.  Note that *many* Apple apps and frameworks/libraries write to the system log (as they should).
> in the System console

In the Console app.
I we had reproducible steps for generating large numbers of these messages, we might be able to work around them, even if they are caused by Apple bugs.

But I'm frankly very skeptical that we'll ever have good STR for them.
(Reporter)

Comment 12

6 years ago
This bug is not about these particular CoreGraphics messages, but about logging in general and how it should be handled.
My assertion is that as long as logging to syslog is the default when starting the .app, then you are at risk of having your syslogd spammed, no matter what component is failing.
This time it might be CG, next time WebRTC might be the culprit and after that some random add-ons or the add-on SDK itself, ...
From what I understand everything that put on stderr gets logged; no need to NSLog directly.

And I don't see a dire need for logging in the default case, especially considering the drawbacks. Also, Windows Firefox does get away with no logging just fine.
Pretty much every OS *except* Windows has a system log.  It's considered a system resource, and there are syslogd apis that can be used by any app to write to it.

This is part of the Unix/BSD legacy.  It's also present in Linux.
(Reporter)

Comment 14

6 years ago
(In reply to Steven Michaud from comment #13)
> Pretty much every OS *except* Windows has a system log.

Windows has an event log, too. Yet I don't see Firefox spamming that.

>  It's considered a
> system resource, and there are syslogd apis that can be used by any app to
> write to it.

The magic word here is *can*.

> It's also present in Linux.

Except on *nix != Darwin, Firefox will *not* syslog everything. In fact it will syslog nothing at all (except for WebRTC and breakpad, both of with log on specific errors and both of which are third-party code).
On OSX it will log the entire stderr (stdout too?).
The bottom line here (and why I called this bug invalid) is that error messages like those in comment #0 (ones emitted by parts of the OS) need to get into /var/log/system.log.  Otherwise it will be much harder to deal with bug reports:  We often ask users to use the Console app to look at system messages, and the content of these messages is often critical to understanding why a bug happens.

I didn't appreciate at first, though, that there are also other issues involved.  These are being dealt with at bug 420534.  And sometime in the next few weeks I'll open another bug to deal with them more broadly.  See bug 420534 comment #17.
Speaking of spamming syslog, on Fedora 26 x64 with Firefox Nightly (20170807113452), every page load spams /var/log/messages with messages like this:

Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Times
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: FreeSerif
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Times
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: FreeSerif
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Verdana-Bold
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Arial
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Courier
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Arial
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Helvetica
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Arial
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Helvetica
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Arial
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Helvetica
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Arial
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Optima
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Futura
Aug  7 23:07:24 fedora org.xfce.FileManager: serialization: Roboto

Visiting this page triggered over 25 lines to be written to this file. RIP the SSD of any power browser or anyone that leaves pages open that auto-refresh.
You need to log in before you can comment on or make changes to this bug.