libvirt/src/util/logging.c

/*
 * logging.c: internal logging and debugging
 *
 * Copyright (C) 2008 Red Hat, Inc.
 *
 * 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., 59 Temple Place, Suite 330, Boston, MA 02111-1307  USA
 *
 */

#include <config.h>

#include <stdio.h>
#include <stdarg.h>
#include <stdlib.h>
#include <time.h>
#include <sys/time.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>
#if HAVE_SYSLOG_H
#include <syslog.h>
#endif

#include "logging.h"
#include "memory.h"
#include "util.h"
#include "threads.h"

/*
 * Macro used to format the message as a string in virLogMessage
 * and borrowed from libxml2 (also used in virRaiseError)
 */
#define VIR_GET_VAR_STR(msg, str) {				\
    int       size, prev_size = -1;				\
    int       chars;						\
    char      *larger;						\
    va_list   ap;						\
                                                                \
    str = (char *) malloc(150);					\
    if (str != NULL) {						\
                                                                \
    size = 150;							\
                                                                \
    while (1) {							\
        va_start(ap, msg);					\
        chars = vsnprintf(str, size, msg, ap);			\
        va_end(ap);						\
        if ((chars > -1) && (chars < size)) {			\
            if (prev_size == chars) {				\
                break;						\
            } else {						\
                prev_size = chars;				\
            }							\
        }							\
        if (chars > -1)						\
            size += chars + 1;					\
        else							\
            size += 100;					\
        if ((larger = (char *) realloc(str, size)) == NULL) {	\
            break;						\
        }							\
        str = larger;						\
    }}								\
}

/*
 * A logging buffer to keep some history over logs
 */
#define LOG_BUFFER_SIZE 64000

static char virLogBuffer[LOG_BUFFER_SIZE + 1];
static int virLogLen = 0;
static int virLogStart = 0;
static int virLogEnd = 0;

/*
 * Filters are used to refine the rules on what to keep or drop
 * based on a matching pattern (currently a substring)
 */
struct _virLogFilter {
    const char *match;
    int priority;
};
typedef struct _virLogFilter virLogFilter;
typedef virLogFilter *virLogFilterPtr;

static virLogFilterPtr virLogFilters = NULL;
static int virLogNbFilters = 0;

/*
 * Outputs are used to emit the messages retained
 * after filtering, multiple output can be used simultaneously
 */
struct _virLogOutput {
    void *data;
    virLogOutputFunc f;
    virLogCloseFunc c;
    int priority;
};
typedef struct _virLogOutput virLogOutput;
typedef virLogOutput *virLogOutputPtr;

static virLogOutputPtr virLogOutputs = NULL;
static int virLogNbOutputs = 0;

/*
 * Default priorities
 */
static virLogPriority virLogDefaultPriority = VIR_LOG_DEFAULT;

static int virLogResetFilters(void);
static int virLogResetOutputs(void);

/*
 * Logs accesses must be serialized though a mutex
 */
virMutex virLogMutex;

static void virLogLock(void)
{
    virMutexLock(&virLogMutex);
}
static void virLogUnlock(void)
{
    virMutexUnlock(&virLogMutex);
}


static const char *virLogPriorityString(virLogPriority lvl) {
    switch (lvl) {
        case VIR_LOG_DEBUG:
            return("debug");
        case VIR_LOG_INFO:
            return("info");
        case VIR_LOG_WARN:
            return("warning");
        case VIR_LOG_ERROR:
            return("error");
    }
    return("unknown");
}

static int virLogInitialized = 0;

/**
 * virLogStartup:
 *
 * Initialize the logging module
 *
 * Returns 0 if successful, and -1 in case or error
 */
int virLogStartup(void) {
    if (virLogInitialized)
        return(-1);

    if (virMutexInit(&virLogMutex) < 0)
        return -1;

    virLogInitialized = 1;
    virLogLock();
    virLogLen = 0;
    virLogStart = 0;
    virLogEnd = 0;
    virLogDefaultPriority = VIR_LOG_DEFAULT;
    virLogUnlock();
    return(0);
}

