You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4cxx-user@logging.apache.org by Tomislav Petrović <t....@inet.hr> on 2008/02/18 13:53:19 UTC
log4cxx::LoggerPtr becoming NULL
I'm fresh user of log4cxx. Recently one of the larger projects
in firm landed into my lap which uses log4cxx extensively, and
crashes on customer site (our internal testing newer caught this :()
due to following:
I have a class which has private log4cxx::LoggerPtr.
In constructor it is initialized like:
MyClass()
: logger(log4cxx::Logger::getLogger("someName"))
{
...
}
Then it is used extensively in some other parts of code and in
destructor it is set to NULL.
Program crashes because at some point logger becomes NULL, actually
operator-> method called on logger returns NULL. Since LOG4CXX_DEBUG
macro does logger->isDebugEnabled() this crashes due to NULL pointer
exception.
My question is which method called external to my class can make logger
(actually its underlying pointer) become NULL?
I hope I managed to explain my problem, any help is appreciated.
Thanks in advance,
--
Tomy <t....@inet.hr>
Re: log4cxx::LoggerPtr becoming NULL
Posted by Tomislav Petrović <t....@inet.hr>.
Curt Arnold said on 18.2.2008 17:47:
>
> That should not happen unless other code intentionally bypasses the
> enforcement of the private visibility. log4cxx does not maintain any
> list of LoggerPtr's or push changes out to them. The only way that a
> LoggerPtr should become null would be if some code outside of log4cxx
> set it or if the LoggerPtr was destructed.
>
OK, a bit more info.
MyClass instances are being created and their method executed by many
simultaneous threads.
So effectively we might have log4cxx::Logger::getLogger("identicalName")
from many threads simultaneously.
Can the behavior we are experiencing be somehow related to the problems
described in https://issues.apache.org/jira/browse/LOGCXX-132 ???
When were issues described there fixed, we still might have them since
we are using relatively old version (1+ year old :( - company policy not
to update anything unless proven there is a problem in old version which
is fixed in new one).
--
Tomy <t....@inet.hr>
Re: log4cxx::LoggerPtr becoming NULL
Posted by Curt Arnold <ca...@apache.org>.
On Feb 19, 2008, at 5:08 AM, Tomislav Petrović wrote:
> Curt Arnold said on 19.2.2008 10:15:
>
> First of all, many many thanks for your prompt responses.
>
>> On Feb 19, 2008, at 2:07 AM, Tomislav Petrović wrote:
>>> Unfortunately it is not that simple :). MyClass instance is very
>>> much
>>> alive :(.
>>> Inside one of the MyClass methods, for example I have code like
>>> this:
>>>
>>> LOG4CXX_DEBUG(logger, "log something")
>>> simple statement (or few statements) which does not do anything
>>> with logger
>>> LOG4CXX_DEBUG(logger, "log something else")
>> Is "logger" a static class member, class member, or an local
>> variable? You said in your other message that would might be
>> calling Logger::getLogger() from many threads which would not be
>> the case if you were using a static class member.
>
> logger is a class member being initialized with Logger::getLogger()
> in some initialization method of class, this initialization method
> is called for each class instance once in separate thread so there
> is possibility that two instances have their initialization methods
> called
> simultaneously.
>
I don't see a mechanism for a fault in Logger::getLogger() to affect
an already initialized LoggerPtr. If you are initializing logger in
an initialization method per instance, then there is the possibility
that the initialization method has been skipped. You could move the
initialization back into the object constructor to make sure there is
not a path to attempt to use logger before it is initialized, though
it would be better to push it back even further and make it a static
member.
> So since we are using revision 474761 (sorry missed last 1 in first
> post), is it possible this is related to https://issues.apache.org/jira/browse/LOGCXX-132?
> In which revision where problems described there fixed?
According to the Subversion Commits page on the bug, the last commit
against the bug was rev 407850. So it looks like you have all the
LOGCXX-132 fixes.
>
>
>
>> Don't know how cooperative your client is, but having someone being
>> able to reproduce the problem is key to figuring out how to avoid
>> it. Some possible experiments would be:
>> 1. Attempt to substantially reduce or eliminate calls to
>> Logger::getLogger() on non-main threads and see if the problem goes
>> away.
>> 2. Update to SVN HEAD and see if the problem goes away.
>> 3. Fabricate a test case that mimics the logging behavior of the
>> application and attach to a bug report. If the code can run or
>> easily be ported to Linux, I could run it under helgrind to check
>> for synchronization issues. It would also be be useful to know:
>> does the code fail on the client's machine with your snapshot of
>> log4cxx and does it fail when built with the current head.
>
> Code fails on client machine with our snapshot (revision 474761).
>
> I'll think about all of those possibilities and see which I can try
> with the client, thanks.
>
Another possibility would be to change the definitions of the
LOG4CXX_level macros in logger.h et al to check for null-ness before
checked isEnabledFor. That is a design inherited from log4j and log4j
would throw a NPE if you attempted to log on a null logger. You'd
lose logging, if it was only a log4cxx issue, then that might be
acceptible.
If you are seeing in one straight code path the logger go from non-
null to null, perhaps another thread has deleted you in the interim.
I'd expect that if that happened, if you got past the logging
statement something else would quickly blow up
Re: log4cxx::LoggerPtr becoming NULL
Posted by Tomislav Petrović <t....@inet.hr>.
Curt Arnold said on 19.2.2008 10:15:
>
First of all, many many thanks for your prompt responses.
> On Feb 19, 2008, at 2:07 AM, Tomislav Petrović wrote:
>> Unfortunately it is not that simple :). MyClass instance is very much
>> alive :(.
>> Inside one of the MyClass methods, for example I have code like this:
>>
>> LOG4CXX_DEBUG(logger, "log something")
>> simple statement (or few statements) which does not do anything with
>> logger
>> LOG4CXX_DEBUG(logger, "log something else")
>
>
> Is "logger" a static class member, class member, or an local variable?
> You said in your other message that would might be calling
> Logger::getLogger() from many threads which would not be the case if you
> were using a static class member.
logger is a class member being initialized with Logger::getLogger() in
some initialization method of class, this initialization method is
called for each class instance once in separate thread so there is
possibility that two instances have their initialization methods called
simultaneously.
So since we are using revision 474761 (sorry missed last 1 in first
post), is it possible this is related to
https://issues.apache.org/jira/browse/LOGCXX-132? In which revision
where problems described there fixed?
>
> Don't know how cooperative your client is, but having someone being able
> to reproduce the problem is key to figuring out how to avoid it. Some
> possible experiments would be:
>
> 1. Attempt to substantially reduce or eliminate calls to
> Logger::getLogger() on non-main threads and see if the problem goes away.
> 2. Update to SVN HEAD and see if the problem goes away.
> 3. Fabricate a test case that mimics the logging behavior of the
> application and attach to a bug report. If the code can run or easily
> be ported to Linux, I could run it under helgrind to check for
> synchronization issues. It would also be be useful to know: does the
> code fail on the client's machine with your snapshot of log4cxx and does
> it fail when built with the current head.
>
Code fails on client machine with our snapshot (revision 474761).
I'll think about all of those possibilities and see which I can try with
the client, thanks.
--
Tomy <t....@inet.hr>
Re: log4cxx::LoggerPtr becoming NULL
Posted by Curt Arnold <ca...@apache.org>.
On Feb 19, 2008, at 2:07 AM, Tomislav Petrović wrote:
> Curt Arnold said on 18.2.2008 17:47:
>> That should not happen unless other code intentionally bypasses the
>> enforcement of the private visibility. log4cxx does not maintain
>> any list of LoggerPtr's or push changes out to them. The only way
>> that a LoggerPtr should become null would be if some code outside
>> of log4cxx set it or if the LoggerPtr was destructed.
>
> OK, thanks for the info.
>
>> I think it is more likely that an instance of MyClass is used after
>> destruction. Something like:
>> MyClass* instance = new MyClass();
>> delete instance;
>> instance->doSomething();
>> could trigger the issue.
>
> Unfortunately it is not that simple :). MyClass instance is very much
> alive :(.
> Inside one of the MyClass methods, for example I have code like this:
>
> LOG4CXX_DEBUG(logger, "log something")
> simple statement (or few statements) which does not do anything with
> logger
> LOG4CXX_DEBUG(logger, "log something else")
Is "logger" a static class member, class member, or an local
variable? You said in your other message that would might be calling
Logger::getLogger() from many threads which would not be the case if
you were using a static class member.
>
>
> And during its execution first LOG4CXX_DEBUG passes ok, and second
> one crashes. After examining crash dump and the dissasembly around
> statements when it crashed this happens (roughly speaking).
> Method operator-> is called on logger, it returns NULL and
> isDebugEnabled is called on this NULL and this crashes.
>
> As I said above what puzzles me is that first call to function with
> identical code (just the string logged is different) passes ok.
>
> Has anything similar been reported before against log4cxx since we
> are using older SVN trunk version (i think is it revision 47476)???
>
> A bit more info is that this doesn't happen on any of our testing
> systems but happens on customer production machine. The only thing
> this machine has and our testing machines don't is 8 (16 virtual
> ones) processors (our testing ones have two at the most - 4 virtual).
>
>> If you are running on Linux, I'd suggest running your application
>> under Valgrind and see if it reports anything suspicious. If other
>> platforms, then something like Purify or BoundsChecker might help
>> identify the problem.
>
> I'm on Windows, we have tried BoundsChecker, nothing suspicious
> except one memory leak has been discovered. :(
>
Don't know how cooperative your client is, but having someone being
able to reproduce the problem is key to figuring out how to avoid it.
Some possible experiments would be:
1. Attempt to substantially reduce or eliminate calls to
Logger::getLogger() on non-main threads and see if the problem goes
away.
2. Update to SVN HEAD and see if the problem goes away.
3. Fabricate a test case that mimics the logging behavior of the
application and attach to a bug report. If the code can run or easily
be ported to Linux, I could run it under helgrind to check for
synchronization issues. It would also be be useful to know: does the
code fail on the client's machine with your snapshot of log4cxx and
does it fail when built with the current head.
Re: log4cxx::LoggerPtr becoming NULL
Posted by Tomislav Petrović <t....@inet.hr>.
Curt Arnold said on 18.2.2008 17:47:
>
> That should not happen unless other code intentionally bypasses the
> enforcement of the private visibility. log4cxx does not maintain any
> list of LoggerPtr's or push changes out to them. The only way that a
> LoggerPtr should become null would be if some code outside of log4cxx
> set it or if the LoggerPtr was destructed.
OK, thanks for the info.
> I think it is more likely that an instance of MyClass is used after
> destruction. Something like:
>
> MyClass* instance = new MyClass();
> delete instance;
> instance->doSomething();
>
> could trigger the issue.
Unfortunately it is not that simple :). MyClass instance is very much
alive :(.
Inside one of the MyClass methods, for example I have code like this:
LOG4CXX_DEBUG(logger, "log something")
simple statement (or few statements) which does not do anything with logger
LOG4CXX_DEBUG(logger, "log something else")
And during its execution first LOG4CXX_DEBUG passes ok, and second one
crashes. After examining crash dump and the dissasembly around
statements when it crashed this happens (roughly speaking).
Method operator-> is called on logger, it returns NULL and
isDebugEnabled is called on this NULL and this crashes.
As I said above what puzzles me is that first call to function with
identical code (just the string logged is different) passes ok.
Has anything similar been reported before against log4cxx since we are
using older SVN trunk version (i think is it revision 47476)???
A bit more info is that this doesn't happen on any of our testing
systems but happens on customer production machine. The only thing this
machine has and our testing machines don't is 8 (16 virtual ones)
processors (our testing ones have two at the most - 4 virtual).
>
> If you are running on Linux, I'd suggest running your application under
> Valgrind and see if it reports anything suspicious. If other platforms,
> then something like Purify or BoundsChecker might help identify the
> problem.
>
I'm on Windows, we have tried BoundsChecker, nothing suspicious except
one memory leak has been discovered. :(
--
Tomy <t....@inet.hr>
Re: log4cxx::LoggerPtr becoming NULL
Posted by Curt Arnold <ca...@apache.org>.
On Feb 18, 2008, at 6:53 AM, Tomislav Petrović wrote:
> I'm fresh user of log4cxx. Recently one of the larger projects
> in firm landed into my lap which uses log4cxx extensively, and
> crashes on customer site (our internal testing newer caught this :()
> due to following:
>
> I have a class which has private log4cxx::LoggerPtr.
> In constructor it is initialized like:
> MyClass()
> : logger(log4cxx::Logger::getLogger("someName"))
> {
> ...
> }
>
> Then it is used extensively in some other parts of code and in
> destructor it is set to NULL.
>
> Program crashes because at some point logger becomes NULL, actually
> operator-> method called on logger returns NULL. Since LOG4CXX_DEBUG
> macro does logger->isDebugEnabled() this crashes due to NULL pointer
> exception.
>
> My question is which method called external to my class can make
> logger (actually its underlying pointer) become NULL?
>
That should not happen unless other code intentionally bypasses the
enforcement of the private visibility. log4cxx does not maintain any
list of LoggerPtr's or push changes out to them. The only way that a
LoggerPtr should become null would be if some code outside of log4cxx
set it or if the LoggerPtr was destructed.
> I hope I managed to explain my problem, any help is appreciated.
I think it is more likely that an instance of MyClass is used after
destruction. Something like:
MyClass* instance = new MyClass();
delete instance;
instance->doSomething();
could trigger the issue.
If you are running on Linux, I'd suggest running your application
under Valgrind and see if it reports anything suspicious. If other
platforms, then something like Purify or BoundsChecker might help
identify the problem.
Re: When will log4cxx 0.10 be released?
Posted by Curt Arnold <ca...@apache.org>.
On Feb 19, 2008, at 3:35 AM, Tomislav Petrović wrote:
> When will next version (I guess 0.10) of log4cxx be released?
>
I am hoping to get an initial release candidate out today. I'd expect
to come out with a second release candidate in a week or so after
having done a release for cpptasks, and polishing up some of the
documentation and fixing any minor issues that come out in testing.
At that point, I'd expect to call for a vote to accept one of the
release candidates as 0.10.0.
When will log4cxx 0.10 be released?
Posted by Tomislav Petrović <t....@inet.hr>.
When will next version (I guess 0.10) of log4cxx be released?
--
Tomy <t....@inet.hr>