/*

  Copyright (c) 2008-2012 Red Hat, Inc. <http://www.redhat.com>

  This file is part of GlusterFS.

  This file is licensed to you under your choice of the GNU Lesser

  General Public License, version 3 or any later version (LGPLv3 or

  later), or the GNU General Public License, version 2 (GPLv2), in all

  cases as published by the Free Software Foundation.

*/

#include <errno.h>

#include <pthread.h>

#include <stdio.h>

#include <stdarg.h>

#include <time.h>

#include <locale.h>

#include <string.h>

#include <stdlib.h>

#include <syslog.h>

#include <sys/resource.h>

#ifdef HAVE_BACKTRACE

#include <execinfo.h>

#else

#include "execinfo_compat.h"

#endif

#include <sys/stat.h>

#include "glusterfs/syscall.h"

#define GF_JSON_MSG_LENGTH 8192

#define GF_SYSLOG_CEE_FORMAT                                                   \

    "@cee: {\"msg\": \"%s\", \"gf_code\": \"%u\", \"gf_message\": \"%s\"}"

#define GF_LOG_CONTROL_FILE "/etc/glusterfs/logger.conf"

#define GF_LOG_BACKTRACE_DEPTH 5

#define GF_LOG_BACKTRACE_SIZE 4096

#define GF_LOG_TIMESTR_SIZE 256

#define GF_MAX_SLOG_PAIR_COUNT 100

#include "glusterfs/xlator.h"

#include "glusterfs/logging.h"

#include "glusterfs/defaults.h"

#include "glusterfs/glusterfs.h"

#include "glusterfs/timer.h"

#include "glusterfs/libglusterfs-messages.h"

/* Do not replace gf_log in TEST_LOG with gf_msg, as there is a slight chance

 * that it could lead to an infinite recursion.*/

