Fix indentation for some messages, lower priority of others to make EAP-TLS debug...

Reword yet more log messages, so they make sense for mortals

diff --git a/src/main/tls.c b/src/main/tls.c
index 8b05d644ff1e948af0dc44e216b8d6d7e41c012d..7c052b6c6a61a65071559027f9dec22b1930e655 100644 (file)
--- 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 59411676760dc98044a927958d0da026e356bdfc..ff46b7c04cbb46b251260d4470ff44310e379cbb 100644 (file)
--- 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 4c2fd6929e5a114186d50684bedca327aac1abb2..ba20c0a5d2796e45e1e864860e58be05a4213f34 100644 (file)
--- 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 f05c7cb34ad99a0a4f7cb5306f526c2496151124..c30b0368bf0681e246626880837cf531d8c8c75e 100644 (file)
--- 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 76ca81a52bf96e39e86629054c3f0e589576f325..472c5e428eaf2452c27626f832c979a83ef9d37b 100644 (file)
--- 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, "<INVALID>"));
@@ -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;