summaryrefslogtreecommitdiffstats
path: root/libglusterfs/src/logging.c
diff options
context:
space:
mode:
Diffstat (limited to 'libglusterfs/src/logging.c')
-rw-r--r--libglusterfs/src/logging.c2756
1 files changed, 2243 insertions, 513 deletions
diff --git a/libglusterfs/src/logging.c b/libglusterfs/src/logging.c
index 6071269e01c..a930d3e3b63 100644
--- a/libglusterfs/src/logging.c
+++ b/libglusterfs/src/logging.c
@@ -8,11 +8,6 @@
cases as published by the Free Software Foundation.
*/
-#ifndef _CONFIG_H
-#define _CONFIG_H
-#include "config.h"
-#endif
-
#include <errno.h>
#include <pthread.h>
#include <stdio.h>
@@ -21,696 +16,2431 @@
#include <locale.h>
#include <string.h>
#include <stdlib.h>
-
-#include "xlator.h"
-#include "logging.h"
-#include "defaults.h"
-
-#ifdef GF_LINUX_HOST_OS
#include <syslog.h>
-#endif
+#include <sys/resource.h>
#ifdef HAVE_BACKTRACE
#include <execinfo.h>
+#else
+#include "execinfo_compat.h"
#endif
+#include <sys/stat.h>
-static pthread_mutex_t logfile_mutex;
-static char *filename = NULL;
-static uint8_t logrotate = 0;
-static FILE *logfile = NULL;
-static gf_loglevel_t loglevel = GF_LOG_INFO;
-static int gf_log_syslog = 1;
-static gf_loglevel_t sys_log_level = GF_LOG_CRITICAL;
+#include "glusterfs/syscall.h"
-char gf_log_xl_log_set;
-gf_loglevel_t gf_log_loglevel = GF_LOG_INFO; /* extern'd */
-FILE *gf_log_logfile;
+#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_MAX_SLOG_PAIR_COUNT 100
-static char *cmd_log_filename = NULL;
-static FILE *cmdlogfile = NULL;
+#include "glusterfs/logging.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);
+
+static 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 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);
+static void
+gf_log_rotate(glusterfs_ctx_t *ctx);
+
+static char gf_level_strings[] = {
+ ' ', /* NONE */
+ 'M', /* EMERGENCY */
+ 'A', /* ALERT */
+ 'C', /* CRITICAL */
+ 'E', /* ERROR */
+ 'W', /* WARNING */
+ 'N', /* NOTICE */
+ 'I', /* INFO */
+ 'D', /* DEBUG */
+ 'T', /* TRACE */
+};
void
-gf_log_logrotate (int signum)
+gf_log_logrotate(int signum)
{
- logrotate = 1;
+ if (THIS->ctx) {
+ THIS->ctx->log.logrotate = 1;
+ THIS->ctx->log.cmd_history_logrotate = 1;
+ }
}
void
-gf_log_enable_syslog (void)
+gf_log_enable_syslog(void)
{
- gf_log_syslog = 1;
+ if (THIS->ctx)
+ THIS->ctx->log.gf_log_syslog = 1;
}
void
-gf_log_disable_syslog (void)
+gf_log_disable_syslog(void)
{
- gf_log_syslog = 0;
+ if (THIS->ctx)
+ THIS->ctx->log.gf_log_syslog = 0;
}
gf_loglevel_t
-gf_log_get_loglevel (void)
+gf_log_get_loglevel(void)
{
- return loglevel;
+ if (THIS->ctx)
+ return THIS->ctx->log.loglevel;
+ else
+ /* return global defaults (see gf_log_globals_init) */
+ return GF_LOG_INFO;
}
void
-gf_log_set_loglevel (gf_loglevel_t level)
+gf_log_set_loglevel(glusterfs_ctx_t *ctx, gf_loglevel_t level)
{
- gf_log_loglevel = loglevel = level;
+ if (ctx)
+ ctx->log.loglevel = level;
}
+int
+gf_log_get_localtime(void)
+{
+ if (THIS->ctx)
+ return THIS->ctx->log.localtime;
+ else
+ /* return global defaults (see gf_log_globals_init) */
+ return 0;
+}
-gf_loglevel_t
-gf_log_get_xl_loglevel (void *this)
+void
+gf_log_set_localtime(int on_off)
{
- xlator_t *xl = this;
- if (!xl)
- return 0;
- return xl->loglevel;
+ if (THIS->ctx)
+ THIS->ctx->log.localtime = on_off;
}
void
-gf_log_set_xl_loglevel (void *this, gf_loglevel_t level)
+gf_log_flush(void)
{
- xlator_t *xl = this;
- if (!xl)
- return;
- gf_log_xl_log_set = 1;
- xl->loglevel = level;
+ xlator_t *this = THIS;
+ glusterfs_ctx_t *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_fini (void)
+gf_log_set_xl_loglevel(void *this, gf_loglevel_t level)
{
- pthread_mutex_destroy (&logfile_mutex);
+ 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 */
void
-gf_log_globals_init (void)
+gf_log_set_logformat(gf_log_format_t format)
{
- pthread_mutex_init (&logfile_mutex, NULL);
+ if (THIS->ctx)
+ THIS->ctx->log.logformat = format;
+}
-#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
+void
+gf_log_set_logger(gf_log_logger_t logger)
+{
+ if (THIS->ctx)
+ THIS->ctx->log.logger = logger;
}
-int
-gf_log_init (const char *file)
+gf_loglevel_t
+gf_log_get_xl_loglevel(void *this)
{
- int fd = -1;
+ xlator_t *xl = this;
+ if (!xl)
+ return 0;
+ return xl->loglevel;
+}
- if (!file){
- fprintf (stderr, "ERROR: no filename specified\n");
- return -1;
- }
+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);
+}
- if (strcmp (file, "-") == 0) {
- gf_log_logfile = stderr;
+void
+gf_log_set_log_flush_timeout(uint32_t timeout)
+{
+ THIS->ctx->log.timeout = timeout;
+}
- return 0;
- }
+/* 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.
+ */
+static 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;
- filename = gf_strdup (file);
- if (!filename) {
- fprintf (stderr, "ERROR: updating log-filename failed: %s\n",
- strerror (errno));
- return -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;
+}
+
+static 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 = open (file, O_CREAT | O_RDONLY, S_IRUSR | S_IWUSR);
+ fd = sys_open(ctx->log.filename, 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;
+ gf_smsg("logrotate", GF_LOG_ERROR, errno,
+ LG_MSG_OPEN_LOGFILE_FAILED, NULL);
+ return;
}
- close (fd);
- logfile = fopen (file, "a");
- if (!logfile){
- fprintf (stderr, "ERROR: failed to open logfile \"%s\" (%s)\n",
- file, strerror (errno));
- return -1;
+ new_logfile = fdopen(fd, "a");
+ if (!new_logfile) {
+ gf_smsg("logrotate", GF_LOG_CRITICAL, errno,
+ LG_MSG_OPEN_LOGFILE_FAILED, "filename=%s",
+ ctx->log.filename, NULL);
+ sys_close(fd);
+ return;
}
- gf_log_logfile = logfile;
-
- return 0;
-}
-
+ 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);
-struct _msg_queue {
- struct list_head msgs;
-};
+ if (old_logfile != NULL)
+ fclose(old_logfile);
+ }
-struct _log_msg {
- const char *msg;
- struct list_head queue;
-};
+ 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_lock (void)
+gf_log_disable_suppression_before_exit(glusterfs_ctx_t *ctx)
{
- pthread_mutex_lock (&logfile_mutex);
+ /*
+ * 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);
-void
-gf_log_unlock (void)
+ 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
+ */
+static void
+gf_openlog(const char *ident, int option, int facility)
{
- pthread_mutex_unlock (&logfile_mutex);
+ 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 erroron /tmp/bar file"
+ * buf = "I/O error\u001bon /tmp/bar file"
+ *
+ */
+static 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;
+ }
-void
-gf_log_cleanup (void)
+ 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
+ */
+static void
+gf_syslog(int facility_priority, char *format, ...)
{
- pthread_mutex_destroy (&logfile_mutex);
+ 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
-set_sys_log_level (gf_loglevel_t level)
+gf_log_globals_init(void *data, gf_loglevel_t level)
{
- sys_log_level = 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_nomem (const char *domain, const char *file,
- const char *function, int line, gf_loglevel_t level,
- size_t size)
-{
- const char *basename = NULL;
- xlator_t *this = NULL;
- struct timeval tv = {0,};
- int ret = 0;
- char msg[8092] = {0,};
- char timestr[256] = {0,};
- char callstr[4096] = {0,};
-
- this = THIS;
-
- if (gf_log_xl_log_set) {
- if (this->loglevel && (level > this->loglevel))
- goto out;
- else if (level > gf_log_loglevel)
- goto out;
- }
-
- static char *level_strings[] = {"", /* NONE */
- "M", /* EMERGENCY */
- "A", /* ALERT */
- "C", /* CRITICAL */
- "E", /* ERROR */
- "W", /* WARNING */
- "N", /* NOTICE */
- "I", /* INFO */
- "D", /* DEBUG */
- "T", /* TRACE */
- ""};
-
- if (!domain || !file || !function) {
- fprintf (stderr,
- "logging: %s:%s():%d: invalid argument\n",
- __FILE__, __PRETTY_FUNCTION__, __LINE__);
- return -1;
+gf_log_init(void *data, const char *file, const char *ident)
+{
+ glusterfs_ctx_t *ctx = data;
+ int fd = -1;
+ struct stat buf;
+
+ 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;
}
-#if HAVE_BACKTRACE
- /* Print 'calling function' */
- do {
- void *array[5];
- char **callingfn = NULL;
- size_t bt_size = 0;
-
- bt_size = backtrace (array, 5);
- if (bt_size)
- callingfn = backtrace_symbols (&array[2], bt_size-2);
- if (!callingfn)
- break;
-
- if (bt_size == 5)
- snprintf (callstr, 4096, "(-->%s (-->%s (-->%s)))",
- callingfn[2], callingfn[1], callingfn[0]);
- if (bt_size == 4)
- snprintf (callstr, 4096, "(-->%s (-->%s))",
- callingfn[1], callingfn[0]);
- if (bt_size == 3)
- snprintf (callstr, 4096, "(-->%s)", callingfn[0]);
-
- free (callingfn);
- } while (0);
-#endif /* HAVE_BACKTRACE */
-
- ret = gettimeofday (&tv, NULL);
- if (-1 == ret)
- goto out;
- gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
- snprintf (timestr + strlen (timestr), sizeof timestr - strlen (timestr),
- ".%"GF_PRI_SUSECONDS, tv.tv_usec);
-
- basename = strrchr (file, '/');
- if (basename)
- basename++;
- else
- basename = file;
-
- ret = sprintf (msg, "[%s] %s [%s:%d:%s] %s %s: no memory "
- "available for size (%"GF_PRI_SIZET")",
- timestr, level_strings[level],
- basename, line, function, callstr,
- domain, size);
- if (-1 == ret) {
- goto out;
+ dupfd = dup(fileno(stderr));
+ if (dupfd == -1) {
+ fprintf(stderr, "ERROR: could not dup %d (%s)\n", fileno(stderr),
+ strerror(errno));
+ return -1;
}
- pthread_mutex_lock (&logfile_mutex);
- {
- if (logfile) {
- fprintf (logfile, "%s\n", msg);
- fflush (logfile);
- } else {
- fprintf (stderr, "%s\n", msg);
- }
+ 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_smsg("logging", GF_LOG_ERROR, 0, LG_MSG_STRDUP_ERROR,
+ "logdir=%s", logdir, "errno=%s", strerror(errno), NULL);
+ 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;
+ }
-#ifdef GF_LINUX_HOST_OS
- /* We want only serious log in 'syslog', not our debug
- and trace logs */
- if (gf_log_syslog && level && (level <= sys_log_level))
- syslog ((level-1), "%s\n", msg);
-#endif
+ 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;
}
- pthread_mutex_unlock (&logfile_mutex);
-out:
- return ret;
- }
+ 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)
+{
+ if (THIS->ctx)
+ THIS->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_loglevel_t existing_level = this->loglevel ? this->loglevel
+ : this->ctx->log.loglevel;
+ if (level > existing_level) {
+ return _gf_true;
+ }
+
+ if (level == GF_LOG_NONE) {
+ return _gf_true;
+ }
+
+ return _gf_false;
+}
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 *str1 = NULL;
- char *str2 = NULL;
- char *msg = NULL;
- char timestr[256] = {0,};
- char callstr[4096] = {0,};
- struct timeval tv = {0,};
- size_t len = 0;
- int ret = 0;
- va_list ap;
-
- this = THIS;
-
- if (gf_log_xl_log_set) {
- if (this->loglevel && (level > this->loglevel))
- goto out;
- else if (level > gf_log_loglevel)
- goto out;
- }
-
- static char *level_strings[] = {"", /* NONE */
- "M", /* EMERGENCY */
- "A", /* ALERT */
- "C", /* CRITICAL */
- "E", /* ERROR */
- "W", /* WARNING */
- "N", /* NOTICE */
- "I", /* INFO */
- "D", /* DEBUG */
- "T", /* TRACE */
- ""};
-
- if (!domain || !file || !function || !fmt) {
- fprintf (stderr,
- "logging: %s:%s():%d: invalid argument\n",
- __FILE__, __PRETTY_FUNCTION__, __LINE__);
- return -1;
+_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 = THIS;
+ char *logline = NULL;
+ char *msg = NULL;
+ char timestr[GF_TIMESTR_SIZE] = {
+ 0,
+ };
+ char *callstr = NULL;
+ struct timeval tv = {
+ 0,
+ };
+ int ret = 0;
+ va_list ap;
+ glusterfs_ctx_t *ctx = this->ctx;
+
+ if (!ctx)
+ goto out;
+
+ if (skip_logging(this, level))
+ goto out;
+
+ if (!domain || !file || !function || !fmt) {
+ fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__,
+ __PRETTY_FUNCTION__, __LINE__);
+ return -1;
+ }
+
+ basename = strrchr(file, '/');
+ if (basename)
+ basename++;
+ else
+ basename = file;
+
+ /*Saving the backtrace to pre-allocated ctx->btbuf
+ * to avoid allocating memory from the heap*/
+ callstr = gf_backtrace_save(NULL);
+
+ va_start(ap, fmt);
+ ret = vasprintf(&msg, fmt, ap);
+ va_end(ap);
+ if (-1 == ret) {
+ goto out;
+ }
+
+ if (ctx->log.log_control_file_found) {
+ int priority;
+ /* treat GF_LOG_TRACE and GF_LOG_NONE as LOG_DEBUG and
+ other level as is */
+ if (GF_LOG_TRACE == level || GF_LOG_NONE == level) {
+ priority = LOG_DEBUG;
+ } else {
+ priority = level - 1;
}
-#if HAVE_BACKTRACE
- /* Print 'calling function' */
- do {
- void *array[5];
- char **callingfn = NULL;
- size_t size = 0;
-
- size = backtrace (array, 5);
- if (size)
- callingfn = backtrace_symbols (&array[2], size-2);
- if (!callingfn)
- break;
-
- if (size == 5)
- snprintf (callstr, 4096, "(-->%s (-->%s (-->%s)))",
- callingfn[2], callingfn[1], callingfn[0]);
- if (size == 4)
- snprintf (callstr, 4096, "(-->%s (-->%s))",
- callingfn[1], callingfn[0]);
- if (size == 3)
- snprintf (callstr, 4096, "(-->%s)", callingfn[0]);
-
- free (callingfn);
- } while (0);
-#endif /* HAVE_BACKTRACE */
-
- ret = gettimeofday (&tv, NULL);
- if (-1 == ret)
- goto out;
- va_start (ap, fmt);
- gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
- snprintf (timestr + strlen (timestr), sizeof timestr - strlen (timestr),
- ".%"GF_PRI_SUSECONDS, tv.tv_usec);
-
- basename = strrchr (file, '/');
- if (basename)
- basename++;
- else
- basename = file;
-
- ret = gf_asprintf (&str1, "[%s] %s [%s:%d:%s] %s %d-%s: ",
- timestr, level_strings[level],
- basename, line, function, callstr,
- ((this->graph) ? this->graph->id:0), domain);
- if (-1 == ret) {
- goto out;
+ gf_syslog(priority, "[%s:%d:%s] %s %d-%s: %s", basename, line, function,
+ callstr, ((this->graph) ? this->graph->id : 0), domain, msg);
+
+ goto out;
+ }
+
+ ret = gettimeofday(&tv, NULL);
+ if (-1 == ret)
+ goto out;
+
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
+
+ ret = gf_asprintf(&logline, "[%s] %c [%s:%d:%s] %s %d-%s: %s\n", timestr,
+ gf_level_strings[level], basename, line, function,
+ callstr, ((this->graph) ? this->graph->id : 0), domain,
+ msg);
+ if (-1 == ret) {
+ goto out;
+ }
+
+ pthread_mutex_lock(&ctx->log.logfile_mutex);
+ {
+ if (ctx->log.logfile) {
+ fputs(logline, ctx->log.logfile);
+ fflush(ctx->log.logfile);
+ } else if (ctx->log.loglevel >= level) {
+ fputs(logline, stderr);
+ fflush(stderr);
}
- ret = vasprintf (&str2, fmt, ap);
- if (-1 == ret) {
- goto out;
- }
+#ifdef GF_LINUX_HOST_OS
+ /* We want only serious log in 'syslog', not our debug
+ and trace logs */
+ if (ctx->log.gf_log_syslog && level &&
+ (level <= ctx->log.sys_log_level))
+ syslog((level - 1), "%s", logline);
+#endif
+ }
- va_end (ap);
+ pthread_mutex_unlock(&ctx->log.logfile_mutex);
- len = strlen (str1);
- msg = GF_MALLOC (len + strlen (str2) + 1, gf_common_mt_char);
+out:
- strcpy (msg, str1);
- strcpy (msg + len, str2);
+ GF_FREE(logline);
- pthread_mutex_lock (&logfile_mutex);
- {
- if (logfile) {
- fprintf (logfile, "%s\n", msg);
- fflush (logfile);
+ FREE(msg);
+
+ return ret;
+}
+
+static int
+_gf_msg_plain_internal(gf_loglevel_t level, const char *msg)
+{
+ xlator_t *this = NULL;
+ glusterfs_ctx_t *ctx = NULL;
+ int priority;
+
+ this = THIS;
+ ctx = this->ctx;
+
+ /* log to the configured logging service */
+ switch (ctx->log.logger) {
+ case gf_logger_syslog:
+ if (ctx->log.log_control_file_found && ctx->log.gf_log_syslog) {
+ SET_LOG_PRIO(level, priority);
+
+ syslog(priority, "%s", msg);
+ break;
+ }
+ /* NOTE: If syslog control file is absent, which is another
+ * way to control logging to syslog, then we will fall through
+ * to the gluster log. The ideal way to do things would be to
+ * not have the extra control file check */
+ case gf_logger_glusterlog:
+ pthread_mutex_lock(&ctx->log.logfile_mutex);
+ {
+ if (ctx->log.logfile) {
+ fprintf(ctx->log.logfile, "%s\n", msg);
+ fflush(ctx->log.logfile);
} else {
- fprintf (stderr, "%s\n", msg);
+ fprintf(stderr, "%s\n", msg);
+ fflush(stderr);
}
#ifdef GF_LINUX_HOST_OS
- /* We want only serious log in 'syslog', not our debug
- and trace logs */
- if (gf_log_syslog && level && (level <= sys_log_level))
- syslog ((level-1), "%s\n", msg);
+ /* We want only serious logs in 'syslog', not our debug
+ * and trace logs */
+ if (ctx->log.gf_log_syslog && level &&
+ (level <= ctx->log.sys_log_level))
+ syslog((level - 1), "%s\n", msg);
#endif
- }
+ }
+ pthread_mutex_unlock(&ctx->log.logfile_mutex);
+
+ break;
+ }
+
+ return 0;
+}
+
+int
+_gf_msg_plain(gf_loglevel_t level, const char *fmt, ...)
+{
+ xlator_t *this = NULL;
+ int ret = 0;
+ va_list ap;
+ char *msg = NULL;
+ glusterfs_ctx_t *ctx = NULL;
+
+ this = THIS;
+ ctx = this->ctx;
+
+ if (!ctx)
+ goto out;
+
+ if (skip_logging(this, level))
+ goto out;
+
+ va_start(ap, fmt);
+ ret = vasprintf(&msg, fmt, ap);
+ va_end(ap);
+ if (-1 == ret) {
+ goto out;
+ }
- pthread_mutex_unlock (&logfile_mutex);
+ ret = _gf_msg_plain_internal(level, msg);
+
+ FREE(msg);
out:
- if (msg)
- GF_FREE (msg);
+ return ret;
+}
+
+int
+_gf_msg_vplain(gf_loglevel_t level, const char *fmt, va_list ap)
+{
+ xlator_t *this = NULL;
+ int ret = 0;
+ char *msg = NULL;
+ glusterfs_ctx_t *ctx = NULL;
- if (str1)
- GF_FREE (str1);
+ this = THIS;
+ ctx = this->ctx;
- if (str2)
- FREE (str2);
+ if (!ctx)
+ goto out;
- return ret;
+ if (skip_logging(this, level))
+ goto out;
+
+ ret = vasprintf(&msg, fmt, ap);
+ if (-1 == ret) {
+ goto out;
+ }
+
+ ret = _gf_msg_plain_internal(level, msg);
+
+ FREE(msg);
+out:
+ return ret;
}
int
-_gf_log (const char *domain, const char *file, const char *function, int line,
- gf_loglevel_t level, const char *fmt, ...)
-{
- const char *basename = NULL;
- FILE *new_logfile = NULL;
- va_list ap;
- char timestr[256] = {0,};
- struct timeval tv = {0,};
- char *str1 = NULL;
- char *str2 = NULL;
- char *msg = NULL;
- size_t len = 0;
- int ret = 0;
- int fd = -1;
- xlator_t *this = NULL;
-
- this = THIS;
-
- if (gf_log_xl_log_set) {
- if (this->loglevel && (level > this->loglevel))
- goto out;
- else if (level > gf_log_loglevel)
- goto out;
- }
-
- static char *level_strings[] = {"", /* NONE */
- "M", /* EMERGENCY */
- "A", /* ALERT */
- "C", /* CRITICAL */
- "E", /* ERROR */
- "W", /* WARNING */
- "N", /* NOTICE */
- "I", /* INFO */
- "D", /* DEBUG */
- "T", /* TRACE */
- ""};
-
- if (!domain || !file || !function || !fmt) {
- fprintf (stderr,
- "logging: %s:%s():%d: invalid argument\n",
- __FILE__, __PRETTY_FUNCTION__, __LINE__);
- return -1;
+_gf_msg_plain_nomem(gf_loglevel_t level, const char *msg)
+{
+ xlator_t *this = NULL;
+ int ret = 0;
+ glusterfs_ctx_t *ctx = NULL;
+
+ this = THIS;
+ ctx = this->ctx;
+
+ if (!ctx)
+ goto out;
+
+ if (skip_logging(this, level))
+ goto out;
+
+ ret = _gf_msg_plain_internal(level, msg);
+
+out:
+ return ret;
+}
+
+void
+_gf_msg_backtrace_nomem(gf_loglevel_t level, int stacksize)
+{
+ xlator_t *this = NULL;
+ glusterfs_ctx_t *ctx = NULL;
+ void *array[200];
+ size_t bt_size = 0;
+ int fd = -1;
+
+ this = THIS;
+ ctx = this->ctx;
+
+ if (!ctx)
+ goto out;
+
+ /* syslog does not have fd support, hence no no-mem variant */
+ if (ctx->log.logger != gf_logger_glusterlog)
+ goto out;
+
+ if (skip_logging(this, level))
+ goto out;
+
+ bt_size = backtrace(array, ((stacksize <= 200) ? stacksize : 200));
+ if (!bt_size)
+ goto out;
+ pthread_mutex_lock(&ctx->log.logfile_mutex);
+ {
+ fd = ctx->log.logfile ? fileno(ctx->log.logfile) : fileno(stderr);
+ if (fd != -1) {
+ /* print to the file fd, to prevent any
+ allocations from backtrace_symbols
+ */
+ backtrace_symbols_fd(&array[0], bt_size, fd);
}
+ }
+ pthread_mutex_unlock(&ctx->log.logfile_mutex);
+out:
+ return;
+}
- if (logrotate) {
- logrotate = 0;
+int
+_gf_msg_backtrace(int stacksize, char *callstr, size_t strsize)
+{
+ int ret = -1;
+ int i = 0;
+ int size = 0;
+ int savstrsize = strsize;
+ void *array[200];
+ char **callingfn = NULL;
+
+ /* We chop off last 2 anyway, so if request is less than tolerance
+ * nothing to do */
+ if (stacksize < 3)
+ goto out;
+
+ size = backtrace(array, ((stacksize <= 200) ? stacksize : 200));
+ if ((size - 3) < 0)
+ goto out;
+ if (size)
+ callingfn = backtrace_symbols(&array[2], size - 2);
+ if (!callingfn)
+ goto out;
+
+ ret = snprintf(callstr, strsize, "(");
+ PRINT_SIZE_CHECK(ret, out, strsize);
+
+ for ((i = size - 3); i >= 0; i--) {
+ ret = snprintf(callstr + savstrsize - strsize, strsize, "-->%s ",
+ callingfn[i]);
+ PRINT_SIZE_CHECK(ret, out, strsize);
+ }
+
+ ret = snprintf(callstr + savstrsize - strsize, strsize, ")");
+ PRINT_SIZE_CHECK(ret, out, strsize);
+out:
+ FREE(callingfn);
+ return ret;
+}
- fd = open (filename, O_CREAT | O_RDONLY, S_IRUSR | S_IWUSR);
- if (fd < 0) {
- gf_log ("logrotate", GF_LOG_ERROR,
- "%s", strerror (errno));
- return -1;
- }
- close (fd);
-
- new_logfile = fopen (filename, "a");
- if (!new_logfile) {
- gf_log ("logrotate", GF_LOG_CRITICAL,
- "failed to open logfile %s (%s)",
- filename, strerror (errno));
- goto log;
+int
+_gf_msg_nomem(const char *domain, const char *file, const char *function,
+ int line, gf_loglevel_t level, size_t size)
+{
+ const char *basename = NULL;
+ xlator_t *this = NULL;
+ struct timeval tv = {
+ 0,
+ };
+ int ret = 0;
+ int fd = -1;
+ char msg[2048] = {
+ 0,
+ };
+ char timestr[GF_TIMESTR_SIZE] = {
+ 0,
+ };
+ glusterfs_ctx_t *ctx = NULL;
+ int wlen = 0;
+ int priority;
+ struct rusage r_usage;
+
+ this = THIS;
+ ctx = this->ctx;
+
+ if (!ctx)
+ goto out;
+
+ if (skip_logging(this, level))
+ goto out;
+
+ if (!domain || !file || !function) {
+ fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__,
+ __PRETTY_FUNCTION__, __LINE__);
+ return -1;
+ }
+
+ GET_FILE_NAME_TO_LOG(file, basename);
+
+ ret = gettimeofday(&tv, NULL);
+ if (-1 == ret)
+ goto out;
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
+
+ /* TODO: Currently we print in the enhanced format, with a message ID
+ * of 0. Need to enhance this to support format as configured */
+ wlen = snprintf(
+ msg, sizeof msg,
+ "[%s] %c [MSGID: %" PRIu64
+ "]"
+ " [%s:%d:%s] %s: no memory "
+ "available for size (%" GF_PRI_SIZET
+ ") current memory usage in kilobytes %ld"
+ " [call stack follows]\n",
+ timestr, gf_level_strings[level], (uint64_t)0, basename, line, function,
+ domain, size,
+ (!getrusage(RUSAGE_SELF, &r_usage) ? r_usage.ru_maxrss : 0));
+ if (-1 == wlen) {
+ ret = -1;
+ goto out;
+ }
+
+ /* log to the configured logging service */
+ switch (ctx->log.logger) {
+ case gf_logger_syslog:
+ if (ctx->log.log_control_file_found && ctx->log.gf_log_syslog) {
+ SET_LOG_PRIO(level, priority);
+
+ /* if syslog allocates, then this may fail, but we
+ * cannot do much about it at the moment */
+ /* There is no fd for syslog, hence no stack printed */
+ syslog(priority, "%s", msg);
+ break;
+ }
+ /* NOTE: If syslog control file is absent, which is another
+ * way to control logging to syslog, then we will fall through
+ * to the gluster log. The ideal way to do things would be to
+ * not have the extra control file check */
+ case gf_logger_glusterlog:
+ pthread_mutex_lock(&ctx->log.logfile_mutex);
+ {
+ fd = ctx->log.logfile ? fileno(ctx->log.logfile)
+ : fileno(stderr);
+ if (fd == -1) {
+ pthread_mutex_unlock(&ctx->log.logfile_mutex);
+ goto out;
}
- pthread_mutex_lock (&logfile_mutex);
- {
- if (logfile)
- fclose (logfile);
-
- gf_log_logfile = logfile = new_logfile;
+ /* write directly to the fd to prevent out of order
+ * message and stack */
+ ret = sys_write(fd, msg, wlen);
+ if (ret == -1) {
+ pthread_mutex_unlock(&ctx->log.logfile_mutex);
+ goto out;
}
- pthread_mutex_unlock (&logfile_mutex);
+#ifdef GF_LINUX_HOST_OS
+ /* We want only serious log in 'syslog', not our debug
+ * and trace logs */
+ if (ctx->log.gf_log_syslog && level &&
+ (level <= ctx->log.sys_log_level))
+ syslog((level - 1), "%s\n", msg);
+#endif
+ }
+ pthread_mutex_unlock(&ctx->log.logfile_mutex);
- }
+ _gf_msg_backtrace_nomem(level, GF_LOG_BACKTRACE_DEPTH);
-log:
- ret = gettimeofday (&tv, NULL);
- if (-1 == ret)
- goto out;
- va_start (ap, fmt);
- gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
- snprintf (timestr + strlen (timestr), sizeof timestr - strlen (timestr),
- ".%"GF_PRI_SUSECONDS, tv.tv_usec);
+ break;
+ }
- basename = strrchr (file, '/');
- if (basename)
- basename++;
- else
- basename = file;
+out:
+ return ret;
+}
+
+static int
+gf_log_syslog(glusterfs_ctx_t *ctx, const char *domain, const char *file,
+ const char *function, int32_t line, gf_loglevel_t level,
+ int errnum, uint64_t msgid, char **appmsgstr, char *callstr,
+ int graph_id, gf_log_format_t fmt)
+{
+ int priority;
+
+ SET_LOG_PRIO(level, priority);
+
+ /* log with appropriate format */
+ switch (fmt) {
+ case gf_logformat_traditional:
+ if (!callstr) {
+ if (errnum)
+ syslog(priority, "[%s:%d:%s] %d-%s: %s [%s]", file, line,
+ function, graph_id, domain, *appmsgstr,
+ strerror(errnum));
+ else
+ syslog(priority, "[%s:%d:%s] %d-%s: %s", file, line,
+ function, graph_id, domain, *appmsgstr);
+ } else {
+ if (errnum)
+ syslog(priority,
+ "[%s:%d:%s] %s %d-%s:"
+ " %s [%s]",
+ file, line, function, callstr, graph_id, domain,
+ *appmsgstr, strerror(errnum));
+ else
+ syslog(priority, "[%s:%d:%s] %s %d-%s: %s", file, line,
+ function, callstr, graph_id, domain, *appmsgstr);
+ }
+ break;
+ case gf_logformat_withmsgid:
+ if (!callstr) {
+ if (errnum)
+ syslog(priority,
+ "[MSGID: %" PRIu64
+ "]"
+ " [%s:%d:%s] %d-%s: %s [%s]",
+ msgid, file, line, function, graph_id, domain,
+ *appmsgstr, strerror(errnum));
+ else
+ syslog(priority,
+ "[MSGID: %" PRIu64
+ "]"
+ " [%s:%d:%s] %d-%s: %s",
+ msgid, file, line, function, graph_id, domain,
+ *appmsgstr);
+ } else {
+ if (errnum)
+ syslog(priority,
+ "[MSGID: %" PRIu64
+ "]"
+ " [%s:%d:%s] %s %d-%s: %s [%s]",
+ msgid, file, line, function, callstr, graph_id,
+ domain, *appmsgstr, strerror(errnum));
+ else
+ syslog(priority,
+ "[MSGID: %" PRIu64
+ "]"
+ " [%s:%d:%s] %s %d-%s: %s",
+ msgid, file, line, function, callstr, graph_id,
+ domain, *appmsgstr);
+ }
+ break;
+ case gf_logformat_cee:
+ /* TODO: Enhance CEE with additional parameters */
+ gf_syslog(priority, "[%s:%d:%s] %d-%s: %s", file, line, function,
+ graph_id, domain, *appmsgstr);
+ break;
+
+ default:
+ /* NOTE: should not get here without logging */
+ break;
+ }
+
+ /* TODO: There can be no errors from gf_syslog? */
+ return 0;
+}
- ret = gf_asprintf (&str1, "[%s] %s [%s:%d:%s] %d-%s: ",
- timestr, level_strings[level],
- basename, line, function,
- ((this->graph)?this->graph->id:0), domain);
- if (-1 == ret) {
- goto err;
+static int
+gf_log_glusterlog(glusterfs_ctx_t *ctx, const char *domain, const char *file,
+ const char *function, int32_t line, gf_loglevel_t level,
+ int errnum, uint64_t msgid, char **appmsgstr, char *callstr,
+ struct timeval tv, int graph_id, gf_log_format_t fmt)
+{
+ char timestr[GF_TIMESTR_SIZE] = {
+ 0,
+ };
+ char *header = NULL;
+ char *footer = NULL;
+ int ret = 0;
+
+ /* rotate if required */
+ gf_log_rotate(ctx);
+
+ /* format the time stamp */
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
+
+ /* generate footer */
+ if (errnum) {
+ ret = gf_asprintf(&footer, " [%s]\n", strerror(errnum));
+ } else {
+ ret = gf_asprintf(&footer, " \n");
+ }
+ if (-1 == ret) {
+ goto err;
+ }
+
+ /* generate message, inc. the header */
+ if (fmt == gf_logformat_traditional) {
+ if (!callstr) {
+ ret = gf_asprintf(&header,
+ "[%s] %c [%s:%d:%s]"
+ " %d-%s: %s",
+ timestr, gf_level_strings[level], file, line,
+ function, graph_id, domain, *appmsgstr);
+ } else {
+ ret = gf_asprintf(&header,
+ "[%s] %c [%s:%d:%s] %s"
+ " %d-%s: %s",
+ timestr, gf_level_strings[level], file, line,
+ function, callstr, graph_id, domain, *appmsgstr);
+ }
+ } else { /* gf_logformat_withmsgid */
+ /* CEE log format unsupported in logger_glusterlog, so just
+ * print enhanced log format */
+ if (!callstr) {
+ ret = gf_asprintf(&header,
+ "[%s] %c [MSGID: %" PRIu64
+ "]"
+ " [%s:%d:%s] %d-%s: %s",
+ timestr, gf_level_strings[level], msgid, file,
+ line, function, graph_id, domain, *appmsgstr);
+ } else {
+ ret = gf_asprintf(&header,
+ "[%s] %c [MSGID: %" PRIu64
+ "]"
+ " [%s:%d:%s] %s %d-%s: %s",
+ timestr, gf_level_strings[level], msgid, file,
+ line, function, callstr, graph_id, domain,
+ *appmsgstr);
+ }
+ }
+ if (-1 == ret) {
+ goto err;
+ }
+
+ /* send the full message to log */
+
+ pthread_mutex_lock(&ctx->log.logfile_mutex);
+ {
+ if (ctx->log.logfile) {
+ fprintf(ctx->log.logfile, "%s%s", header, footer);
+ fflush(ctx->log.logfile);
+ } else if (ctx->log.loglevel >= level) {
+ fprintf(stderr, "%s%s", header, footer);
+ fflush(stderr);
}
- ret = vasprintf (&str2, fmt, ap);
- if (-1 == ret) {
- goto err;
+#ifdef GF_LINUX_HOST_OS
+ /* We want only serious logs in 'syslog', not our debug
+ * and trace logs */
+ if (ctx->log.gf_log_syslog && level &&
+ (level <= ctx->log.sys_log_level)) {
+ syslog((level - 1), "%s%s", header, footer);
}
+#endif
+ }
- va_end (ap);
+ /* TODO: Plugin in memory log buffer retention here. For logs not
+ * flushed during cores, it would be useful to retain some of the last
+ * few messages in memory */
+ pthread_mutex_unlock(&ctx->log.logfile_mutex);
+ ret = 0;
- len = strlen (str1);
- msg = GF_MALLOC (len + strlen (str2) + 1, gf_common_mt_char);
+err:
+ GF_FREE(header);
+ GF_FREE(footer);
- strcpy (msg, str1);
- strcpy (msg + len, str2);
+ return ret;
+}
- pthread_mutex_lock (&logfile_mutex);
- {
+static int
+gf_syslog_log_repetitions(const char *domain, const char *file,
+ const char *function, int32_t line,
+ gf_loglevel_t level, int errnum, uint64_t msgid,
+ char **appmsgstr, char *callstr, int refcount,
+ struct timeval oldest, struct timeval latest,
+ int graph_id)
+{
+ int priority;
+ char timestr_latest[GF_TIMESTR_SIZE] = {
+ 0,
+ };
+ char timestr_oldest[GF_TIMESTR_SIZE] = {
+ 0,
+ };
+
+ SET_LOG_PRIO(level, priority);
+
+ gf_time_fmt_tv(timestr_latest, sizeof timestr_latest, &latest,
+ gf_timefmt_FT);
+ gf_time_fmt_tv(timestr_oldest, sizeof timestr_oldest, &oldest,
+ gf_timefmt_FT);
+
+ if (errnum) {
+ syslog(priority,
+ "The message \"[MSGID: %" PRIu64
+ "] [%s:%d:%s] "
+ "%d-%s: %s [%s] \" repeated %d times between %s"
+ " and %s",
+ msgid, file, line, function, graph_id, domain, *appmsgstr,
+ strerror(errnum), refcount, timestr_oldest, timestr_latest);
+ } else {
+ syslog(priority,
+ "The message \"[MSGID: %" PRIu64
+ "] [%s:%d:%s] "
+ "%d-%s: %s \" repeated %d times between %s"
+ " and %s",
+ msgid, file, line, function, graph_id, domain, *appmsgstr,
+ refcount, timestr_oldest, timestr_latest);
+ }
+ return 0;
+}
- if (logfile) {
- fprintf (logfile, "%s\n", msg);
- fflush (logfile);
- } else {
- fprintf (stderr, "%s\n", msg);
- }
+static int
+gf_glusterlog_log_repetitions(glusterfs_ctx_t *ctx, const char *domain,
+ const char *file, const char *function,
+ int32_t line, gf_loglevel_t level, int errnum,
+ uint64_t msgid, char **appmsgstr, char *callstr,
+ int refcount, struct timeval oldest,
+ struct timeval latest, int graph_id)
+{
+ int ret = 0;
+ char timestr_latest[GF_TIMESTR_SIZE] = {
+ 0,
+ };
+ char timestr_oldest[GF_TIMESTR_SIZE] = {
+ 0,
+ };
+ char errstr[256] = {
+ 0,
+ };
+ char *header = NULL;
+ char *footer = NULL;
+
+ if (!ctx)
+ goto err;
+
+ gf_log_rotate(ctx);
+
+ ret = gf_asprintf(&header,
+ "The message \"%c [MSGID: %" PRIu64
+ "]"
+ " [%s:%d:%s] %d-%s: %s",
+ gf_level_strings[level], msgid, file, line, function,
+ graph_id, domain, *appmsgstr);
+ if (-1 == ret) {
+ goto err;
+ }
+
+ gf_time_fmt_tv(timestr_latest, sizeof timestr_latest, &latest,
+ gf_timefmt_FT);
+
+ gf_time_fmt_tv(timestr_oldest, sizeof timestr_oldest, &oldest,
+ gf_timefmt_FT);
+
+ if (errnum)
+ snprintf(errstr, sizeof(errstr) - 1, " [%s]", strerror(errnum));
+
+ ret = gf_asprintf(&footer, "%s\" repeated %d times between [%s] and [%s]",
+ errstr, refcount, timestr_oldest, timestr_latest);
+ if (-1 == ret) {
+ ret = -1;
+ goto err;
+ }
+
+ pthread_mutex_lock(&ctx->log.logfile_mutex);
+ {
+ if (ctx->log.logfile) {
+ fprintf(ctx->log.logfile, "%s%s\n", header, footer);
+ fflush(ctx->log.logfile);
+ } else if (ctx->log.loglevel >= level) {
+ fprintf(stderr, "%s%s\n", header, footer);
+ fflush(stderr);
+ }
#ifdef GF_LINUX_HOST_OS
- /* We want only serious log in 'syslog', not our debug
- and trace logs */
- if (gf_log_syslog && level && (level <= sys_log_level))
- syslog ((level-1), "%s\n", msg);
+ /* We want only serious logs in 'syslog', not our debug
+ * and trace logs */
+ if (ctx->log.gf_log_syslog && level &&
+ (level <= ctx->log.sys_log_level))
+ syslog((level - 1), "%s%s\n", header, footer);
#endif
- }
+ }
- pthread_mutex_unlock (&logfile_mutex);
+ /* TODO: Plugin in memory log buffer retention here. For logs not
+ * flushed during cores, it would be useful to retain some of the last
+ * few messages in memory */
+ pthread_mutex_unlock(&ctx->log.logfile_mutex);
+ ret = 0;
err:
- if (msg) {
- GF_FREE (msg);
+ GF_FREE(header);
+ GF_FREE(footer);
+
+ return ret;
+}
+
+static int
+gf_log_print_with_repetitions(glusterfs_ctx_t *ctx, const char *domain,
+ const char *file, const char *function,
+ int32_t line, gf_loglevel_t level, int errnum,
+ uint64_t msgid, char **appmsgstr, char *callstr,
+ int refcount, struct timeval oldest,
+ struct timeval latest, int graph_id)
+{
+ int ret = -1;
+ gf_log_logger_t logger = ctx->log.logger;
+
+ switch (logger) {
+ case gf_logger_syslog:
+ if (ctx->log.log_control_file_found && ctx->log.gf_log_syslog) {
+ ret = gf_syslog_log_repetitions(
+ domain, file, function, line, level, errnum, msgid,
+ appmsgstr, callstr, refcount, oldest, latest, graph_id);
+ break;
+ }
+ /* NOTE: If syslog control file is absent, which is another
+ * way to control logging to syslog, then we will fall through
+ * to the gluster log. The ideal way to do things would be to
+ * not have the extra control file check */
+
+ case gf_logger_glusterlog:
+ ret = gf_glusterlog_log_repetitions(
+ ctx, domain, file, function, line, level, errnum, msgid,
+ appmsgstr, callstr, refcount, oldest, latest, graph_id);
+ break;
+ }
+
+ return ret;
+}
+
+static int
+gf_log_print_plain_fmt(glusterfs_ctx_t *ctx, const char *domain,
+ const char *file, const char *function, int32_t line,
+ gf_loglevel_t level, int errnum, uint64_t msgid,
+ char **appmsgstr, char *callstr, struct timeval tv,
+ int graph_id, gf_log_format_t fmt)
+{
+ int ret = -1;
+ gf_log_logger_t logger = 0;
+
+ logger = ctx->log.logger;
+
+ /* log to the configured logging service */
+ switch (logger) {
+ case gf_logger_syslog:
+ if (ctx->log.log_control_file_found && ctx->log.gf_log_syslog) {
+ ret = gf_log_syslog(ctx, domain, file, function, line, level,
+ errnum, msgid, appmsgstr, callstr, graph_id,
+ fmt);
+ break;
+ }
+ /* NOTE: If syslog control file is absent, which is another
+ * way to control logging to syslog, then we will fall through
+ * to the gluster log. The ideal way to do things would be to
+ * not have the extra control file check */
+ case gf_logger_glusterlog:
+ ret = gf_log_glusterlog(ctx, domain, file, function, line, level,
+ errnum, msgid, appmsgstr, callstr, tv,
+ graph_id, fmt);
+ break;
+ }
+
+ return ret;
+}
+
+void
+gf_log_flush_message(log_buf_t *buf, glusterfs_ctx_t *ctx)
+{
+ if (buf->refcount == 1) {
+ (void)gf_log_print_plain_fmt(ctx, buf->domain, buf->file, buf->function,
+ buf->line, buf->level, buf->errnum,
+ buf->msg_id, &buf->msg, NULL, buf->latest,
+ buf->graph_id, gf_logformat_withmsgid);
+ }
+
+ if (buf->refcount > 1) {
+ gf_log_print_with_repetitions(
+ ctx, buf->domain, buf->file, buf->function, buf->line, buf->level,
+ buf->errnum, buf->msg_id, &buf->msg, NULL, buf->refcount,
+ buf->oldest, buf->latest, buf->graph_id);
+ }
+ return;
+}
+
+static void
+gf_log_flush_list(struct list_head *copy, glusterfs_ctx_t *ctx)
+{
+ log_buf_t *iter = NULL;
+ log_buf_t *tmp = NULL;
+
+ list_for_each_entry_safe(iter, tmp, copy, msg_list)
+ {
+ gf_log_flush_message(iter, ctx);
+ list_del_init(&iter->msg_list);
+ log_buf_destroy(iter);
+ }
+}
+
+void
+gf_log_flush_msgs(glusterfs_ctx_t *ctx)
+{
+ struct list_head copy;
+
+ INIT_LIST_HEAD(&copy);
+
+ pthread_mutex_lock(&ctx->log.log_buf_lock);
+ {
+ list_splice_init(&ctx->log.lru_queue, &copy);
+ ctx->log.lru_cur_size = 0;
+ }
+ pthread_mutex_unlock(&ctx->log.log_buf_lock);
+
+ gf_log_flush_list(&copy, ctx);
+
+ return;
+}
+
+static void
+gf_log_flush_extra_msgs(glusterfs_ctx_t *ctx, uint32_t new)
+{
+ int count = 0;
+ int i = 0;
+ log_buf_t *iter = NULL;
+ log_buf_t *tmp = NULL;
+ struct list_head copy;
+
+ INIT_LIST_HEAD(&copy);
+
+ /* If the number of outstanding log messages does not cause list
+ * overflow even after reducing the size of the list, then do nothing.
+ * Otherwise (that is if there are more items in the list than there
+ * need to be after reducing its size), move the least recently used
+ * 'diff' elements to be flushed into a separate list...
+ */
+
+ pthread_mutex_lock(&ctx->log.log_buf_lock);
+ {
+ if (ctx->log.lru_cur_size <= new)
+ goto unlock;
+ count = ctx->log.lru_cur_size - new;
+ list_for_each_entry_safe(iter, tmp, &ctx->log.lru_queue, msg_list)
+ {
+ if (i == count)
+ break;
+
+ list_del_init(&iter->msg_list);
+ list_add_tail(&iter->msg_list, &copy);
+ i++;
}
+ ctx->log.lru_cur_size = ctx->log.lru_cur_size - count;
+ }
+ // ... quickly unlock ...
+unlock:
+ pthread_mutex_unlock(&ctx->log.log_buf_lock);
+ if (list_empty(&copy))
+ return;
+
+ TEST_LOG(
+ "Log buffer size reduced. About to flush %d extra log "
+ "messages",
+ count);
+ // ... and then flush them outside the lock.
+ gf_log_flush_list(&copy, ctx);
+ TEST_LOG("Just flushed %d extra log messages", count);
+
+ return;
+}
+
+static int
+__gf_log_inject_timer_event(glusterfs_ctx_t *ctx)
+{
+ int ret = -1;
+ struct timespec timeout = {
+ 0,
+ };
+
+ if (!ctx)
+ goto out;
+
+ if (ctx->log.log_flush_timer) {
+ gf_timer_call_cancel(ctx, ctx->log.log_flush_timer);
+ ctx->log.log_flush_timer = NULL;
+ }
+
+ timeout.tv_sec = ctx->log.timeout;
+ timeout.tv_nsec = 0;
- if (str1)
- GF_FREE (str1);
+ TEST_LOG("Starting timer now. Timeout = %u, current buf size = %d",
+ ctx->log.timeout, ctx->log.lru_size);
+ ctx->log.log_flush_timer = gf_timer_call_after(
+ ctx, timeout, gf_log_flush_timeout_cbk, (void *)ctx);
+ if (!ctx->log.log_flush_timer)
+ goto out;
- if (str2)
- FREE (str2);
+ ret = 0;
out:
- return (0);
+ return ret;
}
int
-gf_log_eh (void *data)
+gf_log_inject_timer_event(glusterfs_ctx_t *ctx)
{
- int ret = -1;
+ int ret = -1;
- ret = eh_save_history (THIS->history, data);
+ if (!ctx)
+ return -1;
- return ret;
+ pthread_mutex_lock(&ctx->log.log_buf_lock);
+ {
+ ret = __gf_log_inject_timer_event(ctx);
+ }
+ pthread_mutex_unlock(&ctx->log.log_buf_lock);
+
+ return ret;
}
-int
-gf_cmd_log_init (const char *filename)
+void
+gf_log_flush_timeout_cbk(void *data)
{
- int fd = -1;
- xlator_t *this = NULL;
+ glusterfs_ctx_t *ctx = NULL;
- this = THIS;
+ ctx = (glusterfs_ctx_t *)data;
- if (!filename){
- gf_log (this->name, GF_LOG_CRITICAL, "gf_cmd_log_init: no "
- "filename specified\n");
- return -1;
+ TEST_LOG(
+ "Log timer timed out. About to flush outstanding messages if "
+ "present");
+ gf_log_flush_msgs(ctx);
+
+ (void)gf_log_inject_timer_event(ctx);
+
+ return;
+}
+
+static int
+_gf_msg_internal(const char *domain, const char *file, const char *function,
+ int32_t line, gf_loglevel_t level, int errnum, uint64_t msgid,
+ char **appmsgstr, char *callstr, int graph_id)
+{
+ int ret = -1;
+ uint32_t size = 0;
+ const char *basename = NULL;
+ xlator_t *this = NULL;
+ glusterfs_ctx_t *ctx = NULL;
+ log_buf_t *iter = NULL;
+ log_buf_t *buf_tmp = NULL;
+ log_buf_t *buf_new = NULL;
+ log_buf_t *first = NULL;
+ struct timeval tv = {
+ 0,
+ };
+ gf_boolean_t found = _gf_false;
+ gf_boolean_t flush_lru = _gf_false;
+ gf_boolean_t flush_logged_msg = _gf_false;
+
+ this = THIS;
+ ctx = this->ctx;
+
+ if (!ctx)
+ goto out;
+
+ GET_FILE_NAME_TO_LOG(file, basename);
+
+ ret = gettimeofday(&tv, NULL);
+ if (ret)
+ goto out;
+
+ /* If this function is called via _gf_msg_callingfn () (indicated by a
+ * non-NULL callstr), or if the logformat is traditional, flush the
+ * message directly to disk.
+ */
+
+ if ((callstr) || (ctx->log.logformat == gf_logformat_traditional)) {
+ ret = gf_log_print_plain_fmt(ctx, domain, basename, function, line,
+ level, errnum, msgid, appmsgstr, callstr,
+ tv, graph_id, gf_logformat_traditional);
+ goto out;
+ }
+
+ pthread_mutex_lock(&ctx->log.log_buf_lock);
+ {
+ /* Check if the msg being logged is already part of the list */
+ list_for_each_entry_safe_reverse(iter, buf_tmp, &ctx->log.lru_queue,
+ msg_list)
+ {
+ if (first == NULL)
+ // Remember the first (lru) element in first ptr
+ first = iter;
+
+ /* Try to fail the search early on by doing the less
+ * expensive integer comparisons and continue to string
+ * parameter comparisons only after all int parameters
+ * are found to be matching.
+ */
+ if (line != iter->line)
+ continue;
+
+ if (errnum != iter->errnum)
+ continue;
+
+ if (msgid != iter->msg_id)
+ continue;
+
+ if (level != iter->level)
+ continue;
+
+ if (graph_id != iter->graph_id)
+ continue;
+
+ if (strcmp(domain, iter->domain))
+ continue;
+
+ if (strcmp(basename, iter->file))
+ continue;
+
+ if (strcmp(function, iter->function))
+ continue;
+
+ if (strcmp(*appmsgstr, iter->msg))
+ continue;
+
+ // Ah! Found a match!
+ list_move_tail(&iter->msg_list, &ctx->log.lru_queue);
+ iter->refcount++;
+ found = _gf_true;
+ // Update the 'latest' timestamp.
+ memcpy((void *)&(iter->latest), (void *)&tv,
+ sizeof(struct timeval));
+ break;
+ }
+ if (found) {
+ ret = 0;
+ goto unlock;
+ }
+ // else ...
+
+ size = ctx->log.lru_size;
+ /* If the upper limit on the log buf size is 0, flush the msg to
+ * disk directly after unlock. There's no need to buffer the
+ * msg here.
+ */
+ if (size == 0) {
+ flush_logged_msg = _gf_true;
+ goto unlock;
+ } else if (((ctx->log.lru_cur_size + 1) > size) && (first)) {
+ /* If the list is full, flush the lru msg to disk and also
+ * release it after unlock, and ...
+ * */
+ if (first->refcount >= 1)
+ TEST_LOG(
+ "Buffer overflow of a buffer whose size limit "
+ "is %d. About to flush least recently used log"
+ " message to disk",
+ size);
+ list_del_init(&first->msg_list);
+ ctx->log.lru_cur_size--;
+ flush_lru = _gf_true;
+ }
+ /* create a new list element, initialise and enqueue it.
+ * Additionally, this being the first occurrence of the msg,
+ * log it directly to disk after unlock. */
+ buf_new = mem_get0(THIS->ctx->logbuf_pool);
+ if (!buf_new) {
+ ret = -1;
+ goto unlock;
+ }
+ ret = log_buf_init(buf_new, domain, basename, function, line, level,
+ errnum, msgid, appmsgstr, graph_id);
+ if (ret) {
+ log_buf_destroy(buf_new);
+ goto unlock;
}
- cmd_log_filename = gf_strdup (filename);
- if (!cmd_log_filename) {
- gf_log (this->name, GF_LOG_CRITICAL,
- "gf_cmd_log_init: strdup error\n");
+ memcpy((void *)&(buf_new->latest), (void *)&tv, sizeof(struct timeval));
+ memcpy((void *)&(buf_new->oldest), (void *)&tv, sizeof(struct timeval));
+
+ list_add_tail(&buf_new->msg_list, &ctx->log.lru_queue);
+ ctx->log.lru_cur_size++;
+ flush_logged_msg = _gf_true;
+ ret = 0;
+ }
+unlock:
+ pthread_mutex_unlock(&ctx->log.log_buf_lock);
+
+ /* Value of @ret is a don't-care below since irrespective of success or
+ * failure post setting of @flush_lru, @first must be flushed and freed.
+ */
+ if (flush_lru) {
+ gf_log_flush_message(first, ctx);
+ log_buf_destroy(first);
+ }
+ /* Similarly, irrespective of whether all operations since setting of
+ * @flush_logged_msg were successful or not, flush the message being
+ * logged to disk in the plain format.
+ */
+ if (flush_logged_msg) {
+ ret = gf_log_print_plain_fmt(ctx, domain, basename, function, line,
+ level, errnum, msgid, appmsgstr, callstr,
+ tv, graph_id, gf_logformat_withmsgid);
+ }
+
+out:
+ return ret;
+}
+
+int
+_gf_msg(const char *domain, const char *file, const char *function,
+ int32_t line, gf_loglevel_t level, int errnum, int trace,
+ uint64_t msgid, const char *fmt, ...)
+{
+ int ret = 0;
+ char *msgstr = NULL;
+ va_list ap;
+ xlator_t *this = THIS;
+ glusterfs_ctx_t *ctx = NULL;
+ char *callstr = NULL;
+ int log_inited = 0;
+
+ if (this == NULL)
+ return -1;
+
+ ctx = this->ctx;
+ if (ctx == NULL) {
+ /* messages before context initialization are ignored */
+ return -1;
+ }
+
+ /* check if we should be logging */
+ if (skip_logging(this, level))
+ goto out;
+
+ /* in args check */
+ if (!domain || !file || !function || !fmt) {
+ fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__,
+ __PRETTY_FUNCTION__, __LINE__);
+ return -1;
+ }
+
+ /* form the message */
+ va_start(ap, fmt);
+ ret = vasprintf(&msgstr, fmt, ap);
+ va_end(ap);
+
+ /* log */
+ if (ret != -1) {
+ if (trace) {
+ callstr = GF_MALLOC(GF_LOG_BACKTRACE_SIZE, gf_common_mt_char);
+ if (callstr == NULL)
return -1;
+
+ ret = _gf_msg_backtrace(GF_LOG_BACKTRACE_DEPTH, callstr,
+ GF_LOG_BACKTRACE_SIZE);
+ if (ret < 0) {
+ GF_FREE(callstr);
+ callstr = NULL;
+ }
+ }
+
+ pthread_mutex_lock(&ctx->log.logfile_mutex);
+ {
+ if (ctx->log.logfile) {
+ log_inited = 1;
+ }
+ }
+ pthread_mutex_unlock(&ctx->log.logfile_mutex);
+
+ if (!log_inited && ctx->log.gf_log_syslog) {
+ ret = gf_log_syslog(
+ ctx, domain, file, function, line, level, errnum, msgid,
+ &msgstr, (callstr ? callstr : NULL),
+ (this->graph) ? this->graph->id : 0, gf_logformat_traditional);
+ } else {
+ ret = _gf_msg_internal(domain, file, function, line, level, errnum,
+ msgid, &msgstr, (callstr ? callstr : NULL),
+ (this->graph) ? this->graph->id : 0);
}
- /* close and reopen cmdlogfile for log rotate*/
- if (cmdlogfile) {
- fclose (cmdlogfile);
- cmdlogfile = NULL;
+ } else {
+ /* man (3) vasprintf states on error strp contents
+ * are undefined, be safe */
+ msgstr = NULL;
+ }
+ if (callstr)
+ GF_FREE(callstr);
+ FREE(msgstr);
+
+out:
+ return ret;
+}
+
+/* TODO: Deprecate (delete) _gf_log, _gf_log_callingfn,
+ * once messages are changed to use _gf_msgXXX APIs for logging */
+int
+_gf_log(const char *domain, const char *file, const char *function, int line,
+ gf_loglevel_t level, const char *fmt, ...)
+{
+ const char *basename = NULL;
+ FILE *new_logfile = NULL;
+ va_list ap;
+ char timestr[GF_TIMESTR_SIZE] = {
+ 0,
+ };
+ struct timeval tv = {
+ 0,
+ };
+ char *logline = NULL;
+ char *msg = NULL;
+ int ret = 0;
+ int fd = -1;
+ xlator_t *this = THIS;
+ glusterfs_ctx_t *ctx = this->ctx;
+
+ if (!ctx)
+ goto out;
+
+ if (skip_logging(this, level))
+ goto out;
+
+ if (!domain || !file || !function || !fmt) {
+ fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__,
+ __PRETTY_FUNCTION__, __LINE__);
+ return -1;
+ }
+
+ basename = strrchr(file, '/');
+ if (basename)
+ basename++;
+ else
+ basename = file;
+
+ va_start(ap, fmt);
+ ret = vasprintf(&msg, fmt, ap);
+ va_end(ap);
+ if (-1 == ret) {
+ goto err;
+ }
+
+ if (ctx->log.log_control_file_found) {
+ int priority;
+ /* treat GF_LOG_TRACE and GF_LOG_NONE as LOG_DEBUG and
+ other level as is */
+ if (GF_LOG_TRACE == level || GF_LOG_NONE == level) {
+ priority = LOG_DEBUG;
+ } else {
+ priority = level - 1;
}
- fd = open (cmd_log_filename, O_CREAT | O_RDONLY, S_IRUSR | S_IWUSR);
+ gf_syslog(priority, "[%s:%d:%s] %d-%s: %s", basename, line, function,
+ ((this->graph) ? this->graph->id : 0), domain, msg);
+ goto err;
+ }
+
+ if (ctx->log.logrotate) {
+ ctx->log.logrotate = 0;
+
+ fd = sys_open(ctx->log.filename, O_CREAT | O_RDONLY, S_IRUSR | S_IWUSR);
if (fd < 0) {
- gf_log (this->name, GF_LOG_CRITICAL,
- "%s", strerror (errno));
- return -1;
+ gf_smsg("logrotate", GF_LOG_ERROR, errno,
+ LG_MSG_OPEN_LOGFILE_FAILED, NULL);
+ return -1;
+ }
+ sys_close(fd);
+
+ new_logfile = fopen(ctx->log.filename, "a");
+ if (!new_logfile) {
+ gf_smsg("logrotate", GF_LOG_CRITICAL, errno,
+ LG_MSG_OPEN_LOGFILE_FAILED, "filename=%s",
+ ctx->log.filename, NULL);
+ goto log;
}
- close (fd);
- cmdlogfile = fopen (cmd_log_filename, "a");
- if (!cmdlogfile){
- gf_log (this->name, GF_LOG_CRITICAL,
- "gf_cmd_log_init: failed to open logfile \"%s\" "
- "(%s)\n", cmd_log_filename, strerror (errno));
- return -1;
+ pthread_mutex_lock(&ctx->log.logfile_mutex);
+ {
+ if (ctx->log.logfile)
+ fclose(ctx->log.logfile);
+
+ ctx->log.gf_log_logfile = ctx->log.logfile = new_logfile;
}
- return 0;
+ pthread_mutex_unlock(&ctx->log.logfile_mutex);
+ }
+
+log:
+ ret = gettimeofday(&tv, NULL);
+ if (-1 == ret)
+ goto out;
+
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
+
+ ret = gf_asprintf(&logline, "[%s] %c [%s:%d:%s] %d-%s: %s\n", timestr,
+ gf_level_strings[level], basename, line, function,
+ ((this->graph) ? this->graph->id : 0), domain, msg);
+ if (-1 == ret) {
+ goto err;
+ }
+
+ pthread_mutex_lock(&ctx->log.logfile_mutex);
+ {
+ if (ctx->log.logfile) {
+ fputs(logline, ctx->log.logfile);
+ fflush(ctx->log.logfile);
+ } else if (ctx->log.loglevel >= level) {
+ fputs(logline, stderr);
+ fflush(stderr);
+ }
+
+#ifdef GF_LINUX_HOST_OS
+ /* We want only serious log in 'syslog', not our debug
+ and trace logs */
+ if (ctx->log.gf_log_syslog && level &&
+ (level <= ctx->log.sys_log_level))
+ syslog((level - 1), "%s", logline);
+#endif
+ }
+
+ pthread_mutex_unlock(&ctx->log.logfile_mutex);
+
+err:
+ GF_FREE(logline);
+
+ FREE(msg);
+
+out:
+ return (0);
}
int
-gf_cmd_log (const char *domain, const char *fmt, ...)
-{
- va_list ap;
- char timestr[64];
- struct timeval tv = {0,};
- char *str1 = NULL;
- char *str2 = NULL;
- char *msg = NULL;
- size_t len = 0;
- int ret = 0;
-
- if (!cmdlogfile)
- return -1;
+_gf_log_eh(const char *function, const char *fmt, ...)
+{
+ int ret = -1;
+ va_list ap;
+ char *logline = NULL;
+ char *msg = NULL;
+ xlator_t *this = NULL;
+ this = THIS;
- if (!domain || !fmt) {
- gf_log ("glusterd", GF_LOG_TRACE,
- "logging: invalid argument\n");
- return -1;
+ va_start(ap, fmt);
+ ret = vasprintf(&msg, fmt, ap);
+ va_end(ap);
+ if (-1 == ret) {
+ goto out;
+ }
+
+ ret = gf_asprintf(&logline, "[%d] %s: %s",
+ ((this->graph) ? this->graph->id : 0), function, msg);
+ if (-1 == ret) {
+ goto out;
+ }
+
+ ret = eh_save_history(this->history, logline);
+
+out:
+ GF_FREE(logline);
+
+ FREE(msg);
+
+ return ret;
+}
+
+int
+gf_cmd_log_init(const char *filename)
+{
+ int fd = -1;
+ xlator_t *this = NULL;
+ glusterfs_ctx_t *ctx = NULL;
+
+ this = THIS;
+ ctx = this->ctx;
+
+ if (!ctx)
+ return -1;
+
+ if (!filename) {
+ gf_smsg(this->name, GF_LOG_CRITICAL, 0, LG_MSG_FILENAME_NOT_SPECIFIED,
+ "gf_cmd_log_init", NULL);
+ return -1;
+ }
+
+ ctx->log.cmd_log_filename = gf_strdup(filename);
+ if (!ctx->log.cmd_log_filename) {
+ return -1;
+ }
+ /* close and reopen cmdlogfile for log rotate*/
+ if (ctx->log.cmdlogfile) {
+ fclose(ctx->log.cmdlogfile);
+ ctx->log.cmdlogfile = NULL;
+ }
+
+ fd = sys_open(ctx->log.cmd_log_filename, O_CREAT | O_WRONLY | O_APPEND,
+ S_IRUSR | S_IWUSR);
+ if (fd < 0) {
+ gf_smsg(this->name, GF_LOG_CRITICAL, errno, LG_MSG_OPEN_LOGFILE_FAILED,
+ "cmd_log_file", NULL);
+ return -1;
+ }
+
+ ctx->log.cmdlogfile = fdopen(fd, "a");
+ if (!ctx->log.cmdlogfile) {
+ gf_smsg(this->name, GF_LOG_CRITICAL, errno, LG_MSG_OPEN_LOGFILE_FAILED,
+ "gf_cmd_log_init: %s", ctx->log.cmd_log_filename, NULL);
+ sys_close(fd);
+ return -1;
+ }
+ return 0;
+}
+
+int
+gf_cmd_log(const char *domain, const char *fmt, ...)
+{
+ va_list ap;
+ char timestr[GF_TIMESTR_SIZE];
+ struct timeval tv = {
+ 0,
+ };
+ char *logline = NULL;
+ char *msg = NULL;
+ int ret = 0;
+ int fd = -1;
+ glusterfs_ctx_t *ctx = NULL;
+
+ ctx = THIS->ctx;
+
+ if (!ctx)
+ return -1;
+
+ if (!ctx->log.cmdlogfile)
+ return -1;
+
+ if (!domain || !fmt) {
+ gf_msg_trace("glusterd", 0, "logging: invalid argument\n");
+ return -1;
+ }
+
+ ret = gettimeofday(&tv, NULL);
+ if (ret == -1)
+ goto out;
+ va_start(ap, fmt);
+ ret = vasprintf(&msg, fmt, ap);
+ va_end(ap);
+ if (ret == -1) {
+ goto out;
+ }
+
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
+
+ ret = gf_asprintf(&logline, "[%s] %s : %s\n", timestr, domain, msg);
+ if (ret == -1) {
+ goto out;
+ }
+
+ /* close and reopen cmdlogfile fd for in case of log rotate*/
+ if (ctx->log.cmd_history_logrotate) {
+ ctx->log.cmd_history_logrotate = 0;
+
+ if (ctx->log.cmdlogfile) {
+ fclose(ctx->log.cmdlogfile);
+ ctx->log.cmdlogfile = NULL;
}
- ret = gettimeofday (&tv, NULL);
- if (ret == -1)
+ fd = sys_open(ctx->log.cmd_log_filename, O_CREAT | O_WRONLY | O_APPEND,
+ S_IRUSR | S_IWUSR);
+ if (fd < 0) {
+ gf_smsg(THIS->name, GF_LOG_CRITICAL, errno,
+ LG_MSG_OPEN_LOGFILE_FAILED, "name=%s",
+ ctx->log.cmd_log_filename, NULL);
+ ret = -1;
+ goto out;
+ }
+
+ ctx->log.cmdlogfile = fdopen(fd, "a");
+ if (!ctx->log.cmdlogfile) {
+ gf_smsg(THIS->name, GF_LOG_CRITICAL, errno,
+ LG_MSG_OPEN_LOGFILE_FAILED, "name=%s",
+ ctx->log.cmd_log_filename, NULL);
+ ret = -1;
+ sys_close(fd);
+ goto out;
+ }
+ }
+
+ fputs(logline, ctx->log.cmdlogfile);
+ fflush(ctx->log.cmdlogfile);
+
+out:
+ GF_FREE(logline);
+
+ FREE(msg);
+
+ return ret;
+}
+
+static int
+_do_slog_format(int errnum, const char *event, va_list inp, char **msg)
+{
+ va_list valist_tmp;
+ int i = 0;
+ int j = 0;
+ int k = 0;
+ int ret = 0;
+ char *fmt = NULL;
+ char *buffer = NULL;
+ int num_format_chars = 0;
+ char format_char = '%';
+ char *tmp1 = NULL;
+ char *tmp2 = NULL;
+ char temp_sep[3] = "";
+
+ tmp2 = gf_strdup("");
+ if (!tmp2) {
+ ret = -1;
+ goto out;
+ }
+
+ /* Hardcoded value for max key value pairs, exits early */
+ /* from loop if found NULL */
+ for (i = 0; i < GF_MAX_SLOG_PAIR_COUNT; i++) {
+ fmt = va_arg(inp, char *);
+ if (fmt == NULL) {
+ break;
+ }
+
+ /* Get number of times % is used in input for formatting, */
+ /* this count will be used to skip those many args from the */
+ /* main list and will be used to format inner format */
+ num_format_chars = 0;
+ for (k = 0; fmt[k] != '\0'; k++) {
+ /* If %% is used then that is escaped */
+ if (fmt[k] == format_char && fmt[k + 1] == format_char) {
+ k++;
+ } else if (fmt[k] == format_char) {
+ num_format_chars++;
+ }
+ }
+
+ tmp1 = gf_strdup(tmp2);
+ if (!tmp1) {
+ ret = -1;
+ goto out;
+ }
+
+ GF_FREE(tmp2);
+ tmp2 = NULL;
+
+ if (num_format_chars > 0) {
+ /* Make separate valist and format the string */
+ va_copy(valist_tmp, inp);
+ ret = gf_vasprintf(&buffer, fmt, valist_tmp);
+ if (ret < 0) {
+ va_end(valist_tmp);
goto out;
- va_start (ap, fmt);
- gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
- snprintf (timestr + strlen (timestr), 256 - strlen (timestr),
- ".%"GF_PRI_SUSECONDS, tv.tv_usec);
-
- ret = gf_asprintf (&str1, "[%s] %s : ",
- timestr, domain);
- if (ret == -1) {
+ }
+ va_end(valist_tmp);
+
+ for (j = 0; j < num_format_chars; j++) {
+ /* Skip the va_arg value since these values
+ are already used for internal formatting */
+ (void)va_arg(inp, void *);
+ }
+
+ ret = gf_asprintf(&tmp2, "%s%s{%s}", tmp1, temp_sep, buffer);
+ if (ret < 0)
goto out;
- }
- ret = vasprintf (&str2, fmt, ap);
- if (ret == -1) {
+ GF_FREE(buffer);
+ buffer = NULL;
+ } else {
+ ret = gf_asprintf(&tmp2, "%s%s{%s}", tmp1, temp_sep, fmt);
+ if (ret < 0)
goto out;
}
- va_end (ap);
+ /* Set seperator for next iteration */
+ temp_sep[0] = ',';
+ temp_sep[1] = ' ';
+ temp_sep[2] = 0;
+
+ GF_FREE(tmp1);
+ tmp1 = NULL;
+ }
+
+ tmp1 = gf_strdup(tmp2);
+ if (!tmp1) {
+ ret = -1;
+ goto out;
+ }
+ GF_FREE(tmp2);
+ tmp2 = NULL;
+
+ if (errnum) {
+ ret = gf_asprintf(&tmp2, "%s [%s%s{errno=%d}, {error=%s}]", event, tmp1,
+ temp_sep, errnum, strerror(errnum));
+ } else {
+ ret = gf_asprintf(&tmp2, "%s [%s]", event, tmp1);
+ }
+
+ if (ret == -1)
+ goto out;
+
+ *msg = gf_strdup(tmp2);
+ if (!*msg)
+ ret = -1;
- len = strlen (str1);
- msg = GF_MALLOC (len + strlen (str2) + 1, gf_common_mt_char);
+out:
+ if (buffer)
+ GF_FREE(buffer);
- strcpy (msg, str1);
- strcpy (msg + len, str2);
+ if (tmp1)
+ GF_FREE(tmp1);
- fprintf (cmdlogfile, "%s\n", msg);
- fflush (cmdlogfile);
+ if (tmp2)
+ GF_FREE(tmp2);
-out:
- if (msg) {
- GF_FREE (msg);
- }
+ return ret;
+}
+
+int
+_gf_smsg(const char *domain, const char *file, const char *function,
+ int32_t line, gf_loglevel_t level, int errnum, int trace,
+ uint64_t msgid, const char *event, ...)
+{
+ va_list valist;
+ char *msg = NULL;
+ int ret = 0;
+ xlator_t *this = THIS;
- if (str1)
- GF_FREE (str1);
+ if (skip_logging(this, level))
+ return ret;
- if (str2)
- FREE (str2);
+ va_start(valist, event);
+ ret = _do_slog_format(errnum, event, valist, &msg);
+ if (ret == -1)
+ goto out;
- return (0);
+ /* Pass errnum as zero since it is already formated as required */
+ ret = _gf_msg(domain, file, function, line, level, 0, trace, msgid, "%s",
+ msg);
+
+out:
+ va_end(valist);
+ if (msg)
+ GF_FREE(msg);
+ return ret;
}
generated by cgit (git 2.34.1) at 2025-12-28 23:08:49 +0000