log.c

Go to the documentation of this file.

/*
 *   This program is free software; you can redistribute it and/or modify
 *   it under the terms of the GNU General Public License as published by
 *   the Free Software Foundation; either version 2 of the License, or
 *   (at your option) any later version.
 *
 *   This program is distributed in the hope that it will be useful,
 *   but WITHOUT ANY WARRANTY; without even the implied warranty of
 *   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 *   GNU General Public License for more details.
 *
 *   You should have received a copy of the GNU General Public License
 *   along with this program; if not, write to the Free Software
 *   Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301, USA
 */
 
/**
 * $Id: b4d40b2750dfdea3cf3a112fd62e696586dd63d1 $
 *
 * @file tls/log.c
 * @brief Retrieve errors and log messages from OpenSSL's overly complex logging system.
 *
 * @copyright 2016,2021 Arran Cudbard-Bell (a.cudbardb@freeradius.org)
 * @copyright 2016 The FreeRADIUS server project
 */
RCSID("$Id: b4d40b2750dfdea3cf3a112fd62e696586dd63d1 $")
USES_APPLE_DEPRECATED_API       /* OpenSSL API has been deprecated by Apple */
 
#ifdef WITH_TLS
#define LOG_PREFIX "tls"
 
#include <freeradius-devel/util/debug.h>
#include <freeradius-devel/util/atexit.h>
#include <freeradius-devel/tls/strerror.h>
#include <freeradius-devel/tls/utils.h>
 
#include "log.h"
 
/** Holds the state of a log BIO
 *
 * Most of these fields are expected to change between uses of the BIO.
 *
 * BIOs do not have indexed extension structures like other structures in OpenSSL,
 * so we're forced to place all information in a structure, and populate it just
 * prior to a BIO being used.
 *
 * These BIOs are thread local to avoid conflicts or locking issues.
 */
typedef struct {
        BIO                     *bio;           //!< Logging bio to write to.
        fr_sbuff_t              sbuff;          //!< Used to aggregate line data.
        fr_sbuff_uctx_talloc_t  tctx;           //!< extra talloc information for the sbuff.
        fr_sbuff_marker_t       logged_m;       //!< How much data has been written.
 
        request_t               *request;       //!< the current request.  Only used for the
                                                ///< request log BIOs.
        fr_log_type_t           type;           //!< The type of log messages the bio will produce.
        fr_log_lvl_t            lvl;            //!< Level to log message at.
        char const              *file;          //!< File this log bio was bound on.
        int                     line;           //!< Line this log bio was bound on.
} fr_tls_log_bio_t;
 
/** Template for the thread local request log BIOs
 */
static BIO_METHOD       *tls_request_log_meth;
 
/** Template for the global log BIOs
 */
static BIO_METHOD       *tls_global_log_meth;
 
/** Counter for users of the request log bio
 *
 */
static _Atomic(uint32_t) tls_request_log_ref;
 
/** Counter for users of the global log bio
 *
 */
static _Atomic(uint32_t) tls_global_log_ref;
 
/** Thread local request log BIO
 */
static _Thread_local    fr_tls_log_bio_t        *request_log_bio;
 
/** Thread local global log BIO
 */
static _Thread_local    fr_tls_log_bio_t        *global_log_bio;
 
/** Print out the current stack of certs
 *
 * @param[in] file      File where this function is being called.
 * @param[in] line      Line where this function is being called.
 * @param[in] request   Current request, may be NULL.
 * @param[in] log_type  The type of log message to produce L_INFO, L_ERR, L_DBG etc...
 * @param[in] chain     The certificate chain.
 * @param[in] cert      The leaf certificate.
 */
void _fr_tls_chain_log(char const *file, int line,
                       request_t *request, fr_log_type_t log_type,
                       STACK_OF(X509) *chain, X509 *cert)
{
        /*
         *      Dump to the thread local buffer
         */
        fr_strerror_clear();
        _fr_tls_strerror_push_chain(file, line, chain, cert);
        if (request) {
                log_request_perror(log_type, L_DBG_LVL_OFF, request, file, line, NULL);
        } else {
                fr_perror(NULL);
        }
}
 
