commit 582f283c49c754a07aee6eea0fbcd4b188f23236

Author: John Dennis <jdennis@redhat.com>

Date:   Wed Feb 7 09:45:18 2018 -0500

    Log SAML status response information

    Knowing if a SAML operation failed and the reason why is essential to

    diagnose problems. The SAML Status Response is always included in all

    SAML responses. In addition to the major reason why a transaction

    failed it may also include extra expository information giving

    additional details. Unfortunately we never logged any of the status

    response information when a failure occurred. This patch adds code to

    log the status response information.

    In addition the patch adds diagnostic logging of received POST data.

    Signed-off-by: John Dennis <jdennis@redhat.com>

diff --git a/auth_mellon.h b/auth_mellon.h

index a10bc4c..289db0c 100644

--- a/auth_mellon.h

+++ b/auth_mellon.h

@@ -511,6 +511,9 @@ char *am_ecp_service_options_str(apr_pool_t *pool, ECPServiceOptions options);

 bool am_is_paos_request(request_rec *r, int *error_code);

 #endif /* HAVE_ECP */

+char *

+am_saml_response_status_str(request_rec *r, LassoNode *node);

+

 int am_auth_mellon_user(request_rec *r);

 int am_check_uid(request_rec *r);

 int am_handler(request_rec *r);

@@ -577,6 +580,11 @@ am_diag_log_lasso_node(request_rec *r, int level, LassoNode *node,

                        const char *fmt, ...)

     __attribute__((format(printf,4,5)));

+void

+am_diag_log_saml_status_response(request_rec *r, int level, LassoNode *node,

+                                 const char *fmt, ...)

+    __attribute__((format(printf,4,5)));

+

 void

 am_diag_log_profile(request_rec *r, int level, LassoProfile *profile,

                     const char *fmt, ...)

@@ -608,6 +616,7 @@ am_diag_time_t_to_8601(request_rec *r, apr_time_t t);

 #define am_diag_log_cache_entry(...) do {} while(0)

 #define am_diag_log_file_data(...) do {} while(0)

 #define am_diag_log_lasso_node(...) do {} while(0)

+#define am_diag_log_saml_status_response(...) do {} while(0)

 #define am_diag_log_profile(...) do {} while(0)

 #define am_diag_printf(...) do {} while(0)

diff --git a/auth_mellon_diagnostics.c b/auth_mellon_diagnostics.c

index 289a878..89fbc62 100644

--- a/auth_mellon_diagnostics.c

+++ b/auth_mellon_diagnostics.c

@@ -867,7 +867,9 @@ am_diag_log_lasso_node(request_rec *r, int level, LassoNode *node,

         write_indented_text(diag_cfg->fd, level+1, xml);

         lasso_release_string(xml);

     } else {

-        apr_file_printf(diag_cfg->fd, "node is NULL\n");

+        apr_file_printf(diag_cfg->fd,

+                        "%snode is NULL\n",

+                        indent(level+1));

     }

     apr_file_flush(diag_cfg->fd);

 }

@@ -919,6 +921,99 @@ am_diag_log_file_data(request_rec *r, int level, am_file_data_t *file_data,

     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, ...)

diff --git a/auth_mellon_handler.c b/auth_mellon_handler.c

index 030abe7..5058744 100644

--- a/auth_mellon_handler.c

+++ b/auth_mellon_handler.c

@@ -826,6 +826,8 @@ static int am_handle_logout_response(request_rec *r, LassoLogout *logout)

     am_dir_cfg_rec *cfg = am_get_dir_cfg(r);

     res = lasso_logout_process_response_msg(logout, r->args);

