Merge tag 'release_3_0_10' into tr-integ
[freeradius.git] / src / main / tls.c
index 8e910e3..d86391f 100644 (file)
@@ -56,6 +56,8 @@ USES_APPLE_DEPRECATED_API     /* OpenSSL API has been deprecated by Apple */
 #  endif
 #  include <openssl/ssl.h>
 
+#define LOG_PREFIX "tls"
+
 #ifdef ENABLE_OPENSSL_VERSION_CHECK
 typedef struct libssl_defect {
        uint64_t        high;
@@ -77,12 +79,31 @@ static libssl_defect_t libssl_defects[] =
                .comment        = "For more information see http://heartbleed.com"
        }
 };
-#endif
+#endif /* ENABLE_OPENSSL_VERSION_CHECK */
+
+FR_NAME_NUMBER const fr_tls_status_table[] = {
+       { "invalid",                    FR_TLS_INVALID },
+       { "request",                    FR_TLS_REQUEST },
+       { "response",                   FR_TLS_RESPONSE },
+       { "success",                    FR_TLS_SUCCESS },
+       { "fail",                       FR_TLS_FAIL },
+       { "noop",                       FR_TLS_NOOP },
+
+       { "start",                      FR_TLS_START },
+       { "ok",                         FR_TLS_OK },
+       { "ack",                        FR_TLS_ACK },
+       { "first fragment",             FR_TLS_FIRST_FRAGMENT },
+       { "more fragments",             FR_TLS_MORE_FRAGMENTS },
+       { "length included",            FR_TLS_LENGTH_INCLUDED },
+       { "more fragments with length", FR_TLS_MORE_FRAGMENTS_WITH_LENGTH },
+       { "handled",                    FR_TLS_HANDLED },
+       {  NULL ,                       -1},
+};
 
 /* index we use to store cached session VPs
  * needs to be dynamic so we can supply a "free" function
  */
-static int fr_tls_ex_index_vps = -1;
+int fr_tls_ex_index_vps = -1;
 int fr_tls_ex_index_certs = -1;
 
 /* Session */
@@ -148,7 +169,7 @@ static unsigned int psk_server_callback(SSL *ssl, const char *identity,
                        return 0;
                }
 
-               vp = pairmake_packet("TLS-PSK-Identity", identity, T_OP_SET);
+               vp = pair_make_request("TLS-PSK-Identity", identity, T_OP_SET);
                if (!vp) return 0;
 
                hex_len = radius_xlat(buffer, sizeof(buffer), request, conf->psk_query,
@@ -287,12 +308,11 @@ tls_session_t *tls_new_client_session(TALLOC_CTX *ctx, fr_tls_server_conf_t *con
                return NULL;
        }
 
-       ssn->offset = conf->fragment_size;
+       ssn->mtu = conf->fragment_size;
 
        return ssn;
 }
 
-
 /** Create a new TLS session
  *
  * Configures a new TLS session, configuring options, setting callbacks etc...
@@ -306,13 +326,15 @@ tls_session_t *tls_new_client_session(TALLOC_CTX *ctx, fr_tls_server_conf_t *con
  */
 tls_session_t *tls_new_session(TALLOC_CTX *ctx, fr_tls_server_conf_t *conf, REQUEST *request, bool client_cert)
 {
-       tls_session_t *state = NULL;
-       SSL *new_tls = NULL;
+       tls_session_t   *state = NULL;
+       SSL             *new_tls = NULL;
        int             verify_mode = 0;
        VALUE_PAIR      *vp;
 
        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
@@ -322,8 +344,7 @@ tls_session_t *tls_new_session(TALLOC_CTX *ctx, fr_tls_server_conf_t *conf, REQU
         */
        if (conf->session_cache_enable &&
            ((conf->session_last_flushed + ((int)conf->session_timeout * 1800)) <= request->timestamp)){
-               RDEBUG2("Flushing SSL sessions (of #%ld)",
-                       SSL_CTX_sess_number(conf->ctx));
+               RDEBUG2("Flushing SSL sessions (of #%ld)", SSL_CTX_sess_number(conf->ctx));
 
                SSL_CTX_flush_sessions(conf->ctx, request->timestamp);
                conf->session_last_flushed = request->timestamp;
@@ -386,7 +407,7 @@ tls_session_t *tls_new_session(TALLOC_CTX *ctx, fr_tls_server_conf_t *conf, REQU
         *      Verify the peer certificate, if asked.
         */
        if (client_cert) {
-               RDEBUG2("Requiring client certificate");
+               RDEBUG2("Setting verify mode to require certificate from client");
                verify_mode = SSL_VERIFY_PEER;
                verify_mode |= SSL_VERIFY_FAIL_IF_NO_PEER_CERT;
                verify_mode |= SSL_VERIFY_CLIENT_ONCE;
@@ -409,16 +430,14 @@ tls_session_t *tls_new_session(TALLOC_CTX *ctx, fr_tls_server_conf_t *conf, REQU
         *      of EAP-TLS in order to calculate fragment sizes is
         *      just too much.
         */
-       state->offset = conf->fragment_size;
-       vp = pairfind(request->packet->vps, PW_FRAMED_MTU, 0, TAG_ANY);
-       if (vp && (vp->vp_integer > 100) && (vp->vp_integer < state->offset)) {
-               state->offset = vp->vp_integer;
+       state->mtu = conf->fragment_size;
+       vp = fr_pair_find_by_num(request->packet->vps, PW_FRAMED_MTU, 0, TAG_ANY);
+       if (vp && (vp->vp_integer > 100) && (vp->vp_integer < state->mtu)) {
+               state->mtu = vp->vp_integer;
        }
 
        if (conf->session_cache_enable) state->allow_session_resumption = true; /* otherwise it's false */
 
-       RDEBUG2("Initiate");
-
        return state;
 }
 
@@ -433,23 +452,23 @@ static int int_ssl_check(REQUEST *request, SSL *s, int ret, char const *text)
        if ((l = ERR_get_error()) != 0) {
                char const *p = ERR_error_string(l, NULL);
 
-               if (request && p) REDEBUG("SSL says: %s", p);
+               if (p) ROPTIONAL(REDEBUG, ERROR, "SSL says: %s", p);
        }
-       e = SSL_get_error(s, ret);
 
+       e = SSL_get_error(s, ret);
        switch (e) {
-               /*
-                *      These seem to be harmless and already "dealt
-                *      with" by our non-blocking environment. NB:
-                *      "ZERO_RETURN" is the clean "error"
-                *      indicating a successfully closed SSL
-                *      tunnel. We let this happen because our IO
-                *      loop should not appear to have broken on
-                *      this condition - and outside the IO loop, the
-                *      "shutdown" state is checked.
-                *
-                *      Don't print anything if we ignore the error.
-                */
+       /*
+        *      These seem to be harmless and already "dealt
+        *      with" by our non-blocking environment. NB:
+        *      "ZERO_RETURN" is the clean "error"
+        *      indicating a successfully closed SSL
+        *      tunnel. We let this happen because our IO
+        *      loop should not appear to have broken on
+        *      this condition - and outside the IO loop, the
+        *      "shutdown" state is checked.
+        *
+        *      Don't print anything if we ignore the error.
+        */
        case SSL_ERROR_NONE:
        case SSL_ERROR_WANT_READ:
        case SSL_ERROR_WANT_WRITE:
@@ -457,29 +476,27 @@ static int int_ssl_check(REQUEST *request, SSL *s, int ret, char const *text)
        case SSL_ERROR_ZERO_RETURN:
                break;
 
-               /*
-                *      These seem to be indications of a genuine
-                *      error that should result in the SSL tunnel
-                *      being regarded as "dead".
-                */
+       /*
+        *      These seem to be indications of a genuine
+        *      error that should result in the SSL tunnel
+        *      being regarded as "dead".
+        */
        case SSL_ERROR_SYSCALL:
-               ERROR("SSL: %s failed in a system call (%d), TLS session fails.",
-                      text, ret);
+               ROPTIONAL(REDEBUG, ERROR, "%s failed in a system call (%d), TLS session failed", text, ret);
                return 0;
 
        case SSL_ERROR_SSL:
-               ERROR("SSL: %s failed inside of TLS (%d), TLS session fails.",
-                      text, ret);
+               ROPTIONAL(REDEBUG, ERROR, "%s failed inside of TLS (%d), TLS session failed", text, ret);
                return 0;
 
+       /*
+        *      For any other errors that (a) exist, and (b)
+        *      crop up - we need to interpret what to do with
+        *      them - so "politely inform" the caller that
+        *      the code needs updating here.
+        */
        default:
-               /*
-                *      For any other errors that (a) exist, and (b)
-                *      crop up - we need to interpret what to do with
-                *      them - so "politely inform" the caller that
-                *      the code needs updating here.
-                */
-               ERROR("SSL: FATAL SSL error ..... %d\n", e);
+               ROPTIONAL(REDEBUG, ERROR, "FATAL SSL error: %d", e);
                return 0;
        }
 
@@ -507,8 +524,7 @@ int tls_handshake_recv(REQUEST *request, tls_session_t *ssn)
 
        err = BIO_write(ssn->into_ssl, ssn->dirty_in.data, ssn->dirty_in.used);
        if (err != (int) ssn->dirty_in.used) {
-               RDEBUG("Failed writing %d to SSL BIO: %d", ssn->dirty_in.used,
-                       err);
+               REDEBUG("Failed writing %zd bytes to SSL BIO: %d", ssn->dirty_in.used, err);
                record_init(&ssn->dirty_in);
                return 0;
        }
@@ -521,26 +537,14 @@ int tls_handshake_recv(REQUEST *request, tls_session_t *ssn)
                return 1;
        }
 
-       if (!int_ssl_check(request, ssn->ssl, err, "SSL_read")) {
-               return 0;
-       }
+       if (!int_ssl_check(request, ssn->ssl, err, "SSL_read")) return 0;
 
        /* Some Extra STATE information for easy debugging */
-       if (SSL_is_init_finished(ssn->ssl)) {
-               DEBUG2("SSL Connection Established\n");
-       }
-       if (SSL_in_init(ssn->ssl)) {
-               DEBUG2("In SSL Handshake Phase\n");
-       }
-       if (SSL_in_before(ssn->ssl)) {
-               DEBUG2("Before SSL Handshake Phase\n");
-       }
-       if (SSL_in_accept_init(ssn->ssl)) {
-               DEBUG2("In SSL Accept mode \n");
-       }
-       if (SSL_in_connect_init(ssn->ssl)) {
-               DEBUG2("In SSL Connect mode \n");
-       }
+       if (SSL_is_init_finished(ssn->ssl)) RDEBUG2("SSL Connection Established");
+       if (SSL_in_init(ssn->ssl)) RDEBUG2("In SSL Handshake Phase");
+       if (SSL_in_before(ssn->ssl)) RDEBUG2("Before SSL Handshake Phase");
+       if (SSL_in_accept_init(ssn->ssl)) RDEBUG2("In SSL Accept mode");
+       if (SSL_in_connect_init(ssn->ssl)) RDEBUG2("In SSL Connect mode");
 
        err = BIO_ctrl_pending(ssn->from_ssl);
        if (err > 0) {
@@ -551,7 +555,7 @@ int tls_handshake_recv(REQUEST *request, tls_session_t *ssn)
 
                } else if (BIO_should_retry(ssn->from_ssl)) {
                        record_init(&ssn->dirty_in);
-                       DEBUG2("  tls: Asking for more data in tunnel");
+                       RDEBUG2("Asking for more data in tunnel");
                        return 1;
 
                } else {
@@ -560,7 +564,7 @@ int tls_handshake_recv(REQUEST *request, tls_session_t *ssn)
                        return 0;
                }
        } else {
-               DEBUG2("SSL Application Data");
+               RDEBUG2("SSL Application Data");
                /* Its clean application data, do whatever we want */
                record_init(&ssn->clean_out);
        }
@@ -617,10 +621,10 @@ static void session_init(tls_session_t *ssn)
 
        memset(&ssn->info, 0, sizeof(ssn->info));
 
-       ssn->offset = 0;
-       ssn->fragment = 0;
+       ssn->mtu = 0;
+       ssn->fragment = false;
        ssn->tls_msg_len = 0;
-       ssn->length_flag = 0;
+       ssn->length_flag = false;
        ssn->opaque = NULL;
        ssn->free_opaque = NULL;
 }
@@ -700,12 +704,13 @@ void tls_session_information(tls_session_t *tls_session)
        char const *str_write_p, *str_version, *str_content_type = "";
        char const *str_details1 = "", *str_details2= "";
        REQUEST *request;
+       char buffer[32];
 
        /*
         *      Don't print this out in the normal course of
         *      operations.
         */
-       if (debug_flag == 0) {
+       if (rad_debug_lvl == 0) {
                return;
        }
 
@@ -738,7 +743,8 @@ void tls_session_information(tls_session_t *tls_session)
 #endif
 
        default:
-               str_version = "Unknown TLS version";
+               sprintf(buffer, "UNKNOWN TLS VERSION ?%04X?", tls_session->info.version);
+               str_version = buffer;
                break;
        }
 
@@ -947,13 +953,13 @@ static CONF_PARSER cache_config[] = {
 
        { "max_entries", FR_CONF_OFFSET(PW_TYPE_INTEGER, fr_tls_server_conf_t, session_cache_size), "255" },
        { "persist_dir", FR_CONF_OFFSET(PW_TYPE_STRING, fr_tls_server_conf_t, session_cache_path), NULL },
-       { NULL, -1, 0, NULL, NULL }        /* end the list */
+       CONF_PARSER_TERMINATOR
 };
 
 static CONF_PARSER verify_config[] = {
        { "tmpdir", FR_CONF_OFFSET(PW_TYPE_STRING, fr_tls_server_conf_t, verify_tmp_dir), NULL },
        { "client", FR_CONF_OFFSET(PW_TYPE_STRING, fr_tls_server_conf_t, verify_client_cert_cmd), NULL },
-       { NULL, -1, 0, NULL, NULL }        /* end the list */
+       CONF_PARSER_TERMINATOR
 };
 
 #ifdef HAVE_OPENSSL_OCSP_H
@@ -964,7 +970,7 @@ static CONF_PARSER ocsp_config[] = {
        { "use_nonce", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, ocsp_use_nonce), "yes" },
        { "timeout", FR_CONF_OFFSET(PW_TYPE_INTEGER, fr_tls_server_conf_t, ocsp_timeout), "yes" },
        { "softfail", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, ocsp_softfail), "no" },
-       { NULL, -1, 0, NULL, NULL }        /* end the list */
+       CONF_PARSER_TERMINATOR
 };
 #endif
 
@@ -992,6 +998,9 @@ static CONF_PARSER tls_server_config[] = {
        { "fragment_size", FR_CONF_OFFSET(PW_TYPE_INTEGER, fr_tls_server_conf_t, fragment_size), "1024" },
        { "include_length", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, include_length), "yes" },
        { "check_crl", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, check_crl), "no" },