/**
 * virLogReset:
 *
 * Reset the logging module to its default initial state
 *
 * Returns 0 if successful, and -1 in case or error
 */
int virLogReset(void) {
    if (!virLogInitialized)
        return(virLogStartup());

    virLogLock();
    virLogResetFilters();
    virLogResetOutputs();
    virLogLen = 0;
    virLogStart = 0;
    virLogEnd = 0;
    virLogDefaultPriority = VIR_LOG_DEFAULT;
    virLogUnlock();
    return(0);
}
/**
 * virLogShutdown:
 *
 * Shutdown the logging module
 */
void virLogShutdown(void) {
    if (!virLogInitialized)
        return;
    virLogLock();
    virLogResetFilters();
    virLogResetOutputs();
    virLogLen = 0;
    virLogStart = 0;
    virLogEnd = 0;
    virLogUnlock();
    virMutexDestroy(&virLogMutex);
    virLogInitialized = 0;
}

/*
 * Store a string in the ring buffer
 */
static void virLogStr(const char *str, int len) {
    int tmp;

    if (str == NULL)
        return;
    if (len <= 0)
        len = strlen(str);
    if (len > LOG_BUFFER_SIZE)
        return;
    virLogLock();

    /*
     * copy the data and reset the end, we cycle over the end of the buffer
     */
    if (virLogEnd + len >= LOG_BUFFER_SIZE) {
        tmp = LOG_BUFFER_SIZE - virLogEnd;
        memcpy(&virLogBuffer[virLogEnd], str, tmp);
        virLogBuffer[LOG_BUFFER_SIZE] = 0;
        memcpy(&virLogBuffer[0], &str[tmp], len - tmp);
        virLogEnd = len - tmp;
    } else {
        memcpy(&virLogBuffer[virLogEnd], str, len);
        virLogEnd += len;
    }
    /*
     * Update the log length, and if full move the start index
     */
    virLogLen += len;
    if (virLogLen > LOG_BUFFER_SIZE) {
        tmp = virLogLen - LOG_BUFFER_SIZE;
        virLogLen = LOG_BUFFER_SIZE;
        virLogStart += tmp;
    }
    virLogUnlock();
}

#if 0
/*
 * Output the ring buffer
 */
static int virLogDump(void *data, virLogOutputFunc f) {
    int ret = 0, tmp;

    if ((virLogLen == 0) || (f == NULL))
        return(0);
    virLogLock();
    if (virLogStart + virLogLen < LOG_BUFFER_SIZE) {
push_end:
        virLogBuffer[virLogStart + virLogLen] = 0;
        tmp = f(data, &virLogBuffer[virLogStart], virLogLen);
        if (tmp < 0) {
            ret = -1;
            goto error;
        }
        ret += tmp;
        virLogStart += tmp;
        virLogLen -= tmp;
    } else {
        tmp = LOG_BUFFER_SIZE - virLogStart;
        ret = f(data, &virLogBuffer[virLogStart], tmp);
        if (ret < 0) {
            ret = -1;
            goto error;
        }
        if (ret < tmp) {
            virLogStart += ret;
            virLogLen -= ret;
        } else {
            virLogStart = 0;
            virLogLen -= tmp;
            /* dump the second part */
            if (virLogLen > 0)
                goto push_end;
        }
    }
error:
    virLogUnlock();
    return(ret);
}
#endif

/**
 * virLogSetDefaultPriority:
 * @priority: the default priority level
 *
 * Set the default priority level, i.e. any logged data of a priority
 * equal or superior to this level will be logged, unless a specific rule
 * was defined for the log category of the message.
 *
 * Returns 0 if successful, -1 in case of error.
 */
int virLogSetDefaultPriority(int priority) {
    if ((priority < VIR_LOG_DEBUG) || (priority > VIR_LOG_ERROR)) {
        VIR_WARN0(_("Ignoring invalid log level setting."));
        return(-1);
    }
    if (!virLogInitialized)
        virLogStartup();
    virLogDefaultPriority = priority;
    return(0);
}

/**
 * virLogResetFilters:
 *
 * Removes the set of logging filters defined.
 *
 * Returns the number of filters removed
 */
