237326 - PR_NewLogModule is not threadsafe

Status: NEW

(NSPR :: NSPR, defect)

Description

[timeless]

PR_NewLogModule makes an unlocked change to the static |logModules|.

If two threads call PR_NewLogModule, then a log module could be lost.

Comment 1

[timeless]

Attachment: make threadsafe and add new api PR_SetLogModuleLevel

Our qa want to be able to dynamically change the logging level. This additional
api allows for that.

Comment 2

[Wan-Teh Chang]

Comment on attachment 143765 [details] [diff] [review]
make threadsafe and add new api PR_SetLogModuleLevel

You don't need to test _pr_logLock.  It is not NULL
after NSPR is initialized.

Use the _PR_LOCK_LOG() and _PR_UNLOCK_LOG() macros.

PR_SetLogModuleLevel is not thread-safe.  This is
probably okay, especially if you can ensure that
the log module in question is not being used when
you change its logging level.

Comment 3

[timeless]

Comment on attachment 143765 [details] [diff] [review]
make threadsafe and add new api PR_SetLogModuleLevel

> You don't need to test _pr_logLock. 

That's not correct.

> It is not NULL after NSPR is initialized.

That's true, but not helpful, because PR_NewLogModule is called *while* NSPR is 
being initialized and before the call to _PR_InitLog which would initialize 
_pr_logLock. 

In http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/misc/prinit.c#167

