nsr : Fix "special" recon logging functions.

Combining two patches together.
http://review.gluster.org/#/c/6538/4, author : Jeff Darcy
and
http://review.gluster.org/#/c/6748/2, author : Anuradha Talur.

(1) Put logs into /var/log instead of /tmp.
(2) Added debug-level check.
(3) Added function/line information.
(4) Fixed many instances of missing symbol GF_LOG_ERR.
Removing spurious newlines will have to wait until a subsequent patch.
Keeping this one up to date is tedious enough.

Changed the logging directory of reconciliation logs to
 /var/log/nsr-logs.

Change-Id: I8ffd901537d77329eddbd17b380c1611607927d6
Credits: Jeff Darcy <jdarcy@redhat.com>
Signed-off-by: Anuradha <atalur@redhat.com>

4 files changed, 208 insertions, 106 deletions

diff --git a/xlators/cluster/nsr-recon/src/recon_driver.c b/xlators/cluster/nsr-recon/src/recon_driver.c
index 0d5560957..084b7f5ce 100644
--- a/xlators/cluster/nsr-recon/src/recon_driver.c
+++ b/xlators/cluster/nsr-recon/src/recon_driver.c
@@ -74,6 +74,94 @@
  * APIs.
  */
 
+#if defined(NSR_DEBUG)
+
+/* This lets us change on the fly even if NSR_DEBUG is defined. */
+int nsr_debug_level = GF_LOG_TRACE;
+
+FILE *
+recon_create_log (char *member, char *module)
+{
+        char    *dpath  = NULL;
+        char    *p;
+        char    *fpath  = NULL;
+        FILE    *fp     = NULL;
+
+        (void)mkdir(NSR_LOG_DIR,0777);
+        (void)asprintf(&dpath,NSR_LOG_DIR"/%s",member);
+        if (dpath) {
+                for (p = dpath + strlen(NSR_LOG_DIR) + 1; *p; ++p) {
+                        if (*p == '/') {
+                                *p = '-';
+                        }
+                }
+                (void)mkdir(dpath,0777);
+                (void)asprintf(&fpath,"%s/%s",dpath,module);
+                if (fpath) {
+                        fp = fopen(fpath,"w");
+                        free(fpath);
+                }
+                free(dpath);
+        }
+
+        return fp;
+}
+
+void
+_nsr_driver_log (const char *func, int line, char *member, char *fmt, ...)
+{
+        static FILE     *fp     = NULL;
+        va_list         ap;
+        char            *buf    = NULL;
+        int             retval;
+
+        if (!fp) {
+                fp = recon_create_log(member,"nsr-driver-log");
+                if (!fp) {
+                        return;
+                }
+        }
+
+        va_start(ap,fmt);
+        retval = vasprintf(&buf,fmt,ap);
+        if (buf) {
+                fprintf(fp,"[%s:%d] %.*s\n",func,line,retval,buf);
+                free(buf);
+        }
+        va_end(ap);
+}
+
+void
+_nsr_worker_log (const char *func, int line, char *member,
+                 char *type, uint32_t index, char *fmt, ...)
+{
+        static FILE     *fp     = NULL;
+        va_list         ap;
+        char            *buf    = NULL;
+        int             retval;
+
+        if (!fp) {
+                char *name;
+                if (asprintf(&name,"%s-%u",type,index) < 1) {
+                        return;
+                }
+                fp = recon_create_log(member,"recon-main-log");
+                if (!fp) {
+                        return;
+                }
+        }
+
+        va_start(ap,fmt);
+        retval = vasprintf(&buf,fmt,ap);
+        if (buf) {
+                fprintf(fp,"[%s:%d] %.*s\n",func,line,retval,buf);
+                free(buf);
+        }
+        va_end(ap);
+}
+
+#endif
+
 /*
  * This function gets the size of all the extended attributes for a file.
  * This is used so that caller knows how much to allocate for key-value storage.
@@ -309,6 +397,15 @@ nsr_recon_start_work(nsr_per_node_worker_t *ctx,
         int32_t ret = 0;
         glfs_fd_t *aux_fd = NULL; // fd of auxilary log
         char lf[256];
+        nsr_recon_private_t *priv = NULL;
+        char *my_name = NULL;
+        char *morph_name = NULL, *ptr = NULL;
+
+        priv = this->private;
+        my_name = GF_CALLOC (1,
+                             strlen (priv->replica_group_members[0]) + 1,
+                             gf_mt_recon_private_t);
+        strcpy (my_name, priv->replica_group_members[0]);
 
         nsr_worker_log(this->name, GF_LOG_INFO,
                        "starting work with volfile %s\n",
@@ -336,10 +433,26 @@ nsr_recon_start_work(nsr_per_node_worker_t *ctx,
                 return -1;
         }
 
+        morph_name = GF_CALLOC (1, strlen (my_name) + 1, gf_mt_recon_private_t);
+        strcpy (morph_name, my_name);
+
+        ptr = strchr (morph_name, '/');
+        while (ptr)
+        {
+                *ptr = '-';
+                 ptr = strchr (morph_name, '/');
+        }
         // TBD - convert this to right /usr/local/var/log based log files.
-        sprintf(lf,"/tmp/logs/%s-%s",(control == _gf_true)?"con":"data",ctx->id);
-        glfs_set_logging (fs, lf, 7);
-        glusterfs_this_set(this);
+
+        sprintf(lf, NSR_LOG_DIR"/%s/%s-%"PRIu32, morph_name,
+                (control == _gf_true)?"glfs-con":"glfs-data", ctx->index);
+        ret =  glfs_set_logging (fs, lf, 7);
+        if (ret) {
+                glusterfs_this_set(this);
+                gf_log (this->name, GF_LOG_ERROR, "glfs logging set failed (%s)",
+                        strerror (errno));
+                return -1;
+        }
 
         ret = glfs_init (fs);
         if (ret != 0) {
@@ -1338,7 +1451,7 @@ apply_record(nsr_per_node_worker_t *ctx,
                 }
                 if (glfs_ftruncate_with_xdata(fd, ri->rec.offset, dict) == -1) {
                         GF_ASSERT(0);
-                        nsr_worker_log(this->name, GF_LOG_ERROR
+                        nsr_worker_log(this->name, GF_LOG_ERROR,
                                        "trunctae for file %s failed @offset %d\n",
                                        ri->rec.gfid,ri->rec.offset );
                         return;
@@ -2641,9 +2754,6 @@ i_am_resolutor:
 
                 if (state == joiner) {
 
-                        int32_t chosen = -1;
-                        int32_t last_term = -1, last_ops = -1;
-
                         nsr_driver_log (this->name, GF_LOG_INFO, "getting last term info from all members of this group\n");
                         // Get last term info from all members for this group
                         // which will be the leader(this node) and the node that wants to join.
diff --git a/xlators/cluster/nsr-recon/src/recon_driver.h b/xlators/cluster/nsr-recon/src/recon_driver.h
index a9a9a9182..47852f225 100644
--- a/xlators/cluster/nsr-recon/src/recon_driver.h
+++ b/xlators/cluster/nsr-recon/src/recon_driver.h
@@ -232,9 +232,6 @@ typedef struct _nsr_per_node_worker_s {
        pthread_mutex_t mutex; //mutex to guard the state
        pthread_cond_t cv; //condition variable for signaling the worker thread
        gf_boolean_t is_control;
-#ifdef  NSR_DEBUG
-       uint32_t worker_log_fd;
-#endif
 } nsr_per_node_worker_t;
 
 typedef struct _nsr_replica_worker_s {
@@ -258,9 +255,6 @@ typedef struct _nsr_recon_driver_ctxt {
        uint32_t txn_id;
        uint32_t current_term;
        jmp_buf *env;
-#ifdef  NSR_DEBUG
-       uint32_t driver_log_fd;
-#endif
        nsr_mode_t mode; // default set to seq
 } nsr_recon_driver_ctx_t;
 
@@ -275,63 +269,46 @@ nsr_recon_driver_set_role(nsr_recon_driver_ctx_t *ctx, nsr_recon_role_t *rr, uin
 #define atomic_fetch_and       __sync_fetch_and_and
 #define atomic_fetch_or        __sync_fetch_and_or
 
-/*
- * REVIEW
- * Ideally, use gf_log like everyone else.  Failing that, at least put the logs
- * with all the others in /var/log instead of /tmp.
- * NB two instances, for nsr_driver_log and nsr_worker_log
- */
-#ifdef NSR_DEBUG
-#define nsr_driver_log(dom, levl, fmt...) \
-        { \
-                char c[255]; \
-                if (!ctx->driver_log_fd) { \
-                        char str[255], b[255]; \
-                        char *ptr; \
-                        nsr_recon_private_t *priv = ctx->this->private; \
-                        strcpy(b, priv->replica_group_members[0]); \
-                        ptr = strchr (b, '/'); \
-                        while (ptr) { \
-                                *ptr = '-'; \
-                                ptr = strchr (b, '/'); \
-                        } \
-                        sprintf(str,"/tmp/nsr-logs/%s",b); \
-                        mkdir("/tmp/nsr-logs/", 0777);  \
-                        mkdir(str, 0777);  \
-                        sprintf(str,"/tmp/nsr-logs/%s/nsr-driver-log",b); \
-                        ctx->driver_log_fd = open(str, O_RDWR|O_CREAT|O_TRUNC); \
-                } \
-                sprintf(c, fmt); \
-                write(ctx->driver_log_fd, c, strlen(c));  \
-        }
-#else
-#define nsr_driver_log(dom, levl, fmt...) gf_log(dom, levl, fmt)
-#endif
+#if defined(NSR_DEBUG)
+
+#define NSR_LOG_DIR "/var/log/nsr-logs"
+
+extern int      nsr_debug_level;
+extern FILE     *recon_create_log (char *member, char *module);
+
+extern void
+_nsr_driver_log (const char *func, int line, char *member, char *fmt, ...);
+
+#define nsr_driver_log(dom, levl, fmt...) do {                          \
+        FMT_WARN (fmt);                                                 \
+        if (levl <= nsr_debug_level) {                                  \
+                nsr_recon_private_t     *priv   = ctx->this->private;   \
+                _nsr_driver_log (__FUNCTION__, __LINE__,                \
+                                   priv->replica_group_members[0],      \
+                                   ##fmt);                              \
+        }                                                               \
+} while (0)
+
+extern void
+_nsr_worker_log (const char *func, int line, char *member,
+                 char *type, uint32_t index, char *fmt, ...);
+
+#define nsr_worker_log(dom, levl, fmt...) do {                          \
+        FMT_WARN (fmt);                                                 \
+        if (levl <= nsr_debug_level) {                                  \
+                nsr_recon_private_t *priv;                              \
+                priv = ctx->driver_ctx->this->private;                  \
+                _nsr_worker_log (__FUNCTION__, __LINE__,                \
+                                 priv->replica_group_members[0],        \
+                                 ctx->is_control ? "recon-con" :        \
+                                 "recon-data",                          \
+                                 ctx->index,                            \
+                                 ##fmt);                                \
+        }                                                               \
+} while (0)
 
