1174972 - Switch out mozilla logging backend

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Eric Rahm [:erahm]]

Currently we piggy back on NSPR logging, it would be preferable to move away from this.

Initially we probably only need to support logging to stdout/stderr/files. As follow ups it would be great to support syslog (linux/BSD/OSX), logcat (Android/FxOS), OutputDebugString (Windows), and possibly Windows Event Tracing.

Also initially we'll want to use NSPR-style format strings (the format that PR_Log uses). Follow ups to use a more standard format would be great as well.

As far as how the output would look, it would be nice to have:
  - Process type - (parent, child, plugin, gmp)
  - process id
  - log level (?)
  - log name (?) - either full string or an abbreviation
  - thread id (?)

Initially I envision something like:
  <Log Level> [<Process Type>? <Process ID>] <log name> <message>

Of course the order and detail are up for discussion. As a follow up it would be great to allow the user to specify the format.

Currently by default, NSPR logging does the following:
  gibberish[hexcodegibberish] <message>

Where gibberish is apparently the thread_id (AFAICT they're just printing a pthread_t directly) and hexcodegiberish is the pointer to the PR_Thread object that is doing the logging.

If we look at prior art in our codebase, there's NS_DebugBreak (think NS_WARN_IF and friends) which does roughly:
  [<Process Type>? <Process ID>] <Log Level> <message>

By default logcat on FxOS is:
  <first char of level>/<log name>(<PID>): <message>

Default output syslog on my Ubuntu machine /var/log/syslog:
  <timestamp> <host> <process name>[<PID>]: <message>

Comment 1

[Eric Rahm [:erahm]]

Attachment: Add basic mozilla logging backend

Initial draft of swapping out the NSPR logging backend. Primarily looking for
feedback on the addition of mozilla::detail::log_print. This was the best way
I found for handling the fact that the third param for MOZ_LOG is
parenthisized.

Life is somewhat simplified as we can just use |fprintf_stderr| which takes
of using android logging functions on android, OutputDebugString on Windows
if a debugger is attached.

The format I chose is slightly different than NSPR. It adds a
first-char-of-log-level prefix and removes the crazy junk prefix that we
currently have. I'm open to suggestion on this as well.

The other piece that's not implemented yet is logging to a file. NSPR logging
does some somewhat weird stuff, I'm contemplating just fopen'ing the file and
calling it a day. Thoughts on this are most welcome!

Comment 2

[Eric Rahm [:erahm]]

Attachment: Add basic mozilla logging backend

Alright, lets just go for a review. I updated to add file support and the log
module name in the outupt.

Comment 3

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=1f3842e42638

Comment 4

[Nathan Froyd [:froydnj]]

Comment on attachment 8704812 [details] [diff] [review]
Add basic mozilla logging backend

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

Wow, we've come this far?  That's fantastic!  Some things to consider below.

::: xpcom/base/Logging.cpp
@@ +47,5 @@
> +      return "V";
> +    case LogLevel::Disabled:
> +    default:
> +      MOZ_ASSERT(false);
> +      return "";

Maybe MOZ_CRASH()?

@@ +57,5 @@
>  public:
>    LogModuleManager()
>      : mModulesLock("logmodules")
>      , mModules(kInitialModuleCount)
> +    , mOutFile(stderr)

I think nullptr is the more conventional value to use here.  We ought to just make this an RAII member, which I know we have wrappers for in the tree, but possibly not in a convenient place for Logging.cpp.

@@ +82,5 @@
>      });
> +
> +    const char* logFile = PR_GetEnv("NSPR_LOG_FILE");
> +    if (logFile && logFile[0]) {
> +      // TODO(ER): Add support for append mode.

I think we need support for append before landing this.  Or you could try canvassing dev-platform and see if anybody actually uses append mode (I'm sure someone does...)

@@ +114,5 @@
> +      // We may have maxed out, allocate a buffer instead.
> +      buffToWrite = PR_vsmprintf(aFmt, aArgs);
> +    }
> +
> +    // NSPR format - thread stuff + level

This seems like a misleading comment, as we don't actually print out any thread stuff, right?

We need support for timestamps before this lands.

Comment 5

[Eric Rahm [:erahm]]

Attachment: Add basic mozilla logging backend

This allows for the 'timestamp' and 'append' keywords to be used, handles appending, adds timestamps in the original NSPR format if requested, uses ScopedFile to hold the FILE*, and has an improved description of the output format. Also realized we need to strdup the module name as it might come from the NSPR_LOG_MODULES env str rather than a static string.

Comment 6

[Eric Rahm [:erahm]]

(In reply to Nathan Froyd [:froydnj] from comment #4)
> Comment on attachment 8704812 [details] [diff] [review]
> Add basic mozilla logging backend
> 
> Review of attachment 8704812 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Wow, we've come this far?  That's fantastic!  Some things to consider below.
> 
> ::: xpcom/base/Logging.cpp
> @@ +47,5 @@
> > +      return "V";
> > +    case LogLevel::Disabled:
> > +    default:
> > +      MOZ_ASSERT(false);
> > +      return "";
> 
> Maybe MOZ_CRASH()?

Updated locally.

> @@ +57,5 @@
> >  public:
> >    LogModuleManager()
> >      : mModulesLock("logmodules")
> >      , mModules(kInitialModuleCount)
> > +    , mOutFile(stderr)
> 
> I think nullptr is the more conventional value to use here.  We ought to
> just make this an RAII member, which I know we have wrappers for in the
> tree, but possibly not in a convenient place for Logging.cpp.

I can used ScopedFile I believe.

> @@ +82,5 @@
> >      });
> > +
> > +    const char* logFile = PR_GetEnv("NSPR_LOG_FILE");
> > +    if (logFile && logFile[0]) {
> > +      // TODO(ER): Add support for append mode.
> 
> I think we need support for append before landing this.  Or you could try
> canvassing dev-platform and see if anybody actually uses append mode (I'm
> sure someone does...)

Added support.
 
> @@ +114,5 @@
> > +      // We may have maxed out, allocate a buffer instead.
> > +      buffToWrite = PR_vsmprintf(aFmt, aArgs);
> > +    }
> > +
> > +    // NSPR format - thread stuff + level
> 
> This seems like a misleading comment, as we don't actually print out any
> thread stuff, right?

