Menu
▾
▴
log4perl-devel
|
From: Tom M. <tme...@gm...> - 2010-11-16 20:39:24
|
I like the API Log::Log4perl provides, but using Log::Log4perl v1.28
I've encountered issues with the internal implementation that have been
very time consuming to resolve.
Most relate to the way Log4perl seems to store state in global or class
variables rather than in object or instance variables. This means that
unless you take extra steps to prevent it, library modules that call
upon Log4perl directly will stomp on the logger established by the
calling code.
This state mechanism also is incompatible with Class::Remote (a module
developed at Shopzilla for remote code execution, which apparently
hasn't been released to CPAN), as it attempts to serialize an object's
data and send it to the remote end.
Perhaps all this is a consequence of our use of easy_init(), though if
so, convenience methods shouldn't have the consequence of creating a
fragile system.
The general objectives I'd like to achieve are:
1. Ability to create a library module that can use Log4perl, such that
if the calling code makes no use of Log4perl, it logs independently with
locally specified defaults, but if the caller does use Log4perl, it
picks up the callers settings.
2. Fully serializable state.
Here's an example of an issue I ran into today. I had a block of code
being evaluated that contained an error. The eval() was followed by an
error check, which then called logdie() with $@. But post-evaluation,
logdie() or any other Log4perl method failed to produce any output,
resulting the program mysteriously exiting with no error.
A trace showed that $self->is_fatal(), as called by
Log::Log4perl::Logger->logdie(), which resolved to:
return sub { $return_token };
which apparently returned false, meaning that FATAL level logging is
disabled, which should never be the case.
The trigger for the problem turned out to be a 'use' call in the eval'ed
code that loaded a library which internally called easy_init() (yet
specifying the INFO logging level).
This seems broken that a library using normal Log4perl methods can trash
the logger in use by the calling code.
Is there a more correct way to be using the API to avoid this, or does
Log4perl need some internal refactoring?
-Tom
|
|
From: Mike S. <m...@pe...> - 2010-11-17 01:24:37
|
On Tue, 16 Nov 2010, Tom Metro wrote: > 1. Ability to create a library module that can use Log4perl, such that > if the calling code makes no use of Log4perl, it logs independently > with locally specified defaults, but if the caller does use Log4perl, > it picks up the callers settings. Hi Tom, the current Log4perl implementation assumes that the calling script initializes Log4perl and libraries don't. Libraries make use of Log4perl by issuing log statements, but they don't try to modify the inititalization. If Log4perl isn't initialized in the main program, all is quiet. > The trigger for the problem turned out to be a 'use' call in the eval'ed > code that loaded a library which internally called easy_init() (yet > specifying the INFO logging level). That's very confusing and should be avoided at all cost. > This seems broken that a library using normal Log4perl methods can trash > the logger in use by the calling code. That library wasn't using 'normal Log4perl methods', but was clobbering the settings. We discourage people from doing that, although we don't stop anyone shooting themselves in the foot (or putting up a module on CPAN that shoots everyone in the foot for that matter). But you're bringing up an interesting topic: What would be a good approach to allow a library to meddle with Log4perl's settings, in the absence or even presence of a previous initialization? Everything I've seen so far is just plain confusing to the end user. I'm open to ideas, however. -- Mike Mike Schilli m...@pe... |
|
From: Tom M. <tme...@gm...> - 2010-11-19 03:41:25
|
Mike Schilli wrote: >> The trigger for the problem turned out to be a 'use' call in the eval'ed >> code that loaded a library which internally called easy_init() (yet >> specifying the INFO logging level). > > That's very confusing and should be avoided at all cost. > We discourage people from doing that... You are correct. The man page does discourage initializing the logger in multiple places, and it was an oversight that this code did that. It came about because the $logger object doesn't actually convey the full state, so when serialized and passed to a remote method, the remote logging reverts to default logging settings. To work around that, a Log4perl subclass was created, with it's own init() that applies the application's stock preferences via a call to easy_init(), and then that subclass is invoked both from the main program and from the class that is executed remotely. (On a side note, I had to rewrite easy_init() in order to make it subclass friendly. We can discuss that further in a separate thread, if interested.) The presence of the Log4perl subclass in the project made it all too convenient to invoke Log4perl that way from a library. I've corrected the library to use Log::Log4perl->get_logger($class) to obtain its logger instead, and I've updated the documentation of our Log4perl subclass to warn against its use in all but the main program. (Most libraries in the project get their logger passed to them from the main code, and don't make use of categories.) I'm still puzzled why the original logger object was rendered useless (such that it wouldn't even log fatal messages). The call to easy_init() does reset the logger, but my code also configured it to INFO logging level. Did it reset the old logger and create a new object, which then only the library code saw, while the main code saw the reset logger? > That library wasn't using 'normal Log4perl methods'... I get your point, but I consider easy_init() to be a normal method. With Perl it is almost always possible to monkey with the private namespace of a module, but it suggests bad design if using the provided API makes it possible for one library to stomp on another. I assume that this practice of maintaining global state in Log4perl came about because it is convenient to be able to call get_logger() as a class method, rather than having the application pass an object around. But it seems that it would be way better if Log4perl was internally designed to store all state in instance variables, and leave it to the application developer to decide whether they want to pass around objects, or dedicate a global variable to it. > But you're bringing up an interesting topic: What would be a good > approach to allow a library to meddle with Log4perl's settings, in the > absence or even presence of a previous initialization? When I fixed the library code to use Log::Log4perl->get_logger($class), my first attempt was actually to pass a logger object to the library, and call $logger->get_logger($class), assuming get_logger($class) would clone $logger, set the category, and return a new logger. Instead it fails in Log::Log4perl->_new() when it tries to bless the already blessed object. Ultimately I want a method I can call from my libraries where I can pass in a $logger parameter. The method then looks to see if $logger is set to anything, and if it is, clones it, sets the category, and returns the object. If not, it creates a new logger object for that category, and applies the logger settings I've specified somewhere. And, either code path should have absolutely no impact on any existing logger objects in use elsewhere in the code. As mentioned above, we also have the need to capture the full state in the $logger object, so it can be serialized, and used remotely. -Tom |
|
From: Mike S. <m...@pe...> - 2010-11-28 05:42:22
|
On Thu, 18 Nov 2010, Tom Metro wrote: > It came about because the $logger object doesn't actually convey the > full state, so when serialized and passed to a remote method, the > remote logging reverts to default logging settings. Yeah, the way it's currently implemented, a logger is only meaningful within an initialized Log4perl-system, there's some system-global magic involved, and you cannot serialize a logger and plant it into another Log4perl-enabled system at runtime easily (yet). Can you explain more about what the use case is for serializing loggers and passing them to remote systems? What properties of the logger might be of interest to the remote system? Is the remote system running Log4perl with exactly the same appenders or different ones? > (On a side note, I had to rewrite easy_init() in order to make it > subclass friendly. We can discuss that further in a separate thread, > if interested.) Sure. > I assume that this practice of maintaining global state in Log4perl > came about because it is convenient to be able to call get_logger() as > a class method, rather than having the application pass an object > around. But it seems that it would be way better if Log4perl was > internally designed to store all state in instance variables, and > leave it to the application developer to decide whether they want to > pass around objects, or dedicate a global variable to it. Agreed. > When I fixed the library code to use > Log::Log4perl->get_logger($class), my first attempt was actually to > pass a logger object to the library, and call > $logger->get_logger($class), assuming get_logger($class) would clone > $logger, set the category, and return a new logger. Instead it fails > in Log::Log4perl->_new() when it tries to bless the already blessed > object. Yes, get_logger() is a class method, calling it by an object is not defined. We should have a better error message, though. > Ultimately I want a method I can call from my libraries where I can > pass in a $logger parameter. The method then looks to see if $logger > is set to anything, and if it is, clones it, sets the category, and > returns the object. Hmm, that's similar to how the class method is defined. If the logger for the category exists, you get a copy, if it isn't, you get a new instance. We could implement an object method that does what you've suggested, can you post some code to display how your class hierarchy looks like and how you call the metods of the derived class from your application? -- Mike Mike Schilli m...@pe... |
|
From: Tom M. <tme...@gm...> - 2011-01-26 08:19:26
|
Mike Schilli wrote:
> Tom Metro wrote:
>> It came about because the $logger object doesn't actually convey the
>> full state, so when serialized and passed to a remote method, the
>> remote logging reverts to default logging settings.
>
> Yeah, the way it's currently implemented, a logger is only meaningful
> within an initialized Log4perl-system, there's some system-global magic
> involved, and you cannot serialize a logger and plant it into
> another Log4perl-enabled system at runtime easily (yet).
>
> Can you explain more about what the use case is for serializing loggers
> and passing them to remote systems?
Sure. This is part of a parallel processing cluster. Class::Remote is
used to execute code on remote nodes of the cluster. I'd like to be able
to have a single configured logger object used for the controlling node
(local) and then be able to serialize it and pass it to a remote node so
it can log with the identical settings.
> What properties of the logger might be of interest to the remote
> system?
The better questions is what logger state information can't practically
be serialized?
> Is the remote system running Log4perl with exactly the same appenders
> or different ones?
In this case I know the answer is exactly the same - everything is
outputting to STDOUT. But generally speaking, I'm not sure I know what
you mean.
Are you asking whether the remote system has the same appender drivers
installed? Or are you asking whether the remote system will be logging
to identical paths?
I don't think as a module implementer you need to be concerned with
that. If the paths are not identical, then having "fixup" code on the
remote side will be an obvious requirement. And similarly, an
experienced developer will know better than to write to a network
mounted log file from multiple machines simultaneously.
>> I assume that this practice of maintaining global state in Log4perl
>> came about because it is convenient to be able to call get_logger() as
>> a class method, rather than having the application pass an object
>> around. But it seems that it would be way better if Log4perl was
>> internally designed to store all state in instance variables, and
>> leave it to the application developer to decide whether they want to
>> pass around objects, or dedicate a global variable to it.
>
> Agreed.
OK, so what can we do to start refactoring the code to have the more
desired architecture?
>> Ultimately I want a method I can call from my libraries where I can
>> pass in a $logger parameter. The method then looks to see if $logger
>> is set to anything, and if it is, clones it, sets the category, and
>> returns the object.
>
> Hmm, that's similar to how the class method is defined. If the logger
> for the category exists, you get a copy, if it isn't, you get a new
> instance. We could implement an object method that does what you've
> suggested, can you post some code to display how your class hierarchy
> looks like and how you call the metods of the derived class from your
> application?
Sure.
By illustration, here's a sticky situation I'm dealing with right now.
In the controller, I have code approximately like:
my $logger = Publisher::Logger->init;
...
my $parallel_agents = Parallel::Cluster->new({
agent_lib => 'Some::Agent::Class',
logger => $logger,
});
$parallel_agents->run();
This initializes a logger object, instantiates the parallel processing
system, passing in the logger object, which in turn will get passed to
the constructor of Some::Agent::Class, and kicks off the run.
Parallel::Cluster implements a map-reduce algorithm, where portions
(some instances of Some::Agent::Class) are executed locally on the
controlling node, while other portions (mapping) happen remotely via
Class::Remote.
If the agent code attempts to use $logger locally, it works as expected.
If they use it remotely, nothing gets output.
Looking at a dump of the $logger object shows little difference between
the working local version and the not working remote version:
local
Address: Publisher::Logger=HASH(0x41f9dc0)@15665
$logger = bless( {
'is_OFF' => sub { "DUMMY" },
'is_DEBUG' => sub { "DUMMY" },
'ERROR' => sub { "DUMMY" },
'is_INFO' => sub { "DUMMY" },
'layout' => undef,
'category' => 'main',
'is_TRACE' => sub { "DUMMY" },
'DEBUG' => $logger->{'ERROR'},
'is_ALL' => sub { "DUMMY" },
'additivity' => 1,
'TRACE' => sub { "DUMMY" },
'ALL' => $logger->{'TRACE'},
'is_FATAL' => sub { "DUMMY" },
'is_WARN' => sub { "DUMMY" },
'FATAL' => $logger->{'ERROR'},
'appender_names' => [
'app001'
],
'WARN' => $logger->{'ERROR'},
'INFO' => $logger->{'ERROR'},
'level' => 10000,
'num_appenders' => 1,
'OFF' => $logger->{'ERROR'},
'is_ERROR' => sub { "DUMMY" }
}, 'Publisher::Logger' );
remote
Address: Publisher::Logger=HASH(0x411caa0)@15673
$logger = bless( {
'is_OFF' => sub { "DUMMY" },
'is_DEBUG' => sub { "DUMMY" },
'ERROR' => sub { "DUMMY" },
'layout' => undef,
'is_INFO' => sub { "DUMMY" },
'category' => 'main',
'DEBUG' => $logger->{'ERROR'},
'is_TRACE' => sub { "DUMMY" },
'TRACE' => sub { "DUMMY" },
'additivity' => 1,
'is_ALL' => sub { "DUMMY" },
'ALL' => $logger->{'TRACE'},
'is_FATAL' => sub { "DUMMY" },
'is_WARN' => sub { "DUMMY" },
'INFO' => $logger->{'ERROR'},
'WARN' => $logger->{'ERROR'},
'appender_names' => [
'app001'
],
'FATAL' => $logger->{'ERROR'},
'level' => '10000',
'num_appenders' => 1,
'is_ERROR' => sub { "DUMMY" },
'OFF' => $logger->{'ERROR'}
}, 'Publisher::Logger' );
To compensate for this deficiency, I added code to the agent to
redundantly call Publisher::Logger->init, and this redundancy is
primarily why I spun off logger initialization to subclass of
Log::Log4perl::Logger.
However this then introduced a bug. The place in the agent class where
the logger gets initialized (in its constructor) is called both when the
agent is instantiated for local portions as well as remote portions. As
a result, it re-initalized the state of the local logger object, and as
I reported back in November when I ran across a similar bug I created,
it has the unexpected effect of killing all logged output in the local
process.
So I had to modify init() in my subclass to do:
# bail out and return the global logger object if already initialized
if ($Log::Log4perl::Logger::INITIALIZED) {
return $class->get_logger($caller_class);
}
And that fixed it.
But weighing the pros and cons...
Current scheme:
Pro: have the convenience of calling $class->get_logger() anywhere to
get a logger;
Con: all other behavior is less intuitive; loggers in the same memory
space can interact and library code, if not well behaved, can kill your
logger object; you can't serialize a logger object.
A revised scheme:
Pro: none of the cons above;
Con: you have to handle passing around your own $logger object, or
setting a global.
I'll take the latter any day.
-Tom
|
×
Want the latest updates on software, tech news, and AI?
Get latest updates about software, tech news, and AI from SourceForge directly in your inbox once a month.
Thanks for helping keep SourceForge clean.
X