-#ifdef NSR_DEBUG
-#define nsr_worker_log(dom, levl, fmt...) \
-        { \
-                char c[255]; \
-                if (!ctx->worker_log_fd) { \
-                        char str[255], b[255]; \
-                        char *ptr; \
-                        nsr_recon_private_t *priv = ctx->driver_ctx->this->private; \
-                        strcpy(b, priv->replica_group_members[0]); \
-                        ptr = strchr (b, '/'); \
-                        while (ptr) { \
-                                *ptr = '-'; \
-                                ptr = strchr (b, '/'); \
-                        } \
-                        sprintf(str,"/tmp/nsr-logs/%s",b); \
-                        mkdir("/tmp/nsr-logs/", 0777);  \
-                        mkdir(str, 0777);  \
-                        sprintf(str,"/tmp/nsr-logs/%s/%s-%d",b,ctx->is_control?"con":"data",ctx->index); \
-                        ctx->worker_log_fd = open(str, O_RDWR|O_CREAT|O_TRUNC); \
-                } \
-                sprintf(c, fmt); \
-                write(ctx->worker_log_fd, c, strlen(c));  \
-        }
 #else
+#define nsr_driver_log(dom, levl, fmt...) gf_log(dom, levl, fmt)
 #define nsr_worker_log(dom, levl, fmt...) gf_log(dom, levl, fmt)
 #endif
 
