Blame SOURCES/add-diagnostics.patch

6163e3
commit e8579f6387d9841ce619d836110050fb18117753
6163e3
Author: John Dennis <jdennis@redhat.com>
6163e3
Date:   Wed Jun 14 13:56:18 2017 -0400
6163e3
6163e3
    Add diagnostic logging
6163e3
    
6163e3
    Field experience with Mellon has demonstrated there are many
6163e3
    opportunities for deployment problems. Although there are tools such
6163e3
    as browser plugins which can capture SAML messages it's onerous for
6163e3
    site personnel to install and capture the relevant information. The
6163e3
    problem with this approach is further compounded by the fact the
6163e3
    external SAML messages are not correlated to Mellon's
6163e3
    requests/responses. Mellon currently can dump the Lasso session and
6163e3
    SAML Response messages and place them in Apache environment variables,
6163e3
    however these do not appear in the log file. To get them into the log
6163e3
    you have to add custom logging to the Apache config. Another issue is
6163e3
    the dumps are not human readable, they are base64 encoded, anyone
6163e3
    looking at the logs after setting up the custom logging will have to
6163e3
    find the base64 text and then manually copy the text into an external
6163e3
    base64 decoder. At that point you'll discover the XML is not pretty
6163e3
    printed making human interpretation difficult.
6163e3
    
6163e3
    The Mellon debug messages written to the Apache error are often
6163e3
    insufficient to diagnose problems. And since the Mellon log messages
6163e3
    are written to the Apache error log they are interspersed with a lot
6163e3
    of non-Mellon message.
6163e3
    
6163e3
    Compounding the problem of writing Mellon debug messages to the Apache
6163e3
    error log is the fact Apache log messages have a fixed maximum length
6163e3
    (currently 8192) which is insufficient to completely write out such
6163e3
    things as SAML Assertions, metadata, etc. Apache logging also escapes
6163e3
    all control characters with the consequence line breaks are not
6163e3
    preserved and what was a nicely formatted human readable piece of text
6163e3
    becomes a single line with escape characters and may be truncated.
6163e3
    
6163e3
    It would be really nice if we could capture diagnostic information
6163e3
    with these properties:
6163e3
    
6163e3
    * All relevant data is collected in exactly one file.
6163e3
    
6163e3
    * Only information relevant to Mellon appears in the file.
6163e3
    
6163e3
    * All information is human readable (pretty printed, decrypted) with
6163e3
      no need to rely on other tools.
6163e3
    
6163e3
    * The diagnostic information is grouped by requests.
6163e3
    
6163e3
    * The requests can be cross correlated with other Apache logs because
6163e3
      they utilize the same unique request identifier.
6163e3
    
6163e3
    This patch adds diagnostic logging to a independent Mellon diagnostics
6163e3
    log file. Every piece of relevant information is captured, including:
6163e3
    
6163e3
    * Request information which includes:
6163e3
    
6163e3
      - Request method
6163e3
      - Request URL (raw and processed)
6163e3
      - Scheme
6163e3
      - Port
6163e3
      - Request query parameters
6163e3
      - Server name
6163e3
      - Unique request ID
6163e3
      - process ID, thread ID
6163e3
      - Request headers
6163e3
    
6163e3
    * Mellon per directory configuration
6163e3
    
6163e3
      A complete dump of the entire am_dir_cfg_rec structure keyed using
6163e3
      both the Mellon directive it is associated with and it's internal
6163e3
      name. This is emitted once on first use for a given URL.
6163e3
    
6163e3
      The per directory dump includes the pathname of each file read as
6163e3
      well as the file contents. This includes:
6163e3
    
6163e3
      - IdP metadata
6163e3
      - SP metadata
6163e3
      - SP cert
6163e3
      - SP key
6163e3
      - IdP public key file
6163e3
      - IdP CA file
6163e3
    
6163e3
    * All session management operations
6163e3
    
6163e3
      - cookie
6163e3
      - session lookup
6163e3
      - session creation
6163e3
      - session deletion
6163e3
      - cache management
6163e3
      - cache entry information
6163e3
    
6163e3
    * All SAML messages
6163e3
    
6163e3
      Each SAML message is decrypted, decoded and XML pretty printed in
6163e3
      human readable form.
6163e3
    
6163e3
    * Request pipeline operations
6163e3
    
6163e3
      What operations Mellon performs, what decisions it makes and what
6163e3
      data is being used to make those decisions.
6163e3
    
6163e3
    * Response
6163e3
    
6163e3
      - response status
6163e3
      - response headers
6163e3
      - Apache user name
6163e3
      - auth_type
6163e3
      - all Apache environment variables
6163e3
    
6163e3
    Diagnostics can be enabled/disabled both at compile time and run
6163e3
    time. Compile time inclusion of diagnostics is managed with the
6163e3
    ENABLE_DIAGNOSTICS preprocssor symbol. The configure script now accepts
6163e3
    the
6163e3
    
6163e3
      --enable-diagnostics and --disable-diagnostics
6163e3
    
6163e3
    option. Building with diagnostics is disabled by default, you must
6163e3
    specify --enable-diagnostics to enable the run time option of generating
6163e3
    diagnostics.
6163e3
    
6163e3
    The following server config directives have been added (e.g. may be
6163e3
    specified in the main server config area or within a <VirtualHost>
6163e3
    directive). If Mellon was not built with diagnostics enabled then
6163e3
    these config directives are no-ops and their use will generated a
6163e3
    warning in the log file indicating they have been ignored and to be
6163e3
    effective you must builld Mellon with diagnostics enabled.
6163e3
    
6163e3
      MellonDiagnosticsFile:
6163e3
        The name of the diagnostics file or pipe,
6163e3
        (default is logs/mellon_diagnostics)
6163e3
    
6163e3
      MellonDiagnosticsEnable:
6163e3
        Currently either On or Off but it is designed so it can take other
6163e3
        flags in the future to control what type of information is
6163e3
        reported.
6163e3
    
6163e3
    Signed-off-by: John Dennis <jdennis@redhat.com>
6163e3
6163e3
diff --git a/Makefile.in b/Makefile.in
6163e3
index 731919e..3656bec 100644
6163e3
--- a/Makefile.in
6163e3
+++ b/Makefile.in
6163e3
@@ -1,8 +1,11 @@
6163e3
 
6163e3
 # Source files. mod_auth_mellon.c must be the first file.
6163e3
 SRC=mod_auth_mellon.c \
6163e3
-	auth_mellon_cache.c auth_mellon_config.c \
6163e3
-	auth_mellon_cookie.c auth_mellon_handler.c \
6163e3
+	auth_mellon_cache.c \
6163e3
+	auth_mellon_config.c \
6163e3
+	auth_mellon_cookie.c \
6163e3
+	auth_mellon_diagnostics.c \
6163e3
+	auth_mellon_handler.c \
6163e3
 	auth_mellon_util.c \
6163e3
 	auth_mellon_session.c \
6163e3
 	auth_mellon_httpclient.c
6163e3
@@ -25,7 +28,7 @@ DISTFILES=$(SRC) \
6163e3
 all:	mod_auth_mellon.la
6163e3
 
6163e3
 mod_auth_mellon.la: $(SRC) auth_mellon.h auth_mellon_compat.h
6163e3
-	@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)
6163e3
+	@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)
6163e3
 
6163e3
 
6163e3
 # Building configure (for distribution)
6163e3
@@ -46,6 +49,7 @@ distfile:	@NAMEVER@.tar.gz
6163e3
 .PHONY:	clean
6163e3
 clean:
6163e3
 	rm -f mod_auth_mellon.la
6163e3
+	rm -f $(SRC:%.c=%.o)
6163e3
 	rm -f $(SRC:%.c=%.lo)
6163e3
 	rm -f $(SRC:%.c=%.slo)
6163e3
 	rm -rf .libs/
6163e3
diff --git a/README b/README
6163e3
index e084ef4..8211d66 100644
6163e3
--- a/README
6163e3
+++ b/README
6163e3
@@ -132,6 +132,24 @@ MellonPostSize 1048576
6163e3
 # Default: MellonPostCount 100
6163e3
 MellonPostCount 100
6163e3
 
6163e3
+# MellonDiagnosticsFile If Mellon was built with diagnostic capability
6163e3
+# then diagnostic is written here, it may be either a filename or a pipe.
6163e3
+# If it's a filename then the resulting path is  relative to the ServerRoot.
6163e3
+# If the value is preceeded by the pipe character "|" it should be followed
6163e3
+# by a path to a program to receive the log information on its standard input.
6163e3
+# This is a server context directive, hence it may be specified in the
6163e3
+# main server config area or within a <VirtualHost> directive.
6163e3
+# Default: logs/mellon_diagnostics
6163e3
+MellonDiagnosticsFile logs/mellon_diagnostics
6163e3
+
6163e3
+# MellonDiagnosticsEnable If Mellon was built with diagnostic capability
6163e3
+# then this is a list of words controlling diagnostic output.
6163e3
+# Currently only On and Off are supported.
6163e3
+# This is a server context directive, hence it may be specified in the
6163e3
+# main server config area or within a <VirtualHost> directive.
6163e3
+# Default: Off
6163e3
+MellonDiagnosticsEnable Off
6163e3
+
6163e3
 ###########################################################################
6163e3
 # End of global configuration for mod_auth_mellon.
6163e3
 ###########################################################################
6163e3
diff --git a/auth_mellon.h b/auth_mellon.h
6163e3
index a6fa34c..6ce6a8e 100644
6163e3
--- a/auth_mellon.h
6163e3
+++ b/auth_mellon.h
6163e3
@@ -85,6 +85,14 @@
6163e3
 #define AM_ERROR_MISSING_PAOS_MEDIA_TYPE 3
6163e3
 
6163e3
 
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+typedef enum {
6163e3
+    AM_DIAG_FLAG_ENABLED       = (1 << 0),
6163e3
+    AM_DIAG_FLAG_DISABLE       = 0,
6163e3
+    AM_DIAG_FLAG_ENABLE_ALL    = ~0,
6163e3
+} am_diag_flags_t;
6163e3
+#endif
6163e3
+
6163e3
 /* This is the length of the id we use (for session IDs and
6163e3
  * replaying POST data).
6163e3
  */
6163e3
@@ -100,6 +108,9 @@
6163e3
 
6163e3
 #define am_get_req_cfg(r) (am_req_cfg_rec *)ap_get_module_config((r)->request_config, &auth_mellon_module)
6163e3
 
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+#define am_get_diag_cfg(s) (&(am_get_srv_cfg((s)))->diag_cfg)
6163e3
+#endif
6163e3
 