+#ifdef X509_V_FLAG_CRL_CHECK_ALL
+       { "check_all_crl", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, check_all_crl), "no" },
+#endif
        { "allow_expired_crl", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, allow_expired_crl), NULL },
        { "check_cert_cn", FR_CONF_OFFSET(PW_TYPE_STRING, fr_tls_server_conf_t, check_cert_cn), NULL },
        { "cipher_list", FR_CONF_OFFSET(PW_TYPE_STRING, fr_tls_server_conf_t, cipher_list), NULL },
@@ -1023,8 +1032,7 @@ static CONF_PARSER tls_server_config[] = {
 #ifdef HAVE_OPENSSL_OCSP_H
        { "ocsp", FR_CONF_POINTER(PW_TYPE_SUBSECTION, NULL), (void const *) ocsp_config },
 #endif
-
-       { NULL, -1, 0, NULL, NULL }        /* end the list */
+       CONF_PARSER_TERMINATOR
 };
 
 
@@ -1066,8 +1074,7 @@ static CONF_PARSER tls_client_config[] = {
 #ifdef SSL_OP_NO_TLSv1_2
        { "disable_tlsv1_2", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, disable_tlsv1_2), NULL },
 #endif
-
-       { NULL, -1, 0, NULL, NULL }        /* end the list */
+       CONF_PARSER_TERMINATOR
 };
 
 
@@ -1082,20 +1089,20 @@ static int load_dh_params(SSL_CTX *ctx, char *file)
        if (!file) return 0;
 
        if ((bio = BIO_new_file(file, "r")) == NULL) {
-               ERROR("tls: Unable to open DH file - %s", file);
+               ERROR(LOG_PREFIX ": Unable to open DH file - %s", file);
                return -1;
        }
 
        dh = PEM_read_bio_DHparams(bio, NULL, NULL, NULL);
        BIO_free(bio);
        if (!dh) {
-               WARN("tls: Unable to set DH parameters.  DH cipher suites may not work!");
-               WARN("Fix this by running the OpenSSL command listed in eap.conf");
+               WARN(LOG_PREFIX ": Unable to set DH parameters.  DH cipher suites may not work!");
+               WARN(LOG_PREFIX ": Fix this by running the OpenSSL command listed in eap.conf");
                return 0;
        }
 
        if (SSL_CTX_set_tmp_dh(ctx, dh) < 0) {
-               ERROR("tls: Unable to set DH parameters");
+               ERROR(LOG_PREFIX ": Unable to set DH parameters");
                DH_free(dh);
                return -1;
        }
