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

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: