Bug 1181203

Description of problem:

Here are 2 problems that were exchanged via mail on this,

<<<< 1 >>>>
Test Case:
./tests/basic/volume-snapshot.t

Failure:
At step 30 in the last run reported by Gerrit (the test case has one additional step now, so fails in one of the last 2 steps), OR, now fails at, 30/31.

The above steps are (were),
TEST ! volume_exists $V0
TEST ! volume_exists $V1

The manner of failure states that the volumes are not deleted, but on removing cleanup routine from the test case and checking manually if the volumes are present, results in the volumes actually being absent, so the test case should not fail, or it is a false failure report.

The real reason however, seems to be that the command "/usr/local/sbin/gluster --glusterd-sock=/d/backends/1/glusterd/gd.sock volume info <patchy|patchy2>", results in no output string, hence the grep trick to determine if this volume has been deleted results in a failure (the grep trick is in volume.rc in function volume_exists, from where this command was captured)

Reason for failure:
From my debugging, the reason for failure is that, we reach exit statement in input.c:37:cli_batch() before reaching the vfprintf(...) in _cli_err, which is invoked from, gf_cli_get_volume_cbk post processing the response for the RPC and sending the broadcast that the RPC is done.

The thread that sends the request waits on the condition that the RPC response is processed, and then does a series of returns that end in the exit in input.c. Whereas the other thread is processing the output and still printing it to stderr.

If we hit the exit first, there is no stderr (or it could be closed) or the running threads could itself be _terminated_ before completion.

Further proof of RCA as above:
1) Tried this command in gdb, with a breakpoint at gf_cli_get_volume_cbk, it is invoked every time and results in an output of err_str as required, but sometimes fails to print it.

2) Put a breakpoint in input.c:exit ()... and sometimes this break point is hit before the print to stderr from _cli_err function (which is bad)

3) Put a sleep of 3 seconds just before the exit() call, and the problem never appeared.

4) Removed the sleep and this happens about 50% of the time.

Solution:
Here is where I need your advice/direction. My thought is obviously to broadcast the response post processing the results and printing them. IOW, call cli_cmd_broadcast_response once the RPC post-processing is really done.

We may need to do this for other types of RPC call back handlers as well. So a different solution could be arrived at, where we wait before exit (somehow?).

Strangeness:
The one strange thing is that without the multi thread epoll patch, this problem never appears (not once in 200 iterations). So what is the weirdness in thread scheduling when we have more than one epoll thread, I am not sure, but I guess something there is kicking up this storm. (i.e the RPC request thread gets woken up and scheduled for execution when there is 1 more thread in the executable (or something like that )).

Reproducible nature of the problem:
I cannot reproduce this in my machine, I had to borrow slave22 from the regression setup to get through this. jFYI.

<<<< 1 >>>>

<<<< 2 >>>>
< I did not do much analysis on this one, thought it was straight forward>

Crash observed when 2 epoll threads are conflicting on updating the xprt->list in glusterd.c:glusterd_rpcsvc_notify

GDB session details follow (see NOTE):
(gdb) t a a bt

Thread 8 (Thread 0x7f7960ce5700 (LWP 29623)):
#0  0x00007f7969c9498e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f796a74f77f in syncenv_task (proc=0xcab700) at syncop.c:535
#2  0x00007f796a755c20 in syncenv_processor (thdata=0xcab700) at syncop.c:613
#3  0x00007f7969c909d1 in start_thread () from /lib64/libpthread.so.0
#4  0x00007f79695fa9dd in clone () from /lib64/libc.so.6