/** Print out the current stack of certs
 *
 * @param[in] file      File where this function is being called.
 * @param[in] line      Line where this function is being called.
 * @param[in] request   Current request, may be NULL.
 * @param[in] log_type  The type of log message to produce L_INFO, L_ERR, L_DBG etc...
 * @param[in] chain     The certificate chain.
 * @param[in] cert      The leaf certificate.
 * @param[in] marker    The certificate we want to mark.
 */
void _fr_tls_chain_marker_log(char const *file, int line,
                              request_t *request, fr_log_type_t log_type,
                              STACK_OF(X509) *chain, X509 *cert, X509 *marker)
{
        /*
         *      Dump to the thread local buffer
         */
        fr_strerror_clear();
        _fr_tls_strerror_push_chain_marker(file, line, chain, cert, marker);
        if (request) {
                log_request_perror(log_type, L_DBG_LVL_OFF, request, file, line, NULL);
        } else {
                fr_perror(NULL);
        }
}
 
/** Print out the current stack of X509 objects (certificates only)
 *
 * @param[in] file              File where this function is being called.
 * @param[in] line              Line where this function is being called.
 * @param[in] request           Current request, may be NULL.
 * @param[in] log_type          The type of log message to produce L_INFO, L_ERR, L_DBG etc...
 * @param[in] objects           A stack of X509 objects
 */
void _fr_tls_x509_objects_log(char const *file, int line,
                              request_t *request, fr_log_type_t log_type,
                              STACK_OF(X509_OBJECT) *objects)
{
 
        fr_strerror_clear();
        _fr_tls_strerror_push_x509_objects(file, line, objects);
        if (request) {
                log_request_perror(log_type, L_DBG_LVL_OFF, request, file, line, NULL);
        } else {
                fr_perror(NULL);
        }
}
 
/** Print errors raised by OpenSSL I/O functions
 *
 * Drains the thread local OpenSSL error queue, and prints out errors
 * based on the SSL handle and the return code of the I/O  function.
 *
 * OpenSSL lists I/O functions to be:
 *   - SSL_connect
 *   - SSL_accept
 *   - SSL_do_handshake
 *   - SSL_read
 *   - SSL_peek
 *   - SSL_write
 *
 * @param request       The current request (may be NULL).
 * @param err           returned from SSL_get_error().
 * @param fmt           Error message describing the operation being attempted.
 * @param ...           Arguments for msg.
 * @return
 *      - 0 TLS session may still be viable.
 *      - -1 TLS session cannot continue.
 */
