libglusterfs: gf_log_nomem() and other minor updates

log will be done when the memory allocation fails, hence in code,
no explicit logs required for memory allocation failures.

also, if there are logs before actually doing a log_init(), they will
be logged in 'stderr'.

Signed-off-by: Amar Tumballi <amar@gluster.com>
Signed-off-by: Vijay Bellur <vijay@dev.gluster.com>

BUG: 2346 (Log message enhancements in GlusterFS - phase 1)
URL: http://bugs.gluster.com/cgi-bin/bugzilla3/show_bug.cgi?id=2346

5 files changed, 235 insertions, 66 deletions

diff --git a/libglusterfs/src/globals.c b/libglusterfs/src/globals.c
index 3121a1f14..9e9870e0b 100644
--- a/libglusterfs/src/globals.c
+++ b/libglusterfs/src/globals.c
@@ -349,6 +349,8 @@ glusterfs_globals_init ()
 
         gf_op_list_init ();
 
+        gf_log_globals_init ();
+
         ret = glusterfs_ctx_init ();
         if (ret)
                 goto out;
diff --git a/libglusterfs/src/logging.c b/libglusterfs/src/logging.c
index ed024840a..4c6bc2ed7 100644
--- a/libglusterfs/src/logging.c
+++ b/libglusterfs/src/logging.c
@@ -48,8 +48,8 @@ static pthread_mutex_t  logfile_mutex;
 static char            *filename = NULL;
 static uint8_t          logrotate = 0;
 static FILE            *logfile = NULL;
-static gf_loglevel_t    loglevel = GF_LOG_MAX;
-static int              gf_log_syslog = 0;
+static gf_loglevel_t    loglevel = GF_LOG_INFO;
+static int              gf_log_syslog = 1;
 
 char                    gf_log_xl_log_set;
 gf_loglevel_t           gf_log_loglevel; /* extern'd */
@@ -115,6 +115,18 @@ gf_log_fini (void)
 }
 
 
+void
+gf_log_globals_init (void)
+{
+        pthread_mutex_init (&logfile_mutex, NULL);
+
+#ifdef GF_LINUX_HOST_OS
+        /* For the 'syslog' output. one can grep 'GlusterFS' in syslog
+           for serious logs */
+        openlog ("GlusterFS", LOG_PID, LOG_DAEMON);
+#endif
+}
+
 int
 gf_log_init (const char *file)
 {
@@ -123,8 +135,6 @@ gf_log_init (const char *file)
                 return -1;
         }
 
-        pthread_mutex_init (&logfile_mutex, NULL);
-
         filename = gf_strdup (file);
         if (!filename) {
                 fprintf (stderr, "gf_log_init: strdup error\n");
@@ -140,12 +150,6 @@ gf_log_init (const char *file)
                 return -1;
         }
 
-#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
-
         gf_log_logfile = logfile;
 
         return 0;
@@ -170,8 +174,6 @@ struct _log_msg {
 };
 
 
-
-
 void
 gf_log_lock (void)
 {
@@ -193,6 +195,123 @@ gf_log_cleanup (void)
 }
 
 int
