Bug 1142409

+++ This bug was initially created as a clone of Bug #1139812 +++

+++ This bug was initially created as a clone of Bug #1139213 +++

Description of problem:

rebalance process crashed upon adding a brick and starting the volume.

How reproducible:

Always.

Steps to Reproduce:
1. Run multiple rename operations on the mount point.
2. Add a replica pair to the volume.
3. Start rebalance on the volume.

Actual results:

Rebalance fails and process crashes.


Additional info:

[2014-09-08 10:27:52.734274] E [MSGID: 109019] [dht-common.c:2780:dht_getxattr] 0-t0-dht: Layout is NULL
[2014-09-08 10:27:52.734300] E [MSGID: 109023] [dht-rebalance.c:1520:gf_defrag_migrate_data] 0-t0-dht: M
igrate file failed:Failed to get node-uuid for /scratch/scratch/renameracegvJKY2
pending frames:
frame : type(0) op(0)
frame : type(0) op(0)
frame : type(0) op(0)
frame : type(0) op(0)
patchset: git://git.gluster.com/glusterfs.git
signal received: 11
time of crash: 
2014-09-08 10:27:52
configuration details:
argp 1
backtrace 1
dlfcn 1
libpthread 1
llistxattr 1
setfsid 1
spinlock 1
epoll.h 1
xattr.h 1
st_atim.tv_nsec 1
package-string: glusterfs 3.6.0.28
/usr/lib64/libglusterfs.so.0(_gf_msg_backtrace_nomem+0xb6)[0x349241ff06]
/usr/lib64/libglusterfs.so.0(gf_print_trace+0x33f)[0x349243a59f]
/lib64/libc.so.6[0x3392e329a0]
/usr/lib64/glusterfs/3.6.0.28/xlator/protocol/client.so(client3_3_lookup_cbk+0x89)[0x7f67f0bd2ca9]
/usr/lib64/libgfrpc.so.0(rpc_clnt_handle_reply+0xa5)[0x3492c0e9c5]
/usr/lib64/libgfrpc.so.0(rpc_clnt_notify+0x13f)[0x3492c0fe4f]
/usr/lib64/libgfrpc.so.0(rpc_transport_notify+0x28)[0x3492c0b668]
/usr/lib64/glusterfs/3.6.0.28/rpc-transport/socket.so(+0x9275)[0x7f67f1015275]
/usr/lib64/glusterfs/3.6.0.28/rpc-transport/socket.so(+0xac5d)[0x7f67f1016c5d]
/usr/lib64/libglusterfs.so.0[0x3492476367]
/usr/sbin/glusterfs(main+0x603)[0x407e93]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x3392e1ed1d]
/usr/sbin/glusterfs[0x4049a9]


=======

(gdb) p *frame
$1 = {
  root = 0x7f67f9ecfea4, 
  parent = 0x7f67fa09c1c4, 
  next = 0x7f67fa09ba60, 
  prev = 0x7f67f9ed050c, 
  local = 0x0, 
  this = 0x22020b0, 
  ret = 0x7f67f0993ee0 <afr_lookup_cbk>, 
  ref_count = 0, 
  lock = 1, 
  cookie = 0x1, 
  complete = _gf_true, 
  op = GF_FOP_NULL, 
  begin = {
    tv_sec = 0, 
    tv_usec = 0
  }, 
  end = {
    tv_sec = 0, 
    tv_usec = 0
  }, 
  wind_from = 0x7f67f099f3d1 "afr_lookup", 
  wind_to = 0x7f67f0998528 "priv->children[i]->fops->lookup", 
  unwind_from = 0x7f67f0be6800 "client3_3_lookup_cbk", 
  unwind_to = 0x7f67f099d3a7 "afr_lookup_cbk"
}

