1223222 - Remove usage of PR_NewLogModule in mozilla LogModule code

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Eric Rahm [:erahm]]

Internally mozilla's log module codes uses |PR_NewLogModule| [1] for its env var parsing logic [2]. If we move the logic into LogModuleManager we can avoid this dependency and also avoid TSan issues due to |PR_NewLogModule| having thread-safety issues (see bug, bug).

We can also avoid parsing the env vars every time a log module is created by caching the mappings after parsing once.

This should be a reasonably straight-forward task although we'll probably want to add a test to make sure the parsing logic has parity with NSPR.

[1] https://dxr.mozilla.org/mozilla-central/rev/e2a910c048dc82fc3be53475f18e7f81f03e377b/xpcom/base/Logging.cpp#55
[2] https://dxr.mozilla.org/mozilla-central/rev/e2a910c048dc82fc3be53475f18e7f81f03e377b/nsprpub/pr/src/io/prlog.c#310-346

Comment 1

[Eric Rahm [:erahm]]

Attachment: Remove usage of PR_NewLogModule in mozilla LogModule code

Adds basic handling of the NSPR log module env var format to LogModuleManager's
initialization. This removes the need to create a PR_LogModule for each
mozilla::LogModule.

Comment 2

[Nathan Froyd [:froydnj]]

Comment on attachment 8700860 [details] [diff] [review]
Remove usage of PR_NewLogModule in mozilla LogModule code

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

To be clear, this is just about removing the parsing that NSPR would do for us in PR_NewLogModule?  We're not actually using Mozilla logging facilities yet?

