log: enhance gluster log format with message ID and standardize errno reporting

	Currently there are quite a slew of logs in Gluster that do not
	lend themselves to trivial analysis by various tools that help
	collect	and monitor logs, due to the textual nature of the logs.

	This FEAT is to make this better by giving logs message IDs so
	that the tools do not have to do complex log parsing to break
	it down to problem areas and suggest troubleshooting options.

	With this patch, a new set of logging APIs are introduced that
	take additionally a message ID and an error number, so as to
	print the message ID and the descriptive string for the error.

	New APIs:
		- gf_msg, gf_msg_debug/trace, gf_msg_nomem, gf_msg_callingfn

	These APIs follow the functionality of the previous gf_log*
	counterparts, and hence are 1:1 replacements, with the delta
	that, gf_msg, gf_msg_callingfn take additional parameters as
	specified above.

	Defining the log messages:
	Each invocation of gf_msg/gf_msg_callingfn, should provide an ID
	and an errnum (if available). Towards this, a common message id
	file is provided, which contains defines to various messages and
	their respective strings. As other messages are changed to the
	new infrastructure APIs, it is intended that this file is edited
	to add these messages as well.

	Framework enhanced:
	The logging framework is also enhanced to be able to support
	different logging backends in the future. Hence new configuration
	options for logging framework and logging formats are introduced.

	Backward compatibility:
	Currently the framework supports logging in the traditional
	format, with the inclusion of an error string based on the errnum
	passed in. Hence the shift to these new APIs would retain the log
	file names, locations, and format with the exception of an
	additional error string where applicable.

	Testing done:
	Tested the new APIs with different messages in normal code paths
	Tested with configurations set to gluster logs (syslog pending)
	Tested nomem variants, inducing the message in normal code paths
	Tested ident generation for normal code paths (other paths
		pending)
	Tested with sample gfapi program for gfapi messages
	Test code is stripped from the commit

	Pending work (not to be addressed in this patch (future)):
	- Logging framework should be configurable
	- Logging format should be configurable
	- Once all messages move to the new APIs deprecate/delete older
	  APIs to prevent misuse/abuse using the same
	- Repeated log messages should be suppressed (as a configurable
	  option)
	- Logging framework assumes that only one init is possible, but
	  there is no protection around the same (in existing code)
	- gf_log_fini is not invoked anywhere and does very little
	  cleanup (in existing code)
	- DOxygen comments to message id headers for each message

Change-Id: Ia043fda99a1c6cf7817517ef9e279bfcf35dcc24
BUG: 1075611
Signed-off-by: ShyamsundarR <srangana@redhat.com>
Reviewed-on: http://review.gluster.org/6547
Reviewed-by: Krutika Dhananjay <kdhananj@redhat.com>
Tested-by: Gluster Build System <jenkins@build.gluster.com>
Reviewed-by: Raghavendra G <rgowdapp@redhat.com>
Reviewed-by: Pranith Kumar Karampuri <pkarampu@redhat.com>
Reviewed-by: Vijay Bellur <vbellur@redhat.com>

1 files changed, 901 insertions, 173 deletions

diff --git a/libglusterfs/src/logging.c b/libglusterfs/src/logging.c
index 2bd40b2c2d6..f343731c7f4 100644
--- a/libglusterfs/src/logging.c
+++ b/libglusterfs/src/logging.c
@@ -22,7 +22,6 @@
 #include <string.h>
 #include <stdlib.h>
 
-#ifdef GF_USE_SYSLOG
 #include <libintl.h>
 #include <syslog.h>
 #include <sys/stat.h>
@@ -32,7 +31,9 @@
 #define GF_SYSLOG_CEE_FORMAT    \
         "@cee: {\"msg\": \"%s\", \"gf_code\": \"%u\", \"gf_message\": \"%s\"}"
 #define GF_LOG_CONTROL_FILE     "/etc/glusterfs/logger.conf"
-#endif /* GF_USE_SYSLOG */
+#define GF_LOG_BACKTRACE_DEPTH  5
+#define GF_LOG_BACKTRACE_SIZE   4096
+#define GF_LOG_TIMESTR_SIZE     256
 
 #include "xlator.h"
 #include "logging.h"
@@ -47,6 +48,19 @@
 #include <execinfo.h>
 #endif
 
+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;
@@ -60,41 +74,77 @@ struct _log_msg {
 void
 gf_log_logrotate (int signum)
 {
-        THIS->ctx->log.logrotate = 1;
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = THIS->ctx;
+
+        if (ctx)
+                ctx->log.logrotate = 1;
 }
 
 void
 gf_log_enable_syslog (void)
 {
-        THIS->ctx->log.gf_log_syslog = 1;
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = THIS->ctx;
+
+        if (ctx)
+                ctx->log.gf_log_syslog = 1;
 }
 
 void
 gf_log_disable_syslog (void)
 {
-        THIS->ctx->log.gf_log_syslog = 0;
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = THIS->ctx;
+
+        if (ctx)
+                ctx->log.gf_log_syslog = 0;
 }
 
 gf_loglevel_t
 gf_log_get_loglevel (void)
 {
-        return THIS->ctx->log.loglevel;
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = THIS->ctx;
+
+        if (ctx)
+                return ctx->log.loglevel;
+        else
+                /* return global defaluts (see gf_log_globals_init) */
+                return GF_LOG_INFO;
 }
 
 void
 gf_log_set_loglevel (gf_loglevel_t level)
 {
-        THIS->ctx->log.loglevel = level;
-}
+        glusterfs_ctx_t *ctx = NULL;
 
+        ctx = THIS->ctx;
 
-gf_loglevel_t
-gf_log_get_xl_loglevel (void *this)
+        if (ctx)
+                ctx->log.loglevel = level;
+}
+
+void
+gf_log_flush (void)
 {
-        xlator_t *xl = this;
-        if (!xl)
-                return 0;
-        return xl->loglevel;
+        xlator_t        *this           = NULL;
+        glusterfs_ctx_t *ctx            = NULL;
+
+        this = THIS;
+        ctx = this->ctx;
+
+        if (ctx && ctx->log.logger == gf_logger_glusterlog) {
+                pthread_mutex_lock (&ctx->log.logfile_mutex);
+                fflush (ctx->log.gf_log_logfile);
+                pthread_mutex_unlock (&ctx->log.logfile_mutex);
+        }
+
+        return;
 }
 
 void