6163e3
 typedef struct am_mod_cfg_rec {
6163e3
     int cache_size;
6163e3
@@ -124,8 +135,20 @@ typedef struct am_mod_cfg_rec {
6163e3
 } am_mod_cfg_rec;
6163e3
 
6163e3
 
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+typedef struct am_diag_cfg_rec {
6163e3
+    const char *filename;
6163e3
+    apr_file_t *fd;
6163e3
+    am_diag_flags_t flags;
6163e3
+    apr_table_t *dir_cfg_emitted;
6163e3
+} am_diag_cfg_rec;
6163e3
+#endif
6163e3
+
6163e3
 typedef struct am_srv_cfg_rec {
6163e3
     am_mod_cfg_rec *mc;
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+    am_diag_cfg_rec diag_cfg;
6163e3
+#endif
6163e3
 } am_srv_cfg_rec;
6163e3
 
6163e3
 typedef enum {
6163e3
@@ -284,7 +307,6 @@ typedef struct am_dir_cfg_rec {
6163e3
 
6163e3
     /* List of domains we can redirect to. */
6163e3
     const char * const *redirect_domains;
6163e3
-
6163e3
 } am_dir_cfg_rec;
6163e3
 
6163e3
 /* Bitmask for PAOS service options */
6163e3
@@ -301,6 +323,9 @@ typedef struct am_req_cfg_rec {
6163e3
     bool ecp_authn_req;
6163e3
     ECPServiceOptions ecp_service_options;
6163e3
 #endif /* HAVE_ECP */
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+    bool diag_emitted;
6163e3
+#endif
6163e3
 } am_req_cfg_rec;
6163e3
 
6163e3
 typedef struct am_cache_storage_t {
6163e3
@@ -393,6 +418,7 @@ static const int inherit_ecp_send_idplist = -1;
6163e3
 void *auth_mellon_dir_config(apr_pool_t *p, char *d);
6163e3
 void *auth_mellon_dir_merge(apr_pool_t *p, void *base, void *add);
6163e3
 void *auth_mellon_server_config(apr_pool_t *p, server_rec *s);
6163e3
+void *auth_mellon_srv_merge(apr_pool_t *p, void *base, void *add);
6163e3
 
6163e3
 
6163e3
 const char *am_cookie_get(request_rec *r);
6163e3
@@ -503,4 +529,72 @@ int am_httpclient_post_str(request_rec *r, const char *uri,
6163e3
 
6163e3
 extern module AP_MODULE_DECLARE_DATA auth_mellon_module;
6163e3
 
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+
6163e3
+/* Initializing an apr_time_t to 0x7fffffffffffffffLL yields an
6163e3
+ * iso 8601 time with 1 second precision of "294247-01-10T04:00:54Z"
6163e3
+ * this is 22 characters, +1 for null terminator. */
6163e3
+#define ISO_8601_BUF_SIZE 23
6163e3
+
6163e3
+typedef struct {
6163e3
+    bool req_headers_written;
6163e3
+} am_diag_request_data;
6163e3
+
6163e3
+const char *
6163e3
+am_diag_cache_key_type_str(am_cache_key_t key_type);
6163e3
+
6163e3
+const char *
6163e3
+am_diag_cond_str(request_rec *r, const am_cond_t *cond);
6163e3
+
6163e3
+int
6163e3
+am_diag_finalize_request(request_rec *r);
6163e3
+
6163e3
+const char *
6163e3
+am_diag_lasso_http_method_str(LassoHttpMethod http_method);
6163e3
+
6163e3
+void
6163e3
+am_diag_log_cache_entry(request_rec *r, int level, am_cache_entry_t *entry,
6163e3
+                        const char *fmt, ...)
6163e3
+    __attribute__((format(printf,4,5)));
6163e3
+
6163e3
+void
6163e3
+am_diag_log_file_data(request_rec *r, int level, am_file_data_t *file_data,
6163e3
+                      const char *fmt, ...)
6163e3
+    __attribute__((format(printf,4,5)));
6163e3
+
6163e3
+int
6163e3
+am_diag_log_init(apr_pool_t *pc, apr_pool_t *p, apr_pool_t *pt, server_rec *s);
6163e3
+
6163e3
+void
6163e3
+am_diag_log_lasso_node(request_rec *r, int level, LassoNode *node,
6163e3
+                       const char *fmt, ...)
6163e3
+    __attribute__((format(printf,4,5)));
6163e3
+
6163e3
+void
6163e3
+am_diag_log_profile(request_rec *r, int level, LassoProfile *profile,
6163e3
+                    const char *fmt, ...)
6163e3
+    __attribute__((format(printf,4,5)));
6163e3
+
6163e3
+void
6163e3
+am_diag_printf(request_rec *r, const char *fmt, ...)
6163e3
+    __attribute__((format(printf,2,3)));
6163e3
+
6163e3
+void
6163e3
+am_diag_rerror(const char *file, int line, int module_index,
6163e3
+               int level, apr_status_t status,
6163e3
+               request_rec *r, const char *fmt, ...);
6163e3
+
6163e3
+char *
6163e3
+am_diag_time_t_to_8601(request_rec *r, apr_time_t t);
6163e3
+
6163e3
+#else  /* ENABLE_DIAGNOSTICS */
6163e3
+
6163e3
+#define am_diag_log_cache_entry(...) do {} while(0)
6163e3
+#define am_diag_log_file_data(...) do {} while(0)
6163e3
+#define am_diag_log_lasso_node(...) do {} while(0)
6163e3
+#define am_diag_log_profile(...) do {} while(0)
6163e3
+#define am_diag_printf(...) do {} while(0)
6163e3
+
6163e3
+#endif /* ENABLE_DIAGNOSTICS */
6163e3
+
6163e3
 #endif /* MOD_AUTH_MELLON_H */
6163e3
diff --git a/auth_mellon_cache.c b/auth_mellon_cache.c
6163e3
index af5c267..2115acc 100644
6163e3
--- a/auth_mellon_cache.c
6163e3
+++ b/auth_mellon_cache.c
6163e3
@@ -144,11 +144,17 @@ am_cache_entry_t *am_cache_lock(request_rec *r,
6163e3
             continue;
6163e3
 
6163e3
         if(strcmp(tablekey, key) == 0) {
6163e3
+            apr_time_t now = apr_time_now();
6163e3
             /* We found the entry. */
6163e3
-            if(e->expires > apr_time_now()) {
6163e3
+            if(e->expires > now) {
6163e3
                 /* And it hasn't expired. */
6163e3
                 return e;
6163e3
             }
6163e3
+            else {
6163e3
+                am_diag_log_cache_entry(r, 0, e,
6163e3
+                                        "found expired session, now %s\n",
6163e3
+                                        am_diag_time_t_to_8601(r, now));
6163e3
+            }
6163e3
         }
6163e3
     }
6163e3
 
6163e3
@@ -342,6 +348,10 @@ am_cache_entry_t *am_cache_new(request_rec *r,
6163e3
              * Update 't' and exit loop.
6163e3
              */
6163e3
             t = e;
6163e3
+            am_diag_log_cache_entry(r, 0, e,
6163e3
+                                    "%s ejecting expired sessions, now %s\n",
6163e3
+                                    __func__,
6163e3
+                                    am_diag_time_t_to_8601(r, current_time));
6163e3
             break;
6163e3
         }
6163e3
 
6163e3
@@ -400,6 +410,11 @@ am_cache_entry_t *am_cache_new(request_rec *r,
6163e3
         return NULL;
6163e3
     }
6163e3
 
6163e3
+    am_diag_printf(r, "%s created new session, id=%s at %s"
6163e3
+                   " cookie_token=\"%s\"\n",
6163e3
+                   __func__, t->key, am_diag_time_t_to_8601(r, current_time),
6163e3
+                   cookie_token);
6163e3
+
6163e3
     return t;
6163e3
 }
6163e3
 
6163e3
diff --git a/auth_mellon_config.c b/auth_mellon_config.c
6163e3
index c3cb5e0..66966fc 100644
6163e3
--- a/auth_mellon_config.c
6163e3
+++ b/auth_mellon_config.c
6163e3
@@ -78,6 +78,15 @@ static const apr_size_t post_size = 1024 * 1024;
6163e3
  */
6163e3
 static const int post_count = 100;
6163e3
 
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+/* Default filename for mellon diagnostics log file.
6163e3
+ * Relative pathname is relative to server root. */
6163e3
+static const char *default_diag_filename = "logs/mellon_diagnostics";
6163e3
+
6163e3
+/* Default state for diagnostics is off */
6163e3
+static am_diag_flags_t default_diag_flags = AM_DIAG_FLAG_DISABLE;
6163e3
+#endif
6163e3
+
6163e3
 /* whether to merge env. vars or not
6163e3
  * the MellonMergeEnvVars configuration directive if you change this.
6163e3
  */
6163e3
@@ -470,6 +479,78 @@ static const char *am_set_module_config_int_slot(cmd_parms *cmd,
6163e3
     return ap_set_int_slot(cmd, am_get_mod_cfg(cmd->server), arg);
6163e3
 }
6163e3
 
6163e3
+/* This function handles the MellonDiagnosticsFile configuration directive.
6163e3
+ * It emits as warning in the log file if Mellon is not built with
6163e3
+ * diagnostics enabled.
6163e3
+ *
6163e3
+ * Parameters:
6163e3
+ *  cmd_parms *cmd       The command structure for this configuration
6163e3
+ *                       directive.
6163e3
+ *  void *struct_ptr     Pointer to the current directory configuration.
6163e3
+ *                       NULL if we are not in a directory configuration.
6163e3
+ *  const char *arg      The string argument following this configuration
6163e3
+ *                       directive in the configuraion file.
6163e3
+ *
6163e3
+ * Returns:
6163e3
+ *  NULL on success or an error string on failure.
6163e3
+ */
6163e3
+static const char *am_set_module_diag_file_slot(cmd_parms *cmd,
6163e3
+                                                    void *struct_ptr,
6163e3
+                                                    const char *arg)
6163e3
+{
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+    return ap_set_file_slot(cmd, am_get_diag_cfg(cmd->server), arg);
6163e3
+#else
6163e3
+    ap_log_error(APLOG_MARK, APLOG_NOTICE, 0, cmd->server,
6163e3
+                 "%s has no effect because Mellon was not compiled with"
6163e3
+                 " diagnostics enabled, use ./configure --enable-diagnostics"
6163e3
+                 " at build time to turn this feature on.",
6163e3
+                 cmd->directive->directive);
6163e3
+    return NULL;
6163e3
+#endif
6163e3
+}
6163e3
+
6163e3
+/* This function handles configuration directives which sets the
6163e3
+ * diagnostics flags in the module configuration.
6163e3
+ *
6163e3
+ * Parameters:
6163e3
+ *  cmd_parms *cmd       The command structure for this configuration
6163e3
+ *                       directive.
6163e3
+ *  void *struct_ptr     Pointer to the current directory configuration.
6163e3
+ *                       NULL if we are not in a directory configuration.
6163e3
+ *  const char *arg      The string argument following this configuration
6163e3
+ *                       directive in the configuraion file.
6163e3
+ *
6163e3
+ * Returns:
6163e3
+ *  NULL on success or an error string on failure.
6163e3
+ */
6163e3
+static const char *am_set_module_diag_flags_slot(cmd_parms *cmd,
6163e3
+                                                 void *struct_ptr,
6163e3
+                                                 const char *arg)
6163e3
+{
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+    am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(cmd->server);
6163e3
+
6163e3
+    if (strcasecmp(arg, "on") == 0) {
6163e3
+        diag_cfg->flags = AM_DIAG_FLAG_ENABLE_ALL;
6163e3
+    }
6163e3
+    else if (strcasecmp(arg, "off") == 0) {
6163e3
+        diag_cfg->flags = AM_DIAG_FLAG_DISABLE;
6163e3
+    } else {
6163e3
+        return apr_psprintf(cmd->pool, "%s: must be one of: 'on', 'off'",
6163e3
+                            cmd->cmd->name);
6163e3
+    }
6163e3
+    return NULL;
6163e3
+#else
6163e3
+    ap_log_error(APLOG_MARK, APLOG_NOTICE, 0, cmd->server,
6163e3
+                 "%s has no effect because Mellon was not compiled with"
6163e3
+                 " diagnostics enabled, use ./configure --enable-diagnostics"
6163e3
+                 " at build time to turn this feature on.",
6163e3
+                 cmd->directive->directive);
6163e3
+    return NULL;
6163e3
+#endif
6163e3
+}
6163e3
+
6163e3
 /* This function handles the MellonCookieSameSite configuration directive.
6163e3
  * This directive can be set to "lax" or "strict"
6163e3
  *
6163e3
@@ -684,7 +765,7 @@ static const char *am_set_setenv_no_prefix_slot(cmd_parms *cmd,
6163e3
 static int am_cond_flags(const char *arg)
6163e3
 {
6163e3
     int flags = AM_COND_FLAG_NULL; 
6163e3
-    static const char const *options[] = { 
6163e3
+    static const char * const options[] = {
6163e3
         "OR",  /* AM_EXPIRE_FLAG_OR */
6163e3
         "NOT", /* AM_EXPIRE_FLAG_NOT */
6163e3
         "REG", /* AM_EXPIRE_FLAG_REG */
6163e3
@@ -1123,6 +1204,30 @@ const command_rec auth_mellon_commands[] = {
6163e3
         "The maximum size of a saved POST, in bytes."
6163e3
         " Default value is 1048576 (1 MB)."
6163e3
         ), 
6163e3
+    AP_INIT_TAKE1(
6163e3
+        "MellonDiagnosticsFile",
6163e3
+        am_set_module_diag_file_slot,
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+        (void *)APR_OFFSETOF(am_diag_cfg_rec, filename),
6163e3
+#else
6163e3
+        NULL,
6163e3
+#endif
6163e3
+        RSRC_CONF,
6163e3
+        "Diagnostics log file. [file|pipe] "
6163e3
+        "If file then file is a filename, relative to the ServerRoot."
6163e3
+        "If pipe then the filename is a pipe character \"|\", "
6163e3
+        "followed by the path to a program to receive the log information "
6163e3
+        "on its standard input. "
6163e3
+        " Default value is \"logs/mellon_diagnostics\"."
6163e3
+        ),
6163e3
+    AP_INIT_ITERATE(
6163e3
+        "MellonDiagnosticsEnable",
6163e3
+        am_set_module_diag_flags_slot,
6163e3
+        NULL,
6163e3
+        RSRC_CONF,
6163e3
+        "Diagnostics flags. [on|off] "
6163e3
+        " Default value is \"off\"."
6163e3
+        ),
6163e3
 
6163e3
 
6163e3
     /* Per-location configuration directives. */
6163e3
@@ -1855,6 +1960,13 @@ void *auth_mellon_server_config(apr_pool_t *p, server_rec *s)
6163e3
 
6163e3
     srv = apr_palloc(p, sizeof(*srv));
6163e3
 
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+    srv->diag_cfg.filename = default_diag_filename;
6163e3
+    srv->diag_cfg.fd = NULL;
6163e3
+    srv->diag_cfg.flags = default_diag_flags;
6163e3
+    srv->diag_cfg.dir_cfg_emitted = apr_table_make(p, 0);
6163e3
+#endif
6163e3
+
6163e3
     /* we want to keeep our global configuration of shared memory and
6163e3
      * mutexes, so we try to find it in the userdata before doing anything
6163e3
      * else */
6163e3
@@ -1886,6 +1998,47 @@ void *auth_mellon_server_config(apr_pool_t *p, server_rec *s)
6163e3
     apr_pool_userdata_set(mod, key, apr_pool_cleanup_null, p);
6163e3
 
6163e3
     srv->mc = mod;
6163e3
+
6163e3
     return srv;
6163e3
 }
6163e3
 
6163e3
+/* This function merges two am_srv_cfg_rec structures.
6163e3
+ * It will try to inherit from the base where possible.
6163e3
+ *
6163e3
+ * Parameters:
6163e3
+ *  apr_pool_t *p        The pool we should allocate memory from.
6163e3
+ *  void *base           The original structure.
6163e3
+ *  void *add            The structure we should add to base.
6163e3
+ *
6163e3
+ * Returns:
6163e3
+ *  The merged structure.
6163e3
+ */
6163e3
+void *auth_mellon_srv_merge(apr_pool_t *p, void *base, void *add)
6163e3
+{
6163e3
+    am_srv_cfg_rec *base_cfg = (am_srv_cfg_rec *)base;
6163e3
+    am_srv_cfg_rec *new_cfg;
6163e3
+
6163e3
+    new_cfg = (am_srv_cfg_rec *)apr_palloc(p, sizeof(*new_cfg));
6163e3
+
6163e3
+    new_cfg->mc = base_cfg->mc;
6163e3
+
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+    am_srv_cfg_rec *add_cfg = (am_srv_cfg_rec *)add;
6163e3
+    new_cfg->diag_cfg.filename = (add_cfg->diag_cfg.filename !=
6163e3
+                                  default_diag_filename ?
6163e3
+                                  add_cfg->diag_cfg.filename :
6163e3
+                                  base_cfg->diag_cfg.filename);
6163e3
+
6163e3
+    new_cfg->diag_cfg.fd = NULL;
6163e3
+
6163e3
+    new_cfg->diag_cfg.flags = (add_cfg->diag_cfg.flags !=
6163e3
+                               default_diag_flags ?
6163e3
+                               add_cfg->diag_cfg.flags :
6163e3
+                               base_cfg->diag_cfg.flags);
6163e3
+
6163e3
+    new_cfg->diag_cfg.dir_cfg_emitted = apr_table_make(p, 0);
6163e3
+
6163e3
+#endif
6163e3
+
6163e3
+    return new_cfg;
6163e3
+}
6163e3
diff --git a/auth_mellon_diagnostics.c b/auth_mellon_diagnostics.c
6163e3
new file mode 100644
6163e3
index 0000000..519a44f
6163e3
--- /dev/null
6163e3
+++ b/auth_mellon_diagnostics.c
6163e3
@@ -0,0 +1,1017 @@
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+
6163e3
+#include "auth_mellon.h"
6163e3
+
6163e3
+#if APR_HAVE_UNISTD_H
6163e3
+#include <unistd.h>
6163e3
+#endif
6163e3
+#if APR_HAVE_PROCESS_H
6163e3
+#include <process.h>            /* for getpid() on Win32 */
6163e3
+#endif
6163e3
+
6163e3
+/*============================= Internal Static ==============================*/
6163e3
+
6163e3
+/*------------------ Defines ------------------*/
6163e3
+
6163e3
+#define AM_DIAG_ENABLED(diag_cfg)                                       \
6163e3
+    (diag_cfg && diag_cfg->fd && (diag_cfg->flags & AM_DIAG_FLAG_ENABLED))
6163e3
+
6163e3
+/*------------------ Typedefs ------------------*/
6163e3
+
6163e3
+typedef struct iter_callback_data {
6163e3
+    apr_file_t *diag_fd;
6163e3
+    int level;
6163e3
+} iter_callback_data;
6163e3
+
6163e3
+/*------------------ Prototypes ------------------*/
6163e3
+
6163e3
+static const char *
6163e3
+indent(int level);
6163e3
+
6163e3
+static void
6163e3
+write_indented_text(apr_file_t *diag_fd, int level, const char* text);
6163e3
+
6163e3
+static void
6163e3
+am_diag_format_line(apr_pool_t *pool, apr_file_t *diag_fd, int level,
6163e3
+                    const char *fmt, va_list ap);
6163e3
+
6163e3
+static const char *
6163e3
+am_diag_cond_flag_str(request_rec *r, am_cond_flag_t flags);
6163e3
+
6163e3
+static const char *
6163e3
+am_diag_enable_str(am_enable_t enable);
6163e3
+
6163e3
+static const char *
6163e3
+am_diag_samesite_str(am_samesite_t samesite);
6163e3
+
6163e3
+static const char *
6163e3
+am_diag_httpd_error_level_str(request_rec *r, int level);
6163e3
+
6163e3
+static apr_size_t
6163e3
+am_diag_time_t_to_8601_buf(char *buf, apr_size_t buf_size, apr_time_t t);
6163e3
+
6163e3
+static int
6163e3
+am_diag_open_log(server_rec *s, apr_pool_t *p);
6163e3
+
6163e3
+static int
6163e3
+am_table_count(void *rec, const char *key, const char *value);
6163e3
+
6163e3
+static int
6163e3
+log_headers(void *rec, const char *key, const char *value);
6163e3
+
6163e3
+static int
6163e3
+log_probe_discovery_idp(void *rec, const char *key, const char *value);
6163e3
+
6163e3
+static void
6163e3
+am_diag_log_dir_cfg(request_rec *r, int level, am_dir_cfg_rec *cfg,
6163e3
+                    const char *fmt, ...)
6163e3
+    __attribute__((format(printf,4,5)));
6163e3
+
6163e3
+static bool
6163e3
+am_diag_initialize_req(request_rec *r, am_diag_cfg_rec *diag_cfg,
6163e3
+                       am_req_cfg_rec *req_cfg);
6163e3
+
6163e3
+/*------------------ Functions ------------------*/
6163e3
+
6163e3
+static const char *
6163e3
+indent(int level)
6163e3
+{
6163e3
+    static const char * const indents[] = {
6163e3
+        "",                     /* 0 */
6163e3
+        "  ",                   /* 1 */
6163e3
+        "    ",                 /* 2 */
6163e3
+        "      ",               /* 3 */
6163e3
+        "        ",             /* 4 */
6163e3
+        "          ",           /* 5 */
6163e3
+        "            ",         /* 6 */
6163e3
+        "              ",       /* 7 */
6163e3
+        "                ",     /* 8 */
6163e3
+        "                  ",   /* 9 */
6163e3
+    };
6163e3
+    int n_indents = sizeof(indents)/sizeof(indents[0]);
6163e3
+
6163e3
+    if (level < 0) {
6163e3
+        return "";
6163e3
+    }
6163e3
+    if (level < n_indents) {
6163e3
+        return indents[level];
6163e3
+    }
6163e3
+    return indents[n_indents-1];
6163e3
+}
6163e3
+
6163e3
+static void
6163e3
+write_indented_text(apr_file_t *diag_fd, int level, const char* text)
6163e3
+{
6163e3
+    const char *start, *end, *prefix;
6163e3
+    size_t len, prefix_len;
6163e3
+    bool crlf = false;
6163e3
+
6163e3
+    if (!text) return;
6163e3
+
6163e3
+    prefix = indent(level);
6163e3
+    prefix_len = strlen(prefix);
6163e3
+    start = end = text;
6163e3
+    while (*end) {
6163e3
+         /* find end of line */
6163e3
+        for (; *end && *end != '\n'; end++);
6163e3
+        if (*end == '\n') {
6163e3
+            /* was this a crlf sequence? */
6163e3
+            if (end > text && end[-1] == '\r') crlf = true;
6163e3
+            /* advance past line ending */
6163e3
+            end += 1;
6163e3
+        }
6163e3
+        /* length of line including line ending */
6163e3
+        len = end - start;
6163e3
+        /* write indent prefix */
6163e3
+        apr_file_write_full(diag_fd, prefix, prefix_len, NULL);
6163e3
+        /* write line including line ending */
6163e3
+        apr_file_write_full(diag_fd, start, len, NULL);
6163e3
+        /* begin again where we left off */
6163e3
+        start = end;
6163e3
+    }
6163e3
+    /* always write a trailing line ending */
6163e3
+    if (end > text && end[-1] != '\n') {
6163e3
+        if (crlf) {
6163e3
+            apr_file_write_full(diag_fd, "\r\n", 2, NULL);
6163e3
+        } else {
6163e3
+            apr_file_write_full(diag_fd, "\n", 1, NULL);
6163e3
+        }
6163e3
+    }
6163e3
+}
6163e3
+
6163e3
+static void
6163e3
+am_diag_format_line(apr_pool_t *pool, apr_file_t *diag_fd, int level,
6163e3
+                    const char *fmt, va_list ap)
6163e3
+{
6163e3
+    char * buf = NULL;
6163e3
+    apr_size_t buf_len;
6163e3
+
6163e3
+    if (fmt) {
6163e3
+        buf = apr_pvsprintf(pool, fmt, ap);
6163e3
+        buf_len = strlen(buf);
6163e3
+        if (buf_len > 0) {
6163e3
+            const char *prefix = indent(level);
6163e3
+            apr_size_t prefix_len = strlen(prefix);
6163e3
+            apr_file_write_full(diag_fd, prefix, prefix_len, NULL);
6163e3
+            apr_file_write_full(diag_fd, buf, buf_len, NULL);
6163e3
+            apr_file_putc('\n', diag_fd);
6163e3
+        }
6163e3
+
6163e3
+    }
6163e3
+}
6163e3
+
6163e3
+static const char *
6163e3
+am_diag_cond_flag_str(request_rec *r, am_cond_flag_t flags)
6163e3
+{
6163e3
+    char *str;
6163e3
+    char *comma;
6163e3
+
6163e3
+    str = apr_pstrcat(r->pool,
6163e3
+                      "[",
6163e3
+                      flags & AM_COND_FLAG_OR   ? "OR,"   : "",
6163e3
+                      flags & AM_COND_FLAG_NOT  ? "NOT,"  : "",
6163e3
+                      flags & AM_COND_FLAG_REG  ? "REG,"  : "",
6163e3
+                      flags & AM_COND_FLAG_NC   ? "NC,"   : "",
6163e3
+                      flags & AM_COND_FLAG_MAP  ? "MAP,"  : "",
6163e3
+                      flags & AM_COND_FLAG_REF  ? "REF,"  : "",
6163e3
+                      flags & AM_COND_FLAG_SUB  ? "SUB,"  : "",
6163e3
+                      flags & AM_COND_FLAG_IGN  ? "IGN,"  : "",
6163e3
+                      flags & AM_COND_FLAG_REQ  ? "REQ,"  : "",
6163e3
+                      flags & AM_COND_FLAG_FSTR ? "FSTR," : "",
6163e3
+                      "]",
6163e3
+                      NULL);
6163e3
+
6163e3
+    /* replace trailing ",]" with "]" */
6163e3
+    comma = rindex(str, ',');
6163e3
+    if (comma) {
6163e3
+        *comma = ']';
6163e3
+        *(comma+1) = 0;
6163e3
+    }
6163e3
+    return str;
6163e3
+}
6163e3
+
6163e3
+static const char *
6163e3
+am_diag_enable_str(am_enable_t enable)
6163e3
+{
6163e3
+    switch(enable) {
6163e3
+    case am_enable_default: return "default";
6163e3
+    case am_enable_off:     return "off";
6163e3
+    case am_enable_info:    return "info";
6163e3
+    case am_enable_auth:    return "auth";
6163e3
+    default:                return "unknown";
6163e3
+    }
6163e3
+
6163e3
+}
6163e3
+
6163e3
+static const char *
6163e3
+am_diag_samesite_str(am_samesite_t samesite)
6163e3
+{
6163e3
+    switch(samesite) {
6163e3
+    case am_samesite_default: return "default";
6163e3
+    case am_samesite_lax:     return "lax";
6163e3
+    case am_samesite_strict:  return "strict";
6163e3
+    default:                  return "unknown";
6163e3
+    }
6163e3
+}
6163e3
+
6163e3
+static const char *
6163e3
+am_diag_httpd_error_level_str(request_rec *r, int level)
6163e3
+{
6163e3
+    switch(level) {
6163e3
+    case APLOG_EMERG:   return "APLOG_EMERG";
6163e3
+    case APLOG_ALERT:   return "APLOG_ALERT";
6163e3
+    case APLOG_CRIT:    return "APLOG_CRIT";
6163e3
+    case APLOG_ERR:     return "APLOG_ERR";
6163e3
+    case APLOG_WARNING: return "APLOG_WARNING";
6163e3
+    case APLOG_NOTICE:  return "APLOG_NOTICE";
6163e3
+    case APLOG_INFO:    return "APLOG_INFO";
6163e3
+    case APLOG_DEBUG:   return "APLOG_DEBUG";
6163e3
+    case APLOG_TRACE1:  return "APLOG_TRACE1";
6163e3
+    case APLOG_TRACE2:  return "APLOG_TRACE2";
6163e3
+    case APLOG_TRACE3:  return "APLOG_TRACE3";
6163e3
+    case APLOG_TRACE4:  return "APLOG_TRACE4";
6163e3
+    case APLOG_TRACE5:  return "APLOG_TRACE5";
6163e3
+    case APLOG_TRACE6:  return "APLOG_TRACE6";
6163e3
+    case APLOG_TRACE7:  return "APLOG_TRACE7";
6163e3
+    case APLOG_TRACE8:  return "APLOG_TRACE8";
6163e3
+    default:
6163e3
+        return apr_psprintf(r->pool, "APLOG_%d", level);
6163e3
+    }
6163e3
+}
6163e3
+
6163e3
+static apr_size_t
6163e3
+am_diag_time_t_to_8601_buf(char *buf, apr_size_t buf_size, apr_time_t t)
6163e3
+{
6163e3
+    apr_size_t ret_size;
6163e3
+    apr_time_exp_t tm;
6163e3
+    const char fmt[] = "%FT%TZ";
6163e3
+
6163e3
+    apr_time_exp_gmt(&tm, t);
6163e3
+    apr_strftime(buf, &ret_size, buf_size, fmt, &tm;;
6163e3
+
6163e3
+    /* on errror assure string is null terminated */
6163e3
+    if (ret_size == 0) buf[0] = 0;
6163e3
+    return ret_size;
6163e3
+}
6163e3
+
6163e3
+static int
6163e3
+am_diag_open_log(server_rec *s, apr_pool_t *p)
6163e3
+{
6163e3
+    const char *server_name = NULL;
6163e3
+    const char *server_desc = NULL;
6163e3
+    am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(s);
6163e3
+
6163e3
+    /* Build the ServerName as it would appear in the ServerName directive */
6163e3
+    if (s->server_scheme) {
6163e3
+        server_name = apr_psprintf(p, "%s://%s",
6163e3
+                                       s->server_scheme, s->server_hostname);
6163e3
+    } else {
6163e3
+        server_name = apr_psprintf(p, "%s", s->server_hostname);
6163e3
+    }
6163e3
+    if (s->port) {
6163e3
+        server_name = apr_psprintf(p, "%s:%u", server_name, s->port);
6163e3
+    }
6163e3
+
6163e3
+    if (s->is_virtual) {
6163e3
+        server_desc = apr_psprintf(p, "virtual server %s:%d (%s:%u)"
6163e3
+                                   " ServerName=%s",
6163e3
+                                   s->addrs->virthost, s->addrs->host_port,
6163e3
+                                   s->defn_name, s->defn_line_number,
6163e3
+                                   server_name);
6163e3
+    } else {
6163e3
+        server_desc = apr_psprintf(p, "main server, ServerName=%s",
6163e3
+                                   server_name);
6163e3
+    }
6163e3
+
6163e3
+    if (!(diag_cfg->flags & AM_DIAG_FLAG_ENABLED)) {
6163e3
+        ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s,
6163e3
+                     "mellon diagnostics disabled for %s", server_desc);
6163e3
+        return 1;
6163e3
+    } else {
6163e3
+        ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s,
6163e3
+                     "mellon diagnostics enabled for %s, "
6163e3
+                     "diagnostics filename=%s",
6163e3
+                     server_desc, diag_cfg->filename);
6163e3
+    }
6163e3
+
6163e3
+    if (!diag_cfg->filename || diag_cfg->fd)
6163e3
+        return 1;
6163e3
+
6163e3
+    if (*diag_cfg->filename == '|') {
6163e3
+        piped_log *pl;
6163e3
+        const char *pname = ap_server_root_relative(p, diag_cfg->filename + 1);
6163e3
+
6163e3
+        pl = ap_open_piped_log(p, pname);
6163e3
+        if (pl == NULL) {
6163e3
+            ap_log_error(APLOG_MARK, APLOG_ERR, 0, s,
6163e3
+                         "couldn't spawn mellon diagnostics log pipe %s",
6163e3
+                         diag_cfg->filename);
6163e3
+            return 0;
6163e3
+        }
6163e3
+        diag_cfg->fd = ap_piped_log_write_fd(pl);
6163e3
+    }
6163e3
+    else {
6163e3
+        const char *fname = ap_server_root_relative(p, diag_cfg->filename);
6163e3
+        apr_status_t rv;
6163e3
+
6163e3
+        if ((rv = apr_file_open(&diag_cfg->fd, fname,
6163e3
+                                APR_WRITE | APR_APPEND | APR_CREATE,
6163e3
+                                APR_OS_DEFAULT, p)) != APR_SUCCESS) {
6163e3
+            ap_log_error(APLOG_MARK, APLOG_ERR, rv, s,
6163e3
+                         "could not open mellon diagnostics log file %s.",
6163e3
+                         fname);
6163e3
+            return 0;
6163e3
+        }
6163e3
+    }
6163e3
+
6163e3
+    return 1;
6163e3
+}
6163e3
+
6163e3
+static int
6163e3
+am_table_count(void *rec, const char *key, const char *value)
6163e3
+{
6163e3
+    int *n_items = (int *)rec;
6163e3
+
6163e3
+    (*n_items)++;
6163e3
+
6163e3
+    return 1;
6163e3
+}
6163e3
+
6163e3
+static int
6163e3
+log_headers(void *rec, const char *key, const char *value)
6163e3
+{
6163e3
+    iter_callback_data *iter_data = (iter_callback_data *)rec;
6163e3
+
6163e3
+    apr_file_printf(iter_data->diag_fd, "%s%s: %s\n",
6163e3
+                    indent(iter_data->level), key, value);
6163e3
+
6163e3
+    return 1;
6163e3
+}
6163e3
+
6163e3
+static int
6163e3
+log_probe_discovery_idp(void *rec, const char *key, const char *value)
6163e3
+{
6163e3
+    iter_callback_data *iter_data = (iter_callback_data *)rec;
6163e3
+
6163e3
+    apr_file_printf(iter_data->diag_fd,
6163e3
+                    "%s%s: %s\n", indent(iter_data->level), key, value);
6163e3
+
6163e3
+    return 1;
6163e3
+}
6163e3
+
6163e3
+static void
6163e3
+am_diag_log_dir_cfg(request_rec *r, int level, am_dir_cfg_rec *cfg,
6163e3
+                    const char *fmt, ...)
6163e3
+{
6163e3
+    va_list ap;
6163e3
+    am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
6163e3
+    am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
6163e3
+    int i, n_items;
6163e3
+    apr_hash_index_t *hash_item;
6163e3
+    GList *list_item;
6163e3
+    iter_callback_data iter_data;
6163e3
+
6163e3
+    if (!AM_DIAG_ENABLED(diag_cfg)) return;
6163e3
+    if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
6163e3
+
6163e3
+    iter_data.diag_fd = diag_cfg->fd;
6163e3
+    iter_data.level = level+1;
6163e3
+
6163e3
+    va_start(ap, fmt);
6163e3
+    am_diag_format_line(r->pool, diag_cfg->fd, level, fmt, ap);
6163e3
+    va_end(ap);
6163e3
+
6163e3
+    if (!cfg) {
6163e3
+        apr_file_flush(diag_cfg->fd);
6163e3
+        return;
6163e3
+    }
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonEnable (enable): %s\n",
6163e3
+                    indent(level+1), am_diag_enable_str(cfg->enable_mellon));
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonVariable (varname): %s\n",
6163e3
+                    indent(level+1), cfg->varname);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonSecureCookie (secure): %s\n",
6163e3
+                    indent(level+1), cfg->secure ? "On":"Off"); /* FIXME, should be combined? */
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonSecureCookie (httpd_only): %s\n",
6163e3
+                    indent(level+1), cfg->http_only ? "On":"Off");
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonMergeEnvVars (merge_env_vars): %s\n",
6163e3
+                    indent(level+1), cfg->merge_env_vars);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonEnvVarsIndexStart (env_vars_index_start): %d\n",
6163e3
+                    indent(level+1), cfg->env_vars_index_start);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonEnvVarsSetCount (env_vars_count_in_n): %s\n",
6163e3
+                    indent(level+1), cfg->env_vars_count_in_n ? "On":"Off");
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonCookieDomain (cookie_domain): %s\n",
6163e3
+                    indent(level+1), cfg->cookie_domain);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonCookiePath (cookie_path): %s\n",
6163e3
+                    indent(level+1), cfg->cookie_path);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonCookieSameSite (cookie_samesite): %s\n",
6163e3
+                    indent(level+1),
6163e3
+                    am_diag_samesite_str(cfg->cookie_samesite));
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonCond (cond): %d items\n",
6163e3
+                    indent(level+1), cfg->cond->nelts);
6163e3
+    for (i = 0; i < cfg->cond->nelts; i++) {
6163e3
+        const am_cond_t *cond = &((am_cond_t *)(cfg->cond->elts))[i];
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%s[%2d]: %s\n",
6163e3
+                        indent(level+2), i, am_diag_cond_str(r, cond));
6163e3
+    }
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonSetEnv (envattr): %u items\n",
6163e3
+                    indent(level+1), apr_hash_count(cfg->envattr));
6163e3
+    for (hash_item = apr_hash_first(r->pool, cfg->envattr);
6163e3
+         hash_item;
6163e3
+         hash_item = apr_hash_next(hash_item)) {
6163e3
+        const char *key;
6163e3
+        const am_envattr_conf_t *envattr_conf;
6163e3
+        const char *name;
6163e3
+
6163e3
+        apr_hash_this(hash_item, (void *)&key, NULL, (void *)&envattr_conf);
6163e3
+
6163e3
+        if (envattr_conf->prefixed) {
6163e3
+            name = apr_pstrcat(r->pool, "MELLON_",
6163e3
+                               envattr_conf->name, NULL);
6163e3
+        } else {
6163e3
+            name = envattr_conf->name;
6163e3
+        }
6163e3
+
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%s%s ==> %s\n",
6163e3
+                        indent(level+2), key, name);
6163e3
+    }
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonUser (userattr): %s\n",
6163e3
+                    indent(level+1), cfg->userattr);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonIdP (idpattr): %s\n",
6163e3
+                    indent(level+1), cfg->idpattr);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonSessionDump (dump_session): %s\n",
6163e3
+                    indent(level+1), cfg->dump_session ? "On":"Off");
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonSamlResponseDump (dump_saml_response): %s\n",
6163e3
+                    indent(level+1), cfg->dump_saml_response ? "On":"Off");
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonEndpointPath (endpoint_path): %s\n",
6163e3
+                    indent(level+1), cfg->endpoint_path);
6163e3
+    am_diag_log_file_data(r, level+1, cfg->sp_metadata_file,
6163e3
+                          "MellonSPMetadataFile (sp_metadata_file):");
6163e3
+    am_diag_log_file_data(r, level+1, cfg->sp_private_key_file,
6163e3
+                          "MellonSPPrivateKeyFile (sp_private_key_file):");
6163e3
+    am_diag_log_file_data(r, level+1, cfg->sp_cert_file,
6163e3
+                          "MellonSPCertFile (sp_cert_file):");
6163e3
+    am_diag_log_file_data(r, level+1, cfg->idp_public_key_file,
6163e3
+                          "MellonIdPPublicKeyFile (idp_public_key_file):");
6163e3
+    am_diag_log_file_data(r, level+1, cfg->idp_ca_file,
6163e3
+                          "MellonIdPCAFile (idp_ca_file):");
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonIdPMetadataFile (idp_metadata): %d items\n",
6163e3
+                    indent(level+1), cfg->idp_metadata->nelts);
6163e3
+    for (i = 0; i < cfg->idp_metadata->nelts; i++) {
6163e3
+        const am_metadata_t *idp_metadata;
6163e3
+        idp_metadata = &(((const am_metadata_t*)cfg->idp_metadata->elts)[i]);
6163e3
+
6163e3
+        am_diag_log_file_data(r, level+1, idp_metadata->metadata,
6163e3
+                              "[%2d] Metadata", i);
6163e3
+        am_diag_log_file_data(r, level+1, idp_metadata->chain,
6163e3
+                              "[%2d] Chain File", i);
6163e3
+    }
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonIdPIgnore (idp_ignore):\n",
6163e3
+                    indent(level+1));
6163e3
+    for (list_item = cfg->idp_ignore, i = 0;
6163e3
+         list_item;
6163e3
+         list_item = g_list_next(list_item), i++) {
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%s[%2d]: %s\n",
6163e3
+                        indent(level+2), i, (char *)list_item->data);
6163e3
+    }
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonSPentityId (sp_entity_id): %s\n",
6163e3
+                    indent(level+1), cfg->sp_entity_id);
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonOrganizationName (sp_org_name): %u items\n",
6163e3
+                    indent(level+1), apr_hash_count(cfg->sp_org_name));
6163e3
+    for (hash_item = apr_hash_first(r->pool, cfg->sp_org_name);
6163e3
+         hash_item;
6163e3
+         hash_item = apr_hash_next(hash_item)) {
6163e3
+        const char *lang;
6163e3
+        const char *value;
6163e3
+
6163e3
+        apr_hash_this(hash_item, (void *)&lang, NULL, (void *)&value);
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%s(lang=%s): %s\n",
6163e3
+                        indent(level+2), lang, value);
6163e3
+    }
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonOrganizationDisplayName (sp_org_display_name):"
6163e3
+                    " %u items\n",
6163e3
+                    indent(level+1), apr_hash_count(cfg->sp_org_display_name));
6163e3
+    for (hash_item = apr_hash_first(r->pool, cfg->sp_org_display_name);
6163e3
+         hash_item;
6163e3
+         hash_item = apr_hash_next(hash_item)) {
6163e3
+        const char *lang;
6163e3
+        const char *value;
6163e3
+
6163e3
+        apr_hash_this(hash_item, (void *)&lang, NULL, (void *)&value);
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%s(lang=%s): %s\n",
6163e3
+                        indent(level+2), lang, value);
6163e3
+    }
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonOrganizationURL (sp_org_url): %u items\n",
6163e3
+                    indent(level+1), apr_hash_count(cfg->sp_org_url));
6163e3
+    for (hash_item = apr_hash_first(r->pool, cfg->sp_org_url);
6163e3
+         hash_item;
6163e3
+         hash_item = apr_hash_next(hash_item)) {
6163e3
+        const char *lang;
6163e3
+        const char *value;
6163e3
+
6163e3
+        apr_hash_this(hash_item, (void *)&lang, NULL, (void *)&value);
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%s(lang=%s): %s\n",
6163e3
+                        indent(level+2), lang, value);
6163e3
+    }
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonSessionLength (session_length): %d\n",
6163e3
+                    indent(level+1), cfg->session_length);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonNoCookieErrorPage (no_cookie_error_page): %s\n",
6163e3
+                    indent(level+1), cfg->no_cookie_error_page);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonNoSuccessErrorPage (no_success_error_page): %s\n",
6163e3
+                    indent(level+1), cfg->no_success_error_page);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonDefaultLoginPath (login_path): %s\n",
6163e3
+                    indent(level+1), cfg->login_path);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonDiscoveryURL (discovery_url): %s\n",
6163e3
+                    indent(level+1), cfg->discovery_url);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonProbeDiscoveryTimeout (probe_discovery_timeout):"
6163e3
+                    " %d\n",
6163e3
+                    indent(level+1), cfg->probe_discovery_timeout);
6163e3
+
6163e3
+    n_items = 0;
6163e3
+    apr_table_do(am_table_count, &n_items, cfg->probe_discovery_idp, NULL);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonProbeDiscoveryIdP (probe_discovery_idp):"
6163e3
+                    " %d items\n",
6163e3
+                    indent(level+1), n_items);
6163e3
+    apr_table_do(log_probe_discovery_idp, &iter_data,
6163e3
+                 cfg->probe_discovery_idp, NULL);
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonAuthnContextClassRef (authn_context_class_ref):"
6163e3
+                    " %d items\n",
6163e3
+                    indent(level+1), cfg->authn_context_class_ref->nelts);
6163e3
+    for(i = 0; i < cfg->authn_context_class_ref->nelts; i++) {
6163e3
+        const char *context_class;
6163e3
+
6163e3
+        context_class = APR_ARRAY_IDX(cfg->authn_context_class_ref, i, char *);
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%s[%2d]: %s\n",
6163e3
+                        indent(level+2), i, context_class);
6163e3
+    }
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonSubjectConfirmationDataAddressCheck"
6163e3
+                    " (subject_confirmation_data_address_check): %s\n",
6163e3
+                    indent(level+1),
6163e3
+                    cfg->subject_confirmation_data_address_check ? "On":"Off");
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonDoNotVerifyLogoutSignature"
6163e3
+                    " (do_not_verify_logout_signature): %u items\n",
6163e3
+                    indent(level+1),
6163e3
+                    apr_hash_count(cfg->do_not_verify_logout_signature));
6163e3
+
6163e3
+    for (hash_item = apr_hash_first(r->pool,
6163e3
+                                    cfg->do_not_verify_logout_signature);
6163e3
+         hash_item;
6163e3
+         hash_item = apr_hash_next(hash_item)) {
6163e3
+        const char *entity_id;
6163e3
+
6163e3
+        apr_hash_this(hash_item, (void *)&entity_id, NULL, NULL);
6163e3
+
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%s%s\n",
6163e3
+                        indent(level+2), entity_id);
6163e3
+    }
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonSendCacheControlHeader"
6163e3
+                    " (send_cache_control_header): %s\n",
6163e3
+                    indent(level+1),
6163e3
+                    cfg->send_cache_control_header ? "On":"Off");
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonPostReplay (post_replay): %s\n",
6163e3
+                    indent(level+1), cfg->post_replay ? "On":"Off");
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonECPSendIDPList (ecp_send_idplist): %s\n",
6163e3
+                    indent(level+1), cfg->ecp_send_idplist ? "On":"Off");
6163e3
+
6163e3
+    for (n_items = 0; cfg->redirect_domains[n_items] != NULL; n_items++);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "%sMellonRedirectDomains (redirect_domains): %d items\n",
6163e3
+                    indent(level+1), n_items);
6163e3
+    for (i = 0; cfg->redirect_domains[i] != NULL; i++) {
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%s%s\n",
6163e3
+                        indent(level+2), cfg->redirect_domains[i]);
6163e3
+    }
6163e3
+
6163e3
+    apr_file_flush(diag_cfg->fd);
6163e3
+}
6163e3
+
6163e3
+
6163e3
+static bool
6163e3
+am_diag_initialize_req(request_rec *r, am_diag_cfg_rec *diag_cfg,
6163e3
+                       am_req_cfg_rec *req_cfg)
6163e3
+{
6163e3
+    server_rec *s = r->server;
6163e3
+    am_dir_cfg_rec *dir_cfg;
6163e3
+    apr_os_thread_t tid = apr_os_thread_current();
6163e3
+    iter_callback_data iter_data;
6163e3
+    int level = 0;
6163e3
+
6163e3
+    if (!diag_cfg) return false;
6163e3
+    if (!diag_cfg->fd) return false;
6163e3
+    if (!req_cfg) return false;
6163e3
+
6163e3
+    if (req_cfg->diag_emitted) return true;
6163e3
+
6163e3
+    iter_data.diag_fd = diag_cfg->fd;
6163e3
+    iter_data.level = level+1;
6163e3
+
6163e3
+    apr_file_puts("---------------------------------- New Request"
6163e3
+                  " ---------------------------------\n", diag_cfg->fd);
6163e3
+    apr_file_printf(diag_cfg->fd, "%s - %s\n", r->method, r->uri);
6163e3
+    apr_file_printf(diag_cfg->fd, "log_id: %s\n", r->log_id);
6163e3
+    apr_file_printf(diag_cfg->fd, "server: scheme=%s hostname=%s port=%d\n",
6163e3
+                    s->server_scheme, s->server_hostname, s->port);
6163e3
+    apr_file_printf(diag_cfg->fd, "pid: %" APR_PID_T_FMT ", tid: %pT\n",
6163e3
+                    getpid(), &tid;;
6163e3
+    apr_file_printf(diag_cfg->fd, "unparsed_uri: %s\n", r->unparsed_uri);
6163e3
+    apr_file_printf(diag_cfg->fd, "uri: %s\n", r->uri);
6163e3
+    apr_file_printf(diag_cfg->fd, "path_info: %s\n", r->path_info);
6163e3
+    apr_file_printf(diag_cfg->fd, "filename: %s\n", r->filename);
6163e3
+    apr_file_printf(diag_cfg->fd, "query args: %s\n", r->args);
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd, "Request Headers:\n");
6163e3
+    apr_table_do(log_headers, &iter_data, r->headers_in, NULL);
6163e3
+
6163e3
+    req_cfg->diag_emitted = true;
6163e3
+
6163e3
+
6163e3
+    /* Only emit directory configuration once */
6163e3
+    if (!apr_table_get(diag_cfg->dir_cfg_emitted, r->uri)) {
6163e3
+        dir_cfg = am_get_dir_cfg(r);
6163e3
+
6163e3
+        am_diag_log_dir_cfg(r, level, dir_cfg,
6163e3
+                            "Mellon Directory Configuration for URL: %s",
6163e3
+                            r->uri);
6163e3
+        apr_table_set(diag_cfg->dir_cfg_emitted, r->uri, "1");
6163e3
+    }
6163e3
+    return true;
6163e3
+}
6163e3
+
6163e3
+/*=============================== Public API =================================*/
6163e3
+
6163e3
+int
6163e3
+am_diag_log_init(apr_pool_t *pc, apr_pool_t *p, apr_pool_t *pt, server_rec *s)
6163e3
+{
6163e3
+    for ( ; s ; s = s->next) {
6163e3
+        if (!am_diag_open_log(s, p)) {
6163e3
+            return HTTP_INTERNAL_SERVER_ERROR;
6163e3
+        }
6163e3
+    }
6163e3
+
6163e3
+    return OK;
6163e3
+}
6163e3
+
6163e3
+int
6163e3
+am_diag_finalize_request(request_rec *r)
6163e3
+{
6163e3
+    am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
6163e3
+    am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
6163e3
+    int level = 0;
6163e3
+    iter_callback_data iter_data;
6163e3
+
6163e3
+    if (!AM_DIAG_ENABLED(diag_cfg)) return OK;
6163e3
+    if (!req_cfg) return OK;
6163e3
+
6163e3
+    if (!req_cfg->diag_emitted) return OK;
6163e3
+
6163e3
+    iter_data.diag_fd = diag_cfg->fd;
6163e3
+    iter_data.level = level+1;
6163e3
+
6163e3
+    apr_file_puts("\n=== Response ===\n", diag_cfg->fd);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "Status: %s(%d)\n",
6163e3
+                    r->status_line, r->status);
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "user: %s auth_type=%s\n",
6163e3
+                    r->user, r->ap_auth_type);
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "Response Headers:\n");
6163e3
+    apr_table_do(log_headers, &iter_data, r->headers_out, NULL);
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "Response Error Headers:\n");
6163e3
+    apr_table_do(log_headers, &iter_data, r->err_headers_out, NULL);
6163e3
+
6163e3
+    apr_file_printf(diag_cfg->fd,
6163e3
+                    "Environment:\n");
6163e3
+    apr_table_do(log_headers, &iter_data, r->subprocess_env, NULL);
6163e3
+
6163e3
+    return OK;
6163e3
+}
6163e3
+
6163e3
+char *
6163e3
+am_diag_time_t_to_8601(request_rec *r, apr_time_t t)
6163e3
+{
6163e3
+    char *buf;
6163e3
+
6163e3
+    buf = apr_palloc(r->pool, ISO_8601_BUF_SIZE);
6163e3
+    if (!buf) return NULL;
6163e3
+
6163e3
+    am_diag_time_t_to_8601_buf(buf, ISO_8601_BUF_SIZE, t);
6163e3
+    return buf;
6163e3
+}
6163e3
+
6163e3
+const char *
6163e3
+am_diag_cond_str(request_rec *r, const am_cond_t *cond)
6163e3
+{
6163e3
+    return apr_psprintf(r->pool,
6163e3
+                        "varname=\"%s\" flags=%s str=\"%s\" directive=\"%s\"",
6163e3
+                        cond->varname, am_diag_cond_flag_str(r, cond->flags),
6163e3
+                        cond->str, cond->directive);
6163e3
+}
6163e3
+
6163e3
+const char *
6163e3
+am_diag_cache_key_type_str(am_cache_key_t key_type)
6163e3
+{
6163e3
+    switch(key_type) {
6163e3
+    case AM_CACHE_SESSION: return "session";
6163e3
+    case AM_CACHE_NAMEID : return "name id";
6163e3
+    default:               return "unknown";
6163e3
+    }
6163e3
+}
6163e3
+
6163e3
+const char *
6163e3
+am_diag_lasso_http_method_str(LassoHttpMethod http_method)
6163e3
+{
6163e3
+    switch(http_method) {
6163e3
+    case LASSO_HTTP_METHOD_NONE:          return "LASSO_HTTP_METHOD_NONE";
6163e3
+    case LASSO_HTTP_METHOD_ANY:           return "LASSO_HTTP_METHOD_ANY";
6163e3
+    case LASSO_HTTP_METHOD_IDP_INITIATED: return "LASSO_HTTP_METHOD_IDP_INITIATED";
6163e3
+    case LASSO_HTTP_METHOD_GET:           return "LASSO_HTTP_METHOD_GET";
6163e3
+    case LASSO_HTTP_METHOD_POST:          return "LASSO_HTTP_METHOD_POST";
6163e3
+    case LASSO_HTTP_METHOD_REDIRECT:      return "LASSO_HTTP_METHOD_REDIRECT";
6163e3
+    case LASSO_HTTP_METHOD_SOAP:          return "LASSO_HTTP_METHOD_SOAP";
6163e3
+    case LASSO_HTTP_METHOD_ARTIFACT_GET:  return "LASSO_HTTP_METHOD_ARTIFACT_GET";
6163e3
+    case LASSO_HTTP_METHOD_ARTIFACT_POST: return "LASSO_HTTP_METHOD_ARTIFACT_POST";
6163e3
+    case LASSO_HTTP_METHOD_PAOS:          return "LASSO_HTTP_METHOD_PAOS";
6163e3
+    default:                              return "unknown";
6163e3
+    }
6163e3
+}
6163e3
+
6163e3
+void
6163e3
+am_diag_printf(request_rec *r, const char *fmt, ...)
6163e3
+{
6163e3
+    va_list ap;
6163e3
+    am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
6163e3
+    am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
6163e3
+    char *buf;
6163e3
+    apr_size_t buf_len;
6163e3
+
6163e3
+    if (!AM_DIAG_ENABLED(diag_cfg)) return;
6163e3
+    if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
6163e3
+
6163e3
+
6163e3
+    va_start(ap, fmt);
6163e3
+    buf = apr_pvsprintf(r->pool, fmt, ap);
6163e3
+    va_end(ap);
6163e3
+    buf_len = strlen(buf);
6163e3
+    if (buf_len > 0) {
6163e3
+        apr_file_write_full(diag_cfg->fd, buf, buf_len, NULL);
6163e3
+    }
6163e3
+    apr_file_flush(diag_cfg->fd);
6163e3
+}
6163e3
+
6163e3
+void
6163e3
+am_diag_rerror(const char *file, int line, int module_index,
6163e3
+               int level, apr_status_t status,
6163e3
+               request_rec *r, const char *fmt, ...)
6163e3
+{
6163e3
+    va_list ap;
6163e3
+    am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
6163e3
+    am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
6163e3
+    char *buf;
6163e3
+
6163e3
+    if (!AM_DIAG_ENABLED(diag_cfg)) return;
6163e3
+    if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
6163e3
+
6163e3
+    buf = apr_psprintf(r->pool, "[%s %s:%d] ",
6163e3
+                       am_diag_httpd_error_level_str(r, level), file, line);
6163e3
+    apr_file_puts(buf, diag_cfg->fd);
6163e3
+
6163e3
+    va_start(ap, fmt);
6163e3
+    buf = apr_pvsprintf(r->pool, fmt, ap);
6163e3
+    va_end(ap);
6163e3
+    apr_file_puts(buf, diag_cfg->fd);
6163e3
+
6163e3
+    apr_file_puts(APR_EOL_STR, diag_cfg->fd);
6163e3
+    apr_file_flush(diag_cfg->fd);
6163e3
+}
6163e3
+
6163e3
+void
6163e3
+am_diag_log_lasso_node(request_rec *r, int level, LassoNode *node,
6163e3
+                       const char *fmt, ...)
6163e3
+{
6163e3
+    va_list ap;
6163e3
+    am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
6163e3
+    am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
6163e3
+    gchar *xml = NULL;
6163e3
+
6163e3
+    if (!AM_DIAG_ENABLED(diag_cfg)) return;
6163e3
+    if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
6163e3
+
6163e3
+    va_start(ap, fmt);
6163e3
+    am_diag_format_line(r->pool, diag_cfg->fd, level, fmt, ap);
6163e3
+    va_end(ap);
6163e3
+
6163e3
+    if (node) {
6163e3
+        xml = lasso_node_debug(node, 0);
6163e3
+        write_indented_text(diag_cfg->fd, level+1, xml);
6163e3
+        lasso_release_string(xml);
6163e3
+    } else {
6163e3
+        apr_file_printf(diag_cfg->fd, "node is NULL\n");
6163e3
+    }
6163e3
+    apr_file_flush(diag_cfg->fd);
6163e3
+}
6163e3
+
6163e3
+void
6163e3
+am_diag_log_file_data(request_rec *r, int level, am_file_data_t *file_data,
6163e3
+                      const char *fmt, ...)
6163e3
+{
6163e3
+    va_list ap;
6163e3
+    am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
6163e3
+    am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
6163e3
+
6163e3
+    if (!AM_DIAG_ENABLED(diag_cfg)) return;
6163e3
+    if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
6163e3
+
6163e3
+    va_start(ap, fmt);
6163e3
+    am_diag_format_line(r->pool, diag_cfg->fd, level, fmt, ap);
6163e3
+    va_end(ap);
6163e3
+
6163e3
+    if (file_data) {
6163e3
+        if (file_data->generated) {
6163e3
+            apr_file_printf(diag_cfg->fd,
6163e3
+                            "%sGenerated file contents:\n",
6163e3
+                            indent(level+1));
6163e3
+            write_indented_text(diag_cfg->fd,
6163e3
+                                level+2, file_data->contents);
6163e3
+        } else {
6163e3
+            apr_file_printf(diag_cfg->fd,
6163e3
+                            "%spathname: \"%s\"\n",
6163e3
+                            indent(level+1), file_data->path);
6163e3
+            if (!file_data->read_time) {
6163e3
+                am_file_read(file_data);
6163e3
+            }
6163e3
+            if (file_data->rv == APR_SUCCESS) {
6163e3
+                write_indented_text(diag_cfg->fd,
6163e3
+                                    level+2, file_data->contents);
6163e3
+            } else {
6163e3
+                apr_file_printf(diag_cfg->fd,
6163e3
+                                "%s%s\n",
6163e3
+                                indent(level+1), file_data->strerror);
6163e3
+            }
6163e3
+        }
6163e3
+    } else {
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%sfile_data: NULL\n",
6163e3
+                        indent(level+1));
6163e3
+    }
6163e3
+
6163e3
+    apr_file_flush(diag_cfg->fd);
6163e3
+}
6163e3
+
6163e3
+void
6163e3
+am_diag_log_profile(request_rec *r, int level, LassoProfile *profile,
6163e3
+                    const char *fmt, ...)
6163e3
+{
6163e3
+    va_list ap;
6163e3
+    am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
6163e3
+    am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
6163e3
+    LassoSession *session = lasso_profile_get_session(profile);
6163e3
+    GList *assertions = lasso_session_get_assertions(session, NULL);
6163e3
+    GList *iter = NULL;
6163e3
+    int i;
6163e3
+
6163e3
+    if (!AM_DIAG_ENABLED(diag_cfg)) return;
6163e3
+    if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
6163e3
+
6163e3
+    va_start(ap, fmt);
6163e3
+    am_diag_format_line(r->pool, diag_cfg->fd, level, fmt, ap);
6163e3
+    va_end(ap);
6163e3
+
6163e3
+    if (profile) {
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%sProfile Type: %s\n",
6163e3
+                        indent(level+1), G_OBJECT_TYPE_NAME(profile));
6163e3
+
6163e3
+        for (iter = assertions, i=0;
6163e3
+             iter != NULL;
6163e3
+             iter = g_list_next(iter), i++) {
6163e3
+            LassoSaml2Assertion *assertion = NULL;
6163e3
+
6163e3
+            assertion = LASSO_SAML2_ASSERTION(iter->data);
6163e3
+            if (!LASSO_IS_SAML2_ASSERTION(assertion)) {
6163e3
+                apr_file_printf(diag_cfg->fd,
6163e3
+                                "%sObject at index %d in session assertion"
6163e3
+                                " list is not LassoSaml2Assertion",
6163e3
+                                indent(level+1), i);
6163e3
+            } else {
6163e3
+                am_diag_log_lasso_node(r, level+1, &assertion->parent,
6163e3
+                                       "Assertion %d", i);
6163e3
+            }
6163e3
+        }
6163e3
+    } else {
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%sprofile is NULL\n",
6163e3
+                        indent(level+1));
6163e3
+    }
6163e3
+
6163e3
+    apr_file_flush(diag_cfg->fd);
6163e3
+}
6163e3
+
6163e3
+void
6163e3
+am_diag_log_cache_entry(request_rec *r, int level, am_cache_entry_t *entry,
6163e3
+                        const char *fmt, ...)
6163e3
+{
6163e3
+    va_list ap;
6163e3
+    am_diag_cfg_rec *diag_cfg = am_get_diag_cfg(r->server);
6163e3
+    am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
6163e3
+
6163e3
+    const char *name_id = NULL;
6163e3
+
6163e3
+    if (!AM_DIAG_ENABLED(diag_cfg)) return;
6163e3
+    if (!am_diag_initialize_req(r, diag_cfg, req_cfg)) return;
6163e3
+
6163e3
+    va_start(ap, fmt);
6163e3
+    am_diag_format_line(r->pool, diag_cfg->fd, level, fmt, ap);
6163e3
+    va_end(ap);
6163e3
+
6163e3
+    if (entry) {
6163e3
+        name_id = am_cache_env_fetch_first(entry, "NAME_ID");
6163e3
+
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%skey: %s\n",
6163e3
+                        indent(level+1), entry->key);
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%sname_id: %s\n",
6163e3
+                        indent(level+1), name_id);
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%sexpires: %s\n",
6163e3
+                        indent(level+1),
6163e3
+                        am_diag_time_t_to_8601(r, entry->expires));
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%saccess: %s\n",
6163e3
+                        indent(level+1),
6163e3
+                        am_diag_time_t_to_8601(r, entry->access));
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%slogged_in: %s\n",
6163e3
+                        indent(level+1), entry->logged_in ? "True" : "False");
6163e3
+    } else {
6163e3
+        apr_file_printf(diag_cfg->fd,
6163e3
+                        "%sentry is NULL\n",
6163e3
+                        indent(level+1));
6163e3
+    }
6163e3
+    apr_file_flush(diag_cfg->fd);
6163e3
+}
6163e3
+
6163e3
+
6163e3
+#endif /* ENABLE_DIAGNOSTICS */
6163e3
diff --git a/auth_mellon_handler.c b/auth_mellon_handler.c
6163e3
index 08b7869..0cbc0ad 100644
6163e3
--- a/auth_mellon_handler.c
6163e3
+++ b/auth_mellon_handler.c
6163e3
@@ -121,6 +121,8 @@ static char *am_generate_metadata(apr_pool_t *p, request_rec *r)
6163e3
     char *cert = "";
