log.c

Go to the documentation of this file.

/*
 *   This library is free software; you can redistribute it and/or
 *   modify it under the terms of the GNU Lesser General Public
 *   License as published by the Free Software Foundation; either
 *   version 2.1 of the License, or (at your option) any later version.
 *
 *   This library 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
 *   Lesser General Public License for more details.
 *
 *   You should have received a copy of the GNU Lesser General Public
 *   License along with this library; if not, write to the Free Software
 *   Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301, USA
 */
 
/** Support functions for logging in FreeRADIUS libraries
 *
 * @file src/lib/util/log.c
 *
 * @copyright 2003,2006 The FreeRADIUS server project
 */
RCSID("$Id: 797aa76d8c9081b17fce2afac0078e102bad9379 $")
 
#include <freeradius-devel/util/debug.h>
#include <freeradius-devel/util/log.h>
#include <freeradius-devel/util/print.h>
#include <freeradius-devel/util/syserror.h>
#include <freeradius-devel/util/value.h>
 
#include <fcntl.h>
#include <stdatomic.h>
#ifdef HAVE_FEATURES_H
#  include <features.h>
#endif
#ifdef HAVE_SYSLOG_H
#  include <syslog.h>
#endif
 
FILE    *fr_log_fp = NULL;
int     fr_debug_lvl = 0;
 
static _Thread_local TALLOC_CTX *fr_log_pool;
 
/** Latched once shutdown has freed every thread's log pool
 *
 * `fr_atexit_thread_trigger_all()` runs every registered thread destructor
 * on the calling (main) thread, so it frees the log pool memory for threads
 * whose TLS slot it can't reach (librdkafka's bg threads, anything spawned
 * by a third-party library that bypasses our schedule).  Those threads
 * still hold the now-dangling pointer in their `_Thread_local fr_log_pool`,
 * and will hand it to `talloc_new` on the next log call - "Bad talloc magic
 * value" abort.
 *
 * Once set, `fr_log_pool_init()` ignores the TLS slot entirely and returns
 * NULL; downstream `talloc_new(NULL)` / `talloc_asprintf(NULL, ...)` calls
 * just allocate top-level chunks for the duration of the log line.  No
 * pooling, no TLS, safe from any thread.
 */
static atomic_bool log_pools_disabled;
 
static uint32_t location_indent = 30;
static fr_event_list_t *log_el;                 //!< Event loop we use for process logging data.
 
static int stderr_fd = -1;                      //!< The original unmolested stderr file descriptor
static int stdout_fd = -1;                      //!< The original unmolested stdout file descriptor
 
static fr_log_fd_event_ctx_t stdout_ctx;        //!< Logging ctx for stdout.
static fr_log_fd_event_ctx_t stderr_ctx;        //!< Logging ctx for stderr.
 
static int stdout_pipe[2];                      //!< Pipe we use to transport stdout data.
static int stderr_pipe[2];                      //!< Pipe we use to transport stderr data.
 
static FILE *devnull;                           //!< File handle for /dev/null
 
bool fr_log_rate_limit = true;                  //!< Whether repeated log entries should be rate limited
 
static _Thread_local fr_log_type_t log_msg_type;//!< The type of the last message logged.
                                                ///< Mainly uses for syslog.
 
/** Canonicalize error strings, removing tabs, and generate spaces for error marker
 *
 * @note talloc_free must be called on the buffer returned in spaces and text
 *
 * Used to produce error messages such as this:
 @verbatim
  I'm a string with a parser # error
                             ^ Unexpected character in string
 @endverbatim
 *
 * With code resembling this:
 @code{.c}
   ERROR("%s", parsed_str);
   ERROR("%s^ %s", space, text);
 @endcode
 *
 * @todo merge with above function (log_request_marker)
 *
 * @param sp Where to write a dynamically allocated buffer of spaces used to indent the error text.
 * @param text Where to write the canonicalized version of fmt (the error text).
 * @param ctx to allocate the spaces and text buffers in.
 * @param slen of error marker. Expects negative integer value, as returned by parse functions.
 * @param fmt to canonicalize.
 */
void fr_canonicalize_error(TALLOC_CTX *ctx, char **sp, char **text, ssize_t slen, char const *fmt)
{
        size_t offset, prefix, suffix;
        char *spaces, *p;
        char const *start;
        char *value;
        size_t inlen;
 
        offset = -slen;
 
        inlen = strlen(fmt);
        start = fmt;
        prefix = suffix = 0;
 
        if (offset == inlen + 1) offset = inlen;
 
        /*
         *      Catch bad callers.
         */
        if (offset > inlen) {
                *sp = talloc_asprintf(ctx, "Invalid offset %zu > %zu", offset, inlen);
                *text = talloc_strdup(ctx, fmt);
                return;
        }
 
        /*
         *      Too many characters before the inflection point.  Skip
         *      leading text until we have only 45 characters before it.
         */
        if (offset > 30) {
                size_t skip = offset - 30;
 
                start += skip;
                inlen -= skip;
                offset -= skip;
                prefix = 4;
        }
 
        /*
         *      Too many characters after the inflection point,
         *      truncate it to 30 characters after the inflection
         *      point.
         */
        if (inlen > (offset + 30)) {
                inlen = offset + 30;
                suffix = 4;
        }
 
        /*
         *      Allocate an array to hold just the text we need.
         */
        value = talloc_array(ctx, char, prefix + inlen + 1 + suffix);
        if (prefix) {
                memcpy(value, "... ", 4);
        }
        memcpy(value + prefix, start, inlen);
        if (suffix) {
                memcpy(value + prefix + inlen, "...", 3);
                value[prefix + inlen + 3] = '\0';
        }
        value[prefix + inlen + suffix] = '\0';
 
        /*
         *      Smash tabs to spaces for the input string.
         */
        for (p = value; *p != '\0'; p++) {
                if (*p == '\t') *p = ' ';
        }
 
        /*
         *      Allocate the spaces array
         */
        spaces = talloc_array(ctx, char, prefix + offset + 1);
        memset(spaces, ' ', prefix + offset);
        spaces[prefix + offset] = '\0';
 
        *sp = spaces;
        *text = value;
}
 