static int virLogResetFilters(void) {
    int i;

    for (i = 0; i < virLogNbFilters;i++)
        VIR_FREE(virLogFilters[i].match);
    VIR_FREE(virLogFilters);
    virLogNbFilters = 0;
    return(i);
}

/**
 * virLogDefineFilter:
 * @match: the pattern to match
 * @priority: the priority to give to messages matching the pattern
 * @flags: extra flag, currently unused
 *
 * Defines a pattern used for log filtering, it allow to select or
 * reject messages independently of the default priority.
 * The filter defines a rules that will apply only to messages matching
 * the pattern (currently if @match is a substring of the message category)
 *
 * Returns -1 in case of failure or the filter number if successful
 */
int virLogDefineFilter(const char *match, int priority,
                       int flags ATTRIBUTE_UNUSED) {
    int i;
    char *mdup = NULL;

    if ((match == NULL) || (priority < VIR_LOG_DEBUG) ||
        (priority > VIR_LOG_ERROR))
        return(-1);

    virLogLock();
    for (i = 0;i < virLogNbFilters;i++) {
        if (STREQ(virLogFilters[i].match, match)) {
            virLogFilters[i].priority = priority;
            goto cleanup;
        }
    }

    mdup = strdup(match);
    if (dup == NULL) {
        i = -1;
        goto cleanup;
    }
    i = virLogNbFilters;
    if (VIR_REALLOC_N(virLogFilters, virLogNbFilters + 1)) {
        i = -1;
        VIR_FREE(mdup);
        goto cleanup;
    }
    virLogFilters[i].match = mdup;
    virLogFilters[i].priority = priority;
    virLogNbFilters++;
cleanup:
    virLogUnlock();
    return(i);
}

/**
 * virLogFiltersCheck:
 * @input: the input string
 *
 * Check the input of the message against the existing filters. Currently
 * the match is just a substring check of the category used as the input
 * string, a more subtle approach could be used instead
 *
 * Returns 0 if not matched or the new priority if found.
 */
static int virLogFiltersCheck(const char *input) {
    int ret = 0;
    int i;

    virLogLock();
    for (i = 0;i < virLogNbFilters;i++) {
        if (strstr(input, virLogFilters[i].match)) {
            ret = virLogFilters[i].priority;
            break;
        }
    }
    virLogUnlock();
    return(ret);
}

/**
 * virLogResetOutputs:
 *
 * Removes the set of logging output defined.
 *
 * Returns the number of output removed
 */
static int virLogResetOutputs(void) {
    int i;

    for (i = 0;i < virLogNbOutputs;i++) {
        if (virLogOutputs[i].c != NULL)
            virLogOutputs[i].c(virLogOutputs[i].data);
    }
    VIR_FREE(virLogOutputs);
    i = virLogNbOutputs;
    virLogNbOutputs = 0;
    return(i);
}

/**
 * virLogDefineOutput:
 * @f: the function to call to output a message
 * @f: the function to call to close the output (or NULL)
 * @data: extra data passed as first arg to the function
 * @priority: minimal priority for this filter, use 0 for none
 * @flags: extra flag, currently unused
 *
 * Defines an output function for log messages. Each message once
 * gone though filtering is emitted through each registered output.
 *
 * Returns -1 in case of failure or the output number if successful
 */
int virLogDefineOutput(virLogOutputFunc f, virLogCloseFunc c, void *data,
                       int priority, int flags ATTRIBUTE_UNUSED) {
    int ret = -1;

    if (f == NULL)
        return(-1);

    virLogLock();
    if (VIR_REALLOC_N(virLogOutputs, virLogNbOutputs + 1)) {
        goto cleanup;
    }
    ret = virLogNbOutputs++;
    virLogOutputs[ret].f = f;
    virLogOutputs[ret].c = c;
    virLogOutputs[ret].data = data;
    virLogOutputs[ret].priority = priority;
cleanup:
    virLogUnlock();
    return(ret);
}