6163e3
     const char *sp_entity_id;
6163e3
 
6163e3
+    am_diag_printf(r, "Generating SP metadata\n");
6163e3
+
6163e3
     sp_entity_id = cfg->sp_entity_id ? cfg->sp_entity_id : url;
6163e3
 
6163e3
     if (cfg->sp_cert_file && cfg->sp_cert_file->contents) {
6163e3
@@ -251,6 +253,13 @@ static guint am_server_add_providers(am_dir_cfg_rec *cfg, request_rec *r)
6163e3
 
6163e3
         idp_metadata = &( ((const am_metadata_t*)cfg->idp_metadata->elts) [index] );
6163e3
 
6163e3
+        am_diag_log_file_data(r, 0, idp_metadata->metadata,
6163e3
+                              "Loading IdP Metadata");
6163e3
+        if (idp_metadata->chain) {
6163e3
+            am_diag_log_file_data(r, 0, idp_metadata->chain,
6163e3
+                                  "Loading IdP metadata chain");
6163e3
+        }
6163e3
+
6163e3
 #ifdef HAVE_lasso_server_load_metadata
6163e3
         error = lasso_server_load_metadata(cfg->server,
6163e3
                                            LASSO_PROVIDER_ROLE_IDP,
6163e3
@@ -674,6 +683,9 @@ static void am_restore_lasso_profile_state(request_rec *r,
6163e3
             am_release_request_session(r, am_session);
6163e3
         }
6163e3
     }
6163e3
+    am_diag_log_cache_entry(r, 0, am_session, "%s: Session Cache Entry", __func__);
6163e3
+
6163e3
+    am_diag_log_profile(r, 0, profile,  "%s: Restored Profile", __func__);
6163e3
 }
