diff options
Diffstat (limited to 'libglusterfs/src/logging.c')
| -rw-r--r-- | libglusterfs/src/logging.c | 692 |
1 files changed, 266 insertions, 426 deletions
diff --git a/libglusterfs/src/logging.c b/libglusterfs/src/logging.c index b1a167f7997..a930d3e3b63 100644 --- a/libglusterfs/src/logging.c +++ b/libglusterfs/src/logging.c @@ -17,6 +17,7 @@ #include <string.h> #include <stdlib.h> #include <syslog.h> +#include <sys/resource.h> #ifdef HAVE_BACKTRACE #include <execinfo.h> @@ -26,7 +27,7 @@ #include <sys/stat.h> -#include "syscall.h" +#include "glusterfs/syscall.h" #define GF_JSON_MSG_LENGTH 8192 #define GF_SYSLOG_CEE_FORMAT \ @@ -34,22 +35,19 @@ #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 "xlator.h" -#include "logging.h" -#include "defaults.h" -#include "glusterfs.h" -#include "timer.h" -#include "libglusterfs-messages.h" +#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); -void +static void gf_log_flush_timeout_cbk(void *data); int @@ -58,72 +56,54 @@ 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; +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) { - glusterfs_ctx_t *ctx = NULL; - - ctx = THIS->ctx; - - if (ctx) { - ctx->log.logrotate = 1; - ctx->log.cmd_history_logrotate = 1; + if (THIS->ctx) { + THIS->ctx->log.logrotate = 1; + THIS->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; + if (THIS->ctx) + THIS->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; + if (THIS->ctx) + THIS->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; + if (THIS->ctx) + return THIS->ctx->log.loglevel; else /* return global defaults (see gf_log_globals_init) */ return GF_LOG_INFO; @@ -139,12 +119,8 @@ gf_log_set_loglevel(glusterfs_ctx_t *ctx, gf_loglevel_t level) int gf_log_get_localtime(void) { - glusterfs_ctx_t *ctx = NULL; - - ctx = THIS->ctx; - - if (ctx) - return ctx->log.localtime; + if (THIS->ctx) + return THIS->ctx->log.localtime; else /* return global defaults (see gf_log_globals_init) */ return 0; @@ -153,22 +129,15 @@ gf_log_get_localtime(void) void gf_log_set_localtime(int on_off) { - glusterfs_ctx_t *ctx = NULL; - - ctx = THIS->ctx; - - if (ctx) - ctx->log.localtime = on_off; + if (THIS->ctx) + THIS->ctx->log.localtime = on_off; } void gf_log_flush(void) { - xlator_t *this = NULL; - glusterfs_ctx_t *ctx = NULL; - - this = THIS; - ctx = this->ctx; + 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); @@ -205,54 +174,19 @@ gf_log_set_xl_loglevel(void *this, gf_loglevel_t level) * * 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; + if (THIS->ctx) + THIS->ctx->log.logformat = format; } void gf_log_set_logger(gf_log_logger_t logger) { - glusterfs_ctx_t *ctx = NULL; - - ctx = THIS->ctx; - - if (ctx) - ctx->log.logger = logger; + if (THIS->ctx) + THIS->ctx->log.logger = logger; } gf_loglevel_t @@ -296,21 +230,11 @@ 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 +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) @@ -349,7 +273,7 @@ out: return ret; } -int +static int log_buf_destroy(log_buf_t *buf) { if (!buf) @@ -387,18 +311,16 @@ gf_log_rotate(glusterfs_ctx_t *ctx) 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"); + gf_smsg("logrotate", GF_LOG_ERROR, errno, + LG_MSG_OPEN_LOGFILE_FAILED, NULL); 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); + gf_smsg("logrotate", GF_LOG_CRITICAL, errno, + LG_MSG_OPEN_LOGFILE_FAILED, "filename=%s", + ctx->log.filename, NULL); sys_close(fd); return; } @@ -507,7 +429,7 @@ out: * * @return: void */ -void +static void gf_openlog(const char *ident, int option, int facility) { int _option = option; @@ -551,7 +473,7 @@ gf_openlog(const char *ident, int option, int facility) * buf = "I/O error\u001bon /tmp/bar file" * */ -char * +static char * _json_escape(const char *str, char *buf, size_t len) { static const unsigned char json_exceptions[UCHAR_MAX + 1] = { @@ -630,7 +552,7 @@ _json_escape(const char *str, char *buf, size_t len) * * @return: void */ -void +static void gf_syslog(int facility_priority, char *format, ...) { char *msg = NULL; @@ -680,12 +602,10 @@ gf_log_globals_init(void *data, gf_loglevel_t level) int gf_log_init(void *data, const char *file, const char *ident) { - glusterfs_ctx_t *ctx = NULL; + glusterfs_ctx_t *ctx = data; int fd = -1; struct stat buf; - ctx = data; - if (ctx == NULL) { fprintf(stderr, "ERROR: ctx is NULL\n"); return -1; @@ -762,9 +682,8 @@ gf_log_init(void *data, const char *file, const char *ident) } 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_smsg("logging", GF_LOG_ERROR, 0, LG_MSG_STRDUP_ERROR, + "logdir=%s", logdir, "errno=%s", strerror(errno), NULL); GF_FREE(logdir); return -1; } @@ -808,12 +727,8 @@ gf_log_init(void *data, const char *file, const char *ident) 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; + if (THIS->ctx) + THIS->ctx->log.sys_log_level = level; } /* Check if we should be logging @@ -823,21 +738,17 @@ set_sys_log_level(gf_loglevel_t level) 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; + 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) { - ret = _gf_true; - goto out; + return _gf_true; } - existing_level = this->loglevel ? this->loglevel : this->ctx->log.loglevel; - if (level > existing_level) { - ret = _gf_true; - goto out; - } -out: - return ret; + return _gf_false; } int @@ -845,10 +756,10 @@ _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; + xlator_t *this = THIS; char *logline = NULL; char *msg = NULL; - char timestr[256] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; char *callstr = NULL; @@ -857,10 +768,7 @@ _gf_log_callingfn(const char *domain, const char *file, const char *function, }; int ret = 0; va_list ap; - glusterfs_ctx_t *ctx = NULL; - - this = THIS; - ctx = this->ctx; + glusterfs_ctx_t *ctx = this->ctx; if (!ctx) goto out; @@ -868,18 +776,6 @@ _gf_log_callingfn(const char *domain, const char *file, const char *function, 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 */ - "T", /* TRACE */ - ""}; - if (!domain || !file || !function || !fmt) { fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__, __PRETTY_FUNCTION__, __LINE__); @@ -923,13 +819,12 @@ _gf_log_callingfn(const char *domain, const char *file, const char *function, 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); + gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT); - ret = gf_asprintf(&logline, "[%s] %s [%s:%d:%s] %s %d-%s: %s", timestr, - level_strings[level], basename, line, function, callstr, - ((this->graph) ? this->graph->id : 0), domain, msg); + 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; } @@ -937,10 +832,10 @@ _gf_log_callingfn(const char *domain, const char *file, const char *function, pthread_mutex_lock(&ctx->log.logfile_mutex); { if (ctx->log.logfile) { - fprintf(ctx->log.logfile, "%s\n", logline); + fputs(logline, ctx->log.logfile); fflush(ctx->log.logfile); } else if (ctx->log.loglevel >= level) { - fprintf(stderr, "%s\n", logline); + fputs(logline, stderr); fflush(stderr); } @@ -949,7 +844,7 @@ _gf_log_callingfn(const char *domain, const char *file, const char *function, and trace logs */ if (ctx->log.gf_log_syslog && level && (level <= ctx->log.sys_log_level)) - syslog((level - 1), "%s\n", logline); + syslog((level - 1), "%s", logline); #endif } @@ -964,7 +859,7 @@ out: return ret; } -int +static int _gf_msg_plain_internal(gf_loglevel_t level, const char *msg) { xlator_t *this = NULL; @@ -1121,10 +1016,12 @@ _gf_msg_backtrace_nomem(gf_loglevel_t level, int stacksize) 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 (bt_size && (fd != -1)) { + if (fd != -1) { /* print to the file fd, to prevent any allocations from backtrace_symbols */ @@ -1190,12 +1087,13 @@ _gf_msg_nomem(const char *domain, const char *file, const char *function, char msg[2048] = { 0, }; - char timestr[GF_LOG_TIMESTR_SIZE] = { + 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; @@ -1217,25 +1115,23 @@ _gf_msg_nomem(const char *domain, const char *file, const char *function, ret = gettimeofday(&tv, NULL); if (-1 == ret) goto out; - gf_time_fmt(timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT); - ret = snprintf(timestr + strlen(timestr), sizeof timestr - strlen(timestr), - ".%" GF_PRI_SUSECONDS, tv.tv_usec); - 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 */ - ret = snprintf(msg, sizeof msg, - "[%s] %s [MSGID: %" PRIu64 - "]" - " [%s:%d:%s] %s: no memory " - "available for size (%" GF_PRI_SIZET - ")" - " [call stack follows]\n", - timestr, gf_level_strings[level], (uint64_t)0, basename, - line, function, domain, size); - if (-1 == ret) { + 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; } @@ -1265,8 +1161,6 @@ _gf_msg_nomem(const char *domain, const char *file, const char *function, goto out; } - wlen = strlen(msg); - /* write directly to the fd to prevent out of order * message and stack */ ret = sys_write(fd, msg, wlen); @@ -1380,93 +1274,77 @@ gf_log_glusterlog(glusterfs_ctx_t *ctx, const char *domain, const char *file, int errnum, uint64_t msgid, char **appmsgstr, char *callstr, struct timeval tv, int graph_id, gf_log_format_t fmt) { - char timestr[GF_LOG_TIMESTR_SIZE] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; char *header = NULL; char *footer = NULL; - char *msg = NULL; - size_t hlen = 0, flen = 0, mlen = 0; int ret = 0; /* rotate if required */ gf_log_rotate(ctx); /* format the time stamp */ - 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); + 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 header and footer */ + /* generate message, inc. the header */ if (fmt == gf_logformat_traditional) { if (!callstr) { ret = gf_asprintf(&header, - "[%s] %s [%s:%d:%s]" - " %d-%s: ", + "[%s] %c [%s:%d:%s]" + " %d-%s: %s", timestr, gf_level_strings[level], file, line, - function, graph_id, domain); + function, graph_id, domain, *appmsgstr); } else { ret = gf_asprintf(&header, - "[%s] %s [%s:%d:%s] %s" - " %d-%s: ", + "[%s] %c [%s:%d:%s] %s" + " %d-%s: %s", timestr, gf_level_strings[level], file, line, - function, callstr, graph_id, domain); - } - if (-1 == ret) { - goto err; + 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] %s [MSGID: %" PRIu64 + "[%s] %c [MSGID: %" PRIu64 "]" - " [%s:%d:%s] %d-%s: ", + " [%s:%d:%s] %d-%s: %s", timestr, gf_level_strings[level], msgid, file, - line, function, graph_id, domain); + line, function, graph_id, domain, *appmsgstr); } else { ret = gf_asprintf(&header, - "[%s] %s [MSGID: %" PRIu64 + "[%s] %c [MSGID: %" PRIu64 "]" - " [%s:%d:%s] %s %d-%s: ", + " [%s:%d:%s] %s %d-%s: %s", timestr, gf_level_strings[level], msgid, file, - line, function, callstr, graph_id, domain); - } - if (-1 == ret) { - goto err; + line, function, callstr, graph_id, domain, + *appmsgstr); } } - - if (errnum) { - ret = gf_asprintf(&footer, " [%s]", strerror(errnum)); - if (-1 == ret) { - goto err; - } - } - - /* generate the full message to log */ - hlen = strlen(header); - flen = footer ? strlen(footer) : 0; - mlen = strlen(*appmsgstr); - msg = GF_MALLOC(hlen + flen + mlen + 1, gf_common_mt_char); - if (!msg) { - ret = -1; + if (-1 == ret) { goto err; } - strcpy(msg, header); - strcpy(msg + hlen, *appmsgstr); - if (footer) - strcpy(msg + hlen + mlen, footer); + /* send the full message to log */ pthread_mutex_lock(&ctx->log.logfile_mutex); { if (ctx->log.logfile) { - fprintf(ctx->log.logfile, "%s\n", msg); + fprintf(ctx->log.logfile, "%s%s", header, footer); fflush(ctx->log.logfile); } else if (ctx->log.loglevel >= level) { - fprintf(stderr, "%s\n", msg); + fprintf(stderr, "%s%s", header, footer); fflush(stderr); } @@ -1474,8 +1352,9 @@ gf_log_glusterlog(glusterfs_ctx_t *ctx, const char *domain, const char *file, /* 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); + (level <= ctx->log.sys_log_level)) { + syslog((level - 1), "%s%s", header, footer); + } #endif } @@ -1486,7 +1365,6 @@ gf_log_glusterlog(glusterfs_ctx_t *ctx, const char *domain, const char *file, ret = 0; err: - GF_FREE(msg); GF_FREE(header); GF_FREE(footer); @@ -1502,39 +1380,34 @@ gf_syslog_log_repetitions(const char *domain, const char *file, int graph_id) { int priority; - char timestr_latest[256] = { + char timestr_latest[GF_TIMESTR_SIZE] = { 0, }; - char timestr_oldest[256] = { + char timestr_oldest[GF_TIMESTR_SIZE] = { 0, }; SET_LOG_PRIO(level, priority); - gf_time_fmt(timestr_latest, sizeof timestr_latest, latest.tv_sec, - gf_timefmt_FT); - snprintf(timestr_latest + strlen(timestr_latest), - sizeof(timestr_latest) - strlen(timestr_latest), - ".%" GF_PRI_SUSECONDS, latest.tv_usec); - - gf_time_fmt(timestr_oldest, sizeof timestr_oldest, oldest.tv_sec, - gf_timefmt_FT); - snprintf(timestr_oldest + strlen(timestr_oldest), - sizeof(timestr_oldest) - strlen(timestr_oldest), - ".%" GF_PRI_SUSECONDS, oldest.tv_usec); + 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", + "%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", + "%d-%s: %s \" repeated %d times between %s" + " and %s", msgid, file, line, function, graph_id, domain, *appmsgstr, refcount, timestr_oldest, timestr_latest); } @@ -1550,13 +1423,10 @@ gf_glusterlog_log_repetitions(glusterfs_ctx_t *ctx, const char *domain, struct timeval latest, int graph_id) { int ret = 0; - size_t hlen = 0; - size_t flen = 0; - size_t mlen = 0; - char timestr_latest[256] = { + char timestr_latest[GF_TIMESTR_SIZE] = { 0, }; - char timestr_oldest[256] = { + char timestr_oldest[GF_TIMESTR_SIZE] = { 0, }; char errstr[256] = { @@ -1564,65 +1434,45 @@ gf_glusterlog_log_repetitions(glusterfs_ctx_t *ctx, const char *domain, }; char *header = NULL; char *footer = NULL; - char *msg = NULL; if (!ctx) goto err; gf_log_rotate(ctx); - gf_time_fmt(timestr_latest, sizeof timestr_latest, latest.tv_sec, - gf_timefmt_FT); - snprintf(timestr_latest + strlen(timestr_latest), - sizeof(timestr_latest) - strlen(timestr_latest), - ".%" GF_PRI_SUSECONDS, latest.tv_usec); - - gf_time_fmt(timestr_oldest, sizeof timestr_oldest, oldest.tv_sec, - gf_timefmt_FT); - snprintf(timestr_oldest + strlen(timestr_oldest), - sizeof(timestr_oldest) - strlen(timestr_oldest), - ".%" GF_PRI_SUSECONDS, oldest.tv_usec); - ret = gf_asprintf(&header, - "The message \"%s [MSGID: %" PRIu64 + "The message \"%c [MSGID: %" PRIu64 "]" - " [%s:%d:%s] %d-%s: ", + " [%s:%d:%s] %d-%s: %s", gf_level_strings[level], msgid, file, line, function, - graph_id, domain); - if (-1 == ret) + 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]", + ret = gf_asprintf(&footer, "%s\" repeated %d times between [%s] and [%s]", errstr, refcount, timestr_oldest, timestr_latest); - if (-1 == ret) - goto err; - - /* generate the full message to log */ - hlen = strlen(header); - flen = strlen(footer); - mlen = strlen(*appmsgstr); - msg = GF_MALLOC(hlen + flen + mlen + 1, gf_common_mt_char); - if (!msg) { + if (-1 == ret) { ret = -1; goto err; } - strcpy(msg, header); - strcpy(msg + hlen, *appmsgstr); - strcpy(msg + hlen + mlen, footer); - pthread_mutex_lock(&ctx->log.logfile_mutex); { if (ctx->log.logfile) { - fprintf(ctx->log.logfile, "%s\n", msg); + fprintf(ctx->log.logfile, "%s%s\n", header, footer); fflush(ctx->log.logfile); } else if (ctx->log.loglevel >= level) { - fprintf(stderr, "%s\n", msg); + fprintf(stderr, "%s%s\n", header, footer); fflush(stderr); } @@ -1631,7 +1481,7 @@ gf_glusterlog_log_repetitions(glusterfs_ctx_t *ctx, const char *domain, * and trace logs */ if (ctx->log.gf_log_syslog && level && (level <= ctx->log.sys_log_level)) - syslog((level - 1), "%s\n", msg); + syslog((level - 1), "%s%s\n", header, footer); #endif } @@ -1642,7 +1492,6 @@ gf_glusterlog_log_repetitions(glusterfs_ctx_t *ctx, const char *domain, ret = 0; err: - GF_FREE(msg); GF_FREE(header); GF_FREE(footer); @@ -1658,9 +1507,7 @@ gf_log_print_with_repetitions(glusterfs_ctx_t *ctx, const char *domain, struct timeval latest, int graph_id) { int ret = -1; - gf_log_logger_t logger = 0; - - logger = ctx->log.logger; + gf_log_logger_t logger = ctx->log.logger; switch (logger) { case gf_logger_syslog: @@ -1670,6 +1517,11 @@ gf_log_print_with_repetitions(glusterfs_ctx_t *ctx, const char *domain, 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, @@ -1994,7 +1846,7 @@ _gf_msg_internal(const char *domain, const char *file, const char *function, if (size == 0) { flush_logged_msg = _gf_true; goto unlock; - } else if ((ctx->log.lru_cur_size + 1) > size) { + } 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 ... * */ @@ -2011,7 +1863,7 @@ _gf_msg_internal(const char *domain, const char *file, const char *function, /* 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 = log_buf_new(); + buf_new = mem_get0(THIS->ctx->logbuf_pool); if (!buf_new) { ret = -1; goto unlock; @@ -2063,23 +1915,11 @@ _gf_msg(const char *domain, const char *file, const char *function, int ret = 0; char *msgstr = NULL; va_list ap; - xlator_t *this = NULL; + xlator_t *this = THIS; glusterfs_ctx_t *ctx = NULL; - char callstr[GF_LOG_BACKTRACE_SIZE] = { - 0, - }; - int passcallstr = 0; + char *callstr = NULL; int log_inited = 0; - /* in args check */ - if (!domain || !file || !function || !fmt) { - fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__, - __PRETTY_FUNCTION__, __LINE__); - return -1; - } - - this = THIS; - if (this == NULL) return -1; @@ -2093,20 +1933,12 @@ _gf_msg(const char *domain, const char *file, const char *function, if (skip_logging(this, level)) goto out; - if (trace) { - ret = _gf_msg_backtrace(GF_LOG_BACKTRACE_DEPTH, callstr, - GF_LOG_BACKTRACE_SIZE); - if (ret >= 0) - passcallstr = 1; - } - - pthread_mutex_lock(&ctx->log.logfile_mutex); - { - if (ctx->log.logfile) { - log_inited = 1; - } + /* in args check */ + if (!domain || !file || !function || !fmt) { + fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__, + __PRETTY_FUNCTION__, __LINE__); + return -1; } - pthread_mutex_unlock(&ctx->log.logfile_mutex); /* form the message */ va_start(ap, fmt); @@ -2115,15 +1947,35 @@ _gf_msg(const char *domain, const char *file, const char *function, /* 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, (passcallstr ? callstr : NULL), + &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, - (passcallstr ? callstr : NULL), + msgid, &msgstr, (callstr ? callstr : NULL), (this->graph) ? this->graph->id : 0); } } else { @@ -2131,7 +1983,8 @@ _gf_msg(const char *domain, const char *file, const char *function, * are undefined, be safe */ msgstr = NULL; } - + if (callstr) + GF_FREE(callstr); FREE(msgstr); out: @@ -2147,7 +2000,7 @@ _gf_log(const char *domain, const char *file, const char *function, int line, const char *basename = NULL; FILE *new_logfile = NULL; va_list ap; - char timestr[GF_LOG_TIMESTR_SIZE] = { + char timestr[GF_TIMESTR_SIZE] = { 0, }; struct timeval tv = { @@ -2157,11 +2010,8 @@ _gf_log(const char *domain, const char *file, const char *function, int line, char *msg = NULL; int ret = 0; int fd = -1; - xlator_t *this = NULL; - glusterfs_ctx_t *ctx = NULL; - - this = THIS; - ctx = this->ctx; + xlator_t *this = THIS; + glusterfs_ctx_t *ctx = this->ctx; if (!ctx) goto out; @@ -2169,18 +2019,6 @@ _gf_log(const char *domain, const char *file, const char *function, int line, 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 */ - "T", /* TRACE */ - ""}; - if (!domain || !file || !function || !fmt) { fprintf(stderr, "logging: %s:%s():%d: invalid argument\n", __FILE__, __PRETTY_FUNCTION__, __LINE__); @@ -2220,16 +2058,17 @@ _gf_log(const char *domain, const char *file, const char *function, int line, fd = sys_open(ctx->log.filename, O_CREAT | O_RDONLY, S_IRUSR | S_IWUSR); if (fd < 0) { - gf_msg("logrotate", GF_LOG_ERROR, errno, LG_MSG_FILE_OP_FAILED, - "failed to open logfile"); + 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_msg("logrotate", GF_LOG_CRITICAL, errno, LG_MSG_FILE_OP_FAILED, - "failed to open logfile %s", ctx->log.filename); + gf_smsg("logrotate", GF_LOG_CRITICAL, errno, + LG_MSG_OPEN_LOGFILE_FAILED, "filename=%s", + ctx->log.filename, NULL); goto log; } @@ -2248,12 +2087,10 @@ log: 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); + gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT); - ret = gf_asprintf(&logline, "[%s] %s [%s:%d:%s] %d-%s: %s", timestr, - level_strings[level], basename, line, function, + 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; @@ -2262,10 +2099,10 @@ log: pthread_mutex_lock(&ctx->log.logfile_mutex); { if (ctx->log.logfile) { - fprintf(ctx->log.logfile, "%s\n", logline); + fputs(logline, ctx->log.logfile); fflush(ctx->log.logfile); } else if (ctx->log.loglevel >= level) { - fprintf(stderr, "%s\n", logline); + fputs(logline, stderr); fflush(stderr); } @@ -2274,7 +2111,7 @@ log: and trace logs */ if (ctx->log.gf_log_syslog && level && (level <= ctx->log.sys_log_level)) - syslog((level - 1), "%s\n", logline); + syslog((level - 1), "%s", logline); #endif } @@ -2337,8 +2174,8 @@ gf_cmd_log_init(const char *filename) return -1; if (!filename) { - gf_msg(this->name, GF_LOG_CRITICAL, 0, LG_MSG_INVALID_ENTRY, - "gf_cmd_log_init: no filename specified\n"); + gf_smsg(this->name, GF_LOG_CRITICAL, 0, LG_MSG_FILENAME_NOT_SPECIFIED, + "gf_cmd_log_init", NULL); return -1; } @@ -2355,17 +2192,15 @@ gf_cmd_log_init(const char *filename) fd = sys_open(ctx->log.cmd_log_filename, O_CREAT | O_WRONLY | O_APPEND, S_IRUSR | S_IWUSR); if (fd < 0) { - gf_msg(this->name, GF_LOG_CRITICAL, errno, LG_MSG_FILE_OP_FAILED, - "failed to open cmd_log_file"); + 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_msg(this->name, GF_LOG_CRITICAL, errno, LG_MSG_FILE_OP_FAILED, - "gf_cmd_log_init: failed to open logfile \"%s\" " - "\n", - ctx->log.cmd_log_filename); + 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; } @@ -2376,7 +2211,7 @@ int gf_cmd_log(const char *domain, const char *fmt, ...) { va_list ap; - char timestr[64]; + char timestr[GF_TIMESTR_SIZE]; struct timeval tv = { 0, }; @@ -2409,11 +2244,9 @@ gf_cmd_log(const char *domain, const char *fmt, ...) goto out; } - gf_time_fmt(timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT); - snprintf(timestr + strlen(timestr), GF_LOG_TIMESTR_SIZE - strlen(timestr), - ".%" GF_PRI_SUSECONDS, tv.tv_usec); + gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT); - ret = gf_asprintf(&logline, "[%s] %s : %s", timestr, domain, msg); + ret = gf_asprintf(&logline, "[%s] %s : %s\n", timestr, domain, msg); if (ret == -1) { goto out; } @@ -2430,27 +2263,25 @@ gf_cmd_log(const char *domain, const char *fmt, ...) fd = sys_open(ctx->log.cmd_log_filename, O_CREAT | O_WRONLY | O_APPEND, S_IRUSR | S_IWUSR); if (fd < 0) { - gf_msg(THIS->name, GF_LOG_CRITICAL, errno, LG_MSG_FILE_OP_FAILED, - "failed to open " - "logfile \"%s\" \n", - ctx->log.cmd_log_filename); + 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_msg(THIS->name, GF_LOG_CRITICAL, errno, LG_MSG_FILE_OP_FAILED, - "failed to open logfile \"%s\"" - " \n", - ctx->log.cmd_log_filename); + 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; } } - fprintf(ctx->log.cmdlogfile, "%s\n", logline); + fputs(logline, ctx->log.cmdlogfile); fflush(ctx->log.cmdlogfile); out: @@ -2462,7 +2293,7 @@ out: } static int -_do_slog_format(const char *event, va_list inp, char **msg) +_do_slog_format(int errnum, const char *event, va_list inp, char **msg) { va_list valist_tmp; int i = 0; @@ -2475,10 +2306,13 @@ _do_slog_format(const char *event, va_list inp, char **msg) char format_char = '%'; char *tmp1 = NULL; char *tmp2 = NULL; + char temp_sep[3] = ""; - ret = gf_asprintf(&tmp2, "%s", event); - if (ret == -1) + tmp2 = gf_strdup(""); + if (!tmp2) { + ret = -1; goto out; + } /* Hardcoded value for max key value pairs, exits early */ /* from loop if found NULL */ @@ -2526,22 +2360,45 @@ _do_slog_format(const char *event, va_list inp, char **msg) (void)va_arg(inp, void *); } - ret = gf_asprintf(&tmp2, "%s\t%s", tmp1, buffer); + ret = gf_asprintf(&tmp2, "%s%s{%s}", tmp1, temp_sep, buffer); if (ret < 0) goto out; GF_FREE(buffer); buffer = NULL; } else { - ret = gf_asprintf(&tmp2, "%s\t%s", tmp1, fmt); + ret = gf_asprintf(&tmp2, "%s%s{%s}", tmp1, temp_sep, fmt); if (ret < 0) goto out; } + /* 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; @@ -2567,36 +2424,19 @@ _gf_smsg(const char *domain, const char *file, const char *function, va_list valist; char *msg = NULL; int ret = 0; + xlator_t *this = THIS; - va_start(valist, event); - ret = _do_slog_format(event, valist, &msg); - if (ret == -1) - goto out; - - ret = _gf_msg(domain, file, function, line, level, errnum, trace, msgid, - "%s", msg); - -out: - va_end(valist); - if (msg) - GF_FREE(msg); - return ret; -} - -int -_gf_slog(const char *domain, const char *file, const char *function, int line, - gf_loglevel_t level, const char *event, ...) -{ - va_list valist; - char *msg = NULL; - int ret = 0; + if (skip_logging(this, level)) + return ret; va_start(valist, event); - ret = _do_slog_format(event, valist, &msg); + ret = _do_slog_format(errnum, event, valist, &msg); if (ret == -1) goto out; - ret = _gf_log(domain, file, function, line, level, "%s", msg); + /* 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); |