/**
 * virLogMessage:
 * @category: where is that message coming from
 * @priority: the priority level
 * @funcname: the function emitting the (debug) message
 * @linenr: line where the message was emitted
 * @flags: extra flags, 1 if coming from the error handler
 * @fmt: the string format
 * @...: the arguments
 *
 * Call the libvirt logger with some informations. Based on the configuration
 * the message may be stored, sent to output or just discarded
 */
void virLogMessage(const char *category, int priority, const char *funcname,
                   long long linenr, int flags, const char *fmt, ...) {
    char *str = NULL;
    char *msg;
    struct timeval cur_time;
    struct tm time_info;
    int len, fprio, i, ret;

    if (!virLogInitialized)
        virLogStartup();

    if (fmt == NULL)
       return;

    /*
     * check against list of specific logging patterns
     */
    fprio = virLogFiltersCheck(category);
    if (fprio == 0) {
        if (priority < virLogDefaultPriority)
            return;
    } else if (priority < fprio)
        return;

    /*
     * serialize the error message, add level and timestamp
     */
    VIR_GET_VAR_STR(fmt, str);
    if (str == NULL)
        return;
    gettimeofday(&cur_time, NULL);
    localtime_r(&cur_time.tv_sec, &time_info);

    if ((funcname != NULL)) {
        ret = virAsprintf(&msg, "%02d:%02d:%02d.%03d: %s : %s:%lld : %s\n",
                          time_info.tm_hour, time_info.tm_min,
                          time_info.tm_sec, (int) cur_time.tv_usec / 1000,
                          virLogPriorityString(priority), funcname, linenr, str);
    } else {
        ret = virAsprintf(&msg, "%02d:%02d:%02d.%03d: %s : %s\n",
                          time_info.tm_hour, time_info.tm_min,
                          time_info.tm_sec, (int) cur_time.tv_usec / 1000,
                          virLogPriorityString(priority), str);
    }
    VIR_FREE(str);
    if (ret < 0) {
        /* apparently we're running out of memory */
        return;
    }

    /*
     * Log based on defaults, first store in the history buffer
     * then push the message on the outputs defined, if none
     * use stderr.
     * NOTE: the locking is a single point of contention for multiple
     *       threads, but avoid intermixing. Maybe set up locks per output
     *       to improve paralellism.
     */
    len = strlen(msg);
    virLogStr(msg, len);
    virLogLock();
    for (i = 0; i < virLogNbOutputs;i++) {
        if (priority >= virLogOutputs[i].priority)
            virLogOutputs[i].f(category, priority, funcname, linenr,
                               msg, len, virLogOutputs[i].data);
    }
    if ((virLogNbOutputs == 0) && (flags != 1))
        safewrite(2, msg, len);
    virLogUnlock();

    VIR_FREE(msg);
}

static int virLogOutputToFd(const char *category ATTRIBUTE_UNUSED,
                            int priority ATTRIBUTE_UNUSED,
                            const char *funcname ATTRIBUTE_UNUSED,
                            long long linenr ATTRIBUTE_UNUSED,
                            const char *str, int len, void *data) {
    int fd = (long) data;
    int ret;

    if (fd < 0)
        return(-1);
    ret = safewrite(fd, str, len);
    return(ret);
}

static void virLogCloseFd(void *data) {
    int fd = (long) data;

    if (fd >= 0)
        close(fd);
}

static int virLogAddOutputToStderr(int priority) {
    if (virLogDefineOutput(virLogOutputToFd, NULL, (void *)2L, priority, 0) < 0)
        return(-1);
    return(0);
}

static int virLogAddOutputToFile(int priority, const char *file) {
    int fd;

    fd = open(file, O_CREAT | O_TRUNC | O_WRONLY, S_IRUSR | S_IWUSR);
    if (fd < 0)
        return(-1);
    if (virLogDefineOutput(virLogOutputToFd, virLogCloseFd, (void *)(long)fd,
                           priority, 0) < 0) {
        close(fd);
        return(-1);
    }
    return(0);
}