6163e3
 
6163e3
 /* This function handles an IdP initiated logout request.
6163e3
@@ -693,6 +705,8 @@ static int am_handle_logout_request(request_rec *r,
6163e3
     am_cache_entry_t *session = NULL;
6163e3
     am_dir_cfg_rec *cfg = am_get_dir_cfg(r);
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
     /* Process the logout message. Ignore missing signature. */
6163e3
     res = lasso_logout_process_request_msg(logout, msg);
6163e3
 #ifdef HAVE_lasso_profile_set_signature_verify_hint
6163e3
@@ -724,6 +738,10 @@ static int am_handle_logout_request(request_rec *r,
6163e3
         rc = HTTP_BAD_REQUEST;
6163e3
         goto exit;
6163e3
     }
6163e3
+
6163e3
+    am_diag_printf(r, "%s name id %s\n", __func__,
6163e3
+                   ((LassoSaml2NameID*)logout->parent.nameIdentifier)->content);
6163e3
+
6163e3
     session = am_get_request_session_by_nameid(r,
6163e3
                     ((LassoSaml2NameID*)logout->parent.nameIdentifier)->content);
6163e3
     if (session == NULL) {
6163e3
@@ -733,6 +751,9 @@ static int am_handle_logout_request(request_rec *r,
6163e3
                       ((LassoSaml2NameID*)logout->parent.nameIdentifier)->content);
6163e3
 
6163e3
     }