/** Function to provide as the readable callback to the event loop
 *
 * Writes any data read from a file descriptor to the request log,
 * tries very hard not to chop lines in the middle, but will split
 * at 1024 byte boundaries if forced to.
 *
 * @param[in] el        UNUSED
 * @param[in] fd        UNUSED
 * @param[in] flags     UNUSED
 * @param[in] uctx      Pointer to a log_fd_event_ctx_t
 */
void fr_log_fd_event(UNUSED fr_event_list_t *el, int fd, UNUSED int flags, void *uctx)
{
        char                    buffer[1024] = "";
        fr_log_fd_event_ctx_t   *log_info = uctx;
        fr_sbuff_t              sbuff;
        fr_sbuff_marker_t       m_start, m_end;
 
        fr_sbuff_term_t const   line_endings = FR_SBUFF_TERMS(L("\n"), L("\r"));
 
        if (log_info->lvl < fr_debug_lvl) {
                while (read(fd, buffer, sizeof(buffer)) > 0);
                return;
        }
 
#ifndef NDEBUG
        memset(buffer, 0x42, sizeof(buffer));
#endif
 
        fr_sbuff_init_out(&sbuff, buffer, sizeof(buffer));
        fr_sbuff_marker(&m_start, &sbuff);
        fr_sbuff_marker(&m_end, &sbuff);
 
        for (;;) {
                ssize_t         slen;
 
                slen = read(fd, fr_sbuff_current(&m_end), fr_sbuff_remaining(&m_end));
                if ((slen < 0) && (errno == EINTR)) continue;
 
                if (slen > 0) fr_sbuff_advance(&m_end, slen);
 
                while (fr_sbuff_ahead(&m_end) > 0) {
                        fr_sbuff_adv_until(&sbuff, fr_sbuff_ahead(&m_end), &line_endings, '\0');
 
                        /*
                         *      Incomplete line, try and read the rest.
                         */
                        if ((slen > 0) && (fr_sbuff_used(&m_start) > 0) &&
                            !fr_sbuff_is_terminal(&sbuff, &line_endings)) {
                                break;
                        }
 
                        fr_log(log_info->dst, log_info->type,
                               __FILE__, __LINE__,
                               "%s%s%pV",
                               log_info->prefix ? log_info->prefix : "",
                               log_info->prefix ? " - " : "",
                               fr_box_strvalue_len(fr_sbuff_current(&m_start), fr_sbuff_behind(&m_start)));
 
                        fr_sbuff_advance(&sbuff, 1);    /* Skip the whitespace */
                        fr_sbuff_set(&m_start, &sbuff);
                }
 
                /*
                 *      Error or done
                 */
                if (slen <= 0) break;
 
                /*
                 *      Clear out the existing data
                 */
                fr_sbuff_shift(&sbuff, fr_sbuff_used(&m_start), false);
        }
}
 
/** Maps log categories to message prefixes
 */
fr_table_num_ordered_t const fr_log_levels[] = {
        { L("Debug : "),                L_DBG           },
        { L("Info  : "),                L_INFO          },
        { L("Warn  : "),                L_WARN          },
        { L("Error : "),                L_ERR           },
        { L("Auth  : "),                L_AUTH          },
        { L("INFO  : "),                L_DBG_INFO      },
        { L("WARN  : "),                L_DBG_WARN      },
        { L("ERROR : "),                L_DBG_ERR       },
        { L("WARN  : "),                L_DBG_WARN_REQ  },
        { L("ERROR : "),                L_DBG_ERR_REQ   }
};
size_t fr_log_levels_len = NUM_ELEMENTS(fr_log_levels);
 
/** @name VT100 escape sequences
 *
 * These sequences may be written to VT100 terminals to change the
 * colour and style of the text.
 *
 @code{.c}
   fprintf(stdout, VTC_RED "This text will be coloured red" VTC_RESET);
 @endcode
 * @{
 */
#define VTC_RED         "\x1b[31m"      //!< Colour following text red.
#define VTC_YELLOW      "\x1b[33m"      //!< Colour following text yellow.
#define VTC_BOLD        "\x1b[1m"       //!< Embolden following text.
#define VTC_RESET       "\x1b[0m"       //!< Reset terminal text to default style/colour.
/** @} */
 
/** Maps log categories to VT100 style/colour escape sequences
 */
static fr_table_num_ordered_t const colours[] = {
        { L(VTC_BOLD),                  L_INFO          },
        { L(VTC_RED),                   L_ERR           },
        { L(VTC_BOLD VTC_YELLOW),       L_WARN          },
        { L(VTC_BOLD VTC_RED),          L_DBG_ERR       },
        { L(VTC_BOLD VTC_YELLOW),       L_DBG_WARN      },
        { L(VTC_BOLD VTC_RED),          L_DBG_ERR_REQ   },
        { L(VTC_BOLD VTC_YELLOW),       L_DBG_WARN_REQ  },
};
static size_t colours_len = NUM_ELEMENTS(colours);
 
 
bool log_dates_utc = false;
 
fr_log_t default_log = {
        .colourise = false,             //!< Will be set later. Should be off before we do terminal detection.
        .fd = STDOUT_FILENO,
        .dst = L_DST_STDOUT,
        .file = NULL,
        .timestamp = L_TIMESTAMP_AUTO
};
 
/** Cleanup the memory pool used by vlog_request
 *
 */
static int _fr_log_pool_free(void *arg)
{
        if (talloc_free(arg) < 0) return -1;
        fr_log_pool = NULL;
        return 0;
}
 
/** Disable per-thread log pools for the rest of the process lifetime
 *
 * Call this from the main thread immediately after
 * `fr_atexit_thread_trigger_all()`, which frees every other thread's log
 * pool but can't reset their `_Thread_local` slot.  After this returns,
 * subsequent `fr_log` calls fall back to `talloc_new(NULL)` instead of
 * touching the (now dangling) TLS pool pointer.
 */