#define TEST_LOG(__msg, __args...)                                             \

    gf_log("logging-infra", GF_LOG_DEBUG, __msg, ##__args);

void

gf_log_flush_timeout_cbk(void *data);

int

gf_log_inject_timer_event(glusterfs_ctx_t *ctx);

static void

gf_log_flush_extra_msgs(glusterfs_ctx_t *ctx, uint32_t new);

static char *gf_level_strings[] = {"",  /* NONE */

                                   "M", /* EMERGENCY */

                                   "A", /* ALERT */

                                   "C", /* CRITICAL */

                                   "E", /* ERROR */

                                   "W", /* WARNING */

                                   "N", /* NOTICE */

                                   "I", /* INFO */

                                   "D", /* DEBUG */

                                   "T", /* TRACE */

                                   ""};

/* Ideally this should get moved to logging.h */

struct _msg_queue {

    struct list_head msgs;

};

struct _log_msg {

    const char *msg;

    struct list_head queue;

};

void

gf_log_logrotate(int signum)

{

    glusterfs_ctx_t *ctx = NULL;

    ctx = THIS->ctx;

    if (ctx) {

        ctx->log.logrotate = 1;

        ctx->log.cmd_history_logrotate = 1;

    }

}

void

gf_log_enable_syslog(void)

{

    glusterfs_ctx_t *ctx = NULL;

    ctx = THIS->ctx;

    if (ctx)

        ctx->log.gf_log_syslog = 1;

}

void

gf_log_disable_syslog(void)

{

    glusterfs_ctx_t *ctx = NULL;

    ctx = THIS->ctx;

    if (ctx)

        ctx->log.gf_log_syslog = 0;

}

gf_loglevel_t

gf_log_get_loglevel(void)

{

    glusterfs_ctx_t *ctx = NULL;

    ctx = THIS->ctx;

    if (ctx)

        return ctx->log.loglevel;

    else

        /* return global defaults (see gf_log_globals_init) */

        return GF_LOG_INFO;

}

void

gf_log_set_loglevel(glusterfs_ctx_t *ctx, gf_loglevel_t level)

{

    if (ctx)

        ctx->log.loglevel = level;

}

int

gf_log_get_localtime(void)

{

    glusterfs_ctx_t *ctx = NULL;

    ctx = THIS->ctx;

    if (ctx)

        return ctx->log.localtime;

    else

        /* return global defaults (see gf_log_globals_init) */

        return 0;

}

void

gf_log_set_localtime(int on_off)

{

    glusterfs_ctx_t *ctx = NULL;

    ctx = THIS->ctx;

    if (ctx)

        ctx->log.localtime = on_off;

}

void

gf_log_flush(void)

{

    xlator_t *this = NULL;

    glusterfs_ctx_t *ctx = NULL;

    this = THIS;

    ctx = this->ctx;

    if (ctx && ctx->log.logger == gf_logger_glusterlog) {

        pthread_mutex_lock(&ctx->log.logfile_mutex);

        fflush(ctx->log.gf_log_logfile);

        pthread_mutex_unlock(&ctx->log.logfile_mutex);

    }

    return;

}

void

gf_log_set_xl_loglevel(void *this, gf_loglevel_t level)

{

    xlator_t *xl = this;

    if (!xl)

        return;

    xl->loglevel = level;

}

/* TODO: The following get/set functions are yet not invoked from anywhere

 * in the code. The _intention_ is to pass CLI arguments to various daemons

 * that are started, which would then invoke these set APIs as required.

 *

 * glusterd would read the defaults from its .vol file configuration shipped

 * as a part of the packages distributed.

 *

 * For any gluster* daemon that is started the shipped configuration becomes the

 * default, if a volume has to change its logging format or logger, then a

 * gluster CLI is invoked to set this property for the volume in question.

 *

 * The property is maintained by glusterd, and passed to the daemon as a CLI

 * option, IOW persistence of the option is maintained by glusterd persistent

 * storage (i.e .vol file) only

 *

 * care needs to be taken to configure and start daemons based on the versions

 * that supports these features */

gf_log_format_t

gf_log_get_logformat(void)

{

    glusterfs_ctx_t *ctx = NULL;

    ctx = THIS->ctx;

    if (ctx)

        return ctx->log.logformat;

    else

        /* return global defaluts (see gf_log_globals_init) */

        return gf_logformat_withmsgid;

}

void

gf_log_set_logformat(gf_log_format_t format)

{

    glusterfs_ctx_t *ctx = NULL;

    ctx = THIS->ctx;

    if (ctx)

        ctx->log.logformat = format;

}

gf_log_logger_t

gf_log_get_logger(void)

{

    glusterfs_ctx_t *ctx = NULL;

    ctx = THIS->ctx;

    if (ctx)

        return ctx->log.logger;

    else

        /* return global defaluts (see gf_log_globals_init) */

        return gf_logger_glusterlog;

}

void

gf_log_set_logger(gf_log_logger_t logger)

{

    glusterfs_ctx_t *ctx = NULL;

    ctx = THIS->ctx;

    if (ctx)

        ctx->log.logger = logger;

}

gf_loglevel_t

gf_log_get_xl_loglevel(void *this)

{

    xlator_t *xl = this;

    if (!xl)

        return 0;

    return xl->loglevel;

}

void

gf_log_set_log_buf_size(uint32_t buf_size)

{

    uint32_t old = 0;

    glusterfs_ctx_t *ctx = THIS->ctx;

    pthread_mutex_lock(&ctx->log.log_buf_lock);

    {

        old = ctx->log.lru_size;

        ctx->log.lru_size = buf_size;

    }

    pthread_mutex_unlock(&ctx->log.log_buf_lock);

    /* If the old size is less than/equal to the new size, then do nothing.

     *

     * But if the new size is less than the old size, then

     *   a. If the cur size of the buf is less than or equal the new size,

     *      then do nothing.

     *   b. But if the current size of the buf is greater than the new size,

     *      then flush the least recently used (cur size - new_size) msgs

     *      to disk.

     */

    if (buf_size < old)

        gf_log_flush_extra_msgs(ctx, buf_size);

}

void

gf_log_set_log_flush_timeout(uint32_t timeout)

{

    THIS->ctx->log.timeout = timeout;

}

log_buf_t *

log_buf_new()

{

    log_buf_t *buf = NULL;

    buf = mem_get0(THIS->ctx->logbuf_pool);

    return buf;

}

/* If log_buf_init() fails (indicated by a return value of -1),

 * call log_buf_destroy() to clean up memory allocated in heap and to return

 * the log_buf_t object back to its memory pool.

 */

int

log_buf_init(log_buf_t *buf, const char *domain, const char *file,

             const char *function, int32_t line, gf_loglevel_t level,

             int errnum, uint64_t msgid, char **appmsgstr, int graph_id)

{

    int ret = -1;

    if (!buf || !domain || !file || !function || !appmsgstr || !*appmsgstr)

        goto out;

    buf->msg = gf_strdup(*appmsgstr);

    if (!buf->msg)

        goto out;

    buf->msg_id = msgid;

    buf->errnum = errnum;

    buf->domain = gf_strdup(domain);

    if (!buf->domain)

        goto out;

    buf->file = gf_strdup(file);

    if (!buf->file)

        goto out;

    buf->function = gf_strdup(function);

    if (!buf->function)

        goto out;

    buf->line = line;

    buf->level = level;

    buf->refcount = 0;

    buf->graph_id = graph_id;

    INIT_LIST_HEAD(&buf->msg_list);

    ret = 0;

out:

    return ret;

}

int

log_buf_destroy(log_buf_t *buf)

{

    if (!buf)

        return -1;

    GF_FREE(buf->msg);

    GF_FREE(buf->domain);

    GF_FREE(buf->file);

    GF_FREE(buf->function);

    mem_put(buf);

    return 0;

}

static void

gf_log_rotate(glusterfs_ctx_t *ctx)

{

    int fd = -1;

    FILE *new_logfile = NULL;

    FILE *old_logfile = NULL;

    /* not involving locks on initial check to speed it up */

    if (ctx->log.logrotate) {

        /* let only one winner through on races */

        pthread_mutex_lock(&ctx->log.logfile_mutex);

        if (!ctx->log.logrotate) {

            pthread_mutex_unlock(&ctx->log.logfile_mutex);

            return;

        } else {

            ctx->log.logrotate = 0;

            pthread_mutex_unlock(&ctx->log.logfile_mutex);

        }

        fd = sys_open(ctx->log.filename, O_CREAT | O_WRONLY | O_APPEND,

                      S_IRUSR | S_IWUSR);

        if (fd < 0) {

            gf_msg("logrotate", GF_LOG_ERROR, errno, LG_MSG_FILE_OP_FAILED,

                   "failed to open "

                   "logfile");

            return;

        }

        new_logfile = fdopen(fd, "a");

        if (!new_logfile) {

            gf_msg("logrotate", GF_LOG_CRITICAL, errno, LG_MSG_FILE_OP_FAILED,

                   "failed to open logfile"

                   " %s",

                   ctx->log.filename);

            sys_close(fd);

            return;

        }

        pthread_mutex_lock(&ctx->log.logfile_mutex);

        {

            if (ctx->log.logfile)

                old_logfile = ctx->log.logfile;

            ctx->log.gf_log_logfile = ctx->log.logfile = new_logfile;

        }

        pthread_mutex_unlock(&ctx->log.logfile_mutex);

        if (old_logfile != NULL)

            fclose(old_logfile);

    }

    return;

}

void

gf_log_globals_fini(void)

{

    /* TODO: Nobody is invoking the fini, but cleanup needs to happen here,

     * needs cleanup for, log.ident, log.filename, closelog, log file close

     * rotate state, possibly under a lock */

    pthread_mutex_destroy(&THIS->ctx->log.logfile_mutex);

    pthread_mutex_destroy(&THIS->ctx->log.log_buf_lock);

}

void

gf_log_disable_suppression_before_exit(glusterfs_ctx_t *ctx)

{

    /*

     * First set log buf size to 0. This would ensure two things:

     * i. that all outstanding log messages are flushed to disk, and

     * ii. all subsequent calls to gf_msg will result in the logs getting

     *     directly flushed to disk without being buffered.

     *

     * Then, cancel the current log timer event.

     */

    gf_log_set_log_buf_size(0);

    pthread_mutex_lock(&ctx->log.log_buf_lock);

    {

        if (ctx->log.log_flush_timer) {

            gf_timer_call_cancel(ctx, ctx->log.log_flush_timer);

            ctx->log.log_flush_timer = NULL;

        }

    }

    pthread_mutex_unlock(&ctx->log.log_buf_lock);

}

/** gf_log_fini - function to perform the cleanup of the log information

 * @data - glusterfs context

 * @return: success: 0

 *          failure: -1

 */

int

gf_log_fini(void *data)

{

    glusterfs_ctx_t *ctx = data;

    int ret = 0;

    FILE *old_logfile = NULL;

    if (ctx == NULL) {

        ret = -1;

        goto out;

    }

    gf_log_disable_suppression_before_exit(ctx);

    pthread_mutex_lock(&ctx->log.logfile_mutex);

    {

        if (ctx->log.logfile) {

            old_logfile = ctx->log.logfile;

            /* Logfile needs to be set to NULL, so that any

               call to gf_log after calling gf_log_fini, will

               log the message to stderr.

            */

            ctx->log.loglevel = GF_LOG_NONE;

            ctx->log.logfile = NULL;

        }

    }

    pthread_mutex_unlock(&ctx->log.logfile_mutex);

    if (old_logfile && (fclose(old_logfile) != 0))

        ret = -1;

    GF_FREE(ctx->log.ident);

    GF_FREE(ctx->log.filename);

out:

    return ret;

}

/**

 * gf_openlog -function to open syslog specific to gluster based on

 *             existence of file /etc/glusterfs/logger.conf

 * @ident:    optional identification string similar to openlog()

 * @option:   optional value to option to openlog().  Passing -1 uses

 *            'LOG_PID | LOG_NDELAY' as default

 * @facility: optional facility code similar to openlog().  Passing -1

 *            uses LOG_DAEMON as default

 *

 * @return: void

 */

void

gf_openlog(const char *ident, int option, int facility)

{

    int _option = option;

    int _facility = facility;

    if (-1 == _option) {

        _option = LOG_PID | LOG_NDELAY;

    }

    if (-1 == _facility) {

        _facility = LOG_LOCAL1;

    }

    /* TODO: Should check for errors here and return appropriately */

    setlocale(LC_ALL, "");

    setlocale(LC_NUMERIC, "C"); /* C-locale for strtod, ... */

    /* close the previous syslog if open as we are changing settings */

    closelog();

    openlog(ident, _option, _facility);

}

/**

 * _json_escape -function to convert string to json encoded string

 * @str: input string

 * @buf: buffer to store encoded string

 * @len: length of @buf

 *

 * @return: success: last unprocessed character position by pointer in @str

 *          failure: NULL

 *

 * Internal function. Heavily inspired by _ul_str_escape() function in

 * libumberlog

 *

 * Sample output:

 * [1] str = "devel error"

 *     buf = "devel error"

 * [2] str = "devel	error"

 *     buf = "devel\terror"

 * [3] str = "I/O error on "/tmp/foo" file"

 *     buf = "I/O error on \"/tmp/foo\" file"

 * [4] str = "I/O error?on /tmp/bar file"

 *     buf = "I/O error\u001bon /tmp/bar file"

 *

 */

char *

_json_escape(const char *str, char *buf, size_t len)

{

    static const unsigned char json_exceptions[UCHAR_MAX + 1] = {

        [0x01] = 1, [0x02] = 1, [0x03] = 1, [0x04] = 1, [0x05] = 1, [0x06] = 1,

        [0x07] = 1, [0x08] = 1, [0x09] = 1, [0x0a] = 1, [0x0b] = 1, [0x0c] = 1,

        [0x0d] = 1, [0x0e] = 1, [0x0f] = 1, [0x10] = 1, [0x11] = 1, [0x12] = 1,

        [0x13] = 1, [0x14] = 1, [0x15] = 1, [0x16] = 1, [0x17] = 1, [0x18] = 1,

        [0x19] = 1, [0x1a] = 1, [0x1b] = 1, [0x1c] = 1, [0x1d] = 1, [0x1e] = 1,

        [0x1f] = 1, ['\\'] = 1, ['"'] = 1};

    static const char json_hex_chars[16] = "0123456789abcdef";

    unsigned char *p = NULL;

    size_t pos = 0;

    if (!str || !buf || len <= 0) {

        return NULL;

    }

    for (p = (unsigned char *)str; *p && (pos + 1) < len; p++) {

        if (json_exceptions[*p] == 0) {

            buf[pos++] = *p;

            continue;

        }

        if ((pos + 2) >= len) {

            break;

        }

        switch (*p) {

            case '\b':

                buf[pos++] = '\\';

                buf[pos++] = 'b';

                break;

            case '\n':

                buf[pos++] = '\\';

                buf[pos++] = 'n';

                break;

            case '\r':

                buf[pos++] = '\\';

                buf[pos++] = 'r';

                break;

            case '\t':

                buf[pos++] = '\\';

                buf[pos++] = 't';

                break;

            case '\\':

                buf[pos++] = '\\';

                buf[pos++] = '\\';

                break;

            case '"':

                buf[pos++] = '\\';

                buf[pos++] = '"';

                break;

            default:

                if ((pos + 6) >= len) {

                    buf[pos] = '\0';

                    return (char *)p;

                }

                buf[pos++] = '\\';

                buf[pos++] = 'u';

                buf[pos++] = '0';

                buf[pos++] = '0';

                buf[pos++] = json_hex_chars[(*p) >> 4];

                buf[pos++] = json_hex_chars[(*p) & 0xf];

                break;

        }

    }

    buf[pos] = '\0';

    return (char *)p;

}

/**

 * gf_syslog -function to submit message to syslog specific to gluster

 * @facility_priority: facility_priority of syslog()

 * @format:            optional format string to syslog()

 *

 * @return: void

 */

void

gf_syslog(int facility_priority, char *format, ...)

{

    char *msg = NULL;

    char json_msg[GF_JSON_MSG_LENGTH];

    GF_UNUSED char *p = NULL;

    va_list ap;

    GF_ASSERT(format);

    va_start(ap, format);

    if (vasprintf(&msg, format, ap) != -1) {

        p = _json_escape(msg, json_msg, GF_JSON_MSG_LENGTH);

        syslog(facility_priority, "%s", msg);

        free(msg);

    } else

        syslog(GF_LOG_CRITICAL, "vasprintf() failed, out of memory?");

    va_end(ap);

}

void

gf_log_globals_init(void *data, gf_loglevel_t level)

{

    glusterfs_ctx_t *ctx = data;

    pthread_mutex_init(&ctx->log.logfile_mutex, NULL);

    ctx->log.loglevel = level;

    ctx->log.gf_log_syslog = 1;

    ctx->log.sys_log_level = GF_LOG_CRITICAL;

    ctx->log.logger = gf_logger_glusterlog;

    ctx->log.logformat = gf_logformat_withmsgid;

    ctx->log.lru_size = GF_LOG_LRU_BUFSIZE_DEFAULT;

    ctx->log.timeout = GF_LOG_FLUSH_TIMEOUT_DEFAULT;

    ctx->log.localtime = GF_LOG_LOCALTIME_DEFAULT;

    pthread_mutex_init(&ctx->log.log_buf_lock, NULL);

    INIT_LIST_HEAD(&ctx->log.lru_queue);

#ifdef GF_LINUX_HOST_OS

    /* For the 'syslog' output. one can grep 'GlusterFS' in syslog

       for serious logs */

    openlog("GlusterFS", LOG_PID, LOG_DAEMON);

#endif

}

int

gf_log_init(void *data, const char *file, const char *ident)

{

    glusterfs_ctx_t *ctx = NULL;

    int fd = -1;

    struct stat buf;

    ctx = data;

    if (ctx == NULL) {

        fprintf(stderr, "ERROR: ctx is NULL\n");

        return -1;

    }

    if (ident) {

        GF_FREE(ctx->log.ident);

        ctx->log.ident = gf_strdup(ident);

    }

    /* we keep the files and the syslog open, so that on logger change, we

     * are ready to log anywhere, that the new value specifies */

    if (ctx->log.ident) {

        gf_openlog(ctx->log.ident, -1, LOG_DAEMON);

    } else {

        gf_openlog(NULL, -1, LOG_DAEMON);

    }

    /* TODO: make FACILITY configurable than LOG_DAEMON */

    if (sys_stat(GF_LOG_CONTROL_FILE, &buf) == 0) {

        /* use syslog logging */

        ctx->log.log_control_file_found = 1;

    } else {

        /* use old style logging */

        ctx->log.log_control_file_found = 0;

    }

    if (!file) {

        fprintf(stderr, "ERROR: no filename specified\n");

        return -1;

    }

    /* free the (possible) previous filename */

    GF_FREE(ctx->log.filename);

    ctx->log.filename = NULL;

    /* close and reopen logfile for log rotate */

    if (ctx->log.logfile) {

        fclose(ctx->log.logfile);

        ctx->log.logfile = NULL;

        ctx->log.gf_log_logfile = NULL;

    }

    if (strcmp(file, "-") == 0) {

        int dupfd = -1;

        ctx->log.filename = gf_strdup("/dev/stderr");

        if (!ctx->log.filename) {

            fprintf(stderr, "ERROR: strdup failed\n");

            return -1;

        }

        dupfd = dup(fileno(stderr));

        if (dupfd == -1) {

            fprintf(stderr, "ERROR: could not dup %d (%s)\n", fileno(stderr),

                    strerror(errno));

            return -1;

        }

        ctx->log.logfile = fdopen(dupfd, "a");

        if (!ctx->log.logfile) {

            fprintf(stderr, "ERROR: could not fdopen on %d (%s)\n", dupfd,

                    strerror(errno));

            sys_close(dupfd);

            return -1;

        }

    } else {

        /* Also create parent dir */

        char *logdir = gf_strdup(file);

        if (!logdir) {

            return -1;

        }

        char *tmp_index = rindex(logdir, '/');

        if (tmp_index) {

            tmp_index[0] = '\0';

        }

        if (mkdir_p(logdir, 0755, true)) {

            /* EEXIST is handled in mkdir_p() itself */

            gf_msg("logging", GF_LOG_ERROR, 0, LG_MSG_STRDUP_ERROR,

                   "failed to create metrics dir %s (%s)", logdir,

                   strerror(errno));

            GF_FREE(logdir);

            return -1;

        }

        /* no need of this variable */

        GF_FREE(logdir);

        ctx->log.filename = gf_strdup(file);

        if (!ctx->log.filename) {

            fprintf(stderr,

                    "ERROR: updating log-filename failed: "

                    "%s\n",

                    strerror(errno));

            return -1;

        }

        fd = sys_open(file, O_CREAT | O_WRONLY | O_APPEND, S_IRUSR | S_IWUSR);

        if (fd < 0) {

            fprintf(stderr,

                    "ERROR: failed to create logfile"

                    " \"%s\" (%s)\n",

                    file, strerror(errno));

            return -1;

        }

        ctx->log.logfile = fdopen(fd, "a");

        if (!ctx->log.logfile) {

            fprintf(stderr,

                    "ERROR: failed to open logfile \"%s\" "

                    "(%s)\n",

                    file, strerror(errno));

            sys_close(fd);

            return -1;

        }

    }

    ctx->log.gf_log_logfile = ctx->log.logfile;

    return 0;

}

void

set_sys_log_level(gf_loglevel_t level)

{

    glusterfs_ctx_t *ctx = NULL;

    ctx = THIS->ctx;

    if (ctx)

        ctx->log.sys_log_level = level;

}

/* Check if we should be logging

 * Return value: _gf_false : Print the log

 *               _gf_true : Do not Print the log

 */

static gf_boolean_t

skip_logging(xlator_t *this, gf_loglevel_t level)

{

    gf_boolean_t ret = _gf_false;

    gf_loglevel_t existing_level = GF_LOG_NONE;

    if (level == GF_LOG_NONE) {

        ret = _gf_true;

        goto out;

    }

    existing_level = this->loglevel ? this->loglevel : this->ctx->log.loglevel;

    if (level > existing_level) {

        ret = _gf_true;

        goto out;

    }

out:

    return ret;

}

int

_gf_log_callingfn(const char *domain, const char *file, const char *function,

                  int line, gf_loglevel_t level, const char *fmt, ...)

{

    const char *basename = NULL;

    xlator_t *this = NULL;

    char *logline = NULL;

    char *msg = NULL;

    char timestr[256] = {

        0,

    };

    char *callstr = NULL;

    struct timeval tv = {

        0,

    };

    int ret = 0;

    va_list ap;

    glusterfs_ctx_t *ctx = NULL;

    this = THIS;

    ctx = this->ctx;

    if (!ctx)

        goto out;

    if (skip_logging(this, level))

        goto out;

    static char *level_strings[] = {"",  /* NONE */

                                    "M", /* EMERGENCY */

                                    "A", /* ALERT */

                                    "C", /* CRITICAL */

                                    "E", /* ERROR */

                                    "W", /* WARNING */

                                    "N", /* NOTICE */

                                    "I", /* INFO */

                                    "D", /* DEBUG */