Add diagnostic logging

Field experience with Mellon has demonstrated there are many
opportunities for deployment problems. Although there are tools such
as browser plugins which can capture SAML messages it's onerous for
site personnel to install and capture the relevant information. The
problem with this approach is further compounded by the fact the
external SAML messages are not correlated to Mellon's
requests/responses. Mellon currently can dump the Lasso session and
SAML Response messages and place them in Apache environment variables,
however these do not appear in the log file. To get them into the log
you have to add custom logging to the Apache config. Another issue is
the dumps are not human readable, they are base64 encoded, anyone
looking at the logs after setting up the custom logging will have to
find the base64 text and then manually copy the text into an external
base64 decoder. At that point you'll discover the XML is not pretty
printed making human interpretation difficult.

The Mellon debug messages written to the Apache error are often
insufficient to diagnose problems. And since the Mellon log messages
are written to the Apache error log they are interspersed with a lot
of non-Mellon message.

Compounding the problem of writing Mellon debug messages to the Apache
error log is the fact Apache log messages have a fixed maximum length
(currently 8192) which is insufficient to completely write out such
things as SAML Assertions, metadata, etc. Apache logging also escapes
all control characters with the consequence line breaks are not
preserved and what was a nicely formatted human readable piece of text
becomes a single line with escape characters and may be truncated.

It would be really nice if we could capture diagnostic information
with these properties:

* All relevant data is collected in exactly one file.

* Only information relevant to Mellon appears in the file.

* All information is human readable (pretty printed, decrypted) with
  no need to rely on other tools.

* The diagnostic information is grouped by requests.

* The requests can be cross correlated with other Apache logs because
  they utilize the same unique request identifier.

This patch adds diagnostic logging to a independent Mellon diagnostics
log file. Every piece of relevant information is captured, including:

* Request information which includes:

  - Request method
  - Request URL (raw and processed)
  - Scheme
  - Port
  - Request query parameters
  - Server name
  - Unique request ID
  - process ID, thread ID
  - Request headers

* Mellon per directory configuration

  A complete dump of the entire am_dir_cfg_rec structure keyed using
  both the Mellon directive it is associated with and it's internal
  name. This is emitted once on first use for a given URL.

  The per directory dump includes the pathname of each file read as
  well as the file contents. This includes:

  - IdP metadata
  - SP metadata
  - SP cert
  - SP key
  - IdP public key file
  - IdP CA file

* All session management operations

  - cookie
  - session lookup
  - session creation
  - session deletion
  - cache management
  - cache entry information

* All SAML messages

  Each SAML message is decrypted, decoded and XML pretty printed in
  human readable form.

* Request pipeline operations

  What operations Mellon performs, what decisions it makes and what
  data is being used to make those decisions.

* Response

  - response status
  - response headers
  - Apache user name
  - auth_type
  - all Apache environment variables

Diagnostics can be enabled/disabled both at compile time and run
time. Compile time inclusion of diagnostics is managed with the
ENABLE_DIAGNOSTICS preprocssor symbol. The configure script now accepts
the

  --enable-diagnostics and --disable-diagnostics

option. Building with diagnostics is disabled by default, you must
specify --enable-diagnostics to enable the run time option of generating
diagnostics.

The following server config directives have been added (e.g. may be
specified in the main server config area or within a <VirtualHost>
directive). If Mellon was not built with diagnostics enabled then
these config directives are no-ops and their use will generated a
warning in the log file indicating they have been ignored and to be
effective you must builld Mellon with diagnostics enabled.

  MellonDiagnosticsFile:
    The name of the diagnostics file or pipe,
    (default is logs/mellon_diagnostics)

  MellonDiagnosticsEnable:
    Currently either On or Off but it is designed so it can take other
    flags in the future to control what type of information is
    reported.

Signed-off-by: John Dennis <jdennis@redhat.com>
This commit is contained in:
John Dennis 2017-06-14 13:56:18 -04:00
parent 6d2ee845c0
commit e8579f6387
11 changed files with 1453 additions and 13 deletions

View File