Thread 7 (Thread 0x7f7953fff700 (LWP 29750)):
#0  0x00007f7969c97264 in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00007f7969c92508 in _L_lock_854 () from /lib64/libpthread.so.0
#2  0x00007f7969c923d7 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00007f795bcea895 in glusterd_rpcsvc_notify (rpc=<value optimized out>, xl=<value optimized out>, event=<value optimized out>, data=0x7f7940006f00) at glusterd.c:324
#4  0x00007f796a4e4d14 in rpcsvc_program_notify (trans=<value optimized out>, mydata=<value optimized out>, event=<value optimized out>, data=0x7f7940006f00) at rpcsvc.c:327
#5  rpcsvc_accept (trans=<value optimized out>, mydata=<value optimized out>, event=<value optimized out>, data=0x7f7940006f00) at rpcsvc.c:350
#6  rpcsvc_notify (trans=<value optimized out>, mydata=<value optimized out>, event=<value optimized out>, data=0x7f7940006f00) at rpcsvc.c:775
#7  0x00007f796a4e63c8 in rpc_transport_notify (this=<value optimized out>, event=<value optimized out>, data=<value optimized out>) at rpc-transport.c:516
#8  0x00007f795a9af07e in socket_server_event_handler (fd=<value optimized out>, idx=<value optimized out>, data=0xcbbb90, poll_in=<value optimized out>, poll_out=<value optimized out>, poll_err=<value optimized out>) at socket.c:2773
#9  0x00007f796a7698bc in event_dispatch_epoll_handler (data=0xc9c3f0) at event-epoll.c:550
#10 event_dispatch_epoll_worker (data=0xc9c3f0) at event-epoll.c:608
#11 0x00007f7969c909d1 in start_thread () from /lib64/libpthread.so.0
#12 0x00007f79695fa9dd in clone () from /lib64/libc.so.6

NOTE: Above thread is waiting for the lock after INIT_LIST_HEAD (&xprt->list); which is outside the lock.

Thread 6 (Thread 0x7f79616e6700 (LWP 29622)):
#0  0x00007f7969c9498e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f796a74f77f in syncenv_task (proc=0xcab340) at syncop.c:535
#2  0x00007f796a755c20 in syncenv_processor (thdata=0xcab340) at syncop.c:613
#3  0x00007f7969c909d1 in start_thread () from /lib64/libpthread.so.0
#4  0x00007f79695fa9dd in clone () from /lib64/libc.so.6

Thread 5 (Thread 0x7f7958ce5700 (LWP 29749)):
#0  0x00007f7969c945bc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00007f795bd8cfe3 in hooks_worker (args=<value optimized out>) at glusterd-hooks.c:502
#2  0x00007f7969c909d1 in start_thread () from /lib64/libpthread.so.0
#3  0x00007f79695fa9dd in clone () from /lib64/libc.so.6

Thread 4 (Thread 0x7f79620e7700 (LWP 29620)):
#0  0x00007f7969c97f3d in nanosleep () from /lib64/libpthread.so.0
#1  0x00007f796a7306bc in gf_timer_proc (ctx=0xc7e010) at timer.c:170
#2  0x00007f7969c909d1 in start_thread () from /lib64/libpthread.so.0
#3  0x00007f79695fa9dd in clone () from /lib64/libc.so.6

Thread 3 (Thread 0x7f79596e6700 (LWP 29621)):
#0  0x00007f7969c984b5 in sigwait () from /lib64/libpthread.so.0
#1  0x000000000040560b in glusterfs_sigwaiter (arg=<value optimized out>) at glusterfsd.c:1734
#2  0x00007f7969c909d1 in start_thread () from /lib64/libpthread.so.0
#3  0x00007f79695fa9dd in clone () from /lib64/libc.so.6

Thread 2 (Thread 0x7f796aba2700 (LWP 29619)):
#0  0x00007f7969c9122d in pthread_join () from /lib64/libpthread.so.0
#1  0x00007f796a7694d0 in event_dispatch_epoll (event_pool=<value optimized out>) at event-epoll.c:632
#2  0x0000000000407e78 in main (argc=9, argv=0x7fff225292b8) at glusterfsd.c:2052