void fr_log_disable_pools(void)
{
        atomic_store_explicit(&log_pools_disabled, true, memory_order_relaxed);
}
 
/** talloc ctx to use when composing log messages
 *
 * Functions must ensure that they allocate a new ctx from the one returned
 * here, and that this ctx is freed before the function returns.
 *
 * @return talloc pool to use for scratch space, or NULL if pools have been
 *      disabled - callers must tolerate a NULL return.
 */
TALLOC_CTX *fr_log_pool_init(void)
{
        TALLOC_CTX      *pool;
 
        /*
         *      Once main has signalled shutdown the TLS slot may be a
         *      dangling pointer for any thread we don't own (librdkafka's
         *      bg threads etc.) - skip the pool entirely.
         */
        if (unlikely(fr_atexit_thread_local_alloc_disabled())) return NULL;
 
        pool = fr_log_pool;
        if (unlikely(!pool)) {
                if (fr_atexit_is_exiting()) return NULL;        /* No new pools if we're exiting */
 
                pool = talloc_pool(NULL, 16384);
                if (!pool) {
                        fr_perror("Failed allocating memory for vlog_request_pool");
                        return NULL;
                }
                fr_atexit_thread_local(fr_log_pool, _fr_log_pool_free, pool);
        }
 
        return pool;
}
 
/** Send a server log message to its destination
 *
 * @param[in] log       destination.
 * @param[in] type      of log message.
 * @param[in] file      src file the log message was generated in.
 * @param[in] line      number the log message was generated on.
 * @param[in] arg_names source text of each substitution argument, or NULL.
 * @param[in] fmt       with printf style substitution tokens.
 * @param[in] ap        Substitution arguments.
 */
void _fr_vlog(fr_log_t const *log, fr_log_type_t type, char const *file, int line,
              UNUSED char const * const arg_names[], char const *fmt, va_list ap)
{
        int             colourise = log->colourise;
        char            *buffer;
        TALLOC_CTX      *pool, *thread_log_pool;
        char const      *fmt_colour = "";
        char const      *fmt_location = "";
        char            fmt_time[50];
        char const      *fmt_type = "";
        char            *fmt_msg;
 
        static char const *spaces = "                                    ";     /* 40 */
 
        fmt_time[0] = '\0';
 
        /*
         *      If we don't want any messages, then
         *      throw them away.
         */
        if (log->dst == L_DST_NULL) return;
 
        thread_log_pool = fr_log_pool_init();
        pool = talloc_new(thread_log_pool);     /* Track our local allocations */
 
        /*
         *      Set colourisation
         */
        if (colourise) {
                fmt_colour = fr_table_str_by_value(colours, type, NULL);
                if (!fmt_colour) colourise = false;
        }
 
        /*
         *      Print src file/line
         */
        if (log->line_number) {
                size_t  len;
                int     pad = 0;
                char    *str;
 
                str = talloc_asprintf(pool, "%s:%i", file, line);
                len = talloc_strlen(str);
 
                /*
                 *      Only increase the indent
                 */
                if (len > location_indent) {
                        location_indent = len;
                } else {
                        pad = location_indent - len;
                }
 
                fmt_location = talloc_asprintf_append_buffer(str, "%.*s : ", pad, spaces);
        }
        /*
         *      Determine if we need to add a timestamp to the start of the message
         */
        switch (log->timestamp) {
        case L_TIMESTAMP_OFF:
                break;
 
        /*
         *      If we're not logging to syslog, and the debug level is -xxx
         *      then log timestamps by default.
         */
        case L_TIMESTAMP_AUTO:
                if (log->dst == L_DST_SYSLOG) break;
                if ((log->dst != L_DST_FILES) && (fr_debug_lvl <= L_DBG_LVL_2)) break;
                FALL_THROUGH;
 
        case L_TIMESTAMP_ON:
        {
                fr_unix_time_t now = fr_time_to_unix_time(fr_time());
                fr_sbuff_t time_sbuff = FR_SBUFF_OUT(fmt_time, sizeof(fmt_time));
                fr_unix_time_to_str(&time_sbuff, now, FR_TIME_RES_USEC, log->dates_utc);
                break;
        }
        }
 
        /*
         *      Add ERROR or WARNING prefixes to messages not going to
         *      syslog.  It's redundant for syslog because of syslog
         *      facilities.
         */
        if (log->dst != L_DST_SYSLOG) {
                /*
                 *      We always print "WARN" and "ERROR" prefixes.
                 */
                switch (type) {
                case L_DBG_WARN:
                case L_DBG_ERR:
                        fmt_type = fr_table_str_by_value(fr_log_levels, type, NULL);
                        break;
 
                default:
                        /*
                         *      Otherwise, print the other info levels only if we're asked to print the level,
                         *      and we're not colourizing the output.  If we're colourizing the output, then
                         *      the colors indicate the debug level (info, warning, error), and we don't need
                         *      any prefix.
                         */
                        if (!log->print_level || log->colourise) break;
 
                        if (fmt_time[0] != '\0') {
                                fmt_type = fr_table_str_by_value(fr_log_levels, type, ": ");
                                break;
                        }
 
                        /*
                         *      The mixed-case "Debug", "Info", "Warn", and "Error" prefixes are
                         *      only useful when the messages are timestamped, i.e. when the server
                         *      runs as a daemon, or at high debug levels.  A "radiusd -X" session
                         *      has no timestamps, so print no prefix at all for "Debug" and
                         *      "Info", and use the all-caps prefixes of the equivalent debug
                         *      levels for warnings and errors.
                         */
                        switch (type) {
                        case L_DBG:
                        case L_INFO:
                                break;
 
                        case L_WARN:
                                fmt_type = fr_table_str_by_value(fr_log_levels, L_DBG_WARN, NULL);
                                break;
 
                        case L_ERR:
                                fmt_type = fr_table_str_by_value(fr_log_levels, L_DBG_ERR, NULL);
                                break;
 
                        default:
                                fmt_type = fr_table_str_by_value(fr_log_levels, type, ": ");
                                break;
                        }
                        break;
                }
        }
 
        /*
         *      Sanitize output.
         *
         *      Most strings should be escaped before they get here.
         */
        {
                char    *p, *end;
 
                p = fmt_msg = fr_vasprintf(pool, fmt, ap);
                end = p + talloc_strlen(fmt_msg);
 
                /*
                 *      Filter out control chars and non UTF8 chars
                 */
                for (p = fmt_msg; p < end; p++) {
                        int clen;
 
                        switch (*p) {
                        case '\r':
                        case '\n':
                                *p = ' ';
                                break;
 
                        case '\t':
                                continue;
 
                        default:
                                clen = fr_utf8_char((uint8_t *)p, -1);
                                if (!clen) {
                                        *p = '?';
                                        continue;
                                }
                                p += (clen - 1);
                                break;
                        }
                }
        }
 
        switch (log->dst) {
 
#ifdef HAVE_SYSLOG_H
        case L_DST_SYSLOG:
        {
                int syslog_priority = L_DBG;
 
                switch (type) {
                case L_DBG:
                case L_DBG_INFO:
                case L_DBG_WARN:
                case L_DBG_ERR:
                case L_DBG_ERR_REQ:
                case L_DBG_WARN_REQ:
                        syslog_priority= LOG_DEBUG;
                        break;
 
                case L_INFO:
                        syslog_priority = LOG_INFO;
                        break;
 
                case L_WARN:
                        syslog_priority = LOG_WARNING;
                        break;
 
                case L_ERR:
                        syslog_priority = LOG_ERR;
                        break;
 
                case L_AUTH:
                        syslog_priority = LOG_AUTH | LOG_INFO;
                        break;
                }
                syslog(syslog_priority,
                       "%s"     /* time */
                       "%s"     /* time sep */
                       "%s",    /* message */
                       fmt_time,
                       fmt_time[0] ? ": " : "",
                       fmt_msg);
        }
                break;
#endif
 
        case L_DST_FILES:
        case L_DST_STDOUT:
        case L_DST_STDERR:
        {
                buffer = talloc_asprintf(pool,
                                         "%s"   /* colourise */
                                         "%s"   /* location */
                                         "%s"   /* time */
                                         "%s"   /* time sep */
                                         "%s"   /* message type */
                                         "%s"   /* message */
                                         "%s"   /* colourise reset */
                                         "\n",
                                         colourise ? fmt_colour : "",
                                         fmt_location,
                                         fmt_time,
                                         fmt_time[0] ? ": " : "",
                                         fmt_type,
                                         fmt_msg,
                                         colourise ? VTC_RESET : "");
 
                /*
                 *      This function is in a utility library, and can't do anything about write errors,
                 *      except for writes to stdout().  We can't recover from those, so we might as well exit
                 *      rather than continue to write to a place which doesn't exist.
                 */
                if (write(log->fd, buffer, talloc_strlen(buffer)) < 0) {
                        if (log->dst == L_DST_STDOUT) {
                                switch (errno) {
                                case EPIPE:
                                case EBADF:
                                        fr_exit_now(EXIT_FAILURE);
 
                                default:
                                        break;
                                }
                        }
                }
        }
                break;
 
        default:
        case L_DST_NULL:        /* should have been caught above */
                break;
        }
 
        talloc_free(pool);      /* clears all temporary allocations */
 
        return;
}
 
