You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Stefan Fritsch <sf...@sfritsch.de> on 2009/12/23 13:14:46 UTC
Per module LogLevel configuration
Hi,
when debugging problems, one needs detailed debug logging of the
involved functions. Unfortunately, some modules (especially mod_ssl)
log so much that switching to LogLevel debug in a production
environment is often impractical. Therefore I think it would be very
useful if one could set the loglevel per module.
Also, there is some need to have finer control over what is logged, as
demonstrated by modules with their own log configuration
(SSLLogLevelDebugDump, DumpIOLogLevel, RewriteLogLevel, ...). I would
introduce some new loglevels above "debug" (maybe trace1 to trace6
corresponding to the rewrite log levels) and use these for the most
detailed messages. Together with the per module log level, one could
then remove the special per module config directives.
What I want is the admin being abled to configure something like this:
LogLevel info ldap=debug authnz_ldap=debug ssl=warn rewrite=trace4
For the implementation I thought of some loglevel vector similar to
the construct used by ap_get_module_config. There should then be a
ap_get_module_loglevel and the ap_log_*error functions would get the
module_index as additional parameter. To make things somewhat source
compatible, one could redefine APLOG_MARK to something like
__FILE__,__LINE__,GLOBAL, i.e. most modules could be compiled without
changes (but would then use the global log level). To add support to a
module, something like
#define APLOG_MARK_LDAP __FILE__,__LINE__,ldap_module->module_index
and a global search and replace would be enough for most modules (or
one could even redefine APLOG_MARK in the module source).
With that infrastructure in place, it would then be possible to add
some more detailed logging in some places, like
- core: dump of complete headers from/to client
- proxy: dump of complete headers from/to backend
- ldap: trace communication to ldap server
What do you think of this idea? Would it be ok to drop the ability to
write the rewrite log into a separate file? Or should there also be
the possibility to configure a separate logfile per module?
Cheers,
Stefan
Re: Per module LogLevel configuration
Posted by Stefan Fritsch <sf...@sfritsch.de>.
On Thu, 24 Dec 2009, Paul Querna wrote:
> On Wed, Dec 23, 2009 at 4:14 AM, Stefan Fritsch <sf...@sfritsch.de> wrote:
> An alternative implementation would be something along the lines of
> how reconnoiter does logging:
> <https://labs.omniti.com/trac/reconnoiter/browser/trunk/src/utils/noit_log.h>
>
> This would definitely be a larger rewrite in general for logging, but
> would be much more flexible in the long run, but I have grown fond of
> how reconoiter's logging subsystem has worked.
>
> Most modules would do this in their init function:
>
> dlog = ap_log_stream_find("mod_foo/debug")
> elog = ap_log_stream_find("mod_foo/error")
>
> Where dlog/elog are static globals for that file. If the logging
> system is disabled for that module, logging in the module is then done
> like this:
>
> apL(dlog, "foo is wrong: %d", bar);
I don't see how this would work well with per vhost log level
configuration. Any idea?
Also, I want something that can be implemented on 2.4 time scales and
won't delay the release of 2.4. Maybe we should leave a larger rewrite for
3.0?
> Our current system only has emerg, alert, crit, error, warn, notice,
> info, debug, but because they are not configurable per-module, they
> are difficult to use effectively, I think in general if we had
> per-module logging, we could easily get by with just critical, error,
> info, and debug.
mod_ssl currently has three sublevels for log level debug, mod_rewrite has
six. Unless we keep the special directives like RewriteLogLevel, we need
more levels, not fewer. But if the consensus is that keeping
RewriteLogLevel is preferred, I am fine with that, too.
Some granularity below module level would be nice, too. For example:
ssl.reneg, ssl.require, ssl.session_cache, ...
But this is something that I would leave for 3.0, too.
>> For the implementation I thought of some loglevel vector similar to
>> the construct used by ap_get_module_config. There should then be a
>> ap_get_module_loglevel and the ap_log_*error functions would get the
>> module_index as additional parameter. To make things somewhat source
>> compatible, one could redefine APLOG_MARK to something like
>> __FILE__,__LINE__,GLOBAL, i.e. most modules could be compiled without
>> changes (but would then use the global log level). To add support to a
>> module, something like
>>
>> #define APLOG_MARK_LDAP __FILE__,__LINE__,ldap_module->module_index
>>
>> and a global search and replace would be enough for most modules (or
>> one could even redefine APLOG_MARK in the module source).
>
> hmm, I'm not sure I really like having to redefine APLOG_MARK in every
> file.. It would be nice if we could build the macro into the module
> declaration perhaps?
Sure. Any idea how to do that in a non-ugly way?
Maybe in httpd.h:
#define AP_USE_MODULE_LOG(mod) \
static int *ap_log_module_index = &mod->module_index
#define AP_LOG_MARK __FILE__,__LINE__,*ap_log_module_index
and then in mod_xyz.c:
module AP_MODULE_DECLARE_DATA xyz_module;
#ifdef AP_USE_MODULE_LOG
AP_USE_MODULE_LOG(xyz_module);
#endif
...
ap_log_error(AP_LOG_MARK, ...
This would at least compile with 2.2.x, too.
Re: Per module LogLevel configuration
Posted by Paul Querna <pa...@querna.org>.
On Wed, Dec 23, 2009 at 4:14 AM, Stefan Fritsch <sf...@sfritsch.de> wrote:
> Hi,
>
> when debugging problems, one needs detailed debug logging of the
> involved functions. Unfortunately, some modules (especially mod_ssl)
> log so much that switching to LogLevel debug in a production
> environment is often impractical. Therefore I think it would be very
> useful if one could set the loglevel per module.
+1 in concept, this is one of the most annoying parts of the logging
subsystem today!
An alternative implementation would be something along the lines of
how reconnoiter does logging:
<https://labs.omniti.com/trac/reconnoiter/browser/trunk/src/utils/noit_log.h>
This would definitely be a larger rewrite in general for logging, but
would be much more flexible in the long run, but I have grown fond of
how reconoiter's logging subsystem has worked.
Most modules would do this in their init function:
dlog = ap_log_stream_find("mod_foo/debug")
elog = ap_log_stream_find("mod_foo/error")
Where dlog/elog are static globals for that file. If the logging
system is disabled for that module, logging in the module is then done
like this:
apL(dlog, "foo is wrong: %d", bar);
Our current system only has emerg, alert, crit, error, warn, notice,
info, debug, but because they are not configurable per-module, they
are difficult to use effectively, I think in general if we had
per-module logging, we could easily get by with just critical, error,
info, and debug.
> Also, there is some need to have finer control over what is logged, as
> demonstrated by modules with their own log configuration
> (SSLLogLevelDebugDump, DumpIOLogLevel, RewriteLogLevel, ...). I would
> introduce some new loglevels above "debug" (maybe trace1 to trace6
> corresponding to the rewrite log levels) and use these for the most
> detailed messages. Together with the per module log level, one could
> then remove the special per module config directives.
>
> What I want is the admin being abled to configure something like this:
>
> LogLevel info ldap=debug authnz_ldap=debug ssl=warn rewrite=trace4
>
> For the implementation I thought of some loglevel vector similar to
> the construct used by ap_get_module_config. There should then be a
> ap_get_module_loglevel and the ap_log_*error functions would get the
> module_index as additional parameter. To make things somewhat source
> compatible, one could redefine APLOG_MARK to something like
> __FILE__,__LINE__,GLOBAL, i.e. most modules could be compiled without
> changes (but would then use the global log level). To add support to a
> module, something like
>
> #define APLOG_MARK_LDAP __FILE__,__LINE__,ldap_module->module_index
>
> and a global search and replace would be enough for most modules (or
> one could even redefine APLOG_MARK in the module source).
hmm, I'm not sure I really like having to redefine APLOG_MARK in every
file.. It would be nice if we could build the macro into the module
declaration perhaps?
Thanks,
Paul
[PATCH] Per module LogLevel configuration
Posted by Stefan Fritsch <sf...@sfritsch.de>.
It would be nice if some people could look at the patch and comment if
this is a reasonable way to do this. Maybe during the Hackathon?
Thanks in advance
Stefan
On Sunday 03 January 2010, Stefan Fritsch wrote:
> I have started an implementation of this:
>
> http://people.apache.org/~sf/per-module-loglevel-1.v1.diff
> http://people.apache.org/~sf/per-module-loglevel-2.v1.diff
>
> The first diff is the infrastructure and the second patch touches
> nearly every file to set the correct module for logging (and
> tweaks mod_ssl to cope with the changed ap_log_*error functions).
>
> As suggested by Paul, it will skip the argument setup on C99
> compilers, but should continue to work on older compilers. With
> C99 compilers, it is also possible to remove some logging at
> compile time by defining APLOG_MAX_LOGLEVEL.
>
> To select the module for logging, one needs to add somethink like
>
> #define APLOG_MODULE_INDEX core_module.module_index
>
> at the top of every source file and the *_module struct must be
> declared. If someone has a better idea how to do this, I would like
> to hear it. All other comments are of course welcome, too.
>
> Still missing are per directory loglevel configuration and per
> module logfile selection.
>
> Things like "LogLevel info proxy_http:debug" work for me. Apart
> from that I have done only minimal testing. I am currently having
> some test framework problems with the (unchanged) trunk and can't
> really test with my changes.
Re: Per module LogLevel configuration
Posted by Stefan Fritsch <sf...@sfritsch.de>.
Hi,
I have started an implementation of this:
http://people.apache.org/~sf/per-module-loglevel-1.v1.diff
http://people.apache.org/~sf/per-module-loglevel-2.v1.diff
The first diff is the infrastructure and the second patch touches
nearly every file to set the correct module for logging (and tweaks
mod_ssl to cope with the changed ap_log_*error functions).
As suggested by Paul, it will skip the argument setup on C99
compilers, but should continue to work on older compilers. With C99
compilers, it is also possible to remove some logging at compile time
by defining APLOG_MAX_LOGLEVEL.
To select the module for logging, one needs to add somethink like
#define APLOG_MODULE_INDEX core_module.module_index
at the top of every source file and the *_module struct must be
declared. If someone has a better idea how to do this, I would like to
hear it. All other comments are of course welcome, too.
Still missing are per directory loglevel configuration and per module
logfile selection.
Things like "LogLevel info proxy_http:debug" work for me. Apart from
that I have done only minimal testing. I am currently having some test
framework problems with the (unchanged) trunk and can't really test
with my changes.
Cheers,
Stefan
Re: Per module LogLevel configuration
Posted by Paul Querna <pa...@querna.org>.
On Tue, Dec 29, 2009 at 1:30 AM, Ruediger Pluem <rp...@apache.org> wrote:
> On 28.12.2009 18:28, Stefan Fritsch wrote:
>> On Monday 28 December 2009, Paul Querna wrote:
>>>> You describe the internal arg processing. Keep in mind that fn
>>>> args aren't conditionally processed, they must be created before
>>>> being passed to the function. If we can dodge that with a module
>>>> query 'is mod_foo at loglevel debug here?' then we can optimize
>>>> this considerably.
>>> Yes, see the implementation of the Noit Logger which I linked to,
>>> it uses a Macro to check if a logger is enabled, so you don't have
>>> the function arg prep/frame overhead if a logger isn't enabled.
>>>
>>
>> This would also make it possible to define the macro in a way that
>> disables debug logging at compile time, just as Bill wanted.
>>
>> However, the way reconoiter does it requires variadic macros
>> (http://en.wikipedia.org/wiki/Variadic_macro):
>>
>> #define APLOG(file, line, loglevel, server, ...) \
>> do { if (server->loglevel >= loglevel) \
>> ap_log_error(file, line, loglevel, server, __VA_ARGS__) \
>> } while (0)
>>
>>
>> But variadic macros are only part of C99. Is it ok to drop support for
>> older, pre-C99 compilers in httpd?
>
> I think that would cancel support for some platforms (Netware ???).
> So IMHO no.
Pretty much everything else has a c99 compiler these days. On
platforms that don't, you could easily fallback to this:
#ifdef HAVE_VA_ARGS
#define apL(stream, fmt, ...) if ((stream)->enabled) { \
stream->log(fmt, __VA_ARGS__) \
}
#else
#define apL ap_stream_log
#endif
Where ap_strream_log is a normal function with a signature matching apL.
Yes, it means on netware, its slower, but no slower than what we do
today, and on most other platforms, it would be faster than what we do
today.
Re: Per module LogLevel configuration
Posted by Ruediger Pluem <rp...@apache.org>.
On 28.12.2009 18:28, Stefan Fritsch wrote:
> On Monday 28 December 2009, Paul Querna wrote:
>>> You describe the internal arg processing. Keep in mind that fn
>>> args aren't conditionally processed, they must be created before
>>> being passed to the function. If we can dodge that with a module
>>> query 'is mod_foo at loglevel debug here?' then we can optimize
>>> this considerably.
>> Yes, see the implementation of the Noit Logger which I linked to,
>> it uses a Macro to check if a logger is enabled, so you don't have
>> the function arg prep/frame overhead if a logger isn't enabled.
>>
>
> This would also make it possible to define the macro in a way that
> disables debug logging at compile time, just as Bill wanted.
>
> However, the way reconoiter does it requires variadic macros
> (http://en.wikipedia.org/wiki/Variadic_macro):
>
> #define APLOG(file, line, loglevel, server, ...) \
> do { if (server->loglevel >= loglevel) \
> ap_log_error(file, line, loglevel, server, __VA_ARGS__) \
> } while (0)
>
>
> But variadic macros are only part of C99. Is it ok to drop support for
> older, pre-C99 compilers in httpd?
I think that would cancel support for some platforms (Netware ???).
So IMHO no.
Regards
Rüdiger
Re: Per module LogLevel configuration
Posted by Stefan Fritsch <sf...@sfritsch.de>.
On Monday 28 December 2009, Paul Querna wrote:
> > You describe the internal arg processing. Keep in mind that fn
> > args aren't conditionally processed, they must be created before
> > being passed to the function. If we can dodge that with a module
> > query 'is mod_foo at loglevel debug here?' then we can optimize
> > this considerably.
>
> Yes, see the implementation of the Noit Logger which I linked to,
> it uses a Macro to check if a logger is enabled, so you don't have
> the function arg prep/frame overhead if a logger isn't enabled.
>
This would also make it possible to define the macro in a way that
disables debug logging at compile time, just as Bill wanted.
However, the way reconoiter does it requires variadic macros
(http://en.wikipedia.org/wiki/Variadic_macro):
#define APLOG(file, line, loglevel, server, ...) \
do { if (server->loglevel >= loglevel) \
ap_log_error(file, line, loglevel, server, __VA_ARGS__) \
} while (0)
But variadic macros are only part of C99. Is it ok to drop support for
older, pre-C99 compilers in httpd?
Cheers,
Stefan
Re: Per module LogLevel configuration
Posted by Paul Querna <pa...@querna.org>.
On Sun, Dec 27, 2009 at 11:08 PM, William A. Rowe Jr.
<wr...@rowe-clan.net> wrote:
> Dan Poirier wrote:
>>
>> Looking at log_error_core(), it appears that if the logging level is set
>> to disallow a particular message from being logged, that
>> log_error_core() returns before doing any argument processing. So the
>> overhead would only consist of a few function calls, and my sense would
>> be that saving that wouldn't make a big difference.
>
> You describe the internal arg processing. Keep in mind that fn args aren't
> conditionally processed, they must be created before being passed to the
> function. If we can dodge that with a module query 'is mod_foo at loglevel
> debug here?' then we can optimize this considerably.
>
> A minimum vector is per-vhost-per-module, but per-dir-per-module would be
> even better :) At that granularity, and adding per-mod forensics, the user
> can be grabbing lots of detail on one specific module in the single context
> that is causing that module to misbehave.
Yes, see the implementation of the Noit Logger which I linked to, it
uses a Macro to check if a logger is enabled, so you don't have the
function arg prep/frame overhead if a logger isn't enabled.
Re: Per module LogLevel configuration
Posted by "William A. Rowe Jr." <wr...@rowe-clan.net>.
Dan Poirier wrote:
>
> Looking at log_error_core(), it appears that if the logging level is set
> to disallow a particular message from being logged, that
> log_error_core() returns before doing any argument processing. So the
> overhead would only consist of a few function calls, and my sense would
> be that saving that wouldn't make a big difference.
You describe the internal arg processing. Keep in mind that fn args aren't
conditionally processed, they must be created before being passed to the
function. If we can dodge that with a module query 'is mod_foo at loglevel
debug here?' then we can optimize this considerably.
A minimum vector is per-vhost-per-module, but per-dir-per-module would be
even better :) At that granularity, and adding per-mod forensics, the user
can be grabbing lots of detail on one specific module in the single context
that is causing that module to misbehave.
Re: Per module LogLevel configuration
Posted by Dan Poirier <po...@pobox.com>.
"William A. Rowe Jr." <wr...@rowe-clan.net> writes:
> Dan Poirier wrote:
>> "William A. Rowe Jr." <wr...@rowe-clan.net> writes:
>>
>>> One thing we should refactor is 'debug' logging. Proper debug
>>> logging is log early and often, but there is overhead involved
>>> in preparing the args and submitting the log request, only to have
>>> it fall on deaf ears.
>>>
>>> If we are doing any significant 2.0 refactoring, toggling the
>>> truly-debug log level processing at compile time would be a big win.
>>
>> Do we have some measurements of how much overhead this adds?
>
> Of course not, since it varies wildly by what is being logged. But just
> the preparation can consume double buffers/invoke a copy with the simple
> presence of an LF character.
Looking at log_error_core(), it appears that if the logging level is set
to disallow a particular message from being logged, that
log_error_core() returns before doing any argument processing. So the
overhead would only consist of a few function calls, and my sense would
be that saving that wouldn't make a big difference.
Of course common sense is notoriously unreliable in making judgments
about performance :-), but this does make me even more interested in
seeing some evidence of significant improvement before we make major
changes in this area at the expense of making problem determination more
difficult.
Dan
Re: Per module LogLevel configuration
Posted by "William A. Rowe Jr." <wr...@rowe-clan.net>.
Dan Poirier wrote:
> "William A. Rowe Jr." <wr...@rowe-clan.net> writes:
>
>> One thing we should refactor is 'debug' logging. Proper debug
>> logging is log early and often, but there is overhead involved
>> in preparing the args and submitting the log request, only to have
>> it fall on deaf ears.
>>
>> If we are doing any significant 2.0 refactoring, toggling the
>> truly-debug log level processing at compile time would be a big win.
>
> Do we have some measurements of how much overhead this adds?
Of course not, since it varies wildly by what is being logged. But just
the preparation can consume double buffers/invoke a copy with the simple
presence of an LF character.
> Being able to turn on debug logging by just changing the configuration
> is much more convenient than requiring a recompile, and I'd hate to give
> that up without knowing we were gaining significantly in performance.
One aspect would be compile-in optional logging, but another option for
most modules would be runtime module log level querying. That would at
least allow the authors of cpu/memory intensive logging features
Re: Per module LogLevel configuration
Posted by Dan Poirier <po...@pobox.com>.
"William A. Rowe Jr." <wr...@rowe-clan.net> writes:
> One thing we should refactor is 'debug' logging. Proper debug
> logging is log early and often, but there is overhead involved
> in preparing the args and submitting the log request, only to have
> it fall on deaf ears.
>
> If we are doing any significant 2.0 refactoring, toggling the
> truly-debug log level processing at compile time would be a big win.
Do we have some measurements of how much overhead this adds?
Being able to turn on debug logging by just changing the configuration
is much more convenient than requiring a recompile, and I'd hate to give
that up without knowing we were gaining significantly in performance.
Re: Per module LogLevel configuration
Posted by "William A. Rowe Jr." <wr...@rowe-clan.net>.
Your redesign ideas are interesting, Stefan.
One thing we should refactor is 'debug' logging. Proper debug
logging is log early and often, but there is overhead involved
in preparing the args and submitting the log request, only to have
it fall on deaf ears.
If we are doing any significant 2.0 refactoring, toggling the
truly-debug log level processing at compile time would be a big win.