@@ -1107,36 +1114,39 @@ static int load_dh_params(SSL_CTX *ctx, char *file)
 
 /*
  *     Print debugging messages, and free data.
- *
- *     FIXME: Write sessions to some long-term storage, so that
- *            session resumption can still occur after the server
- *            restarts.
  */
 #define MAX_SESSION_SIZE (256)
 
 static void cbtls_remove_session(SSL_CTX *ctx, SSL_SESSION *sess)
 {
-       size_t size;
-       char buffer[2 * MAX_SESSION_SIZE + 1];
-       fr_tls_server_conf_t *conf;
+       size_t                  size;
+       char                    buffer[2 * MAX_SESSION_SIZE + 1];
+       fr_tls_server_conf_t    *conf;
 
        size = sess->session_id_length;
        if (size > MAX_SESSION_SIZE) size = MAX_SESSION_SIZE;
 
        fr_bin2hex(buffer, sess->session_id, size);
 
-       DEBUG2("  SSL: Removing session %s from the cache", buffer);
        conf = (fr_tls_server_conf_t *)SSL_CTX_get_app_data(ctx);
-       if (conf && conf->session_cache_path) {
+       if (!conf) {
+               DEBUG(LOG_PREFIX ": Failed to find TLS configuration in session");
+               return;
+       }
+
+       {
                int rv;
                char filename[256];
 
+               DEBUG2(LOG_PREFIX ": Removing session %s from the cache", buffer);
+
                /* remove session and any cached VPs */
                snprintf(filename, sizeof(filename), "%s%c%s.asn1",
                         conf->session_cache_path, FR_DIR_SEP, buffer);
                rv = unlink(filename);
                if (rv != 0) {
-                       DEBUG2("  SSL: could not remove persisted session file %s: %s", filename, fr_syserror(errno));
+                       DEBUG2(LOG_PREFIX ": Could not remove persisted session file %s: %s",
+                              filename, fr_syserror(errno));
                }
                /* VPs might be absent; might not have been written to disk yet */
                snprintf(filename, sizeof(filename), "%s%c%s.vps",
@@ -1149,29 +1159,36 @@ static void cbtls_remove_session(SSL_CTX *ctx, SSL_SESSION *sess)
 
 static int cbtls_new_session(SSL *ssl, SSL_SESSION *sess)
 {
-       size_t size;
-       char buffer[2 * MAX_SESSION_SIZE + 1];
-       fr_tls_server_conf_t *conf;
-       unsigned char *sess_blob = NULL;
+       size_t                  size;
+       char                    buffer[2 * MAX_SESSION_SIZE + 1];
+       fr_tls_server_conf_t    *conf;
+       unsigned char           *sess_blob = NULL;
+
+       REQUEST                 *request = SSL_get_ex_data(ssl, FR_TLS_EX_INDEX_REQUEST);
+
+       conf = (fr_tls_server_conf_t *)SSL_get_ex_data(ssl, FR_TLS_EX_INDEX_CONF);
+       if (!conf) {
+               RWDEBUG("Failed to find TLS configuration in session");
+               return 0;
+       }
 
        size = sess->session_id_length;
        if (size > MAX_SESSION_SIZE) size = MAX_SESSION_SIZE;
 
        fr_bin2hex(buffer, sess->session_id, size);
 
-       DEBUG2("  TLS: adding session %s to cache", buffer);
-
-       conf = (fr_tls_server_conf_t *)SSL_get_ex_data(ssl, FR_TLS_EX_INDEX_CONF);
-       if (conf && conf->session_cache_path) {
+       {
                int fd, rv, todo, blob_len;
                char filename[256];
                unsigned char *p;
 
+               RDEBUG2("Serialising session %s, and storing in cache", buffer);
+
                /* find out what length data we need */
                blob_len = i2d_SSL_SESSION(sess, NULL);
                if (blob_len < 1) {
                        /* something went wrong */
-                       DEBUG2("  SSL: could not find buffer length to persist session");
+                       RWDEBUG("Session serialisation failed, couldn't determine required buffer length");
                        return 0;
                }
 
@@ -1180,14 +1197,14 @@ static int cbtls_new_session(SSL *ssl, SSL_SESSION *sess)
                /* alloc and convert to ASN.1 */
                sess_blob = malloc(blob_len);
                if (!sess_blob) {
-                       DEBUG2("  SSL: could not allocate buffer len=%d to persist session", blob_len);
+                       RWDEBUG("Session serialisation failed, couldn't allocate buffer (%d bytes)", blob_len);
                        return 0;
                }
                /* openssl mutates &p */
                p = sess_blob;
                rv = i2d_SSL_SESSION(sess, &p);
                if (rv != blob_len) {
-                       DEBUG2("  SSL: could not persist session");
+                       RWDEBUG("Session serialisation failed");
                        goto error;
                }
 
@@ -1196,7 +1213,8 @@ static int cbtls_new_session(SSL *ssl, SSL_SESSION *sess)
                         conf->session_cache_path, FR_DIR_SEP, buffer);
                fd = open(filename, O_RDWR|O_CREAT|O_EXCL, 0600);
                if (fd < 0) {
-                       DEBUG2("  SSL: could not open session file %s: %s", filename, fr_syserror(errno));
+                       RERROR("Session serialisation failed, failed opening session file %s: %s",
+                             filename, fr_syserror(errno));
                        goto error;
                }
 
@@ -1205,7 +1223,7 @@ static int cbtls_new_session(SSL *ssl, SSL_SESSION *sess)
                while (todo > 0) {
                        rv = write(fd, p, todo);
                        if (rv < 1) {
-                               DEBUG2("  SSL: failed writing session: %s", fr_syserror(errno));
+                               RWDEBUG("Failed writing session: %s", fr_syserror(errno));
                                close(fd);
                                goto error;
                        }
@@ -1213,7 +1231,7 @@ static int cbtls_new_session(SSL *ssl, SSL_SESSION *sess)
                        todo -= rv;
                }
                close(fd);
-               DEBUG2("  SSL: wrote session %s to %s len=%d", buffer, filename, blob_len);
+               RWDEBUG("Wrote session %s to %s (%d bytes)", buffer, filename, blob_len);
        }
 
 error:
@@ -1222,64 +1240,73 @@ error:
        return 0;
 }
 
-static SSL_SESSION *cbtls_get_session(SSL *ssl,
-                                     unsigned char *data, int len,
-                                     int *copy)
+static SSL_SESSION *cbtls_get_session(SSL *ssl, unsigned char *data, int len, int *copy)
 {
-       size_t size;
-       char buffer[2 * MAX_SESSION_SIZE + 1];
-       fr_tls_server_conf_t *conf;
-       TALLOC_CTX *talloc_ctx;
+       size_t                  size;
+       char                    buffer[2 * MAX_SESSION_SIZE + 1];
+       fr_tls_server_conf_t    *conf;
+       TALLOC_CTX              *talloc_ctx;
+
+       SSL_SESSION             *sess = NULL;
+       unsigned char           *sess_data = NULL;
+       PAIR_LIST               *pairlist = NULL;
 
-       SSL_SESSION *sess = NULL;
-       unsigned char *sess_data = NULL;
-       PAIR_LIST *pairlist = NULL;
+       REQUEST                 *request = SSL_get_ex_data(ssl, FR_TLS_EX_INDEX_REQUEST);
+
+       rad_assert(request != NULL);
 
        size = len;
        if (size > MAX_SESSION_SIZE) size = MAX_SESSION_SIZE;
 
        fr_bin2hex(buffer, data, size);
 
-       DEBUG2("  SSL: Client requested cached session %s", buffer);
+       RDEBUG2("Peer requested cached session: %s", buffer);
+
+       *copy = 0;
 
        conf = (fr_tls_server_conf_t *)SSL_get_ex_data(ssl, FR_TLS_EX_INDEX_CONF);
+       if (!conf) {
+               RWDEBUG("Failed to find TLS configuration in session");
+               return NULL;
+       }
+
        talloc_ctx = SSL_get_ex_data(ssl, FR_TLS_EX_INDEX_TALLOC);
-       if (conf && conf->session_cache_path) {
-               int rv, fd, todo;
-               char filename[256];
-               unsigned char *p;
-               struct stat st;
-               VALUE_PAIR *vp;
+
+       {
+               int             rv, fd, todo;
+               char            filename[256];
+               unsigned char   *p;
+               struct stat     st;
+               VALUE_PAIR      *vps = NULL;
 
                /* read in the cached VPs from the .vps file */
                snprintf(filename, sizeof(filename), "%s%c%s.vps",
                         conf->session_cache_path, FR_DIR_SEP, buffer);
-               rv = pairlist_read(NULL, filename, &pairlist, 1);
+               rv = pairlist_read(talloc_ctx, filename, &pairlist, 1);
                if (rv < 0) {
                        /* not safe to un-persist a session w/o VPs */
-                       DEBUG2("  SSL: could not load persisted VPs for session %s", buffer);
+                       RWDEBUG("Failed loading persisted VPs for session %s", buffer);
                        goto err;
                }
 
                /* load the actual SSL session */
-               snprintf(filename, sizeof(filename), "%s%c%s.asn1",
-                        conf->session_cache_path, FR_DIR_SEP, buffer);
+               snprintf(filename, sizeof(filename), "%s%c%s.asn1", conf->session_cache_path, FR_DIR_SEP, buffer);
                fd = open(filename, O_RDONLY);
                if (fd < 0) {
-                       DEBUG2("  SSL: could not find persisted session file %s: %s", filename, fr_syserror(errno));
+                       RWDEBUG("No persisted session file %s: %s", filename, fr_syserror(errno));
                        goto err;
                }
 
                rv = fstat(fd, &st);
                if (rv < 0) {
-                       DEBUG2("  SSL: could not stat persisted session file %s: %s", filename, fr_syserror(errno));
+                       RWDEBUG("Failed stating persisted session file %s: %s", filename, fr_syserror(errno));
                        close(fd);
                        goto err;
                }
 
                sess_data = talloc_array(NULL, unsigned char, st.st_size);
                if (!sess_data) {
-                 DEBUG2("  SSL: could not alloc buffer for persisted session len=%d", (int) st.st_size);
+                       RWDEBUG("Failed allocating buffer for persisted session (%d bytes)", (int) st.st_size);
                        close(fd);
                        goto err;
                }
@@ -1289,7 +1316,7 @@ static SSL_SESSION *cbtls_get_session(SSL *ssl,
                while (todo > 0) {
                        rv = read(fd, p, todo);
                        if (rv < 1) {
-                               DEBUG2("  SSL: could not read from persisted session: %s", fr_syserror(errno));
+                               RWDEBUG("Failed reading persisted session: %s", fr_syserror(errno));
                                close(fd);
                                goto err;
                        }
@@ -1303,49 +1330,59 @@ static SSL_SESSION *cbtls_get_session(SSL *ssl,
                sess = d2i_SSL_SESSION(NULL, (unsigned char const **)(void **) &p, st.st_size);
 
                if (!sess) {
-                       DEBUG2("  SSL: OpenSSL failed to load persisted session: %s", ERR_error_string(ERR_get_error(), NULL));
+                       RWDEBUG("Failed loading persisted session: %s", ERR_error_string(ERR_get_error(), NULL));
                        goto err;
                }
 
-               /* cache the VPs into the session */
-               vp = paircopy(talloc_ctx, pairlist->reply);
-               SSL_SESSION_set_ex_data(sess, fr_tls_ex_index_vps, vp);
-               DEBUG2("  SSL: Successfully restored session %s", buffer);
+               /* move the cached VPs into the session */
+               fr_pair_list_mcopy_by_num(talloc_ctx, &vps, &pairlist->reply, 0, 0, TAG_ANY);
+
+               SSL_SESSION_set_ex_data(sess, fr_tls_ex_index_vps, vps);
+               RWDEBUG("Successfully restored session %s", buffer);
+               rdebug_pair_list(L_DBG_LVL_2, request, vps, "reply:");
        }
 err:
        if (sess_data) talloc_free(sess_data);
        if (pairlist) pairlist_free(&pairlist);
 
-       *copy = 0;
        return sess;
 }
 
 #ifdef HAVE_OPENSSL_OCSP_H
-/*
- * This function extracts the OCSP Responder URL
- * from an existing x509 certificate.
+
+/** Extract components of OCSP responser URL from a certificate
+ *
+ * @param[in] cert to extract URL from.
+ * @param[out] host_out Portion of the URL (must be freed with free()).
+ * @param[out] port_out Port portion of the URL (must be freed with free()).
+ * @param[out] path_out Path portion of the URL (must be freed with free()).
+ * @param[out] is_https Whether the responder should be contacted using https.
+ * @return
+ *     - 0 if no valid URL is contained in the certificate.
+ *     - 1 if a URL was found and parsed.
+ *     - -1 if at least one URL was found, but none could be parsed.
  */
-static int ocsp_parse_cert_url(X509 *cert, char **phost, char **pport,
-                              char **ppath, int *pssl)
+static int ocsp_parse_cert_url(X509 *cert, char **host_out, char **port_out,
+                              char **path_out, int *is_https)
 {
-       int i;
+       int                     i;
+       bool                    found_uri = false;
 
-       AUTHORITY_INFO_ACCESS *aia;
-       ACCESS_DESCRIPTION *ad;
+       AUTHORITY_INFO_ACCESS   *aia;
+       ACCESS_DESCRIPTION      *ad;
 
        aia = X509_get_ext_d2i(cert, NID_info_access, NULL, NULL);
 
        for (i = 0; i < sk_ACCESS_DESCRIPTION_num(aia); i++) {
                ad = sk_ACCESS_DESCRIPTION_value(aia, i);
-               if (OBJ_obj2nid(ad->method) == NID_ad_OCSP) {
-                       if (ad->location->type == GEN_URI) {
-                         if(OCSP_parse_url((char *) ad->location->d.ia5->data,
-                                                 phost, pport, ppath, pssl))
-                                       return 1;
-                       }
-               }
+               if (OBJ_obj2nid(ad->method) != NID_ad_OCSP) continue;
+               if (ad->location->type != GEN_URI) continue;
+               found_uri = true;
+
+               if (OCSP_parse_url((char *) ad->location->d.ia5->data, host_out,
+                                  port_out, path_out, is_https)) return 1;
        }
-       return 0;
+       return found_uri ? -1 : 0;
 }
 
 /*
@@ -1356,29 +1393,29 @@ static int ocsp_parse_cert_url(X509 *cert, char **phost, char **pport,
 /* Maximum leeway in validity period: default 5 minutes */
 #define MAX_VALIDITY_PERIOD     (5 * 60)
 
-static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
+static int ocsp_check(REQUEST *request, X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
                      fr_tls_server_conf_t *conf)
 {
-       OCSP_CERTID *certid;
-       OCSP_REQUEST *req;
-       OCSP_RESPONSE *resp = NULL;
-       OCSP_BASICRESP *bresp = NULL;
-       char *host = NULL;
-       char *port = NULL;
-       char *path = NULL;
-       char hostheader[1024];
-       int use_ssl = -1;
-       long nsec = MAX_VALIDITY_PERIOD, maxage = -1;
-       BIO *cbio, *bio_out;
-       int ocsp_ok = 0;
-       int status ;
+       OCSP_CERTID     *certid;
+       OCSP_REQUEST    *req;
+       OCSP_RESPONSE   *resp = NULL;
+       OCSP_BASICRESP  *bresp = NULL;
+       char            *host = NULL;
+       char            *port = NULL;
+       char            *path = NULL;
+       char            hostheader[1024];
+       int             use_ssl = -1;
+       long            nsec = MAX_VALIDITY_PERIOD, maxage = -1;
+       BIO             *cbio, *bio_out;
+       int             ocsp_ok = 0;
+       int             status;
        ASN1_GENERALIZEDTIME *rev, *thisupd, *nextupd;
-       int reason;
+       int             reason;
 #if OPENSSL_VERSION_NUMBER >= 0x1000003f
-       OCSP_REQ_CTX *ctx;
-       int rc;
-       struct timeval now;
-       struct timeval when;
+       OCSP_REQ_CTX    *ctx;
+       int             rc;
+       struct timeval  now;
+       struct timeval  when;
 #endif
 
        /*
@@ -1387,9 +1424,7 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
        certid = OCSP_cert_to_id(NULL, client_cert, issuer_cert);
        req = OCSP_REQUEST_new();
        OCSP_request_add0_id(req, certid);
-       if(conf->ocsp_use_nonce) {
-               OCSP_request_add1_nonce(req, NULL, 8);
-       }
+       if (conf->ocsp_use_nonce) OCSP_request_add1_nonce(req, NULL, 8);
 
        /*
         * Send OCSP Request and get OCSP Response
@@ -1399,25 +1434,43 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
        if (conf->ocsp_override_url) {
                char *url;
 
+       use_ocsp_url:
                memcpy(&url, &conf->ocsp_url, sizeof(url));
                /* Reading the libssl src, they do a strdup on the URL, so it could of been const *sigh* */
                OCSP_parse_url(url, &host, &port, &path, &use_ssl);
-       }
-       else {
-               ocsp_parse_cert_url(client_cert, &host, &port, &path, &use_ssl);
-       }
+               if (!host || !port || !path) {
+                       RWDEBUG("ocsp: Host or port or path missing from configured URL \"%s\".  Not doing OCSP", url);
+                       ocsp_ok = 2;
+                       goto ocsp_skip;
+               }
+       } else {
+               int ret;
 
-       if (!host || !port || !path) {
-               DEBUG2("[ocsp] - Host / port / path missing.  Not doing OCSP");
-               ocsp_ok = 2;
-               goto ocsp_skip;
+               ret = ocsp_parse_cert_url(client_cert, &host, &port, &path, &use_ssl);
+               switch (ret) {
+               case -1:
+                       RWDEBUG("ocsp: Invalid URL in certificate.  Not doing OCSP");
+                       break;
+
+               case 0:
+                       if (conf->ocsp_url) {
+                               RWDEBUG("ocsp: No OCSP URL in certificate, falling back to configured URL");
+                               goto use_ocsp_url;
+                       }
+                       RWDEBUG("ocsp: No OCSP URL in certificate.  Not doing OCSP");
+                       ocsp_ok = 2;
+                       goto ocsp_skip;
+
+               case 1:
+                       break;
+               }
        }
 
-       DEBUG2("[ocsp] --> Responder URL = http://%s:%s%s", host, port, path);
+       RDEBUG2("ocsp: Using responder URL \"http://%s:%s%s\"", host, port, path);
 
        /* Check host and port length are sane, then create Host: HTTP header */
        if ((strlen(host) + strlen(port) + 2) > sizeof(hostheader)) {
-               ERROR("OCSP Host and port too long");
+               RWDEBUG("ocsp: Host and port too long");
                goto ocsp_skip;
        }
        snprintf(hostheader, sizeof(hostheader), "%s:%s", host, port);
@@ -1426,7 +1479,7 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
        cbio = BIO_new_connect(host);
 
        bio_out = NULL;
-       if (debug_flag) {
+       if (rad_debug_lvl) {
                if (default_log.dst == L_DST_STDOUT) {
                        bio_out = BIO_new_fp(stdout, BIO_NOCLOSE);
                } else if (default_log.dst == L_DST_STDERR) {
@@ -1441,7 +1494,7 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
        /* Send OCSP request and wait for response */
        resp = OCSP_sendreq_bio(cbio, path, req);
        if (!resp) {
-               ERROR("Couldn't get OCSP response");
+               REDEBUG("ocsp: Couldn't get OCSP response");
                ocsp_ok = 2;
                goto ocsp_end;
        }
@@ -1451,26 +1504,26 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
 
        rc = BIO_do_connect(cbio);
        if ((rc <= 0) && ((!conf->ocsp_timeout) || !BIO_should_retry(cbio))) {
-               ERROR("Couldn't connect to OCSP responder");
+               REDEBUG("ocsp: Couldn't connect to OCSP responder");
                ocsp_ok = 2;
                goto ocsp_end;
        }
 
        ctx = OCSP_sendreq_new(cbio, path, NULL, -1);
        if (!ctx) {
-               ERROR("Couldn't create OCSP request");
+               REDEBUG("ocsp: Couldn't create OCSP request");
                ocsp_ok = 2;
                goto ocsp_end;
        }
 
        if (!OCSP_REQ_CTX_add1_header(ctx, "Host", hostheader)) {
-               ERROR("Couldn't set Host header");
+               REDEBUG("ocsp: Couldn't set Host header");
                ocsp_ok = 2;
                goto ocsp_end;
        }
 
        if (!OCSP_REQ_CTX_set1_req(ctx, req)) {
-               ERROR("Couldn't add data to OCSP request");
+               REDEBUG("ocsp: Couldn't add data to OCSP request");
                ocsp_ok = 2;
                goto ocsp_end;
        }
@@ -1488,7 +1541,7 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
        } while ((rc == -1) && BIO_should_retry(cbio));
 
        if (conf->ocsp_timeout && (rc == -1) && BIO_should_retry(cbio)) {
-               ERROR("OCSP response timed out");
+               REDEBUG("ocsp: Response timed out");
                ocsp_ok = 2;
                goto ocsp_end;
        }
@@ -1496,7 +1549,7 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
        OCSP_REQ_CTX_free(ctx);
 
        if (rc == 0) {
-               ERROR("Couldn't get OCSP response");
+               REDEBUG("ocsp: Couldn't get OCSP response");
                ocsp_ok = 2;
                goto ocsp_end;
        }
@@ -1504,25 +1557,23 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
 
        /* Verify OCSP response status */
        status = OCSP_response_status(resp);
-       DEBUG2("[ocsp] --> Response status: %s",OCSP_response_status_str(status));
-       if(status != OCSP_RESPONSE_STATUS_SUCCESSFUL) {
-               ERROR("OCSP response status: %s", OCSP_response_status_str(status));
+       if (status != OCSP_RESPONSE_STATUS_SUCCESSFUL) {
+               REDEBUG("ocsp: Response status: %s", OCSP_response_status_str(status));
                goto ocsp_end;
        }
        bresp = OCSP_response_get1_basic(resp);
-       if(conf->ocsp_use_nonce && OCSP_check_nonce(req, bresp)!=1) {
-               ERROR("OCSP response has wrong nonce value");
+       if (conf->ocsp_use_nonce && OCSP_check_nonce(req, bresp)!=1) {
+               REDEBUG("ocsp: Response has wrong nonce value");
                goto ocsp_end;
        }
-       if(OCSP_basic_verify(bresp, NULL, store, 0)!=1){
-               ERROR("Couldn't verify OCSP basic response");
+       if (OCSP_basic_verify(bresp, NULL, store, 0)!=1){
+               REDEBUG("ocsp: Couldn't verify OCSP basic response");
                goto ocsp_end;
        }
 
        /*      Verify OCSP cert status */
-       if(!OCSP_resp_find_status(bresp, certid, &status, &reason,
-                                                     &rev, &thisupd, &nextupd)) {
-               ERROR("No Status found.\n");
+       if (!OCSP_resp_find_status(bresp, certid, &status, &reason, &rev, &thisupd, &nextupd)) {
+               REDEBUG("ocsp: No Status found");
                goto ocsp_end;
        }
 
@@ -1534,7 +1585,6 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
                goto ocsp_end;
        }
 
-
        if (bio_out) {
                BIO_puts(bio_out, "\tThis Update: ");
                ASN1_GENERALIZEDTIME_print(bio_out, thisupd);
@@ -1548,15 +1598,14 @@ static int ocsp_check(X509_STORE *store, X509 *issuer_cert, X509 *client_cert,
 
        switch (status) {
        case V_OCSP_CERTSTATUS_GOOD:
-               DEBUG2("[oscp] --> Cert status: good");
+               RDEBUG2("ocsp: Cert status: good");
                ocsp_ok = 1;
                break;
 
        default:
                /* REVOKED / UNKNOWN */
-               DEBUG2("[ocsp] --> Cert status: %s",OCSP_cert_status_str(status));
-               if (reason != -1)
-                       DEBUG2("[ocsp] --> Reason: %s", OCSP_crl_reason_str(reason));
+               REDEBUG("ocsp: Cert status: %s", OCSP_cert_status_str(status));
+               if (reason != -1) REDEBUG("ocsp: Reason: %s", OCSP_crl_reason_str(reason));
 
                if (bio_out) {
                        BIO_puts(bio_out, "\tRevocation Time: ");
@@ -1580,20 +1629,22 @@ ocsp_end:
  ocsp_skip:
        switch (ocsp_ok) {
        case 1:
-               DEBUG2("[ocsp] --> Certificate is valid!");
+               RDEBUG2("ocsp: Certificate is valid");
                break;
+
        case 2:
                if (conf->ocsp_softfail) {
-                       DEBUG2("[ocsp] --> Unable to check certificate; assuming valid");
-                       DEBUG2("[ocsp] --> Warning! This may be insecure");
+                       RWDEBUG("ocsp: Unable to check certificate, assuming it's valid");
+                       RWDEBUG("ocsp: This may be insecure");
                        ocsp_ok = 1;
                } else {
-                       DEBUG2("[ocsp] --> Unable to check certificate; failing!");
+                       REDEBUG("ocsp: Unable to check certificate, failing");
                        ocsp_ok = 0;
                }
                break;
+
        default:
-               DEBUG2("[ocsp] --> Certificate has been expired/revoked!");
+               REDEBUG("ocsp: Certificate has been expired/revoked");
                break;
        }
 
@@ -1605,14 +1656,14 @@ ocsp_end:
  *     For creating certificate attributes.
  */
 static char const *cert_attr_names[8][2] = {
-  { "TLS-Client-Cert-Serial",          "TLS-Cert-Serial" },
-  { "TLS-Client-Cert-Expiration",      "TLS-Cert-Expiration" },
-  { "TLS-Client-Cert-Subject",         "TLS-Cert-Subject" },
-  { "TLS-Client-Cert-Issuer",          "TLS-Cert-Issuer" },
-  { "TLS-Client-Cert-Common-Name",     "TLS-Cert-Common-Name" },
-  { "TLS-Client-Cert-Subject-Alt-Name-Email",  "TLS-Cert-Subject-Alt-Name-Email" },
-  { "TLS-Client-Cert-Subject-Alt-Name-Dns",    "TLS-Cert-Subject-Alt-Name-Dns" },
-  { "TLS-Client-Cert-Subject-Alt-Name-Upn",    "TLS-Cert-Subject-Alt-Name-Upn" }
+       { "TLS-Client-Cert-Serial",                     "TLS-Cert-Serial" },
+       { "TLS-Client-Cert-Expiration",                 "TLS-Cert-Expiration" },
+       { "TLS-Client-Cert-Subject",                    "TLS-Cert-Subject" },
+       { "TLS-Client-Cert-Issuer",                     "TLS-Cert-Issuer" },
+       { "TLS-Client-Cert-Common-Name",                "TLS-Cert-Common-Name" },
+       { "TLS-Client-Cert-Subject-Alt-Name-Email",     "TLS-Cert-Subject-Alt-Name-Email" },
+       { "TLS-Client-Cert-Subject-Alt-Name-Dns",       "TLS-Cert-Subject-Alt-Name-Dns" },
+       { "TLS-Client-Cert-Subject-Alt-Name-Upn",       "TLS-Cert-Subject-Alt-Name-Upn" }
 };
 
 #define FR_TLS_SERIAL          (0)
@@ -1651,31 +1702,33 @@ static char const *cert_attr_names[8][2] = {
  */
 int cbtls_verify(int ok, X509_STORE_CTX *ctx)
 {
-       char subject[1024]; /* Used for the subject name */
-       char issuer[1024]; /* Used for the issuer name */
-       char attribute[1024];
-       char value[1024];
-       char common_name[1024];
-       char cn_str[1024];
-       char buf[64];
-       X509 *client_cert;
-       X509_CINF *client_inf;
+       char            subject[1024]; /* Used for the subject name */
+       char            issuer[1024]; /* Used for the issuer name */
+       char            attribute[1024];
+       char            value[1024];
+       char            common_name[1024];
+       char            cn_str[1024];
+       char            buf[64];
+       X509            *client_cert;
+       X509_CINF       *client_inf;
        STACK_OF(X509_EXTENSION) *ext_list;
-       SSL *ssl;
-       int err, depth, lookup, loc;
+       SSL             *ssl;
+       int             err, depth, lookup, loc;
        fr_tls_server_conf_t *conf;
-       int my_ok = ok;
-       REQUEST *request;
-       ASN1_INTEGER *sn = NULL;
-       ASN1_TIME *asn_time = NULL;
-       VALUE_PAIR **certs;
+       int             my_ok = ok;
+
+       ASN1_INTEGER    *sn = NULL;
+       ASN1_TIME       *asn_time = NULL;
+       VALUE_PAIR      **certs;
        char **identity;
 #ifdef HAVE_OPENSSL_OCSP_H
-       X509_STORE *ocsp_store = NULL;
-       X509 *issuer_cert;
+       X509_STORE      *ocsp_store = NULL;
+       X509            *issuer_cert;
 #endif
-       VALUE_PAIR *vp;
-       TALLOC_CTX *talloc_ctx;
+       VALUE_PAIR      *vp;
+       TALLOC_CTX      *talloc_ctx;
+
+       REQUEST         *request;
 
        client_cert = X509_STORE_CTX_get_current_cert(ctx);
        err = X509_STORE_CTX_get_error(ctx);
@@ -1714,7 +1767,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();
 
        /*
@@ -1732,7 +1785,7 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
                        sprintf(p, "%02x", (unsigned int)sn->data[i]);
                        p += 2;
                }
-               vp = pairmake(talloc_ctx, certs, cert_attr_names[FR_TLS_SERIAL][lookup], buf, T_OP_SET);
+               vp = fr_pair_make(talloc_ctx, certs, cert_attr_names[FR_TLS_SERIAL][lookup], buf, T_OP_SET);
                rdebug_pair(L_DBG_LVL_2, request, vp, NULL);
        }
 
@@ -1746,7 +1799,7 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
            (asn_time->length < (int) sizeof(buf))) {
                memcpy(buf, (char*) asn_time->data, asn_time->length);
                buf[asn_time->length] = '\0';
-               vp = pairmake(talloc_ctx, certs, cert_attr_names[FR_TLS_EXPIRATION][lookup], buf, T_OP_SET);
+               vp = fr_pair_make(talloc_ctx, certs, cert_attr_names[FR_TLS_EXPIRATION][lookup], buf, T_OP_SET);
                rdebug_pair(L_DBG_LVL_2, request, vp, NULL);
        }
 
@@ -1758,7 +1811,7 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
                          sizeof(subject));
        subject[sizeof(subject) - 1] = '\0';
        if (certs && identity && (lookup <= 1) && subject[0]) {
-               vp = pairmake(talloc_ctx, certs, cert_attr_names[FR_TLS_SUBJECT][lookup], subject, T_OP_SET);
+               vp = fr_pair_make(talloc_ctx, certs, cert_attr_names[FR_TLS_SUBJECT][lookup], subject, T_OP_SET);
                rdebug_pair(L_DBG_LVL_2, request, vp, NULL);
        }
 
@@ -1766,7 +1819,7 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
                          sizeof(issuer));
        issuer[sizeof(issuer) - 1] = '\0';
        if (certs && identity && (lookup <= 1) && issuer[0]) {
-               vp = pairmake(talloc_ctx, certs, cert_attr_names[FR_TLS_ISSUER][lookup], issuer, T_OP_SET);
+               vp = fr_pair_make(talloc_ctx, certs, cert_attr_names[FR_TLS_ISSUER][lookup], issuer, T_OP_SET);
                rdebug_pair(L_DBG_LVL_2, request, vp, NULL);
        }
 
@@ -1777,7 +1830,7 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
                                  NID_commonName, common_name, sizeof(common_name));
        common_name[sizeof(common_name) - 1] = '\0';
        if (certs && identity && (lookup <= 1) && common_name[0] && subject[0]) {
-               vp = pairmake(talloc_ctx, certs, cert_attr_names[FR_TLS_CN][lookup], common_name, T_OP_SET);
+               vp = fr_pair_make(talloc_ctx, certs, cert_attr_names[FR_TLS_CN][lookup], common_name, T_OP_SET);
                rdebug_pair(L_DBG_LVL_2, request, vp, NULL);
        }
 
@@ -1798,14 +1851,14 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
                                switch (name->type) {
 #ifdef GEN_EMAIL
                                case GEN_EMAIL:
-                                       vp = pairmake(talloc_ctx, certs, cert_attr_names[FR_TLS_SAN_EMAIL][lookup],
+                                       vp = fr_pair_make(talloc_ctx, certs, cert_attr_names[FR_TLS_SAN_EMAIL][lookup],
                                                      (char *) ASN1_STRING_data(name->d.rfc822Name), T_OP_SET);
                                        rdebug_pair(L_DBG_LVL_2, request, vp, NULL);
                                        break;
 #endif /* GEN_EMAIL */
 #ifdef GEN_DNS
                                case GEN_DNS:
-                                       vp = pairmake(talloc_ctx, certs, cert_attr_names[FR_TLS_SAN_DNS][lookup],
+                                       vp = fr_pair_make(talloc_ctx, certs, cert_attr_names[FR_TLS_SAN_DNS][lookup],
                                                      (char *) ASN1_STRING_data(name->d.dNSName), T_OP_SET);
                                        rdebug_pair(L_DBG_LVL_2, request, vp, NULL);
                                        break;
@@ -1816,7 +1869,7 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
                                        if (NID_ms_upn == OBJ_obj2nid(name->d.otherName->type_id)) {
                                            /* we've got a UPN - Must be ASN1-encoded UTF8 string */
                                            if (name->d.otherName->value->type == V_ASN1_UTF8STRING) {
-                                                   vp = pairmake(talloc_ctx, certs, cert_attr_names[FR_TLS_SAN_UPN][lookup],
+                                                   vp = fr_pair_make(talloc_ctx, certs, cert_attr_names[FR_TLS_SAN_UPN][lookup],
                                                                  (char *) ASN1_STRING_data(name->d.otherName->value->value.utf8string), T_OP_SET);
                                                    rdebug_pair(L_DBG_LVL_2, request, vp, NULL);
                                                break;
@@ -1865,7 +1918,7 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
         *      Grab the X509 extensions, and create attributes out of them.
         *      For laziness, we re-use the OpenSSL names
         */
-       if (sk_X509_EXTENSION_num(ext_list) > 0) {
+       if (certs && (sk_X509_EXTENSION_num(ext_list) > 0)) {
                int i, len;
                char *p;
                BIO *out;
@@ -1896,13 +1949,18 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
 
                        value[len] = '\0';
 
-                       vp = pairmake(talloc_ctx, certs, attribute, value, T_OP_ADD);
+                       vp = fr_pair_make(talloc_ctx, certs, attribute, value, T_OP_ADD);
                        if (!vp) {
                                RDEBUG3("Skipping %s += '%s'.  Please check that both the "
                                        "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();
                        }
                }
 
@@ -1945,7 +2003,8 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
                 */
                if (conf->check_cert_issuer &&
                    (strcmp(issuer, conf->check_cert_issuer) != 0)) {
-                       AUTH("tls: Certificate issuer (%s) does not match specified value (%s)!", issuer, conf->check_cert_issuer);
+                       AUTH(LOG_PREFIX ": Certificate issuer (%s) does not match specified value (%s)!",
+                            issuer, conf->check_cert_issuer);
                        my_ok = 0;
                }
 
@@ -1961,7 +2020,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;
                                }
                        }
@@ -1969,11 +2029,11 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
 
 #ifdef HAVE_OPENSSL_OCSP_H
                if (my_ok && conf->ocsp_enable){
-                       RDEBUG2("--> Starting OCSP Request");
+                       RDEBUG2("Starting OCSP Request");
                        if (X509_STORE_CTX_get1_issuer(&issuer_cert, ctx, client_cert) != 1) {
                                RERROR("Couldn't get issuer_cert for %s", common_name);
                        } else {
-                               my_ok = ocsp_check(ocsp_store, issuer_cert, client_cert, conf);
+                               my_ok = ocsp_check(request, ocsp_store, issuer_cert, client_cert, conf);
                        }
                }
 #endif
@@ -2007,7 +2067,7 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
                        }
                        fclose(fp);
 
-                       if (!pairmake_packet("TLS-Client-Cert-Filename",
+                       if (!pair_make_request("TLS-Client-Cert-Filename",
                                             filename, T_OP_SET)) {
                                RDEBUG("Failed creating TLS-Client-Cert-Filename");
 
@@ -2015,10 +2075,10 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
                        }
 
                        RDEBUG("Verifying client certificate: %s", conf->verify_client_cert_cmd);
-                       if (radius_exec_program(NULL, 0, NULL, request, conf->verify_client_cert_cmd,
+                       if (radius_exec_program(request, NULL, 0, NULL, request, conf->verify_client_cert_cmd,
                                                request->packet->vps,
                                                true, true, EXEC_TIMEOUT) != 0) {
-                               AUTH("tls: Certificate CN (%s) fails external verification!", common_name);
+                               AUTH(LOG_PREFIX ": Certificate CN (%s) fails external verification!", common_name);
                                my_ok = 0;
                        } else {
                                RDEBUG("Client certificate CN %s passed external validation", common_name);
@@ -2032,15 +2092,15 @@ int cbtls_verify(int ok, X509_STORE_CTX *ctx)
 
        } /* depth == 0 */
 
-       if (debug_flag > 0) {
-               RDEBUG2("chain-depth=%d, ", depth);
-               RDEBUG2("error=%d", err);
+       if (RDEBUG_ENABLED3) {
+               RDEBUG3("chain-depth   : %d", depth);
+               RDEBUG3("error         : %d", err);
 
-               if (identity) RDEBUG2("--> User-Name = %s", *identity);
-               RDEBUG2("--> BUF-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;
 }
@@ -2063,8 +2123,8 @@ static X509_STORE *init_revocation_store(fr_tls_server_conf_t *conf)
        /* Load the CAs we trust */
        if (conf->ca_file || conf->ca_path)
                if(!X509_STORE_load_locations(store, conf->ca_file, conf->ca_path)) {
-                       ERROR("tls: X509_STORE error %s", ERR_error_string(ERR_get_error(), NULL));
-                       ERROR("tls: Error reading Trusted root CA list %s",conf->ca_file );
+                       ERROR(LOG_PREFIX ": X509_STORE error %s", ERR_error_string(ERR_get_error(), NULL));
+                       ERROR(LOG_PREFIX ": Error reading Trusted root CA list %s",conf->ca_file );
                        return NULL;
                }
 
@@ -2072,6 +2132,10 @@ static X509_STORE *init_revocation_store(fr_tls_server_conf_t *conf)
        if (conf->check_crl)
                X509_STORE_set_flags(store, X509_V_FLAG_CRL_CHECK);
 #endif
+#ifdef X509_V_FLAG_CRL_CHECK_ALL
+       if (conf->check_all_crl)
+               X509_STORE_set_flags(store, X509_V_FLAG_CRL_CHECK_ALL);
+#endif
        return store;
 }
 #endif /* HAVE_OPENSSL_OCSP_H */
@@ -2087,13 +2151,13 @@ static int set_ecdh_curve(SSL_CTX *ctx, char const *ecdh_curve)
 
        nid = OBJ_sn2nid(ecdh_curve);
        if (!nid) {
-               ERROR("Unknown ecdh_curve \"%s\"", ecdh_curve);
+               ERROR(LOG_PREFIX ": Unknown ecdh_curve \"%s\"", ecdh_curve);
                return -1;
        }
 
        ecdh = EC_KEY_new_by_curve_name(nid);
        if (!ecdh) {
-               ERROR("Unable to create new curve \"%s\"", ecdh_curve);
+               ERROR(LOG_PREFIX ": Unable to create new curve \"%s\"", ecdh_curve);
                return -1;
        }
 
@@ -2123,9 +2187,9 @@ static void sess_free_vps(UNUSED void *parent, void *data_ptr,
        VALUE_PAIR *vp = data_ptr;
        if (!vp) return;
 
-       DEBUG2( Freeing cached session VPs");
+       DEBUG2(LOG_PREFIX ": Freeing cached session VPs");
 
-       pairfree(&vp);
+       fr_pair_list_free(&vp);
 }
 
 static void sess_free_certs(UNUSED void *parent, void *data_ptr,
@@ -2135,9 +2199,9 @@ static void sess_free_certs(UNUSED void *parent, void *data_ptr,
        VALUE_PAIR **certs = data_ptr;
        if (!certs) return;
 
-       DEBUG2( Freeing cached session Certificates");
+       DEBUG2(LOG_PREFIX ": Freeing cached session Certificates");
 
-       pairfree(certs);
+       fr_pair_list_free(certs);
 }
 
 /** Add all the default ciphers and message digests reate our context.
@@ -2220,12 +2284,12 @@ void tls_global_cleanup(void)
  */
 SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
 {
-       SSL_CTX *ctx;
-       X509_STORE *certstore;
-       int verify_mode = SSL_VERIFY_NONE;
-       int ctx_options = 0;
-       int ctx_tls_versions = 0;
-       int type;
+       SSL_CTX         *ctx;
+       X509_STORE      *certstore;
+       int             verify_mode = SSL_VERIFY_NONE;
+       int             ctx_options = 0;
+       int             ctx_tls_versions = 0;
+       int             type;
 
        /*
         *      SHA256 is in all versions of OpenSSL, but isn't
@@ -2240,8 +2304,7 @@ SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
        if (!ctx) {
                int err;
                while ((err = ERR_get_error())) {
-                       DEBUG("Failed creating SSL context: %s",
-                             ERR_error_string(err, NULL));
+                       ERROR(LOG_PREFIX ": Failed creating SSL context: %s", ERR_error_string(err, NULL));
                        return NULL;
                }
        }
@@ -2279,20 +2342,20 @@ SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
                        snprintf(cmd, sizeof(cmd) - 1, "/usr/sbin/certadmin --get-private-key-passphrase \"%s\"",
                                 conf->private_key_file);
 
-                       DEBUG2("tls: Getting private key passphrase using command \"%s\"", cmd);
+                       DEBUG2(LOG_PREFIX ":  Getting private key passphrase using command \"%s\"", cmd);
 
                        FILE* cmd_pipe = popen(cmd, "r");
                        if (!cmd_pipe) {
-                               ERROR("TLS: %s command failed.  Unable to get private_key_password", cmd);
-                               ERROR("Error reading private_key_file %s", conf->private_key_file);
+                               ERROR(LOG_PREFIX ": %s command failed: Unable to get private_key_password", cmd);
+                               ERROR(LOG_PREFIX ": Error reading private_key_file %s", conf->private_key_file);
                                return NULL;
                        }
 
                        rad_const_free(conf->private_key_password);
                        password = talloc_array(conf, char, max_password_len);
                        if (!password) {
-                               ERROR("TLS: Can't allocate space for private_key_password");
-                               ERROR("TLS: Error reading private_key_file %s", conf->private_key_file);
+                               ERROR(LOG_PREFIX ": Can't allocate space for private_key_password");
+                               ERROR(LOG_PREFIX ": Error reading private_key_file %s", conf->private_key_file);
                                pclose(cmd_pipe);
                                return NULL;
                        }
@@ -2303,7 +2366,7 @@ SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
                        /* Get rid of newline at end of password. */
                        password[strlen(password) - 1] = '\0';
 
-                       DEBUG3("tls:  Password from command = \"%s\"", password);
+                       DEBUG3(LOG_PREFIX ": Password from command = \"%s\"", password);
                        conf->private_key_password = password;
                }
 #endif
@@ -2324,7 +2387,7 @@ SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
                 *      statically configured identity and password.
                 */
                if (conf->psk_query && !*conf->psk_query) {
-                       ERROR("Invalid PSK Configuration: psk_query cannot be empty");
+                       ERROR(LOG_PREFIX ": Invalid PSK Configuration: psk_query cannot be empty");
                        return NULL;
                }
 
@@ -2336,7 +2399,7 @@ SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
                }
 
        } else if (conf->psk_query) {
-               ERROR("Invalid PSK Configuration: psk_query cannot be used for outgoing connections");
+               ERROR(LOG_PREFIX ": Invalid PSK Configuration: psk_query cannot be used for outgoing connections");
                return NULL;
        }
 
@@ -2347,7 +2410,7 @@ SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
            (!conf->psk_identity && conf->psk_password) ||
            (conf->psk_identity && !*conf->psk_identity) ||
            (conf->psk_password && !*conf->psk_password)) {
-               ERROR("Invalid PSK Configuration: psk_identity or psk_password are empty");
+               ERROR(LOG_PREFIX ": Invalid PSK Configuration: psk_identity or psk_password are empty");
                return NULL;
        }
 
@@ -2358,7 +2421,7 @@ SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
                if (conf->certificate_file ||
                    conf->private_key_password || conf->private_key_file ||
                    conf->ca_file || conf->ca_path) {
-                       ERROR("When PSKs are used, No certificate configuration is permitted");
+                       ERROR(LOG_PREFIX ": When PSKs are used, No certificate configuration is permitted");
                        return NULL;
                }
 
@@ -2369,8 +2432,7 @@ SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
 
                psk_len = strlen(conf->psk_password);
                if (strlen(conf->psk_password) > (2 * PSK_MAX_PSK_LEN)) {
-                       ERROR("psk_hexphrase is too long (max %d)",
-                              PSK_MAX_PSK_LEN);
+                       ERROR(LOG_PREFIX ": psk_hexphrase is too long (max %d)", PSK_MAX_PSK_LEN);
                        return NULL;
                }
 
@@ -2380,7 +2442,7 @@ SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
                 */
                hex_len = fr_hex2bin(buffer, sizeof(buffer), conf->psk_password, psk_len);
                if (psk_len != (2 * hex_len)) {
-                       ERROR("psk_hexphrase is not all hex");
+                       ERROR(LOG_PREFIX ": psk_hexphrase is not all hex");
                        return NULL;
                }
 
@@ -2403,16 +2465,15 @@ SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
 
        if (type == SSL_FILETYPE_PEM) {
                if (!(SSL_CTX_use_certificate_chain_file(ctx, conf->certificate_file))) {
-                       ERROR("Error reading certificate file %s:%s",
-                              conf->certificate_file,
-                              ERR_error_string(ERR_get_error(), NULL));
+                       ERROR(LOG_PREFIX ": Error reading certificate file %s:%s", conf->certificate_file,
+                             ERR_error_string(ERR_get_error(), NULL));
                        return NULL;
                }
 
        } else if (!(SSL_CTX_use_certificate_file(ctx, conf->certificate_file, type))) {
-               ERROR("Error reading certificate file %s:%s",
-                      conf->certificate_file,
-                      ERR_error_string(ERR_get_error(), NULL));
+               ERROR(LOG_PREFIX ": Error reading certificate file %s:%s",
+                     conf->certificate_file,
+                     ERR_error_string(ERR_get_error(), NULL));
                return NULL;
        }
 
@@ -2420,8 +2481,8 @@ SSL_CTX *tls_init_ctx(fr_tls_server_conf_t *conf, int client)
 load_ca:
        if (conf->ca_file || conf->ca_path) {
                if (!SSL_CTX_load_verify_locations(ctx, conf->ca_file, conf->ca_path)) {
-                       ERROR("tls: SSL error %s", ERR_error_string(ERR_get_error(), NULL));
-                       ERROR("tls: Error reading Trusted root CA list %s",conf->ca_file );
+                       ERROR(LOG_PREFIX ": SSL error %s", ERR_error_string(ERR_get_error(), NULL));
+                       ERROR(LOG_PREFIX ": Error reading Trusted root CA list %s",conf->ca_file );
                        return NULL;
                }
        }
@@ -2429,9 +2490,9 @@ load_ca:
 
        if (conf->private_key_file) {
                if (!(SSL_CTX_use_PrivateKey_file(ctx, conf->private_key_file, type))) {
-                       ERROR("Failed reading private key file %s:%s",
-                              conf->private_key_file,
-                              ERR_error_string(ERR_get_error(), NULL));
+                       ERROR(LOG_PREFIX ": Failed reading private key file %s:%s",
+                             conf->private_key_file,
+                             ERR_error_string(ERR_get_error(), NULL));
                        return NULL;
                }
 
@@ -2439,7 +2500,7 @@ load_ca:
                 * Check if the loaded private key is the right one
                 */
                if (!SSL_CTX_check_private_key(ctx)) {
-                       ERROR("Private key does not match the certificate public key");
+                       ERROR(LOG_PREFIX ": Private key does not match the certificate public key");
                        return NULL;
                }
        }
@@ -2475,7 +2536,8 @@ post_ca:
 #endif
 
        if ((ctx_options & ctx_tls_versions) == ctx_tls_versions) {
-               ERROR("You have disabled all available TLS versions.  EAP will not work.");
+               ERROR(LOG_PREFIX ": You have disabled all available TLS versions.  EAP will not work");
+               return NULL;
        }
 
 #ifdef SSL_OP_NO_TICKET
@@ -2535,9 +2597,14 @@ post_ca:
         *      Callbacks, etc. for session resumption.
         */
        if (conf->session_cache_enable) {
-               SSL_CTX_sess_set_new_cb(ctx, cbtls_new_session);
-               SSL_CTX_sess_set_get_cb(ctx, cbtls_get_session);
-               SSL_CTX_sess_set_remove_cb(ctx, cbtls_remove_session);
+               /*
+                *      Cache sessions on disk if requested.
+                */
+               if (conf->session_cache_path) {
+                       SSL_CTX_sess_set_new_cb(ctx, cbtls_new_session);
+                       SSL_CTX_sess_set_get_cb(ctx, cbtls_get_session);
+                       SSL_CTX_sess_set_remove_cb(ctx, cbtls_remove_session);
+               }
 
                SSL_CTX_set_quiet_shutdown(ctx, 1);
                if (fr_tls_ex_index_vps < 0)
@@ -2551,11 +2618,16 @@ post_ca:
        if (conf->check_crl) {
                certstore = SSL_CTX_get_cert_store(ctx);
                if (certstore == NULL) {
-                       ERROR("tls: SSL error %s", ERR_error_string(ERR_get_error(), NULL));
-                       ERROR("tls: Error reading Certificate Store");
+                       ERROR(LOG_PREFIX ": SSL error %s", ERR_error_string(ERR_get_error(), NULL));
+                       ERROR(LOG_PREFIX ": Error reading Certificate Store");
                        return NULL;
                }
                X509_STORE_set_flags(certstore, X509_V_FLAG_CRL_CHECK);
+
+#ifdef X509_V_FLAG_CRL_CHECK_ALL
+               if (conf->check_all_crl)
+                       X509_STORE_set_flags(certstore, X509_V_FLAG_CRL_CHECK_ALL);
+#endif
        }
 #endif
 
@@ -2575,8 +2647,8 @@ post_ca:
        /* Load randomness */
        if (conf->random_file) {
                if (!(RAND_load_file(conf->random_file, 1024*10))) {
-                       ERROR("tls: SSL error %s", ERR_error_string(ERR_get_error(), NULL));
-                       ERROR("tls: Error loading randomness");
+                       ERROR(LOG_PREFIX ": SSL error %s", ERR_error_string(ERR_get_error(), NULL));
+                       ERROR(LOG_PREFIX ": Error loading randomness");
                        return NULL;
                }
        }
@@ -2586,7 +2658,7 @@ post_ca:
         */
        if (conf->cipher_list) {
                if (!SSL_CTX_set_cipher_list(ctx, conf->cipher_list)) {
-                       ERROR("tls: Error setting cipher list");
+                       ERROR(LOG_PREFIX ": Error setting cipher list");
                        return NULL;
                }
        }
@@ -2661,7 +2733,7 @@ static fr_tls_server_conf_t *tls_server_conf_alloc(TALLOC_CTX *ctx)
 
        conf = talloc_zero(ctx, fr_tls_server_conf_t);
        if (!conf) {
-               ERROR("Out of memory");
+               ERROR(LOG_PREFIX ": Out of memory");
                return NULL;
        }
 
@@ -2680,7 +2752,7 @@ fr_tls_server_conf_t *tls_server_conf_parse(CONF_SECTION *cs)
         */
        conf = cf_data_find(cs, "tls-conf");
        if (conf) {
-               DEBUG("Using cached TLS configuration from previous invocation");
+               DEBUG(LOG_PREFIX ": Using cached TLS configuration from previous invocation");
                return conf;
        }
 
@@ -2698,12 +2770,12 @@ fr_tls_server_conf_t *tls_server_conf_parse(CONF_SECTION *cs)
        if (conf->fragment_size < 100) conf->fragment_size = 100;
 
        if (!conf->private_key_file) {
-               ERROR("TLS Server requires a private key file");
+               ERROR(LOG_PREFIX ": TLS Server requires a private key file");
                goto error;
        }
 
        if (!conf->certificate_file) {
-               ERROR("TLS Server requires a certificate file");
+               ERROR(LOG_PREFIX ": TLS Server requires a certificate file");
                goto error;
        }
 
@@ -2735,13 +2807,14 @@ fr_tls_server_conf_t *tls_server_conf_parse(CONF_SECTION *cs)
 
        if (conf->verify_tmp_dir) {
                if (chmod(conf->verify_tmp_dir, S_IRWXU) < 0) {
-                       ERROR("Failed changing permissions on %s: %s", conf->verify_tmp_dir, fr_syserror(errno));
+                       ERROR(LOG_PREFIX ": Failed changing permissions on %s: %s",
+                             conf->verify_tmp_dir, fr_syserror(errno));
                        goto error;
                }
        }
 
        if (conf->verify_client_cert_cmd && !conf->verify_tmp_dir) {
-               ERROR("You MUST set the verify directory in order to use verify_client_cmd");
+               ERROR(LOG_PREFIX ": You MUST set the verify directory in order to use verify_client_cmd");
                goto error;
        }
 
@@ -2759,7 +2832,7 @@ fr_tls_server_conf_t *tls_client_conf_parse(CONF_SECTION *cs)
 
        conf = cf_data_find(cs, "tls-conf");
        if (conf) {
-               DEBUG("Using cached TLS configuration from previous invocation");
+               DEBUG2(LOG_PREFIX ": Using cached TLS configuration from previous invocation");
                return conf;
        }
 
@@ -2819,7 +2892,7 @@ int tls_success(tls_session_t *ssn, REQUEST *request)
         *      user.
         */
        if ((!ssn->allow_session_resumption) ||
-           (((vp = pairfind(request->config, PW_ALLOW_SESSION_RESUMPTION, 0, TAG_ANY)) != NULL) &&
+           (((vp = fr_pair_find_by_num(request->config, PW_ALLOW_SESSION_RESUMPTION, 0, TAG_ANY)) != NULL) &&
             (vp->vp_integer == 0))) {
                SSL_CTX_remove_session(ssn->ctx,
                                       ssn->ssl->session);
@@ -2830,7 +2903,7 @@ int tls_success(tls_session_t *ssn, REQUEST *request)
                 *      not allowed,
                 */
                if (SSL_session_reused(ssn->ssl)) {
-                       RDEBUG("FAIL: Forcibly stopping session resumption as it is not allowed");
+                       RDEBUG("Forcibly stopping session resumption as it is not allowed");
                        return -1;
                }
 
@@ -2848,20 +2921,20 @@ int tls_success(tls_session_t *ssn, REQUEST *request)
 
                fr_bin2hex(buffer, ssn->ssl->session->session_id, size);
 
-               vp = paircopy_by_num(talloc_ctx, request->reply->vps, PW_USER_NAME, 0, TAG_ANY);
-               if (vp) pairadd(&vps, vp);
+               vp = fr_pair_list_copy_by_num(talloc_ctx, request->reply->vps, PW_USER_NAME, 0, TAG_ANY);
+               if (vp) fr_pair_add(&vps, vp);
 
-               vp = paircopy_by_num(talloc_ctx, request->packet->vps, PW_STRIPPED_USER_NAME, 0, TAG_ANY);
-               if (vp) pairadd(&vps, vp);
+               vp = fr_pair_list_copy_by_num(talloc_ctx, request->packet->vps, PW_STRIPPED_USER_NAME, 0, TAG_ANY);
+               if (vp) fr_pair_add(&vps, vp);
 
-               vp = paircopy_by_num(talloc_ctx, request->packet->vps, PW_STRIPPED_USER_DOMAIN, 0, TAG_ANY);
-               if (vp) pairadd(&vps, vp);
+               vp = fr_pair_list_copy_by_num(talloc_ctx, request->packet->vps, PW_STRIPPED_USER_DOMAIN, 0, TAG_ANY);
+               if (vp) fr_pair_add(&vps, vp);
 
-               vp = paircopy_by_num(talloc_ctx, request->reply->vps, PW_CHARGEABLE_USER_IDENTITY, 0, TAG_ANY);
-               if (vp) pairadd(&vps, vp);
+               vp = fr_pair_list_copy_by_num(talloc_ctx, request->reply->vps, PW_CHARGEABLE_USER_IDENTITY, 0, TAG_ANY);
+               if (vp) fr_pair_add(&vps, vp);
 
-               vp = paircopy_by_num(talloc_ctx, request->reply->vps, PW_CACHED_SESSION_POLICY, 0, TAG_ANY);
-               if (vp) pairadd(&vps, vp);
+               vp = fr_pair_list_copy_by_num(talloc_ctx, request->reply->vps, PW_CACHED_SESSION_POLICY, 0, TAG_ANY);
+               if (vp) fr_pair_add(&vps, vp);
 
                certs = (VALUE_PAIR **)SSL_get_ex_data(ssn->ssl, fr_tls_ex_index_certs);
 
@@ -2873,47 +2946,51 @@ int tls_success(tls_session_t *ssn, REQUEST *request)
                         *      @todo: some go into reply, others into
                         *      request
                         */
-                       pairadd(&vps, paircopy(talloc_ctx, *certs));
+                       fr_pair_add(&vps, fr_pair_list_copy(talloc_ctx, *certs));
 
                        /*
                         *      Save the certs in the packet, so that we can see them.
                         */
-                       pairadd(&request->packet->vps, paircopy(request->packet, *certs));
+                       fr_pair_add(&request->packet->vps, fr_pair_list_copy(request->packet, *certs));
                }
 
                if (vps) {
-                       RDEBUG2("Saving session %s vps %p in the cache", buffer, vps);
                        SSL_SESSION_set_ex_data(ssn->ssl->session, fr_tls_ex_index_vps, vps);
+                       rdebug_pair_list(L_DBG_LVL_2, request, vps, "  caching ");
+
                        if (conf->session_cache_path) {
                                /* write the VPs to the cache file */
                                char filename[256], buf[1024];
                                FILE *vp_file;
 
+                               RDEBUG2("Saving session %s in the disk cache", buffer);
+
                                snprintf(filename, sizeof(filename), "%s%c%s.vps", conf->session_cache_path,
                                         FR_DIR_SEP, buffer);
                                vp_file = fopen(filename, "w");
                                if (vp_file == NULL) {
-                                       RDEBUG2("Could not write session VPs to persistent cache: %s",
+                                       RWDEBUG("Could not write session VPs to persistent cache: %s",
                                                fr_syserror(errno));
                                } else {
                                        VALUE_PAIR *prev = NULL;
                                        vp_cursor_t cursor;
                                        /* generate a dummy user-style entry which is easy to read back */
                                        fprintf(vp_file, "# SSL cached session\n");
-                                       fprintf(vp_file, "%s\n", buffer);
+                                       fprintf(vp_file, "%s\n\t", buffer);
+
                                        for (vp = fr_cursor_init(&cursor, &vps);
                                             vp;
                                             vp = fr_cursor_next(&cursor)) {
                                                /*
                                                 *      Terminate the previous line.
                                                 */
-                                               if (prev) fprintf(vp_file, ",\n");
+                                               if (prev) fprintf(vp_file, ",\n\t");
 
                                                /*
                                                 *      Write this one.
                                                 */
                                                vp_prints(buf, sizeof(buf), vp);
-                                               fprintf(vp_file, "\t%s,\n", buf);
+                                               fputs(buf, vp_file);
                                                prev = vp;
                                        }
 
@@ -2923,6 +3000,8 @@ int tls_success(tls_session_t *ssn, REQUEST *request)
                                        fprintf(vp_file, "\n");
                                        fclose(vp_file);
                                }
+                       } else {
+                               RDEBUG("Failed to find 'persist_dir' in TLS configuration.  Session will not be cached on disk.");
                        }
                } else {
                        RDEBUG2("No information to cache: session caching will be disabled for session %s", buffer);
@@ -2941,48 +3020,27 @@ int tls_success(tls_session_t *ssn, REQUEST *request)
 
                fr_bin2hex(buffer, ssn->ssl->session->session_id, size);
 
-               vps = SSL_SESSION_get_ex_data(ssn->ssl->session, fr_tls_ex_index_vps);
-               if (!vps) {
-                       RWDEBUG("No information in cached session %s", buffer);
-                       return -1;
-               } else {
-                       vp_cursor_t cursor;
-
-                       RDEBUG("Adding cached attributes for session %s:", buffer);
-                       rdebug_pair_list(L_DBG_LVL_1, request, vps, NULL);
-                       for (vp = fr_cursor_init(&cursor, &vps);
-                            vp;
-                            vp = fr_cursor_next(&cursor)) {
-                               /*
-                                *      TLS-* attrs get added back to
-                                *      the request list.
-                                */
-                               if ((vp->da->vendor == 0) &&
-                                   (vp->da->attr >= PW_TLS_CERT_SERIAL) &&
-                                   (vp->da->attr <= PW_TLS_CLIENT_CERT_SUBJECT_ALT_NAME_UPN)) {
-                                       pairadd(&request->packet->vps, paircopyvp(request->packet, vp));
-                               } else {
-                                       pairadd(&request->reply->vps, paircopyvp(request->reply, vp));
-                               }
-                       }
+               /*
+                *      The "restore VPs from OpenSSL cache" code is
+                *      now in eaptls_process()
+                */
 
-                       if (conf->session_cache_path) {
-                               /* "touch" the cached session/vp file */
-                               char filename[256];
-
-                               snprintf(filename, sizeof(filename), "%s%c%s.asn1",
-                                       conf->session_cache_path, FR_DIR_SEP, buffer);
-                               utime(filename, NULL);
-                               snprintf(filename, sizeof(filename), "%s%c%s.vps",
-                                       conf->session_cache_path, FR_DIR_SEP, buffer);
-                               utime(filename, NULL);
-                       }
+               if (conf->session_cache_path) {
+                       /* "touch" the cached session/vp file */
+                       char filename[256];
 
-                       /*
-                        *      Mark the request as resumed.
-                        */
-                       pairmake_packet("EAP-Session-Resumed", "1", T_OP_SET);
+                       snprintf(filename, sizeof(filename), "%s%c%s.asn1",
+                                conf->session_cache_path, FR_DIR_SEP, buffer);
+                       utime(filename, NULL);
+                       snprintf(filename, sizeof(filename), "%s%c%s.vps",
+                                conf->session_cache_path, FR_DIR_SEP, buffer);
+                       utime(filename, NULL);
                }
+
+               /*
+                *      Mark the request as resumed.
+                */
+               pair_make_request("EAP-Session-Resumed", "1", T_OP_SET);
        }
 
        return 0;
@@ -2997,8 +3055,7 @@ void tls_fail(tls_session_t *ssn)
        SSL_CTX_remove_session(ssn->ctx, ssn->ssl->session);
 }
 
-fr_tls_status_t tls_application_data(tls_session_t *ssn,
-                                    REQUEST *request)
+fr_tls_status_t tls_application_data(tls_session_t *ssn, REQUEST *request)
 
 {
        int err;
@@ -3011,7 +3068,7 @@ fr_tls_status_t tls_application_data(tls_session_t *ssn,
                        ssn->dirty_in.used);
        if (err != (int) ssn->dirty_in.used) {
                record_init(&ssn->dirty_in);
-               RDEBUG("Failed writing %d to SSL BIO: %d", ssn->dirty_in.used, err);
+               RDEBUG("Failed writing %zd bytes to SSL BIO: %d", ssn->dirty_in.used, err);
                return FR_TLS_FAIL;
        }
 
@@ -3067,7 +3124,7 @@ fr_tls_status_t tls_application_data(tls_session_t *ssn,
         */
        certs = (VALUE_PAIR **)SSL_get_ex_data(ssn->ssl, fr_tls_ex_index_certs);
 
-       if (certs) pairadd(&request->packet->vps, paircopy(request->packet, *certs));
+       if (certs) fr_pair_add(&request->packet->vps, fr_pair_list_copy(request->packet, *certs));
 
        return FR_TLS_OK;
 }
@@ -3081,29 +3138,28 @@ fr_tls_status_t tls_application_data(tls_session_t *ssn,
  */
 fr_tls_status_t tls_ack_handler(tls_session_t *ssn, REQUEST *request)
 {
-       RDEBUG2("Received TLS ACK");
-
        if (ssn == NULL){
-               RERROR("FAIL: Unexpected ACK received.  Could not obtain session information");
+               REDEBUG("Unexpected ACK received:  No ongoing SSL session");
                return FR_TLS_INVALID;
        }
-       if (ssn->info.initialized == 0) {
-               RDEBUG("No SSL info available. Waiting for more SSL data");
+       if (!ssn->info.initialized) {
+               RDEBUG("No SSL info available.  Waiting for more SSL data");
                return FR_TLS_REQUEST;
        }
+
        if ((ssn->info.content_type == handshake) && (ssn->info.origin == 0)) {
-               RERROR("FAIL: ACK without earlier message");
+               REDEBUG("Unexpected ACK received:  We sent no previous messages");
                return FR_TLS_INVALID;
        }
 
        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
@@ -3114,12 +3170,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;
 
                /*
@@ -3127,11 +3183,9 @@ fr_tls_status_t tls_ack_handler(tls_session_t *ssn, REQUEST *request)
                 *      to the default section below.
                 */
        default:
-               RERROR("Invalid ACK received: %d", ssn->info.content_type);
-
+               REDEBUG("Invalid ACK received: %d", ssn->info.content_type);
                return FR_TLS_INVALID;
        }
 }
-
 #endif /* WITH_TLS */