/** Send a server log message to its destination
 *
 * @param log           destination.
 * @param type          of log message.
 * @param file          where the log message originated
 * @param line          where the log message originated
 * @param arg_names     source text of each substitution argument, or NULL.
 * @param fmt           with printf style substitution tokens.
 * @param ...           Substitution arguments.
 */
void _fr_log(fr_log_t const *log, fr_log_type_t type, char const *file, int line,
             char const * const arg_names[], char const *fmt, ...)
{
        va_list ap;
 
        /*
         *      Non-debug message, or debugging is enabled.  Log it.
         */
        if (!(((type & L_DBG) == 0) || (fr_debug_lvl > 0))) return;
 
        va_start(ap, fmt);
        _fr_vlog(log, type, file, line, arg_names, fmt, ap);
        va_end(ap);
}
 
/** Drain any outstanding messages from the fr_strerror buffers
 *
 * This function drains any messages from fr_strerror buffer prefixing
 * the first message with fmt + args.
 *
 * If a prefix is specified in rules, this is prepended to all lines
 * logged.  The prefix is useful for adding context, i.e. configuration
 * file and line number information.
 *
 * @param[in] log       destination.
 * @param[in] type      of log message.
 * @param[in] file      src file the log message was generated in.
 * @param[in] line      number the log message was generated on.
 * @param[in] f_rules   for printing multiline errors.
 * @param[in] arg_names source text of each substitution argument, or NULL.
 * @param[in] fmt       with printf style substitution tokens.
 * @param[in] ap        Substitution arguments.
 */