167 static void _PR_InitStuff(void)
168 {
170     if (_pr_initialized) return;
171     _pr_initialized = PR_TRUE;
...
this block:
182     _pr_clock_lm = PR_NewLogModule("clock");
...
192     _pr_shma_lm = PR_NewLogModule("shma");
...
preceeds:
237     _PR_InitLog();

And
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/io/prlog.c#189
189 void _PR_InitLog(void)
190 {
191     char *ev;
192 
193     _pr_logLock = PR_NewLock();

Is the thing that sets _pr_logLock.

Further, while some modules assert that they could create their lock, 
_PR_InitLog does not.
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/io/prfdcach.c#280

280     _pr_fd_cache.ml = PR_NewLock();
281     PR_ASSERT(NULL != _pr_fd_cache.ml);

http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/io/prlayer.c#742
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/md/mac/macsockotpt.c#129
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/md/unix/unix.c#2874
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/md/unix/uxproces.c#828
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/md/windows/ntio.c#910

There are even a few things which try to tolerate newlock failing:
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/io/prmwait.c#178
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/misc/pralarm.c#188
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/misc/prtpool.c#609
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/threads/prrwlock.c#161
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/threads/prsem.c#58

by far the most amusing is 
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/md/mac/macthr.c#297
which both asserts and then tolerates the failure (i can't figure out who 
releases its lock, perhaps it last forever...).

Comment 4

[timeless]

> PR_SetLogModuleLevel is not thread-safe.
Yeah, that was intentional, i didn't see any harm in skipping thread safety.

If someone decides to change the logging level on one thread while another 
thread may be logging, so be it, I can't guarantee the order of those two 
events, and no harm will come because of it.

Similarly, if someone has nothing better to do than to change the logging level 
from two threads at about the same time, then oh well.

I'm willing to add the locking if you feel it's worth it. In my case, I will 
probably have a single thread which makes all changes to the locking level, 
although I can't and won't guarantee which thread that is. And even if I have 
two threads which are able and willing to change the locking level, there will 
only be one active consumer (a user), and that consumer will only trigger a 
single method of changing the level, which will take a single path.

Comment 5

[timeless]

wtc: could you please review this?

Comment 6

[Wan-Teh Chang]

Comment on attachment 143765 [details] [diff] [review]
make threadsafe and add new api PR_SetLogModuleLevel

timeless, I have a question about this patch.

Why did you add the following for loop to the
PR_NewLog function?

>+    for (lm = logModules; lm; lm = lm->next)
>+        if (lm->name && !strcasecmp(lm->name, name))
>+            break;

Comment 7

[timeless]

just a note, prlog.h (from the beginning of time) says:
** One of these structures is created for each module that uses logging.
**    "name" is the name of the module
**    "level" is the debugging level selected for that module
*/
typedef struct PRLogModuleInfo
...

One ... for each.

to answer your question, that loop is what lets PR_SetLogModuleLevel work.

Imagine this behavior:
set NSPR_LOG_MODULES=test:1
./run-mozilla.sh ./loggingtest
logging test reads a file which tells it to set test's loglevel to 5
PRLogModuleInfo *test = PR_NewLogModule("test");
if (test)
  PR_SetLogModuleLevel(test, 5);
loggingtest encounters a command which causes it to create some object which
needs to do "test" logging. that module was not loaded until this point, so it
can't rely on itself having initialized its log module before someone changed
its log level to 5.
PRLogModuleInfo *myModule = PR_NewLogModule("test");
if (myModule)
  PR_LOG(myModule, PR_LOG_DEBUG, ("hello world"));
Without the change, PR_NewLogModule will /try to/ create a new log module and
initialize it with the default setting (level=1 from the environment).

Rare case, five callers call PR_NewLogModule("test") and some succeed, and one
fails (oom). The logging for "test" is now broken because some have a handle to
it and some don't. IMO, I shouldn't need to expose my own api to statically
share the log module.

A note on threadsafety of PR_SetLogModuleLevel. currently i just have a non
atomic read/write. The only concern is that someone is silly enough to call
PR_SetLogModuleLevel concurrently on multiple threads. There are no
performance/locking implications for threads calling PR_LOG.

If I can't guarantee uniqueness for a log module, then PR_SetLogModuleLevel
would have to iterate over the entire loglist and change each instance, plus it
would have to make a note to cause any new logs to be created with the right
level, and it would need to hold the logging lock while it does all of this so
that you don't have inconsistent logging or logmodule creation.

Comment 8

[Wan-Teh Chang]

timeless, if multiple callers call PR_NewLogModule("test"),
only one should succeed; the others shoud fail rather than
return a handle to the existing log module.

Your code should ensure that only one caller calls
PR_NewLogModule("test").

Comment 9

[timeless]

wtc: that's a significant departure from the current behavior of nspr logging.
Given that PR_LOG(null, 0, "") will crash, i don't think that enforcing the |one
log module per log name| 'rule' by returning null is a good idea.

That said, I can implement SetLogModuleLevel and NewLogModule to work as you
described.

Problems I know of:
1. I managed to crash with a .h staticly constructed log module
2. This would require mozilla to call PR_Cleanup() and PR_Cleanup would actually
have to clean up log modules (I consider both of these things to be good things,
but I don't think anyone else wants to do the work). Otherwise any module that
wanted to load in after xpcom restarted and get a log module would fail -- which
would make this a death sentence of sorts.

Comment 10

[timeless]

Attachment: Make PR_NewLogModule() return null if called twice for the same module name

alternate implementation per comment 8.

Comment 11

[Darin Fisher]

+NSPR_API(PRLogModuleLevel) PR_SetLogModuleLevel(const char *name,
+NSPR_API(PRLogModuleLevel) PR_SetLogModuleLevel(PRLogModuleInfo *lm, 

Are these signatures supposed to be different?  If we are going to provide the
ability to affect a module given only its name, then perhaps it makes better
sense to provide a module lookup function instead.  However, I'd rather we not
bloat NSPR logging with that kind of thing.  It just seems overkill.  Consumers
should always have a reference to their PRLogModuleInfo.

Isn't this PR_SetLogModuleLevel business drifting a bit from the subject of this
bug?

Comment 12

[Wan-Teh Chang]

timeless: let's continue to allow two log modules to
have the same name.

Your original proposal (attachment 143765 [details] [diff] [review]) passes
a PRLogModuleInfo* pointer to PRLogModuleLevel.  It
doesn't require log modules to have unique names.

Comment 13

[Wan-Teh Chang]

Attachment: wtc's proposed patch

This is what timeless proposed in his original patch,
with the following modifications:

1. I improved the comment in prlog.h a little bit.
timeless, does my comment explain correctly why
you want PR_SetLogModuleLevel to return the old
level?

2. I export the new function PR_SetLogModuleLevel
from the nspr4 shared library.

3. I removed the module name uniqueness test from
_PR_SetLogModuleLevel.	I added a comment explaining
why _pr_logLock may be NULL.  I lock _pr_logLock
only when it's absolutely necessary (when we are
accessing 'logModules').

Comment 14

[Wan-Teh Chang]

Comment on attachment 147759 [details] [diff] [review]
wtc's proposed patch

timeless, please review and test this patch.

Darin, please review this patch.

Comment 15

[Wan-Teh Chang]

Comment on attachment 147617 [details] [diff] [review]
Make PR_NewLogModule() return null if called twice for the same module name

Marked this patch obsolete.

Comment 16

[timeless]

Comment on attachment 147759 [details] [diff] [review]
wtc's proposed patch

The only reason I want Set to return the old level is because i didn't see a
need to have an extra Get method in nspr.

Note that your patch does not help me.

I need to be able to Get an existing module. I'm trying to write code which
manages logging levels of arbitrary log modules. The only thing that can do
that is nspr. Note that having duplicate log modules with the same name will
make writing a useful logging level manager impossible, it also makes fixing
bug 204201 (which is the alternative way to get a log module) impossible.

The reasons that I wrote NewLogModule to return the same module are:
1. the modules are owned by nspr, so callers are not allowed to delete them.
2. returning the same module means that i can set its logging level.
3. this saves creating another function GetLogModule.

>+** WARNING: this function is not thread-safe.  The same thread should
>+** make the PR_SetLogModuleLevel calls on a particular log module.

The warning is a bit silly. The only hazard is that a non current log level may
be returned or the log level that's set may not be the one that is live when
the function returns.

Comment 17

[Wan-Teh Chang]

timeless: your code should obtain a reference to the
PRLogModuleInfo in some way other than looking it up
by name.  Darin made the same point in comment 11.
Why is it hard to pass PRLogModuleInfo pointers to
your code?

If it's impossible to pass PRLogModuleInfo pointers
to your code, I think it is better to add this function:

void PR_SetLogModuleLevel(const char *name, PRLogModuleLevel level);

Note that it returns void and takes the module name
as input argument.  If there are multiple modules
by that name, the new level is applied to all of them.
(That is, we remove the break statement from the for
loop in your second patch.)

We must warn the users if a function is not thread-safe.
There are different ways to write the warning.  I chose
to simply describe a way to use the function without the
hazard.  We can certainly describe the hazard itself
instead as you suggested.

Comment 18

[timeless]

> If it's impossible to pass PRLogModuleInfo pointers to your code, I think it
is better to add this function:

It is. All I am is a manager module, I don't have access to any log modules. I
could create a log module each time (intentionally leaking) and then forcefully
traverse nspr's private data, but something tells me people wouldn't like that.

> void PR_SetLogModuleLevel(const char *name, PRLogModuleLevel level);

That's fine. But if you're going to do that, then I'd like a
PR_GetLogModuleLevel. My manager api needs to be able to show end users
(developers) what the current levels are.

Given that nspr owns the log modules, I don't see any reason for New to generate
duplicates, it's just more work for everyone and it results in extra 'leak'
footprint for seamonkey because it never calls PR_Cleanup which is responsible
for releasing the prlog modules.

Comment 19

[timeless]

ping.

Comment 20

[timeless]

wtc: ping

Comment 21

[David :Bienvenu]

*** Bug 257810 has been marked as a duplicate of this bug. ***

Comment 22

[David :Bienvenu]

We'd like to enable something like what timeless wants - some UI that allows the
user to dynamically change the log modules to turn on logging. We'd probably do
something like add a method to nsIMessenger or something that in turn pokes NSPR
logging. That would allow someone to add UI to mailnews that turns on or off
arbitrary logging, and then UI that would package up and e-mail the log file to
a help desk. But this UI would need to be able to specify the log module by
name, not by PRLogModuleInfo structs.

Comment 23

[timeless]

fwiw i have an xpcom component (service) which lets you twiddle arbitrary
modules, we use it here and it works fairly well, but i need something landed in
nspr (with known apis) before i can reasonably post the xpcom component.

Comment 24

[BugBot [:suhaib / :marco/ :calixte]]

The bug assignee is inactive on Bugzilla, so the assignee is being reset.