cluster/dht: Added code to capture races in dht-lookup path

Change-Id: I9270d2d40ebd4b113ff961583dfda7754741f151
BUG: 1138385
Signed-off-by: Venkatesh Somyajulu <vsomyaju@redhat.com>
Reviewed-on-master: http://review.gluster.org/8430
Tested-by: Gluster Build System <jenkins@build.gluster.com>
Reviewed-by: Vijay Bellur <vbellur@redhat.com>
Reviewed-by: Jeff Darcy <jdarcy@redhat.com>
Reviewed-on: http://review.gluster.org/8668
Tested-by: Vijay Bellur <vbellur@redhat.com>

2 files changed, 152 insertions, 10 deletions

diff --git a/xlators/cluster/dht/src/dht-common.c b/xlators/cluster/dht/src/dht-common.c
index 313fd89aa59..0d686bdbf4a 100644
--- a/xlators/cluster/dht/src/dht-common.c
+++ b/xlators/cluster/dht/src/dht-common.c
@@ -507,10 +507,14 @@ dht_lookup_dir_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 
                 is_dir = check_is_dir (inode, stbuf, xattr);
                 if (!is_dir) {
+
                         gf_msg_debug (this->name, 0,
-                                      "lookup of %s on %s returned non dir 0%o",
+                                      "lookup of %s on %s returned non"
+                                      "dir 0%o"
+                                      "calling lookup_everywhere",
                                       local->loc.path, prev->this->name,
                                       stbuf->ia_type);
+
                         local->need_selfheal = 1;
                         goto unlock;
                 }