+_gf_log_nomem (const char *domain, const char *file,
+               const char *function, int line, gf_loglevel_t level,
+               size_t size)
+{
+        const char     *basename        = NULL;
+        struct tm      *tm              = NULL;
+        xlator_t       *this            = NULL;
+        struct timeval  tv              = {0,};
+        int             ret             = 0;
+        gf_loglevel_t   xlator_loglevel = 0;
+        char            msg[8092];
+        char            timestr[256];
+        char            callstr[4096];
+
+        this = THIS;
+
+        xlator_loglevel = this->loglevel;
+        if (xlator_loglevel == 0)
+                xlator_loglevel = loglevel;
+
+        if (level > xlator_loglevel)
+                goto out;
+
+        static char *level_strings[] = {"",  /* NONE */
+                                        "M", /* EMERGENCY */
+                                        "A", /* ALERT */
+                                        "C", /* CRITICAL */
+                                        "E", /* ERROR */
+                                        "W", /* WARNING */
+                                        "N", /* NOTICE */
+                                        "I", /* INFO/NORMAL */
+                                        "D", /* DEBUG */
+                                        "T", /* TRACE */
+                                        ""};
+
+        if (!domain || !file || !function) {
+                fprintf (stderr,
+                         "logging: %s:%s():%d: invalid argument\n",
+                         __FILE__, __PRETTY_FUNCTION__, __LINE__);
+                return -1;
+        }
+
+#if HAVE_BACKTRACE
+        /* Print 'calling function' */
+        do {
+                void *array[5];
+                char **callingfn = NULL;
+                size_t bt_size = 0;
+
+                bt_size = backtrace (array, 5);
+                if (bt_size)
+                        callingfn = backtrace_symbols (&array[2], bt_size-2);
+                if (!callingfn)
+                        break;
+
+                if (bt_size == 5)
+                        snprintf (callstr, 4096, "(-->%s (-->%s (-->%s)))",
+                                  callingfn[2], callingfn[1], callingfn[0]);
+                if (bt_size == 4)
+                        snprintf (callstr, 4096, "(-->%s (-->%s))",
+                                  callingfn[1], callingfn[0]);
+                if (bt_size == 3)
+                        snprintf (callstr, 4096, "(-->%s)", callingfn[0]);
+
+                free (callingfn);
+        } while (0);
+#endif /* HAVE_BACKTRACE */
+
+        ret = gettimeofday (&tv, NULL);
+        if (-1 == ret)
+                goto out;
+
+        tm    = localtime (&tv.tv_sec);
+
+        pthread_mutex_lock (&logfile_mutex);
+        {
+                strftime (timestr, 256, "%Y-%m-%d %H:%M:%S", tm);
+                snprintf (timestr + strlen (timestr), 256 - strlen (timestr),
+                          ".%"GF_PRI_SUSECONDS, tv.tv_usec);
+
+                basename = strrchr (file, '/');
+                if (basename)
+                        basename++;
+                else
+                        basename = file;
+
+                ret = sprintf (msg, "[%s] %s [%s:%d:%s] %s %s: no memory "
+                               "available for size (%"GF_PRI_SIZET")",
+                               timestr, level_strings[level],
+                               basename, line, function, callstr,
+                               domain, size);
+                if (-1 == ret) {
+                        goto unlock;
+                }
+
+                if (logfile) {
+                        fprintf (logfile, "%s\n", msg);
+                        fflush (logfile);
+                } else {
+                        fprintf (stderr, "%s\n", msg);
+                }
+
+#ifdef GF_LINUX_HOST_OS
+                /* We want only serious log in 'syslog', not our debug
+                   and trace logs */
+                if (gf_log_syslog && level && (level <= GF_LOG_ERROR))
+                        syslog ((level-1), "%s\n", msg);
+#endif
+        }
+
+unlock:
+        pthread_mutex_unlock (&logfile_mutex);
+out:
+        return ret;
+ }
+
+int
 _gf_log_callingfn (const char *domain, const char *file, const char *function,
                    int line, gf_loglevel_t level, const char *fmt, ...)
 {
@@ -210,9 +329,6 @@ _gf_log_callingfn (const char *domain, const char *file, const char *function,
         gf_loglevel_t   xlator_loglevel = 0;
         va_list         ap;
 
-        if (!logfile)
-                return -1;
-
         this = THIS;
 
         xlator_loglevel = this->loglevel;
@@ -308,13 +424,17 @@ _gf_log_callingfn (const char *domain, const char *file, const char *function,
                 strcpy (msg, str1);
                 strcpy (msg + len, str2);
 
-                fprintf (logfile, "%s\n", msg);
-                fflush (logfile);
+                if (logfile) {
+                        fprintf (logfile, "%s\n", msg);
+                        fflush (logfile);
+                } else {
+                        fprintf (stderr, "%s\n", msg);
+                }
 
 #ifdef GF_LINUX_HOST_OS
                 /* We want only serious log in 'syslog', not our debug
                    and trace logs */
-                if (gf_log_syslog && level && (level <= GF_LOG_ERROR))
+                if (gf_log_syslog && level && (level <= GF_LOG_CRITICAL))
                         syslog ((level-1), "%s\n", msg);
 #endif
         }
@@ -355,9 +475,6 @@ _gf_log (const char *domain, const char *file, const char *function, int line,
         xlator_t    *this = NULL;
         gf_loglevel_t xlator_loglevel = 0;
 
-        if (!logfile)
-                return -1;
-
         this = THIS;
 
         xlator_loglevel = this->loglevel;
@@ -398,7 +515,9 @@ _gf_log (const char *domain, const char *file, const char *function, int line,
                         goto log;
                 }
 
-                fclose (logfile);
+                if (logfile)
+                        fclose (logfile);
+
                 gf_log_logfile = logfile = new_logfile;
         }
 
@@ -444,13 +563,17 @@ log:
                 strcpy (msg, str1);
                 strcpy (msg + len, str2);
 
-                fprintf (logfile, "%s\n", msg);
-                fflush (logfile);
+                if (logfile) {
+                        fprintf (logfile, "%s\n", msg);
+                        fflush (logfile);
+                } else {
+                        fprintf (stderr, "%s\n", msg);
+                }
 
 #ifdef GF_LINUX_HOST_OS
                 /* We want only serious log in 'syslog', not our debug
                    and trace logs */
-                if (gf_log_syslog && level && (level <= GF_LOG_ERROR))
+                if (gf_log_syslog && level && (level <= GF_LOG_CRITICAL))
                         syslog ((level-1), "%s\n", msg);
 #endif
         }
diff --git a/libglusterfs/src/logging.h b/libglusterfs/src/logging.h
index aa6e00edb..0664b2efa 100644
--- a/libglusterfs/src/logging.h
+++ b/libglusterfs/src/logging.h
@@ -69,8 +69,6 @@ typedef enum {
         GF_LOG_TRACE,      /* full trace of operation */
 } gf_loglevel_t;
 
-#define GF_LOG_MAX GF_LOG_DEBUG
-
 extern gf_loglevel_t gf_log_loglevel;
 extern char gf_log_xl_log_set;
 
@@ -94,27 +92,38 @@ extern char gf_log_xl_log_set;
                                    levl, ##fmt);                        \
         } while (0)
 