(gdb) p *frame->next
$2 = {
  root = 0x7f67f9ecfea4, 
  parent = 0x7f67fa09c1c4, 
  next = 0x7f67fa09c1c4, 
  prev = 0x7f67fa09b454, 
  local = 0x0, 
  this = 0x2201180, 
  ret = 0x7f67f0993ee0 <afr_lookup_cbk>, 
  ref_count = 0, 
  lock = 1, 
  cookie = 0x0, 
  complete = _gf_true, 
  op = GF_FOP_NULL, 
  begin = {
    tv_sec = 0, 
    tv_usec = 0
  }, 
  end = {
    tv_sec = 0, 
    tv_usec = 0
  }, 
  wind_from = 0x7f67f099f3d1 "afr_lookup", 
  wind_to = 0x7f67f0998528 "priv->children[i]->fops->lookup", 
  unwind_from = 0x7f67f0be6800 "client3_3_lookup_cbk", 
  unwind_to = 0x7f67f099d3a7 "afr_lookup_cbk"
}

(gdb) p *frame->next->next
$3 = {
  root = 0x7f67f9ecfea4, 
  parent = 0x7f67fa09b3a8, 
  next = 0x7f67fa09b3a8, 
  prev = 0x7f67fa09ba60, 
  local = 0x7f67eb18c04c, 
  this = 0x2204ee0, 
  ret = 0x7f67f0711c20 <dht_lookup_cbk>, 
  ref_count = 0, 
  lock = 1, 
  cookie = 0x7f67fa09c1c4, 
  complete = _gf_false, 
  op = GF_FOP_NULL, 
  begin = {
    tv_sec = 0, 
    tv_usec = 0
  }, 
  end = {
    tv_sec = 0, 
    tv_usec = 0
  }, 
  wind_from = 0x7f67f072ac67 "dht_lookup", 
  wind_to = 0x7f67f0728a5a "hashed_subvol->fops->lookup", 
  unwind_from = 0x0, 
  unwind_to = 0x7f67f0728a76 "dht_lookup_cbk"
}

(gdb) p *frame->next->next->next
$4 = {
  root = 0x7f67f9ecfea4, 
  parent = 0x7f67f9ed050c, 
  next = 0x0, 
  prev = 0x7f67fa09c1c4, 
  local = 0x7f67eb6b304c, 
  this = 0x2205b30, 
  ret = 0x349245d0e0 <syncop_lookup_cbk>, 
  ref_count = 1, 
  lock = 1, 
  cookie = 0x7f67e9c12d10, 
  complete = _gf_false, 
  op = GF_FOP_NULL, 
  begin = {
    tv_sec = 0, 
    tv_usec = 0
  }, 
  end = {
    tv_sec = 0, 
    tv_usec = 0
  }, 
  wind_from = 0x3492483794 "syncop_lookup", 
  wind_to = 0x349248310a "subvol->fops->lookup", 
  unwind_from = 0x0, 
  unwind_to = 0x349248311f "syncop_lookup_cbk"
}

(gdb) bt
#0  client3_3_lookup_cbk (req=0x7f67ea660298, iov=<value optimized out>, count=<value optimized out>, 
    myframe=0x7f67fa09b454) at client-rpc-fops.c:2710
#1  0x0000003492c0e9c5 in rpc_clnt_handle_reply (clnt=0x22ecd70, pollin=0x21f6360) at rpc-clnt.c:763
#2  0x0000003492c0fe4f in rpc_clnt_notify (trans=<value optimized out>, mydata=0x22ecda0, 
    event=<value optimized out>, data=<value optimized out>) at rpc-clnt.c:891
#3  0x0000003492c0b668 in rpc_transport_notify (this=<value optimized out>, 
    event=<value optimized out>, data=<value optimized out>) at rpc-transport.c:512
#4  0x00007f67f1015275 in socket_event_poll_in (this=0x22fc900) at socket.c:2127
#5  0x00007f67f1016c5d in socket_event_handler (fd=<value optimized out>, idx=<value optimized out>, 
    data=0x22fc900, poll_in=1, poll_out=0, poll_err=0) at socket.c:2240
#6  0x0000003492476367 in event_dispatch_epoll_handler (event_pool=0x21d5d00) at event-epoll.c:384
#7  event_dispatch_epoll (event_pool=0x21d5d00) at event-epoll.c:445
#8  0x0000000000407e93 in main (argc=31, argv=0x7fff82c05998) at glusterfsd.c:2023
(gdb)

--- Additional comment from Saurabh on 2014-09-09 07:20:45 EDT ---

I also found the same issue while executing remove-brick operation and no other operation executing on the mount-point.