#if HAVE_SYSLOG_H
static int virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED,
                                int priority,
                                const char *funcname ATTRIBUTE_UNUSED,
                                long long linenr ATTRIBUTE_UNUSED,
                                const char *str, int len ATTRIBUTE_UNUSED,
                                void *data ATTRIBUTE_UNUSED) {
    int prio;

    switch (priority) {
        case VIR_LOG_DEBUG:
            prio = LOG_DEBUG;
            break;
        case VIR_LOG_INFO:
            prio = LOG_INFO;
            break;
        case VIR_LOG_WARN:
            prio = LOG_WARNING;
            break;
        case VIR_LOG_ERROR:
            prio = LOG_ERR;
            break;
        default:
            prio = LOG_ERR;
    }
    syslog(prio, "%s", str);
    return(len);
}

static char *current_ident = NULL;

static void virLogCloseSyslog(void *data ATTRIBUTE_UNUSED) {
    closelog();
    VIR_FREE(current_ident);
}

static int virLogAddOutputToSyslog(int priority, const char *ident) {
    /*
     * ident needs to be kept around on Solaris
     */
    VIR_FREE(current_ident);
    current_ident = strdup(ident);
    if (current_ident == NULL)
        return(-1);

    openlog(current_ident, 0, 0);
    if (virLogDefineOutput(virLogOutputToSyslog, virLogCloseSyslog, NULL,
                           priority, 0) < 0) {
        closelog();
        VIR_FREE(current_ident);
        return(-1);
    }
    return(0);
}
#endif /* HAVE_SYSLOG_H */

#define IS_SPACE(cur)                                                   \
    ((*cur == ' ') || (*cur == '\t') || (*cur == '\n') ||               \
     (*cur == '\r') || (*cur == '\\'))

/**
 * virLogParseOutputs:
 * @outputs: string defining a (set of) output(s)
 *
 * The format for an output can be:
 *    x:stderr
 *       output goes to stderr
 *    x:syslog:name
 *       use syslog for the output and use the given name as the ident
 *    x:file:file_path
 *       output to a file, with the given filepath
 * In all case the x prefix is the minimal level, acting as a filter
 *    0: everything
 *    1: DEBUG
 *    2: INFO
 *    3: WARNING
 *    4: ERROR
 *
 * Multiple output can be defined in a single @output, they just need to be
 * separated by spaces.
 *
 * Returns the number of output parsed and installed or -1 in case of error
 */
int virLogParseOutputs(const char *outputs) {
    const char *cur = outputs, *str;
    char *name;
    int prio;
    int ret = -1;
    int count = 0;

    if (cur == NULL)
        return(-1);

    virSkipSpaces(&cur);
    while (*cur != 0) {
        prio= virParseNumber(&cur);
        if ((prio < VIR_LOG_DEBUG) || (prio > VIR_LOG_ERROR))
            goto cleanup;
        if (*cur != ':')
            goto cleanup;
        cur++;
        if (STREQLEN(cur, "stderr", 6)) {
            cur += 6;
            if (virLogAddOutputToStderr(prio) == 0)
                count++;
        } else if (STREQLEN(cur, "syslog", 6)) {
            cur += 6;
            if (*cur != ':')
                goto cleanup;
            cur++;
            str = cur;
            while ((*cur != 0) && (!IS_SPACE(cur)))
                cur++;
            if (str == cur)
                goto cleanup;
#if HAVE_SYSLOG_H
            name = strndup(str, cur - str);
            if (name == NULL)
                goto cleanup;
            if (virLogAddOutputToSyslog(prio, name) == 0)
                count++;
            VIR_FREE(name);
#endif /* HAVE_SYSLOG_H */
        } else if (STREQLEN(cur, "file", 4)) {
            cur += 4;
            if (*cur != ':')
                goto cleanup;
            cur++;
            str = cur;
            while ((*cur != 0) && (!IS_SPACE(cur)))
                cur++;
            if (str == cur)
                goto cleanup;
            name = strndup(str, cur - str);
            if (name == NULL)
                goto cleanup;
            if (virLogAddOutputToFile(prio, name) == 0)
                count++;
            VIR_FREE(name);
        } else {
            goto cleanup;
        }
        virSkipSpaces(&cur);
    }
    ret = count;
cleanup:
    if (ret == -1)
        VIR_WARN0(_("Ignoring invalid log output setting."));
    return(ret);
}