+
+/* No malloc or calloc should be called in this function */
+#define gf_log_nomem(dom, levl, size) do {                              \
+                if ((levl > gf_log_loglevel) && !gf_log_xl_log_set)     \
+                        break;                                          \
+                _gf_log_nomem (dom, __FILE__, __FUNCTION__, __LINE__,   \
+                               levl, size);                             \
+        } while (0)
+
+
 /* Log once in GF_UNIVERSAL_ANSWER times */
 #define GF_LOG_OCCASIONALLY(var, args...) if (!(var++%GF_UNIVERSAL_ANSWER)) { \
                 gf_log (args);                                          \
         }
 
 
-void
-gf_log_logrotate (int signum);
+void gf_log_logrotate (int signum);
 
+void gf_log_globals_init (void);
 int gf_log_init (const char *filename);
 void gf_log_cleanup (void);
 
-int
-_gf_log (const char *domain, const char *file, const char *function,
-         int32_t line, gf_loglevel_t level, const char *fmt, ...);
-int
-_gf_log_callingfn (const char *domain, const char *file, const char *function,
-                   int32_t line, gf_loglevel_t level, const char *fmt, ...);
+int _gf_log (const char *domain, const char *file, const char *function,
+             int32_t line, gf_loglevel_t level, const char *fmt, ...);
+int _gf_log_callingfn (const char *domain, const char *file, const char *function,
+                       int32_t line, gf_loglevel_t level, const char *fmt, ...);
+
+int _gf_log_nomem (const char *domain, const char *file,
+                   const char *function, int line, gf_loglevel_t level,
+                   size_t size);
 
-int
-gf_log_from_client (const char *msg, char *identifier);
+int gf_log_from_client (const char *msg, char *identifier);
 
 void gf_log_lock (void);
 void gf_log_unlock (void);
