summaryrefslogtreecommitdiffstats
path: root/libglusterfs/src/logging.c
diff options
context:
space:
mode:
authorYaniv Kaul <ykaul@redhat.com>2019-03-08 14:13:32 +0200
committerAmar Tumballi <amarts@redhat.com>2019-04-25 04:13:31 +0000
commit3db4f4ed6dec55316e7167eaddd9ddf0af875185 (patch)
tree2a2381befb39488755d207dfbd848c176524eda7 /libglusterfs/src/logging.c
parent1ccc62d11287e8ffd091123517f7988a4e7f1935 (diff)
logging.c/h: aggressively remove sprintfs()
Try to reduce the number of sprintf() and string copies until we finally log a log line. Specifically, do not sprintf separately the timestr string and do not sprintf/strcpy the appmsgstr separately - just stick it with the header. Hoping I did not leak anything or changed the log line formatting. Also, allocate 4K (GF_LOG_BACKTRACE_SIZE) of memory dynamically for trace output - only if trace was actually requested (previously, it was unconditionally) In addition, some minor code formatting (unrelated to the above). updates: bz#1193929 Signed-off-by: Yaniv Kaul <ykaul@redhat.com> Change-Id: Id2ccc85f9213a2b1c6eaa4a2f58ce043eac1824f
Diffstat (limited to 'libglusterfs/src/logging.c')
-rw-r--r--libglusterfs/src/logging.c517
1 files changed, 195 insertions, 322 deletions
diff --git a/libglusterfs/src/logging.c b/libglusterfs/src/logging.c
index 5d469163220..c9d733db99d 100644
--- a/libglusterfs/src/logging.c
+++ b/libglusterfs/src/logging.c
@@ -83,47 +83,31 @@ struct _log_msg {
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 +123,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 +133,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 +178,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 +234,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 +277,7 @@ out:
return ret;
}
-int
+static int
log_buf_destroy(log_buf_t *buf)
{
if (!buf)
@@ -507,7 +435,7 @@ out:
*
* @return: void
*/
-void
+static void
gf_openlog(const char *ident, int option, int facility)
{
int _option = option;
@@ -630,7 +558,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 +608,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;
@@ -808,12 +734,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 +745,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 +763,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_LOG_TIMESTR_SIZE] = {
0,
};
char *callstr = NULL;
@@ -857,10 +775,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,17 +783,17 @@ _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 */
- ""};
+ static const 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__,
@@ -924,12 +839,11 @@ _gf_log_callingfn(const char *domain, const char *file, const char *function,
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);
- 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.%" GF_PRI_SUSECONDS "] %s [%s:%d:%s] %s %d-%s: %s\n",
+ timestr, tv.tv_usec, level_strings[level], basename, line, function,
+ callstr, ((this->graph) ? this->graph->id : 0), domain, msg);
if (-1 == ret) {
goto out;
}
@@ -937,10 +851,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 +863,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 +878,7 @@ out:
return ret;
}
-int
+static int
_gf_msg_plain_internal(gf_loglevel_t level, const char *msg)
{
xlator_t *this = NULL;
@@ -1121,10 +1035,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
*/
@@ -1218,24 +1134,20 @@ _gf_msg_nomem(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);
- ret = snprintf(timestr + strlen(timestr), sizeof timestr - strlen(timestr),
- ".%" GF_PRI_SUSECONDS, tv.tv_usec);
- if (-1 == ret) {
- goto out;
- }
/* 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.%" GF_PRI_SUSECONDS "] %s [MSGID: %" PRIu64
+ "]"
+ " [%s:%d:%s] %s: no memory "
+ "available for size (%" GF_PRI_SIZET
+ ")"
+ " [call stack follows]\n",
+ timestr, tv.tv_usec, gf_level_strings[level], (uint64_t)0,
+ basename, line, function, domain, size);
+ if (-1 == wlen) {
+ ret = -1;
goto out;
}
@@ -1265,8 +1177,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);
@@ -1385,8 +1295,6 @@ gf_log_glusterlog(glusterfs_ctx_t *ctx, const char *domain, const char *file,
};
char *header = NULL;
char *footer = NULL;
- char *msg = NULL;
- size_t hlen = 0, flen = 0, mlen = 0;
int ret = 0;
/* rotate if required */
@@ -1394,79 +1302,70 @@ gf_log_glusterlog(glusterfs_ctx_t *ctx, const char *domain, const char *file,
/* 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);
- /* generate header and footer */
+ /* 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] %s [%s:%d:%s]"
- " %d-%s: ",
- timestr, gf_level_strings[level], file, line,
- function, graph_id, domain);
+ "[%s.%" GF_PRI_SUSECONDS
+ "] %s [%s:%d:%s]"
+ " %d-%s: %s",
+ timestr, tv.tv_usec, gf_level_strings[level],
+ file, line, function, graph_id, domain,
+ *appmsgstr);
} else {
ret = gf_asprintf(&header,
- "[%s] %s [%s:%d:%s] %s"
- " %d-%s: ",
- timestr, gf_level_strings[level], file, line,
- function, callstr, graph_id, domain);
- }
- if (-1 == ret) {
- goto err;
+ "[%s.%" GF_PRI_SUSECONDS
+ "] %s [%s:%d:%s] %s"
+ " %d-%s: %s",
+ timestr, tv.tv_usec, 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] %s [MSGID: %" PRIu64
+ "[%s.%" GF_PRI_SUSECONDS "] %s [MSGID: %" PRIu64
"]"
- " [%s:%d:%s] %d-%s: ",
- timestr, gf_level_strings[level], msgid, file,
- line, function, graph_id, domain);
+ " [%s:%d:%s] %d-%s: %s",
+ timestr, tv.tv_usec, gf_level_strings[level],
+ msgid, file, line, function, graph_id, domain,
+ *appmsgstr);
} else {
ret = gf_asprintf(&header,
- "[%s] %s [MSGID: %" PRIu64
+ "[%s.%" GF_PRI_SUSECONDS "] %s [MSGID: %" PRIu64
"]"
- " [%s:%d:%s] %s %d-%s: ",
- timestr, gf_level_strings[level], msgid, file,
- line, function, callstr, graph_id, domain);
- }
- if (-1 == ret) {
- goto err;
+ " [%s:%d:%s] %s %d-%s: %s",
+ timestr, tv.tv_usec, gf_level_strings[level],
+ msgid, file, 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 +1373,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 +1386,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,10 +1401,10 @@ gf_syslog_log_repetitions(const char *domain, const char *file,
int graph_id)
{
int priority;
- char timestr_latest[256] = {
+ char timestr_latest[GF_LOG_TIMESTR_SIZE] = {
0,
};
- char timestr_oldest[256] = {
+ char timestr_oldest[GF_LOG_TIMESTR_SIZE] = {
0,
};
@@ -1513,30 +1412,28 @@ gf_syslog_log_repetitions(const char *domain, const char *file,
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);
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);
+ syslog(
+ priority,
+ "The message \"[MSGID: %" PRIu64
+ "] [%s:%d:%s] "
+ "%d-%s: %s [%s] \" repeated %d times between %s.%" GF_PRI_SUSECONDS
+ " and %s.%" GF_PRI_SUSECONDS,
+ msgid, file, line, function, graph_id, domain, *appmsgstr,
+ strerror(errnum), refcount, timestr_oldest, oldest.tv_usec,
+ timestr_latest, latest.tv_usec);
} 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.%" GF_PRI_SUSECONDS
+ " and %s.%" GF_PRI_SUSECONDS,
msgid, file, line, function, graph_id, domain, *appmsgstr,
- refcount, timestr_oldest, timestr_latest);
+ refcount, timestr_oldest, oldest.tv_usec, timestr_latest,
+ latest.tv_usec);
}
return 0;
}
@@ -1550,13 +1447,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_LOG_TIMESTR_SIZE] = {
0,
};
- char timestr_oldest[256] = {
+ char timestr_oldest[GF_LOG_TIMESTR_SIZE] = {
0,
};
char errstr[256] = {
@@ -1564,65 +1458,49 @@ 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
"]"
- " [%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(timestr_latest, sizeof timestr_latest, latest.tv_sec,
+ gf_timefmt_FT);
+
+ gf_time_fmt(timestr_oldest, sizeof timestr_oldest, oldest.tv_sec,
+ 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)
- 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) {
+ " [%s.%" GF_PRI_SUSECONDS "] and [%s.%" GF_PRI_SUSECONDS
+ "]",
+ errstr, refcount, timestr_oldest, oldest.tv_usec,
+ timestr_latest, latest.tv_usec);
+ 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 +1509,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 +1520,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 +1535,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:
@@ -2011,7 +1886,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;
@@ -2065,10 +1940,7 @@ _gf_msg(const char *domain, const char *file, const char *function,
va_list ap;
xlator_t *this = NULL;
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 */
@@ -2093,21 +1965,6 @@ _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;
- }
- }
- pthread_mutex_unlock(&ctx->log.logfile_mutex);
-
/* form the message */
va_start(ap, fmt);
ret = vasprintf(&msgstr, fmt, ap);
@@ -2115,15 +1972,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 +2008,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:
@@ -2157,11 +2035,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,17 +2044,17 @@ _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 */
- ""};
+ static const 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__,
@@ -2249,12 +2124,11 @@ log:
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);
- ret = gf_asprintf(&logline, "[%s] %s [%s:%d:%s] %d-%s: %s", timestr,
- level_strings[level], basename, line, function,
- ((this->graph) ? this->graph->id : 0), domain, msg);
+ ret = gf_asprintf(
+ &logline, "[%s.%" GF_PRI_SUSECONDS "] %s [%s:%d:%s] %d-%s: %s\n",
+ timestr, tv.tv_usec, level_strings[level], basename, line, function,
+ ((this->graph) ? this->graph->id : 0), domain, msg);
if (-1 == ret) {
goto err;
}
@@ -2262,10 +2136,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 +2148,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
}
@@ -2410,10 +2284,9 @@ gf_cmd_log(const char *domain, const char *fmt, ...)
}
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);
- ret = gf_asprintf(&logline, "[%s] %s : %s", timestr, domain, msg);
+ ret = gf_asprintf(&logline, "[%s.%" GF_PRI_SUSECONDS "] %s : %s\n", timestr,
+ tv.tv_usec, domain, msg);
if (ret == -1) {
goto out;
}
@@ -2450,7 +2323,7 @@ gf_cmd_log(const char *domain, const char *fmt, ...)
}
}
- fprintf(ctx->log.cmdlogfile, "%s\n", logline);
+ fputs(logline, ctx->log.cmdlogfile);
fflush(ctx->log.cmdlogfile);
out: