Merge tag 'release_3_0_10' into tr-integ
authorSam Hartman <hartmans@debian.org>
Mon, 16 Nov 2015 15:11:12 +0000 (10:11 -0500)
committerSam Hartman <hartmans@debian.org>
Mon, 16 Nov 2015 15:11:12 +0000 (10:11 -0500)
Conflicts:
raddb/mods-config/attr_filter/access_reject
src/main/tls.c
src/main/tls_listen.c
src/modules/rlm_realm/rlm_realm.c
src/modules/rlm_realm/trustrouter.c

1  2 
raddb/mods-config/attr_filter/access_reject
src/main/tls.c
src/main/tls_listen.c
src/modules/rlm_sql/drivers/rlm_sql_sqlite/rlm_sql_sqlite.c

@@@ -16,4 -16,5 +16,6 @@@ DEFAUL
        Reply-Message =* ANY,
        MS-CHAP-Error =* ANY,
        Proxy-State =* ANY,
-       Error-Cause =* ANY
+       FreeRADIUS-Response-Delay =* ANY,
+       FreeRADIUS-Response-Delay-USec =* ANY
++
diff --combined src/main/tls.c
@@@ -43,13 -43,20 +43,20 @@@ USES_APPLE_DEPRECATED_API  /* OpenSSL AP
  #include <ctype.h>
  
  #ifdef WITH_TLS
- #ifdef HAVE_OPENSSL_RAND_H
- #include <openssl/rand.h>
- #endif
+ #  ifdef HAVE_OPENSSL_RAND_H
+ #    include <openssl/rand.h>
+ #  endif
  
- #ifdef HAVE_OPENSSL_OCSP_H
- #include <openssl/ocsp.h>
- #endif
+ #  ifdef HAVE_OPENSSL_OCSP_H
+ #    include <openssl/ocsp.h>
+ #  endif
+ #  ifdef HAVE_OPENSSL_EVP_H
+ #    include <openssl/evp.h>
+ #  endif
+ #  include <openssl/ssl.h>
+ #define LOG_PREFIX "tls"
  
  #ifdef ENABLE_OPENSSL_VERSION_CHECK
  typedef struct libssl_defect {
@@@ -72,14 -79,37 +79,37 @@@ 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 */
+ static void           session_close(tls_session_t *ssn);
+ static void           session_init(tls_session_t *ssn);
  /* record */
  static void           record_init(record_t *buf);
  static void           record_close(record_t *buf);
@@@ -139,7 -169,7 +169,7 @@@ static unsigned int psk_server_callback
                        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,
@@@ -278,20 -308,34 +308,33 @@@ tls_session_t *tls_new_client_session(T
                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...
+  *
+  * @param ctx to alloc session data in. Should usually be NULL unless the lifetime of the
+  *    session is tied to another talloc'd object.
+  * @param conf to use to configure the tls session.
+  * @param request The current #REQUEST.
+  * @param client_cert Whether to require a client_cert.
+  * @return a new session on success, or NULL on error.
+  */
  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
         */
        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;
        }
  
        if ((new_tls = SSL_new(conf->ctx)) == NULL) {
-               ERROR("SSL: Error creating new SSL: %s",
-                      ERR_error_string(ERR_get_error(), NULL));
+               RERROR("Error creating new SSL session: %s", ERR_error_string(ERR_get_error(), NULL));
                return NULL;
        }
  
        SSL_set_app_data(new_tls, NULL);
  
        if ((state = talloc_zero(ctx, tls_session_t)) == NULL) {
-               ERROR("SSL: Error allocating memory for SSL state");
+               RERROR("Error allocating memory for SSL state");
                return NULL;
        }
        session_init(state);
         *      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;
         *      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;
  }
  
@@@ -413,23 -453,23 +452,23 @@@ static int int_ssl_check(REQUEST *reque
        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:
        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;
        }
  
@@@ -487,8 -525,7 +524,7 @@@ int tls_handshake_recv(REQUEST *request
  
        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;
        }
                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) {
  
                } 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 {
                        return 0;
                }
        } else {
-               DEBUG2("SSL Application Data");
+               RDEBUG2("SSL Application Data");
                /* Its clean application data, do whatever we want */
                record_init(&ssn->clean_out);
        }
@@@ -586,7 -611,7 +610,7 @@@ int tls_handshake_send(REQUEST *request
        return 1;
  }
  
- void session_init(tls_session_t *ssn)
static void session_init(tls_session_t *ssn)
  {
        ssn->ssl = NULL;
        ssn->into_ssl = ssn->from_ssl = NULL;
  
        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;
  }
  