[root@nfs4 ~]# gluster volume remove-brick dist-rep 10.70.37.156:/bricks/d1r1-add3 10.70.37.81:/bricks/d1r2-add3 status
                                    Node Rebalanced-files          size       scanned      failures       skipped               status   run time in secs
                               ---------      -----------   -----------   -----------   -----------   -----------         ------------     --------------
                            10.70.37.156                0        0Bytes             0             0             0               failed               0.00
                             10.70.37.81                0        0Bytes             0             0             0               failed               0.00


(gdb) bt
#0  client3_3_lookup_cbk (req=0x7f07451fb4e4, iov=<value optimized out>, count=<value optimized out>, myframe=0x7f075635bd50)
    at client-rpc-fops.c:2710
#1  0x000000391ca0e9c5 in rpc_clnt_handle_reply (clnt=0x2543ea0, pollin=0x270dec0) at rpc-clnt.c:763
#2  0x000000391ca0fe4f in rpc_clnt_notify (trans=<value optimized out>, mydata=0x2543ed0, event=<value optimized out>, data=<value optimized out>)
    at rpc-clnt.c:891
#3  0x000000391ca0b668 in rpc_transport_notify (this=<value optimized out>, event=<value optimized out>, data=<value optimized out>)
    at rpc-transport.c:512
#4  0x00007f074d2d3275 in socket_event_poll_in (this=0x2553aa0) at socket.c:2127
#5  0x00007f074d2d4c5d in socket_event_handler (fd=<value optimized out>, idx=<value optimized out>, data=0x2553aa0, poll_in=1, poll_out=0, 
    poll_err=0) at socket.c:2240
#6  0x000000391c276367 in event_dispatch_epoll_handler (event_pool=0x22c04d0) at event-epoll.c:384
#7  event_dispatch_epoll (event_pool=0x22c04d0) at event-epoll.c:445
#8  0x0000000000407e93 in main (argc=31, argv=0x7ffffe0a22e8) at glusterfsd.c:2023

--- Additional comment from Shyamsundar on 2014-09-09 12:49:23 EDT ---

Root caused this as follows:

In dht_lookup_everywhere_done

Line: 1194 we call DHT_STACK_UNWIND
and in the same if condition we go ahead and call, goto
unwind_hashed_and_cached; which at Line 1371 calls another UNWIND.

Pointers to the problem:
- If you see in the cores, the ref count for the frames become -1 which
means double dereference of sorts.

From (gdb) f 2  if the frame, frame->parent, frame->parent->parent is
inspected, we can see this ref count.

- In all the cores, the statement that caused the UNWIND is occuring at
"unwind_hashed_and_cached:" at dht_lookup_everywhere_done, and we can
get here only from that loop as mentioned above.

So the problem is a double UNWIND in a particular code path that causes this core dump.

BTW, bug #1139535 has the same root cause.

--- Additional comment from Shyamsundar on 2014-09-09 13:00:57 EDT ---

Another symptom of the same issue:
==================================

Description of problem:
I tried to resolve the gfid mismatch for a file and then did "ls" for that same file. The ls command hung and nfs server reported crash.

gluster volume info,
[root@nfs4 ~]# gluster volume info dist-rep
 
Volume Name: dist-rep
Type: Distributed-Replicate
Volume ID: 9a80c514-ddd4-45cb-b2b6-d745fd438db8
Status: Started
Snap Volume: no
Number of Bricks: 7 x 2 = 14
Transport-type: tcp
Bricks:
Brick1: 10.70.37.156:/bricks/d1r1
Brick2: 10.70.37.81:/bricks/d1r2
Brick3: 10.70.37.50:/bricks/d2r1
Brick4: 10.70.37.95:/bricks/d2r2
Brick5: 10.70.37.156:/bricks/d3r1
Brick6: 10.70.37.81:/bricks/d3r2
Brick7: 10.70.37.50:/bricks/d4r1
Brick8: 10.70.37.95:/bricks/d4r2
Brick9: 10.70.37.156:/bricks/d5r1
Brick10: 10.70.37.81:/bricks/d5r2
Brick11: 10.70.37.50:/bricks/d6r1
Brick12: 10.70.37.95:/bricks/d6r2
Brick13: 10.70.37.156:/bricks/d1r1-add3
Brick14: 10.70.37.81:/bricks/d1r2-add3
Options Reconfigured:
features.quota-deem-statfs: on
features.quota: on
performance.readdir-ahead: on
snap-max-hard-limit: 256
snap-max-soft-limit: 90
auto-delete: disable