void _fr_vlog_perror(fr_log_t const *log, fr_log_type_t type, char const *file, int line,
                     fr_log_perror_format_t const *f_rules,
                     UNUSED char const * const arg_names[], char const *fmt, va_list ap)
{
        char const                              *error;
        static fr_log_perror_format_t           default_f_rules;
 
        TALLOC_CTX                              *thread_log_pool;
        fr_sbuff_marker_t                       prefix_m;
 
        fr_sbuff_t                              sbuff;
        fr_sbuff_uctx_talloc_t                  tctx;
 
        /*
         *      Non-debug message, or debugging is enabled.  Log it.
         */
        if (!(((type & L_DBG) == 0) || (fr_debug_lvl > 0))) return;
 
        if (!f_rules) f_rules = &default_f_rules;
 
        thread_log_pool = fr_log_pool_init();
 
        /*
         *      Setup the aggregation buffer
         */
        fr_sbuff_init_talloc(thread_log_pool, &sbuff, &tctx, 1024, 16384);
 
        /*
         *      Add the prefix for the first line
         */
        if (f_rules->first_prefix) (void) fr_sbuff_in_strcpy(&sbuff, f_rules->first_prefix);
 
        /*
         *      Add the (optional) message, and/or (optional) error
         *      with the error_sep.
         *      i.e. <msg>: <error>
         */
        error = fr_strerror_pop();
 
        if (!error && !fmt) return;     /* NOOP */
 
        if (fmt) {
                va_list aq;
 
                va_copy(aq, ap);
                fr_sbuff_in_vsprintf(&sbuff, fmt, aq);
                va_end(aq);
        }
 
        if (error && (fmt || f_rules->first_prefix)) {
                if (fmt) (void) fr_sbuff_in_strcpy(&sbuff, ": ");
                (void) fr_sbuff_in_strcpy(&sbuff, error);
        }
 
        error = fr_sbuff_start(&sbuff);         /* may not be talloced with const */
 
        /*
         *      Log the first line
         */
        fr_log(log, type, file, line, "%s", error);
 
        fr_sbuff_set_to_start(&sbuff);
        if (f_rules->subsq_prefix) {
                (void) fr_sbuff_in_strcpy(&sbuff, f_rules->subsq_prefix);
                fr_sbuff_marker(&prefix_m, &sbuff);
        }
 
        /*
         *      Print out additional error lines
         */
        while ((error = fr_strerror_pop())) {
                if (f_rules->subsq_prefix) {
                        fr_sbuff_set(&sbuff, &prefix_m);
                        (void) fr_sbuff_in_strcpy(&sbuff, error);       /* may not be talloced with const */
                        error = fr_sbuff_start(&sbuff);
                }
 
                fr_log(log, type, file, line, "%s", error);
        }
 
        talloc_free(sbuff.buff);
}
 
/** Drain any outstanding messages from the fr_strerror buffers
 *
 * This function drains any messages from fr_strerror buffer adding a prefix (fmt)
 * to the first message.
 *
 * @param[in] log       destination.
 * @param[in] type      of log message.
 * @param[in] file      src file the log message was generated in.
 * @param[in] line      number the log message was generated on.
 * @param[in] rules     for printing multiline errors.
 * @param[in] arg_names source text of each substitution argument, or NULL.
 * @param[in] fmt       with printf style substitution tokens.
 * @param[in] ...       Substitution arguments.
 */
void _fr_log_perror(fr_log_t const *log, fr_log_type_t type, char const *file, int line,
                    fr_log_perror_format_t const *rules,
                    char const * const arg_names[], char const *fmt, ...)
{
        va_list ap;
 
        va_start(ap, fmt);
        _fr_vlog_perror(log, type, file, line, rules, arg_names, fmt, ap);
        va_end(ap);
}
 
DIAG_OFF(format-nonliteral)
/** Print out an error marker
 *
 * @param[in] log               destination.
 * @param[in] type              of log message.
 * @param[in] file              src file the log message was generated in.
 * @param[in] line              number the log message was generated on.
 * @param[in] str               Subject string we're printing a marker for.
 * @param[in] str_len           Subject string length.  Use SIZE_MAX for the
 *                              length of the string.
 * @param[in] marker_idx        Where to place the marker.  May be negative.
 * @param[in] marker            text to print at marker_idx.
 * @param[in] line_prefix_fmt   Prefix to add to the marker messages.
 * @param[in] ...               Arguments for line_prefix_fmt.
 */
void fr_log_marker(fr_log_t const *log, fr_log_type_t type, char const *file, int line,
                   char const *str, size_t str_len,
                   ssize_t marker_idx, char const *marker, char const *line_prefix_fmt, ...)
{
        char const              *ellipses = "";
        va_list                 ap;
        TALLOC_CTX              *thread_log_pool = fr_log_pool_init();
        char                    *line_prefix = NULL;
        static char const       marker_spaces[] = "                                                            "; /* 60 */
 
        if (str_len == SIZE_MAX) str_len = strlen(str);
 
        if (marker_idx < 0) marker_idx = marker_idx * -1;
 
        if ((size_t)marker_idx >= sizeof(marker_spaces)) {
                size_t offset = (marker_idx - (sizeof(marker_spaces) - 1)) + (sizeof(marker_spaces) * 0.75);
                marker_idx -= offset;
 
                if (offset > str_len) offset = str_len;
                str += offset;
                str_len -= offset;
 
                ellipses = "... ";
        }
 
        if (line_prefix_fmt) {
                va_start(ap, line_prefix_fmt);
                line_prefix = fr_vasprintf(thread_log_pool, line_prefix_fmt, ap);
                va_end(ap);
        }
 
        fr_log(log, type, file, line, "%s%s%.*s",
               line_prefix ? line_prefix : "", ellipses, (int)str_len, str);
        fr_log(log, type, file, line, "%s%s%.*s^ %s",
               line_prefix ? line_prefix : "", ellipses, (int)marker_idx, marker_spaces, marker);
 
        if (line_prefix_fmt) talloc_free(line_prefix);
}
 
/** Print out hex block
 *
 * @param[in] log               destination.
 * @param[in] type              of log message.
 * @param[in] file              src file the log message was generated in.
 * @param[in] line              number the log message was generated on.
 * @param[in] data              to print.
 * @param[in] data_len          length of data.
 * @param[in] line_prefix_fmt   Prefix to add to the marker messages.
 * @param[in] ...               Arguments for line_prefix_fmt.
 */
void fr_log_hex(fr_log_t const *log, fr_log_type_t type, char const *file, int line,
                uint8_t const *data, size_t data_len, char const *line_prefix_fmt, ...)
{
        size_t          i, j, len;
        char            buffer[(0x10 * 3) + 1];
        char            *p, *end = buffer + sizeof(buffer);
        TALLOC_CTX      *thread_log_pool = fr_log_pool_init();
        char            *line_prefix = NULL;
 
        if (line_prefix_fmt) {
                va_list ap;
 
                va_start(ap, line_prefix_fmt);
                line_prefix = fr_vasprintf(thread_log_pool, line_prefix_fmt, ap);
                va_end(ap);
        }
 
        for (i = 0; i < data_len; i += 0x10) {
                len = 0x10;
                if ((i + len) > data_len) len = data_len - i;
 
                for (p = buffer, j = 0; j < len; j++, p += 3) snprintf(p, end - p, "%02x ", data[i + j]);
 
                if (line_prefix_fmt) {
                        fr_log(log, type, file, line, "%s%04x: %s",
                               line_prefix, (unsigned int) i, buffer);
                } else {
                        fr_log(log, type, file, line, "%04x: %s", (unsigned int) i, buffer);
                }
        }
 
        if (line_prefix_fmt) talloc_free(line_prefix);
}
 