- void session_close(tls_session_t *ssn)
static void session_close(tls_session_t *ssn)
  {
        SSL_set_quiet_shutdown(ssn->ssl, 1);
        SSL_shutdown(ssn->ssl);
@@@ -680,12 -705,13 +704,13 @@@ void tls_session_information(tls_sessio
        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;
        }
  
  
        switch (tls_session->info.version) {
        case SSL2_VERSION:
-               str_version = "SSL 2.0";
+               str_version = "SSL 2.0 ";
                break;
        case SSL3_VERSION:
                str_version = "SSL 3.0 ";
        case TLS1_VERSION:
                str_version = "TLS 1.0 ";
                break;
+ #ifdef TLS1_1_VERSION
+       case TLS1_1_VERSION:
+               str_version = "TLS 1.1 ";
+               break;
+ #endif
+ #ifdef TLS1_2_VERSION
+       case TLS1_2_VERSION:
+               str_version = "TLS 1.2 ";
+               break;
+ #endif
+ #ifdef TLS1_3_VERSON
+       case TLS1_3_VERSION:
+               str_version = "TLS 1.3 ";
+               break;
+ #endif
        default:
-               str_version = "Unknown TLS version";
+               sprintf(buffer, "UNKNOWN TLS VERSION ?%04X?", tls_session->info.version);
+               str_version = buffer;
                break;
        }
  
  
  static CONF_PARSER cache_config[] = {
        { "enable", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, session_cache_enable), "no" },
        { "lifetime", FR_CONF_OFFSET(PW_TYPE_INTEGER, fr_tls_server_conf_t, session_timeout), "24" },
-       { "max_entries", FR_CONF_OFFSET(PW_TYPE_INTEGER, fr_tls_server_conf_t, session_cache_size), "255" },
        { "name", FR_CONF_OFFSET(PW_TYPE_STRING, fr_tls_server_conf_t, session_id_name), NULL },
+       { "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
@@@ -926,7 -971,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
  
@@@ -954,6 -999,9 +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 },
  #endif
  #endif
  
+ #ifdef SSL_OP_NO_TLSv1
+       { "disable_tlsv1", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, disable_tlsv1), NULL },
+ #endif
+ #ifdef SSL_OP_NO_TLSv1_1
        { "disable_tlsv1_1", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, disable_tlsv1_1), NULL },
+ #endif
+ #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
  
        { "cache", FR_CONF_POINTER(PW_TYPE_SUBSECTION, NULL), (void const *) cache_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
  };
  
  
@@@ -1008,14 -1064,18 +1063,18 @@@ static CONF_PARSER tls_client_config[] 
  #endif
  #endif
  
+ #ifdef SSL_OP_NO_TLSv1
+       { "disable_tlsv1", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, disable_tlsv1), NULL },
+ #endif
  #ifdef SSL_OP_NO_TLSv1_1
        { "disable_tlsv1_1", FR_CONF_OFFSET(PW_TYPE_BOOLEAN, fr_tls_server_conf_t, disable_tlsv1_1), NULL },
  #endif
  #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
  };
  
  
@@@ -1030,20 -1090,20 +1089,20 @@@ static int load_dh_params(SSL_CTX *ctx
        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;
        }
  
  /*
   *    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",
  
  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("  SSL: 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;
                }
  
                /* 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;
                }
  
                         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;
                }
  
                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;
                        }
                        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:
        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;
                }
                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;
                        }
                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;
  }
  
  /*
  /* 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
  
        /*
        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
        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);
        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) {
        /* 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;
        }
  
        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;
        }
        } 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;
        }
        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;
        }
  
        /* 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;
        }
  
                goto ocsp_end;
        }
  
        if (bio_out) {
                BIO_puts(bio_out, "\tThis Update: ");
                ASN1_GENERALIZEDTIME_print(bio_out, thisupd);
  
        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: ");
@@@ -1528,20 -1630,22 +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;
        }
  
   *    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)
   */
  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);
        buf[0] = '\0';
        sn = X509_get_serialNumber(client_cert);
  
-       RDEBUG2("TLS Verify adding attributes");
+       RDEBUG2("Creating attributes from certificate OIDs");
        RINDENT();
  
        /*
                        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);
-               rdebug_pair(L_DBG_LVL_2, request, vp, "&request:");
+               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);
        }
  
  
            (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);
-               rdebug_pair(L_DBG_LVL_2, request, vp, "&request:");
+               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);
        }
  
        /*
                          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);
-               rdebug_pair(L_DBG_LVL_2, request, vp, "&request:");
+               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);
        }
  
        X509_NAME_oneline(X509_get_issuer_name(ctx->current_cert), issuer,
                          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);
-               rdebug_pair(L_DBG_LVL_2, request, vp, "&request:");
+               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);
        }
  
        /*
                                  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);
-               rdebug_pair(L_DBG_LVL_2, request, vp, "&request:");
+               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);
        }
  
        /*
                                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, "&request:");
+                                       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, "&request:");
+                                       rdebug_pair(L_DBG_LVL_2, request, vp, NULL);
                                        break;
  #endif        /* GEN_DNS */
  #ifdef GEN_OTHERNAME
                                        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, "&request:");
+                                                   rdebug_pair(L_DBG_LVL_2, request, vp, NULL);
                                                break;
                                            } else {
                                                RWARN("Invalid UPN in Subject Alt Name (should be UTF-8)");
         *      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;
  
                        attribute[16 + len] = '\0';
  
+                       for (p = attribute + 16; *p != '\0'; p++) {
+                               if (*p == ' ') *p = '-';
+                       }
                        X509V3_EXT_print(out, ext, 0, 0);
                        len = BIO_read(out, value , sizeof(value) - 1);
                        if (len <= 0) continue;
  
                        value[len] = '\0';
  
-                       /*
-                        *      Mash the OpenSSL name to our name, and
-                        *      create the attribute.
-                        */
-                       for (p = value + 16; *p != '\0'; p++) {
-                               if (*p == ' ') *p = '-';
+                       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();
                        }
-                       vp = pairmake(talloc_ctx, certs, attribute, value, T_OP_ADD);
-                       rdebug_pair_list(L_DBG_LVL_2, request, vp, NULL);
                }
  
                BIO_free_all(out);
                 */
                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;
                }
  
                        } 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;
                                }
                        }
  
  #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
                        }
                        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");
  
                        }
  
                        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);
  
        } /* 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;
  }
@@@ -2009,8 -2124,8 +2123,8 @@@ static X509_STORE *init_revocation_stor
        /* 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;
                }
  
        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 */
