From: Stefan Fritsch Date: Sat, 2 Jul 2011 08:30:38 +0000 (+0000) Subject: Add new non-default debugging module mod_log_debug X-Git-Tag: 2.3.14^2~90 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=3a2ff3375788b8d227a3b7be5f54510d826cd65b;p=thirdparty%2Fapache%2Fhttpd.git Add new non-default debugging module mod_log_debug It allows to log custom debug messages at various phases in the request processing and is the first consumer of the new string-valued ap_expr API. git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@1142170 13f79535-47bb-0310-9956-ffa450edef68 --- diff --git a/CHANGES b/CHANGES index a75a5a59446..571668ea306 100644 --- a/CHANGES +++ b/CHANGES @@ -2,6 +2,9 @@ Changes with Apache 2.3.14 + *) mod_log_debug: New module that allows to log custom messages at various + phases in the request processing. [Stefan Fritsch] + *) mod_ssl: Add some debug logging when loading server certificates. PR 37912. [Nick Burch ] diff --git a/docs/manual/expr.xml b/docs/manual/expr.xml index 07fbb667ac9..fc412bfc5cb 100644 --- a/docs/manual/expr.xml +++ b/docs/manual/expr.xml @@ -46,6 +46,7 @@ FilterProvider Require expr SSLRequire +LogMessage mod_include
@@ -227,7 +228,7 @@ listfunction ::= listfuncname "(" word ")" "on" if the connection uses IPv6, "off" otherwise REQUEST_STATUS - The HTTP error status of the request + The HTTP error status of the request REQUEST_LOG_ID The error log id of the request (see ErrorLogFormat) diff --git a/docs/manual/mod/mod_log_debug.xml b/docs/manual/mod/mod_log_debug.xml new file mode 100644 index 00000000000..d4f629dbaf9 --- /dev/null +++ b/docs/manual/mod/mod_log_debug.xml @@ -0,0 +1,132 @@ + + + + + + + + + +mod_log_debug +Additional configurable debug logging +Experimental +mod_log_debug.c +log_debug_module +Available in Apache 2.3.14 and later + +
Examples + +
    +
  1. + Log message after request to /foo/* is processed: + + + <Location /foo>
    +   LogMessage "/foo has been requested"
    + </Location>
    +     +
    2. + +
  2. + Log message if request to /foo/* is processed in a sub-request: + + <Location /foo>
    +   LogMessage "subrequest to /foo" hook=type_checker if=%{IS_SUBREQ}
    + </Location>
    +     + + The default log_transaction hook is not executed for sub-requests, + therefore we have to use a different hook. +
    3. + + +
  3. + Log message if an IPv6 client causes a request timeout: + + LogMessage "IPv6 timeout from %{REMOTE_ADDR}" + "if=-T %{IPV6} && %{REQUEST_STATUS} = 408" + + Note the placing of the dobule quotes for the if= argument. +
    4. + +
  4. + Log the value of the "X-Foo" request environment variable in each + stage of the request: + + <Location />
    +   LogMessage "%{reqenv:X-Foo}" hook=all
    + </Location>
    +     + Together with the microsecond time stamps in the error log, this + allows to determine the times spent in the different parts of the + request processing. +
    5. + +
+
+ + +LogMessage +Log userdefined message to error log + +LogMessage message +[hook=hook] [if=expression] + +Unset +directory + + + +

This directive causes a user defined message to be logged to the + error log. The message can use variables and functions from the + ap_expr syntax. The messages are logged at + loglevel info.

+ +

The hook specifies before which phase of request procesing the message + will be logged. The following hooks are supported:

+ + + + + + + + + + + + + + + + +
Name
translate_name
type_checker
quick_handler
map_to_storage
check_access
check_access_ex
insert_filter
check_authn
check_authz
fixups
handler
log_transaction
+ +

The default is log_transaction. The special value + all is also supported, causing a message to be logged at each + phase. Not all hooks are executed for every request.

+ +

The optional expression allows to restrict the message if a + condition is met. The details of the expression syntax are described in + the ap_expr documentation.

+ + + + + + diff --git a/docs/manual/new_features_2_4.xml b/docs/manual/new_features_2_4.xml index 6e30b0f7c63..98967c1a921 100644 --- a/docs/manual/new_features_2_4.xml +++ b/docs/manual/new_features_2_4.xml @@ -107,6 +107,10 @@
mod_slotmem_shm
Provides a Slot-based shared memory provider (ala the scoreboard).
+
mod_log_debug
+
Allows to add customizable debug logging at different phases of the + request processing.
+
diff --git a/modules/loggers/config.m4 b/modules/loggers/config.m4 index 8571e9e7083..b795804ee03 100644 --- a/modules/loggers/config.m4 +++ b/modules/loggers/config.m4 @@ -5,6 +5,7 @@ dnl APACHE_MODULE(name, helptext[, objects[, structname[, default[, config]]]]) APACHE_MODPATH_INIT(loggers) APACHE_MODULE(log_config, logging configuration. You won't be able to log requests to the server without this module., , , yes) +APACHE_MODULE(log_debug, configurable debug logging, , , no) APACHE_MODULE(log_forensic, forensic logging) if test "x$enable_log_forensic" != "xno"; then diff --git a/modules/loggers/mod_log_debug.c b/modules/loggers/mod_log_debug.c new file mode 100644 index 00000000000..588cb3f34e6 --- /dev/null +++ b/modules/loggers/mod_log_debug.c @@ -0,0 +1,281 @@ +/* Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#include "apr_strings.h" + +#include "httpd.h" +#include "http_config.h" +#include "http_log.h" +#include "http_protocol.h" +#include "http_request.h" +#include "ap_expr.h" + +extern module log_debug_module; + +typedef struct { + ap_expr_info_t *msg_expr; + ap_expr_info_t *condition; + const char *hook; +} msg_entry; + +typedef struct { + apr_array_header_t *entries; +} log_debug_dirconf; + +const char *allhooks = "all"; +const char * const hooks[] = { + "log_transaction", /* 0 */ + "quick_handler", /* 1 */ + "handler", /* 2 */ + "translate_name", /* 3 */ + "map_to_storage", /* 4 */ + "fixups", /* 5 */ + "type_checker", /* 6 */ + "check_access", /* 7 */ + "check_access_ex", /* 8 */ + "check_authn", /* 9 */ + "check_authz", /* 10 */ + "insert_filter", /* 11 */ + NULL +}; + +static void do_debug_log(request_rec *r, const char *hookname) +{ + log_debug_dirconf *dconf = ap_get_module_config(r->per_dir_config, &log_debug_module); + int i; + if (dconf->entries == NULL) + return; + + for (i = 0; i < dconf->entries->nelts; i++) { + const char *msg, *err; + msg_entry *entry = APR_ARRAY_IDX(dconf->entries, i, msg_entry *); + if (entry->hook != allhooks && entry->hook != hookname) + continue; + if (entry->condition) { + int ret = ap_expr_exec(r, entry->condition, &err); + if (err) { + ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, + "Can't evaluate condition: %s", err); + continue; + } + if (!ret) + continue; + } + msg = ap_expr_str_exec(r, entry->msg_expr, &err); + if (err) + ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, + "Can't evaluate message expression: %s", err); + if (APLOGrdebug(r)) + ap_log_rerror(APLOG_MARK, APLOG_INFO, 0, r, "%s (%s hook, %s:%d)", + msg, hookname, entry->msg_expr->filename, + entry->msg_expr->line_number); + else + ap_log_rerror(APLOG_MARK, APLOG_INFO, 0, r, "%s", msg); + } +} + +static int log_debug_log_transaction(request_rec *r) +{ + do_debug_log(r, hooks[0]); + return DECLINED; +} + +static int log_debug_quick_handler(request_rec *r, int lookup_uri) +{ + do_debug_log(r, hooks[1]); + return DECLINED; +} + +static int log_debug_handler(request_rec *r) +{ + do_debug_log(r, hooks[2]); + return DECLINED; +} + +static int log_debug_translate_name(request_rec *r) +{ + do_debug_log(r, hooks[3]); + return DECLINED; +} + +static int log_debug_map_to_storage(request_rec *r) +{ + do_debug_log(r, hooks[4]); + return DECLINED; +} + +static int log_debug_fixups(request_rec *r) +{ + do_debug_log(r, hooks[5]); + return DECLINED; +} + +static int log_debug_type_checker(request_rec *r) +{ + do_debug_log(r, hooks[6]); + return DECLINED; +} + +static int log_debug_check_access(request_rec *r) +{ + do_debug_log(r, hooks[7]); + return DECLINED; +} + +static int log_debug_check_access_ex(request_rec *r) +{ + do_debug_log(r, hooks[8]); + return DECLINED; +} + +static int log_debug_check_authn(request_rec *r) +{ + do_debug_log(r, hooks[9]); + return DECLINED; +} + +static int log_debug_check_authz(request_rec *r) +{ + do_debug_log(r, hooks[10]); + return DECLINED; +} + +static void log_debug_insert_filter(request_rec *r) +{ + do_debug_log(r, hooks[11]); +} + +static void *log_debug_create_dconf(apr_pool_t *p, char *dirspec) +{ + log_debug_dirconf *dconf = apr_pcalloc(p, sizeof(log_debug_dirconf)); + return dconf; +} + +static void *log_debug_merge_dconf(apr_pool_t *p, void *parent_conf, void *new_conf) +{ + log_debug_dirconf *merged = apr_pcalloc(p, sizeof(log_debug_dirconf)); + const log_debug_dirconf *parent = parent_conf; + const log_debug_dirconf *new = new_conf; + + if (parent->entries == NULL) + merged->entries = new->entries; + else if (new->entries == NULL) + merged->entries = parent->entries; + else + /* apr_array_append actually creates a new array */ + merged->entries = apr_array_append(p, parent->entries, new->entries); + + return merged; +} + +static const char *cmd_log_message(cmd_parms *cmd, void *dconf_, const char *arg1, + const char *arg2, const char *arg3) +{ + msg_entry *entry = apr_pcalloc(cmd->pool, sizeof(msg_entry)); + log_debug_dirconf *dconf = dconf_; + int i, j; + const char *err; + const char *args[2] = { arg2, arg3 }; + + entry->msg_expr = ap_expr_parse_cmd(cmd, arg1, AP_EXPR_FLAG_STRING_RESULT| + AP_EXPR_FLAG_DONT_VARY, + &err, NULL); + if (err) + return apr_psprintf(cmd->pool, + "Could not parse message expression '%s': %s", + arg1, err); + + for (i = 0; i < 2; i++) { + if (args[i] == NULL) + break; + + if (strncasecmp(args[i], "hook=", 5) == 0) { + const char *name = args[i] + 5; + j = 0; + while (hooks[j]) { + if (strcasecmp(hooks[j], name) == 0) { + entry->hook = hooks[j]; + break; + } + j++; + } + if (entry->hook == NULL) { + if (strcmp(name, "*") == 0 || strcasecmp(name, allhooks) == 0) + entry->hook = allhooks; + else + return apr_psprintf(cmd->pool, "Invalid hook name: %s", name); + } + } + else if (strncasecmp(args[i], "if=", 3) == 0) { + const char *expr = args[i] + 3; + entry->condition = ap_expr_parse_cmd(cmd, expr, + AP_EXPR_FLAG_DONT_VARY, + &err, NULL); + if (err) + return apr_psprintf(cmd->pool, + "Could not parse expression '%s': %s", + expr, err); + } + else { + return apr_psprintf(cmd->pool, "Invalid argument %s", args[i]); + } + } + if (entry->hook == NULL) + entry->hook = hooks[0]; + + if (!dconf->entries) + dconf->entries = apr_array_make(cmd->pool, 4, sizeof(msg_entry *)); + + APR_ARRAY_PUSH(dconf->entries, msg_entry *) = entry; + + return NULL; +} + +static const command_rec log_debug_cmds[] = +{ + AP_INIT_TAKE123("LogMessage", cmd_log_message, NULL, RSRC_CONF|ACCESS_CONF, + "Log a debug message to the error log if this config block is used for " + " a request"), + {NULL} +}; + +static void register_hooks(apr_pool_t *p) +{ + ap_hook_log_transaction(log_debug_log_transaction, NULL, NULL, APR_HOOK_FIRST); + ap_hook_quick_handler(log_debug_quick_handler, NULL, NULL, APR_HOOK_FIRST); + ap_hook_handler(log_debug_handler, NULL, NULL, APR_HOOK_FIRST); + ap_hook_translate_name(log_debug_translate_name, NULL, NULL, APR_HOOK_FIRST); + ap_hook_map_to_storage(log_debug_map_to_storage, NULL, NULL, APR_HOOK_FIRST); + ap_hook_fixups(log_debug_fixups, NULL, NULL, APR_HOOK_FIRST); + ap_hook_type_checker(log_debug_type_checker, NULL, NULL, APR_HOOK_FIRST); + ap_hook_check_access(log_debug_check_access, NULL, NULL, APR_HOOK_FIRST, AP_AUTH_INTERNAL_PER_URI); + ap_hook_check_access_ex(log_debug_check_access_ex, NULL, NULL, APR_HOOK_FIRST, AP_AUTH_INTERNAL_PER_URI); + ap_hook_check_authn(log_debug_check_authn, NULL, NULL, APR_HOOK_FIRST, AP_AUTH_INTERNAL_PER_URI); + ap_hook_check_authz(log_debug_check_authz, NULL, NULL, APR_HOOK_FIRST, AP_AUTH_INTERNAL_PER_URI); + ap_hook_insert_filter(log_debug_insert_filter, NULL, NULL, APR_HOOK_FIRST); +} + +AP_DECLARE_MODULE(log_debug) = +{ + STANDARD20_MODULE_STUFF, + log_debug_create_dconf, /* create per-dir config */ + log_debug_merge_dconf, /* merge per-dir config */ + NULL, /* server config */ + NULL, /* merge server config */ + log_debug_cmds, /* command apr_table_t */ + register_hooks /* register hooks */ +}; +