modmellon/auth_mellon_diagnostics.c

1148 lines
39 KiB
C

#include "auth_mellon.h"
#ifdef ENABLE_DIAGNOSTICS
#if APR_HAVE_UNISTD_H
#include <unistd.h>
#endif
#if APR_HAVE_PROCESS_H
#include <process.h> /* for getpid() on Win32 */
#endif
/*============================= Internal Static ==============================*/
/*------------------ Defines ------------------*/
#define AM_DIAG_ENABLED(diag_cfg) \
(diag_cfg && diag_cfg->fd && (diag_cfg->flags & AM_DIAG_FLAG_ENABLED))
/*------------------ Typedefs ------------------*/
typedef struct iter_callback_data {
apr_file_t *diag_fd;
int level;
} iter_callback_data;
/*------------------ Prototypes ------------------*/
static const char *
indent(int level);
static void
write_indented_text(apr_file_t *diag_fd, int level, const char* text);
static void
am_diag_format_line(apr_pool_t *pool, apr_file_t *diag_fd, int level,
const char *fmt, va_list ap);
static const char *
am_diag_cond_flag_str(request_rec *r, am_cond_flag_t flags);
static const char *
am_diag_enable_str(request_rec *r, am_enable_t enable);
static const char *
am_diag_samesite_str(request_rec *r, am_samesite_t samesite);
static const char *
am_diag_httpd_error_level_str(request_rec *r, int level);
static const char *
am_diag_signature_method_str(request_rec *r,
LassoSignatureMethod signature_method);
static apr_size_t
am_diag_time_t_to_8601_buf(char *buf, apr_size_t buf_size, apr_time_t t);
static int
am_diag_open_log(server_rec *s, apr_pool_t *p);
static int
am_table_count(void *rec, const char *key, const char *value);
static int
log_headers(void *rec, const char *key, const char *value);
static int
log_probe_discovery_idp(void *rec, const char *key, const char *value);
static void
am_diag_log_dir_cfg(request_rec *r, int level, am_dir_cfg_rec *cfg,
const char *fmt, ...)
__attribute__((format(printf,4,5)));
static bool
am_diag_initialize_req(request_rec *r, am_diag_cfg_rec *diag_cfg,
am_req_cfg_rec *req_cfg);
/*------------------ Functions ------------------*/
static const char *
indent(int level)
{
static const char * const indents[] = {
"", /* 0 */
" ", /* 1 */
" ", /* 2 */
" ", /* 3 */
" ", /* 4 */
" ", /* 5 */
" ", /* 6 */
" ", /* 7 */
" ", /* 8 */
" ", /* 9 */
};
int n_indents = sizeof(indents)/sizeof(indents[0]);
if (level < 0) {
return "";
}
if (level < n_indents) {
return indents[level];
}
return indents[n_indents-1];
}
static void
write_indented_text(apr_file_t *diag_fd, int level, const char* text)
{
const char *start, *end, *prefix;
size_t len, prefix_len;
bool crlf = false;
if (!text) return;
prefix = indent(level);
prefix_len = strlen(prefix);
start = end = text;
while (*end) {
/* find end of line */
for (; *end && *end != '\n'; end++);
if (*end == '\n') {
/* was this a crlf sequence? */
if (end > text && end[-1] == '\r') crlf = true;
/* advance past line ending */
end += 1;
}
/* length of line including line ending */
len = end - start;
/* write indent prefix */
apr_file_write_full(diag_fd, prefix, prefix_len, NULL);
/* write line including line ending */
apr_file_write_full(diag_fd, start, len, NULL);
/* begin again where we left off */
start = end;
}
/* always write a trailing line ending */
if (end > text && end[-1] != '\n') {
if (crlf) {
apr_file_write_full(diag_fd, "\r\n", 2, NULL);
} else {
apr_file_write_full(diag_fd, "\n", 1, NULL);
}
}
}
static void
am_diag_format_line(apr_pool_t *pool, apr_file_t *diag_fd, int level,
const char *fmt, va_list ap)
{
char * buf = NULL;
apr_size_t buf_len;
if (fmt) {
buf = apr_pvsprintf(pool, fmt, ap);
buf_len = strlen(buf);
if (buf_len > 0) {
const char *prefix = indent(level);
apr_size_t prefix_len = strlen(prefix);
apr_file_write_full(diag_fd, prefix, prefix_len, NULL);
apr_file_write_full(diag_fd, buf, buf_len, NULL);
apr_file_putc('\n', diag_fd);
}
}
}
static const char *
am_diag_cond_flag_str(request_rec *r, am_cond_flag_t flags)
{
char *str;
char *comma;
str = apr_pstrcat(r->pool,
"[",
flags & AM_COND_FLAG_OR ? "OR," : "",
flags & AM_COND_FLAG_NOT ? "NOT," : "",
flags & AM_COND_FLAG_REG ? "REG," : "",
flags & AM_COND_FLAG_NC ? "NC," : "",
flags & AM_COND_FLAG_MAP ? "MAP," : "",
flags & AM_COND_FLAG_REF ? "REF," : "",
flags & AM_COND_FLAG_SUB ? "SUB," : "",
flags & AM_COND_FLAG_IGN ? "IGN," : "",
flags & AM_COND_FLAG_REQ ? "REQ," : "",
flags & AM_COND_FLAG_FSTR ? "FSTR," : "",
"]",
NULL);
/* replace trailing ",]" with "]" */
comma = rindex(str, ',');
if (comma) {
*comma = ']';
*(comma+1) = 0;
}
return str;
}
static const char *
am_diag_enable_str(request_rec *r, am_enable_t enable)
{
switch(enable) {
case am_enable_default: return "default";
case am_enable_off: return "off";
case am_enable_info: return "info";
case am_enable_auth: return "auth";
default:
return apr_psprintf(r->pool, "unknown (%d)", enable);
}
}
static const char *
am_diag_samesite_str(request_rec *r, am_samesite_t samesite)
{
switch(samesite) {
case am_samesite_default: return "default";
case am_samesite_lax: return "lax";
case am_samesite_strict: return "strict";
default:
return apr_psprintf(r->pool, "unknown (%d)", samesite);
}
}
static const char *
am_diag_httpd_error_level_str(request_rec *r, int level)
{
switch(level) {
case APLOG_EMERG: return "APLOG_EMERG";
case APLOG_ALERT: return "APLOG_ALERT";
case APLOG_CRIT: return "APLOG_CRIT";
case APLOG_ERR: return "APLOG_ERR";
case APLOG_WARNING: return "APLOG_WARNING";
case APLOG_NOTICE: return "APLOG_NOTICE";
case APLOG_INFO: return "APLOG_INFO";
case APLOG_DEBUG: return "APLOG_DEBUG";
case APLOG_TRACE1: return "APLOG_TRACE1";
case APLOG_TRACE2: return "APLOG_TRACE2";
case APLOG_TRACE3: return "APLOG_TRACE3";
case APLOG_TRACE4: return "APLOG_TRACE4";
case APLOG_TRACE5: return "APLOG_TRACE5";
case APLOG_TRACE6: return "APLOG_TRACE6";
case APLOG_TRACE7: return "APLOG_TRACE7";
case APLOG_TRACE8: return "APLOG_TRACE8";
default:
return apr_psprintf(r->pool, "APLOG_%d", level);
}
}
static const char *
am_diag_signature_method_str(request_rec *r,
LassoSignatureMethod signature_method)
{
switch(signature_method) {
case LASSO_SIGNATURE_METHOD_RSA_SHA1: return "rsa-sha1";
#if HAVE_DECL_LASSO_SIGNATURE_METHOD_RSA_SHA256
case LASSO_SIGNATURE_METHOD_RSA_SHA256: return "rsa-sha256";
#endif
#if HAVE_DECL_LASSO_SIGNATURE_METHOD_RSA_SHA384
case LASSO_SIGNATURE_METHOD_RSA_SHA384: return "rsa-sha384";
#endif
#if HAVE_DECL_LASSO_SIGNATURE_METHOD_RSA_SHA512
case LASSO_SIGNATURE_METHOD_RSA_SHA512: return "rsa-sha512";
#endif
default:
return apr_psprintf(r->pool, "unknown (%d)", signature_method);
}
}
static apr_size_t
am_diag_time_t_to_8601_buf(char *buf, apr_size_t buf_size, apr_time_t t)
{
apr_size_t ret_size;
apr_time_exp_t tm;
const char fmt[] = "%FT%TZ";
apr_time_exp_gmt(&tm, t);
apr_strftime(buf, &ret_size, buf_size, fmt, &tm);
/* on errror assure string is null terminated */
if (ret_size == 0) buf[0] = 0;
return ret_size;
}
static int
am_diag_open_log(server_rec *s, apr_pool_t *p)
{
const char *server_name = NULL;
const char *server_desc = NULL;
am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(s);
/* Build the ServerName as it would appear in the ServerName directive */
if (s->server_scheme) {
server_name = apr_psprintf(p, "%s://%s",
s->server_scheme, s->server_hostname);
} else {
server_name = apr_psprintf(p, "%s", s->server_hostname);
}
if (s->port) {
server_name = apr_psprintf(p, "%s:%u", server_name, s->port);
}
if (s->is_virtual) {
server_desc = apr_psprintf(p, "virtual server %s:%d (%s:%u)"
" ServerName=%s",
s->addrs->virthost, s->addrs->host_port,
s->defn_name, s->defn_line_number,
server_name);
} else {
server_desc = apr_psprintf(p, "main server, ServerName=%s",
server_name);
}
if (!(diag_cfg->flags & AM_DIAG_FLAG_ENABLED)) {
ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s,
"mellon diagnostics disabled for %s", server_desc);
return 1;
} else {
ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s,
"mellon diagnostics enabled for %s, "
"diagnostics filename=%s",
server_desc, diag_cfg->filename);
}
if (!diag_cfg->filename || diag_cfg->fd)
return 1;
if (*diag_cfg->filename == '|') {
piped_log *pl;
const char *pname = ap_server_root_relative(p, diag_cfg->filename + 1);
pl = ap_open_piped_log(p, pname);
if (pl == NULL) {
ap_log_error(APLOG_MARK, APLOG_ERR, 0, s,
"couldn't spawn mellon diagnostics log pipe %s",
diag_cfg->filename);
return 0;
}
diag_cfg->fd = ap_piped_log_write_fd(pl);
}
else {
const char *fname = ap_server_root_relative(p, diag_cfg->filename);
apr_status_t rv;
if ((rv = apr_file_open(&diag_cfg->fd, fname,
APR_WRITE | APR_APPEND | APR_CREATE,
APR_OS_DEFAULT, p)) != APR_SUCCESS) {
ap_log_error(APLOG_MARK, APLOG_ERR, rv, s,
"could not open mellon diagnostics log file %s.",
fname);
return 0;
}
}
return 1;
}
static int
am_table_count(void *rec, const char *key, const char *value)
{
int *n_items = (int *)rec;
(*n_items)++;
return 1;
}
static int
log_headers(void *rec, const char *key, const char *value)
{
iter_callback_data *iter_data = (iter_callback_data *)rec;
apr_file_printf(iter_data->diag_fd, "%s%s: %s\n",
indent(iter_data->level), key, value);
return 1;
}
static int
log_probe_discovery_idp(void *rec, const char *key, const char *value)
{
iter_callback_data *iter_data = (iter_callback_data *)rec;
apr_file_printf(iter_data->diag_fd,
"%s%s: %s\n", indent(iter_data->level), key, value);
return 1;
}
static void
am_diag_log_dir_cfg(request_rec *r, int level, am_dir_cfg_rec *cfg,
const char *fmt, ...)
{
va_list ap;
am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
int i, n_items;
apr_hash_index_t *hash_item;
GList *list_item;
iter_callback_data iter_data;
if (!AM_DIAG_ENABLED(diag_cfg)) return;
if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
iter_data.diag_fd = diag_cfg->fd;
iter_data.level = level+1;
va_start(ap, fmt);
am_diag_format_line(r->pool, diag_cfg->fd, level, fmt, ap);
va_end(ap);
if (!cfg) {
apr_file_flush(diag_cfg->fd);
return;
}
apr_file_printf(diag_cfg->fd,
"%sMellonEnable (enable): %s\n",
indent(level+1), am_diag_enable_str(r, cfg->enable_mellon));
apr_file_printf(diag_cfg->fd,
"%sMellonVariable (varname): %s\n",
indent(level+1), cfg->varname);
apr_file_printf(diag_cfg->fd,
"%sMellonSecureCookie (secure): %s\n",
indent(level+1), cfg->secure ? "On":"Off"); /* FIXME, should be combined? */
apr_file_printf(diag_cfg->fd,
"%sMellonSecureCookie (httpd_only): %s\n",
indent(level+1), cfg->http_only ? "On":"Off");
apr_file_printf(diag_cfg->fd,
"%sMellonMergeEnvVars (merge_env_vars): %s\n",
indent(level+1), cfg->merge_env_vars);
apr_file_printf(diag_cfg->fd,
"%sMellonEnvVarsIndexStart (env_vars_index_start): %d\n",
indent(level+1), cfg->env_vars_index_start);
apr_file_printf(diag_cfg->fd,
"%sMellonEnvVarsSetCount (env_vars_count_in_n): %s\n",
indent(level+1), cfg->env_vars_count_in_n ? "On":"Off");
apr_file_printf(diag_cfg->fd,
"%sMellonCookieDomain (cookie_domain): %s\n",
indent(level+1), cfg->cookie_domain);
apr_file_printf(diag_cfg->fd,
"%sMellonCookiePath (cookie_path): %s\n",
indent(level+1), cfg->cookie_path);
apr_file_printf(diag_cfg->fd,
"%sMellonCookieSameSite (cookie_samesite): %s\n",
indent(level+1),
am_diag_samesite_str(r, cfg->cookie_samesite));
apr_file_printf(diag_cfg->fd,
"%sMellonEnvPrefix (env_prefix): %s\n",
indent(level+1), cfg->env_prefix);
apr_file_printf(diag_cfg->fd,
"%sMellonCond (cond): %d items\n",
indent(level+1), cfg->cond->nelts);
for (i = 0; i < cfg->cond->nelts; i++) {
const am_cond_t *cond = &((am_cond_t *)(cfg->cond->elts))[i];
apr_file_printf(diag_cfg->fd,
"%s[%2d]: %s\n",
indent(level+2), i, am_diag_cond_str(r, cond));
}
apr_file_printf(diag_cfg->fd,
"%sMellonSetEnv (envattr): %u items\n",
indent(level+1), apr_hash_count(cfg->envattr));
for (hash_item = apr_hash_first(r->pool, cfg->envattr);
hash_item;
hash_item = apr_hash_next(hash_item)) {
const char *key;
const am_envattr_conf_t *envattr_conf;
const char *name;
apr_hash_this(hash_item, (void *)&key, NULL, (void *)&envattr_conf);
if (envattr_conf->prefixed) {
name = apr_pstrcat(r->pool, cfg->env_prefix,
envattr_conf->name, NULL);
} else {
name = envattr_conf->name;
}
apr_file_printf(diag_cfg->fd,
"%s%s ==> %s\n",
indent(level+2), key, name);
}
apr_file_printf(diag_cfg->fd,
"%sMellonUser (userattr): %s\n",
indent(level+1), cfg->userattr);
apr_file_printf(diag_cfg->fd,
"%sMellonIdP (idpattr): %s\n",
indent(level+1), cfg->idpattr);
apr_file_printf(diag_cfg->fd,
"%sMellonSessionDump (dump_session): %s\n",
indent(level+1), cfg->dump_session ? "On":"Off");
apr_file_printf(diag_cfg->fd,
"%sMellonSamlResponseDump (dump_saml_response): %s\n",
indent(level+1), cfg->dump_saml_response ? "On":"Off");
apr_file_printf(diag_cfg->fd,
"%sMellonEndpointPath (endpoint_path): %s\n",
indent(level+1), cfg->endpoint_path);
am_diag_log_file_data(r, level+1, cfg->sp_metadata_file,
"MellonSPMetadataFile (sp_metadata_file):");
am_diag_log_file_data(r, level+1, cfg->sp_private_key_file,
"MellonSPPrivateKeyFile (sp_private_key_file):");
am_diag_log_file_data(r, level+1, cfg->sp_cert_file,
"MellonSPCertFile (sp_cert_file):");
am_diag_log_file_data(r, level+1, cfg->idp_public_key_file,
"MellonIdPPublicKeyFile (idp_public_key_file):");
am_diag_log_file_data(r, level+1, cfg->idp_ca_file,
"MellonIdPCAFile (idp_ca_file):");
apr_file_printf(diag_cfg->fd,
"%sMellonIdPMetadataFile (idp_metadata): %d items\n",
indent(level+1), cfg->idp_metadata->nelts);
for (i = 0; i < cfg->idp_metadata->nelts; i++) {
const am_metadata_t *idp_metadata;
idp_metadata = &(((const am_metadata_t*)cfg->idp_metadata->elts)[i]);
am_diag_log_file_data(r, level+1, idp_metadata->metadata,
"[%2d] Metadata", i);
am_diag_log_file_data(r, level+1, idp_metadata->chain,
"[%2d] Chain File", i);
}
apr_file_printf(diag_cfg->fd,
"%sMellonIdPIgnore (idp_ignore):\n",
indent(level+1));
for (list_item = cfg->idp_ignore, i = 0;
list_item;
list_item = g_list_next(list_item), i++) {
apr_file_printf(diag_cfg->fd,
"%s[%2d]: %s\n",
indent(level+2), i, (char *)list_item->data);
}
apr_file_printf(diag_cfg->fd,
"%sMellonSPentityId (sp_entity_id): %s\n",
indent(level+1), cfg->sp_entity_id);
apr_file_printf(diag_cfg->fd,
"%sMellonOrganizationName (sp_org_name): %u items\n",
indent(level+1), apr_hash_count(cfg->sp_org_name));
for (hash_item = apr_hash_first(r->pool, cfg->sp_org_name);
hash_item;
hash_item = apr_hash_next(hash_item)) {
const char *lang;
const char *value;
apr_hash_this(hash_item, (void *)&lang, NULL, (void *)&value);
apr_file_printf(diag_cfg->fd,
"%s(lang=%s): %s\n",
indent(level+2), lang, value);
}
apr_file_printf(diag_cfg->fd,
"%sMellonOrganizationDisplayName (sp_org_display_name):"
" %u items\n",
indent(level+1), apr_hash_count(cfg->sp_org_display_name));
for (hash_item = apr_hash_first(r->pool, cfg->sp_org_display_name);
hash_item;
hash_item = apr_hash_next(hash_item)) {
const char *lang;
const char *value;
apr_hash_this(hash_item, (void *)&lang, NULL, (void *)&value);
apr_file_printf(diag_cfg->fd,
"%s(lang=%s): %s\n",
indent(level+2), lang, value);
}
apr_file_printf(diag_cfg->fd,
"%sMellonOrganizationURL (sp_org_url): %u items\n",
indent(level+1), apr_hash_count(cfg->sp_org_url));
for (hash_item = apr_hash_first(r->pool, cfg->sp_org_url);
hash_item;
hash_item = apr_hash_next(hash_item)) {
const char *lang;
const char *value;
apr_hash_this(hash_item, (void *)&lang, NULL, (void *)&value);
apr_file_printf(diag_cfg->fd,
"%s(lang=%s): %s\n",
indent(level+2), lang, value);
}
apr_file_printf(diag_cfg->fd,
"%sMellonSessionLength (session_length): %d\n",
indent(level+1), cfg->session_length);
apr_file_printf(diag_cfg->fd,
"%sMellonNoCookieErrorPage (no_cookie_error_page): %s\n",
indent(level+1), cfg->no_cookie_error_page);
apr_file_printf(diag_cfg->fd,
"%sMellonNoSuccessErrorPage (no_success_error_page): %s\n",
indent(level+1), cfg->no_success_error_page);
apr_file_printf(diag_cfg->fd,
"%sMellonDefaultLoginPath (login_path): %s\n",
indent(level+1), cfg->login_path);
apr_file_printf(diag_cfg->fd,
"%sMellonDiscoveryURL (discovery_url): %s\n",
indent(level+1), cfg->discovery_url);
apr_file_printf(diag_cfg->fd,
"%sMellonProbeDiscoveryTimeout (probe_discovery_timeout):"
" %d\n",
indent(level+1), cfg->probe_discovery_timeout);
n_items = 0;
apr_table_do(am_table_count, &n_items, cfg->probe_discovery_idp, NULL);
apr_file_printf(diag_cfg->fd,
"%sMellonProbeDiscoveryIdP (probe_discovery_idp):"
" %d items\n",
indent(level+1), n_items);
apr_table_do(log_probe_discovery_idp, &iter_data,
cfg->probe_discovery_idp, NULL);
apr_file_printf(diag_cfg->fd,
"%sMellonAuthnContextClassRef (authn_context_class_ref):"
" %d items\n",
indent(level+1), cfg->authn_context_class_ref->nelts);
for(i = 0; i < cfg->authn_context_class_ref->nelts; i++) {
const char *context_class;
context_class = APR_ARRAY_IDX(cfg->authn_context_class_ref, i, char *);
apr_file_printf(diag_cfg->fd,
"%s[%2d]: %s\n",
indent(level+2), i, context_class);
}
apr_file_printf(diag_cfg->fd,
"%sMellonAuthnContextComparisonType (authn_context_comparison_type): %s\n",
indent(level+1), cfg->authn_context_comparison_type);
apr_file_printf(diag_cfg->fd,
"%sMellonSubjectConfirmationDataAddressCheck"
" (subject_confirmation_data_address_check): %s\n",
indent(level+1),
CFG_VALUE(cfg, subject_confirmation_data_address_check) ? "On":"Off");
apr_file_printf(diag_cfg->fd,
"%sMellonDoNotVerifyLogoutSignature"
" (do_not_verify_logout_signature): %u items\n",
indent(level+1),
apr_hash_count(cfg->do_not_verify_logout_signature));
for (hash_item = apr_hash_first(r->pool,
cfg->do_not_verify_logout_signature);
hash_item;
hash_item = apr_hash_next(hash_item)) {
const char *entity_id;
apr_hash_this(hash_item, (void *)&entity_id, NULL, NULL);
apr_file_printf(diag_cfg->fd,
"%s%s\n",
indent(level+2), entity_id);
}
apr_file_printf(diag_cfg->fd,
"%sMellonSendCacheControlHeader"
" (send_cache_control_header): %s\n",
indent(level+1),
CFG_VALUE(cfg, send_cache_control_header) ? "On":"Off");
apr_file_printf(diag_cfg->fd,
"%sMellonPostReplay (post_replay): %s\n",
indent(level+1), CFG_VALUE(cfg, post_replay) ? "On":"Off");
apr_file_printf(diag_cfg->fd,
"%sMellonECPSendIDPList (ecp_send_idplist): %s\n",
indent(level+1), CFG_VALUE(cfg, ecp_send_idplist) ? "On":"Off");
for (n_items = 0; cfg->redirect_domains[n_items] != NULL; n_items++);
apr_file_printf(diag_cfg->fd,
"%sMellonRedirectDomains (redirect_domains): %d items\n",
indent(level+1), n_items);
for (i = 0; cfg->redirect_domains[i] != NULL; i++) {
apr_file_printf(diag_cfg->fd,
"%s%s\n",
indent(level+2), cfg->redirect_domains[i]);
}
apr_file_printf(diag_cfg->fd,
"%sMellonSignatureMethod (signature_method): %s\n",
indent(level+1),
am_diag_signature_method_str(r, CFG_VALUE(cfg, signature_method)));
apr_file_flush(diag_cfg->fd);
}
static bool
am_diag_initialize_req(request_rec *r, am_diag_cfg_rec *diag_cfg,
am_req_cfg_rec *req_cfg)
{
server_rec *s = r->server;
am_dir_cfg_rec *dir_cfg;
apr_os_thread_t tid = apr_os_thread_current();
iter_callback_data iter_data;
int level = 0;
if (!diag_cfg) return false;
if (!diag_cfg->fd) return false;
if (!req_cfg) return false;
if (req_cfg->diag_emitted) return true;
iter_data.diag_fd = diag_cfg->fd;
iter_data.level = level+1;
apr_file_puts("---------------------------------- New Request"
" ---------------------------------\n", diag_cfg->fd);
apr_file_printf(diag_cfg->fd, "%s - %s\n", r->method, r->uri);
apr_file_printf(diag_cfg->fd, "log_id: %s\n", r->log_id);
apr_file_printf(diag_cfg->fd, "server: scheme=%s hostname=%s port=%d\n",
s->server_scheme, s->server_hostname, s->port);
apr_file_printf(diag_cfg->fd, "pid: %" APR_PID_T_FMT ", tid: %pT\n",
getpid(), &tid);
apr_file_printf(diag_cfg->fd, "unparsed_uri: %s\n", r->unparsed_uri);
apr_file_printf(diag_cfg->fd, "uri: %s\n", r->uri);
apr_file_printf(diag_cfg->fd, "path_info: %s\n", r->path_info);
apr_file_printf(diag_cfg->fd, "filename: %s\n", r->filename);
apr_file_printf(diag_cfg->fd, "query args: %s\n", r->args);
apr_file_printf(diag_cfg->fd, "Request Headers:\n");
apr_table_do(log_headers, &iter_data, r->headers_in, NULL);
req_cfg->diag_emitted = true;
/* Only emit directory configuration once */
if (!apr_table_get(diag_cfg->dir_cfg_emitted, r->uri)) {
dir_cfg = am_get_dir_cfg(r);
am_diag_log_dir_cfg(r, level, dir_cfg,
"Mellon Directory Configuration for URL: %s",
r->uri);
apr_table_set(diag_cfg->dir_cfg_emitted, r->uri, "1");
}
return true;
}
/*=============================== Public API =================================*/
int
am_diag_log_init(apr_pool_t *pc, apr_pool_t *p, apr_pool_t *pt, server_rec *s)
{
for ( ; s ; s = s->next) {
if (!am_diag_open_log(s, p)) {
return HTTP_INTERNAL_SERVER_ERROR;
}
}
return OK;
}
int
am_diag_finalize_request(request_rec *r)
{
am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
int level = 0;
iter_callback_data iter_data;
if (!AM_DIAG_ENABLED(diag_cfg)) return OK;
if (!req_cfg) return OK;
if (!req_cfg->diag_emitted) return OK;
iter_data.diag_fd = diag_cfg->fd;
iter_data.level = level+1;
apr_file_puts("\n=== Response ===\n", diag_cfg->fd);
apr_file_printf(diag_cfg->fd,
"Status: %s(%d)\n",
r->status_line, r->status);
apr_file_printf(diag_cfg->fd,
"user: %s auth_type=%s\n",
r->user, r->ap_auth_type);
apr_file_printf(diag_cfg->fd,
"Response Headers:\n");
apr_table_do(log_headers, &iter_data, r->headers_out, NULL);
apr_file_printf(diag_cfg->fd,
"Response Error Headers:\n");
apr_table_do(log_headers, &iter_data, r->err_headers_out, NULL);
apr_file_printf(diag_cfg->fd,
"Environment:\n");
apr_table_do(log_headers, &iter_data, r->subprocess_env, NULL);
return OK;
}
char *
am_diag_time_t_to_8601(request_rec *r, apr_time_t t)
{
char *buf;
buf = apr_palloc(r->pool, ISO_8601_BUF_SIZE);
if (!buf) return NULL;
am_diag_time_t_to_8601_buf(buf, ISO_8601_BUF_SIZE, t);
return buf;
}
const char *
am_diag_cond_str(request_rec *r, const am_cond_t *cond)
{
return apr_psprintf(r->pool,
"varname=\"%s\" flags=%s str=\"%s\" directive=\"%s\"",
cond->varname, am_diag_cond_flag_str(r, cond->flags),
cond->str, cond->directive);
}
const char *
am_diag_cache_key_type_str(am_cache_key_t key_type)
{
switch(key_type) {
case AM_CACHE_SESSION: return "session";
case AM_CACHE_NAMEID : return "name id";
default: return "unknown";
}
}
const char *
am_diag_lasso_http_method_str(LassoHttpMethod http_method)
{
switch(http_method) {
case LASSO_HTTP_METHOD_NONE: return "LASSO_HTTP_METHOD_NONE";
case LASSO_HTTP_METHOD_ANY: return "LASSO_HTTP_METHOD_ANY";
case LASSO_HTTP_METHOD_IDP_INITIATED: return "LASSO_HTTP_METHOD_IDP_INITIATED";
case LASSO_HTTP_METHOD_GET: return "LASSO_HTTP_METHOD_GET";
case LASSO_HTTP_METHOD_POST: return "LASSO_HTTP_METHOD_POST";
case LASSO_HTTP_METHOD_REDIRECT: return "LASSO_HTTP_METHOD_REDIRECT";
case LASSO_HTTP_METHOD_SOAP: return "LASSO_HTTP_METHOD_SOAP";
case LASSO_HTTP_METHOD_ARTIFACT_GET: return "LASSO_HTTP_METHOD_ARTIFACT_GET";
case LASSO_HTTP_METHOD_ARTIFACT_POST: return "LASSO_HTTP_METHOD_ARTIFACT_POST";
case LASSO_HTTP_METHOD_PAOS: return "LASSO_HTTP_METHOD_PAOS";
default: return "unknown";
}
}
void
am_diag_printf(request_rec *r, const char *fmt, ...)
{
va_list ap;
am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
char *buf;
apr_size_t buf_len;
if (!AM_DIAG_ENABLED(diag_cfg)) return;
if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
va_start(ap, fmt);
buf = apr_pvsprintf(r->pool, fmt, ap);
va_end(ap);
buf_len = strlen(buf);
if (buf_len > 0) {
apr_file_write_full(diag_cfg->fd, buf, buf_len, NULL);
}
apr_file_flush(diag_cfg->fd);
}
void
am_diag_rerror(const char *file, int line, int module_index,
int level, apr_status_t status,
request_rec *r, const char *fmt, ...)
{
va_list ap;
am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
char *buf;
if (!AM_DIAG_ENABLED(diag_cfg)) return;
if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
buf = apr_psprintf(r->pool, "[%s %s:%d] ",
am_diag_httpd_error_level_str(r, level), file, line);
apr_file_puts(buf, diag_cfg->fd);
va_start(ap, fmt);
buf = apr_pvsprintf(r->pool, fmt, ap);
va_end(ap);
apr_file_puts(buf, diag_cfg->fd);
apr_file_puts(APR_EOL_STR, diag_cfg->fd);
apr_file_flush(diag_cfg->fd);
}
void
am_diag_log_lasso_node(request_rec *r, int level, LassoNode *node,
const char *fmt, ...)
{
va_list ap;
am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
gchar *xml = NULL;
if (!AM_DIAG_ENABLED(diag_cfg)) return;
if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
va_start(ap, fmt);
am_diag_format_line(r->pool, diag_cfg->fd, level, fmt, ap);
va_end(ap);
if (node) {
xml = lasso_node_debug(node, 0);
write_indented_text(diag_cfg->fd, level+1, xml);
lasso_release_string(xml);
} else {
apr_file_printf(diag_cfg->fd,
"%snode is NULL\n",
indent(level+1));
}
apr_file_flush(diag_cfg->fd);
}
void
am_diag_log_file_data(request_rec *r, int level, am_file_data_t *file_data,
const char *fmt, ...)
{
va_list ap;
am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
if (!AM_DIAG_ENABLED(diag_cfg)) return;
if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
va_start(ap, fmt);
am_diag_format_line(r->pool, diag_cfg->fd, level, fmt, ap);
va_end(ap);
if (file_data) {
if (file_data->generated) {
apr_file_printf(diag_cfg->fd,
"%sGenerated file contents:\n",
indent(level+1));
write_indented_text(diag_cfg->fd,
level+2, file_data->contents);
} else {
apr_file_printf(diag_cfg->fd,
"%spathname: \"%s\"\n",
indent(level+1), file_data->path);
if (!file_data->read_time) {
am_file_read(file_data);
}
if (file_data->rv == APR_SUCCESS) {
write_indented_text(diag_cfg->fd,
level+2, file_data->contents);
} else {
apr_file_printf(diag_cfg->fd,
"%s%s\n",
indent(level+1), file_data->strerror);
}
}
} else {
apr_file_printf(diag_cfg->fd,
"%sfile_data: NULL\n",
indent(level+1));
}
apr_file_flush(diag_cfg->fd);
}
void
am_diag_log_saml_status_response(request_rec *r, int level, LassoNode *node,
const char *fmt, ...)
{
va_list ap;
am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
LassoSamlp2StatusResponse *response = (LassoSamlp2StatusResponse*)node;
LassoSamlp2Status *status = NULL;
const char *status_code1 = NULL;
const char *status_code2 = NULL;
if (!AM_DIAG_ENABLED(diag_cfg)) return;
if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
va_start(ap, fmt);
am_diag_format_line(r->pool, diag_cfg->fd, level, fmt, ap);
va_end(ap);
if (response == NULL) {
apr_file_printf(diag_cfg->fd,
"%sresponse is NULL\n", indent(level+1));
return;
}
if (!LASSO_IS_SAMLP2_STATUS_RESPONSE(response)) {
apr_file_printf(diag_cfg->fd,
"%sERROR, expected LassoSamlp2StatusResponse "
"but got %s\n",
indent(level+1),
lasso_node_get_name((LassoNode*)response));
return;
}
status = response->Status;
if (status == NULL ||
!LASSO_IS_SAMLP2_STATUS(status) ||
status->StatusCode == NULL ||
status->StatusCode->Value == NULL) {
apr_file_printf(diag_cfg->fd,
"%sStatus missing\n",
indent(level+1));
return;
}
status_code1 = status->StatusCode->Value;
if (status->StatusCode->StatusCode) {
status_code2 = status->StatusCode->StatusCode->Value;
}
apr_file_printf(diag_cfg->fd,
"%sID: %s\n",
indent(level+1), response->ID);
apr_file_printf(diag_cfg->fd,
"%sInResponseTo: %s\n",
indent(level+1), response->InResponseTo);
apr_file_printf(diag_cfg->fd,
"%sVersion: %s\n",
indent(level+1), response->Version);
apr_file_printf(diag_cfg->fd,
"%sIssueInstant: %s\n",
indent(level+1), response->IssueInstant);
apr_file_printf(diag_cfg->fd,
"%sConsent: %s\n",
indent(level+1), response->Consent);
apr_file_printf(diag_cfg->fd,
"%sIssuer: %s\n",
indent(level+1), response->Issuer->content);
apr_file_printf(diag_cfg->fd,
"%sDestination: %s\n",
indent(level+1), response->Destination);
apr_file_printf(diag_cfg->fd,
"%sStatus:\n", indent(level+1));
apr_file_printf(diag_cfg->fd,
"%sTop Level Status code: %s\n",
indent(level+2), status_code1);
apr_file_printf(diag_cfg->fd,
"%s2nd Level Status code: %s\n",
indent(level+2), status_code2);
apr_file_printf(diag_cfg->fd,
"%sStatus Message: %s\n",
indent(level+2), status->StatusMessage);
am_diag_log_lasso_node(r, level+2, (LassoNode*)status->StatusDetail,
"Status Detail:");
return;
}
void
am_diag_log_profile(request_rec *r, int level, LassoProfile *profile,
const char *fmt, ...)
{
va_list ap;
am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
LassoSession *session = lasso_profile_get_session(profile);
GList *assertions = lasso_session_get_assertions(session, NULL);
GList *iter = NULL;
int i;
if (!AM_DIAG_ENABLED(diag_cfg)) return;
if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
va_start(ap, fmt);
am_diag_format_line(r->pool, diag_cfg->fd, level, fmt, ap);
va_end(ap);
if (profile) {
apr_file_printf(diag_cfg->fd,
"%sProfile Type: %s\n",
indent(level+1), G_OBJECT_TYPE_NAME(profile));
for (iter = assertions, i=0;
iter != NULL;
iter = g_list_next(iter), i++) {
LassoSaml2Assertion *assertion = NULL;
assertion = LASSO_SAML2_ASSERTION(iter->data);
if (!LASSO_IS_SAML2_ASSERTION(assertion)) {
apr_file_printf(diag_cfg->fd,
"%sObject at index %d in session assertion"
" list is not LassoSaml2Assertion",
indent(level+1), i);
} else {
am_diag_log_lasso_node(r, level+1, &assertion->parent,
"Assertion %d", i);
}
}
} else {
apr_file_printf(diag_cfg->fd,
"%sprofile is NULL\n",
indent(level+1));
}
apr_file_flush(diag_cfg->fd);
}
void
am_diag_log_cache_entry(request_rec *r, int level, am_cache_entry_t *entry,
const char *fmt, ...)
{
va_list ap;
am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
const char *name_id = NULL;
if (!AM_DIAG_ENABLED(diag_cfg)) return;
if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
va_start(ap, fmt);
am_diag_format_line(r->pool, diag_cfg->fd, level, fmt, ap);
va_end(ap);
if (entry) {
name_id = am_cache_env_fetch_first(entry, "NAME_ID");
apr_file_printf(diag_cfg->fd,
"%skey: %s\n",
indent(level+1), entry->key);
apr_file_printf(diag_cfg->fd,
"%sname_id: %s\n",
indent(level+1), name_id);
apr_file_printf(diag_cfg->fd,
"%sexpires: %s\n",
indent(level+1),
am_diag_time_t_to_8601(r, entry->expires));
apr_file_printf(diag_cfg->fd,
"%saccess: %s\n",
indent(level+1),
am_diag_time_t_to_8601(r, entry->access));
apr_file_printf(diag_cfg->fd,
"%slogged_in: %s\n",
indent(level+1), entry->logged_in ? "True" : "False");
} else {
apr_file_printf(diag_cfg->fd,
"%sentry is NULL\n",
indent(level+1));
}
apr_file_flush(diag_cfg->fd);
}
#endif /* ENABLE_DIAGNOSTICS */