@@ -107,9 +157,142 @@ gf_log_set_xl_loglevel (void *this, gf_loglevel_t level)
         xl->loglevel = level;
 }
 
+/* TODO: The following get/set functions are yet not invoked from anywhere
+ * in the code. The _intention_ is to pass CLI arguments to various daemons
+ * that are started, which would then invoke these set APIs as required.
+ *
+ * glusterd would read the defaults from its .vol file configuration shipped
+ * as a part of the packages distributed.
+ *
+ * For any gluster* daemon that is started the shipped configuration becomes the
+ * default, if a volume has to change its logging format or logger, then a
+ * gluster CLI is invoked to set this property for the volume in question.
+ *
+ * The property is maintained by glusterd, and passed to the daemon as a CLI
+ * option, IOW persistence of the option is maintained by glusterd persistent
+ * storage (i.e .vol file) only
+ *
+ * care needs to be taken to configure and start daemons based on the versions
+ * that supports these features */
+gf_log_format_t
+gf_log_get_logformat (void)
+{
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = THIS->ctx;
+
+        if (ctx)
+                return ctx->log.logformat;
+        else
+                /* return global defaluts (see gf_log_globals_init) */
+                return gf_logformat_withmsgid;
+}
+
+void
+gf_log_set_logformat (gf_log_format_t format)
+{
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = THIS->ctx;
+
+        if (ctx)
+                ctx->log.logformat = format;
+}
+
+gf_log_logger_t
+gf_log_get_logger (void)
+{
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = THIS->ctx;
+
+        if (ctx)
+                return ctx->log.logger;
+        else
+                /* return global defaluts (see gf_log_globals_init) */
+                return gf_logger_glusterlog;
+}
+
+void
+gf_log_set_logger (gf_log_logger_t logger)
+{
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = THIS->ctx;
+
+        if (ctx)
+                ctx->log.logger = logger;
+}
+
+gf_loglevel_t
+gf_log_get_xl_loglevel (void *this)
+{
+        xlator_t *xl = this;
+        if (!xl)
+                return 0;
+        return xl->loglevel;
+}
+
+static void
+gf_log_rotate(glusterfs_ctx_t *ctx)
+{
+        int            fd   = -1;
+        FILE          *new_logfile = NULL;
+        FILE          *old_logfile = NULL;
+
+        /* not involving locks on initial check to speed it up */
+        if (ctx->log.logrotate) {
+                /* let only one winner through on races */
+                pthread_mutex_lock (&ctx->log.logfile_mutex);
+
+                if (!ctx->log.logrotate) {
+                        pthread_mutex_unlock (&ctx->log.logfile_mutex);
+                        return;
+                } else {
+                        ctx->log.logrotate = 0;
+                        pthread_mutex_unlock (&ctx->log.logfile_mutex);
+                }
+
+                fd = open (ctx->log.filename,
+                           O_CREAT | O_RDONLY, S_IRUSR | S_IWUSR);
+                if (fd < 0) {
+                        gf_log ("logrotate", GF_LOG_ERROR,
+                                "%s", strerror (errno));
+                        return;
+                }
+                close (fd);
+
+                new_logfile = fopen (ctx->log.filename, "a");
+                if (!new_logfile) {
+                        gf_log ("logrotate", GF_LOG_CRITICAL,
+                                "failed to open logfile %s (%s)",
+                                ctx->log.filename, strerror (errno));
+                        return;
+                }
+
+                pthread_mutex_lock (&ctx->log.logfile_mutex);
+                {
+                        if (ctx->log.logfile)
+                                old_logfile = ctx->log.logfile;
+
+                        ctx->log.gf_log_logfile = ctx->log.logfile =
+                                                                new_logfile;
+                }
+                pthread_mutex_unlock (&ctx->log.logfile_mutex);
+
+                if (old_logfile != NULL)
+                        fclose (old_logfile);
+        }
+
+        return;
+}
+
 void
 gf_log_globals_fini (void)
 {
+        /* TODO: Nobody is invoking the fini, but cleanup needs to happen here,
+         * needs cleanup for, log.ident, log.filename, closelog, log file close
+         * rotate state, possibly under a lock */
         pthread_mutex_destroy (&THIS->ctx->log.logfile_mutex);
 }
 