@@@ -2033,13 -2152,13 +2151,13 @@@ static int set_ecdh_curve(SSL_CTX *ctx
  
        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;
        }
  
@@@ -2069,9 -2188,9 +2187,9 @@@ static void sess_free_vps(UNUSED void *
        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,
        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.
@@@ -2158,20 -2277,20 +2276,20 @@@ void tls_global_cleanup(void
        CRYPTO_cleanup_all_ex_data();
  }
  
- /*
-  *    Create SSL context
+ /** Create SSL context
   *
-  *    - Load the trusted CAs
-  *    - Load the Private key & the certificate
-  *    - Set the Context options & Verify options
+  * - Load the trusted CAs
+  * - Load the Private key & the certificate
+  * - Set the Context options & Verify options
   */
  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 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
        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;
                }
        }
                        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;
                        }
                        /* 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
                 *      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;
                }
  
                }
  
        } 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;
        }
  
            (!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;
        }
  
                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;
                }
  
  
                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;
                }
  
                 */
                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;
                }
  
  
        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;
        }
  
  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;
                }
        }
  
        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;
                }
  
                 * 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;
                }
        }
@@@ -2404,15 -2520,29 +2519,29 @@@ post_ca
         *      As of 3.0.5, we always allow TLSv1.1 and TLSv1.2.
         *      Though they can be *globally* disabled if necessary.x
         */
+ #ifdef SSL_OP_NO_TLSv1
+       if (conf->disable_tlsv1) ctx_options |= SSL_OP_NO_TLSv1;
+       ctx_tls_versions |= SSL_OP_NO_TLSv1;
+ #endif
  #ifdef SSL_OP_NO_TLSv1_1
        if (conf->disable_tlsv1_1) ctx_options |= SSL_OP_NO_TLSv1_1;
+       ctx_tls_versions |= SSL_OP_NO_TLSv1_1;
  #endif
  #ifdef SSL_OP_NO_TLSv1_2
        if (conf->disable_tlsv1_2) ctx_options |= SSL_OP_NO_TLSv1_2;
+       ctx_tls_versions |= SSL_OP_NO_TLSv1_2;
  #endif
  
+       if ((ctx_options & ctx_tls_versions) == ctx_tls_versions) {
+               ERROR(LOG_PREFIX ": You have disabled all available TLS versions.  EAP will not work");
+               return NULL;
+       }
  #ifdef SSL_OP_NO_TICKET
-       ctx_options |= SSL_OP_NO_TICKET ;
+       ctx_options |= SSL_OP_NO_TICKET;
  #endif
  
        /*
         *      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)
        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
  
        /* 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;
                }
        }
         */
        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;
                }
        }
                 *      Create a unique context Id per EAP-TLS configuration.
                 */
                if (conf->session_id_name) {
-                       snprintf(conf->session_context_id,
-                                sizeof(conf->session_context_id),
-                                "FR eap %s",
-                                conf->session_id_name);
+                       snprintf(conf->session_context_id, sizeof(conf->session_context_id),
+                                "FR eap %s", conf->session_id_name);
                } else {
-                       snprintf(conf->session_context_id,
-                                sizeof(conf->session_context_id),
+                       snprintf(conf->session_context_id, sizeof(conf->session_context_id),
                                 "FR eap %p", conf);
                }
  
@@@ -2597,7 -2734,7 +2733,7 @@@ static fr_tls_server_conf_t *tls_server
  
        conf = talloc_zero(ctx, fr_tls_server_conf_t);
        if (!conf) {
-               ERROR("Out of memory");
+               ERROR(LOG_PREFIX ": Out of memory");
                return NULL;
        }
  
@@@ -2616,7 -2753,7 +2752,7 @@@ fr_tls_server_conf_t *tls_server_conf_p
         */
        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;
        }
  
        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;
        }
  
  
        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;
        }
  
@@@ -2695,7 -2833,7 +2832,7 @@@ fr_tls_server_conf_t *tls_client_conf_p
  
        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;
        }
  