/**
 * virLogParseFilters:
 * @filters: string defining a (set of) filter(s)
 *
 * The format for a filter is:
 *    x:name
 *       where name is a match string
 * the x prefix is the minimal level where the messages should be logged
 *    1: DEBUG
 *    2: INFO
 *    3: WARNING
 *    4: ERROR
 *
 * Multiple filter can be defined in a single @filters, they just need to be
 * separated by spaces.
 *
 * Returns the number of filter parsed and installed or -1 in case of error
 */
int virLogParseFilters(const char *filters) {
    const char *cur = filters, *str;
    char *name;
    int prio;
    int ret = -1;
    int count = 0;

    if (cur == NULL)
        return(-1);

    virSkipSpaces(&cur);
    while (*cur != 0) {
        prio= virParseNumber(&cur);
        if ((prio < VIR_LOG_DEBUG) || (prio > VIR_LOG_ERROR))
            goto cleanup;
        if (*cur != ':')
            goto cleanup;
        cur++;
        str = cur;
        while ((*cur != 0) && (!IS_SPACE(cur)))
            cur++;
        if (str == cur)
            goto cleanup;
        name = strndup(str, cur - str);
        if (name == NULL)
            goto cleanup;
        if (virLogDefineFilter(name, prio, 0) >= 0)
            count++;
        VIR_FREE(name);
        virSkipSpaces(&cur);
    }
    ret = count;
cleanup:
    if (ret == -1)
        VIR_WARN0(_("Ignoring invalid log filter setting."));
    return(ret);
}

/**
 * virLogGetDefaultPriority:
 *
 * Returns the current logging priority level.
 */
int virLogGetDefaultPriority(void) {
    return (virLogDefaultPriority);
}

/**
 * virLogGetNbFilters:
 *
 * Returns the current number of defined log filters.
 */
int virLogGetNbFilters(void) {
    return (virLogNbFilters);
}

/**
 * virLogGetNbOutputs:
 *
 * Returns the current number of defined log outputs.
 */
int virLogGetNbOutputs(void) {
    return (virLogNbOutputs);
}

/**
 * virLogParseDefaultPriority:
 * @priority: string defining the desired logging level
 *
 * Parses and sets the default log priority level. It can take a string or
 * number corresponding to the following levels:
 *    1: DEBUG
 *    2: INFO
 *    3: WARNING
 *    4: ERROR
 *
 * Returns the parsed log level or -1 on error.
 */
int virLogParseDefaultPriority(const char *priority) {
    int ret = -1;

    if (STREQ(priority, "1") || STREQ(priority, "debug"))
        ret = virLogSetDefaultPriority(VIR_LOG_DEBUG);
    else if (STREQ(priority, "2") || STREQ(priority, "info"))
        ret = virLogSetDefaultPriority(VIR_LOG_INFO);
    else if (STREQ(priority, "3") || STREQ(priority, "warning"))
        ret = virLogSetDefaultPriority(VIR_LOG_WARN);
    else if (STREQ(priority, "4") || STREQ(priority, "error"))
        ret = virLogSetDefaultPriority(VIR_LOG_ERROR);
    else
        VIR_WARN0(_("Ignoring invalid log level setting"));

    return ret;
}

/**
 * virLogSetFromEnv:
 *
 * Sets virLogDefaultPriority, virLogFilters and virLogOutputs based on
 * environment variables.
 */
void virLogSetFromEnv(void) {
    char *debugEnv;

    debugEnv = getenv("LIBVIRT_DEBUG");
    if (debugEnv && *debugEnv)
        virLogParseDefaultPriority(debugEnv);
    debugEnv = getenv("LIBVIRT_LOG_FILTERS");
    if (debugEnv && *debugEnv)
        virLogParseFilters(strdup(debugEnv));
    debugEnv = getenv("LIBVIRT_LOG_OUTPUTS");
    if (debugEnv && *debugEnv)
        virLogParseOutputs(strdup(debugEnv));
}