procedure folllowed for overcoming gfid mismatch is this,

1. find the gfid on the replica pair using getfattr command.

2. if the gfid is different for the file. then on brick of the pair 
   a. first delete the gfid entry from .glusterfs/indices/xattrop dir
   b. second delete the file itself from the same brick where step 2a is executed

3. check the gfid again using getfattr. Found that the gfid now matches


after above the above steps I have done ls <filename> on the mount-point.

How reproducible:
seen this time

Actual results:

nfs.log,

signal received: 11
time of crash: 
2014-09-08 20:11:48
configuration details:
argp 1
backtrace 1
dlfcn 1
libpthread 1
llistxattr 1
setfsid 1
spinlock 1
epoll.h 1
xattr.h 1
st_atim.tv_nsec 1
package-string: glusterfs 3.6.0.28
/usr/lib64/libglusterfs.so.0(_gf_msg_backtrace_nomem+0xb6)[0x391c21ff06]
/usr/lib64/libglusterfs.so.0(gf_print_trace+0x33f)[0x391c23a59f]
/lib64/libc.so.6[0x3c6be326b0]
/usr/lib64/glusterfs/3.6.0.28/xlator/nfs/server.so(nfs_fop_lookup_cbk+0x225)[0x7fc08287f2e5]
/usr/lib64/glusterfs/3.6.0.28/xlator/debug/io-stats.so(io_stats_lookup_cbk+0x113)[0x7fc082ad5e73]
/usr/lib64/glusterfs/3.6.0.28/xlator/cluster/distribute.so(dht_lookup_everywhere_done+0x668)[0x7fc082f1cba8]
/usr/lib64/glusterfs/3.6.0.28/xlator/cluster/distribute.so(dht_lookup_everywhere_cbk+0x403)[0x7fc082f215b3]
/usr/lib64/glusterfs/3.6.0.28/xlator/cluster/replicate.so(afr_lookup_cbk+0x558)[0x7fc0831a4438]
/usr/lib64/glusterfs/3.6.0.28/xlator/protocol/client.so(client3_3_lookup_cbk+0x647)[0x7fc0833e3267]
/usr/lib64/libgfrpc.so.0(rpc_clnt_handle_reply+0xa5)[0x391ca0e9c5]
/usr/lib64/libgfrpc.so.0(rpc_clnt_notify+0x13f)[0x391ca0fe4f]
/usr/lib64/libgfrpc.so.0(rpc_transport_notify+0x28)[0x391ca0b668]
/usr/lib64/glusterfs/3.6.0.28/rpc-transport/socket.so(+0x9275)[0x7fc08839e275]
/usr/lib64/glusterfs/3.6.0.28/rpc-transport/socket.so(+0xac5d)[0x7fc08839fc5d]
/usr/lib64/libglusterfs.so.0[0x391c276367]
/usr/sbin/glusterfs(main+0x603)[0x407e93]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x3c6be1ed5d]
/usr/sbin/glusterfs[0x4049a9]


(gdb) bt
#0  nfs_fop_lookup_cbk (frame=0x7fc09085b740, cookie=0x1f38790, this=<value optimized out>, op_ret=<value optimized out>, 
    op_errno=<value optimized out>, inode=<value optimized out>, buf=0x7fc07fd7916c, xattr=0x2919ecc, postparent=0x7fc07fd7939c) at nfs-fops.c:427
#1  0x00007fc082ad5e73 in io_stats_lookup_cbk (frame=0x7fc090a2635c, cookie=<value optimized out>, this=<value optimized out>, op_ret=0, op_errno=0, 
    inode=0x0, buf=0x7fc07fd7916c, xdata=0x2919ecc, postparent=0x7fc07fd7939c) at io-stats.c:1505
