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);
+}