@@@ -2755,7 -2893,7 +2892,7 @@@ int tls_success(tls_session_t *ssn, REQ
         *      user.
         */
        if ((!ssn->allow_session_resumption) ||
-           (((vp = pairfind(request->config_items, 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);
                 *      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;
                }
        /*
         *      Else resumption IS allowed, so we store the
         *      user data in the cache.
  
                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);
  
                         *      @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.
+                        */
+                       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\t");
+                                               /*
+                                                *      Write this one.
+                                                */
                                                vp_prints(buf, sizeof(buf), vp);
-                                               fprintf(vp_file, "\t%s,\n", buf);
+                                               fputs(buf, vp_file);
+                                               prev = vp;
                                        }
+                                       /*
+                                        *      Terminate the final line.
+                                        */
+                                       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);
  
                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;
@@@ -2912,11 -3056,11 +3055,11 @@@ 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;
+       VALUE_PAIR **certs;
  
        /*
         *      Decrypt the complete record.
                        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;
        }
  
         */
        ssn->clean_out.used = err;
  
+       /*
+        *      Add the certificates to intermediate packets, so that
+        *      the inner tunnel policies can use them.
+        */
+       certs = (VALUE_PAIR **)SSL_get_ex_data(ssn->ssl, fr_tls_ex_index_certs);
+       if (certs) fr_pair_add(&request->packet->vps, fr_pair_list_copy(request->packet, *certs));
        return FR_TLS_OK;
  }
  
   */
  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
                        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;
  
                /*
                 *      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 */
  
diff --combined src/main/tls_listen.c
@@@ -54,7 -54,7 +54,7 @@@ static void dump_hex(char const *msg, u
  {
        size_t i;
  
-       if (debug_flag < 3) return;
+       if (rad_debug_lvl < 3) return;
  
        printf("%s %d\n", msg, (int) data_len);
        if (data_len > 256) data_len = 256;
@@@ -139,13 -139,11 +139,11 @@@ static int tls_socket_recv(rad_listen_
                sock->packet->dst_ipaddr = sock->my_ipaddr;
                sock->packet->dst_port = sock->my_port;
  
-               if (sock->request) {
-                       sock->request->packet = talloc_steal(sock->request, sock->packet);
-               }
+               if (sock->request) sock->request->packet = talloc_steal(sock->request, sock->packet);
        }
  
        /*
-        *      Allocate a REQUEST for debugging.
+        *      Allocate a REQUEST for debugging, and initialize the TLS session.
         */
        if (!sock->request) {
                sock->request = request = request_alloc(sock);
                request->component = "<core>";
                request->component = "<tls-connect>";
  
-               /*
-                *      Not sure if we should do this on every packet...
-                */
                request->reply = rad_alloc(request, false);
                if (!request->reply) return 0;
  
                }
  
                SSL_set_ex_data(sock->ssn->ssl, FR_TLS_EX_INDEX_REQUEST, (void *)request);
-               SSL_set_ex_data(sock->ssn->ssl, fr_tls_ex_index_certs, (void *)&request->packet->vps);
+               SSL_set_ex_data(sock->ssn->ssl, fr_tls_ex_index_certs, (void *) &sock->certs);
                SSL_set_ex_data(sock->ssn->ssl, FR_TLS_EX_INDEX_TALLOC, sock->parent);
  
                doing_init = true;
        }
  
        /*
-        *      Skip ahead to reading application data.
+        *      If we need to do more initialization, do that here.
         */
-       if (SSL_is_init_finished(sock->ssn->ssl)) goto app;
+       if (!SSL_is_init_finished(sock->ssn->ssl)) {
+               if (!tls_handshake_recv(request, sock->ssn)) {
+                       RDEBUG("FAILED in TLS handshake receive");
+                       goto do_close;
+               }
  
-       if (!tls_handshake_recv(request, sock->ssn)) {
-               RDEBUG("FAILED in TLS handshake receive");
-               goto do_close;
-       }
+               /*
+                *      More ACK data to send.  Do so.
+                */
+               if (sock->ssn->dirty_out.used > 0) {
+                       tls_socket_write(listener, request);
+                       PTHREAD_MUTEX_UNLOCK(&sock->mutex);
+                       return 0;
+               }
  
-       if (sock->ssn->dirty_out.used > 0) {
-               tls_socket_write(listener, request);
-               PTHREAD_MUTEX_UNLOCK(&sock->mutex);
-               return 0;
+               /*
+                *      FIXME: Run the request through a virtual
+                *      server in order to see if we like the
+                *      certificate presented by the client.
+                */
        }
  
- app:
        /*
-        *      FIXME: Run the packet through a virtual server in
-        *      order to see if we like the certificate presented by
-        *      the client.
+        *      Try to get application data.
         */
        status = tls_application_data(sock->ssn, request);
        RDEBUG("Application data status %d", status);
  
                return 0;
        }
  
+       /*
+        *      We now have a bunch of application data.
+        */
        dump_hex("TUNNELED DATA > ", sock->ssn->clean_out.data, sock->ssn->clean_out.used);
  
        /*
         */
        if ((sock->ssn->clean_out.used < 20) ||
            (((sock->ssn->clean_out.data[2] << 8) | sock->ssn->clean_out.data[3]) != (int) sock->ssn->clean_out.used)) {
-               RDEBUG("Received bad packet: Length %d contents %d",
+               RDEBUG("Received bad packet: Length %zd contents %d",
                       sock->ssn->clean_out.used,
                       (sock->ssn->clean_out.data[2] << 8) | sock->ssn->clean_out.data[3]);
                goto do_close;
        PTHREAD_MUTEX_UNLOCK(&sock->mutex);
  
        if (!rad_packet_ok(packet, 0, NULL)) {
-               RDEBUG("Received bad packet: %s", fr_strerror());
+               if (DEBUG_ENABLED) ERROR("Receive - %s", fr_strerror());
                DEBUG("Closing TLS socket from client");
                PTHREAD_MUTEX_LOCK(&sock->mutex);
                tls_socket_close(listener);
        /*
         *      Copied from src/lib/radius.c, rad_recv();
         */
-       if (fr_debug_flag) {
+       if (fr_debug_lvl) {
                char host_ipaddr[128];
  
                if (is_radius_code(packet->code)) {
  
        FR_STATS_INC(auth, total_requests);
  
 +      /*
 +       *      Re-parent the packet to nothing.
 +       */
 +      (void) talloc_steal(NULL, packet);
 +
        return 1;
  }
  
@@@ -345,7 -343,8 +348,8 @@@ int dual_tls_recv(rad_listen_t *listene
        rad_assert(sock->ssn != NULL);
        rad_assert(client != NULL);
  
-       packet = sock->packet;
+       packet = talloc_steal(NULL, sock->packet);
+       sock->packet = NULL;
  
        /*
         *      Some sanity checks, based on the packet code.
                if (!main_config.status_server) {
                        FR_STATS_INC(auth, total_unknown_types);
                        WARN("Ignoring Status-Server request due to security configuration");
-                       rad_free(&sock->packet);
+                       rad_free(&packet);
                        return 0;
                }
                fun = rad_status_server;
  
                DEBUG("Invalid packet code %d sent from client %s port %d : IGNORED",
                      packet->code, client->shortname, packet->src_port);
-               rad_free(&sock->packet);
+               rad_free(&packet);
                return 0;
        } /* switch over packet types */
  
        if (!request_receive(NULL, listener, packet, client, fun)) {
                FR_STATS_INC(auth, total_packets_dropped);
-               rad_free(&sock->packet);
+               rad_free(&packet);
                return 0;
        }
  
-       sock->packet = NULL;    /* we have no need for more partial reads */
        return 1;
  }
  
@@@ -502,7 -499,7 +504,7 @@@ static ssize_t proxy_tls_read(rad_liste
         *      Get the maximum size of data to receive.
         */
        if (!sock->data) sock->data = talloc_array(sock, uint8_t,
-                                                  sock->ssn->offset);
+                                                  sock->ssn->mtu);
  
        data = sock->data;
  
                 *      FIXME: allocate a RADIUS_PACKET, and set
                 *      "data" to be as large as necessary.
                 */
-               if (length > sock->ssn->offset) {
+               if (length > sock->ssn->mtu) {
                        INFO("Received packet will be too large! Set \"fragment_size = %u\"",
                             (data[2] << 8) | data[3]);
                        goto do_close;
@@@ -55,24 -55,32 +55,32 @@@ typedef struct rlm_sql_sqlite_conn 
  } rlm_sql_sqlite_conn_t;
  
  typedef struct rlm_sql_sqlite_config {
-       char const *filename;
+       char const      *filename;
+       uint32_t        busy_timeout;
  } rlm_sql_sqlite_config_t;
  
  static const CONF_PARSER driver_config[] = {
        { "filename", FR_CONF_OFFSET(PW_TYPE_FILE_OUTPUT | PW_TYPE_REQUIRED, rlm_sql_sqlite_config_t, filename), NULL },
-       {NULL, -1, 0, NULL, NULL}
+       { "busy_timeout", FR_CONF_OFFSET(PW_TYPE_INTEGER, rlm_sql_sqlite_config_t, busy_timeout), "200" },
+       CONF_PARSER_TERMINATOR
  };
  
- static sql_rcode_t sql_check_error(sqlite3 *db)
+ /** Convert an sqlite status code to an sql_rcode_t
+  *
+  * @param status to convert.
+  * @return
+  *    - RLM_SQL_OK - If no errors found.
+  *    - RLM_SQL_ERROR - If a known, non-fatal, error occurred.
+  *    - RLM_SQL_ALT_QUERY - If a constraints violation occurred.
+  *    - RLM_SQL_RECONNECT - Anything else, we assume the connection can no longer be used.
+  */
+ static sql_rcode_t sql_error_to_rcode(int status)
  {
-       int error = sqlite3_errcode(db);
        /*
         *      Lowest byte is error category, other byte may contain
         *      the extended error, depending on version.
         */
-       switch (error & 0xff) {
+       switch (status & 0xff) {
        /*
         *      Not errors
         */
         *      Errors with the handle, that probably require reinitialisation
         */
        default:
-               ERROR("rlm_sql_sqlite: Handle is unusable, error (%d): %s", error, sqlite3_errmsg(db));
                return RLM_SQL_RECONNECT;
        }
  }
  
+ /** Determine if an error occurred, and what type of error it was
+  *
+  * @param db handle to extract error from (may be NULL).
+  * @param status to check (if unused, set to SQLITE_OK).
+  * @return
+  *    - RLM_SQL_OK - If no errors found.
+  *    - RLM_SQL_ERROR - If a known, non-fatal, error occurred.
+  *    - RLM_SQL_ALT_QUERY - If a constraints violation occurred.
+  *    - RLM_SQL_RECONNECT - Anything else. We assume the connection can no longer be used.
+  */
+ static sql_rcode_t sql_check_error(sqlite3 *db, int status)
+ {
+       int hstatus = SQLITE_OK;
+       if (db) {
+               hstatus = sqlite3_errcode(db);
+               switch (hstatus & 0xff) {
+               case SQLITE_OK:
+               case SQLITE_DONE:
+               case SQLITE_ROW:
+                       hstatus = SQLITE_OK;
+                       break;
+               default:
+                       break;
+               }
+       }
+       switch (status & 0xff) {
+       case SQLITE_OK:
+       case SQLITE_DONE:
+       case SQLITE_ROW:
+               status = SQLITE_OK;
+               break;
+       default:
+               break;
+       }
+       if (status != SQLITE_OK) return sql_error_to_rcode(status);
+       if (hstatus != SQLITE_OK) return sql_error_to_rcode(status);
+       return RLM_SQL_OK;
+ }
+ /** Print an error to the global debug log
+  *
+  * If status does not indicate success, write an error to the global error log.
+  *
+  * @note The error code will be appended to the fmt string in the format ": code 0x<hex> (<int>)[: <string>]".
+  *
+  * @param db handle to extract error from (may be NULL).
+  * @param status to check (if unused, set to SQLITE_OK).
+  * @param fmt to preprend.
+  * @param ... arguments to fmt.
+  */
+ static void sql_print_error(sqlite3 *db, int status, char const *fmt, ...)
+       CC_HINT(format (printf, 3, 4)) CC_HINT(nonnull (3));
+ static void sql_print_error(sqlite3 *db, int status, char const *fmt, ...)
+ {
+       va_list ap;
+       char *p;
+       int hstatus = SQLITE_OK;
+       if (db) {
+               hstatus = sqlite3_errcode(db);
+               switch (hstatus & 0xff) {
+               case SQLITE_OK:
+               case SQLITE_DONE:
+               case SQLITE_ROW:
+                       hstatus = SQLITE_OK;
+                       break;
+               default:
+                       break;
+               }
+       }
+       switch (status & 0xff) {
+       case SQLITE_OK:
+       case SQLITE_DONE:
+       case SQLITE_ROW:
+               status = SQLITE_OK;
+               break;
+       default:
+               break;
+       }
+       /*
+        *      No errors!
+        */
+       if ((hstatus == SQLITE_OK) && (status == SQLITE_OK)) return;
+       /*
+        *      At least one error...
+        */
+       va_start(ap, fmt);
+       MEM(p = talloc_vasprintf(NULL, fmt, ap));
+       va_end(ap);
+       /*
+        *      Disagreement between handle, and function return code,
+        *      print them both.
+        */
+       if ((status != SQLITE_OK) && (status != hstatus)) {
+ #ifdef HAVE_SQLITE3_ERRSTR
+               ERROR("rlm_sql_sqlite: %s: Code 0x%04x (%i): %s", p, status, status, sqlite3_errstr(status));
+ #else
+               ERROR("rlm_sql_sqlite: %s: Code 0x%04x (%i)", p, status, status);
+ #endif
+       }
+       if (hstatus != SQLITE_OK) ERROR("rlm_sql_sqlite: %s: Code 0x%04x (%i): %s",
+                                       p, hstatus, hstatus, sqlite3_errmsg(db));
+ }
  #ifdef HAVE_SQLITE3_OPEN_V2
  static int sql_loadfile(TALLOC_CTX *ctx, sqlite3 *db, char const *filename)
  {
-       ssize_t len;
-       char *buffer;
-       char *p, *q, *s;
-       int cl;
-       FILE *f;
-       struct stat finfo;
+       ssize_t         len;
+       int             statement_cnt = 0;
+       char            *buffer;
+       char            *p, *q, *s;
+       int             cl;
+       FILE            *f;
+       struct stat     finfo;
  
        int status;
        sqlite3_stmt *statement;
                        if ((*p != 0x0a) && (*p != 0x0d) && (*p != '\t')) break;
                        cl = 1;
                } else {
-                       cl = fr_utf8_char((uint8_t *) p);
+                       cl = fr_utf8_char((uint8_t *) p, -1);
                        if (!cl) break;
                }
        }
        while ((q = strchr(p, ';'))) {
                if (q[1] != '\n') {
                        p = q + 1;
+                       statement_cnt++;
                        continue;
                }
  
                *q = '\0';
  
  #ifdef HAVE_SQLITE3_PREPARE_V2
-               (void) sqlite3_prepare_v2(db, s, len, &statement, &z_tail);
+               status = sqlite3_prepare_v2(db, s, len, &statement, &z_tail);
  #else
-               (void) sqlite3_prepare(db, s, len, &>statement, &z_tail);
+               status = sqlite3_prepare(db, s, len, &statement, &z_tail);
  #endif
-               if (sql_check_error(db) != RLM_SQL_OK) {
+               if (sql_check_error(db, status) != RLM_SQL_OK) {
+                       sql_print_error(db, status, "Failed preparing statement %i", statement_cnt);
                        talloc_free(buffer);
                        return -1;
                }
  
-               (void) sqlite3_step(statement);
-               status = sql_check_error(db);
+               status = sqlite3_step(statement);
+               if (sql_check_error(db, status) != RLM_SQL_OK) {
+                       sql_print_error(db, status, "Failed executing statement %i", statement_cnt);
+                       sqlite3_finalize(statement);
+                       talloc_free(buffer);
+                       return -1;
+               }
  
-               (void) sqlite3_finalize(statement);
-               if ((status != RLM_SQL_OK) || sql_check_error(db)) {
+               status = sqlite3_finalize(statement);
+               if (sql_check_error(db, status) != RLM_SQL_OK) {
+                       sql_print_error(db, status, "Failed finalizing statement %i", statement_cnt);
                        talloc_free(buffer);
                        return -1;
                }
  
+               statement_cnt++;
                p = s = q + 1;
        }
  
@@@ -269,12 -404,12 +404,12 @@@ static int mod_instantiate(CONF_SECTIO
  
        if (cf_pair_find(conf, "bootstrap") && !exists) {
  #  ifdef HAVE_SQLITE3_OPEN_V2
-               int status;
-               int ret;
-               char const *p;
-               char *buff;
-               sqlite3 *db = NULL;
-               CONF_PAIR *cp;
+               int             status;
+               int             ret;
+               char const      *p;
+               char            *buff;
+               sqlite3         *db = NULL;
+               CONF_PAIR       *cp;
  
                INFO("rlm_sql_sqlite: Database doesn't exist, creating it and loading schema");
  
                        goto unlink;
                }
  
-               if (sql_check_error(db) != RLM_SQL_OK) {
+               if (sql_check_error(db, status) != RLM_SQL_OK) {
                        (void) sqlite3_close(db);
  
                        goto unlink;
@@@ -367,9 -502,7 +502,7 @@@ static int _sql_socket_destructor(rlm_s
  
        if (conn->db) {
                status = sqlite3_close(conn->db);
-               if (status != SQLITE_OK) {
-                       WARN("rlm_sql_sqlite: Got SQLite error code (%u) when closing socket", status);
-               }
+               if (status != SQLITE_OK) WARN("rlm_sql_sqlite: Got SQLite error code (%u) when closing socket", status);
        }
  
        return 0;
@@@ -403,31 -536,30 +536,32 @@@ static sql_rcode_t sql_socket_init(rlm_
        INFO("rlm_sql_sqlite: Opening SQLite database \"%s\"", driver->filename);
  #ifdef HAVE_SQLITE3_OPEN_V2
        status = sqlite3_open_v2(driver->filename, &(conn->db), SQLITE_OPEN_READWRITE | SQLITE_OPEN_NOMUTEX, NULL);
 +      sqlite3_busy_timeout( conn->db, 200); /*wait up to 200 ms for db locks*/
  #else
 +      
        status = sqlite3_open(driver->filename, &(conn->db));
  #endif
-       if (!conn->db) {
- #ifdef HAVE_SQLITE3_ERRSTR
-               ERROR("rlm_sql_sqlite: Failed creating opening/creating SQLite: %s", sqlite3_errstr(status));
- #else
-               ERROR("rlm_sql_sqlite: Failed creating opening/creating SQLite database error code (%i)",
-                     status);
- #endif
  
+       if (!conn->db || (sql_check_error(conn->db, status) != RLM_SQL_OK)) {
+               sql_print_error(conn->db, status, "Error opening SQLite database \"%s\"", driver->filename);
+               return RLM_SQL_ERROR;
+       }
+       status = sqlite3_busy_timeout(conn->db, driver->busy_timeout);
+       if (sql_check_error(conn->db, status) != RLM_SQL_OK) {
+               sql_print_error(conn->db, status, "Error setting busy timeout");
                return RLM_SQL_ERROR;
        }
-       if (sql_check_error(conn->db) != RLM_SQL_OK) return RLM_SQL_ERROR;
  
        /*
         *      Enable extended return codes for extra debugging info.
         */
  #ifdef HAVE_SQLITE3_EXTENDED_RESULT_CODES
-       (void) sqlite3_extended_result_codes(conn->db, 1);
+       status = sqlite3_extended_result_codes(conn->db, 1);
+       if (sql_check_error(conn->db, status) != RLM_SQL_OK) {
+               sql_print_error(conn->db, status, "Error enabling extended result codes");
+               return RLM_SQL_ERROR;
+       }
  #endif
-       if (sql_check_error(conn->db) != RLM_SQL_OK) return RLM_SQL_ERROR;
  
  #ifdef HAVE_SQLITE3_CREATE_FUNCTION_V2
        status = sqlite3_create_function_v2(conn->db, "GREATEST", -1, SQLITE_ANY, NULL,
        status = sqlite3_create_function(conn->db, "GREATEST", -1, SQLITE_ANY, NULL,
                                         _sql_greatest, NULL, NULL);
  #endif
-       if (status != SQLITE_OK) {
-               ERROR("rlm_sql_sqlite: Failed registering 'GREATEST' sql function: %s", sqlite3_errmsg(conn->db));
+       if (sql_check_error(conn->db, status) != RLM_SQL_OK) {
+               sql_print_error(conn->db, status, "Failed registering 'GREATEST' sql function");
+               return RLM_SQL_ERROR;
        }
  
        return RLM_SQL_OK;
  
  static sql_rcode_t sql_select_query(rlm_sql_handle_t *handle, UNUSED rlm_sql_config_t *config, char const *query)
  {
-       rlm_sql_sqlite_conn_t *conn = handle->conn;
-       char const *z_tail;
+       rlm_sql_sqlite_conn_t   *conn = handle->conn;
+       char const              *z_tail;
+       int                     status;
  
  #ifdef HAVE_SQLITE3_PREPARE_V2
-       (void) sqlite3_prepare_v2(conn->db, query, strlen(query), &conn->statement, &z_tail);
+       status = sqlite3_prepare_v2(conn->db, query, strlen(query), &conn->statement, &z_tail);
  #else
-       (void) sqlite3_prepare(conn->db, query, strlen(query), &conn->statement, &z_tail);
+       status = sqlite3_prepare(conn->db, query, strlen(query), &conn->statement, &z_tail);
  #endif
  
        conn->col_count = 0;
  
-       return sql_check_error(conn->db);
+       return sql_check_error(conn->db, status);
  }
  
  
  static sql_rcode_t sql_query(rlm_sql_handle_t *handle, UNUSED rlm_sql_config_t *config, char const *query)
  {
-       int status;
-       rlm_sql_sqlite_conn_t *conn = handle->conn;
-       char const *z_tail;
+       sql_rcode_t             rcode;
+       rlm_sql_sqlite_conn_t   *conn = handle->conn;
+       char const              *z_tail;
+       int                     status;
  
  #ifdef HAVE_SQLITE3_PREPARE_V2
        status = sqlite3_prepare_v2(conn->db, query, strlen(query), &conn->statement, &z_tail);
  #else
        status = sqlite3_prepare(conn->db, query, strlen(query), &conn->statement, &z_tail);
  #endif
-       if (status != SQLITE_OK) return sql_check_error(conn->db);
-       (void) sqlite3_step(conn->statement);
+       rcode = sql_check_error(conn->db, status);
+       if (rcode != RLM_SQL_OK) return rcode;
  
-       return sql_check_error(conn->db);
- }
- static sql_rcode_t sql_store_result(UNUSED rlm_sql_handle_t *handle, UNUSED rlm_sql_config_t *config)
- {
-       return 0;
+       status = sqlite3_step(conn->statement);
+       return sql_check_error(conn->db, status);
  }
  
- static int sql_num_fields(rlm_sql_handle_t * handle, UNUSED rlm_sql_config_t *config)
+ static int sql_num_fields(rlm_sql_handle_t *handle, UNUSED rlm_sql_config_t *config)
  {
        rlm_sql_sqlite_conn_t *conn = handle->conn;
  
@@@ -505,6 -636,24 +638,24 @@@ static int sql_num_rows(rlm_sql_handle_
        return 0;
  }
  
+ static sql_rcode_t sql_fields(char const **out[], rlm_sql_handle_t *handle, UNUSED rlm_sql_config_t *config)
+ {
+       rlm_sql_sqlite_conn_t *conn = handle->conn;
+       int             fields, i;
+       char const      **names;
+       fields = sqlite3_column_count(conn->statement);
+       if (fields <= 0) return RLM_SQL_ERROR;
+       MEM(names = talloc_zero_array(handle, char const *, fields + 1));
+       for (i = 0; i < fields; i++) names[i] = sqlite3_column_name(conn->statement, i);
+       *out = names;
+       return RLM_SQL_OK;
+ }
  static sql_rcode_t sql_fetch_row(rlm_sql_handle_t *handle, rlm_sql_config_t *config)
  {
        int status;
        /*
         *      Error getting next row
         */
-       if (sql_check_error(conn->db) != RLM_SQL_OK) return RLM_SQL_ERROR;
+       if (sql_check_error(conn->db, status) != RLM_SQL_OK) return RLM_SQL_ERROR;
  
        /*
         *      No more rows to process (were done)
                        break;
  
                case SQLITE_TEXT:
-                       {
-                               char const *p;
-                               p = (char const *) sqlite3_column_text(conn->statement, i);
+               {
+                       char const *p;
+                       p = (char const *) sqlite3_column_text(conn->statement, i);
  
-                               if (p) {
-                                       MEM(row[i] = talloc_typed_strdup(row, p));
-                               }
-                       }
+                       if (p) MEM(row[i] = talloc_typed_strdup(row, p));
+               }
                        break;
  
                case SQLITE_BLOB:
-                       {
-                               uint8_t const *p;
-                               size_t len;
+               {
+                       uint8_t const *p;
+                       size_t len;
  
-                               p = sqlite3_column_blob(conn->statement, i);
-                               if (p) {
-                                       len = sqlite3_column_bytes(conn->statement, i);
+                       p = sqlite3_column_blob(conn->statement, i);
+                       if (p) {
+                               len = sqlite3_column_bytes(conn->statement, i);
  
-                                       MEM(row[i] = talloc_zero_array(row, char, len + 1));
-                                       memcpy(row[i], p, len);
-                               }
+                               MEM(row[i] = talloc_zero_array(row, char, len + 1));
+                               memcpy(row[i], p, len);
                        }
+               }
                        break;
  
                default:
        return 0;
  }
  
- static sql_rcode_t sql_free_result(rlm_sql_handle_t *handle,
-                          UNUSED rlm_sql_config_t *config)
+ static sql_rcode_t sql_free_result(rlm_sql_handle_t *handle, UNUSED rlm_sql_config_t *config)
  {
        rlm_sql_sqlite_conn_t *conn = handle->conn;
  
@@@ -669,11 -815,11 +817,11 @@@ rlm_sql_module_t rlm_sql_sqlite = 
        .sql_socket_init                = sql_socket_init,
        .sql_query                      = sql_query,
        .sql_select_query               = sql_select_query,
-       .sql_store_result               = sql_store_result,
        .sql_num_fields                 = sql_num_fields,
        .sql_num_rows                   = sql_num_rows,
        .sql_affected_rows              = sql_affected_rows,
        .sql_fetch_row                  = sql_fetch_row,
+       .sql_fields                     = sql_fields,
        .sql_free_result                = sql_free_result,
        .sql_error                      = sql_error,
        .sql_finish_query               = sql_finish_query,