removing warning/debug messages from NSPR (debug) logging

[Nathan Froyd]

Hi all,

Over in bug 794178, we're hitting cases where the combination of write poisoning (crashing if writes to disk are detected after a certain point) and logging are causes crashes. These same crashes are blocking testing for WebRTC (bug 811764). The root cause is that the warnings emitted by NS_* macros such as NS_ENSURE_TRUE are written to the debug log if one exists. David Baron has approved a patch[1] that removes the problematic logging.

If you have objections to this change, please speak up, either here or in bug 794178. Otherwise, the patch that removes the logging will be committed later this week.

Thanks,
-Nathan

[1] https://bugzilla.mozilla.org/attachment.cgi?id=697077

[Benjamin Smedberg]

On 1/2/2013 2:34 PM, Nathan Froyd wrote:
> Hi all,
>
> Over in bug 794178, we're hitting cases where the combination of write poisoning (crashing if writes to disk are detected after a certain point) and logging are causes crashes. These same crashes are blocking testing for WebRTC (bug 811764). The root cause is that the warnings emitted by NS_* macros such as NS_ENSURE_TRUE are written to the debug log if one exists. David Baron has approved a patch[1] that removes the problematic logging.
>
> If you have objections to this change, please speak up, either here or in bug 794178. Otherwise, the patch that removes the logging will be committed later this week.

There are potentially lots of ways to cause logging to happen after
poisoning is enabled. I don't understand why we shouldn't instead
whitelist logging as ok during shutdown.

Was this particular logging enabled with NSPR_LOG_MODULES=all:5 or how
in particular did we end up enabling logging for webrtc tests in
particular that wouldn't have affected many of the other logging modules?

I don't think this is the correct choice.

--BDS

[Nathan Froyd]

----- Original Message -----
> There are potentially lots of ways to cause logging to happen after
> poisoning is enabled. I don't understand why we shouldn't instead
> whitelist logging as ok during shutdown.

The whitelist technique that has been used for other files, e.g.
whitelisting particular file descriptors:

http://mxr.mozilla.org/mozilla-central/source/xpcom/build/mozPoisonWriteMac.cpp#380

can't be used with NSPR logging because we don't have access to the
FILE* or file descriptor that's used for the logging file.

> Was this particular logging enabled with NSPR_LOG_MODULES=all:5 or
> how
> in particular did we end up enabling logging for webrtc tests in
> particular that wouldn't have affected many of the other logging
> modules?

I see that bug 811764 has been resolved in a different way, so the
combination of logging and write poisoning wasn't responsible for
the WebRTC failures. But the problem still remains in other contexts,
especially developers using logging themselves to figure out what's
going on, whether in personal builds or release builds.

-Nathan

[Boris Zbarsky]

On 1/2/13 4:44 PM, Benjamin Smedberg wrote:
> Was this particular logging enabled with NSPR_LOG_MODULES=all:5

No.

The failure mode was that if you enabled logging for any module at all
we would crash at shutdown because there was an NS_WARNING after
poisoning happened (from NS_ENSURE_SOMETHING_OR_OTHER) and NS_WARNING
always got logged into the log, no matter what module you were logging.

Which was arguably broken and made logs a pain to read since they had
all sorts of NS_WARNING spew in them, hence the suggestion to not log
those to logs at all....

-Boris

[Benjamin Smedberg]

On 1/2/13 9:11 PM, Boris Zbarsky wrote:
> On 1/2/13 4:44 PM, Benjamin Smedberg wrote:
>> Was this particular logging enabled with NSPR_LOG_MODULES=all:5
>
> No.
>
> The failure mode was that if you enabled logging for any module at all
> we would crash at shutdown because there was an NS_WARNING after
> poisoning happened (from NS_ENSURE_SOMETHING_OR_OTHER) and NS_WARNING
> always got logged into the log, no matter what module you were logging.

Do we know why this was happening? The log module specifies "nsDebug",
and it should only be written to the log if PR_LOG_MODULES includes
"nsDebug".

What this patch is basically saying is that it's a bug to use NSPR
logging after early shutdown. I don't think that's reasonable, and I
think we should spend time trying to make NSPR logging work correctly.

That the NS_* debug spew shows up in the NSPR logs all the time seems
like a separate bug which we should also fix, but I suspect that having
the existing debug spew mixed into the NSPR logs may be useful for some
people (I've certainly used it in the past) and I'm loathe to remove it
as a bandaid for the real problems.

--BDS

[Boris Zbarsky]

On 1/3/13 1:08 PM, Benjamin Smedberg wrote:
> Do we know why this was happening? The log module specifies "nsDebug",
> and it should only be written to the log if PR_LOG_MODULES includes
> "nsDebug".

It's because InitLog in nsDebugImpl does this:

gDebugLog = PR_NewLogModule("nsDebug");
gDebugLog->level = PR_LOG_DEBUG;

and the second line force-enables gDebugLog at the PR_LOG_DEBUG level no
matter what NSPR_LOG_MODULES is set to, as long as it's set, effectively.

-Boris

[Benjamin Smedberg]

Ah! I fully support removing that line so that nsDebug obeys the normal
rules of NSPR_LOG_MODULES. Count that as r+ to land if you like, and
that should be enough wallpaper to avoid the other patch for now.

--BDS

[Ehsan Akhgari]

On 2013-01-03 1:28 PM, Benjamin Smedberg wrote:
> On 1/3/13 1:23 PM, Boris Zbarsky wrote:

> Ah! I fully support removing that line so that nsDebug obeys the normal
> rules of NSPR_LOG_MODULES. Count that as r+ to land if you like, and
> that should be enough wallpaper to avoid the other patch for now.

https://hg.mozilla.org/integration/mozilla-inbound/rev/8755061452d9

Cheers,
Ehsan

[Neil]

Nathan Froyd wrote:

>If you have objections to this change, please speak up, either here or in bug 794178.
>

set NSPR_LOG_FILE=WinDebug
is currently the only way to get assertions and warnings logged in the
debugger output window. (Other output, such as dump(), is special-cased.)

--
Warning: May contain traces of nuts.