cluster/afr: log enhancements - part 1

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

BUG: 2346 ()
URL: http://bugs.gluster.com/cgi-bin/bugzilla3/show_bug.cgi?id=2346

1 files changed, 166 insertions, 172 deletions

diff --git a/xlators/cluster/afr/src/afr-dir-read.c b/xlators/cluster/afr/src/afr-dir-read.c
index 59bd7872e9f..b2a001a198a 100644
--- a/xlators/cluster/afr/src/afr-dir-read.c
+++ b/xlators/cluster/afr/src/afr-dir-read.c
@@ -70,10 +70,9 @@ gf_boolean_t
 __checksums_differ (uint32_t *checksum, int child_count,
                     unsigned char *child_up)
 {
-        int ret = _gf_false;
-        int i = 0;
-
-        uint32_t cksum;
+        int      ret   = _gf_false;
+        int      i     = 0;
+        uint32_t cksum = 0;
 
         cksum = checksum[0];
 
@@ -98,20 +97,16 @@ afr_examine_dir_readdir_cbk (call_frame_t *frame, void *cookie,
                              xlator_t *this, int32_t op_ret, int32_t op_errno,
                              gf_dirent_t *entries)
 {
-        afr_private_t *    priv  = NULL;
-        afr_local_t *      local = NULL;
-        afr_self_heal_t *  sh    = NULL;
-
-        gf_dirent_t * entry = NULL;
-        gf_dirent_t * tmp   = NULL;
-
-        int child_index = 0;
-
-        uint32_t entry_cksum;
-
-        int   call_count    = 0;
-        off_t last_offset = 0;
-        char  sh_type_str[256] = {0,};
+        afr_private_t *   priv        = NULL;
+        afr_local_t *     local       = NULL;
+        afr_self_heal_t * sh          = NULL;
+        gf_dirent_t *     entry       = NULL;
+        gf_dirent_t *     tmp         = NULL;
+        int               child_index = 0;
+        uint32_t          entry_cksum = 0;
+        int               call_count  = 0;
+        off_t             last_offset = 0;
+        char              sh_type_str[256] = {0,};
 
         priv  = this->private;
         local = frame->local;
@@ -120,13 +115,20 @@ afr_examine_dir_readdir_cbk (call_frame_t *frame, void *cookie,
         child_index = (long) cookie;
 
         if (op_ret == -1) {
+                gf_log (this->name, GF_LOG_INFO,
+                        "%s: failed to do opendir on %s",
+                        local->loc.path, priv->children[child_index]->name);
                 local->op_ret = -1;
                 local->op_ret = op_errno;
                 goto out;
         }
 
-        if (op_ret == 0)
+        if (op_ret == 0) {
+                gf_log (this->name, GF_LOG_DEBUG,
+                        "%s: no entries found in %s",
+                        local->loc.path, priv->children[child_index]->name);
                 goto out;
+        }
 
         list_for_each_entry_safe (entry, tmp, &entries->list, list) {
                 entry_cksum = gf_rsync_weak_checksum (entry->d_name,
@@ -146,37 +148,37 @@ afr_examine_dir_readdir_cbk (call_frame_t *frame, void *cookie,
                            priv->children[child_index]->fops->readdir,
                            local->fd, 131072, last_offset);
 
+        return 0;
+
 out:
-        if ((op_ret == 0) || (op_ret == -1)) {
-                call_count = afr_frame_return (frame);
-
-                if (call_count == 0) {
-                        if (__checksums_differ (local->cont.opendir.checksum,
-                                                priv->child_count,
-                                                local->child_up)) {
-
-                                sh->need_entry_self_heal  = _gf_true;
-                                sh->forced_merge          = _gf_true;
-                                sh->type                  = local->fd->inode->ia_type;
-                                sh->background            = _gf_false;
-                                sh->unwind                = afr_examine_dir_sh_unwind;
-
-                                afr_self_heal_type_str_get(&local->self_heal,
-                                                           sh_type_str,
-                                                           sizeof(sh_type_str));
-                                gf_log (this->name, GF_LOG_NORMAL,
-                                        "%s self-heal triggered. path: %s, "
-                                        "reason: checksums of directory differ,"
-                                        " forced merge option set",
-                                        sh_type_str, local->loc.path);
-
-                                afr_self_heal (frame, this);
-                        } else {
-                                afr_set_opendir_done (this, local->fd->inode);
-
-                                AFR_STACK_UNWIND (opendir, frame, local->op_ret,
-                                                  local->op_errno, local->fd);
-                        }
+        call_count = afr_frame_return (frame);
+
+        if (call_count == 0) {
+                if (__checksums_differ (local->cont.opendir.checksum,
+                                        priv->child_count,
+                                        local->child_up)) {
+
+                        sh->need_entry_self_heal  = _gf_true;
+                        sh->forced_merge          = _gf_true;
+                        sh->type                  = local->fd->inode->ia_type;
+                        sh->background            = _gf_false;
+                        sh->unwind                = afr_examine_dir_sh_unwind;
+
+                        afr_self_heal_type_str_get(&local->self_heal,
+                                                   sh_type_str,
+                                                   sizeof(sh_type_str));
+                        gf_log (this->name, GF_LOG_INFO,
+                                "%s self-heal triggered. path: %s, "
+                                "reason: checksums of directory differ,"
+                                " forced merge option set",
+                                sh_type_str, local->loc.path);
+
+                        afr_self_heal (frame, this);
+                } else {
+                        afr_set_opendir_done (this, local->fd->inode);
+
+                        AFR_STACK_UNWIND (opendir, frame, local->op_ret,
+                                          local->op_errno, local->fd);
                 }
         }
 
@@ -187,11 +189,10 @@ out:
 int
 afr_examine_dir (call_frame_t *frame, xlator_t *this)
 {
-        afr_private_t * priv  = NULL;
-        afr_local_t *   local = NULL;
-
-        int i;
-        int call_count = 0;
+        afr_private_t * priv       = NULL;
+        afr_local_t *   local      = NULL;
+        int             i          = 0;
+        int             call_count = 0;
 
         local = frame->local;
         priv  = this->private;
@@ -229,9 +230,8 @@ afr_opendir_cbk (call_frame_t *frame, void *cookie,
         afr_private_t *priv              = NULL;
         afr_local_t   *local             = NULL;
         int32_t        up_children_count = 0;
-        int           ret                = -1;
-
-        int call_count = -1;
+        int            ret               = -1;
+        int            call_count        = -1;
 
         priv  = this->private;
         local = frame->local;
@@ -251,48 +251,50 @@ afr_opendir_cbk (call_frame_t *frame, void *cookie,
         call_count = afr_frame_return (frame);
 
         if (call_count == 0) {
-                if (local->op_ret == 0) {
-
-                        ret = afr_fd_ctx_set (this, local->fd);
+                if (local->op_ret != 0)
+                        goto out;
 
-                        if (ret) {
-                                local->op_ret = -1;
-                                local->op_errno = -1;
-                                gf_log (this->name, GF_LOG_ERROR, " failed to "
-                                        "set fd ctx for fd %p", local->fd);
-                                goto out;
-                        }
-                        if (!afr_is_opendir_done (this, local->fd->inode) &&
-                            up_children_count > 1) {
-
-                                /*
-                                 * This is the first opendir on this inode. We need
-                                 * to check if the directory's entries are the same
-                                 * on all subvolumes. This is needed in addition
-                                 * to regular entry self-heal because the readdir
-                                 * call is sent only to the first subvolume, and
-                                 * thus files that exist only there will never be healed
-                                 * otherwise (assuming changelog shows no anamolies).
-                                 */
+                ret = afr_fd_ctx_set (this, local->fd);
+                if (ret) {
+                        local->op_ret = -1;
+                        local->op_errno = -1;
+                        gf_log (this->name, GF_LOG_ERROR,
+                                "failed to set fd ctx for fd %p",
+                                local->fd);
+                        goto out;
+                }
+                if (!afr_is_opendir_done (this, local->fd->inode) &&
+                    up_children_count > 1) {
+
+                        /*
+                         * This is the first opendir on this inode. We need
+                         * to check if the directory's entries are the same
+                         * on all subvolumes. This is needed in addition
+                         * to regular entry self-heal because the readdir
+                         * call is sent only to the first subvolume, and
+                         * thus files that exist only there will never be healed
+                         * otherwise (assuming changelog shows no anamolies).
+                         */
 
-                                gf_log (this->name, GF_LOG_TRACE,
-                                        "reading contents of directory %s looking for mismatch",
-                                        local->loc.path);
+                        gf_log (this->name, GF_LOG_TRACE,
+                                "reading contents of directory %s looking for mismatch",
+                                local->loc.path);
 
-                                afr_examine_dir (frame, this);
+                        afr_examine_dir (frame, this);
 
-                        } else {
-                                AFR_STACK_UNWIND (opendir, frame, local->op_ret,
-                                                  local->op_errno, local->fd);
-                        }
                 } else {
-                out:
-                        AFR_STACK_UNWIND (opendir, frame, local->op_ret,
-                                          local->op_errno, local->fd);
+                        /* do the unwind */
+                        goto out;
                 }
         }
 
         return 0;
+
+out:
+        AFR_STACK_UNWIND (opendir, frame, local->op_ret,
+                          local->op_errno, local->fd);
+
+        return 0;
 }
 
 
@@ -302,15 +304,12 @@ afr_opendir (call_frame_t *frame, xlator_t *this,
 {
         afr_private_t * priv        = NULL;
         afr_local_t   * local       = NULL;
-
         int             child_count = 0;
         int             i           = 0;
-
-        int ret = -1;
-        int call_count = -1;
-
-        int32_t         op_ret   = -1;
-        int32_t         op_errno = 0;
+        int             ret         = -1;
+        int             call_count  = -1;
+        int32_t         op_ret      = -1;
+        int32_t         op_errno    = 0;
 
         VALIDATE_OR_GOTO (frame, out);
         VALIDATE_OR_GOTO (this, out);
@@ -376,8 +375,8 @@ struct entry_name {
 static gf_boolean_t
 remembered_name (const char *name, struct list_head *entries)
 {
-        struct entry_name *e;
-        gf_boolean_t ret = _gf_false;
+        struct entry_name *e   = NULL;
+        gf_boolean_t       ret = _gf_false;
 
         list_for_each_entry (e, entries, list) {
                 if (!strcmp (name, e->name)) {
@@ -394,17 +393,15 @@ out:
 static void
 afr_remember_entries (gf_dirent_t *entries, fd_t *fd)
 {
-        struct entry_name *n       = NULL;
-        gf_dirent_t *      entry   = NULL;
-
-        int ret = 0;
-
-        uint64_t      ctx;
-        afr_fd_ctx_t *fd_ctx;
+        struct entry_name *n      = NULL;
+        gf_dirent_t       *entry  = NULL;
+        int                ret    = 0;
+        uint64_t           ctx    = 0;
+        afr_fd_ctx_t      *fd_ctx = NULL;
 
         ret = fd_ctx_get (fd, THIS, &ctx);
         if (ret < 0) {
-                gf_log (THIS->name, GF_LOG_DEBUG,
+                gf_log (THIS->name, GF_LOG_INFO,
                         "could not get fd ctx for fd=%p", fd);
                 return;
         }
@@ -424,17 +421,16 @@ afr_remember_entries (gf_dirent_t *entries, fd_t *fd)
 static off_t
 afr_filter_entries (gf_dirent_t *entries, fd_t *fd)
 {
-        gf_dirent_t *entry, *tmp;
-        int ret = 0;
-
-        uint64_t      ctx;
-        afr_fd_ctx_t *fd_ctx;
-
-        off_t offset = 0;
+        gf_dirent_t  *entry  = NULL;
+        gf_dirent_t  *tmp    = NULL;
+        int           ret    = 0;
+        uint64_t      ctx    = 0;
+        afr_fd_ctx_t *fd_ctx = NULL;
+        off_t         offset = 0;
 
         ret = fd_ctx_get (fd, THIS, &ctx);
         if (ret < 0) {
-                gf_log (THIS->name, GF_LOG_DEBUG,
+                gf_log (THIS->name, GF_LOG_INFO,
                         "could not get fd ctx for fd=%p", fd);
                 return -1;
         }
@@ -457,15 +453,15 @@ afr_filter_entries (gf_dirent_t *entries, fd_t *fd)
 static void
 afr_forget_entries (fd_t *fd)
 {
-        struct entry_name *entry, *tmp;
-        int ret = 0;
-
-        uint64_t      ctx;
-        afr_fd_ctx_t *fd_ctx;
+        struct entry_name *entry  = NULL;
+        struct entry_name *tmp    = NULL;
+        int                ret    = 0;
+        uint64_t           ctx    = 0;
+        afr_fd_ctx_t      *fd_ctx = NULL;
 
         ret = fd_ctx_get (fd, THIS, &ctx);
         if (ret < 0) {
-                gf_log (THIS->name, GF_LOG_DEBUG,
+                gf_log (THIS->name, GF_LOG_INFO,
                         "could not get fd ctx for fd=%p", fd);
                 return;
         }
@@ -485,32 +481,32 @@ afr_readdir_cbk (call_frame_t *frame, void *cookie,
                  xlator_t *this, int32_t op_ret, int32_t op_errno,
                  gf_dirent_t *entries)
 {
-        afr_private_t * priv     = NULL;
-        afr_local_t *   local    = NULL;
-
-        gf_dirent_t * entry = NULL;
-        gf_dirent_t * tmp   = NULL;
-
-        int child_index = -1;
+        afr_private_t * priv        = NULL;
+        afr_local_t *   local       = NULL;
+        gf_dirent_t *   entry       = NULL;
+        gf_dirent_t *   tmp         = NULL;
+        int             child_index = -1;
 
         priv     = this->private;
         local = frame->local;
         child_index = (long) cookie;
 
-        if (op_ret != -1) {
-                list_for_each_entry_safe (entry, tmp, &entries->list, list) {
-                        entry->d_ino = afr_itransform (entry->d_ino,
-                                                       priv->child_count,
-                                                       child_index);
+        if (op_ret == -1)
+                goto out;
 
-                        if ((local->fd->inode == local->fd->inode->table->root)
-                            && !strcmp (entry->d_name, GF_REPLICATE_TRASH_DIR)) {
-                                list_del_init (&entry->list);
-                                GF_FREE (entry);
-                        }
+        list_for_each_entry_safe (entry, tmp, &entries->list, list) {
+                entry->d_ino = afr_itransform (entry->d_ino,
+                                               priv->child_count,
+                                               child_index);
+
+                if ((local->fd->inode == local->fd->inode->table->root)
+                    && !strcmp (entry->d_name, GF_REPLICATE_TRASH_DIR)) {
+                        list_del_init (&entry->list);
+                        GF_FREE (entry);
                 }
         }
 
+out:
         AFR_STACK_UNWIND (readdir, frame, op_ret, op_errno, entries);
 
         return 0;
@@ -521,23 +517,18 @@ int32_t
 afr_readdirp_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                   int32_t op_ret, int32_t op_errno, gf_dirent_t *entries)
 {
-        afr_private_t * priv     = NULL;
-        afr_local_t *   local    = NULL;
-        xlator_t **     children = NULL;
-        ino_t           inum = 0;
-
-        int call_child = 0;
-        int ret        = 0;
-
-        gf_dirent_t * entry = NULL;
-        gf_dirent_t * tmp   = NULL;
-
-        int child_index = -1;
-
-        uint64_t      ctx    = 0;
-        afr_fd_ctx_t *fd_ctx = NULL;
-
-        off_t offset = 0;
+        afr_private_t *  priv        = NULL;
+        afr_local_t *    local       = NULL;
+        xlator_t **      children    = NULL;
+        ino_t            inum        = 0;
+        int              call_child  = 0;
+        int              ret         = 0;
+        gf_dirent_t *    entry       = NULL;
+        gf_dirent_t *    tmp         = NULL;
+        int              child_index = -1;
+        uint64_t         ctx         = 0;
+        afr_fd_ctx_t    *fd_ctx      = NULL;
+        off_t            offset      = 0;
 
         priv     = this->private;
         children = priv->children;
@@ -549,7 +540,7 @@ afr_readdirp_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         if (priv->strict_readdir) {
                 ret = fd_ctx_get (local->fd, this, &ctx);
                 if (ret < 0) {
-                        gf_log (this->name, GF_LOG_DEBUG,
+                        gf_log (this->name, GF_LOG_INFO,
                                 "could not get fd ctx for fd=%p", local->fd);
                         op_ret   = -1;
                         op_errno = -ret;
@@ -560,6 +551,8 @@ afr_readdirp_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 
                 if (child_went_down (op_ret, op_errno)) {
                         if (all_tried (child_index, priv->child_count)) {
+                                gf_log (this->name, GF_LOG_INFO,
+                                        "all options tried going out");
                                 goto out;
                         }
 
@@ -600,6 +593,8 @@ afr_readdirp_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         if (priv->strict_readdir) {
                 if (fd_ctx->failed_over) {
                         if (list_empty (&entries->list)) {
+                                gf_log (this->name, GF_LOG_DEBUG,
+                                        "no entries found");
                                 goto out;
                         }
 
@@ -614,7 +609,8 @@ afr_readdirp_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                                    try to get more entries */
 
                                 gf_log (this->name, GF_LOG_TRACE,
-                                        "trying to fetch non-duplicate entries from offset %"PRId64", child %s",
+                                        "trying to fetch non-duplicate entries "
+                                        "from offset %"PRId64", child %s",
                                         offset, children[child_index]->name);
 
                                 STACK_WIND_COOKIE (frame, afr_readdirp_cbk,
@@ -640,18 +636,15 @@ int32_t
 afr_do_readdir (call_frame_t *frame, xlator_t *this,
                 fd_t *fd, size_t size, off_t offset, int whichop)
 {
-        afr_private_t * priv       = NULL;
-        xlator_t **     children   = NULL;
-        int             call_child = 0;
-        afr_local_t     *local     = NULL;
-
-        uint64_t      ctx;
-        afr_fd_ctx_t *fd_ctx;
-
-        int ret = -1;
-
-        int32_t op_ret   = -1;
-        int32_t op_errno = 0;
+        afr_private_t *  priv       = NULL;
+        xlator_t **      children   = NULL;
+        int              call_child = 0;
+        afr_local_t     *local      = NULL;
+        uint64_t         ctx        = 0;
+        afr_fd_ctx_t    *fd_ctx     = NULL;
+        int              ret        = -1;
+        int32_t          op_ret     = -1;
+        int32_t          op_errno   = 0;
 
         VALIDATE_OR_GOTO (frame, out);
         VALIDATE_OR_GOTO (this, out);
@@ -672,7 +665,7 @@ afr_do_readdir (call_frame_t *frame, xlator_t *this,
         call_child = afr_first_up_child (priv);
         if (call_child == -1) {
                 op_errno = ENOTCONN;
-                gf_log (this->name, GF_LOG_DEBUG,
+                gf_log (this->name, GF_LOG_INFO,
                         "no child is up");
                 goto out;
         }
@@ -683,7 +676,7 @@ afr_do_readdir (call_frame_t *frame, xlator_t *this,
         if (priv->strict_readdir) {
                 ret = fd_ctx_get (fd, this, &ctx);
                 if (ret < 0) {
-                        gf_log (this->name, GF_LOG_DEBUG,
+                        gf_log (this->name, GF_LOG_INFO,
                                 "could not get fd ctx for fd=%p", fd);
                         op_errno = -ret;
                         goto out;
@@ -693,7 +686,8 @@ afr_do_readdir (call_frame_t *frame, xlator_t *this,
 
                 if (fd_ctx->last_tried != call_child) {
                         gf_log (this->name, GF_LOG_TRACE,
-                                "first up child has changed from %d to %d, restarting readdir from offset 0",
+                                "first up child has changed from %d to %d, "
+                                "restarting readdir from offset 0",
                                 fd_ctx->last_tried, call_child);
 
                         fd_ctx->failed_over = _gf_true;