6163e3
+
6163e3
+    am_diag_log_cache_entry(r, 0, session, "%s", __func__);
6163e3
+
6163e3
     if (session == NULL) {
6163e3
         ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
6163e3
                       "Error processing logout request message."
6163e3
@@ -830,6 +851,9 @@ static int am_handle_logout_response(request_rec *r, LassoLogout *logout)
6163e3
 
6163e3
     /* Delete the session. */
6163e3
     session = am_get_request_session(r);
6163e3
+
6163e3
+    am_diag_log_cache_entry(r, 0, session, "%s\n", __func__);
6163e3
+
6163e3
     if(session != NULL) {
6163e3
         am_delete_request_session(r, session);
6163e3
     }
6163e3
@@ -1482,6 +1506,9 @@ static void am_handle_session_expire(request_rec *r, am_cache_entry_t *session,
6163e3
         /* Find timestamp. */
6163e3
         not_on_or_after = authn->SessionNotOnOrAfter;
6163e3
         if(not_on_or_after == NULL) {
6163e3
+            am_diag_printf(r, "%s failed to find"
6163e3
+                           " Assertion.AuthnStatement.SessionNotOnOrAfter\n",
6163e3
+                           __func__);
6163e3
             continue;
6163e3
         }
6163e3
 
6163e3
@@ -1492,6 +1519,10 @@ static void am_handle_session_expire(request_rec *r, am_cache_entry_t *session,
6163e3
             continue;
6163e3
         }
6163e3
 
6163e3
+        am_diag_printf(r, "%s Assertion.AuthnStatement.SessionNotOnOrAfter:"
6163e3
+                       " %s\n",
6163e3
+                       __func__, am_diag_time_t_to_8601(r, t));
6163e3
+
6163e3
         /* Updates the expires timestamp if this one is earlier than the
6163e3
          * previous timestamp.
6163e3
          */
6163e3
@@ -1629,6 +1660,10 @@ static int add_attributes(am_cache_entry_t *session, request_rec *r,
6163e3
                         g_free(dump);
6163e3
                 }
6163e3
                 /* Decode and save the attribute. */
6163e3
+
6163e3
+                am_diag_printf(r, "%s name=%s value=%s\n",
6163e3
+                               __func__, attribute->Name, content);
6163e3
+
6163e3
                 ret = am_cache_env_append(session, attribute->Name, content);
6163e3
                 if(ret != OK) {
6163e3
                     return ret;
6163e3
@@ -1725,6 +1760,9 @@ static int am_handle_reply_common(request_rec *r, LassoLogin *login,
6163e3
     int rc;
6163e3
     const char *idp;
6163e3
 
6163e3
+    am_diag_log_lasso_node(r, 0, LASSO_PROFILE(login)->response,
6163e3
+                           "SAMLResponse:");
6163e3
+
6163e3
     url = am_reconstruct_url(r);
6163e3
     chr = strchr(url, '?');
6163e3
     if (! chr) {
6163e3
@@ -1867,7 +1905,6 @@ static int am_handle_reply_common(request_rec *r, LassoLogin *login,
6163e3
         return HTTP_INTERNAL_SERVER_ERROR;
6163e3
     }
6163e3
 
6163e3
-
6163e3
     /* Save the profile state. */
6163e3
     rc = am_save_lasso_profile_state(r, session, LASSO_PROFILE(login),
6163e3
                                      saml_response);
6163e3
@@ -1941,6 +1978,8 @@ static int am_handle_post_reply(request_rec *r)
6163e3
     am_dir_cfg_rec *dir_cfg = am_get_dir_cfg(r);
6163e3
     int i, err;
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
     /* Make sure that this is a POST request. */
6163e3
     if(r->method_number != M_POST) {
6163e3
         ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
6163e3
@@ -2050,6 +2089,8 @@ static int am_handle_paos_reply(request_rec *r)
6163e3
     char *relay_state = NULL;
6163e3
     int i, err;
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
     /* Make sure that this is a POST request. */
6163e3
     if(r->method_number != M_POST) {
6163e3
         ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
6163e3
@@ -2137,6 +2178,8 @@ static int am_handle_artifact_reply(request_rec *r)
6163e3
     char *saml_art;
6163e3
     char *post_data;
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
     /* Make sure that this is a GET request. */
6163e3
     if(r->method_number != M_GET && r->method_number != M_POST) {
6163e3
         ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
6163e3
@@ -2408,6 +2451,8 @@ static int am_handle_repost(request_rec *r)
6163e3
     const char *(*post_mkform)(request_rec *, const char *);
6163e3
     int rc;
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
     if (am_cookie_get(r) == NULL) {
6163e3
         ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, 
6163e3
                       "Repost query without a session");
6163e3
@@ -2570,6 +2615,8 @@ static int am_handle_metadata(request_rec *r)
6163e3
     LassoServer *server;
6163e3
     const char *data;
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
     server = am_get_lasso_server(r);
6163e3
     if(server == NULL)
6163e3
         return HTTP_INTERNAL_SERVER_ERROR;
6163e3
@@ -2898,6 +2945,11 @@ static int am_init_authn_request_common(request_rec *r,
6163e3
 static int am_set_authn_request_content(request_rec *r, LassoLogin *login)
6163e3
 
6163e3
 {
6163e3
+
6163e3
+    am_diag_log_lasso_node(r, 0, LASSO_PROFILE(login)->request,
6163e3
+                           "SAML AuthnRequest: http_method=%s",
6163e3
+                           am_diag_lasso_http_method_str(login->http_method));
6163e3
+
6163e3
     switch (login->http_method) {
6163e3
     case LASSO_HTTP_METHOD_REDIRECT:
6163e3
         return am_set_authn_request_redirect_content(r, login);
6163e3
@@ -3112,6 +3164,8 @@ static int am_handle_auth(request_rec *r)
6163e3
     am_dir_cfg_rec *cfg = am_get_dir_cfg(r);
6163e3
     const char *relay_state;
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
     relay_state = am_reconstruct_url(r);
6163e3
 
6163e3
     /* Check if IdP discovery is in use and no IdP was selected yet */
6163e3
@@ -3151,6 +3205,8 @@ static int am_handle_login(request_rec *r)
6163e3
     int is_passive;
6163e3
     int ret;
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
     return_to = am_extract_query_parameter(r->pool, r->args, "ReturnTo");
6163e3
     if(return_to == NULL) {
6163e3
         ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,
6163e3
@@ -3255,6 +3311,8 @@ static int am_handle_probe_discovery(request_rec *r) {
6163e3
     char *redirect_url;
6163e3
     int ret;
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
     server = am_get_lasso_server(r);
6163e3
     if(server == NULL) {
6163e3
         return HTTP_INTERNAL_SERVER_ERROR;
6163e3
@@ -3488,6 +3546,8 @@ static int am_start_auth(request_rec *r)
6163e3
     const char *idp;
6163e3
     const char *login_url;
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
     return_to = am_reconstruct_url(r);
6163e3
 
6163e3
     /* If this is a POST request, attempt to save it */
6163e3
@@ -3539,6 +3599,8 @@ int am_auth_mellon_user(request_rec *r)
6163e3
 	return DECLINED;
6163e3
     }
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
     /* Set defaut Cache-Control headers within this location */
6163e3
     if (CFG_VALUE(dir, send_cache_control_header)) {
6163e3
         am_set_cache_control_headers(r);
6163e3
@@ -3563,6 +3625,9 @@ int am_auth_mellon_user(request_rec *r)
6163e3
         if(session == NULL || !session->logged_in) {
6163e3
             /* We don't have a valid session. */
6163e3
 
6163e3
+            am_diag_printf(r, "%s am_enable_auth, no valid session\n",
6163e3
+                           __func__);
6163e3
+
6163e3
             if(session) {
6163e3
                 /* Release the session. */
6163e3
                 am_release_request_session(r, session);
6163e3
@@ -3613,9 +3678,14 @@ int am_auth_mellon_user(request_rec *r)
6163e3
 #endif /* HAVE_ECP */
6163e3
         }
6163e3
 
6163e3
+        am_diag_printf(r, "%s am_enable_auth, have valid session\n",
6163e3
+                       __func__);
6163e3
+
6163e3
         /* Verify that the user has access to this resource. */
6163e3
         return_code = am_check_permissions(r, session);
6163e3
         if(return_code != OK) {
6163e3
+            am_diag_printf(r, "%s failed am_check_permissions, status=%d\n",
6163e3
+                           __func__, return_code);
6163e3
             am_release_request_session(r, session);
6163e3
 
6163e3
             return return_code;
6163e3
@@ -3643,11 +3713,17 @@ int am_auth_mellon_user(request_rec *r)
6163e3
            && session->logged_in
6163e3
            && am_check_permissions(r, session) == OK) {
6163e3
 
6163e3
+            am_diag_printf(r, "%s am_enable_info, have valid session\n",
6163e3
+                           __func__);
6163e3
+
6163e3
             /* The user is authenticated and has access to the resource.
6163e3
              * Now we populate the environment with information about
6163e3
              * the user.
6163e3
              */
6163e3
             am_cache_env_populate(r, session);
6163e3
+        } else {
6163e3
+            am_diag_printf(r, "%s am_enable_info, no valid session\n",
6163e3
+                           __func__);
6163e3
         }
6163e3
 
6163e3
         if(session != NULL) {
6163e3
@@ -3688,6 +3764,8 @@ int am_check_uid(request_rec *r)
6163e3
 	return DECLINED;
6163e3
     }
6163e3
 
6163e3
+    am_diag_printf(r, "enter function %s\n", __func__);
6163e3
+
6163e3
 #ifdef HAVE_ECP
6163e3
     am_req_cfg_rec *req_cfg = am_get_req_cfg(r);
6163e3
     if (req_cfg->ecp_authn_req) {
6163e3
@@ -3744,11 +3822,15 @@ int am_check_uid(request_rec *r)
6163e3
 
6163e3
     /* If we don't have a session, then we can't authorize the user. */
6163e3
     if(session == NULL) {
6163e3
+        am_diag_printf(r, "%s no session, return HTTP_UNAUTHORIZED\n",
6163e3
+                       __func__);
6163e3
         return HTTP_UNAUTHORIZED;
6163e3
     }
6163e3
 
6163e3
     /* If the user isn't logged in, then we can't authorize the user. */
6163e3
     if(!session->logged_in) {
6163e3
+        am_diag_printf(r, "%s session not logged in,"
6163e3
+                       " return HTTP_UNAUTHORIZED\n", __func__);
6163e3
         am_release_request_session(r, session);
6163e3
         return HTTP_UNAUTHORIZED;
6163e3
     }
6163e3
@@ -3756,6 +3838,8 @@ int am_check_uid(request_rec *r)
6163e3
     /* Verify that the user has access to this resource. */
6163e3
     return_code = am_check_permissions(r, session);
6163e3
     if(return_code != OK) {
6163e3
+        am_diag_printf(r, "%s failed am_check_permissions, status=%d\n",
6163e3
+                       __func__, return_code);
6163e3
         am_release_request_session(r, session);
6163e3
         return return_code;
6163e3
     }
6163e3
diff --git a/auth_mellon_session.c b/auth_mellon_session.c
6163e3
index 3eae4a0..31ae5db 100644
6163e3
--- a/auth_mellon_session.c
6163e3
+++ b/auth_mellon_session.c
6163e3
@@ -39,9 +39,18 @@ am_cache_entry_t *am_lock_and_validate(request_rec *r,
6163e3
                                        am_cache_key_t type,
6163e3
                                        const char *key)
6163e3
 {
6163e3
-    am_cache_entry_t *session = am_cache_lock(r, type, key);
6163e3
+    am_cache_entry_t *session = NULL;
6163e3
+
6163e3
+    am_diag_printf(r, "searching for session with key %s (%s) ... ",
6163e3
+                   key, am_diag_cache_key_type_str(type));
6163e3
+
6163e3
+    session = am_cache_lock(r, type, key);
6163e3
     if (session == NULL) {
6163e3
+        am_diag_printf(r, "not found\n");
6163e3
         return NULL;
6163e3
+    } else {
6163e3
+        am_diag_printf(r, "found.\n");
6163e3
+        am_diag_log_cache_entry(r, 0, session, "Session Cache Entry");
6163e3
     }
6163e3
 
6163e3
     const char *cookie_token_session = am_cache_entry_get_string(
6163e3
@@ -123,6 +132,10 @@ am_cache_entry_t *am_new_request_session(request_rec *r)
6163e3
     am_cookie_set(r, session_id);
6163e3
 
6163e3
     const char *cookie_token = am_cookie_token(r);
6163e3
+
6163e3
+    am_diag_printf(r, "%s id=%s cookie_token=\"%s\"\n",
6163e3
+                   __func__, session_id, cookie_token);
6163e3
+
6163e3
     return am_cache_new(r, session_id, cookie_token);
6163e3
 }
6163e3
 
6163e3
@@ -155,6 +168,8 @@ void am_release_request_session(request_rec *r, am_cache_entry_t *session)
6163e3
  */
6163e3
 void am_delete_request_session(request_rec *r, am_cache_entry_t *session)
6163e3
 {
6163e3
+    am_diag_log_cache_entry(r, 0, session, "delete session");
6163e3
+
6163e3
     /* Delete the cookie. */
6163e3
     am_cookie_delete(r);
6163e3
 
6163e3
diff --git a/auth_mellon_util.c b/auth_mellon_util.c
6163e3
index 7f8d52b..46036a9 100644
6163e3
--- a/auth_mellon_util.c
6163e3
+++ b/auth_mellon_util.c
6163e3
@@ -370,6 +370,10 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
6163e3
 
6163e3
         ce = &((am_cond_t *)(dir_cfg->cond->elts))[i];
6163e3
 
6163e3
+        am_diag_printf(r, "%s processing condition %d of %d: %s ",
6163e3
+                       __func__, i, dir_cfg->cond->nelts,
6163e3
+                       am_diag_cond_str(r, ce));
6163e3
+
6163e3
         /*
6163e3
          * Rule with ignore flog?
6163e3
          */
6163e3
@@ -384,9 +388,11 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
6163e3
             if (!(ce->flags & AM_COND_FLAG_OR))
6163e3
                 skip_or = 0;
6163e3
 
6163e3
-             ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
6163e3
-                           "Skip %s, [OR] rule matched previously",
6163e3
-                           ce->directive);
6163e3
+            ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
6163e3
+                          "Skip %s, [OR] rule matched previously",
6163e3
+                          ce->directive);
6163e3
+
6163e3
+            am_diag_printf(r, "Skip, [OR] rule matched previously\n");
6163e3
             continue;
6163e3
         }
6163e3
         
6163e3
@@ -433,6 +439,8 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
6163e3
             ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
6163e3
                           "Evaluate %s vs \"%s\"", 
6163e3
                           ce->directive, value);
6163e3
+
6163e3
+            am_diag_printf(r, "evaluate value \"%s\" ", value);
6163e3
     
6163e3
             if (value == NULL) {
6163e3
                  match = 0;          /* can not happen */
6163e3
@@ -463,11 +471,16 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
6163e3
             } else {
6163e3
                  match = !strcmp(ce->str, value);
6163e3
             }
6163e3
+
6163e3
+        am_diag_printf(r, "match=%s, ", match ? "yes" : "no");
6163e3
         }
6163e3
 
6163e3
-        if (ce->flags & AM_COND_FLAG_NOT)
6163e3
+        if (ce->flags & AM_COND_FLAG_NOT) {
6163e3
             match = !match;
6163e3
 
6163e3
+            am_diag_printf(r, "negating now match=%s ", match ? "yes" : "no");
6163e3
+        }
6163e3
+
6163e3
         ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r,
6163e3
                       "%s: %smatch", ce->directive,
6163e3
                       (match == 0) ? "no ": "");
6163e3
@@ -479,6 +492,9 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
6163e3
             ap_log_rerror(APLOG_MARK, APLOG_NOTICE, 0, r,
6163e3
                           "Client failed to match %s",
6163e3
                           ce->directive);
6163e3
+
6163e3
+            am_diag_printf(r, "failed (no OR condition)"
6163e3
+                           " returning HTTP_FORBIDDEN\n");
6163e3
             return HTTP_FORBIDDEN;
6163e3
         }
6163e3
 
6163e3
@@ -488,8 +504,12 @@ int am_check_permissions(request_rec *r, am_cache_entry_t *session)
6163e3
          */
6163e3
         if (match && (ce->flags & AM_COND_FLAG_OR))
6163e3
             skip_or = 1;
6163e3
+
6163e3
+        am_diag_printf(r, "\n");
6163e3
     }
6163e3
 
6163e3
+    am_diag_printf(r, "%s succeeds\n", __func__);
6163e3
+
6163e3
     return OK;
6163e3
 }
6163e3
 
6163e3
diff --git a/configure.ac b/configure.ac
6163e3
index 5ca2c8a..ae313e0 100644
6163e3
--- a/configure.ac
6163e3
+++ b/configure.ac
6163e3
@@ -41,6 +41,16 @@ The executable may also be named 'apxs'.
6163e3
 ])
6163e3
 fi
6163e3
 
6163e3
+AC_ARG_ENABLE(
6163e3
+        [diagnostics],
6163e3
+        [AS_HELP_STRING([--enable-diagnostics],
6163e3
+        [Build with diagnostic support])],
6163e3
+        [],
6163e3
+        [enable_diagnostics=no])
6163e3
+
6163e3
+AS_IF([test "x$enable_diagnostics" != xno],
6163e3
+      [MELLON_CFLAGS="$MELLON_CFLAGS -DENABLE_DIAGNOSTICS"])
6163e3
+
6163e3
 # Replace any occurances of @APXS2@ with the value of $APXS2 in the Makefile.
6163e3
 AC_SUBST(APXS2)
6163e3
 
6163e3
@@ -74,6 +84,8 @@ PKG_CHECK_MODULES([GLIB], [glib-2.0 >= 2.12])
6163e3
 AC_SUBST(GLIB_CFLAGS)
6163e3
 AC_SUBST(GLIB_LIBS)
6163e3
 
6163e3
+AC_SUBST(MELLON_CFLAGS)
6163e3
+
6163e3
 # Test to see if we can include lasso/utils.h
6163e3
 # AC_CHECK_HEADER won't work correctly unless we specifiy the include directories
6163e3
 # found in the LASSO_CFLAGS. Save and restore CFLAGS and CPPFLAGS.
6163e3
diff --git a/mod_auth_mellon.c b/mod_auth_mellon.c
6163e3
index f632d37..74bd328 100644
6163e3
--- a/mod_auth_mellon.c
6163e3
+++ b/mod_auth_mellon.c
6163e3
@@ -195,6 +195,9 @@ static int am_create_request(request_rec *r)
6163e3
 #ifdef HAVE_ECP
6163e3
     req_cfg->ecp_authn_req = false;
6163e3
 #endif /* HAVE_ECP */
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+    req_cfg->diag_emitted = false;
6163e3
+#endif
6163e3
 
6163e3
     ap_set_module_config(r->request_config, &auth_mellon_module, req_cfg);
6163e3
 
6163e3
@@ -220,6 +223,11 @@ static void register_hooks(apr_pool_t *p)
6163e3
      * r->handler and decide that it is the only handler for this URL.
6163e3
      */
6163e3
     ap_hook_handler(am_handler, NULL, NULL, APR_HOOK_FIRST);
6163e3
+
6163e3
+#ifdef ENABLE_DIAGNOSTICS
6163e3
+    ap_hook_open_logs(am_diag_log_init,NULL,NULL,APR_HOOK_MIDDLE);
6163e3
+    ap_hook_log_transaction(am_diag_finalize_request,NULL,NULL,APR_HOOK_REALLY_LAST);
6163e3
+#endif
6163e3
 }
6163e3
 
6163e3
 
6163e3
@@ -229,7 +237,7 @@ module AP_MODULE_DECLARE_DATA auth_mellon_module =
6163e3
     auth_mellon_dir_config,
6163e3
     auth_mellon_dir_merge,
6163e3
     auth_mellon_server_config,
6163e3
-    NULL,
6163e3
+    auth_mellon_srv_merge,
6163e3
     auth_mellon_commands,
6163e3
     register_hooks
6163e3
 };