::: xpcom/base/Logging.cpp
@@ +57,5 @@
> +
> +      // Format: LOG_MODULES=Foo:2 Bar Baz:5
> +      while (parser.ReadWord(moduleName)) {
> +        // Next should be :<level>, default to Error if not provided.
> +        LogLevel logLevel = LogLevel::Error;

The format of NSPR_LOG_MODULES is somewhat richer:

https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSPR/Reference/NSPR_LOG_MODULES

(I'm not sure we can support "all", but other things we ought to be able to support.)

Tests for the parsing would be *lovely*.

Comment 3

[Eric Rahm [:erahm]]

(In reply to Nathan Froyd [:froydnj] from comment #2)
> Comment on attachment 8700860 [details] [diff] [review]
> Remove usage of PR_NewLogModule in mozilla LogModule code
> 
> Review of attachment 8700860 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> To be clear, this is just about removing the parsing that NSPR would do for
> us in PR_NewLogModule?  We're not actually using Mozilla logging facilities
> yet?
> 
> ::: xpcom/base/Logging.cpp
> @@ +57,5 @@
> > +
> > +      // Format: LOG_MODULES=Foo:2 Bar Baz:5
> > +      while (parser.ReadWord(moduleName)) {
> > +        // Next should be :<level>, default to Error if not provided.
> > +        LogLevel logLevel = LogLevel::Error;
> 
> The format of NSPR_LOG_MODULES is somewhat richer:
> 
> https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSPR/Reference/
> NSPR_LOG_MODULES
> 
> (I'm not sure we can support "all", but other things we ought to be able to
> support.)

I'm not convinced we need/want to support all of the NSPR options (none are used w/in our codebase at least). Either way, there's bug 1174972 which would cover handling timestamp, sync, etc. As-is if you specify those options they'll still be handled by NSPR.

> Tests for the parsing would be *lovely*.

Good point, I'll add a second patch w/ tests.

Comment 4

[Nathan Froyd [:froydnj]]

(In reply to Eric Rahm [:erahm] from comment #3)
> (In reply to Nathan Froyd [:froydnj] from comment #2)
> > The format of NSPR_LOG_MODULES is somewhat richer:
> > 
> > https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSPR/Reference/
> > NSPR_LOG_MODULES
> > 
> > (I'm not sure we can support "all", but other things we ought to be able to
> > support.)
> 
> I'm not convinced we need/want to support all of the NSPR options (none are
> used w/in our codebase at least). Either way, there's bug 1174972 which
> would cover handling timestamp, sync, etc. As-is if you specify those
> options they'll still be handled by NSPR.

Sure.  I should have been clearer: I don't think we have to take action on all the options in this bug.  But I think we do have to at least parse arbitrary NSPR_LOG_MODULE syntax and it's not immediately clear that this code handles something like:

NSPR_LOG_MODULES=timestamp,mozStorage:5 (from the MDN page)

Unless ReadWord is doing something super-clever with the comma there.

> > Tests for the parsing would be *lovely*.
> 
> Good point, I'll add a second patch w/ tests.

Thank you!

Comment 5

[Eric Rahm [:erahm]]

Attachment: Part 1: Add NSPRLogModulesParser

Adds basic parser for handling of the NSPR log module env var format.

Comment 6

[Eric Rahm [:erahm]]

Attachment: Part 2: Add tests for NSPRLogModulesParser

Comment 7

[Eric Rahm [:erahm]]

Attachment: Part 3: Remove usage of PR_NewLogModule in mozilla LogModule code

Comment 8

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=632b6a50655a

Comment 9

[Nathan Froyd [:froydnj]]

Comment on attachment 8701607 [details] [diff] [review]
Part 1: Add NSPRLogModulesParser

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

::: xpcom/base/NSPRLogModulesParser.cpp
@@ +34,5 @@
> +        logLevel = ToLogLevel(level);
> +      }
> +    }
> +
> +    aCallback(moduleName.get(), logLevel);

Doing this unconditionally doesn't seem right, as if a level wasn't specified in the aLogModules, that's a syntax error, not a request for a particular log module with an Error logging level.  Seems like we should skip it in that case, maybe passing something special to the callback to let it know an error occurred, or letting the callback return a boolean to indicate whether we should keep going.  I think NSPR stops entirely if a level isn't specified.

::: xpcom/base/moz.build
@@ +84,5 @@
>      'JSObjectHolder.h',
>      'LinuxUtils.h',
>      'Logging.h',
>      'nsMemoryInfoDumper.h',
> +    'NSPRLogModulesParser.h',

Are we exporting this just so gtests can use it?  I think we should just use LOCAL_INCLUDES in the gtest moz.build...

Comment 10

[Nathan Froyd [:froydnj]]

Comment on attachment 8701608 [details] [diff] [review]
Part 2: Add tests for NSPRLogModulesParser

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

::: xpcom/tests/gtest/TestNSPRLogModulesParser.cpp
@@ +20,5 @@
> +  mozilla::NSPRLogModulesParser("Foo",
> +      [](const char* aName, mozilla::LogLevel aLevel) {
> +        EXPECT_STREQ("Foo", aName);
> +        EXPECT_EQ(mozilla::LogLevel::Error, aLevel);
> +      });

Probably should have a callbackInvoked thingie here.

@@ +25,5 @@
> +}
> +
> +TEST(NSPRLogModulesParser, LevelSpecified)
> +{
> +  mozilla::NSPRLogModulesParser("Foo:3",

...and for these tests too.

@@ +31,5 @@
> +        EXPECT_STREQ("Foo", aName);
> +        EXPECT_EQ(mozilla::LogLevel::Info, aLevel);
> +     });
> +
> +  // Too high.

And a too low test as well.  And one for each level if you want to be paranoid.  (I like paranoid test writers.)

@@ +44,5 @@
> +{
> +  std::pair<const char*, mozilla::LogLevel> expected[] = {
> +    { "Foo", mozilla::LogLevel::Info },
> +    { "Bar", mozilla::LogLevel::Error },
> +    { "Baz", mozilla::LogLevel::Warning },

This bit can't be right, because one can have (citing https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSPR/Reference/NSPR_LOG_MODULES ):

export NSPR_LOG_MODULES=timestamp,mozStorage:5

for the mozStorage log to have timestamps added to it.  I guess your thinking is that we just don't care about any of the options now, so we shouldn't even try to parse them?

@@ +52,5 @@
> +  auto* currTest = expected;
> +
> +  size_t count = 0;
> +  mozilla::NSPRLogModulesParser("Foo:3, Bar,Baz:2,    Qux:5",
> +      [&](const char* aName, mozilla::LogLevel aLevel) mutable {

Should assert that we haven't walked off the edge of |expected| prior to the checks below.

::: xpcom/tests/gtest/TestThreadPool.cpp
@@ +11,5 @@
>  #include "nsIThreadPool.h"
>  #include "nsComponentManagerUtils.h"
>  #include "nsCOMPtr.h"
>  #include "nsIRunnable.h"
> +#include "nsThreadUtils.h"

What are the changes in this file for?

Comment 11

[Nathan Froyd [:froydnj]]

Comment on attachment 8701609 [details] [diff] [review]
Part 3: Remove usage of PR_NewLogModule in mozilla LogModule code

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

::: xpcom/base/Logging.cpp
@@ +51,5 @@
> +  void Init()
> +  {
> +    const char* modules = PR_GetEnv("NSPR_LOG_MODULES");
> +    NSPRLogModulesParser(modules, [] (const char* aName, LogLevel aLevel) {
> +        LogModule::Get(aName)->SetLevel(aLevel);

We need to support the special "all" name here too...though it's not obvious to me that specifying "all" here actually works, because it appears that you need to get all your logging modules setup prior to parsing the environment variable in that case.  Maybe we should explicitly comment that we don't care about the "all" module?

Comment 12

[Nathan Froyd [:froydnj]]

I should clarify comment 10 and comment 4: I think it's OK to ignore the log-specific options NSPR_LOG_MODULES permits.  I don't think it's OK to treat those options as a separate log altogether.

Comment 13

[Eric Rahm [:erahm]]

(In reply to Nathan Froyd [:froydnj] from comment #9)
> Comment on attachment 8701607 [details] [diff] [review]
> Part 1: Add NSPRLogModulesParser
> 
> Review of attachment 8701607 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: xpcom/base/NSPRLogModulesParser.cpp
> @@ +34,5 @@
> > +        logLevel = ToLogLevel(level);
> > +      }
> > +    }
> > +
> > +    aCallback(moduleName.get(), logLevel);
> 
> Doing this unconditionally doesn't seem right, as if a level wasn't
> specified in the aLogModules, that's a syntax error, not a request for a
> particular log module with an Error logging level.

Yeah I thought about this, it's a weird distinction. No level (and colon) means Error, colon and level means whatever level, colon and no level is probably a typo, but clearly there's intent to enable the log. Setting it to the default log level (Error) seems reasonable in this case.

> Seems like we should
> skip it in that case, maybe passing something special to the callback to let
> it know an error occurred, or letting the callback return a boolean to
> indicate whether we should keep going.

I guess we could do that, but as the only user of this I'm just going to return true from the function.

> I think NSPR stops entirely if a level isn't specified.

Yes, I would argue this is an improvement over NSPR.

> ::: xpcom/base/moz.build
> @@ +84,5 @@
> >      'JSObjectHolder.h',
> >      'LinuxUtils.h',
> >      'Logging.h',
> >      'nsMemoryInfoDumper.h',
> > +    'NSPRLogModulesParser.h',
> 
> Are we exporting this just so gtests can use it?  I think we should just use
> LOCAL_INCLUDES in the gtest moz.build...

Yes, just for gtests. I'll move it.

Comment 14

[Eric Rahm [:erahm]]

Thanks for the review, I'll update the tests per your recommendations.

(In reply to Nathan Froyd [:froydnj] from comment #10)
> Comment on attachment 8701608 [details] [diff] [review]
> Part 2: Add tests for NSPRLogModulesParser
> 
> Review of attachment 8701608 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: xpcom/tests/gtest/TestNSPRLogModulesParser.cpp
> @@ +20,5 @@
> > +  mozilla::NSPRLogModulesParser("Foo",
> > +      [](const char* aName, mozilla::LogLevel aLevel) {
> > +        EXPECT_STREQ("Foo", aName);
> > +        EXPECT_EQ(mozilla::LogLevel::Error, aLevel);
> > +      });
> 
> Probably should have a callbackInvoked thingie here.
> 
> @@ +25,5 @@
> > +}
> > +
> > +TEST(NSPRLogModulesParser, LevelSpecified)
> > +{
> > +  mozilla::NSPRLogModulesParser("Foo:3",
> 
> ...and for these tests too.
> 
> @@ +31,5 @@
> > +        EXPECT_STREQ("Foo", aName);
> > +        EXPECT_EQ(mozilla::LogLevel::Info, aLevel);
> > +     });
> > +
> > +  // Too high.
> 
> And a too low test as well.  And one for each level if you want to be
> paranoid.  (I like paranoid test writers.)

Hmm this interesting. I think mozilla::Tokenizer isn't going to properly parse the negative value. I'll look into a workaround.

> @@ +44,5 @@
> > +{
> > +  std::pair<const char*, mozilla::LogLevel> expected[] = {
> > +    { "Foo", mozilla::LogLevel::Info },
> > +    { "Bar", mozilla::LogLevel::Error },
> > +    { "Baz", mozilla::LogLevel::Warning },
> 
> This bit can't be right, because one can have (citing
> https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSPR/Reference/
> NSPR_LOG_MODULES ):
> 
> export NSPR_LOG_MODULES=timestamp,mozStorage:5
> 
> for the mozStorage log to have timestamps added to it.  I guess your
> thinking is that we just don't care about any of the options now, so we
> shouldn't even try to parse them?

Correct, but I agree that adding code to ignore them properly is reasonable.

> @@ +52,5 @@
> > +  auto* currTest = expected;
> > +
> > +  size_t count = 0;
> > +  mozilla::NSPRLogModulesParser("Foo:3, Bar,Baz:2,    Qux:5",
> > +      [&](const char* aName, mozilla::LogLevel aLevel) mutable {
> 
> Should assert that we haven't walked off the edge of |expected| prior to the
> checks below.
> 
> ::: xpcom/tests/gtest/TestThreadPool.cpp
> @@ +11,5 @@
> >  #include "nsIThreadPool.h"
> >  #include "nsComponentManagerUtils.h"
> >  #include "nsCOMPtr.h"
> >  #include "nsIRunnable.h"
> > +#include "nsThreadUtils.h"
> 
> What are the changes in this file for?

It no longer compiled after adding a new test file. I assume it was some unified compilation weirdness and added the stuff it was missing.

Comment 15

[Nathan Froyd [:froydnj]]

(In reply to Eric Rahm [:erahm] from comment #13)
> (In reply to Nathan Froyd [:froydnj] from comment #9)
> > Comment on attachment 8701607 [details] [diff] [review]
> > Part 1: Add NSPRLogModulesParser
> > 
> > Review of attachment 8701607 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > ::: xpcom/base/NSPRLogModulesParser.cpp
> > @@ +34,5 @@
> > > +        logLevel = ToLogLevel(level);
> > > +      }
> > > +    }
> > > +
> > > +    aCallback(moduleName.get(), logLevel);
> > 
> > Doing this unconditionally doesn't seem right, as if a level wasn't
> > specified in the aLogModules, that's a syntax error, not a request for a
> > particular log module with an Error logging level.
> 
> Yeah I thought about this, it's a weird distinction. No level (and colon)
> means Error, colon and level means whatever level, colon and no level is
> probably a typo, but clearly there's intent to enable the log. Setting it to
> the default log level (Error) seems reasonable in this case.
> 
> > I think NSPR stops entirely if a level isn't specified.
> 
> Yes, I would argue this is an improvement over NSPR.

That's fair, though I'm not sure how many logs we really have at LogLevel::Error.  Let's go with it, without the boolean return value from the callback; please document it as a deviation from NSPR, and we can see what feedback is like, if any.

Comment 16

[Eric Rahm [:erahm]]

Attachment: Part 1: Add NSPRLogModulesParser

Updates per code review. Adds handling of negative values, ignores NSPR log
options.

Comment 17

[Eric Rahm [:erahm]]

Attachment: Part 2: Add tests for NSPRLogModulesParser

Code review updates. Adds checks for |callbackInvoked|, adds test for reserved
keywords, expands levelSpecified tests to cover full valid range and negative
values, makes sure we don't pass the end of the expected values array.

Comment 18

[Nathan Froyd [:froydnj]]

Comment on attachment 8703930 [details] [diff] [review]
Part 2: Add tests for NSPRLogModulesParser

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

::: xpcom/tests/gtest/TestNSPRLogModulesParser.cpp
@@ +47,5 @@
> +  };
> +
> +  auto* currTest = expected;
> +
> +  for (size_t i = 0; i < PR_ARRAY_SIZE(expected); i++) {

MOZ_ARRAY_SIZE, please.

@@ +94,5 @@
> +
> +  size_t count = 0;
> +  mozilla::NSPRLogModulesParser("timestamp,Foo:3, Bar,Baz:2,    Qux:5",
> +      [&](const char* aName, mozilla::LogLevel aLevel) mutable {
> +        ASSERT_LT(count, size_t(4));

MOZ_ARRAY_LENGTH(expected) instead of the bare 4?

@@ +101,5 @@
> +        currTest++;
> +        count++;
> +     });
> +
> +  EXPECT_EQ(size_t(4), count);

This too?

Comment 19

[Nathan Froyd [:froydnj]]

Comment on attachment 8703929 [details] [diff] [review]
Part 1: Add NSPRLogModulesParser

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

::: xpcom/base/NSPRLogModulesParser.cpp
@@ +51,5 @@
> +      }
> +    }
> +
> +    // NSPR reserves a few modules names for logging options. We just skip
> +    // those entries here.

This is IMHO an unusual way to handle it, but OK.

Comment 20

[Eric Rahm [:erahm]]

(In reply to Nathan Froyd [:froydnj] from comment #19)
> Comment on attachment 8703929 [details] [diff] [review]
> Part 1: Add NSPRLogModulesParser
> 
> Review of attachment 8703929 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: xpcom/base/NSPRLogModulesParser.cpp
> @@ +51,5 @@
> > +      }
> > +    }
> > +
> > +    // NSPR reserves a few modules names for logging options. We just skip
> > +    // those entries here.
> 
> This is IMHO an unusual way to handle it, but OK.

What would the 'usual' way be? Filtering in the callback?

Comment 21

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=7af0cda25966

Comment 22

[Eric Rahm [:erahm]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ef2ab7d80dd1bb5013d6ec38e7584c2011756d65
Bug 1223222 - Part 1: Add NSPRLogModulesParser. r=froydnj

https://hg.mozilla.org/integration/mozilla-inbound/rev/498fec1562198ca7d7536528f6b8ecca96426c56
Bug 1223222 - Part 2: Add tests for NSPRLogModulesParser. r=froydnj

https://hg.mozilla.org/integration/mozilla-inbound/rev/30709eb90d8765f5afbdcc47b6df5f21f0d93af0
Bug 1223222 - Part 3: Remove usage of PR_NewLogModule in mozilla LogModule code. r=froydnj

Comment 23

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/ef2ab7d80dd1
https://hg.mozilla.org/mozilla-central/rev/498fec156219
https://hg.mozilla.org/mozilla-central/rev/30709eb90d87