@@ -610,6 +614,12 @@ dht_revalidate_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 
         LOCK (&frame->lock);
         {
+
+                gf_msg_debug (this->name, 0,
+                              "revalidate lookup of %s "
+                              "returned with op_ret %d and op_errno %d",
+                              local->loc.path, op_ret, op_errno);
+
                 if (op_ret == -1) {
                         local->op_errno = op_errno;
 
@@ -634,6 +644,14 @@ dht_revalidate_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                          * the file is not migrated */
                         if (op_errno == ENOENT) {
                                 if (IA_ISREG (local->loc.inode->ia_type)) {
+
+                                        gf_msg_debug (this->name, 0,
+                                                      "found ENOENT for %s. "
+                                                      "Setting "
+                                                      "need_lookup_everywhere"
+                                                      " flag to 1",
+                                                      local->loc.path);
+
                                         local->need_lookup_everywhere = 1;
                                 }
                         }
@@ -839,9 +857,16 @@ dht_lookup_linkfile_create_cbk (call_frame_t *frame, void *cookie,
         }
 
 unwind:
+        gf_msg_debug (this->name, 0,
+                      "creation of linkto on hashed subvol:%s, "
+                      "returned with op_ret %d and op_errno %d: %s",
+                      local->hashed_subvol->name,
+                      op_ret, op_errno, uuid_utoa (local->loc.gfid));
+
         if (local->linked == _gf_true)
                 dht_linkfile_attr_heal (frame, this);
 
+
         DHT_STRIP_PHASE1_FLAGS (&local->stbuf);
         DHT_STACK_UNWIND (lookup, frame, local->op_ret, local->op_errno,
                           local->inode, &local->stbuf, local->xattr,
@@ -926,12 +951,24 @@ dht_lookup_unlink_stale_linkto_cbk (call_frame_t *frame, void *cookie,
                                     struct iatt *postparent, dict_t *xdata)
 {
 
+        dht_local_t     *local = NULL;
+        const char      *path  = NULL;
+
         /* NOTE:
          * If stale file unlink fails either there is an open-fd or is not an
          * dht-linkto-file then posix_unlink returns EBUSY, which is overwritten
          *  to ENOENT
          */
 
+        local = frame->local;
+
+        if (local && local->loc.path)
+                path = local->loc.path;
+
+        gf_log (this->name, GF_LOG_INFO, "Returned with op_ret %d and "
+                "op_errno %d for %s", op_ret, op_errno,
+                ((path==NULL)?"null":path));
+
         DHT_STACK_UNWIND (lookup, frame, -1, ENOENT, NULL, NULL, NULL,
                           NULL);
 
@@ -1012,6 +1049,10 @@ dht_lookup_everywhere_done (call_frame_t *frame, xlator_t *this)
                 return 0;
         }
 
+        gf_log (this->name, GF_LOG_INFO, "STATUS: hashed_subvol %s "
+                "cached_subvol %s",
+                (hashed_subvol == NULL)?"null":hashed_subvol->name,
+                (cached_subvol == NULL)?"null":cached_subvol->name);
 
         if (!cached_subvol) {
 
@@ -1064,7 +1105,14 @@ dict_err:
                                                   NULL, NULL, NULL, NULL);
                         } else {
                                local->skip_unlink.handle_valid_link = _gf_false;
-                                STACK_WIND (frame,
+
+                                gf_msg_debug (this->name, 0,
+                                              "No Cached was found and "
+                                              "unlink on hashed was skipped"
+                                              " so performing now: %s",
+                                              local->loc.path);
+
+                               STACK_WIND (frame,
                                             dht_lookup_unlink_stale_linkto_cbk,
                                             hashed_subvol,
                                             hashed_subvol->fops->unlink,
@@ -1073,6 +1121,11 @@ dict_err:
 
                 } else  {
 
+                        gf_msg_debug (this->name, 0,
+                                      "There was no cached file and  "
+                                      "unlink on hashed is not skipped %s",
+                                      local->loc.path);
+
                         DHT_STACK_UNWIND (lookup, frame, -1, ENOENT, NULL, NULL,
                                           NULL, NULL);
                 }
@@ -1096,6 +1149,11 @@ dict_err:
                 } else if ((local->file_count == 1) &&
                             (hashed_subvol == cached_subvol)) {
 
+                        gf_msg_debug (this->name, 0,
+                                      "found cached file on hashed subvolume "
+                                      "so store in context and return for %s",
+                                      local->loc.path);
+
                         found_non_linkto_on_hashed = _gf_true;
                 }
 
@@ -1141,10 +1199,29 @@ dict_err:
                                                 (local->loc.parent, this,
                                                  &local->postparent, 1);
                                 }
+
+                                gf_msg_debug (this->name, 0,
+                                              "Skipped unlinking linkto file "
+                                              "on the hashed subvolume. "
+                                              "Returning success as it is a "
+                                              "valid linkto file. Path:%s"
+                                              ,local->loc.path);
+
                                 goto unwind_hashed_and_cached;
                         } else {
 
                                local->skip_unlink.handle_valid_link = _gf_false;
+
+                               gf_msg_debug (this->name, 0,
+                                             "Linkto file found on hashed "
+                                             "subvol "
+                                             "and data file found on cached "
+                                             "subvolume. But linkto points to "
+                                             "different cached subvolume (%s) "
+                                             "path %s",
+                                         local->skip_unlink.hash_links_to->name,
+                                             local->loc.path);
+
                                if (local->skip_unlink.opend_fd_count == 0) {
 
 
@@ -1224,11 +1301,11 @@ preset_layout:
         }
 
         if (!hashed_subvol) {
-                gf_msg (this->name, GF_LOG_INFO, 0,
-                        DHT_MSG_HASHED_SUBVOL_GET_FAILED,
-                        "cannot create linkfile file for %s on %s: "
-                        "hashed subvolume cannot be found, gfid = %s.",
-                        local->loc.path, cached_subvol->name, gfid);
+
+                gf_msg_debug (this->name, 0,
+                              "Cannot create linkfile for %s on %s: "
+                              "hashed subvolume cannot be found, gfid = %s.",
+                              local->loc.path, cached_subvol->name, gfid);
 
                 local->op_ret = 0;
                 local->op_errno = 0;
@@ -1309,6 +1386,11 @@ dht_lookup_everywhere_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         prev   = cookie;
         subvol = prev->this;
 
+        gf_msg_debug (this->name, 0,
+                      "returned with op_ret %d and op_errno %d (%s) "
+                      "from subvol %s", op_ret, op_errno, loc->path,
+                      subvol->name);
+
         LOCK (&frame->lock);
         {
                 if (op_ret == -1) {
@@ -1333,6 +1415,14 @@ dht_lookup_everywhere_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 
                 is_linkfile = check_is_linkfile (inode, buf, xattr,
                                                  conf->link_xattr_name);
+
+                if (is_linkfile) {
+
+                        gf_msg_debug (this->name, 0,
+                                      "Found linktofile on %s for %s",
+                                       subvol->name, loc->path);
+
+               }
                 is_dir = check_is_dir (inode, buf, xattr);
 
                 if (is_linkfile) {
@@ -1357,15 +1447,20 @@ dht_lookup_everywhere_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 } else {
                         local->file_count++;
 
+                        gf_msg_debug (this->name, 0,
+                                      "found cached file on %s for %s",
+                                      subvol->name, loc->path);
+
                         if (!local->cached_subvol) {
                                 /* found one file */
                                 dht_iatt_merge (this, &local->stbuf, buf,
                                                 subvol);
                                 local->xattr = dict_ref (xattr);
                                 local->cached_subvol = subvol;
+
                                 gf_msg_debug (this->name, 0,
-                                              "found on %s file %s",
-                                              subvol->name, loc->path);
+                                              "storing cached on %s file"
+                                              " %s", subvol->name, loc->path);
 
                                 dht_iatt_merge (this, &local->postparent,
                                                 postparent, subvol);
@@ -1409,6 +1504,12 @@ unlock:
                         uuid_copy (local->skip_unlink.hashed_gfid,
                                    buf->ia_gfid);
 
+                        gf_msg_debug (this->name, 0, "Found"
+                                      " one linkto file on hashed subvol %s "
+                                      "for %s: Skipping unlinking till "
+                                      "everywhere_done", subvol->name,
+                                      loc->path);
+
                 } else if (!ret && (fd_count == 0)) {
                         gf_log (this->name, GF_LOG_INFO,
                                 "deleting stale linkfile %s on %s",
@@ -1452,6 +1553,9 @@ dht_lookup_everywhere (call_frame_t *frame, xlator_t *this, loc_t *loc)
         if (!local->inode)
                 local->inode = inode_ref (loc->inode);
 
+        gf_msg_debug (this->name, 0,
+                      "winding lookup call to %d subvols", call_cnt);
+
         for (i = 0; i < call_cnt; i++) {
                 STACK_WIND (frame, dht_lookup_everywhere_cbk,
                             conf->subvolumes[i],
@@ -1659,8 +1763,12 @@ dht_lookup_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
         if (!op_ret && uuid_is_null (local->gfid))
                 memcpy (local->gfid, stbuf->ia_gfid, 16);
 
+        gf_msg_debug (this->name, 0,
+                      "fresh_lookup returned for %s with op_ret %d and "
+                      "op_errno %d", loc->path, op_ret, op_errno);
+
         if (ENTRY_MISSING (op_ret, op_errno)) {
-                gf_msg_trace (this->name, 0, "Entry %s missing on subvol"
+                gf_log (this->name, GF_LOG_INFO, "Entry %s missing on subvol"
                               " %s", loc->path, prev->this->name);
                 if (conf->search_unhashed == GF_DHT_LOOKUP_UNHASHED_ON) {
                         local->op_errno = ENOENT;
@@ -1721,6 +1829,10 @@ dht_lookup_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
 
         subvol = dht_linkfile_subvol (this, inode, stbuf, xattr);
         if (!subvol) {
+
+                gf_log (this->name, GF_LOG_INFO, "linkfile not having link "
+                        "subvol for %s", loc->path);
+
                 gf_msg_debug (this->name, 0,
                               "linkfile not having link subvolume. path=%s",
                               loc->path);
@@ -1728,6 +1840,10 @@ dht_lookup_cbk (call_frame_t *frame, void *cookie, xlator_t *this,
                 return 0;
         }
 
+        gf_msg_debug (this->name, 0,
+                      "Calling lookup on linkto target %s for path %s",
+                      subvol->name, loc->path);
+
         STACK_WIND (frame, dht_lookup_linkfile_cbk,
                     subvol, subvol->fops->lookup,
                     &local->loc, local->xattr_req);
@@ -1874,6 +1990,13 @@ dht_lookup (call_frame_t *frame, xlator_t *this,
                         dht_layout_unref (this, local->layout);
                         local->layout = NULL;
                         local->cached_subvol = NULL;
+
+                        gf_msg_debug(this->name, 0,
+                                     "Called revalidate lookup for %s, "
+                                     "but layout->gen (%d) is less than "
+                                     "conf->gen (%d), calling fresh_lookup",
+                                     loc->path, layout->gen, conf->gen);
+
                         goto do_fresh_lookup;
                 }
 
@@ -1930,6 +2053,10 @@ dht_lookup (call_frame_t *frame, xlator_t *this,
 		for (i = 0; i < call_cnt; i++) {
 			subvol = layout->list[i].xlator;
 
+                        gf_msg_debug (this->name, 0, "calling "
+                                      "revalidate lookup for %s at %s",
+                                      loc->path, subvol->name);
+
 			STACK_WIND (frame, dht_revalidate_cbk,
 				    subvol, subvol->fops->lookup,
 				    &local->loc, local->xattr_req);
@@ -1972,10 +2099,12 @@ dht_lookup (call_frame_t *frame, xlator_t *this,
                 dht_check_and_set_acl_xattr_req (loc->inode, local->xattr_req);
 
                 if (!hashed_subvol) {
+
                         gf_msg_debug (this->name, 0,
                                       "no subvolume in layout for path=%s, "
                                       "checking on all the subvols to see if "
                                       "it is a directory", loc->path);
+
                         call_cnt        = conf->subvolume_cnt;
                         local->call_cnt = call_cnt;
 
@@ -1986,6 +2115,10 @@ dht_lookup (call_frame_t *frame, xlator_t *this,
                                 goto err;
                         }
 
+                        gf_msg_debug (this->name, 0,
+                                      "Found null hashed subvol. Calling lookup"
+                                      " on all nodes.");
+
                         for (i = 0; i < call_cnt; i++) {
                                 STACK_WIND (frame, dht_lookup_dir_cbk,
                                             conf->subvolumes[i],
@@ -1995,6 +2128,9 @@ dht_lookup (call_frame_t *frame, xlator_t *this,
                         return 0;
                 }
 
+                gf_msg_debug (this->name, 0, "Calling fresh lookup for %s on"
+                              " %s", loc->path, hashed_subvol->name);
+
                 STACK_WIND (frame, dht_lookup_cbk,
                             hashed_subvol, hashed_subvol->fops->lookup,
                             loc, local->xattr_req);
diff --git a/xlators/storage/posix/src/posix.c b/xlators/storage/posix/src/posix.c
index 84574734e2c..1e86d891675 100644
--- a/xlators/storage/posix/src/posix.c
+++ b/xlators/storage/posix/src/posix.c
@@ -1396,6 +1396,9 @@ posix_unlink (call_frame_t *frame, xlator_t *this,
 
                 UNLOCK (&loc->inode->lock);
 
+                gf_log (this->name, GF_LOG_INFO, "open-fd-key-status: "
+                        "%"PRIu32" for %s", skip_unlink, real_path);
+
                 if (skip_unlink) {
                         op_ret = -1;
                         op_errno = EBUSY;
@@ -1423,6 +1426,9 @@ posix_unlink (call_frame_t *frame, xlator_t *this,
 
                 UNLOCK (&loc->inode->lock);
 
+                gf_log (this->name, GF_LOG_INFO, "linkto_xattr status: "
+                        "%"PRIu32" for %s", skip_unlink, real_path);
+
                 if (skip_unlink) {
                         op_ret = -1;
                         op_errno = EBUSY;