Comment updated (it was meant to be read "NSPR format minus thread stuff plus level").

> We need support for timestamps before this lands.

Added support.

Comment 7

[Nathan Froyd [:froydnj]]

Comment on attachment 8705352 [details] [diff] [review]
Add basic mozilla logging backend

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

::: xpcom/base/Logging.cpp
@@ +116,5 @@
> +    char buff[kBuffSize];
> +
> +    char* buffToWrite = buff;
> +
> +    // NB: For backwards compat we need to use the NSPR format string versions

Style nit: I think all comments are essentially NB:, so we don't need to include the prefix, and it makes possibly extensions of the comment in the future more tedious.

@@ +127,5 @@
> +
> +    FILE* out = mOutFile ? mOutFile : stderr;
> +
> +    // NB: This differs from the NSPR format in that we do not output the
> +    //     opaque system system specific thread pointer (ie pthead_t) cast

Nit: pthread_t.  And the NB: thing.

@@ +128,5 @@
> +    FILE* out = mOutFile ? mOutFile : stderr;
> +
> +    // NB: This differs from the NSPR format in that we do not output the
> +    //     opaque system system specific thread pointer (ie pthead_t) cast
> +    //     to a long and the address of the current PR_Thread as a prefix.

I think it's kind of a pain to have all the clutter the NSPR outputs, but I can see the advantage of knowing what thread you are logging from.  WDYT about just printing the PR_Thread address and being able to turn off the PR_Thread address printing with a special "module"?  That is at least less clutter than NSPR, with the ability to forgo it if you know you're not dealing with multithreaded code.

I can easily imagine folks getting upset about this omission if we go live with it.