/** Print out hex block
 *
 * @param[in] log               destination.
 * @param[in] type              of log message.
 * @param[in] file              src file the log message was generated in.
 * @param[in] line              number the log message was generated on.
 * @param[in] data              to print.
 * @param[in] data_len          length of data.
 * @param[in] marker_idx        Where to place the marker.  May be negative.
 * @param[in] marker            text to print at marker_idx.
 * @param[in] line_prefix_fmt   Prefix to add to the marker messages.
 * @param[in] ...               Arguments for line_prefix_fmt.
 */
void fr_log_hex_marker(fr_log_t const *log, fr_log_type_t type, char const *file, int line,
                       uint8_t const *data, size_t data_len,
                       ssize_t marker_idx, char const *marker, char const *line_prefix_fmt, ...)
{
        size_t          i, j, len;
        char            buffer[(0x10 * 3) + 1];
        char            *p, *end = buffer + sizeof(buffer);
        TALLOC_CTX      *thread_log_pool = fr_log_pool_init();
 
        char            *line_prefix = NULL;
        static char     spaces[3 * 0x10];       /* Bytes per line */
 
        if (!*spaces) memset(spaces, ' ', sizeof(spaces) - 1);  /* Leave a \0 */
 
        if (marker_idx < 0) marker_idx = marker_idx * -1;
        if (line_prefix_fmt) {
                va_list ap;
 
                va_start(ap, line_prefix_fmt);
                line_prefix = fr_vasprintf(thread_log_pool, line_prefix_fmt, ap);
                va_end(ap);
        }
 
        for (i = 0; i < data_len; i += 0x10) {
                len = 0x10;
                if ((i + len) > data_len) len = data_len - i;
 
                for (p = buffer, j = 0; j < len; j++, p += 3) snprintf(p, end - p, "%02x ", data[i + j]);
 
                if (line_prefix_fmt) {
                        fr_log(log, type, file, line, "%s%04x: %s",
                               line_prefix, (unsigned int) i, buffer);
                } else {
                        fr_log(log, type, file, line, "%04x: %s", (unsigned int) i, buffer);
                }
 
                /*
                 *      Marker is on this line
                 */
                if (((size_t)marker_idx >= i) && ((size_t)marker_idx < (i + 0x10))) {
                        if (line_prefix_fmt) {
                                fr_log(log, type, file, line, "%s      %.*s^ %s", line_prefix,
                                       (int)((marker_idx - i) * 3), spaces, marker);
                        } else {
                                fr_log(log, type, file, line, "      %.*s^ %s",
                                       (int)((marker_idx - i) * 3), spaces, marker);
                        }
                }
        }
 
        if (line_prefix_fmt) talloc_free(line_prefix);
}
DIAG_ON(format-nonliteral)
/** On fault, reset STDOUT and STDERR to something useful
 *
 * @return 0
 */
static int _restore_std_legacy(UNUSED int sig)
{
        if ((stderr_fd > 0) && (stdout_fd > 0)) {
                dup2(stdout_fd, STDOUT_FILENO);
                dup2(stderr_fd, STDERR_FILENO);
                return 0;
        }
 
        return 0;
}
 
/** Initialise file descriptors based on logging destination
 *
 * @param log Logger to manipulate.
 * @param daemonize Whether the server is starting as a daemon.
 * @return
 *      - 0 on success.
 *      - -1 on failure.
 */
int fr_log_init_legacy(fr_log_t *log, bool daemonize)
{
        int devnull_legacy;
 
        fr_log_rate_limit = daemonize;
 
        /*
         *      If we're running in foreground mode, save STDIN /
         *      STDERR as higher FDs, which won't get used by anyone
         *      else.  When we fork/exec a program, its STD FDs will
         *      get set to pipes.  We later set STDOUT / STDERR to
         *      /dev/null, so that any library trying to write to them
         *      doesn't screw anything up.
         *
         *      Then, when something goes wrong, restore them so that
         *      any debugger called from the panic action has access
         *      to STDOUT / STDERR.
         */
        if (!daemonize) {
                fr_fault_set_cb(_restore_std_legacy);
 
                stdout_fd = dup(STDOUT_FILENO);
                stderr_fd = dup(STDERR_FILENO);
        }
 
        devnull_legacy = open("/dev/null", O_RDWR);
        if (devnull_legacy < 0) {
                fr_strerror_printf("Error opening /dev/null: %s", fr_syserror(errno));
                return -1;
        }
 
        /*
         *      STDOUT & STDERR go to /dev/null, unless we have "-x",
         *      then STDOUT & STDERR go to the "-l log" destination.
         *
         *      The complexity here is because "-l log" can go to
         *      STDOUT or STDERR, too.
         */
        if (log->dst == L_DST_STDOUT) {
                setlinebuf(stdout);
                log->fd = STDOUT_FILENO;
 
                /*
                 *      If we're debugging, allow STDERR to go to
                 *      STDOUT too, for executed programs.
                 *
                 *      Allow stdout when running in foreground mode
                 *      as it's useful for some profiling tools,
                 *      like mutrace.
                 */
                if (fr_debug_lvl || !daemonize) {
                        dup2(STDOUT_FILENO, STDERR_FILENO);
                } else {
                        dup2(devnull_legacy, STDERR_FILENO);
                }
 
        } else if (log->dst == L_DST_STDERR) {
                setlinebuf(stderr);
                log->fd = STDERR_FILENO;
 
                /*
                 *      If we're debugging, allow STDOUT to go to
                 *      STDERR too, for executed programs.
                 *
                 *      Allow stdout when running in foreground mode
                 *      as it's useful for some profiling tools,
                 *      like mutrace.
                 */
                if (fr_debug_lvl || !daemonize) {
                        dup2(STDERR_FILENO, STDOUT_FILENO);
                } else {
                        dup2(devnull_legacy, STDOUT_FILENO);
                }
 
        } else if (log->dst == L_DST_SYSLOG) {
                /*
                 *      Discard STDOUT and STDERR no matter what the
                 *      status of debugging.  Syslog isn't a file
                 *      descriptor, so we can't use it.
                 */
                dup2(devnull_legacy, STDOUT_FILENO);
                dup2(devnull_legacy, STDERR_FILENO);
                log->print_level = false;
 
        } else if (fr_debug_lvl) {
                /*
                 *      If we're debugging, allow STDOUT and STDERR to
                 *      go to the log file.
                 */
                dup2(log->fd, STDOUT_FILENO);
                dup2(log->fd, STDERR_FILENO);
 
        } else {
                /*
                 *      Not debugging, and the log isn't STDOUT or
                 *      STDERR.  Ensure that we move both of them to
                 *      /dev/null, so that the calling terminal can
                 *      exit, and the output from executed programs
                 *      doesn't pollute STDOUT / STDERR.
                 */
                dup2(devnull_legacy, STDOUT_FILENO);
                dup2(devnull_legacy, STDERR_FILENO);
        }
 
        close(devnull_legacy);
 
        fr_fault_set_log_fd(log->fd);
 
        return 0;
}
 