@@ -122,7 +305,8 @@ int
 gf_log_fini (void *data)
 {
         glusterfs_ctx_t *ctx = data;
-        int ret = 0;
+        int              ret = 0;
+        FILE            *old_logfile = NULL;
 
         if (ctx == NULL) {
 	        ret = -1;
@@ -132,8 +316,8 @@ gf_log_fini (void *data)
         pthread_mutex_lock (&ctx->log.logfile_mutex);
         {
                 if (ctx->log.logfile) {
-                        if (fclose (ctx->log.logfile) != 0)
-                                ret = -1;
+                        old_logfile = ctx->log.logfile;
+
                         /* Logfile needs to be set to NULL, so that any
                            call to gf_log after calling gf_log_fini, will
                            log the message to stderr.
@@ -144,11 +328,13 @@ gf_log_fini (void *data)
         }
         pthread_mutex_unlock (&ctx->log.logfile_mutex);
 
+        if (old_logfile && (fclose (old_logfile) != 0))
+                ret = -1;
+
  out:
         return ret;
 }
 
-#ifdef GF_USE_SYSLOG
 /**
  * gf_get_error_message -function to get error message for given error code
  * @error_code: error code defined by log book
@@ -186,10 +372,13 @@ gf_openlog (const char *ident, int option, int facility)
                 _facility = LOG_LOCAL1;
         }
 
+        /* TODO: Should check for errors here and return appropriately */
         setlocale(LC_ALL, "");
         bindtextdomain("gluster", "/usr/share/locale");
         textdomain("gluster");
 
+        /* close the previous syslog if open as we are changing settings */
+        closelog ();
         openlog(ident, _option, _facility);
 }
 
@@ -347,7 +536,6 @@ gf_syslog (int error_code, int facility_priority, char *format, ...)
         }
         va_end (ap);
 }
-#endif /* GF_USE_SYSLOG */
 
 void
 gf_log_globals_init (void *data)
@@ -359,47 +547,45 @@ gf_log_globals_init (void *data)
         ctx->log.loglevel         = GF_LOG_INFO;
         ctx->log.gf_log_syslog    = 1;
         ctx->log.sys_log_level    = GF_LOG_CRITICAL;
+        ctx->log.logger           = gf_logger_glusterlog;
+        ctx->log.logformat        = gf_logformat_withmsgid;
 
-#ifndef GF_USE_SYSLOG
 #ifdef GF_LINUX_HOST_OS
         /* For the 'syslog' output. one can grep 'GlusterFS' in syslog
            for serious logs */
         openlog ("GlusterFS", LOG_PID, LOG_DAEMON);
 #endif
-#endif
+
 }
 
 int
 gf_log_init (void *data, const char *file, const char *ident)
 {
         glusterfs_ctx_t *ctx = NULL;
-        int     fd = -1;
+        int              fd = -1;
+        struct stat      buf;
 
         ctx = data;
 
-#if defined(GF_USE_SYSLOG)
-        {
-                /* use default ident and option */
-                /* TODO: make FACILITY configurable than LOG_DAEMON */
-                struct stat buf;
-
-                if (stat (GF_LOG_CONTROL_FILE, &buf) == 0) {
-                        /* use syslog logging */
-                        ctx->log.log_control_file_found = 1;
-                        if (ident) {
-                                /* we need to keep this value as */
-                                /* syslog uses it on every logging */
-                                ctx->log.ident = gf_strdup (ident);
-                                gf_openlog (ctx->log.ident, -1, LOG_DAEMON);
-                        } else {
-                                gf_openlog (NULL, -1, LOG_DAEMON);
-                        }
-                } else {
-                        /* use old style logging */
-                        ctx->log.log_control_file_found = 0;
-                }
+        if (ident) {
+                ctx->log.ident = gf_strdup (ident);
+        }
+
+        /* we keep the files and the syslog open, so that on logger change, we
+         * are ready to log anywhere, that the new value specifies */
+        if (ctx->log.ident) {
+                gf_openlog (ctx->log.ident, -1, LOG_DAEMON);
+        } else {
+                gf_openlog (NULL, -1, LOG_DAEMON);
+        }
+        /* TODO: make FACILITY configurable than LOG_DAEMON */
+        if (stat (GF_LOG_CONTROL_FILE, &buf) == 0) {
+                /* use syslog logging */
+                ctx->log.log_control_file_found = 1;
+        } else {
+                /* use old style logging */
+                ctx->log.log_control_file_found = 0;
         }
-#endif
 
         if (!file){
                 fprintf (stderr, "ERROR: no filename specified\n");
@@ -407,7 +593,7 @@ gf_log_init (void *data, const char *file, const char *ident)
         }
 
         if (strcmp (file, "-") == 0) {
-		file = "/dev/stderr";
+                file = "/dev/stderr";
         }
 
         ctx->log.filename = gf_strdup (file);
@@ -419,8 +605,8 @@ gf_log_init (void *data, const char *file, const char *ident)
 
         fd = open (file, O_CREAT | O_RDONLY, S_IRUSR | S_IWUSR);
         if (fd < 0) {
-                fprintf (stderr, "ERROR: failed to create logfile \"%s\" (%s)\n",
-                         file, strerror (errno));
+                fprintf (stderr, "ERROR: failed to create logfile"
+                         " \"%s\" (%s)\n", file, strerror (errno));
                 return -1;
         }
         close (fd);
@@ -440,21 +626,29 @@ gf_log_init (void *data, const char *file, const char *ident)
 void
 set_sys_log_level (gf_loglevel_t level)
 {
-        THIS->ctx->log.sys_log_level = level;
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = THIS->ctx;
+
+        if (ctx)
+                ctx->log.sys_log_level = level;
 }
 
 int
-_gf_log_nomem (const char *domain, const char *file,
-               const char *function, int line, gf_loglevel_t level,
-               size_t size)
+_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;
-        struct timeval  tv              = {0,};
-        int             ret             = 0;
-        char            msg[8092]       = {0,};
+        char           *str1            = NULL;
+        char           *str2            = NULL;
+        char           *msg             = NULL;
         char            timestr[256]    = {0,};
         char            callstr[4096]   = {0,};
+        struct timeval  tv              = {0,};
+        size_t          len             = 0;
+        int             ret             = 0;
+        va_list         ap;
         glusterfs_ctx_t *ctx = NULL;
 
         this = THIS;
@@ -479,7 +673,7 @@ _gf_log_nomem (const char *domain, const char *file,
                                         "T", /* TRACE */
                                         ""};
 
-        if (!domain || !file || !function) {
+        if (!domain || !file || !function || !fmt) {
                 fprintf (stderr,
                          "logging: %s:%s():%d: invalid argument\n",
                          __FILE__, __PRETTY_FUNCTION__, __LINE__);
@@ -497,28 +691,27 @@ _gf_log_nomem (const char *domain, const char *file,
         do {
                 void *array[5];
                 char **callingfn = NULL;
-                size_t bt_size = 0;
+                size_t size = 0;
 
-                bt_size = backtrace (array, 5);
-                if (bt_size)
-                        callingfn = backtrace_symbols (&array[2], bt_size-2);
+                size = backtrace (array, 5);
+                if (size)
+                        callingfn = backtrace_symbols (&array[2], size-2);
                 if (!callingfn)
                         break;
 
-                if (bt_size == 5)
+                if (size == 5)
                         snprintf (callstr, 4096, "(-->%s (-->%s (-->%s)))",
                                   callingfn[2], callingfn[1], callingfn[0]);
-                if (bt_size == 4)
+                if (size == 4)
                         snprintf (callstr, 4096, "(-->%s (-->%s))",
                                   callingfn[1], callingfn[0]);
-                if (bt_size == 3)
+                if (size == 3)
                         snprintf (callstr, 4096, "(-->%s)", callingfn[0]);
 
                 free (callingfn);
         } while (0);
 #endif /* HAVE_BACKTRACE */
 
-#if defined(GF_USE_SYSLOG)
         if (ctx->log.log_control_file_found)
         {
                 int priority;
@@ -529,30 +722,50 @@ _gf_log_nomem (const char *domain, const char *file,
                 } else {
                         priority = level - 1;
                 }
+
+                va_start (ap, fmt);
+                vasprintf (&str2, fmt, ap);
+                va_end (ap);
+
                 gf_syslog (GF_ERR_DEV, priority,
-                           "[%s:%d:%s] %s %s: no memory "
-                           "available for size (%"GF_PRI_SIZET")",
-                           basename, line, function, callstr, domain,
-                           size);
+                           "[%s:%d:%s] %s %d-%s: %s",
+                           basename, line, function,
+                           callstr,
+                           ((this->graph) ? this->graph->id:0), domain,
+                           str2);
+
                 goto out;
         }
-#endif /* GF_USE_SYSLOG */
+
         ret = gettimeofday (&tv, NULL);
         if (-1 == ret)
                 goto out;
+        va_start (ap, fmt);
         gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
         snprintf (timestr + strlen (timestr), sizeof timestr - strlen (timestr),
                   ".%"GF_PRI_SUSECONDS, tv.tv_usec);
 
-        ret = sprintf (msg, "[%s] %s [%s:%d:%s] %s %s: no memory "
-                       "available for size (%"GF_PRI_SIZET")",
-                       timestr, level_strings[level],
-                       basename, line, function, callstr,
-                       domain, size);
+        ret = gf_asprintf (&str1, "[%s] %s [%s:%d:%s] %s %d-%s: ",
+                           timestr, level_strings[level],
+                           basename, line, function, callstr,
+                           ((this->graph) ? this->graph->id:0), domain);
+        if (-1 == ret) {
+                goto out;
+        }
+
+        ret = vasprintf (&str2, fmt, ap);
         if (-1 == ret) {
                 goto out;
         }
 
+        va_end (ap);
+
+        len = strlen (str1);
+        msg = GF_MALLOC (len + strlen (str2) + 1, gf_common_mt_char);
+
+        strcpy (msg, str1);
+        strcpy (msg + len, str2);
+
         pthread_mutex_lock (&ctx->log.logfile_mutex);
         {
                 if (ctx->log.logfile) {
@@ -571,30 +784,82 @@ _gf_log_nomem (const char *domain, const char *file,
         }
 
         pthread_mutex_unlock (&ctx->log.logfile_mutex);
+
 out:
+        GF_FREE (msg);
+
+        GF_FREE (str1);
+
+        FREE (str2);
+
         return ret;
- }
+}
 
 int
-_gf_log_callingfn (const char *domain, const char *file, const char *function,
-                   int line, gf_loglevel_t level, const char *fmt, ...)
+_gf_msg_plain_internal (gf_loglevel_t level, const char *msg)
 {
-        const char     *basename        = NULL;
-        xlator_t       *this            = NULL;
-        char           *str1            = NULL;
-        char           *str2            = NULL;
-        char           *msg             = NULL;
-        char            timestr[256]    = {0,};
-        char            callstr[4096]   = {0,};
-        struct timeval  tv              = {0,};
-        size_t          len             = 0;
-        int             ret             = 0;
-        va_list         ap;
+        xlator_t        *this           = NULL;
+        glusterfs_ctx_t *ctx            = NULL;
+        int              priority;
+
+        this = THIS;
+        ctx = this->ctx;
+
+        /* log to the configured logging service */
+        switch (ctx->log.logger) {
+        case gf_logger_syslog:
+                if (ctx->log.log_control_file_found && ctx->log.gf_log_syslog) {
+                        SET_LOG_PRIO (level, priority);
+
+                        syslog (priority, "%s", msg);
+                        break;
+                }
+                /* NOTE: If syslog control file is absent, which is another
+                 * way to control logging to syslog, then we will fall through
+                 * to the gluster log. The ideal way to do things would be to
+                 * not have the extra control file check */
+        case gf_logger_glusterlog:
+                pthread_mutex_lock (&ctx->log.logfile_mutex);
+                {
+                        if (ctx->log.logfile) {
+                                fprintf (ctx->log.logfile, "%s\n", msg);
+                                fflush (ctx->log.logfile);
+                        } else {
+                                fprintf (stderr, "%s\n", msg);
+                                fflush (stderr);
+                        }
+
+#ifdef GF_LINUX_HOST_OS
+                        /* We want only serious logs in 'syslog', not our debug
+                                * and trace logs */
+                        if (ctx->log.gf_log_syslog && level &&
+                                (level <= ctx->log.sys_log_level))
+                                syslog ((level-1), "%s\n", msg);
+#endif
+                }
+                pthread_mutex_unlock (&ctx->log.logfile_mutex);
+
+                break;
+        }
+
+        return 0;
+}
+
+int
+_gf_msg_plain (gf_loglevel_t level, const char *fmt, ...)
+{
+        xlator_t        *this            = NULL;
+        int              ret             = 0;
+        va_list          ap;
+        char            *msg             = NULL;
         glusterfs_ctx_t *ctx = NULL;
 
         this = THIS;
         ctx = this->ctx;
 
+        if (!ctx)
+                goto out;
+
         if (ctx->log.gf_log_xl_log_set) {
                 if (this->loglevel && (level > this->loglevel))
                         goto out;
@@ -602,141 +867,604 @@ _gf_log_callingfn (const char *domain, const char *file, const char *function,
         if (level > ctx->log.loglevel)
                 goto out;
 
-        static char *level_strings[] = {"",  /* NONE */
-                                        "M", /* EMERGENCY */
-                                        "A", /* ALERT */
-                                        "C", /* CRITICAL */
-                                        "E", /* ERROR */
-                                        "W", /* WARNING */
-                                        "N", /* NOTICE */
-                                        "I", /* INFO */
-                                        "D", /* DEBUG */
-                                        "T", /* TRACE */
-                                        ""};
+        va_start (ap, fmt);
+        ret = vasprintf (&msg, fmt, ap);
+        va_end (ap);
+        if (-1 == ret) {
+                goto out;
+        }
 
-        if (!domain || !file || !function || !fmt) {
-                fprintf (stderr,
-                         "logging: %s:%s():%d: invalid argument\n",
-                         __FILE__, __PRETTY_FUNCTION__, __LINE__);
-                return -1;
+        ret = _gf_msg_plain_internal (level, msg);
+
+        FREE (msg);
+
+out:
+        return ret;
+}
+
+int
+_gf_msg_vplain (gf_loglevel_t level, const char *fmt, va_list ap)
+{
+        xlator_t        *this            = NULL;
+        int              ret             = 0;
+        char            *msg             = NULL;
+        glusterfs_ctx_t *ctx             = NULL;
+
+        this = THIS;
+        ctx = this->ctx;
+
+        if (!ctx)
+                goto out;
+
+        if (ctx->log.gf_log_xl_log_set) {
+                if (this->loglevel && (level > this->loglevel))
+                        goto out;
         }
+        if (level > ctx->log.loglevel)
+                goto out;
 
-        basename = strrchr (file, '/');
-        if (basename)
-                basename++;
-        else
-                basename = file;
+        ret = vasprintf (&msg, fmt, ap);
+        if (-1 == ret) {
+                goto out;
+        }
+
+        ret = _gf_msg_plain_internal (level, msg);
+
+        FREE (msg);
+out:
+        return ret;
+}
+
+int
+_gf_msg_plain_nomem (gf_loglevel_t level, const char *msg)
+{
+        xlator_t        *this           = NULL;
+        int              ret            = 0;
+        glusterfs_ctx_t *ctx            = NULL;
+
+        this = THIS;
+        ctx = this->ctx;
+
+        if (!ctx)
+                goto out;
+
+        if (ctx->log.gf_log_xl_log_set) {
+                if (this->loglevel && (level > this->loglevel))
+                        goto out;
+        }
+        if (level > ctx->log.loglevel)
+                goto out;
+
+        ret = _gf_msg_plain_internal (level, msg);
+
+out:
+        return ret;
+}
 
 #if HAVE_BACKTRACE
-        /* Print 'calling function' */
-        do {
-                void *array[5];
-                char **callingfn = NULL;
-                size_t size = 0;
+void
+_gf_msg_backtrace_nomem (gf_loglevel_t level, int stacksize)
+{
+        xlator_t        *this            = NULL;
+        glusterfs_ctx_t *ctx = NULL;
+        void            *array[200];
+        size_t           bt_size = 0;
+        int              fd = -1;
 
-                size = backtrace (array, 5);
-                if (size)
-                        callingfn = backtrace_symbols (&array[2], size-2);
-                if (!callingfn)
-                        break;
+        this = THIS;
+        ctx = this->ctx;
 
-                if (size == 5)
-                        snprintf (callstr, 4096, "(-->%s (-->%s (-->%s)))",
-                                  callingfn[2], callingfn[1], callingfn[0]);
-                if (size == 4)
-                        snprintf (callstr, 4096, "(-->%s (-->%s))",
-                                  callingfn[1], callingfn[0]);
-                if (size == 3)
-                        snprintf (callstr, 4096, "(-->%s)", callingfn[0]);
+        if (!ctx)
+                goto out;
 
-                free (callingfn);
-        } while (0);
-#endif /* HAVE_BACKTRACE */
+        /* syslog does not have fd support, hence no no-mem variant */
+        if (ctx->log.logger != gf_logger_glusterlog)
+                goto out;
 
-#if defined(GF_USE_SYSLOG)
-        if (ctx->log.log_control_file_found)
+        if (ctx->log.gf_log_xl_log_set) {
+                if (this->loglevel && (level > this->loglevel))
+                        goto out;
+        }
+        if (level > ctx->log.loglevel)
+                goto out;
+
+        bt_size = backtrace (array, ((stacksize <= 200)? stacksize : 200));
+        pthread_mutex_lock (&ctx->log.logfile_mutex);
         {
-                int priority;
-                /* treat GF_LOG_TRACE and GF_LOG_NONE as LOG_DEBUG and
-                   other level as is */
-                if (GF_LOG_TRACE == level || GF_LOG_NONE == level) {
-                        priority = LOG_DEBUG;
-                } else {
-                        priority = level - 1;
+                fd = ctx->log.logfile?
+                        fileno (ctx->log.logfile) :
+                        fileno (stderr);
+                if (bt_size && (fd != -1)) {
+                        /* print to the file fd, to prevent any
+                        * allocations from backtrace_symbols */
+                        backtrace_symbols_fd (&array[0], bt_size, fd);
                 }
+        }
+        pthread_mutex_unlock (&ctx->log.logfile_mutex);
 
-                va_start (ap, fmt);
-                vasprintf (&str2, fmt, ap);
-                va_end (ap);
+out:
+        return;
+}
 
-                gf_syslog (GF_ERR_DEV, priority,
-                           "[%s:%d:%s] %s %d-%s: %s",
-                           basename, line, function,
-                           callstr,
-                           ((this->graph) ? this->graph->id:0), domain,
-                           str2);
+int
+_gf_msg_backtrace (int stacksize, char *callstr, size_t strsize)
+{
+        int       ret = -1;
+        int       i = 0;
+        int       size = 0;
+        int       savstrsize = strsize;
+        void     *array[200];
+        char    **callingfn = NULL;
+
+        /* We chop off last 2 anyway, so if request is less than tolerance
+         * nothing to do */
+        if (stacksize < 3)
+                goto out;
 
+        size = backtrace (array, ((stacksize <= 200)? stacksize : 200));
+        if ((size - 3) < 0)
+                goto out;
+        if (size)
+                callingfn = backtrace_symbols (&array[2], size - 2);
+        if (!callingfn)
                 goto out;
+
+        ret = snprintf (callstr, strsize, "(");
+        PRINT_SIZE_CHECK (ret, out, strsize);
+
+        for ((i = size - 3); i >= 0; i--) {
+                ret = snprintf (callstr + savstrsize - strsize, strsize,
+                                "-->%s ", callingfn[i]);
+                PRINT_SIZE_CHECK (ret, out, strsize);
         }
-#endif /* GF_USE_SYSLOG */
+
+        ret = snprintf (callstr + savstrsize - strsize, strsize, ")");
+        PRINT_SIZE_CHECK (ret, out, strsize);
+out:
+        FREE (callingfn);
+        return ret;
+}
+#endif /* HAVE_BACKTRACE */
+
+int
+_gf_msg_nomem (const char *domain, const char *file,
+               const char *function, int line, gf_loglevel_t level,
+               size_t size)
+{
+        const char      *basename        = NULL;
+        xlator_t        *this            = NULL;
+        struct timeval   tv              = {0,};
+        int              ret             = 0;
+        int              fd              = -1;
+        char             msg[2048]       = {0,};
+        char             timestr[GF_LOG_TIMESTR_SIZE]    = {0,};
+        glusterfs_ctx_t *ctx = NULL;
+        int              wlen = 0;
+        int              priority;
+
+        this = THIS;
+        ctx = this->ctx;
+
+        if (!ctx)
+                goto out;
+
+        if (ctx->log.gf_log_xl_log_set) {
+                if (this->loglevel && (level > this->loglevel))
+                        goto out;
+        }
+        if (level > ctx->log.loglevel)
+                goto out;
+
+        if (!domain || !file || !function) {
+                fprintf (stderr,
+                         "logging: %s:%s():%d: invalid argument\n",
+                         __FILE__, __PRETTY_FUNCTION__, __LINE__);
+                return -1;
+        }
+
+        GET_FILE_NAME_TO_LOG (file, basename);
+
         ret = gettimeofday (&tv, NULL);
         if (-1 == ret)
                 goto out;
-        va_start (ap, fmt);
         gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
-        snprintf (timestr + strlen (timestr), sizeof timestr - strlen (timestr),
-                  ".%"GF_PRI_SUSECONDS, tv.tv_usec);
-
-        ret = gf_asprintf (&str1, "[%s] %s [%s:%d:%s] %s %d-%s: ",
-                           timestr, level_strings[level],
-                           basename, line, function, callstr,
-                           ((this->graph) ? this->graph->id:0), domain);
+        ret = snprintf (timestr + strlen (timestr),
+                        sizeof timestr - strlen (timestr),
+                        ".%"GF_PRI_SUSECONDS, tv.tv_usec);
         if (-1 == ret) {
                 goto out;
         }
 
-        ret = vasprintf (&str2, fmt, ap);
+        /* 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) {
                 goto out;
         }
 
-        va_end (ap);
+        /* log to the configured logging service */
+        switch (ctx->log.logger) {
+        case gf_logger_syslog:
+                if (ctx->log.log_control_file_found && ctx->log.gf_log_syslog) {
+                        SET_LOG_PRIO (level, priority);
 
-        len = strlen (str1);
-        msg = GF_MALLOC (len + strlen (str2) + 1, gf_common_mt_char);
+                        /* if syslog allocates, then this may fail, but we
+                         * cannot do much about it at the moment */
+                        /* There is no fd for syslog, hence no stack printed */
+                        syslog (priority, "%s", msg);
+                        break;
+                }
+                /* NOTE: If syslog control file is absent, which is another
+                 * way to control logging to syslog, then we will fall through
+                 * to the gluster log. The ideal way to do things would be to
+                 * not have the extra control file check */
+        case gf_logger_glusterlog:
+                pthread_mutex_lock (&ctx->log.logfile_mutex);
+                {
+                        fd = ctx->log.logfile? fileno (ctx->log.logfile) :
+                                fileno (stderr);
+                        if (fd == -1) {
+                                pthread_mutex_unlock (&ctx->log.logfile_mutex);
+                                goto out;
+                        }
 
-        strcpy (msg, str1);
-        strcpy (msg + len, str2);
+                        wlen = strlen (msg);
+
+                        /* write directly to the fd to prevent out of order
+                         * message and stack */
+                        ret = write (fd, msg, wlen);
+                        if (ret == -1) {
+                                pthread_mutex_unlock (&ctx->log.logfile_mutex);
+                                goto out;
+                        }
+#ifdef GF_LINUX_HOST_OS
+                        /* We want only serious log in 'syslog', not our debug
+                         * and trace logs */
+                        if (ctx->log.gf_log_syslog && level &&
+                                (level <= ctx->log.sys_log_level))
+                                syslog ((level-1), "%s\n", msg);
+#endif
+                }
+                pthread_mutex_unlock (&ctx->log.logfile_mutex);
+
+#ifdef HAVE_BACKTRACE
+                _gf_msg_backtrace_nomem (level, GF_LOG_BACKTRACE_DEPTH);
+#endif
+
+                break;
+        }
+
+out:
+        return ret;
+}
+
+static int
+gf_log_syslog (const char *domain, const char *file, const char *function,
+                   int32_t line, gf_loglevel_t level, int errnum,
+                   uint64_t msgid, char **appmsgstr, char *callstr)
+{
+        int              priority;
+        xlator_t        *this = NULL;
+        glusterfs_ctx_t *ctx = NULL;
+
+        this = THIS;
+        ctx = this->ctx;
+
+        SET_LOG_PRIO (level, priority);
+
+        /* log with appropriate format */
+        if (ctx->log.logformat == gf_logformat_traditional) {
+                if (!callstr) {
+                        if (errnum) {
+                                syslog (priority, "[%s:%d:%s] %d-%s: %s [%s]",
+                                        file, line, function,
+                                        ((this->graph)?this->graph->id:0),
+                                        domain, *appmsgstr, strerror(errnum));
+                        } else {
+                                syslog (priority, "[%s:%d:%s] %d-%s: %s",
+                                        file, line, function,
+                                        ((this->graph)?this->graph->id:0),
+                                        domain, *appmsgstr);
+                        }
+                } else {
+                        if (errnum) {
+                                syslog (priority, "[%s:%d:%s] %s %d-%s:"
+                                        " %s [%s]",
+                                        file, line, function, callstr,
+                                        ((this->graph)?this->graph->id:0),
+                                        domain, *appmsgstr, strerror(errnum));
+                        } else {
+                                syslog (priority, "[%s:%d:%s] %s %d-%s: %s",
+                                        file, line, function, callstr,
+                                        ((this->graph)?this->graph->id:0),
+                                        domain, *appmsgstr);
+                        }
+                }
+        } else if (ctx->log.logformat == gf_logformat_withmsgid) {
+                if (!callstr) {
+                        if (errnum) {
+                                syslog (priority, "[MSGID: %"PRIu64"]"
+                                        " [%s:%d:%s] %d-%s: %s [%s]",
+                                        msgid, file, line, function,
+                                        ((this->graph)?this->graph->id:0),
+                                        domain, *appmsgstr, strerror(errnum));
+                        } else {
+                                syslog (priority, "[MSGID: %"PRIu64"]"
+                                        " [%s:%d:%s] %d-%s: %s",
+                                        msgid, file, line, function,
+                                        ((this->graph)?this->graph->id:0),
+                                        domain, *appmsgstr);
+                        }
+                } else {
+                        if (errnum) {
+                                syslog (priority, "[MSGID: %"PRIu64"]"
+                                        " [%s:%d:%s] %s %d-%s: %s [%s]",
+                                        msgid, file, line, function, callstr,
+                                        ((this->graph)?this->graph->id:0),
+                                        domain, *appmsgstr, strerror(errnum));
+                        } else {
+                                syslog (priority, "[MSGID: %"PRIu64"]"
+                                        " [%s:%d:%s] %s %d-%s: %s",
+                                        msgid, file, line, function, callstr,
+                                        ((this->graph)?this->graph->id:0),
+                                        domain, *appmsgstr);
+                        }
+                }
+        } else if (ctx->log.logformat == gf_logformat_cee) {
+                /* TODO: Enhance CEE with additional parameters */
+                gf_syslog (GF_ERR_DEV, priority,
+                           "[%s:%d:%s] %d-%s: %s",
+                           file, line, function,
+                           ((this->graph) ? this->graph->id:0),
+                           domain, *appmsgstr);
+        } else {
+                /* NOTE: should not get here without logging */
+        }
+
+        /* TODO: There can be no errors from gf_syslog? */
+        return 0;
+}
+
+static int
+gf_log_glusterlog (const char *domain, const char *file, const char *function,
+                   int32_t line, gf_loglevel_t level, int errnum,
+                   uint64_t msgid, char **appmsgstr, char *callstr)
+{
+        char             timestr[GF_LOG_TIMESTR_SIZE] = {0,};
+        struct timeval   tv = {0,};
+        char            *header = NULL;
+        char            *footer = NULL;
+        char            *msg  = NULL;
+        size_t           hlen  = 0, flen = 0, mlen = 0;
+        int              ret  = 0;
+        xlator_t        *this = NULL;
+        glusterfs_ctx_t *ctx = NULL;
+
+        this = THIS;
+        ctx = this->ctx;
+
+        /* rotate if required */
+        gf_log_rotate(ctx);
+
+        /* format the time stanp */
+        ret = gettimeofday (&tv, NULL);
+        if (-1 == ret)
+                goto out;
+        gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
+        snprintf (timestr + strlen (timestr), sizeof timestr - strlen (timestr),
+                  ".%"GF_PRI_SUSECONDS, tv.tv_usec);
+
+        /* generate header and footer */
+        if (ctx->log.logformat == gf_logformat_traditional) {
+                if (!callstr) {
+                        ret = gf_asprintf (&header, "[%s] %s [%s:%d:%s]"
+                                                    " %d-%s: ",
+                                           timestr, gf_level_strings[level],
+                                           file, line, function,
+                                           ((this->graph)?this->graph->id:0),
+                                           domain);
+                } else {
+                        ret = gf_asprintf (&header, "[%s] %s [%s:%d:%s] %s"
+                                                    " %d-%s: ",
+                                           timestr, gf_level_strings[level],
+                                           file, line, function, callstr,
+                                           ((this->graph)?this->graph->id:0),
+                                           domain);
+                }
+                if (-1 == ret) {
+                        goto err;
+                }
+        } 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:%d:%s] %d-%s: ",
+                                           timestr, gf_level_strings[level],
+                                           msgid, file, line, function,
+                                           ((this->graph)?this->graph->id:0),
+                                           domain);
+                } else {
+                        ret = gf_asprintf (&header, "[%s] %s [MSGID: %"PRIu64"]"
+                                                    " [%s:%d:%s] %s %d-%s: ",
+                                           timestr, gf_level_strings[level],
+                                           msgid, file, line, function, callstr,
+                                           ((this->graph)?this->graph->id:0),
+                                           domain);
+                }
+                if (-1 == ret) {
+                        goto err;
+                }
+        }
+
+        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);
+
+        strcpy (msg, header);
+        strcpy (msg + hlen, *appmsgstr);
+        if (footer)
+                strcpy (msg + hlen + mlen, footer);
 
         pthread_mutex_lock (&ctx->log.logfile_mutex);
         {
                 if (ctx->log.logfile) {
                         fprintf (ctx->log.logfile, "%s\n", msg);
+                        fflush (ctx->log.logfile);
                 } else if (ctx->log.loglevel >= level) {
                         fprintf (stderr, "%s\n", msg);
+                        fflush (stderr);
                 }
 
 #ifdef GF_LINUX_HOST_OS
-                /* We want only serious log in 'syslog', not our debug
-                   and trace logs */
+                /* 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))
+                        (level <= ctx->log.sys_log_level))
                         syslog ((level-1), "%s\n", msg);
 #endif
         }
 
+        /* TODO: Plugin in memory log buffer retention here. For logs not
+         * flushed during cores, it would be useful to retain some of the last
+         * few messages in memory */
         pthread_mutex_unlock (&ctx->log.logfile_mutex);
 
-out:
+err:
         GF_FREE (msg);
+        GF_FREE (header);
+        GF_FREE (footer);
 
-        GF_FREE (str1);
+out:
+        return ret;
+}
 
-        FREE (str2);
+static int
+_gf_msg_internal (const char *domain, const char *file, const char *function,
+                  int32_t line, gf_loglevel_t level, int errnum, uint64_t msgid,
+                  char **appmsgstr, char *callstr)
+{
+        const char      *basename = NULL;
+        int              ret  = -1;
+        xlator_t        *this = NULL;
+        glusterfs_ctx_t *ctx = NULL;
+
+        this = THIS;
+        ctx = this->ctx;
+
+        GET_FILE_NAME_TO_LOG (file, basename);
+
+        /* TODO: Plug in repeated message suppression for gluster logs here.
+         * Comparison of last few messages stored based on, appmsgstr, errnum
+         * msgid. */
 
+        /* log to the configured logging service */
+        switch (ctx->log.logger) {
+        case gf_logger_syslog:
+                if (ctx->log.log_control_file_found && ctx->log.gf_log_syslog) {
+                        ret = gf_log_syslog (domain, basename, function, line,
+                                             level, errnum, msgid, appmsgstr,
+                                             callstr);
+                        break;
+                }
+                /* NOTE: If syslog control file is absent, which is another
+                 * way to control logging to syslog, then we will fall through
+                 * to the gluster log. The ideal way to do things would be to
+                 * not have the extra control file check */
+        case gf_logger_glusterlog:
+                ret = gf_log_glusterlog (domain, basename, function, line,
+                                         level, errnum, msgid, appmsgstr,
+                                         callstr);
+                break;
+        }
+
+        return ret;
+}
+
+int
+_gf_msg (const char *domain, const char *file, const char *function,
+         int32_t line, gf_loglevel_t level, int errnum, int trace,
+         uint64_t msgid, const char *fmt, ...)
+{
+        int              ret = 0;
+        char            *msgstr = NULL;
+        va_list          ap;
+        xlator_t        *this = NULL;
+        glusterfs_ctx_t *ctx = NULL;
+        char             callstr[GF_LOG_BACKTRACE_SIZE] = {0,};
+        int              passcallstr = 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;
+        ctx = this->ctx;
+        if (ctx == NULL) {
+                /* messages before context initialization are ignored */
+                return -1;
+        }
+
+        /* check if we should be logging */
+        if (ctx->log.gf_log_xl_log_set) {
+                if (this->loglevel && (level > this->loglevel))
+                        goto out;
+        }
+        if (level > ctx->log.loglevel)
+                goto out;
+
+#if HAVE_BACKTRACE
+        if (trace) {
+                ret = _gf_msg_backtrace (GF_LOG_BACKTRACE_DEPTH, callstr,
+                                         GF_LOG_BACKTRACE_DEPTH);
+                if (ret >= 0)
+                        passcallstr = 1;
+                else
+                        ret = 0;
+        }
+#endif /* HAVE_BACKTRACE */
+
+        /* form the message */
+        va_start (ap, fmt);
+        ret = vasprintf (&msgstr, fmt, ap);
+        va_end (ap);
+
+        /* log */
+        if (ret != -1)
+                ret = _gf_msg_internal(domain, file, function, line, level,
+                                       errnum, msgid, &msgstr,
+                                       (passcallstr? callstr : NULL));
+        else
+                /* man (3) vasprintf states on error strp contents
+                 * are undefined, be safe */
+                msgstr = NULL;
+
+        FREE (msgstr);
+
+out:
         return ret;
 }
 
+/* TODO: Deprecate (delete) _gf_log, _gf_log_callingfn,
+ * once messages are changed to use _gf_msgXXX APIs for logging */
 int
 _gf_log (const char *domain, const char *file, const char *function, int line,
          gf_loglevel_t level, const char *fmt, ...)
@@ -744,7 +1472,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[256] = {0,};
+        char           timestr[GF_LOG_TIMESTR_SIZE] = {0,};
         struct timeval tv = {0,};
         char          *str1 = NULL;
         char          *str2 = NULL;
@@ -790,7 +1518,6 @@ _gf_log (const char *domain, const char *file, const char *function, int line,
         else
                 basename = file;
 
-#if defined(GF_USE_SYSLOG)
         if (ctx->log.log_control_file_found)
         {
                 int priority;
@@ -812,7 +1539,6 @@ _gf_log (const char *domain, const char *file, const char *function, int line,
                            ((this->graph) ? this->graph->id:0), domain, str2);
                 goto err;
         }
-#endif /* GF_USE_SYSLOG */
 
         if (ctx->log.logrotate) {
                 ctx->log.logrotate = 0;
@@ -839,7 +1565,8 @@ _gf_log (const char *domain, const char *file, const char *function, int line,
                         if (ctx->log.logfile)
                                 fclose (ctx->log.logfile);
 
-                        ctx->log.gf_log_logfile = ctx->log.logfile = new_logfile;
+                        ctx->log.gf_log_logfile =
+                                ctx->log.logfile = new_logfile;
                 }
                 pthread_mutex_unlock (&ctx->log.logfile_mutex);
 
@@ -1033,7 +1760,8 @@ gf_cmd_log (const char *domain, const char *fmt, ...)
                 goto out;
         va_start (ap, fmt);
         gf_time_fmt (timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
-        snprintf (timestr + strlen (timestr), 256 - strlen (timestr),
+        snprintf (timestr + strlen (timestr),
+                  GF_LOG_TIMESTR_SIZE - strlen (timestr),
                   ".%"GF_PRI_SUSECONDS, tv.tv_usec);
 
         ret = gf_asprintf (&str1, "[%s] %s : ",