@ -1,8 +1,11 @@
# Source files. mod_auth_mellon.c must be the first file.
SRC=mod_auth_mellon.c \
auth_mellon_cache.c auth_mellon_config.c \
auth_mellon_cookie.c auth_mellon_handler.c \
auth_mellon_cache.c \
auth_mellon_config.c \
auth_mellon_cookie.c \
auth_mellon_diagnostics.c \
auth_mellon_handler.c \
auth_mellon_util.c \
auth_mellon_session.c \
auth_mellon_httpclient.c
@ -25,7 +28,7 @@ DISTFILES=$(SRC) \
all: mod_auth_mellon.la
mod_auth_mellon.la: $(SRC) auth_mellon.h auth_mellon_compat.h
@APXS2@ -Wc,"-std=c99 @OPENSSL_CFLAGS@ @LASSO_CFLAGS@ @CURL_CFLAGS@ @GLIB_CFLAGS@ @CFLAGS@" -Wl,"@OPENSSL_LIBS@ @LASSO_LIBS@ @CURL_LIBS@ @GLIB_LIBS@" -Wc,-Wall -Wc,-g -c $(SRC)
@APXS2@ -Wc,"-std=c99 @MELLON_CFLAGS@ @OPENSSL_CFLAGS@ @LASSO_CFLAGS@ @CURL_CFLAGS@ @GLIB_CFLAGS@ @CFLAGS@" -Wl,"@OPENSSL_LIBS@ @LASSO_LIBS@ @CURL_LIBS@ @GLIB_LIBS@" -Wc,-Wall -Wc,-g -c $(SRC)
# Building configure (for distribution)
@ -46,6 +49,7 @@ distfile: @NAMEVER@.tar.gz
.PHONY: clean
clean:
rm -f mod_auth_mellon.la
rm -f $(SRC:%.c=%.o)
rm -f $(SRC:%.c=%.lo)
rm -f $(SRC:%.c=%.slo)
rm -rf .libs/

18
README
View File

@ -132,6 +132,24 @@ MellonPostSize 1048576
# Default: MellonPostCount 100
MellonPostCount 100
# MellonDiagnosticsFile If Mellon was built with diagnostic capability
# then diagnostic is written here, it may be either a filename or a pipe.
# If it's a filename then the resulting path is relative to the ServerRoot.
# If the value is preceeded by the pipe character "|" it should be followed
# by a path to a program to receive the log information on its standard input.
# This is a server context directive, hence it may be specified in the
# main server config area or within a <VirtualHost> directive.
# Default: logs/mellon_diagnostics
MellonDiagnosticsFile logs/mellon_diagnostics
# MellonDiagnosticsEnable If Mellon was built with diagnostic capability
# then this is a list of words controlling diagnostic output.
# Currently only On and Off are supported.
# This is a server context directive, hence it may be specified in the
# main server config area or within a <VirtualHost> directive.
# Default: Off
MellonDiagnosticsEnable Off
###########################################################################
# End of global configuration for mod_auth_mellon.
###########################################################################

View File