@@ -135,9 +144,7 @@ void gf_log_set_xl_loglevel (void *xl, gf_loglevel_t level);
 #define GF_ERROR(xl, format, args...)                           \
         gf_log ((xl)->name, GF_LOG_ERROR, format, ##args)
 
-int
-gf_cmd_log (const char *domain, const char *fmt, ...);
+int gf_cmd_log (const char *domain, const char *fmt, ...);
 
-int
-gf_cmd_log_init (const char *filename);
+int gf_cmd_log_init (const char *filename);
 #endif /* __LOGGING_H__ */
diff --git a/libglusterfs/src/mem-pool.c b/libglusterfs/src/mem-pool.c
index 9acebad41..0d555020b 100644
--- a/libglusterfs/src/mem-pool.c
+++ b/libglusterfs/src/mem-pool.c
@@ -141,9 +141,10 @@ __gf_calloc (size_t nmemb, size_t size, uint32_t type)
 
         ptr = calloc (1, tot_size);
 
-        if (!ptr)
+        if (!ptr) {
+                gf_log_nomem ("", GF_LOG_ALERT, tot_size);
                 return NULL;
-
+        }
         gf_mem_set_acct_info (xl, &ptr, req_size, type);
 
         return (void *)ptr;
@@ -164,9 +165,10 @@ __gf_malloc (size_t size, uint32_t type)
         tot_size = size + GF_MEM_HEADER_SIZE + GF_MEM_TRAILER_SIZE;
 
         ptr = malloc (tot_size);
-        if (!ptr)
+        if (!ptr) {
+                gf_log_nomem ("", GF_LOG_ALERT, tot_size);
                 return NULL;
-
+        }
         gf_mem_set_acct_info (xl, &ptr, size, type);
 
         return (void *)ptr;
@@ -181,7 +183,7 @@ __gf_realloc (void *ptr, size_t size)
         uint32_t        type = 0;
 
         if (!gf_mem_acct_enable)
-                return realloc (ptr, size);
+                return REALLOC (ptr, size);
 
         tot_size = size + GF_MEM_HEADER_SIZE + GF_MEM_TRAILER_SIZE;
 
@@ -196,8 +198,10 @@ __gf_realloc (void *ptr, size_t size)
         type = *(uint32_t *)orig_ptr;
 
         ptr = realloc (orig_ptr, tot_size);
-        if (!ptr)
+        if (!ptr) {
+                gf_log_nomem ("", GF_LOG_ALERT, tot_size);
                 return NULL;
+        }
 
         gf_mem_set_acct_info (xl, (char **)&ptr, size, type);
 
@@ -221,12 +225,7 @@ gf_vasprintf (char **string_ptr, const char *format, va_list arg)
         size++;
         str = GF_MALLOC (size, gf_common_mt_asprintf);
         if (str == NULL) {
-                /*
-                 * Strictly speaking, GNU asprintf doesn't do this,
-                 * but the caller isn't checking the return value.
-                 */
-                gf_log ("libglusterfs", GF_LOG_CRITICAL,
-                        "failed to allocate memory");
+                /* log is done in GF_MALLOC itself */
                 return -1;
         }
         rv = vsnprintf (str, size, format, arg_save);
diff --git a/libglusterfs/src/mem-pool.h b/libglusterfs/src/mem-pool.h
index 0cda62fb8..85ceeb87e 100644
--- a/libglusterfs/src/mem-pool.h
+++ b/libglusterfs/src/mem-pool.h
@@ -22,6 +22,7 @@
 
 #include "list.h"
 #include "locking.h"
+#include "logging.h"
 #include "mem-types.h"
 #include <stdlib.h>
 #include <inttypes.h>
@@ -29,15 +30,6 @@
 #include <stdarg.h>
 
 
-#define MALLOC(size) malloc(size)
-#define CALLOC(cnt,size) calloc(cnt,size)
-
-#define FREE(ptr)                               \
-        if (ptr != NULL) {                      \
-                free ((void *)ptr);             \
-                ptr = (void *)0xeeeeeeee;       \
-        }
-
 struct mem_acct {
         uint32_t            num_types;
         struct mem_acct_rec     *rec;
@@ -67,16 +59,62 @@ gf_vasprintf (char **string_ptr, const char *format, va_list arg);
 int
 gf_asprintf (char **string_ptr, const char *format, ...);
 
+void
+__gf_free (void *ptr);
+
+
+static inline
+void* __gf_default_malloc (size_t size)
+{
+        void *ptr = NULL;
+
+        ptr = malloc (size);
+        if (!ptr)
+                gf_log_nomem ("", GF_LOG_ALERT, size);
+
+        return ptr;
+}
+
+static inline
+void* __gf_default_calloc (int cnt, size_t size)
+{
+        void *ptr = NULL;
+
+        ptr = calloc (cnt, size);
+        if (!ptr)
+                gf_log_nomem ("", GF_LOG_ALERT, (cnt * size));
+
+        return ptr;
+}
+
+static inline
+void* __gf_default_realloc (void *oldptr, size_t size)
+{
+        void *ptr = NULL;
+
+        ptr = realloc (oldptr, size);
+        if (!ptr)
+                gf_log_nomem ("", GF_LOG_ALERT, size);
+
+        return ptr;
+}
+
+#define MALLOC(size)       __gf_default_malloc(size)
+#define CALLOC(cnt,size)   __gf_default_calloc(cnt,size)
+#define REALLOC(ptr,size)  __gf_default_realloc(ptr,size)
+
+#define FREE(ptr)                               \
+        if (ptr != NULL) {                      \
+                free ((void *)ptr);             \
+                ptr = (void *)0xeeeeeeee;       \
+        }
+
 #define GF_CALLOC(nmemb, size, type) __gf_calloc (nmemb, size, type)
 
 #define GF_MALLOC(size, type)  __gf_malloc (size, type)
 
 #define GF_REALLOC(ptr, size)  __gf_realloc (ptr, size)
 
-void
-__gf_free (void *ptr);
-
-
 #define GF_FREE(free_ptr) __gf_free (free_ptr);
 
 static inline