+    am_diag_log_lasso_node(r, 0, LASSO_PROFILE(logout)->response,

+                           "SAML Response (%s):", __func__);

 #ifdef HAVE_lasso_profile_set_signature_verify_hint

     if(res != 0 && res != LASSO_DS_ERROR_SIGNATURE_NOT_FOUND &&

        logout->parent.remote_providerID != NULL) {

@@ -841,7 +843,10 @@ static int am_handle_logout_response(request_rec *r, LassoLogout *logout)

     if(res != 0) {

         AM_LOG_RERROR(APLOG_MARK, APLOG_ERR, 0, r,

                       "Unable to process logout response."

-                      " Lasso error: [%i] %s", res, lasso_strerror(res));

+                      " Lasso error: [%i] %s, SAML Response: %s",

+                      res, lasso_strerror(res),

+                      am_saml_response_status_str(r,

+                        LASSO_PROFILE(logout)->response));

         lasso_logout_destroy(logout);

         return HTTP_BAD_REQUEST;

@@ -1760,9 +1765,6 @@ static int am_handle_reply_common(request_rec *r, LassoLogin *login,

     int rc;

     const char *idp;

-    am_diag_log_lasso_node(r, 0, LASSO_PROFILE(login)->response,

-                           "SAMLResponse:");

-

     url = am_reconstruct_url(r);

     chr = strchr(url, '?');

     if (! chr) {

@@ -2039,10 +2041,15 @@ static int am_handle_post_reply(request_rec *r)

     /* Process login responce. */

     rc = lasso_login_process_authn_response_msg(login, saml_response);

+    am_diag_log_lasso_node(r, 0, LASSO_PROFILE(login)->response,

+                           "SAML Response (%s):", __func__);

     if (rc != 0) {

         AM_LOG_RERROR(APLOG_MARK, APLOG_ERR, 0, r,

                       "Error processing authn response."

-                      " Lasso error: [%i] %s", rc, lasso_strerror(rc));

+                      " Lasso error: [%i] %s, SAML Response: %s",

+                      rc, lasso_strerror(rc),

+                      am_saml_response_status_str(r,

+                        LASSO_PROFILE(login)->response));

         lasso_login_destroy(login);

         err = HTTP_BAD_REQUEST;

@@ -2134,10 +2141,15 @@ static int am_handle_paos_reply(request_rec *r)

     /* Process login response. */

     rc = lasso_login_process_paos_response_msg(login, post_data);

+    am_diag_log_lasso_node(r, 0, LASSO_PROFILE(login)->response,

+                           "SAML Response (%s):", __func__);

     if (rc != 0) {

         AM_LOG_RERROR(APLOG_MARK, APLOG_ERR, 0, r,

                       "Error processing ECP authn response."

-                      " Lasso error: [%i] %s", rc, lasso_strerror(rc));

+                      " Lasso error: [%i] %s, SAML Response: %s",

+                      rc, lasso_strerror(rc),

+                      am_saml_response_status_str(r,

+                        LASSO_PROFILE(login)->response));

         lasso_login_destroy(login);

         err = HTTP_BAD_REQUEST;

@@ -2275,10 +2287,16 @@ static int am_handle_artifact_reply(request_rec *r)

     }

     rc = lasso_login_process_response_msg(login, response);

+    am_diag_log_lasso_node(r, 0, LASSO_PROFILE(login)->response,

+                           "SAML Response (%s):", __func__);

     if(rc != 0) {

         AM_LOG_RERROR(APLOG_MARK, APLOG_ERR, 0, r,

                       "Failed to handle HTTP-Artifact response data."

-                      " Lasso error: [%i] %s", rc, lasso_strerror(rc));

+                      " Lasso error: [%i] %s, SAML Response: %s",

+                      rc, lasso_strerror(rc),

+                      am_saml_response_status_str(r,

+                        LASSO_PROFILE(login)->response));

+

         lasso_login_destroy(login);

         return HTTP_INTERNAL_SERVER_ERROR;

     }

@@ -2947,8 +2965,9 @@ static int am_set_authn_request_content(request_rec *r, LassoLogin *login)

 {

     am_diag_log_lasso_node(r, 0, LASSO_PROFILE(login)->request,

-                           "SAML AuthnRequest: http_method=%s",

-                           am_diag_lasso_http_method_str(login->http_method));

+                           "SAML AuthnRequest: http_method=%s URL=%s",

+                           am_diag_lasso_http_method_str(login->http_method),

+                           LASSO_PROFILE(login)->msg_url);

     switch (login->http_method) {

     case LASSO_HTTP_METHOD_REDIRECT:

diff --git a/auth_mellon_util.c b/auth_mellon_util.c

index 6538160..1fd3d4b 100644

--- a/auth_mellon_util.c

+++ b/auth_mellon_util.c

@@ -636,6 +636,7 @@ int am_read_post_data(request_rec *r, char **data, apr_size_t *length)

         bytes_left -= read_length;

     }

+    am_diag_printf(r, "POST data: %s\n", *data);

     return OK;

 }

@@ -2630,3 +2631,38 @@ bool am_is_paos_request(request_rec *r, int *error_code)

     return is_paos;

 }

 #endif /* HAVE_ECP */

+

+char *

+am_saml_response_status_str(request_rec *r, LassoNode *node)

+{

+    LassoSamlp2StatusResponse *response = (LassoSamlp2StatusResponse*)node;

+    LassoSamlp2Status *status = NULL;

+    const char *status_code1 = NULL;

+    const char *status_code2 = NULL;

+

+    if (!LASSO_IS_SAMLP2_STATUS_RESPONSE(response)) {

+        return apr_psprintf(r->pool,

+                            "error, expected LassoSamlp2StatusResponse "

+                            "but got %s",

+                            lasso_node_get_name((LassoNode*)response));

+    }

+

+    status = response->Status;

+    if (status == NULL                  ||

+        !LASSO_IS_SAMLP2_STATUS(status) ||

+        status->StatusCode == NULL      ||

+        status->StatusCode->Value == NULL) {

+        return apr_psprintf(r->pool, "Status missing");

+

+    }

+

+    status_code1 = status->StatusCode->Value;

+    if (status->StatusCode->StatusCode) {

+        status_code2 = status->StatusCode->StatusCode->Value;

+    }

+

+    return apr_psprintf(r->pool,

+                        "StatusCode1=\"%s\", StatusCode2=\"%s\", "

+                        "StatusMessage=\"%s\"",

+                        status_code1, status_code2, status->StatusMessage);

+}