diff --git a/xlators/cluster/nsr-recon/src/recon_xlator.c b/xlators/cluster/nsr-recon/src/recon_xlator.c
index 5f63f6671..b527633d8 100644
--- a/xlators/cluster/nsr-recon/src/recon_xlator.c
+++ b/xlators/cluster/nsr-recon/src/recon_xlator.c
@@ -39,6 +39,34 @@ typedef struct _nsr_txn_id_s {
         struct list_head list;
 } nsr_txn_id_t;
 
+#if defined(NSR_DEBUG)
+
+void
+_recon_main_log (const char *func, int line, char *member, char *fmt, ...)
+{
+        static FILE     *fp     = NULL;
+        va_list         ap;
+        char            *buf    = NULL;
+        int             retval;
+
+        if (!fp) {
+                fp = recon_create_log(member,"recon-main-log");
+                if (!fp) {
+                        return;
+                }
+        }
+
+        va_start(ap,fmt);
+        retval = vasprintf(&buf,fmt,ap);
+        if (buf) {
+                fprintf(fp,"[%s:%d] %.*s\n",func,line,retval,buf);
+                free(buf);
+        }
+        va_end(ap);
+}
+
+#endif
+
 // Given fd, get back the NSR based fd context.
 static int32_t this_fd_ctx_get(fd_t *fd, xlator_t *this, nsr_recon_fd_t **rfd)
 {
@@ -240,7 +268,7 @@ void nsr_recon_libchangelog_get_records(xlator_t *this, char *bp, int32_t term,
                                 }
                                 op_str[i] = '\0';
                                 opcode = strtoul(op_str, NULL, 10);
-                                recon_main_log (this->name, GF_LOG_ERR,
+                                recon_main_log (this->name, GF_LOG_ERROR,
                                                 "libchangelog_get_records: got opcode %d @index %d\n", opcode, index);
                                 if ((opcode == GF_FOP_RENAME)) {
                                         type = fop_gfid_pgfid_oldloc_newloc;
@@ -265,7 +293,8 @@ void nsr_recon_libchangelog_get_records(xlator_t *this, char *bp, int32_t term,
                                 } else if (opcode == GF_FOP_WRITE) {
                                         type = fop_gfid_offset_len;
                                 } else {
-                                        recon_main_log (this->name, GF_LOG_ERR,
+                                        recon_main_log (this->name,
+                                                        GF_LOG_ERROR,
                                                         "libchangelog_get_records:got no proper opcode %d @index %d\n",
                                                         opcode, index);
                                         //GF_ASSERT(0);
@@ -278,7 +307,7 @@ void nsr_recon_libchangelog_get_records(xlator_t *this, char *bp, int32_t term,
                                 }
                                 // TBD - handle psuedo holes once that logic is in.
                                 rec->type = NSR_LOG_FILL;
-                                recon_main_log (this->name, GF_LOG_ERR,
+                                recon_main_log (this->name, GF_LOG_ERROR,
                                                "libchangelog_get_records:got type %d at index %d \n",
                                                 rec->type, index);
                                 rec->op = opcode;
@@ -317,7 +346,8 @@ void nsr_recon_libchangelog_get_records(xlator_t *this, char *bp, int32_t term,
                                         // get over the 0
                                         start++;
                                         rec->offset = strtoul(offset_str, NULL, 10);
-                                        recon_main_log (this->name, GF_LOG_ERR,
+                                        recon_main_log (this->name,
+                                                        GF_LOG_ERROR,
                                                         "libchangelog_get_records:got offset %d @index %d \n", rec->offset, index);
 
                                 }
@@ -332,7 +362,8 @@ void nsr_recon_libchangelog_get_records(xlator_t *this, char *bp, int32_t term,
                                         // get over the 0
                                         start++;
                                         rec->len = strtoul(len_str, NULL, 10);
-                                        recon_main_log (this->name, GF_LOG_ERR,
+                                        recon_main_log (this->name,
+                                                        GF_LOG_ERROR,
                                                         "libchangelog_get_records:got length %d @index %d \n", rec->len, index);
                                 }
                                 i = 0;
@@ -354,7 +385,8 @@ void nsr_recon_libchangelog_get_records(xlator_t *this, char *bp, int32_t term,
                                         rec->entry[i] = '\0';
                                         // get over the 0
                                         start++;
-                                        recon_main_log (this->name, GF_LOG_ERR,
+                                        recon_main_log (this->name,
+                                                        GF_LOG_ERROR,
                                                         "libchangelog_get_records:got entry %s @index %d \n", rec->entry, index);
 
                                 }
@@ -572,7 +604,6 @@ nsr_recon_readv (call_frame_t *frame, xlator_t *this,
                  fd_t *fd, size_t size, off_t offset, uint32_t flags, dict_t *xdata)
 {
         nsr_recon_fd_t *rfd = NULL;
-        int32_t op_ret = 0;
         int32_t op_errno = 0;
         // copied stuff from quick-read.c and posix.c
         struct iobuf *iobuf = NULL;
diff --git a/xlators/cluster/nsr-recon/src/recon_xlator.h b/xlators/cluster/nsr-recon/src/recon_xlator.h
index 168db518b..a3c91a741 100644
--- a/xlators/cluster/nsr-recon/src/recon_xlator.h
+++ b/xlators/cluster/nsr-recon/src/recon_xlator.h
@@ -40,41 +40,25 @@ typedef struct _nsr_recon_private_s {
         uint32_t txn_id;
         char *changelog_base_path;
         char *base_dir;
-#ifdef  NSR_DEBUG
-        uint32_t recon_main_log_fd;
-#endif
 } nsr_recon_private_t;
 
 #define atomic_cmpxchg         __sync_val_compare_and_swap
 
-/*
- * REVIEW
- * Ideally, use gf_log like everyone else.  Failing that, at least put the logs
- * with all the others in /var/log instead of /tmp.
- */
-#ifdef NSR_DEBUG
-#define recon_main_log(dom, levl, fmt...) \
-        { \
-                char c[255]; \
-                nsr_recon_private_t   *priv   = this->private;  \
-                if (!priv->recon_main_log_fd) { \
-                        char str[255], b[255]; \
-                        char *ptr; \
-                        strcpy(b, priv->replica_group_members[0]); \
-                        ptr = strchr (b, '/'); \
-                        while (ptr) { \
-                                *ptr = '-'; \
-                                ptr = strchr (b, '/'); \
-                        } \
-                        sprintf(str,"/tmp/nsr-logs/%s",b); \
-                        mkdir("/tmp/nsr-logs/", 0777);  \
-                        mkdir(str, 0777);  \
-                        sprintf(str,"/tmp/nsr-logs/%s/recon-main-log",b); \
-                        priv->recon_main_log_fd = open(str, O_RDWR|O_CREAT|O_TRUNC); \
-                } \
-                sprintf(c, fmt); \
-                write(priv->recon_main_log_fd, c, strlen(c));  \
-        }
+#if defined(NSR_DEBUG)
+
+extern void
+_recon_main_log (const char *func, int line, char *member, char *fmt, ...);
+
+#define recon_main_log(dom, levl, fmt...) do {                          \
+        FMT_WARN (fmt);                                                 \
+        if (levl <= nsr_debug_level) {                                  \
+                nsr_recon_private_t     *priv   = this->private;        \
+                _recon_main_log (__FUNCTION__, __LINE__,                \
+                                 priv->replica_group_members[0],        \
+                                 ##fmt);                                \
+        }                                                               \
+} while (0)
+
 #else
 #define recon_main_log(dom, levl, fmt...) gf_log(dom, levl, fmt)
 #endif