Closed Bug 1165515 Opened 9 years ago Closed 9 years ago

Add stub replacement for NSPR logging

Categories

(Core :: XPCOM, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
Tracking Status
firefox41 --- affected

People

(Reporter: erahm, Assigned: erahm)

References

(Blocks 1 open bug)

Details

Attachments

(16 files, 8 obsolete files)

1.00 MB, patch
froydnj
: review+
Details | Diff | Splinter Review
902 bytes, patch
froydnj
: review+
Details | Diff | Splinter Review
165.26 KB, patch
froydnj
: review+
Details | Diff | Splinter Review
1.04 KB, patch
froydnj
: review+
Details | Diff | Splinter Review
340.27 KB, patch
froydnj
: review+
froydnj
: feedback+
jesup
: feedback+
Details | Diff | Splinter Review
972 bytes, patch
froydnj
: review+
Details | Diff | Splinter Review
24.95 KB, patch
froydnj
: review+
Details | Diff | Splinter Review
3.58 KB, patch
jesup
: review+
Details | Diff | Splinter Review
1.43 KB, patch
ekr
: review+
Details | Diff | Splinter Review
19.73 KB, patch
froydnj
: review+
Details | Diff | Splinter Review
1.57 KB, patch
benjamin
: review+
Details | Diff | Splinter Review
4.79 KB, patch
jesup
: review+
Details | Diff | Splinter Review
2.00 KB, patch
froydnj
: review+
Details | Diff | Splinter Review
1.28 MB, patch
froydnj
: review+
Details | Diff | Splinter Review
4.31 KB, patch
froydnj
: review+
Details | Diff | Splinter Review
2.34 KB, patch
jesup
: review+
Details | Diff | Splinter Review
Add a stub replacement to NSPR logging as a first step to providing a logging framework that more adequately serves Gecko's needs.

This will move over from using "prlog.h" directly in the gecko code base and transition from |PR_LOG*| to |MOZ_LOG*|.

The initial implementation will simply be a pass-through to NSPR.
Depends on: 1165518
Command used:
find . -type f -not \( -path "./nsprpub/*" -o -path "*/nss/*" -o -path "./obj-x86_64-unknown-linux-gnu/*" -o -path "./xpcom/glue/Logging.h" \)  \( -name '*.cpp' -o -name '*.h' -o -name '*.c' \) | xargs sed -i -e 's/PR_LOG(/MOZ_LOG(/g'
Attachment #8608540 - Flags: review?(nfroyd)
Assignee: nobody → erahm
Status: NEW → ASSIGNED
Now w/ *.mm:

find . -type f -not \( -path "./nsprpub/*" -o -path "*/nss/*" -o -path "./obj-x86_64-unknown-linux-gnu/*" -o -path "./xpcom/glue/Logging.h" \)  \( -name '*.cpp' -o -name '*.h' -o -name '*.c' -o -name '*.mm' \) | xargs sed -i -e 's/PR_LOG(/MOZ_LOG(/g'
Attachment #8608544 - Flags: review?(nfroyd)
Attachment #8608540 - Attachment is obsolete: true
Attachment #8608540 - Flags: review?(nfroyd)
Attachment #8608544 - Flags: review?(nfroyd) → review+
This replaces PR_LOG_TEST with a safer MOZ_LOG_TEST version that checks for
null log modules as well.
Attachment #8609009 - Flags: review?(nfroyd)
Attachment #8609010 - Flags: review?(nfroyd)
(In reply to Eric Rahm [:erahm] from comment #6)
> Created attachment 8609010 [details] [diff] [review]
> Part 3: Convert PR_LOG_TEST to MOZ_LOG_TEST

Command used:
> find . -type f -not \( -path "./nsprpub/*" -o -path "*/nss/*" -o \
>                        -path "./obj-x86_64-unknown-linux-gnu/*" -o \
>                        -path "./xpcom/glue/Logging.h" \) 
>        \( -name '*.cpp' -o -name '*.h' -o -name '*.c' -o -name '*.mm' \) | \
> xargs sed -i -e 's/PR_LOG_TEST(/MOZ_LOG_TEST(/g'
Attached patch Part 4: Add PR_LOG_INFO (obsolete) — Splinter Review
This is an interstitial step in preparation for adding a new info level. For
now it just maps to debug.
Attachment #8609085 - Flags: review?(nfroyd)
Most instances were converted to PR_LOG_INFO, some to PR_LOG_DEBUG, and some
to PR_LOG_ERROR.
Attachment #8609086 - Flags: review?(nfroyd)
Keywords: leave-open
General logic is in files that use variations of PR_LOG_DEBUG + 1 we map
existing instances of |PR_LOG_DEBUG + 1| => |PR_LOG_DEBUG| and
|PR_LOG_DEBUG| => |PR_LOG_INFO|.
Attachment #8609099 - Flags: review?(nfroyd)
Forget to qref, here's the actual change.
Attachment #8609117 - Flags: review?(nfroyd)
Attachment #8609085 - Attachment is obsolete: true
Attachment #8609085 - Flags: review?(nfroyd)
Now with the previous patch split out.
Attachment #8609118 - Flags: review?(nfroyd)
Attachment #8609086 - Attachment is obsolete: true
Attachment #8609086 - Flags: review?(nfroyd)
Comment on attachment 8609009 [details] [diff] [review]
Part 2: Add MOZ_LOG_TEST

Since logging is always statically enabled but usually dynamically disabled you might want to add MOZ_UNLIKELY() around the condition. It's not going to make much of a difference on desktop platforms but better code generation might help on the lousy ARM cores we have on FxOS devices (and most Android phones).

Also, what's the rationale behind |_module| being sometimes null? Couldn't you just mandate that MOZ_LOG() users will always provide a module and MOZ_ASSERT() on it just in case?
Comment on attachment 8609009 [details] [diff] [review]
Part 2: Add MOZ_LOG_TEST

Review of attachment 8609009 [details] [diff] [review]:
-----------------------------------------------------------------

r=me with Gabriele's comments addressed; I don't understand why the module can be null here, either, especially because the equivalent nspr macro doesn't check for null.

I think it would be valuable to convert this to an inline function (mozilla::LogLevelIs?  mozilla::LogLevelAtLeast?  keep the all-caps name?), so we can get some type checking that was unavailable with the nspr macro.
Attachment #8609009 - Flags: review?(nfroyd) → review+
Comment on attachment 8609010 [details] [diff] [review]
Part 3: Convert PR_LOG_TEST to MOZ_LOG_TEST

Review of attachment 8609010 [details] [diff] [review]:
-----------------------------------------------------------------

I'm going to assume this was done with find + sed.
Attachment #8609010 - Flags: review?(nfroyd) → review+
Comment on attachment 8609118 [details] [diff] [review]
Part 5: Convert instances of PR_LOG_ALWAYS

Review of attachment 8609118 [details] [diff] [review]:
-----------------------------------------------------------------

I'm not comfortable reviewing a patch that changes one thing to multiple things, depending; it's not clear to me what criteria were used.  The dev-platform discussion has provided some stuff to think about, so I'm going to cancel this review for now.
Attachment #8609118 - Flags: review?(nfroyd)
Attachment #8609117 - Flags: review?(nfroyd) → review+
Comment on attachment 8609099 [details] [diff] [review]
Part 6: Remove PR_LOG_DEBUG + 1 pattern

Review of attachment 8609099 [details] [diff] [review]:
-----------------------------------------------------------------

f+ while I think about this.
Attachment #8609099 - Flags: review?(nfroyd) → feedback+
(In reply to Nathan Froyd [:froydnj] [:nfroyd] from comment #18)
> Comment on attachment 8609010 [details] [diff] [review]
> Part 3: Convert PR_LOG_TEST to MOZ_LOG_TEST
> 
> Review of attachment 8609010 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I'm going to assume this was done with find + sed.

Yes, comment 7 cas the command.
(In reply to Gabriele Svelto [:gsvelto] from comment #16)
> Comment on attachment 8609009 [details] [diff] [review]
> Part 2: Add MOZ_LOG_TEST
> 
> Since logging is always statically enabled but usually dynamically disabled
> you might want to add MOZ_UNLIKELY() around the condition. It's not going to
> make much of a difference on desktop platforms but better code generation
> might help on the lousy ARM cores we have on FxOS devices (and most Android
> phones).

Good idea! I will add this.

> Also, what's the rationale behind |_module| being sometimes null? Couldn't
> you just mandate that MOZ_LOG() users will always provide a module and
> MOZ_ASSERT() on it just in case?

See bug 1166127 (allocating a log module can fail, but we don't handle it). Also see bug 1165641.

(In reply to Nathan Froyd [:froydnj] [:nfroyd] from comment #17)
> Comment on attachment 8609009 [details] [diff] [review]
> Part 2: Add MOZ_LOG_TEST
> 
> Review of attachment 8609009 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> r=me with Gabriele's comments addressed; I don't understand why the module
> can be null here, either, especially because the equivalent nspr macro
> doesn't check for null.

See above. I'm open to dealing with this at a later time if you prefer.

> I think it would be valuable to convert this to an inline function
> (mozilla::LogLevelIs?  mozilla::LogLevelAtLeast?  keep the all-caps name?),
> so we can get some type checking that was unavailable with the nspr macro.

Yes, I would like to do that once we get the enum class added.
(In reply to Nathan Froyd [:froydnj] [:nfroyd] from comment #19)
> Comment on attachment 8609118 [details] [diff] [review]
> Part 5: Convert instances of PR_LOG_ALWAYS
> 
> Review of attachment 8609118 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I'm not comfortable reviewing a patch that changes one thing to multiple
> things, depending; it's not clear to me what criteria were used.  The
> dev-platform discussion has provided some stuff to think about, so I'm going
> to cancel this review for now.

Would you prefer to split it up? Unfortunately there's no straightforward mapping (well it could be PR_LOG_ERROR, but I think that is universally considered a bad thing).
Comment on attachment 8609118 [details] [diff] [review]
Part 5: Convert instances of PR_LOG_ALWAYS

Review of attachment 8609118 [details] [diff] [review]:
-----------------------------------------------------------------

Commented on the ones that didn't cleanly map to INFO.

::: dom/xul/templates/nsXULContentBuilder.cpp
@@ +451,1 @@
>                 ("nsXULContentBuilder::BuildContentFromTemplate (is unique: %d)",

Here I switched to DEBUG b/c the test was for DEBUG.

@@ +1075,5 @@
>  {
>      if (MOZ_LOG_TEST(gXULTemplateLog, PR_LOG_DEBUG)) {
>          nsAutoString id;
>          aResult->GetId(id);
> +        MOZ_LOG(gXULTemplateLog, PR_LOG_DEBUG,

Same deal.

::: dom/xul/templates/nsXULTemplateQueryProcessorRDF.cpp
@@ +491,5 @@
>                  query->mRefVariable->ToString(rvar);
>                  nsAutoString mvar;
>                  query->mMemberVariable->ToString(mvar);
>  
> +                MOZ_LOG(gXULTemplateLog, PR_LOG_DEBUG,

same

@@ +870,5 @@
>          aProperty->GetValueConst(&propertyStr);
>          nsAutoString targetStr;
>          nsXULContentUtils::GetTextForNode(aTarget, targetStr);
>  
> +        MOZ_LOG(gXULTemplateLog, PR_LOG_DEBUG,

same

@@ +957,5 @@
>          aProperty->GetValueConst(&propertyStr);
>          nsAutoString targetStr;
>          nsXULContentUtils::GetTextForNode(aTarget, targetStr);
>  
> +        MOZ_LOG(gXULTemplateLog, PR_LOG_DEBUG,

same

::: gfx/2d/Logging.h
@@ +52,5 @@
>      return PR_LOG_DEBUG;
>    case LOG_DEBUG_PRLOG:
>      return PR_LOG_DEBUG;
>    case LOG_EVERYTHING:
> +    return PR_LOG_ERROR;

This is never used, but the code just meant to use the highest level of logging (that will now be ERROR).

::: layout/style/Loader.cpp
@@ -269,5 @@
>  #define LOG_WARN(args) MOZ_LOG(GetLoaderLog(), PR_LOG_WARNING, args)
>  #define LOG_DEBUG(args) MOZ_LOG(GetLoaderLog(), PR_LOG_DEBUG, args)
>  #define LOG(args) LOG_DEBUG(args)
>  
> -#define LOG_FORCE_ENABLED() MOZ_LOG_TEST(GetLoaderLog(), PR_LOG_ALWAYS)

These were not used.

::: netwerk/protocol/http/HttpLog.h
@@ +30,5 @@
>  //
>  //    set NSPR_LOG_MODULES=nsHttp:5
>  //    set NSPR_LOG_FILE=http.log
>  //
> +// this enables PR_LOG_DEBUG level information and places all output in

Anything like this was just a copy and paste error from the previous writer. Log level 5 in the example is really PR_LOG_DEBUG + 1, but we're getting rid of that so I just went w/ DEBUg.

::: netwerk/sctp/datachannel/DataChannel.cpp
@@ +177,5 @@
>  {
>    va_list ap;
>    char buffer[1024];
>  
> +  if (MOZ_LOG_TEST(GetSCTPLog(), PR_LOG_DEBUG)) {

Considering this function is called |debug_printf| I went w/ debug. It could be info though.

::: rdf/base/nsRDFContentSink.cpp
@@ +1212,5 @@
>          SplitExpatName(aName, getter_AddRefs(localName));
>  
>      if (!nameSpaceURI.EqualsLiteral(RDF_NAMESPACE_URI) ||
>          localName != kLiAtom) {
> +        MOZ_LOG(gLog, PR_LOG_ERROR,

This message was pretty clearly an error and the file uses other log levels.

::: security/manager/ssl/src/nsNSSComponent.cpp
@@ +1146,5 @@
>      MOZ_LOG(gPIPNSSLog, PR_LOG_DEBUG, ("evaporating psm resources\n"));
>      mShutdownObjectList->evaporateAllNSSResources();
>      EnsureNSSInitialized(nssShutdown);
>      if (SECSuccess != ::NSS_Shutdown()) {
> +      MOZ_LOG(gPIPNSSLog, PR_LOG_ERROR, ("NSS SHUTDOWN FAILURE\n"));

same

::: widget/windows/WinUtils.cpp
@@ +483,5 @@
>        // desktop console
>        printf("%s\n", utf8);
>        NS_ASSERTION(gWindowsLog, "Called WinUtils Log() but Widget "
>                                     "log module doesn't exist!");
> +      MOZ_LOG(gWindowsLog, PR_LOG_ERROR, (utf8));

These seemed to want to use the highest level.

::: xpcom/base/nsDebugImpl.cpp
@@ +330,5 @@
>        break;
>  
>      case NS_DEBUG_BREAK:
>        sevString = "###!!! BREAK";
> +      ll = PR_LOG_ERROR;

These seem to want the highest level of output.
Now that there is a PR_LOG_INFO type we can update code that was using
PR_LOG_DEBUG + 1 as follows:
  |PR_LOG_DEBUG|     => |PR_LOG_INFO|
  |PR_LOG_DEBUG + 1| => |PR_LOG_DEBUG|

Jesup, I know you had concerns about this. Would you mind taking a look?
Attachment #8610913 - Flags: review?(rjesup)
Attachment #8609099 - Attachment is obsolete: true
This is the netwerk and layout portions split out from dom/media.
Attachment #8610914 - Flags: review?(nfroyd)
Comment on attachment 8610913 [details] [diff] [review]
Part 6: Remove PR_LOG_DEBUG + 1 pattern from media

Review of attachment 8610913 [details] [diff] [review]:
-----------------------------------------------------------------

You'll need to add reviews from other media peers (padenot for audio and MediaStreamGraph stuff, perhaps cpearce or roc for Decoders, someone for WebM, not sure for MediaSource, etc.  you're also missing others: MediaEngineWebRTC*, MediaManager, etc.)

Also: since you're moving DEBUG->INFO in specific log IDs, did you hit all uses of DEBUG with those log IDs, not just ones in the same files as a DEBUG+1?  For example, MediaManager:N logs affect dom/media/MediaManager.cpp (no +1's), and dom/media/webrtc/MediaEngine* (some files there have a LOG_FRAME()/etc macro, others just use DEBUG).

None of the files here are the ones I should be the primary reviewer for (I could review the MediaStreamGraph stuff and AudioSink/GraphDriver, but padenot is the primary maintainer on that code now).  I would be the reviewer for MediaEngine/MediaManager code, and perhaps some other uses
Attachment #8610913 - Flags: review?(rjesup)
Randell, thank you this is great feedback (I apologize, I should have flagged this as feedback, not review). It can be hard to tell who needs to review dom/media code (https://wiki.mozilla.org/Modules/Core does not provide a clear list, it would be nice if we could improve that).

(In reply to Randell Jesup [:jesup] from comment #28)
> Comment on attachment 8610913 [details] [diff] [review]
> Part 6: Remove PR_LOG_DEBUG + 1 pattern from media
> 
> Review of attachment 8610913 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> You'll need to add reviews from other media peers (padenot for audio and
> MediaStreamGraph stuff, perhaps cpearce or roc for Decoders, someone for
> WebM, not sure for MediaSource, etc.  you're also missing others:
> MediaEngineWebRTC*, MediaManager, etc.)

Would you mind flagging these folks for review, or if you'd like I can split up per area but I do not know who should review "someone for WebM, not sure for MediaSource, etc ... MediaEngineWebRTC*, MediaManager, etc." This is a pretty rote replacement and you had the most straightforward opinions on it; I was hoping you'd feel comfortable reviewing, but if not I could use help identifying others.

> Also: since you're moving DEBUG->INFO in specific log IDs, did you hit all
> uses of DEBUG with those log IDs, not just ones in the same files as a
> DEBUG+1?  For example, MediaManager:N logs affect dom/media/MediaManager.cpp
> (no +1's), and dom/media/webrtc/MediaEngine* (some files there have a
> LOG_FRAME()/etc macro, others just use DEBUG).

This is a great suggestion to provide uniform usage of log levels across the dom/media landscape, if there are any beyond this list please let me know. I'll update those accordingly.

> None of the files here are the ones I should be the primary reviewer for (I
> could review the MediaStreamGraph stuff and AudioSink/GraphDriver, but
> padenot is the primary maintainer on that code now).  I would be the
> reviewer for MediaEngine/MediaManager code, and perhaps some other uses

No worries, from your comments it sounds like padenot, cpearce and roc and yourself should cover things?
(In reply to Eric Rahm [:erahm] from comment #29)
> Randell, thank you this is great feedback (I apologize, I should have
> flagged this as feedback, not review). It can be hard to tell who needs to
> review dom/media code (https://wiki.mozilla.org/Modules/Core does not
> provide a clear list, it would be nice if we could improve that).

There's module ownership, and then there's who's the appropriate reviewer.  Also, a number of media modules are combined in dom/media and dom/media/*

> > You'll need to add reviews from other media peers (padenot for audio and
> > MediaStreamGraph stuff, perhaps cpearce or roc for Decoders, someone for
> > WebM, not sure for MediaSource, etc.  you're also missing others:
> > MediaEngineWebRTC*, MediaManager, etc.)
> 
> Would you mind flagging these folks for review, or if you'd like I can split
> up per area but I do not know who should review "someone for WebM, not sure
> for MediaSource, etc ... MediaEngineWebRTC*, MediaManager, etc." This is a
> pretty rote replacement and you had the most straightforward opinions on it;
> I was hoping you'd feel comfortable reviewing, but if not I could use help
> identifying others.

Generally "hg log foo/bar" and look who's doing most of the work there ;-)
I'll see who makes sense.  I don't want to rework other people's logging structure, especially if there's disagreement over what to do.  (DEBUG->INFO + DEBUG+1->DEBUG or move DEBUG+1 to a new logging ID, for example)

> > Also: since you're moving DEBUG->INFO in specific log IDs, did you hit all
> > uses of DEBUG with those log IDs, not just ones in the same files as a
> > DEBUG+1?  For example, MediaManager:N logs affect dom/media/MediaManager.cpp
> > (no +1's), and dom/media/webrtc/MediaEngine* (some files there have a
> > LOG_FRAME()/etc macro, others just use DEBUG).
> 
> This is a great suggestion to provide uniform usage of log levels across the
> dom/media landscape, if there are any beyond this list please let me know.
> I'll update those accordingly.

My point was that some log IDs (MediaManager, signaling, etc) are used in MANY files, and if you change what "Debug" means in those you need to update all of them.  It's extra painful for one major one you missed:
signaling logs are done via CSFLogDebug/Info/etc - and those levels *don't* match PR_LOG levels.  These were inherited from the SIPCC signaling code we imported (and the backend for logging switched to NSPR, but the levels weren't all redone as that would have involved massive changes to the imported code - and as we've increasingly integrated/rewritten the signaling code this usage has been maintained.

media/webrtc/signaling/src/common/browser_logging/CSFLog.h:

typedef enum{
    CSF_LOG_CRITICAL =1,
    CSF_LOG_ERROR,
    CSF_LOG_WARNING,
    CSF_LOG_NOTICE,
    CSF_LOG_INFO,
    CSF_LOG_DEBUG,
    CSF_LOG_OBNOXIOUS
} CSFLogLevel;

You'll note this has *both* Info and Obnoxious levels.  However, Obnoxious isn't used -- but that's effectively the equivalent in NSPR of DEBUG+2.  CSFLogDebug ~= PR_LOG_DEBUG+1 - and we have hundreds of uses of CSFLogDebug.  And that really is meant to be "debug" not verbose, which is why we in webrtc tend to consider :5 "normal" debug levels as signaling:5 is the most common thing we log.

> > None of the files here are the ones I should be the primary reviewer for (I
> > could review the MediaStreamGraph stuff and AudioSink/GraphDriver, but
> > padenot is the primary maintainer on that code now).  I would be the
> > reviewer for MediaEngine/MediaManager code, and perhaps some other uses
> 
> No worries, from your comments it sounds like padenot, cpearce and roc and
> yourself should cover things?

jya & cpearce for MediaSource (probably cpearce).  rillian for WebM probably.  I'll want to involve bwc (Byron Campen) on the signaling changes
(In reply to Randell Jesup [:jesup] from comment #30)

> Generally "hg log foo/bar" and look who's doing most of the work there ;-)
> I'll see who makes sense.  I don't want to rework other people's logging
> structure, especially if there's disagreement over what to do.  (DEBUG->INFO
> + DEBUG+1->DEBUG or move DEBUG+1 to a new logging ID, for example)

Sure, I'll split out reviews for each relevant area and see if each owner is happy.

> My point was that some log IDs (MediaManager, signaling, etc) are used in
> MANY files, and if you change what "Debug" means in those you need to update
> all of them. 

Point taken, I'm happy to update them.

> It's extra painful for one major one you missed:
> signaling logs are done via CSFLogDebug/Info/etc - and those levels *don't*
> match PR_LOG levels.  These were inherited from the SIPCC signaling code we
> imported (and the backend for logging switched to NSPR, but the levels
> weren't all redone as that would have involved massive changes to the
> imported code - and as we've increasingly integrated/rewritten the signaling
> code this usage has been maintained.
> 
> media/webrtc/signaling/src/common/browser_logging/CSFLog.h:
> 
> typedef enum{
>     CSF_LOG_CRITICAL =1,
>     CSF_LOG_ERROR,
>     CSF_LOG_WARNING,
>     CSF_LOG_NOTICE,
>     CSF_LOG_INFO,
>     CSF_LOG_DEBUG,
>     CSF_LOG_OBNOXIOUS
> } CSFLogLevel;

As CRITICAL, NOTICE, and OBNOXIOUS are never used, it would be probably be simpler to just remove them, which leaves us with:

typedef enum{
    CSF_LOG_ERROR = 1,
    CSF_LOG_WARNING,
    CSF_LOG_INFO,
    CSF_LOG_DEBUG
} CSFLogLevel;

That seems to fit quite nicely with the current logging proposal.

> You'll note this has *both* Info and Obnoxious levels.  However, Obnoxious
> isn't used -- but that's effectively the equivalent in NSPR of DEBUG+2. 
> CSFLogDebug ~= PR_LOG_DEBUG+1 - and we have hundreds of uses of CSFLogDebug.
> And that really is meant to be "debug" not verbose, which is why we in
> webrtc tend to consider :5 "normal" debug levels as signaling:5 is the most
> common thing we log.

Yes unfortunately for webrtc we'll have to slightly adjust that notion and consider the new 'Info' level (aka :4) to be normal.

> jya & cpearce for MediaSource (probably cpearce).  rillian for WebM
> probably.  I'll want to involve bwc (Byron Campen) on the signaling changes

Thank you, I will split out reviews for them.
Comment on attachment 8610914 [details] [diff] [review]
Part 7: Remove PR_LOG_DEBUG + 1 pattern from netwerk and layout

Review of attachment 8610914 [details] [diff] [review]:
-----------------------------------------------------------------

I think the netwerk/ changes are basically no-ops, since the netwerk/protocol/ directory doesn't seem to use LOG4 or similar (the sole suggestion that it might, {Http2Session,SpdySession31}::LogIO:

http://mxr.mozilla.org/mozilla-central/source/netwerk/protocol/http/Http2Session.h#190
http://mxr.mozilla.org/mozilla-central/source/netwerk/protocol/http/SpdySession31.h#162

actually uses LOG5 under the covers, so...).

That being said, I'm not sure I'm within my rights to approve those changes, so bouncing the review to jduell while mcmanus is on PTO.

The AccessibleCaretLogger.h change is an actual behavior change (logging at :4 will now give you lots of output, where it didn't before; I think that would be acceptable if the separation of info/debug were immanent, but...), and outside my bailwick.  Bouncing that to dholbert--I don't know whether it falls under layout or a11y.

::: netwerk/protocol/http/Http2Compression.cpp
@@ -6,5 @@
>  
>  // HttpLog.h should generally be included first
>  #include "HttpLog.h"
>  
>  // Log on level :5, instead of default :4.

These sorts of comments are all wrong now (several examples throughout).
Attachment #8610914 - Flags: review?(nfroyd)
Attachment #8610914 - Flags: review?(jduell.mcbugs)
Attachment #8610914 - Flags: review?(dholbert)
Comment on attachment 8610914 [details] [diff] [review]
Part 7: Remove PR_LOG_DEBUG + 1 pattern from netwerk and layout

After discussing in irc jesup and I have agreed that we should just go with adding a verbose level and mapping DEBUG+1 to VERBOSE so as to keep the current logic consistent.
Attachment #8610914 - Flags: review?(jduell.mcbugs)
Attachment #8610914 - Flags: review?(dholbert)
Attachment #8610913 - Attachment is obsolete: true
Attachment #8610914 - Attachment is obsolete: true
Attachment #8611514 - Flags: review?(nfroyd)
Used the command: |sed -E -i -e 's/PR_LOG_DEBUG\s*\+\s*1/PR_LOG_VERBOSE/g'|
Attachment #8611515 - Flags: review?(nfroyd)
To fit into the new structure of mozilla logging we need to remove |ML_EMERG|
(it is not used) and as an interim step we need to switch from using raw
integers to the new PR_LOG levels.
Attachment #8611599 - Flags: review?(ekr)
Comment on attachment 8611601 [details] [diff] [review]
Part 9: Remove instances of using numeric log levels 1-5. rs=froydnj

Review of attachment 8611601 [details] [diff] [review]:
-----------------------------------------------------------------

Command used:

FILES=$(find . -type f -not \( -path "./nsprpub/*" -o -path "*/nss/*" -o -path "./obj-x86_64-unknown-linux-gnu/*" -o -path "./xpcom/glue/Logging.h" -o -path "*/third_party/*" \)  \( -name '*.cpp' -o -name '*.h' -o -name '*.c' -o -name '*.mm' \))

echo $FILES | xargs sed -E -i -e 's/LOG(_TEST)?(\(.*,\s*)1([,\)])/LOG\1\2PR_LOG_ERROR\3/g'
echo $FILES | xargs sed -E -i -e 's/LOG(_TEST)?(\(.*,\s*)2([,\)])/LOG\1\2PR_LOG_WARNING\3/g'
echo $FILES | xargs sed -E -i -e 's/LOG(_TEST)?(\(.*,\s*)3([,\)])/LOG\1\2PR_LOG_INFO\3/g'
echo $FILES | xargs sed -E -i -e 's/LOG(_TEST)?(\(.*,\s*)4([,\)])/LOG\1\2PR_LOG_DEBUG\3/g'
echo $FILES | xargs sed -E -i -e 's/LOG(_TEST)?(\(.*,\s*)5([,\)])/LOG\1\2PR_LOG_VERBOSE\3/g'
Attachment #8611514 - Flags: review?(nfroyd) → review+
Attachment #8611515 - Flags: review?(nfroyd) → review+
Attachment #8611601 - Flags: review?(nfroyd) → review+
Attachment #8611516 - Flags: review?(rjesup) → review+
This aligns CSFLogLevel with the corresponding PR_LOG levels by removing the
unused CRITICAL, NOTICE, and OBNOXIOUS CSF log levels.
Attachment #8612402 - Flags: review?(rjesup)
Attachment #8609118 - Flags: feedback?(nfroyd)
Comment on attachment 8612402 [details] [diff] [review]
Part 11: Align CSFLogLevel with PR_LOG levels

Review of attachment 8612402 [details] [diff] [review]:
-----------------------------------------------------------------

::: media/webrtc/signaling/src/common/browser_logging/CSFLog.h
@@ +8,5 @@
>  #include <stdarg.h>
>  #include "mozilla/Logging.h"
>  
>  typedef enum{
> +    CSF_LOG_ERROR = 1,

let's make the mapping explicit by either getting rid of CSFLogLevel (and use PR_LOG_foo's below), or using CSF_LOG_ERROR = PR_LOG_ERROR, etc.  At minimum comment as to the mapping.  And since we added Verbose, you could map Obnoxious to Verbose (or rename it CSFLogVerbose(), which would make more sense).
Attachment #8612402 - Flags: review?(rjesup) → review+
(In reply to Randell Jesup [:jesup] from comment #41)
> Comment on attachment 8612402 [details] [diff] [review]
> Part 11: Align CSFLogLevel with PR_LOG levels
> 
> Review of attachment 8612402 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: media/webrtc/signaling/src/common/browser_logging/CSFLog.h
> @@ +8,5 @@
> >  #include <stdarg.h>
> >  #include "mozilla/Logging.h"
> >  
> >  typedef enum{
> > +    CSF_LOG_ERROR = 1,
> 
> let's make the mapping explicit by either getting rid of CSFLogLevel (and
> use PR_LOG_foo's below), or using CSF_LOG_ERROR = PR_LOG_ERROR, etc.  At
> minimum comment as to the mapping.

Originally I was inclined to do this as well. Unfortunately it's a bit trickier than it seems. Step 11 + N in this patchset is going to swap out the PR_LOG levels for the new enum. Since it's an 'enum class' which is not supported in C code, it causes compilation errors in webrtc/signaling.

I *could* make those first class functions and move the impl into CSFLogLevel.cpp or we could keep them just numbers.

> And since we added Verbose, you could
> map Obnoxious to Verbose (or rename it CSFLogVerbose(), which would make
> more sense).

Good point, I'll add that back in as CSFLogVerbose.
Comment on attachment 8609118 [details] [diff] [review]
Part 5: Convert instances of PR_LOG_ALWAYS

Review of attachment 8609118 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for the explanation of instances where things weren't changed to INFO.

Terminology note: I find talking about Error being the "highest level" of logging very confusing, both from a numerical value standpoint, and because I think of the amount of output following the relation Verbose > Debug > Info > Warning > Error.  I don't know which is the accepted highest-to-lowest ordering, though.

::: netwerk/sctp/datachannel/DataChannel.cpp
@@ +177,5 @@
>  {
>    va_list ap;
>    char buffer[1024];
>  
> +  if (MOZ_LOG_TEST(GetSCTPLog(), PR_LOG_DEBUG)) {

I think INFO is probably the right level for this file.
Attachment #8609118 - Flags: feedback?(nfroyd) → feedback+
Comment on attachment 8609118 [details] [diff] [review]
Part 5: Convert instances of PR_LOG_ALWAYS

Review of attachment 8609118 [details] [diff] [review]:
-----------------------------------------------------------------

::: netwerk/sctp/datachannel/DataChannel.cpp
@@ +177,5 @@
>  {
>    va_list ap;
>    char buffer[1024];
>  
> +  if (MOZ_LOG_TEST(GetSCTPLog(), PR_LOG_DEBUG)) {

There's a two-point test for debugs in the SCTP library (see other diff in this file).  Either they should match, or this one should always log (however that is done) and the other one should control at what level the SCTP library is told to log.

SCTP logging is fairly verbose (it includes packet dumps in HEX, plus internal info on the stack), so DEBUG would match better, and you could make an argument for VERBOSE.  In practice, this will only matter for people using "all:<level>", since SCTP: only really supports a single level of logging currently.

I suggest debug, and we can look (if we care) to move the per-packet-hex-dump values to Verbose in the future (will require a small mod to the upstream library)
Attachment #8609118 - Flags: feedback+
Comment on attachment 8611599 [details] [diff] [review]
Part 10: Convert mtransport/logging.h to use PR_LOG levels

Review of attachment 8611599 [details] [diff] [review]:
-----------------------------------------------------------------

LGTM
Attachment #8611599 - Flags: review?(ekr) → review+
PLUGIN_LOG_MAX is removed as it's unused. PLUGIN_LOG_ALWAYS is mapped to
PR_LOG_ERROR which will have the value of '1' now that PR_LOG_ALWAYS is
removed.
Attachment #8613001 - Flags: review?(benjamin)
Attachment #8613001 - Flags: review?(benjamin) → review+
(In reply to Nathan Froyd [:froydnj] [:nfroyd] from comment #43)
> Comment on attachment 8609118 [details] [diff] [review]
> Part 5: Convert instances of PR_LOG_ALWAYS
> 
> Review of attachment 8609118 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Thanks for the explanation of instances where things weren't changed to INFO.
> 
> Terminology note: I find talking about Error being the "highest level" of
> logging very confusing, both from a numerical value standpoint, and because
> I think of the amount of output following the relation Verbose > Debug >
> Info > Warning > Error.  I don't know which is the accepted
> highest-to-lowest ordering, though.

I generally think of this in level of importance. For us an Error message is the highest level of importance, Verbose is the lowest level of importance.

As far as level of output, I'd probably use the term verbosity, with Verbose being the highest level of verbosity.

More specifically I try not to use my knowledge of the actual numeric enum value of each level, as I find that does not convey meaning, is an implementation detail, and leads to confusion in conversation (I get the irony of that last statement).

Either way using an unqualified 'highest level' isn't terribly helpful when discussion these things :(

> ::: netwerk/sctp/datachannel/DataChannel.cpp
> @@ +177,5 @@
> >  {
> >    va_list ap;
> >    char buffer[1024];
> >  
> > +  if (MOZ_LOG_TEST(GetSCTPLog(), PR_LOG_DEBUG)) {
> 
> I think INFO is probably the right level for this file.

Per jesup's comments, lets keep this debug and revisit if necessary.
Comment on attachment 8609118 [details] [diff] [review]
Part 5: Convert instances of PR_LOG_ALWAYS

Now that we've hashed out the details lets get this officially reviewed. Thanks for taking the time to look this over!
Attachment #8609118 - Flags: review?(nfroyd)
jesup, this is an update that adds back in verbose and preps the header to be
compatible w/ C files. This meant I couldn't just use PR_LOG levels (as they
will be replaced with a enum class in a namespace).

This aligns CSFLogLevel with the corresponding PR_LOG levels by removing the
unused CRITICAL and NOTICE CSF log levels and renaming OBNOXIOUS to VERBOSE.

mozilla/Logging.h was moved into the implementation file so as to avoid
compilation errors in C-only code.
Attachment #8613112 - Flags: review?(rjesup)
Attachment #8612402 - Attachment is obsolete: true
This adds the mozilla::LogLevel enum class. Additionaly a log_test function is
added to use rather than a macro, this allows us to enforce only
mozilla::LogLevel is passed into the function.
Attachment #8613116 - Flags: review?(nfroyd)
Attachment #8613116 - Flags: feedback?(gsvelto)
This is straightforward mapping of PR_LOG levels to their LogLevel
counterparts:
  PR_LOG_ERROR   -> LogLevel::Error
  PR_LOG_WARNING -> LogLevel::Warning
  PR_LOG_WARN    -> LogLevel::Warning
  PR_LOG_INFO    -> LogLevel::Info
  PR_LOG_DEBUG   -> LogLevel::Debug
  PR_LOG_NOTICE  -> LogLevel::Debug
  PR_LOG_VERBOSE -> LogLevel::Verbose

Instances of PRLogModuleLevel were mapped to a fully qualified
mozilla::LogLevel, instances of PR_LOG levels in #defines were mapped to a
fully qualified mozilla::LogLevel::* level, and all other instances were
mapped to us a shorter format of LogLevel::*.

Bustage for usage of the non-fully qualified LogLevel were fixed by adding
|using mozilla::LogLevel;| where appropriate.

Commands used:

FILES=$(find . -type f -not \( -path "./nsprpub/*" -o -path "*/nss/*" -o -path "./obj-x86_64-unknown-linux-gnu/*" -o -path "./xpcom/glue/Logging.h" -o -path "*/third_party/*" \)  \( -name '*.cpp' -o -name '*.h' -o -name '*.c' -o -name '*.mm' \))

# Replace PRLogModuleLevel
echo $FILES | sed -E -i -e 's/PRLogModuleLevel/mozilla::LogLevel/g'

# Replace usage in #defines
echo $FILES | xargs sed -i -E -e 's/(#define.*)PR_LOG_ERROR/\1mozilla::LogLevel::Error/g'     \
                              -e 's/(#define.*)PR_LOG_WARNING/\1mozilla::LogLevel::Warning/g' \
                              -e 's/(#define.*)PR_LOG_WARN/\1mozilla::LogLevel::Warning/g'    \
                              -e 's/(#define.*)PR_LOG_INFO/\1mozilla::LogLevel::Info/g'       \
                              -e 's/(#define.*)PR_LOG_DEBUG/\1mozilla::LogLevel::Debug/g'     \
                              -e 's/(#define.*)PR_LOG_VERBOSE/\1mozilla::LogLevel::Verbose/g' \
                              -e 's/(#define.*)PR_LOG_NOTICE/\1mozilla::LogLevel::Debug/g'

# Replace everything else
echo $FILES | xargs sed -i -e 's/PR_LOG_ERROR/LogLevel::Error/g;s/PR_LOG_WARNING/LogLevel::Warning/g;s/PR_LOG_WARN/LogLevel::Warning/g;s/PR_LOG_INFO/LogLevel::Info/g;s/PR_LOG_DEBUG/LogLevel::Debug/g;s/PR_LOG_VERBOSE/LogLevel::Verbose/g;s/PR_LOG_NOTICE/LogLevel::Debug/g'
Attachment #8613122 - Flags: review?(nfroyd)
Attachment #8613112 - Flags: review?(rjesup) → review+
Comment on attachment 8613116 [details] [diff] [review]
Part 13-1: Add log level enum class

Since we have to live with the NULL-check (for now) I'm not sure what's the best course of action here, possibly not using MOZ_UNLIKELY() at all. Let me explain why: the mozilla::log_test will now emit two comparison-and-branches, the first one for the NULL check which is likely to be true, and the second for the logging level which is unlikely to be true. I am unsure about the impact of wrapping the entire condition within MOZ_UNLIKELY(); I think it might be better to skip it for now and add it back when the log check won't have to check for NULL first.
Attachment #8613116 - Flags: feedback?(gsvelto)
Attachment #8609118 - Flags: review?(nfroyd) → review+
Comment on attachment 8613116 [details] [diff] [review]
Part 13-1: Add log level enum class

Review of attachment 8613116 [details] [diff] [review]:
-----------------------------------------------------------------

r=me with changes below.

::: xpcom/glue/Logging.h
@@ +19,2 @@
>  
> +enum class LogLevel {

I think there should be a comment here about the correspondence between these and NSPR's logging levels.

@@ +28,3 @@
>  
> +inline bool log_test(const PRLogModuleInfo* module, LogLevel level) {
> +  return module && module->level >= static_cast<int>(level);

Let's MOZ_ASSERT(level != Disabled) here.  Let's also put this in the mozilla::detail namespace so nobody thinks they should be calling log_test directly.

@@ +31,5 @@
> +}
> +
> +}
> +
> +#define MOZ_LOG_TEST(_module,_level) MOZ_UNLIKELY(mozilla::log_test(_module, _level))

I am ambivalent about MOZ_UNLIKELY here.  I don't know what the compiler will do with the branch information after log_test is expanded inline.
Attachment #8613116 - Flags: review?(nfroyd) → review+
Comment on attachment 8613122 [details] [diff] [review]
Part 13-2: Replace usage of PRLogModuleLevel and PR_LOG_*. rs=froydnj

Review of attachment 8613122 [details] [diff] [review]:
-----------------------------------------------------------------

I approve of your sed-fu.

I'm wondering about the ergnomics of the enum class for LogLevel, whether we should have something like:

#define MOZ_LOG(module, level, args) ...LogLevel::##level...

and probably similarly for MOZ_LOG_TEST, just so people have less to type, less horizontal space, etc.  Doesn't matter for the LOG() macro pattern, but might make a difference other places.  WDYT?
Attachment #8613122 - Flags: review?(nfroyd) → review+
(In reply to Nathan Froyd [:froydnj] [:nfroyd] from comment #56)
> Comment on attachment 8613122 [details] [diff] [review]
> Part 13-2: Replace usage of PRLogModuleLevel and PR_LOG_*. rs=froydnj
> 
> Review of attachment 8613122 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I approve of your sed-fu.
> 
> I'm wondering about the ergnomics of the enum class for LogLevel, whether we
> should have something like:
> 
> #define MOZ_LOG(module, level, args) ...LogLevel::##level...
> 
> and probably similarly for MOZ_LOG_TEST, just so people have less to type,
> less horizontal space, etc.  Doesn't matter for the LOG() macro pattern, but
> might make a difference other places.  WDYT?

I like that it would be less verbose, but it would also prevent people from using the fully qualified names (this might have impact on auto-complete, etc).

In the future I hope to add some helper macros that will negate this issue such as:
   MOZ_LOG_DEBUG(module, msg)
or even:
   MOZ_LOG_D(module) << msg

So lets push this out to the next steps after this bug lands.
(In reply to Nathan Froyd [:froydnj] [:nfroyd] from comment #55)
> Comment on attachment 8613116 [details] [diff] [review]
> Part 13-1: Add log level enum class
> 
> Review of attachment 8613116 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> r=me with changes below.
> 
> ::: xpcom/glue/Logging.h
> @@ +19,2 @@
> >  
> > +enum class LogLevel {
> 
> I think there should be a comment here about the correspondence between
> these and NSPR's logging levels.
> 
> @@ +28,3 @@
> >  
> > +inline bool log_test(const PRLogModuleInfo* module, LogLevel level) {
> > +  return module && module->level >= static_cast<int>(level);
> 
> Let's MOZ_ASSERT(level != Disabled) here.  Let's also put this in the
> mozilla::detail namespace so nobody thinks they should be calling log_test
> directly.
> 
> @@ +31,5 @@
> > +}
> > +
> > +}
> > +
> > +#define MOZ_LOG_TEST(_module,_level) MOZ_UNLIKELY(mozilla::log_test(_module, _level))
> 
> I am ambivalent about MOZ_UNLIKELY here.  I don't know what the compiler
> will do with the branch information after log_test is expanded inline.

I'll update per your suggestions, given gsvelto's feedback and the fact that we've lived w/o for 15+ years I'll remove the MOZ_UNLIKELY for now. We can add a follow-up to investigate whether or not there are any perf improvements when adding it.
Make it harder for users to accidentally reintroduce usage of the PR_LOG macros
when using 'mozilla/Logging.h'. This can still be worked around by directly
including 'prlog.h' (and not 'mozilla/Logging.h') if absolutely necessary.

The few remaining references to PR_LOG were fixed up as well.
Attachment #8613641 - Flags: review?(nfroyd)
Attachment #8613641 - Flags: review?(nfroyd) → review+
Unfortunately I have no way of looking into this as we don't have stack traces. I suppose I could just remove the assertion...
Flags: needinfo?(erahm)
Don't have stack traces for what? I see a crash stack under TestGonkCameraHardware::TestGonkCameraHardware at the link in comment 62. Near the WARNING - PROCESS-CRASH.
(In reply to Andrew McCreight [:mccr8] from comment #64)
> Don't have stack traces for what? I see a crash stack under
> TestGonkCameraHardware::TestGonkCameraHardware at the link in comment 62.
> Near the WARNING - PROCESS-CRASH.

Aha, then I can fix this. That's nowhere near the actual assert though...
sorry had to back this out again for test failures like https://treeherder.mozilla.org/logviewer.html#?job_id=10343036&repo=mozilla-inbound
Flags: needinfo?(erahm)
(In reply to Carsten Book [:Tomcat] from comment #68)
> sorry had to back this out again for test failures like
> https://treeherder.mozilla.org/logviewer.html#?job_id=10343036&repo=mozilla-
> inbound

jesup, any thoughts on this? It looks like it's all WebRTC spew (cursory glance implicates CSFLog). Do we enable this log during tests?
Flags: needinfo?(erahm) → needinfo?(rjesup)
Attachment #8614112 - Flags: review?(rjesup)
Also of note, by my count about 2/3rds of the entire file (by bytes) is lines that look like:
WARNING: NS_ENSURE_TRUE(node) failed: file /builds/slave/m-in-l64-d-0000000000000000000/build/src/layout/base/nsDocumentViewer.cpp, line 3538

That's about 19.7MB. Without the logging patch, the total file size is about 33.3MB. With the logging patch, the total file size is about 52MB. So, clearly the logging changes are causing a huge increase, but the document viewer warning also seems bad. I'll file a separate bug on that.
I filed bug 1170642 for the nsDocumentViewer log spammage.
Depends on: 1170642
Ideally, you'd go through more of the logs and see what the effect of total log size on them is compared to trunk. Some other log might be going from 40% of max size to 95% of max size, say, leaving an impending disaster. I can help with some of this if you'd like.
The 'signaling' log module needs to be reduced to '3'. Previously '5' mapped to 'CSF_LOG_INFO', that value is now '3'.
Attachment #8614732 - Flags: review?(rjesup)
Attachment #8614112 - Attachment is obsolete: true
Attachment #8614112 - Flags: review?(rjesup)
(In reply to Andrew McCreight [:mccr8] from comment #75)
> Ideally, you'd go through more of the logs and see what the effect of total
> log size on them is compared to trunk. Some other log might be going from
> 40% of max size to 95% of max size, say, leaving an impending disaster. I
> can help with some of this if you'd like.

With the fix in bug 1170642 and the updated attachment 8614732 [details] [diff] [review] I think we're probably good, but if you'd like we can take a look at the results from:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=eebe5215c542
Attachment #8614732 - Flags: review?(rjesup) → review+
Depends on: 1171663
Blocks: 659285
Flags: needinfo?(rjesup)
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Keywords: leave-open
Resolution: --- → FIXED
Blocks: 1354222
You need to log in before you can comment on or make changes to this bug.