Closed Bug 1174972 Opened 4 years ago Closed 4 years ago

Switch out mozilla logging backend

Categories

(Core :: XPCOM, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla46
Tracking Status
firefox41 --- affected
firefox46 --- fixed
thunderbird_esr45 --- wontfix

People

(Reporter: erahm, Assigned: erahm)

References

(Blocks 1 open bug)

Details

Attachments

(1 file, 3 obsolete files)

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>
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!
Attachment #8703935 - Flags: feedback?(nfroyd)
Assignee: nobody → erahm
Status: NEW → ASSIGNED
Alright, lets just go for a review. I updated to add file support and the log
module name in the outupt.
Attachment #8704812 - Flags: review?(nfroyd)
Attachment #8703935 - Attachment is obsolete: true
Attachment #8703935 - Flags: feedback?(nfroyd)
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.
Attachment #8704812 - Flags: review?(nfroyd) → feedback+
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.
Attachment #8705352 - Flags: review?(nfroyd)
Attachment #8704812 - Attachment is obsolete: true
(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 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?
Attachment #8705352 - Flags: review?(nfroyd) → feedback+
(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.
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".
Attachment #8705886 - Flags: review?(nfroyd)
Attachment #8705886 - Flags: review?(jduell.mcbugs)
Attachment #8705886 - Flags: review?(docfaraday)
Attachment #8705352 - Attachment is obsolete: true
Attachment #8705886 - Flags: review?(docfaraday) → review+
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"
Attachment #8705886 - Flags: review?(nfroyd) → review+
Attachment #8705886 - Flags: review?(jduell.mcbugs) → review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/3e168e5a04bf8e96719a8c56611271902b0cb226
Bug 1174972 - Add basic mozilla logging backend. r=froydnj,r=bwc,r=jduell
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
"
https://hg.mozilla.org/integration/mozilla-inbound/rev/2aee7dd852a26df0222160c6220adc68014cb4ef
Bug 1174972 - Add basic mozilla logging backend. r=froydnj,r=bwc,r=jduell
Blocks: 1239212
https://hg.mozilla.org/mozilla-central/rev/2aee7dd852a2
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla46
Blocks: 1239686
Depends on: 1241301
Depends on: 1242151
Any chance this can/will be applied for Thunderbird?
(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.
(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.
You need to log in before you can comment on or make changes to this bug.