::: xpcom/base/Logging.h
@@ +166,5 @@
> + * any better.
> + */
> +inline void log_print(const PRLogModuleInfo* aModule,
> +                      LogLevel aLevel,
> +                      const char* aFmt, ...) {

Let's not declare this...

@@ +183,5 @@
>  
> +#if !defined(MOZILLA_XPCOMRT_API)
> +inline void log_print(const LogModule* aModule,
> +                      LogLevel aLevel,
> +                      const char* aFmt, ...) {

...and this as inline functions; there's no reason to bloat up every log call with va_list handling and whatnot.  Let's make them out-of-line instead.  That also means we don't need to include prprf.h in this file, which is nice.

::: xpcom/base/NSPRLogModulesParser.cpp
@@ +15,2 @@
>    "bufsize",
>    "sync",

Re-reading the NSPR_LOG_MODULES documentation, it looks as though all of these are specified as "modules" of their own...perhaps they shouldn't be handled in the parser?

Comment 8

[Eric Rahm [:erahm]]

(In reply to Nathan Froyd [:froydnj] from comment #7)
> Comment on attachment 8705352 [details] [diff] [review]
> Add basic mozilla logging backend
> 
> Review of attachment 8705352 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: xpcom/base/Logging.cpp
> @@ +116,5 @@
> > +    char buff[kBuffSize];
> > +
> > +    char* buffToWrite = buff;
> > +
> > +    // NB: For backwards compat we need to use the NSPR format string versions
> 
> Style nit: I think all comments are essentially NB:, so we don't need to
> include the prefix, and it makes possibly extensions of the comment in the
> future more tedious.

I can remove it.

> @@ +127,5 @@
> > +
> > +    FILE* out = mOutFile ? mOutFile : stderr;
> > +
> > +    // NB: This differs from the NSPR format in that we do not output the
> > +    //     opaque system system specific thread pointer (ie pthead_t) cast
> 
> Nit: pthread_t.  And the NB: thing.

Will update.

> @@ +128,5 @@
> > +    FILE* out = mOutFile ? mOutFile : stderr;
> > +
> > +    // NB: This differs from the NSPR format in that we do not output the
> > +    //     opaque system system specific thread pointer (ie pthead_t) cast
> > +    //     to a long and the address of the current PR_Thread as a prefix.
> 
> I think it's kind of a pain to have all the clutter the NSPR outputs, but I
> can see the advantage of knowing what thread you are logging from.  WDYT
> about just printing the PR_Thread address and being able to turn off the
> PR_Thread address printing with a special "module"?  That is at least less
> clutter than NSPR, with the ability to forgo it if you know you're not
> dealing with multithreaded code.
> 
> I can easily imagine folks getting upset about this omission if we go live
> with it.

I find it completely useless unless you happen to have looked at the prlog.c code, that said njn seemed to like it too, so I'm willing to accept that I'm in the minority.

> ::: xpcom/base/Logging.h
> @@ +166,5 @@
> > + * any better.
> > + */
> > +inline void log_print(const PRLogModuleInfo* aModule,
> > +                      LogLevel aLevel,
> > +                      const char* aFmt, ...) {
> 
> Let's not declare this...
> 
> @@ +183,5 @@
> >  
> > +#if !defined(MOZILLA_XPCOMRT_API)
> > +inline void log_print(const LogModule* aModule,
> > +                      LogLevel aLevel,
> > +                      const char* aFmt, ...) {
> 
> ...and this as inline functions; there's no reason to bloat up every log
> call with va_list handling and whatnot.  Let's make them out-of-line
> instead.  That also means we don't need to include prprf.h in this file,
> which is nice.

For background: not inlining caused some weird build failures in webrtc and netwerk unit tests. It looks like this is b/c although they are using libxul we're not exporting the symbols they want. If they were mozilla gtests we wouldn't have to worry, but they aren't.

The current best, but not great, solution is to just add a fake logger, which I will do.

> ::: xpcom/base/NSPRLogModulesParser.cpp
> @@ +15,2 @@
> >    "bufsize",
> >    "sync",
> 
> Re-reading the NSPR_LOG_MODULES documentation, it looks as though all of
> these are specified as "modules" of their own...perhaps they shouldn't be
> handled in the parser?

Sure, I thought we discussed this already and put this in for a reason, but I'm fine just removing that logic.

Comment 9

[Eric Rahm [:erahm]]

Attachment: Add basic mozilla logging backend

Nathan - can you review the xpcom bits? I believe I've addressed all the CR comments.

Byron - Would you mind reviewing the signaling test changes? These were needed due to linking failures when building the webrtc tests due to our changes to how logging works.

Jason - Would you mind reviewing the netwerk test changes? I chose to just make them pass through to NSPR's PR_LogPrint in order to fix linking errors. This preserves the ability to log by setting NSPR_LOG_MODULES="Test:5".

Comment 10

[Nathan Froyd [:froydnj]]

Comment on attachment 8705886 [details] [diff] [review]
Add basic mozilla logging backend

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

Thank you for persevering with this!

::: xpcom/base/Logging.h
@@ +159,5 @@
>    return module && module->level >= static_cast<int>(level);
>  }
>  
> +/**
> + * A rather inneficient wrapper for PR_LogPrint that always allocates.

Nit: "inefficient"

Comment 11

[Eric Rahm [:erahm]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/3e168e5a04bf8e96719a8c56611271902b0cb226
Bug 1174972 - Add basic mozilla logging backend. r=froydnj,r=bwc,r=jduell

Comment 12

[Phil Ringnalda (:philor)]

Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/e87009320118 - at least, so far, Linux and Mulet agree, https://treeherder.mozilla.org/logviewer.html#?job_id=19620816&repo=mozilla-inbound "Logging.h:103:25: error: 'strdup' was not declared in this scope
"

Comment 13

[Pulsebot]

Backout:
https://hg.mozilla.org/integration/mozilla-inbound/rev/01e673858e34

Comment 14

[Eric Rahm [:erahm]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2aee7dd852a26df0222160c6220adc68014cb4ef
Bug 1174972 - Add basic mozilla logging backend. r=froydnj,r=bwc,r=jduell

Comment 15

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/2aee7dd852a2

Comment 16

[Charles]

Any chance this can/will be applied for Thunderbird?

Comment 17

[Wayne Mery (:wsmwk)]

(In reply to Charles from comment #16)
> Any chance this can/will be applied for Thunderbird?

1. This would never happen on esr because it involves strings. So why set the esr flag?
2. It should first be tested on Thunderbird to assess whether the current state is production quality for Thunderbird. Please test the nightly build using the viewabout addon to get access to about:networking
3. why post the same question in multiple bugs?
3.

Comment 18

[Charles]

(In reply to Wayne Mery (:wsmwk, NI for questions) from comment #17)
> (In reply to Charles from comment #16)
> > Any chance this can/will be applied for Thunderbird?
> 
> 1. This would never happen on esr because it involves strings. So why set
> the esr flag?

Because that was the only choice available for Thunderbird?

> 2. It should first be tested on Thunderbird to assess whether the current
> state is production quality for Thunderbird. Please test the nightly build
> using the viewabout addon to get access to about:networking

Thanks I'll do that.

> 3. why post the same question in multiple bugs?

To get some attention for something that would be extremely useful for troubleshooting TB issues?

Sorry if I offended you.