From: Arran Cudbard-Bell Date: Fri, 5 Jun 2015 16:27:12 +0000 (-0600) Subject: Fix indentation for some messages, lower priority of others to make EAP-TLS debug... X-Git-Tag: release_3_0_9~252 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=db6a6418035e793844862b8855aa6fde7d341da4;p=thirdparty%2Ffreeradius-server.git Fix indentation for some messages, lower priority of others to make EAP-TLS debug cleaner Reword yet more log messages, so they make sense for mortals --- diff --git a/src/main/tls.c b/src/main/tls.c index 8b05d644ff1..7c052b6c6a6 100644 --- a/src/main/tls.c +++ b/src/main/tls.c @@ -334,6 +334,8 @@ tls_session_t *tls_new_session(TALLOC_CTX *ctx, fr_tls_server_conf_t *conf, REQU rad_assert(request != NULL); + RDEBUG2("Initiating new EAP-TLS session"); + /* * Manually flush the sessions every so often. If HALF * of the session lifetime has passed since we last @@ -437,8 +439,6 @@ tls_session_t *tls_new_session(TALLOC_CTX *ctx, fr_tls_server_conf_t *conf, REQU if (conf->session_cache_enable) state->allow_session_resumption = true; /* otherwise it's false */ - RDEBUG2("Initiate"); - return state; } @@ -1509,9 +1509,8 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert, /* Verify OCSP response status */ status = OCSP_response_status(resp); - DEBUG2(LOG_PREFIX ":ocsp: Response status: %s",OCSP_response_status_str(status)); if (status != OCSP_RESPONSE_STATUS_SUCCESSFUL) { - DEBUG2(LOG_PREFIX ": ocsp: Response status: %s", OCSP_response_status_str(status)); + ERROR(LOG_PREFIX ": ocsp: Response status: %s", OCSP_response_status_str(status)); goto ocsp_end; } bresp = OCSP_response_get1_basic(resp); @@ -1537,7 +1536,7 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert, } goto ocsp_end; } - + DEBUG2(LOG_PREFIX ": ocsp: Response status: %s", OCSP_response_status_str(status)); if (bio_out) { BIO_puts(bio_out, "\tThis Update: "); @@ -1721,7 +1720,7 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx) buf[0] = '\0'; sn = X509_get_serialNumber(client_cert); - RDEBUG2("TLS Verify creating certificate attributes"); + RDEBUG2("Creating attributes from certificate OIDs"); RINDENT(); /* @@ -1909,7 +1908,12 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx) "attribute and value are defined in the dictionaries", attribute, value); } else { + /* + * rdebug_pair_list indents (so pre REXDENT()) + */ + REXDENT(); rdebug_pair_list(L_DBG_LVL_2, request, vp, NULL); + RINDENT(); } } @@ -1969,7 +1973,8 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx) } else { RDEBUG2("checking certificate CN (%s) with xlat'ed value (%s)", common_name, cn_str); if (strcmp(cn_str, common_name) != 0) { - AUTH("tls: Certificate CN (%s) does not match specified value (%s)!", common_name, cn_str); + AUTH(LOG_PREFIX ": Certificate CN (%s) does not match specified value (%s)!", + common_name, cn_str); my_ok = 0; } } @@ -2040,15 +2045,15 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx) } /* depth == 0 */ - if (RDEBUG_ENABLED2) { - RDEBUG2("chain-depth : %d, ", depth); - RDEBUG2("error : %d", err); + if (RDEBUG_ENABLED3) { + RDEBUG3("chain-depth : %d", depth); + RDEBUG3("error : %d", err); - if (identity) RDEBUG2("identity : %s", *identity); - RDEBUG2("common name : %s", common_name); - RDEBUG2("subject : %s", subject); - RDEBUG2("issuer : %s", issuer); - RDEBUG2("verify return : %d", my_ok); + if (identity) RDEBUG3("identity : %s", *identity); + RDEBUG3("common name : %s", common_name); + RDEBUG3("subject : %s", subject); + RDEBUG3("issuer : %s", issuer); + RDEBUG3("verify return : %d", my_ok); } return my_ok; } @@ -3087,8 +3092,6 @@ fr_tls_status_t tls_application_data(tls_session_t *ssn, REQUEST *request) */ fr_tls_status_t tls_ack_handler(tls_session_t *ssn, REQUEST *request) { - RDEBUG2("Received TLS ACK"); - if (ssn == NULL){ REDEBUG("Unexpected ACK received: No ongoing SSL session"); return FR_TLS_INVALID; @@ -3105,12 +3108,12 @@ fr_tls_status_t tls_ack_handler(tls_session_t *ssn, REQUEST *request) switch (ssn->info.content_type) { case alert: - RDEBUG2("ACK alert"); + RDEBUG2("Peer ACKed our alert"); return FR_TLS_FAIL; case handshake: if ((ssn->info.handshake_type == handshake_finished) && (ssn->dirty_out.used == 0)) { - RDEBUG2("ACK handshake is finished"); + RDEBUG2("Peer ACKed our handshake fragment. handshake is finished"); /* * From now on all the content is @@ -3121,12 +3124,12 @@ fr_tls_status_t tls_ack_handler(tls_session_t *ssn, REQUEST *request) return FR_TLS_SUCCESS; } /* else more data to send */ - RDEBUG2("ACK handshake fragment handler"); + RDEBUG2("Peer ACKed our handshake fragment"); /* Fragmentation handler, send next fragment */ return FR_TLS_REQUEST; case application_data: - RDEBUG2("ACK handshake fragment handler in application data"); + RDEBUG2("Peer ACKed our application data fragment"); return FR_TLS_REQUEST; /* @@ -3135,10 +3138,8 @@ fr_tls_status_t tls_ack_handler(tls_session_t *ssn, REQUEST *request) */ default: REDEBUG("Invalid ACK received: %d", ssn->info.content_type); - return FR_TLS_INVALID; } } - #endif /* WITH_TLS */ diff --git a/src/modules/rlm_eap/eap.c b/src/modules/rlm_eap/eap.c index 59411676760..ff46b7c04cb 100644 --- a/src/modules/rlm_eap/eap.c +++ b/src/modules/rlm_eap/eap.c @@ -182,7 +182,7 @@ static int eap_module_call(eap_module_t *module, eap_handler_t *handler) rad_assert(module != NULL); - RDEBUG2("Calling EAP submodule %s to process data", module->type->name); + RDEBUG2("Calling submodule %s to process data", module->type->name); request->module = module->type->name; @@ -364,7 +364,7 @@ eap_rcode_t eap_method_select(rlm_eap_t *inst, eap_handler_t *handler) return EAP_INVALID; } - RDEBUG2("Peer sent EAP %s (%d) request", eap_type2name(type->num), type->num); + RDEBUG2("Peer sent packet with method EAP %s (%d)", eap_type2name(type->num), type->num); /* * Figure out what to do. */ @@ -532,9 +532,6 @@ rlm_rcode_t eap_compose(eap_handler_t *handler) default: ++reply->id; } - RDEBUG2("Sending response, EAP ID %d", reply->id); - } else { - RDEBUG2("Sending response, EAP ID %d (set by EAP method handler)", reply->id); } /* @@ -618,6 +615,10 @@ rlm_rcode_t eap_compose(eap_handler_t *handler) break; } + RDEBUG2("Sending EAP %s (code %i) ID %d length %i", + eap_codes[eap_packet->code], eap_packet->code, reply->id, + eap_packet->length[0] * 256 + eap_packet->length[1]); + return rcode; } @@ -756,7 +757,7 @@ int eap_start(rlm_eap_t *inst, REQUEST *request) */ if ((eap_msg->vp_octets[0] == 0) || (eap_msg->vp_octets[0] >= PW_EAP_MAX_CODES)) { - RDEBUG2("Unknown EAP packet"); + RDEBUG2("Peer sent EAP packet with unknown code %i", eap_msg->vp_octets[0]); } else { RDEBUG2("Peer sent EAP %s (code %i) ID %d length %zu", eap_codes[eap_msg->vp_octets[0]], diff --git a/src/modules/rlm_eap/libeap/eap_tls.c b/src/modules/rlm_eap/libeap/eap_tls.c index 4c2fd6929e5..ba20c0a5d27 100644 --- a/src/modules/rlm_eap/libeap/eap_tls.c +++ b/src/modules/rlm_eap/libeap/eap_tls.c @@ -272,17 +272,19 @@ int eaptls_request(EAP_DS *eap_ds, tls_session_t *ssn) * fragments to receive to make the complete * TLS-record/TLS-Message */ -static int eaptls_send_ack(EAP_DS *eap_ds, int peap_flag) +static int eaptls_send_ack(eap_handler_t *handler, int peap_flag) { EAPTLS_PACKET reply; + REQUEST *request = handler->request; + RDEBUG2("ACKing Peer's TLS record fragment"); reply.code = FR_TLS_ACK; reply.length = TLS_HEADER_LEN + 1/*flags*/; reply.flags = peap_flag; reply.data = NULL; reply.dlen = 0; - eaptls_compose(eap_ds, &reply); + eaptls_compose(handler->eap_ds, &reply); return 1; } @@ -324,7 +326,7 @@ static fr_tls_status_t eaptls_verify(eap_handler_t *handler) /* * First output the flags (for debugging) */ - RDEBUG2("Peer sent EAP-TLS flags %c%c%c", + RDEBUG3("Peer sent flags %c%c%c", TLS_START(eaptls_packet->flags) ? 'S' : '-', TLS_MORE_FRAGMENTS(eaptls_packet->flags) ? 'M' : '-', TLS_LENGTH_INCLUDED(eaptls_packet->flags) ? 'L' : '-'); @@ -394,15 +396,20 @@ static fr_tls_status_t eaptls_verify(eap_handler_t *handler) RDEBUG2("Got complete TLS record (no fragmentation)"); return FR_TLS_LENGTH_INCLUDED; } - } else { - RDEBUG2("Got additional TLS record fragment"); } - if (TLS_MORE_FRAGMENTS(eaptls_packet->flags)) { - RDEBUG2("More fragments to follow"); - return FR_TLS_MORE_FRAGMENTS; + /* + * The previous packet had the M flags set, but this one doesn't, + * this must be the final record fragment + */ + if (TLS_MORE_FRAGMENTS(eaptls_prev->flags) && !TLS_MORE_FRAGMENTS(eaptls_packet->flags)) { + RDEBUG2("Got final TLS record fragment"); + } else { + RDEBUG2("Got additional TLS record fragment. Peer indicated more fragments to follow"); } + if (TLS_MORE_FRAGMENTS(eaptls_packet->flags)) return FR_TLS_MORE_FRAGMENTS; + /* * None of the flags are set, but it's still a valid * EAPTLS packet. @@ -628,7 +635,7 @@ static fr_tls_status_t eaptls_operation(fr_tls_status_t status, eap_handler_t *h /* * Send the ACK. */ - eaptls_send_ack(handler->eap_ds, tls_session->peap_flag); + eaptls_send_ack(handler, tls_session->peap_flag); return FR_TLS_HANDLED; } @@ -720,7 +727,8 @@ fr_tls_status_t eaptls_process(eap_handler_t *handler) if (!request) return FR_TLS_FAIL; - RDEBUG2("Processing EAP-TLS"); + RDEBUG2("Continuing EAP-TLS"); + SSL_set_ex_data(tls_session->ssl, FR_TLS_EX_INDEX_REQUEST, request); if (handler->certs) pairadd(&request->packet->vps, @@ -826,8 +834,7 @@ fr_tls_status_t eaptls_process(eap_handler_t *handler) /* * Send the ACK. */ - eaptls_send_ack(handler->eap_ds, - tls_session->peap_flag); + eaptls_send_ack(handler, tls_session->peap_flag); RDEBUG2("Init is done, but tunneled data is fragmented"); status = FR_TLS_HANDLED; goto done; diff --git a/src/modules/rlm_eap/types/rlm_eap_peap/peap.c b/src/modules/rlm_eap/types/rlm_eap_peap/peap.c index f05c7cb34ad..c30b0368bf0 100644 --- a/src/modules/rlm_eap/types/rlm_eap_peap/peap.c +++ b/src/modules/rlm_eap/types/rlm_eap_peap/peap.c @@ -251,7 +251,7 @@ static int eapmessage_verify(REQUEST *request, */ case PW_EAP_MSCHAPV2: default: - RDEBUG2("EAP type %s (%d)", eap_type2name(eap_method), + RDEBUG2("EAP method %s (%d)", eap_type2name(eap_method), eap_method); return 1; } diff --git a/src/modules/rlm_eap/types/rlm_eap_tls/rlm_eap_tls.c b/src/modules/rlm_eap/types/rlm_eap_tls/rlm_eap_tls.c index 76ca81a52bf..472c5e428ea 100644 --- a/src/modules/rlm_eap/types/rlm_eap_tls/rlm_eap_tls.c +++ b/src/modules/rlm_eap/types/rlm_eap_tls/rlm_eap_tls.c @@ -138,8 +138,6 @@ static int CC_HINT(nonnull) mod_process(void *type_arg, eap_handler_t *handler) inst = type_arg; - RDEBUG2("Authenticate"); - status = eaptls_process(handler); if ((status == FR_TLS_INVALID) || (status == FR_TLS_FAIL)) { REDEBUG("[eaptls process] = %s", fr_int2str(fr_tls_status_table, status, "")); @@ -173,7 +171,7 @@ static int CC_HINT(nonnull) mod_process(void *type_arg, eap_handler_t *handler) fake->server = inst->virtual_server; } - RDEBUG("Processing EAP-TLS Certificate check:"); + RDEBUG2("Validating certificate"); rad_virtual_server(fake); /* copy the reply vps back to our reply */ @@ -182,7 +180,7 @@ static int CC_HINT(nonnull) mod_process(void *type_arg, eap_handler_t *handler) /* reject if virtual server didn't return accept */ if (fake->reply->code != PW_CODE_ACCESS_ACCEPT) { - RDEBUG2("Certificates were rejected by the virtual server"); + RDEBUG2("Certificate rejected by the virtual server"); talloc_free(fake); eaptls_fail(handler, 0); return 0;