#2  0x00007fc082f1cba8 in dht_lookup_everywhere_done (frame=0x7fc090a243c8, this=<value optimized out>) at dht-common.c:1370
#3  0x00007fc082f215b3 in dht_lookup_everywhere_cbk (frame=0x7fc090a243c8, cookie=<value optimized out>, this=0x1f34bc0, 
    op_ret=<value optimized out>, op_errno=<value optimized out>, inode=0x7fc081be3b98, buf=0x7fc07f36ba58, xattr=0x2919ecc, 
    postparent=0x7fc07f36bac8) at dht-common.c:1577
#4  0x00007fc0831a4438 in afr_lookup_done (frame=0x7fbfffffffc6, cookie=0x7fff5390a5f8, this=0x1f332e0, op_ret=<value optimized out>, 
    op_errno=43234112, inode=0x8, buf=0x7fff5390a850, xattr=0x2919ecc, postparent=0x7fff5390a7e0) at afr-common.c:2319
#5  afr_lookup_cbk (frame=0x7fbfffffffc6, cookie=0x7fff5390a5f8, this=0x1f332e0, op_ret=<value optimized out>, op_errno=43234112, inode=0x8, 
    buf=0x7fff5390a850, xattr=0x2919ecc, postparent=0x7fff5390a7e0) at afr-common.c:2560
#6  0x00007fc0833e3267 in client3_3_lookup_cbk (req=<value optimized out>, iov=<value optimized out>, count=<value optimized out>, 
    myframe=0x7fc090a37424) at client-rpc-fops.c:2767
#7  0x000000391ca0e9c5 in rpc_clnt_handle_reply (clnt=0x1feefd0, pollin=0x29091b0) at rpc-clnt.c:763
#8  0x000000391ca0fe4f in rpc_clnt_notify (trans=<value optimized out>, mydata=0x1fef000, event=<value optimized out>, data=<value optimized out>)
    at rpc-clnt.c:891
#9  0x000000391ca0b668 in rpc_transport_notify (this=<value optimized out>, event=<value optimized out>, data=<value optimized out>)
    at rpc-transport.c:512
#10 0x00007fc08839e275 in socket_event_poll_in (this=0x1ffebd0) at socket.c:2127
#11 0x00007fc08839fc5d in socket_event_handler (fd=<value optimized out>, idx=<value optimized out>, data=0x1ffebd0, poll_in=1, poll_out=0, 
    poll_err=0) at socket.c:2240
#12 0x000000391c276367 in event_dispatch_epoll_handler (event_pool=0x1efb4d0) at event-epoll.c:384
#13 event_dispatch_epoll (event_pool=0x1efb4d0) at event-epoll.c:445
#14 0x0000000000407e93 in main (argc=11, argv=0x7fff5390bce8) at glusterfsd.c:2023


Expected results:
nfs should not have crashed.

--- Additional comment from Anand Avati on 2014-09-09 13:34:33 EDT ---

REVIEW: http://review.gluster.org/8666 (cluster/dht: Fixed double UNWIND in lookup everywhere code) posted (#1) for review on master by Shyamsundar Ranganathan (srangana)

--- Additional comment from Anand Avati on 2014-09-09 23:29:21 EDT ---

COMMIT: http://review.gluster.org/8666 committed in master by Vijay Bellur (vbellur) 
------
commit b3314ea6e820fb659255d0e6e9a32ea259b7526d
Author: Shyam <srangana>
Date:   Tue Sep 9 13:31:51 2014 -0400

    cluster/dht: Fixed double UNWIND in lookup everywhere code
    
    In dht_lookup_everywhere_done:
    Line: 1194 we call DHT_STACK_UNWIND
    and in the same if condition we go ahead and call, goto
    unwind_hashed_and_cached; which at Line 1371 calls another UNWIND.
    
    As is obvious, higher frames could cleanup their locals and on
    receiving the next unwind could cause a coredump of the process.
    
    Fixed the same by calling the required return post the first unwind
    
    Change-Id: Ic5d57da98255b8616a65b4caaedabeba9144fd49
    BUG: 1139812
    Signed-off-by: Shyam <srangana>
    Reviewed-on: http://review.gluster.org/8666
    Reviewed-by: N Balachandran <nbalacha>
    Reviewed-by: Vijay Bellur <vbellur>
    Reviewed-by: Jeff Darcy <jdarcy>
    Tested-by: Gluster Build System <jenkins.com>
    Reviewed-by: susant palai <spalai>