Thread 1 (Thread 0x7f79535fe700 (LWP 29751)):
#0  list_del (rpc=<value optimized out>, xl=0xcb3860, event=<value optimized out>, data=0x7f7940006f00) at ../../../../libglusterfs/src/list.h:76
#1  glusterd_rpcsvc_notify (rpc=<value optimized out>, xl=0xcb3860, event=<value optimized out>, data=0x7f7940006f00) at glusterd.c:332
#2  0x00007f796a4e32d5 in rpcsvc_handle_disconnect (svc=0xcbb5a0, trans=0x7f7940006f00) at rpcsvc.c:741
#3  0x00007f796a4e4e10 in rpcsvc_notify (trans=0x7f7940006f00, mydata=<value optimized out>, event=<value optimized out>, data=0x7f7940006f00) at rpcsvc.c:779
#4  0x00007f796a4e63c8 in rpc_transport_notify (this=<value optimized out>, event=<value optimized out>, data=<value optimized out>) at rpc-transport.c:516
#5  0x00007f795a9b2031 in socket_event_poll_err (fd=<value optimized out>, idx=<value optimized out>, data=0x7f7940006f00, poll_in=<value optimized out>, poll_out=0, poll_err=0) at socket.c:1163
#6  socket_event_handler (fd=<value optimized out>, idx=<value optimized out>, data=0x7f7940006f00, poll_in=<value optimized out>, poll_out=0, poll_err=0) at socket.c:2364
#7  0x00007f796a7698bc in event_dispatch_epoll_handler (data=0xc9c3f0) at event-epoll.c:550
---Type <return> to continue, or q <return> to quit---
#8  event_dispatch_epoll_worker (data=0xc9c3f0) at event-epoll.c:608
#9  0x00007f7969c909d1 in start_thread () from /lib64/libpthread.so.0
#10 0x00007f79695fa9dd in clone () from /lib64/libc.so.6

NOTE: This thread has the lock and is doing list_del operations

(gdb) list
71      }
72
73      static inline void
74      list_del (struct list_head *old)
75      {
76              old->prev->next = old->next;
77              old->next->prev = old->prev;
78
79              old->next = (void *)0xbabebabe;
80              old->prev = (void *)0xcafecafe;
(gdb) f 1
#1  glusterd_rpcsvc_notify (rpc=<value optimized out>, xl=0xcb3860, event=<value optimized out>, data=0x7f7940006f00) at glusterd.c:332
332                     list_del (&xprt->list);
(gdb) lisy
Undefined command: "lisy".  Try "help".
(gdb) list
327                     break;
328             }
329             case RPCSVC_EVENT_DISCONNECT:
330             {
331                     pthread_mutex_lock (&priv->xprt_lock);
332                     list_del (&xprt->list);
333                     pthread_mutex_unlock (&priv->xprt_lock);
334                     pmap_registry_remove (this, 0, NULL, GF_PMAP_PORT_NONE, xprt);
335                     break;
336             }
(gdb) list -10
322                     INIT_LIST_HEAD (&xprt->list);
323
324                     pthread_mutex_lock (&priv->xprt_lock);
325                     list_add_tail (&xprt->list, &priv->xprt_list);
326                     pthread_mutex_unlock (&priv->xprt_lock);
327                     break;
328             }
329             case RPCSVC_EVENT_DISCONNECT:
330             {
331                     pthread_mutex_lock (&priv->xprt_lock);
(gdb)
332                     list_del (&xprt->list);
333                     pthread_mutex_unlock (&priv->xprt_lock);
334                     pmap_registry_remove (this, 0, NULL, GF_PMAP_PORT_NONE, xprt);
335                     break;
336             }
337
338             default:
339                     break;
340             }
341

Problem:
Initializing the xprt list outside the lock should be avoided, as I assume that is the cause for the core, and as 2 threads are now processing events, this is causing the problem.

<<<< 2 >>>>

Other information captured above. I think I got the component wrong, please correct as appropriate.