@ -85,6 +85,14 @@
#define AM_ERROR_MISSING_PAOS_MEDIA_TYPE 3
#ifdef ENABLE_DIAGNOSTICS
typedef enum {
AM_DIAG_FLAG_ENABLED = (1 << 0),
AM_DIAG_FLAG_DISABLE = 0,
AM_DIAG_FLAG_ENABLE_ALL = ~0,
} am_diag_flags_t;
#endif
/* This is the length of the id we use (for session IDs and
* replaying POST data).
*/
@ -100,6 +108,9 @@
#define am_get_req_cfg(r) (am_req_cfg_rec *)ap_get_module_config((r)->request_config, &auth_mellon_module)
#ifdef ENABLE_DIAGNOSTICS
#define am_get_diag_cfg(s) (&(am_get_srv_cfg((s)))->diag_cfg)
#endif
typedef struct am_mod_cfg_rec {
int cache_size;
@ -124,8 +135,20 @@ typedef struct am_mod_cfg_rec {
} am_mod_cfg_rec;
#ifdef ENABLE_DIAGNOSTICS
typedef struct am_diag_cfg_rec {
const char *filename;
apr_file_t *fd;
am_diag_flags_t flags;
apr_table_t *dir_cfg_emitted;
} am_diag_cfg_rec;
#endif
typedef struct am_srv_cfg_rec {
am_mod_cfg_rec *mc;
#ifdef ENABLE_DIAGNOSTICS
am_diag_cfg_rec diag_cfg;
#endif
} am_srv_cfg_rec;
typedef enum {
@ -284,7 +307,6 @@ typedef struct am_dir_cfg_rec {
/* List of domains we can redirect to. */
const char * const *redirect_domains;
} am_dir_cfg_rec;
/* Bitmask for PAOS service options */
@ -301,6 +323,9 @@ typedef struct am_req_cfg_rec {
bool ecp_authn_req;
ECPServiceOptions ecp_service_options;
#endif /* HAVE_ECP */
#ifdef ENABLE_DIAGNOSTICS
bool diag_emitted;
#endif
} am_req_cfg_rec;
typedef struct am_cache_storage_t {
@ -393,6 +418,7 @@ static const int inherit_ecp_send_idplist = -1;
void *auth_mellon_dir_config(apr_pool_t *p, char *d);
void *auth_mellon_dir_merge(apr_pool_t *p, void *base, void *add);
void *auth_mellon_server_config(apr_pool_t *p, server_rec *s);
void *auth_mellon_srv_merge(apr_pool_t *p, void *base, void *add);
const char *am_cookie_get(request_rec *r);
@ -503,4 +529,72 @@ int am_httpclient_post_str(request_rec *r, const char *uri,
extern module AP_MODULE_DECLARE_DATA auth_mellon_module;
#ifdef ENABLE_DIAGNOSTICS
/* Initializing an apr_time_t to 0x7fffffffffffffffLL yields an
* iso 8601 time with 1 second precision of "294247-01-10T04:00:54Z"
* this is 22 characters, +1 for null terminator. */
#define ISO_8601_BUF_SIZE 23
typedef struct {
bool req_headers_written;
} am_diag_request_data;
const char *
am_diag_cache_key_type_str(am_cache_key_t key_type);
const char *
am_diag_cond_str(request_rec *r, const am_cond_t *cond);
int
am_diag_finalize_request(request_rec *r);
const char *
am_diag_lasso_http_method_str(LassoHttpMethod http_method);
void
am_diag_log_cache_entry(request_rec *r, int level, am_cache_entry_t *entry,
const char *fmt, ...)
__attribute__((format(printf,4,5)));
void
am_diag_log_file_data(request_rec *r, int level, am_file_data_t *file_data,
const char *fmt, ...)
__attribute__((format(printf,4,5)));
int
am_diag_log_init(apr_pool_t *pc, apr_pool_t *p, apr_pool_t *pt, server_rec *s);
void
am_diag_log_lasso_node(request_rec *r, int level, LassoNode *node,
const char *fmt, ...)
__attribute__((format(printf,4,5)));
void
am_diag_log_profile(request_rec *r, int level, LassoProfile *profile,
const char *fmt, ...)
__attribute__((format(printf,4,5)));
void
am_diag_printf(request_rec *r, const char *fmt, ...)
__attribute__((format(printf,2,3)));
void
am_diag_rerror(const char *file, int line, int module_index,
int level, apr_status_t status,
request_rec *r, const char *fmt, ...);
char *
am_diag_time_t_to_8601(request_rec *r, apr_time_t t);
#else /* ENABLE_DIAGNOSTICS */
#define am_diag_log_cache_entry(...) do {} while(0)
#define am_diag_log_file_data(...) do {} while(0)
#define am_diag_log_lasso_node(...) do {} while(0)
#define am_diag_log_profile(...) do {} while(0)
#define am_diag_printf(...) do {} while(0)
#endif /* ENABLE_DIAGNOSTICS */
#endif /* MOD_AUTH_MELLON_H */

View File

@ -144,11 +144,17 @@ am_cache_entry_t *am_cache_lock(request_rec *r,
continue;
if(strcmp(tablekey, key) == 0) {
apr_time_t now = apr_time_now();
/* We found the entry. */
if(e->expires > apr_time_now()) {
if(e->expires > now) {
/* And it hasn't expired. */
return e;
}
else {
am_diag_log_cache_entry(r, 0, e,
"found expired session, now %s\n",
am_diag_time_t_to_8601(r, now));
}
}
}
@ -342,6 +348,10 @@ am_cache_entry_t *am_cache_new(request_rec *r,
* Update 't' and exit loop.
*/
t = e;
am_diag_log_cache_entry(r, 0, e,
"%s ejecting expired sessions, now %s\n",
__func__,
am_diag_time_t_to_8601(r, current_time));
break;
}
@ -400,6 +410,11 @@ am_cache_entry_t *am_cache_new(request_rec *r,
return NULL;
}
am_diag_printf(r, "%s created new session, id=%s at %s"
" cookie_token=\"%s\"\n",
__func__, t->key, am_diag_time_t_to_8601(r, current_time),
cookie_token);
return t;
}

View File

@ -78,6 +78,15 @@ static const apr_size_t post_size = 1024 * 1024;
*/
static const int post_count = 100;
#ifdef ENABLE_DIAGNOSTICS
/* Default filename for mellon diagnostics log file.
* Relative pathname is relative to server root. */
static const char *default_diag_filename = "logs/mellon_diagnostics";
/* Default state for diagnostics is off */
static am_diag_flags_t default_diag_flags = AM_DIAG_FLAG_DISABLE;
#endif
/* whether to merge env. vars or not
* the MellonMergeEnvVars configuration directive if you change this.
*/
@ -470,6 +479,78 @@ static const char *am_set_module_config_int_slot(cmd_parms *cmd,
return ap_set_int_slot(cmd, am_get_mod_cfg(cmd->server), arg);
}
/* This function handles the MellonDiagnosticsFile configuration directive.
* It emits as warning in the log file if Mellon is not built with
* diagnostics enabled.
*
* Parameters:
* cmd_parms *cmd The command structure for this configuration
* directive.
* void *struct_ptr Pointer to the current directory configuration.
* NULL if we are not in a directory configuration.
* const char *arg The string argument following this configuration
* directive in the configuraion file.
*
* Returns:
* NULL on success or an error string on failure.
*/
static const char *am_set_module_diag_file_slot(cmd_parms *cmd,
void *struct_ptr,
const char *arg)
{
#ifdef ENABLE_DIAGNOSTICS
return ap_set_file_slot(cmd, am_get_diag_cfg(cmd->server), arg);
#else
ap_log_error(APLOG_MARK, APLOG_NOTICE, 0, cmd->server,
"%s has no effect because Mellon was not compiled with"
" diagnostics enabled, use ./configure --enable-diagnostics"
" at build time to turn this feature on.",
cmd->directive->directive);
return NULL;
#endif
}
/* This function handles configuration directives which sets the
* diagnostics flags in the module configuration.
*
* Parameters:
* cmd_parms *cmd The command structure for this configuration
* directive.
* void *struct_ptr Pointer to the current directory configuration.
* NULL if we are not in a directory configuration.
* const char *arg The string argument following this configuration
* directive in the configuraion file.
*
* Returns:
* NULL on success or an error string on failure.
*/
static const char *am_set_module_diag_flags_slot(cmd_parms *cmd,
void *struct_ptr,
const char *arg)
{
#ifdef ENABLE_DIAGNOSTICS
am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(cmd->server);
if (strcasecmp(arg, "on") == 0) {
diag_cfg->flags = AM_DIAG_FLAG_ENABLE_ALL;
}
else if (strcasecmp(arg, "off") == 0) {
diag_cfg->flags = AM_DIAG_FLAG_DISABLE;
} else {
return apr_psprintf(cmd->pool, "%s: must be one of: 'on', 'off'",
cmd->cmd->name);
}
return NULL;
#else
ap_log_error(APLOG_MARK, APLOG_NOTICE, 0, cmd->server,
"%s has no effect because Mellon was not compiled with"
" diagnostics enabled, use ./configure --enable-diagnostics"
" at build time to turn this feature on.",
cmd->directive->directive);
return NULL;
#endif
}
/* This function handles the MellonCookieSameSite configuration directive.
* This directive can be set to "lax" or "strict"
*
@ -684,7 +765,7 @@ static const char *am_set_setenv_no_prefix_slot(cmd_parms *cmd,
static int am_cond_flags(const char *arg)
{
int flags = AM_COND_FLAG_NULL;
static const char const *options[] = {
static const char * const options[] = {
"OR", /* AM_EXPIRE_FLAG_OR */
"NOT", /* AM_EXPIRE_FLAG_NOT */
"REG", /* AM_EXPIRE_FLAG_REG */
@ -1123,6 +1204,30 @@ const command_rec auth_mellon_commands[] = {
"The maximum size of a saved POST, in bytes."
" Default value is 1048576 (1 MB)."
),
AP_INIT_TAKE1(
"MellonDiagnosticsFile",
am_set_module_diag_file_slot,
#ifdef ENABLE_DIAGNOSTICS
(void *)APR_OFFSETOF(am_diag_cfg_rec, filename),
#else
NULL,
#endif
RSRC_CONF,
"Diagnostics log file. [file|pipe] "
"If file then file is a filename, relative to the ServerRoot."
"If pipe then the filename is a pipe character \"|\", "
"followed by the path to a program to receive the log information "
"on its standard input. "
" Default value is \"logs/mellon_diagnostics\"."
),
AP_INIT_ITERATE(
"MellonDiagnosticsEnable",
am_set_module_diag_flags_slot,
NULL,
RSRC_CONF,
"Diagnostics flags. [on|off] "
" Default value is \"off\"."
),
/* Per-location configuration directives. */
@ -1855,6 +1960,13 @@ void *auth_mellon_server_config(apr_pool_t *p, server_rec *s)
srv = apr_palloc(p, sizeof(*srv));
#ifdef ENABLE_DIAGNOSTICS
srv->diag_cfg.filename = default_diag_filename;
srv->diag_cfg.fd = NULL;
srv->diag_cfg.flags = default_diag_flags;
srv->diag_cfg.dir_cfg_emitted = apr_table_make(p, 0);
#endif
/* we want to keeep our global configuration of shared memory and
* mutexes, so we try to find it in the userdata before doing anything
* else */
@ -1886,6 +1998,47 @@ void *auth_mellon_server_config(apr_pool_t *p, server_rec *s)
apr_pool_userdata_set(mod, key, apr_pool_cleanup_null, p);
srv->mc = mod;
return srv;
}
/* This function merges two am_srv_cfg_rec structures.
* It will try to inherit from the base where possible.
*
* Parameters:
* apr_pool_t *p The pool we should allocate memory from.
* void *base The original structure.
* void *add The structure we should add to base.
*
* Returns:
* The merged structure.
*/
void *auth_mellon_srv_merge(apr_pool_t *p, void *base, void *add)
{
am_srv_cfg_rec *base_cfg = (am_srv_cfg_rec *)base;
am_srv_cfg_rec *new_cfg;
new_cfg = (am_srv_cfg_rec *)apr_palloc(p, sizeof(*new_cfg));
new_cfg->mc = base_cfg->mc;
#ifdef ENABLE_DIAGNOSTICS
am_srv_cfg_rec *add_cfg = (am_srv_cfg_rec *)add;
new_cfg->diag_cfg.filename = (add_cfg->diag_cfg.filename !=
default_diag_filename ?
add_cfg->diag_cfg.filename :
base_cfg->diag_cfg.filename);
new_cfg->diag_cfg.fd = NULL;
new_cfg->diag_cfg.flags = (add_cfg->diag_cfg.flags !=
default_diag_flags ?
add_cfg->diag_cfg.flags :
base_cfg->diag_cfg.flags);
new_cfg->diag_cfg.dir_cfg_emitted = apr_table_make(p, 0);
#endif
return new_cfg;
}

1017
auth_mellon_diagnostics.c Normal file

File diff suppressed because it is too large Load Diff

View File

@ -121,6 +121,8 @@ static char *am_generate_metadata(apr_pool_t *p, request_rec *r)
char *cert = "";
const char *sp_entity_id;
am_diag_printf(r, "Generating SP metadata\n");
sp_entity_id = cfg->sp_entity_id ? cfg->sp_entity_id : url;
if (cfg->sp_cert_file && cfg->sp_cert_file->contents) {
@ -251,6 +253,13 @@ static guint am_server_add_providers(am_dir_cfg_rec *cfg, request_rec *r)
idp_metadata = &( ((const am_metadata_t*)cfg->idp_metadata->elts) [index] );
am_diag_log_file_data(r, 0, idp_metadata->metadata,
"Loading IdP Metadata");
if (idp_metadata->chain) {
am_diag_log_file_data(r, 0, idp_metadata->chain,
"Loading IdP metadata chain");
}
#ifdef HAVE_lasso_server_load_metadata
error = lasso_server_load_metadata(cfg->server,
LASSO_PROVIDER_ROLE_IDP,
@ -674,6 +683,9 @@ static void am_restore_lasso_profile_state(request_rec *r,
am_release_request_session(r, am_session);
}
}
am_diag_log_cache_entry(r, 0, am_session, "%s: Session Cache Entry", __func__);
am_diag_log_profile(r, 0, profile, "%s: Restored Profile", __func__);
}
/* This function handles an IdP initiated logout request.
@ -693,6 +705,8 @@ static int am_handle_logout_request(request_rec *r,
am_cache_entry_t *session = NULL;
am_dir_cfg_rec *cfg = am_get_dir_cfg(r);
am_diag_printf(r, "enter function %s\n", __func__);
/* Process the logout message. Ignore missing signature. */
res = lasso_logout_process_request_msg(logout, msg);
#ifdef HAVE_lasso_profile_set_signature_verify_hint
@ -724,6 +738,10 @@ static int am_handle_logout_request(request_rec *r,
rc = HTTP_BAD_REQUEST;
goto exit;
}
am_diag_printf(r, "%s name id %s\n", __func__,
((LassoSaml2NameID*)logout->parent.nameIdentifier)->content);
session = am_get_request_session_by_nameid(r,
((LassoSaml2NameID*)logout->parent.nameIdentifier)->content);
if (session == NULL) {
@ -733,6 +751,9 @@ static int am_handle_logout_request(request_rec *r,
((LassoSaml2NameID*)logout->parent.nameIdentifier)->content);
}
am_diag_log_cache_entry(r, 0, session, "%s", __func__);
if (session == NULL) {
ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
"Error processing logout request message."
@ -830,6 +851,9 @@ static int am_handle_logout_response(request_rec *r, LassoLogout *logout)
/* Delete the session. */
session = am_get_request_session(r);
am_diag_log_cache_entry(r, 0, session, "%s\n", __func__);
if(session != NULL) {
am_delete_request_session(r, session);
}
@ -1482,6 +1506,9 @@ static void am_handle_session_expire(request_rec *r, am_cache_entry_t *session,
/* Find timestamp. */
not_on_or_after = authn->SessionNotOnOrAfter;
if(not_on_or_after == NULL) {
am_diag_printf(r, "%s failed to find"
" Assertion.AuthnStatement.SessionNotOnOrAfter\n",
__func__);
continue;
}
@ -1492,6 +1519,10 @@ static void am_handle_session_expire(request_rec *r, am_cache_entry_t *session,
continue;
}
am_diag_printf(r, "%s Assertion.AuthnStatement.SessionNotOnOrAfter:"
" %s\n",
__func__, am_diag_time_t_to_8601(r, t));
/* Updates the expires timestamp if this one is earlier than the
* previous timestamp.
*/
@ -1629,6 +1660,10 @@ static int add_attributes(am_cache_entry_t *session, request_rec *r,
g_free(dump);
}
/* Decode and save the attribute. */
am_diag_printf(r, "%s name=%s value=%s\n",
__func__, attribute->Name, content);
ret = am_cache_env_append(session, attribute->Name, content);
if(ret != OK) {
return ret;
@ -1725,6 +1760,9 @@ static int am_handle_reply_common(request_rec *r, LassoLogin *login,
int rc;
const char *idp;
am_diag_log_lasso_node(r, 0, LASSO_PROFILE(login)->response,
"SAMLResponse:");
url = am_reconstruct_url(r);
chr = strchr(url, '?');
if (! chr) {
@ -1867,7 +1905,6 @@ static int am_handle_reply_common(request_rec *r, LassoLogin *login,
return HTTP_INTERNAL_SERVER_ERROR;
}
/* Save the profile state. */
rc = am_save_lasso_profile_state(r, session, LASSO_PROFILE(login),
saml_response);
@ -1941,6 +1978,8 @@ static int am_handle_post_reply(request_rec *r)
am_dir_cfg_rec *dir_cfg = am_get_dir_cfg(r);
int i, err;
am_diag_printf(r, "enter function %s\n", __func__);
/* Make sure that this is a POST request. */
if(r->method_number != M_POST) {
ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
@ -2050,6 +2089,8 @@ static int am_handle_paos_reply(request_rec *r)
char *relay_state = NULL;
int i, err;
am_diag_printf(r, "enter function %s\n", __func__);
/* Make sure that this is a POST request. */
if(r->method_number != M_POST) {
ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
@ -2137,6 +2178,8 @@ static int am_handle_artifact_reply(request_rec *r)
char *saml_art;
char *post_data;
am_diag_printf(r, "enter function %s\n", __func__);
/* Make sure that this is a GET request. */
if(r->method_number != M_GET && r->method_number != M_POST) {
ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
@ -2408,6 +2451,8 @@ static int am_handle_repost(request_rec *r)
const char *(*post_mkform)(request_rec *, const char *);
int rc;
am_diag_printf(r, "enter function %s\n", __func__);
if (am_cookie_get(r) == NULL) {
ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
"Repost query without a session");
@ -2570,6 +2615,8 @@ static int am_handle_metadata(request_rec *r)
LassoServer *server;
const char *data;
am_diag_printf(r, "enter function %s\n", __func__);
server = am_get_lasso_server(r);
if(server == NULL)
return HTTP_INTERNAL_SERVER_ERROR;
@ -2898,6 +2945,11 @@ static int am_init_authn_request_common(request_rec *r,
static int am_set_authn_request_content(request_rec *r, LassoLogin *login)
{
am_diag_log_lasso_node(r, 0, LASSO_PROFILE(login)->request,
"SAML AuthnRequest: http_method=%s",
am_diag_lasso_http_method_str(login->http_method));
switch (login->http_method) {
case LASSO_HTTP_METHOD_REDIRECT:
return am_set_authn_request_redirect_content(r, login);
@ -3112,6 +3164,8 @@ static int am_handle_auth(request_rec *r)
am_dir_cfg_rec *cfg = am_get_dir_cfg(r);
const char *relay_state;
am_diag_printf(r, "enter function %s\n", __func__);
relay_state = am_reconstruct_url(r);
/* Check if IdP discovery is in use and no IdP was selected yet */
@ -3151,6 +3205,8 @@ static int am_handle_login(request_rec *r)
int is_passive;
int ret;
am_diag_printf(r, "enter function %s\n", __func__);
return_to = am_extract_query_parameter(r->pool, r->args, "ReturnTo");
if(return_to == NULL) {
ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
@ -3255,6 +3311,8 @@ static int am_handle_probe_discovery(request_rec *r) {
char *redirect_url;
int ret;
am_diag_printf(r, "enter function %s\n", __func__);
server = am_get_lasso_server(r);
if(server == NULL) {
return HTTP_INTERNAL_SERVER_ERROR;
@ -3488,6 +3546,8 @@ static int am_start_auth(request_rec *r)
const char *idp;
const char *login_url;
am_diag_printf(r, "enter function %s\n", __func__);
return_to = am_reconstruct_url(r);
/* If this is a POST request, attempt to save it */
@ -3539,6 +3599,8 @@ int am_auth_mellon_user(request_rec *r)
return DECLINED;
}
am_diag_printf(r, "enter function %s\n", __func__);
/* Set defaut Cache-Control headers within this location */
if (CFG_VALUE(dir, send_cache_control_header)) {
am_set_cache_control_headers(r);
@ -3563,6 +3625,9 @@ int am_auth_mellon_user(request_rec *r)
if(session == NULL || !session->logged_in) {
/* We don't have a valid session. */
am_diag_printf(r, "%s am_enable_auth, no valid session\n",
__func__);
if(session) {
/* Release the session. */
am_release_request_session(r, session);
@ -3613,9 +3678,14 @@ int am_auth_mellon_user(request_rec *r)
#endif /* HAVE_ECP */
}
am_diag_printf(r, "%s am_enable_auth, have valid session\n",
__func__);
/* Verify that the user has access to this resource. */
return_code = am_check_permissions(r, session);
if(return_code != OK) {
am_diag_printf(r, "%s failed am_check_permissions, status=%d\n",
__func__, return_code);
am_release_request_session(r, session);
return return_code;
@ -3643,11 +3713,17 @@ int am_auth_mellon_user(request_rec *r)
&& session->logged_in
&& am_check_permissions(r, session) == OK) {
am_diag_printf(r, "%s am_enable_info, have valid session\n",
__func__);
/* The user is authenticated and has access to the resource.
* Now we populate the environment with information about
* the user.
*/
am_cache_env_populate(r, session);
} else {
am_diag_printf(r, "%s am_enable_info, no valid session\n",
__func__);
}
if(session != NULL) {
@ -3688,6 +3764,8 @@ int am_check_uid(request_rec *r)
return DECLINED;
}
am_diag_printf(r, "enter function %s\n", __func__);
#ifdef HAVE_ECP
am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
if (req_cfg->ecp_authn_req) {
@ -3744,11 +3822,15 @@ int am_check_uid(request_rec *r)
/* If we don't have a session, then we can't authorize the user. */
if(session == NULL) {
am_diag_printf(r, "%s no session, return HTTP_UNAUTHORIZED\n",
__func__);
return HTTP_UNAUTHORIZED;
}
/* If the user isn't logged in, then we can't authorize the user. */
if(!session->logged_in) {
am_diag_printf(r, "%s session not logged in,"
" return HTTP_UNAUTHORIZED\n", __func__);
am_release_request_session(r, session);
return HTTP_UNAUTHORIZED;
}
@ -3756,6 +3838,8 @@ int am_check_uid(request_rec *r)
/* Verify that the user has access to this resource. */
return_code = am_check_permissions(r, session);
if(return_code != OK) {
am_diag_printf(r, "%s failed am_check_permissions, status=%d\n",
__func__, return_code);
am_release_request_session(r, session);
return return_code;
}

View File

@ -39,9 +39,18 @@ am_cache_entry_t *am_lock_and_validate(request_rec *r,
am_cache_key_t type,
const char *key)
{
am_cache_entry_t *session = am_cache_lock(r, type, key);
am_cache_entry_t *session = NULL;
am_diag_printf(r, "searching for session with key %s (%s) ... ",
key, am_diag_cache_key_type_str(type));
session = am_cache_lock(r, type, key);
if (session == NULL) {
am_diag_printf(r, "not found\n");
return NULL;
} else {
am_diag_printf(r, "found.\n");
am_diag_log_cache_entry(r, 0, session, "Session Cache Entry");
}
const char *cookie_token_session = am_cache_entry_get_string(
@ -123,6 +132,10 @@ am_cache_entry_t *am_new_request_session(request_rec *r)
am_cookie_set(r, session_id);
const char *cookie_token = am_cookie_token(r);
am_diag_printf(r, "%s id=%s cookie_token=\"%s\"\n",
__func__, session_id, cookie_token);
return am_cache_new(r, session_id, cookie_token);
}
@ -155,6 +168,8 @@ void am_release_request_session(request_rec *r, am_cache_entry_t *session)
*/
void am_delete_request_session(request_rec *r, am_cache_entry_t *session)
{
am_diag_log_cache_entry(r, 0, session, "delete session");
/* Delete the cookie. */
am_cookie_delete(r);

View File

@ -370,6 +370,10 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
ce = &((am_cond_t *)(dir_cfg->cond->elts))[i];
am_diag_printf(r, "%s processing condition %d of %d: %s ",
__func__, i, dir_cfg->cond->nelts,
am_diag_cond_str(r, ce));
/*
* Rule with ignore flog?
*/
@ -384,9 +388,11 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
if (!(ce->flags & AM_COND_FLAG_OR))
skip_or = 0;
ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
"Skip %s, [OR] rule matched previously",
ce->directive);
ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
"Skip %s, [OR] rule matched previously",
ce->directive);
am_diag_printf(r, "Skip, [OR] rule matched previously\n");
continue;
}
@ -433,6 +439,8 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
"Evaluate %s vs \"%s\"",
ce->directive, value);
am_diag_printf(r, "evaluate value \"%s\" ", value);
if (value == NULL) {
match = 0; /* can not happen */
@ -463,11 +471,16 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
} else {
match = !strcmp(ce->str, value);
}
am_diag_printf(r, "match=%s, ", match ? "yes" : "no");
}
if (ce->flags & AM_COND_FLAG_NOT)
if (ce->flags & AM_COND_FLAG_NOT) {
match = !match;
am_diag_printf(r, "negating now match=%s ", match ? "yes" : "no");
}
ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
"%s: %smatch", ce->directive,
(match == 0) ? "no ": "");
@ -479,6 +492,9 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
ap_log_rerror(APLOG_MARK, APLOG_NOTICE, 0, r,
"Client failed to match %s",
ce->directive);
am_diag_printf(r, "failed (no OR condition)"
" returning HTTP_FORBIDDEN\n");
return HTTP_FORBIDDEN;
}
@ -488,8 +504,12 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
*/
if (match && (ce->flags & AM_COND_FLAG_OR))
skip_or = 1;
am_diag_printf(r, "\n");
}
am_diag_printf(r, "%s succeeds\n", __func__);
return OK;
}

View File

@ -41,6 +41,16 @@ The executable may also be named 'apxs'.
])
fi
AC_ARG_ENABLE(
[diagnostics],
[AS_HELP_STRING([--enable-diagnostics],
[Build with diagnostic support])],
[],
[enable_diagnostics=no])
AS_IF([test "x$enable_diagnostics" != xno],
[MELLON_CFLAGS="$MELLON_CFLAGS -DENABLE_DIAGNOSTICS"])
# Replace any occurances of @APXS2@ with the value of $APXS2 in the Makefile.
AC_SUBST(APXS2)
@ -74,6 +84,8 @@ PKG_CHECK_MODULES([GLIB], [glib-2.0 >= 2.12])
AC_SUBST(GLIB_CFLAGS)
AC_SUBST(GLIB_LIBS)
AC_SUBST(MELLON_CFLAGS)
# Test to see if we can include lasso/utils.h
# AC_CHECK_HEADER won't work correctly unless we specifiy the include directories
# found in the LASSO_CFLAGS. Save and restore CFLAGS and CPPFLAGS.

View File

@ -195,6 +195,9 @@ static int am_create_request(request_rec *r)
#ifdef HAVE_ECP
req_cfg->ecp_authn_req = false;
#endif /* HAVE_ECP */
#ifdef ENABLE_DIAGNOSTICS
req_cfg->diag_emitted = false;
#endif
ap_set_module_config(r->request_config, &auth_mellon_module, req_cfg);
@ -220,6 +223,11 @@ static void register_hooks(apr_pool_t *p)
* r->handler and decide that it is the only handler for this URL.
*/
ap_hook_handler(am_handler, NULL, NULL, APR_HOOK_FIRST);
#ifdef ENABLE_DIAGNOSTICS
ap_hook_open_logs(am_diag_log_init,NULL,NULL,APR_HOOK_MIDDLE);
ap_hook_log_transaction(am_diag_finalize_request,NULL,NULL,APR_HOOK_REALLY_LAST);
#endif
}
@ -229,7 +237,7 @@ module AP_MODULE_DECLARE_DATA auth_mellon_module =
auth_mellon_dir_config,
auth_mellon_dir_merge,
auth_mellon_server_config,
NULL,
auth_mellon_srv_merge,
auth_mellon_commands,
register_hooks
};