commit 582f283c49c754a07aee6eea0fbcd4b188f23236 Author: John Dennis 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 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); +}