int fr_tls_log_io_error(request_t *request, int err, char const *fmt, ...)
{
        static fr_table_num_ordered_t const ssl_io_error_table[] = {
                { L("SSL_ERROR_NONE"),                  SSL_ERROR_NONE                  },
                { L("SSL_ERROR_ZERO_RETURN"),           SSL_ERROR_ZERO_RETURN           },
                { L("SSL_ERROR_WANT_READ"),             SSL_ERROR_WANT_READ             },
                { L("SSL_ERROR_WANT_WRITE"),            SSL_ERROR_WANT_WRITE            },
                { L("SSL_ERROR_WANT_CONNECT"),          SSL_ERROR_WANT_CONNECT          },
                { L("SSL_ERROR_WANT_ACCEPT"),           SSL_ERROR_WANT_ACCEPT           },
                { L("SSL_ERROR_WANT_X509_LOOKUP"),      SSL_ERROR_WANT_X509_LOOKUP      },
                { L("SSL_ERROR_WANT_ASYNC"),            SSL_ERROR_WANT_ASYNC            },
                { L("SSL_ERROR_WANT_ASYNC_JOB"),        SSL_ERROR_WANT_ASYNC_JOB        },
                { L("SSL_ERROR_WANT_CLIENT_HELLO_CB"),  SSL_ERROR_WANT_CLIENT_HELLO_CB  },
                { L("SSL_ERROR_SYSCALL"),               SSL_ERROR_SYSCALL               },
                { L("SSL_ERROR_SSL"),                   SSL_ERROR_SSL                   }
        };
        static size_t ssl_io_error_table_len = NUM_ELEMENTS(ssl_io_error_table);
 
        va_list ap;
        char *msg = NULL;
 
        switch (err) {
        /*
         *      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_WANT_X509_LOOKUP:
        case SSL_ERROR_ZERO_RETURN:
                if (DEBUG_ENABLED2 || RDEBUG_ENABLED2) {
                        va_start(ap, fmt);
                        msg = fr_vasprintf(NULL, fmt, ap);
                        va_end(ap);
 
                        ROPTIONAL(RDEBUG2, DEBUG2, "%s - %s (%i)",
                                  msg, fr_table_str_by_value(ssl_io_error_table, err, "<UNKNOWN>"), err);
                        talloc_free(msg);
                }
                break;
 
        /*
         *      These seem to be indications of a genuine
         *      error that should result in the SSL tunnel
         *      being regarded as "dead".
         */
        case SSL_ERROR_SYSCALL:
                va_start(ap, fmt);
                msg = fr_vasprintf(NULL, fmt, ap);
                va_end(ap);
 
                ROPTIONAL(REDEBUG, ERROR, "%s - System call (I/O) error - %s (%i)",
                          msg, fr_table_str_by_value(ssl_io_error_table, err, "<UNKNOWN>"), err);
 
                talloc_free(msg);
                return -1;
 
        /*
         *      Docs say a more verbose error is available
         *      in the normal error stack.
         */
        case SSL_ERROR_SSL:
                va_start(ap, fmt);
                (void)fr_tls_strerror_vprintf(fmt, ap);
                va_end(ap);
 
                ROPTIONAL(RPERROR, PERROR, " ");
                return -1;
 
        /*
         *      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:
                va_start(ap, fmt);
                msg = fr_vasprintf(NULL, fmt, ap);
                va_end(ap);
 
                ROPTIONAL(REDEBUG, ERROR, "%s - TLS session error - %s (%i)",
                          msg, fr_table_str_by_value(ssl_io_error_table, err, "<UNKNOWN>"), err);
 
                talloc_free(msg);
 
                return -1;
        }
 
        return 0;
}
 
 
/** Print errors in the TLS thread local error stack
 *
 * Drains the thread local OpenSSL error queue, and prints out errors.
 *
 * @param[in] request   The current request (may be NULL).
 * @param[in] msg       Error message describing the operation being attempted.
 * @param[in] ...       Arguments for msg.
 * @return the number of errors drained from the stack.
 */
int fr_tls_log(request_t *request, char const *msg, ...)
{
        va_list ap;
        int ret;
 
        va_start(ap, msg);
        ret = fr_tls_strerror_vprintf(msg, ap);
        va_end(ap);
 
        ROPTIONAL(RPERROR, PERROR, " ");
 
        return ret;
}
 
/** Clear errors in the TLS thread local error stack
 *
 */
void fr_tls_log_clear(void)
{
        while (ERR_get_error() != 0);
}
 
/** Increment the bio meth reference counter
 *
 */
static int tls_log_request_bio_create_cb(BIO *bio)
{
        atomic_fetch_add(&tls_request_log_ref, 1);
        BIO_set_init(bio, 1);
        return 1;
}
 
/** Converts BIO_write() calls to request log calls
 *
 * This callback is used to glue the output of OpenSSL functions into request log calls.
 *
 * @param[in] bio       that was written to.
 * @param[in] in        data being written to BIO.
 * @param[in] len       Length of data being written.
 */
static int tls_log_request_bio_write_cb(BIO *bio, char const *in, int len)
{
        fr_tls_log_bio_t        *lb = talloc_get_type_abort(BIO_get_data(bio), fr_tls_log_bio_t);
        request_t               *request = talloc_get_type_abort(lb->request, request_t);
        log_request_func_t      func;
        ssize_t                 slen;
        char                    *le;
 
        /*
         *      Pick the right logging function based on the type
         */
        if ((lb->type == L_ERR) || (lb->type == L_DBG_ERR) || (lb->type == L_DBG_ERR_REQ)) {
                func = log_request_error;
        } else {
                func = log_request;
        }
 
        /*
         *      OpenSSL feeds us data in fragments so we need
         *      to aggregate it, then look for new line chars
         *      as an indication we need to print the line.
         */
        slen = fr_sbuff_in_bstrncpy(&lb->sbuff, in, len);
        if (unlikely(slen < 0)) {
                /*
                 *      We failed to copy the data into the buffer
                 *      so we can't do anything with it.
                 */
                REDEBUG2("Failed copying %u bytes into TLS log aggregation buffer - buffer is too small.", len);
                return 0;
        }
 
        /*
         *      Split incoming data on new lines
         */
        while (fr_sbuff_behind(&lb->logged_m)) {
                le = memchr(fr_sbuff_current(&lb->logged_m), '\n',
                            fr_sbuff_current(&lb->sbuff) - fr_sbuff_current(&lb->logged_m));
                /*
                 *      Wait until we have a complete line
                 */
                if (le == NULL) break;
 
                /*
                 *      Skip empty lines
                 */
                if ((le - fr_sbuff_current(&lb->logged_m)) > 0) {
                        func(lb->type, lb->lvl, request, __FILE__, __LINE__, "%pV",
                             fr_box_strvalue_len(fr_sbuff_current(&lb->logged_m),
                                                 le - fr_sbuff_current(&lb->logged_m)));
                }
 
                fr_sbuff_set(&lb->logged_m, le + 1);
        }
 
        /*
         *      Clear out printed data
         */
        fr_sbuff_shift(&lb->sbuff, fr_sbuff_used(&lb->logged_m), false);
 
        return len;     /* Amount of data written */
}
 
/** Converts BIO_puts() calls to request log calls
 *
 * This callback is used to glue the output of OpenSSL functions into request log calls.
 *
 * @param[in] bio       that was written to.
 * @param[in] in        data being written to BIO.
 */
static int tls_log_request_bio_puts_cb(BIO *bio, char const *in)
{
        return tls_log_request_bio_write_cb(bio, in, strlen(in));
}
 
/** Decrement the bio meth reference counter
 *
 */
static int tls_log_request_bio_free_cb(BIO *bio)
{
        atomic_fetch_sub(&tls_request_log_ref, 1);
        BIO_set_init(bio, 0);
        return 1;
}
 
/** Increment the bio meth reference counter
 *
 */
static int tls_log_global_bio_create_cb(BIO *bio)
{
        atomic_fetch_add(&tls_global_log_ref, 1);
        BIO_set_init(bio, 1);
        return 1;
}
 
/** Converts BIO_write() calls to global log calls
 *
 * This callback is used to glue the output of OpenSSL functions into global log calls.
 *
 * @param[in] bio       that was written to.
 * @param[in] in        data being written to BIO.
 * @param[in] len       Length of data being written.
 */
static int tls_log_global_bio_write_cb(BIO *bio, char const *in, int len)
{
        fr_tls_log_bio_t        *lb = talloc_get_type_abort(BIO_get_data(bio), fr_tls_log_bio_t);
        char                    *le;
 
        /*
         *      OpenSSL feeds us data in fragments so we need
         *      to aggregate it, then look for new line chars
         *      as an indication we need to print the line.
         */
        if (fr_sbuff_in_bstrncpy(&lb->sbuff, in, len) < 0) return 0;
 
        /*
         *      Split incoming data on new lines
         */
        while (fr_sbuff_behind(&lb->logged_m)) {
                le = memchr(fr_sbuff_current(&lb->logged_m), '\n',
                            fr_sbuff_current(&lb->sbuff) - fr_sbuff_current(&lb->logged_m));
                /*
                 *      Wait until we have a complete line
                 */
                if (le == NULL) break;
 
                /*
                 *      Skip empty lines
                 */
                if ((le - fr_sbuff_current(&lb->logged_m)) > 0) {
                        if (fr_debug_lvl >= lb->lvl) fr_log(&default_log, lb->type, __FILE__, __LINE__,
                                                            "%pV",
                                                            fr_box_strvalue_len(fr_sbuff_current(&lb->logged_m),
                                                                                le - fr_sbuff_current(&lb->logged_m)));
                }
 
                fr_sbuff_set(&lb->logged_m, le + 1);
        }
 
        /*
         *      Clear out printed data
         */
        fr_sbuff_shift(&lb->sbuff, fr_sbuff_used(&lb->logged_m), false);
 
        return len;     /* Amount of data written */
}
 
/** Converts BIO_puts() calls to global log calls
 *
 * This callback is used to glue the output of OpenSSL functions into global log calls.
 *
 * @param[in] bio       that was written to.
 * @param[in] in        data being written to BIO.
 */
static int tls_log_global_bio_puts_cb(BIO *bio, char const *in)
{
        return tls_log_global_bio_write_cb(bio, in, strlen(in));
}
 
/** Decrement the bio meth reference counter
 *
 */
static int tls_log_global_bio_free_cb(BIO *bio)
{
        atomic_fetch_sub(&tls_global_log_ref, 1);
        BIO_set_init(bio, 0);
        return 1;
}
 
/** Frees a logging bio and its underlying OpenSSL BIO *
 *
 */
static int _fr_tls_log_bio_free(void *log_bio)
{
        fr_tls_log_bio_t        *our_log_bio = talloc_get_type_abort(log_bio, fr_tls_log_bio_t);
 
        BIO_free(our_log_bio->bio);
        our_log_bio->bio = NULL;
        return talloc_free(our_log_bio);
}
 
/** Return a request log BIO to use with OpenSSL logging functions
 *
 * @note The contents of the BIO will only be written to the logging system on finding
 *       a new line.  If data remains in the BIO when it is re-initialised (this function
 *       is called again), that data will be discarded.
 *
 * @note The returned BIO should be assumed to be invalid if the request yields.
 *
 * @param[in] file      of caller.
 * @param[in] line      of caller.
 * @param[in] request   to temporarily associate with logging BIO.
 * @param[in] type      to temporarily assign to logging bio.
 * @param[in] lvl       to temporarily assign to logging bio.
 * @return A thread local BIO to pass to OpenSSL logging functions.
 */
BIO *_fr_tls_request_log_bio(char const *file, int line, request_t *request, fr_log_type_t type, fr_log_lvl_t lvl)
{
        if (unlikely(!request_log_bio)) {
                fr_tls_log_bio_t        *lb;
 
                MEM(lb = talloc(NULL, fr_tls_log_bio_t));
                *lb = (fr_tls_log_bio_t) {
                        .bio = BIO_new(tls_request_log_meth),
                        .request = request,
                        .type = type,
                        .lvl = lvl,
                        .file = file,
                        .line = line
                };
                MEM(lb->bio);
                BIO_set_data(lb->bio, lb);      /* So we can retrieve the fr_tls_lb_t in the callbacks */
                fr_sbuff_init_talloc(lb, &lb->sbuff, &lb->tctx, 1024, 10 * 1024);       /* start 1k, max 10k */
                fr_atexit_thread_local(request_log_bio, _fr_tls_log_bio_free, lb);
                fr_sbuff_marker(&lb->logged_m, &lb->sbuff);
                return lb->bio;
        }
        fr_sbuff_reset_talloc(&request_log_bio->sbuff); /* Reset to initial size */
        fr_sbuff_marker(&request_log_bio->logged_m, &request_log_bio->sbuff);
        request_log_bio->request = request;
        request_log_bio->type = type;
        request_log_bio->lvl = lvl;
        request_log_bio->file = file;
        request_log_bio->line = line;
 
        return request_log_bio->bio;
}
 
/** Return a global log BIO to use with OpenSSL logging functions
 *
 * @note The contents of the BIO will only be written to the logging system on finding
 *       a new line.  If data remains in the BIO when it is re-initialised (this function
 *       is called again), that data will be discarded.
 *
 * @note The returned BIO should be assumed to be invalid if the current request yields.
 *
 * @param[in] file      of caller.
 * @param[in] line      of caller.
 * @param[in] type      to temporarily assign to logging bio.
 * @param[in] lvl       to temporarily assign to logging bio.
 * @return A thread local BIO to pass to OpenSSL logging functions.
 */
BIO *_fr_tls_global_log_bio(char const *file, int line, fr_log_type_t type, fr_log_lvl_t lvl)
{
        if (unlikely(!global_log_bio)) {
                fr_tls_log_bio_t        *lb;
 
                MEM(lb = talloc(NULL, fr_tls_log_bio_t));
                *lb = (fr_tls_log_bio_t) {
                        .bio = BIO_new(tls_global_log_meth),
                        .type = type,
                        .lvl = lvl,
                        .file = file,
                        .line = line
                };
                MEM(lb->bio);
                BIO_set_data(lb->bio, lb);      /* So we can retrieve the fr_tls_lb_t in the callbacks */
                fr_sbuff_init_talloc(lb, &lb->sbuff, &lb->tctx, 1024, 10 * 1024);       /* start 1k, max 10k */
                fr_atexit_thread_local(global_log_bio, _fr_tls_log_bio_free, lb);
                fr_sbuff_marker(&lb->logged_m, &lb->sbuff);
                return lb->bio;
        }
 
        fr_sbuff_reset_talloc(&global_log_bio->sbuff);  /* Reset to initial size */
        fr_sbuff_marker(&global_log_bio->logged_m, &global_log_bio->sbuff);
        global_log_bio->type = type;
        global_log_bio->lvl = lvl;
        global_log_bio->file = file;
        global_log_bio->line = line;
 
        return global_log_bio->bio;
}
 
/** Initialise the BIO logging meths which are used to create thread local logging BIOs
 *
 */
int fr_tls_log_init(void)
{
        /*
         *      As per the boringSSL documentation
         *
         *      BIO_TYPE_START is the first user-allocated |BIO| type.
         *      No pre-defined type, flag bits aside, may exceed this
         *      value.
         *
         *      The low byte here defines the BIO ID, and the high byte
         *      defines its capabilities.
         */
        tls_request_log_meth = BIO_meth_new(BIO_get_new_index() | BIO_TYPE_SOURCE_SINK, "fr_tls_request_log");
        if (unlikely(!tls_request_log_meth)) return -1;
 
        BIO_meth_set_create(tls_request_log_meth, tls_log_request_bio_create_cb);
        BIO_meth_set_write(tls_request_log_meth, tls_log_request_bio_write_cb);
        BIO_meth_set_puts(tls_request_log_meth, tls_log_request_bio_puts_cb);
        BIO_meth_set_destroy(tls_request_log_meth, tls_log_request_bio_free_cb);
 
        tls_global_log_meth = BIO_meth_new(BIO_get_new_index() | BIO_TYPE_SOURCE_SINK, "fr_tls_global_log");
        if (unlikely(!tls_global_log_meth)) {
                BIO_meth_free(tls_request_log_meth);
                tls_request_log_meth = NULL;
                return -1;
        }
 
        BIO_meth_set_create(tls_global_log_meth, tls_log_global_bio_create_cb);
        BIO_meth_set_write(tls_global_log_meth, tls_log_global_bio_write_cb);
        BIO_meth_set_puts(tls_global_log_meth, tls_log_global_bio_puts_cb);
        BIO_meth_set_destroy(tls_global_log_meth, tls_log_global_bio_free_cb);
 
        return 0;
}
 
/** Free the global log method templates
 *
 */
void fr_tls_log_free(void)
{
        /*
         *      These must be freed first else
         *      we get crashes in the OpenSSL
         *      code when we try to free them.
         */
        fr_assert_msg(atomic_load(&tls_request_log_ref) == 0, "request log BIO refs remaining %u", atomic_load(&tls_request_log_ref));
        fr_assert_msg(atomic_load(&tls_global_log_ref) == 0, "global log BIO refs remaining %u", atomic_load(&tls_global_log_ref));
 
        if (tls_request_log_meth) {
                BIO_meth_free(tls_request_log_meth);
                tls_request_log_meth = NULL;
        }
 
        if (tls_global_log_meth) {
                BIO_meth_free(tls_global_log_meth);
                tls_global_log_meth = NULL;
        }
}
#endif /* WITH_TLS */