DIAG_ON(format-nonliteral)
 
/** Initialise log dst for stdout, stderr or /dev/null
 *
 * @param[out] log      Destination to initialise.
 * @param[in] dst_type  The specific type of log destination to initialise.
 * @return
 *      - 0 on success.
 *      - -1 on failure.
 */
int fr_log_init_std(fr_log_t *log, fr_log_dst_t dst_type)
{
        memset(log, 0, sizeof(*log));
 
        log->dst = dst_type;
        switch (log->dst) {
        case L_DST_STDOUT:
                log->handle = stdout;
                break;
 
        case L_DST_STDERR:
                log->handle = stderr;
                break;
 
        case L_DST_NULL:
                log->handle = devnull;
                break;
 
        default:
                fr_strerror_const("Invalid dst type for FD log destination");
                return -1;
        }
 
        return 0;
}
 
/** Initialise a file logging destination to a FILE*
 *
 * @param[out] log      Destination to initialise.
 * @param[in] fp        pre-existing handle
 * @return
 *      - 0 on success.
 *      - -1 on failure.
 */
int fr_log_init_fp(fr_log_t *log, FILE *fp)
{
        memset(log, 0, sizeof(*log));
 
        log->dst = L_DST_FILES;
        log->handle = fp;
 
        setlinebuf(log->handle);
        log->fd = fileno(log->handle);
 
        return 0;
}
 
/** Initialise a file logging destination
 *
 * @param[out] log      Destination to initialise.
 * @param[in] file      to open handle for.
 * @return
 *      - 0 on success.
 *      - -1 on failure.
 */
int fr_log_init_file(fr_log_t *log, char const *file)
{
        FILE *fp;
 
        if (unlikely((fp = fopen(file, "a")) == NULL)) {
                fr_strerror_printf("Failed opening log file \"%s\": %s", file, fr_syserror(errno));
                return -1;
        }
 
        if (fr_log_init_fp(log, fp) < 0) return -1;
 
        /*
         *      The init over-rode any filename, so we reset it here.
         */
        log->file = file;
        return 0;
}
 
/** Write complete lines to syslog
 *
 */
static ssize_t _syslog_write(UNUSED void *cookie, const char *buf, size_t size)
{
        static int syslog_priority_table[] = {
                [L_DBG] = LOG_DEBUG,
 
                [L_INFO] = LOG_INFO,
                [L_DBG_INFO] = LOG_INFO,
 
                [L_ERR] = LOG_ERR,
                [L_DBG_ERR] = LOG_ERR,
                [L_DBG_ERR_REQ] = LOG_ERR,
 
                [L_WARN] = LOG_WARNING,
                [L_DBG_WARN] = LOG_WARNING,
                [L_DBG_WARN_REQ] = LOG_WARNING,
 
                [L_AUTH] = LOG_AUTH | LOG_INFO
        };
 
        syslog(syslog_priority_table[log_msg_type], "%.*s", (int)size, buf);
 
        return size;
}
 
/** Initialise a syslog logging destination
 *
 * @param[out] log      Destination to initialise.
 * @return
 *      - 0 on success.
 *      - -1 on failure.
 */
int fr_log_init_syslog(fr_log_t *log)
{
        memset(log, 0, sizeof(*log));
 
        log->dst = L_DST_SYSLOG;
        if (unlikely((log->handle = fopencookie(log, "w",
                                                (cookie_io_functions_t){
                                                        .write = _syslog_write,
                                                })) == NULL)) {
                fr_strerror_printf("Failed opening syslog transpor: %s", fr_syserror(errno));
                return -1;
        }
 
        setlinebuf(log->handle);
 
        return 0;
}
 
/** Initialise a function based logging destination
 *
 * @note Cookie functions receive the fr_log_t which contains the uctx, not the uctx directly.
 *
 * @param[out] log      Destination to initialise.
 * @param[in] write     Called when a complete log line is ready for writing.
 * @param[in] close     May be NULL.  Called when the logging destination has been closed.
 * @param[in] uctx      for the write and close functions.
 * @return
 *      - 0 on success.
 *      - -1 on failure.
 */
int fr_log_init_func(fr_log_t *log, cookie_write_function_t write, cookie_close_function_t close, void *uctx)
{
        memset(log, 0, sizeof(*log));
 
        log->dst = L_DST_FUNC;
 
        if (unlikely((log->handle = fopencookie(log, "w",
                                                (cookie_io_functions_t){
                                                        .write = write,
                                                        .close = close
                                                })) == NULL)) {
                fr_strerror_printf("Failed opening func transport: %s", fr_syserror(errno));
                return -1;
        }
 
        setlinebuf(log->handle);
        log->uctx = uctx;
 
        return 0;
}
 
/** Universal close function for all logging destinations
 *
 */
int fr_log_close(fr_log_t *log)
{
        switch (log->dst) {
        case L_DST_STDOUT:
        case L_DST_STDERR:
        case L_DST_NULL:
                return 0;
 
        /*
         *      Other log dsts
         */
        case L_DST_FILES:
        case L_DST_FUNC:
        case L_DST_SYSLOG:
                if (log->handle && (fclose(log->handle) < 0)) {
                        fr_strerror_printf("Failed closing file handle: %s", fr_syserror(errno));
                        return -1;
                }
                return 0;
 
        case L_DST_NUM_DEST:
                break;
        }
 
        fr_strerror_printf("Failed closing invalid log dst %u", log->dst);
        return -1;
}
 
/** Manipulate stderr and stdout so that was capture all data send to it from libraries
 *
 * @param[in] el        The event list we use to process logging data.
 * @param[in] daemonize Whether the server is starting as a daemon.
 * @return
 *      - 0 on success.
 *      - -1 on failure.
 */
int fr_log_global_init(fr_event_list_t *el, bool daemonize)
{
        log_el = el;
 
        fr_log_rate_limit = daemonize;
 
        /*
         *      dup the current stdout/stderr FDs and close
         *      the FDs in the STDOUT/STDERR slots to get
         *      the reference count back to one.
         */
        stdout_fd = dup(STDOUT_FILENO);
        if (unlikely(stdout_fd < 0)) {
                fr_strerror_printf("Failed cloning stdout FD: %s", fr_syserror(errno));
                return -1;
        }
 
        /*
         *      Create two unidirection pipes, duping one end
         *      to the stdout/stderr slots and inserting the
         *      other into our event loop
         */
        if (unlikely(pipe(stdout_pipe) < 0)) {
                fr_strerror_printf("Failed creating logging pipes: %s", fr_syserror(errno));
        error_0:
                log_el = NULL;
                close(stdout_fd);
                return -1;
        }
 
        /*
         *      This closes the other ref to the stdout FD.
         */
        if (unlikely(dup2(stdout_pipe[0], STDOUT_FILENO) < 0)) {
                fr_strerror_printf("Failed copying pipe end over stdout: %s", fr_syserror(errno));
        error_1:
                close(stdout_pipe[0]);
                stdout_pipe[0] = -1;
                close(stdout_pipe[1]);
                stdout_pipe[1] = -1;
                goto error_0;
        }
 
        stdout_ctx.dst = &default_log;
        stdout_ctx.prefix = "(stdout)";
        stdout_ctx.type = L_DBG;
        stdout_ctx.lvl = L_DBG_LVL_2;
 
        /*
         *      Now do stderr...
         */
        if (unlikely(fr_event_fd_insert(NULL, NULL, el, stdout_pipe[1], fr_log_fd_event, NULL, NULL, &stdout_ctx) < 0)) {
                fr_strerror_const_push("Failed adding stdout handler to event loop");
        error_2:
                dup2(STDOUT_FILENO, stdout_fd); /* Copy back the stdout FD */
                goto error_1;
        }
 
        stderr_fd = dup(STDERR_FILENO);
        if (unlikely(stderr_fd < 0)) {
                fr_strerror_printf("Failed cloning stderr FD: %s", fr_syserror(errno));
 
        error_3:
                fr_event_fd_delete(el, stdout_pipe[1], FR_EVENT_FILTER_IO);
                goto error_2;
        }
 
        if (unlikely(pipe(stderr_pipe) < 0)) {
                fr_strerror_printf("Failed creating logging pipes: %s", fr_syserror(errno));
        error_4:
                close(stderr_fd);
                goto error_3;
        }
 
        if (unlikely(dup2(stderr_pipe[0], STDERR_FILENO) < 0)) {
                fr_strerror_printf("Failed copying pipe end over stderr: %s", fr_syserror(errno));
        error_5:
                close(stderr_pipe[0]);
                stderr_pipe[0] = -1;
                close(stderr_pipe[1]);
                stderr_pipe[1] = -1;
                goto error_4;
        }
 
        stderr_ctx.dst = &default_log;
        stderr_ctx.prefix = "(stderr)";
        stderr_ctx.type = L_ERR;
        stderr_ctx.lvl = L_DBG_LVL_OFF; /* Log at all debug levels */
 
        if (unlikely(fr_event_fd_insert(NULL, NULL, el, stderr_pipe[1], fr_log_fd_event, NULL, NULL, &stderr_ctx) < 0)) {
                fr_strerror_const_push("Failed adding stdout handler to event loop");
        error_6:
                dup2(STDERR_FILENO, stderr_fd); /* Copy back the stderr FD */
                goto error_5;
        }
 
        fr_fault_set_log_fd(STDERR_FILENO);
        fr_fault_set_cb(_restore_std_legacy);           /* Restore the original file descriptors if we experience a fault */
 
        /*
         *      Setup our standard file *s
         */
        setlinebuf(stdout);
        setlinebuf(stderr);
 
        devnull = fopen("/dev/null", "w");
        if (unlikely(!devnull)) {
                fr_strerror_printf("Error opening /dev/null: %s", fr_syserror(errno));
                goto error_6;
        }
 
        fr_log_init_std(&default_log, L_DST_STDOUT);
 
        return 0;
}
 
/** Restores the original stdout and stderr FDs, closes the pipes and removes them from the event loop
 *
 */
void fr_log_global_free(void)
{
        if (!log_el) return;
 
        fr_event_fd_delete(log_el, stdout_pipe[1], FR_EVENT_FILTER_IO);
        close(stdout_pipe[1]);
        stdout_pipe[1] = -1;
        fr_event_fd_delete(log_el, stderr_pipe[1], FR_EVENT_FILTER_IO);
        close(stderr_pipe[1]);
        stderr_pipe[1] = -1;
 
        _restore_std_legacy(0); /* Will close stdout_pipe[0] and stderr_pipe[0] with dup2 */
 
        stdout_pipe[0] = -1;
        stderr_pipe[0] = -1;
 
        fclose(devnull);
}