Issue with Ganesha not processing UDP NULL proc requests from AMD
Hi Daniel or Frank, We spoke about this issue on weekly call just over a week ago. I remember Daniel's advice on that call was to dig into the Ganesha core dump and try to extract the communication channel for each fd from the svc_rqst_epoll_loop() calls and verify that the UDP listen socket for NFS is being epoll'd on. I'm not sure however, the data is present in that stack that would actually allow us to make that call. (gdb) bt full #0 0x00007f3c46616eb3 in epoll_wait () from /lib64/libc.so.6 No symbol table info available. #1 0x00007f3c4876f04c in svc_rqst_epoll_loop (sr_rec=0x4ae8c10) at /<redacted>/libntirpc/src/svc_rqst.c:1013 cc = 0x7f3c46d13eb4 <pthread_cond_timedwait@@GLIBC_2.3.2+516> n = 0x0 ts = {tv_sec = 2750901, tv_nsec = 954488941} timeout_ms = 29000 expire_ms = -1544065341 n_events = 32572 __func__ = "svc_rqst_epoll_loop" #2 0x00007f3c4876f199 in svc_rqst_run_task (wpe=0x4ae8c10) at /<redacted>libntirpc/src/svc_rqst.c:1065 sr_rec = 0x4ae8c10 finished = false __func__ = "svc_rqst_run_task" #3 0x00007f3c48777dca in work_pool_thread (arg=0x7f3c300008c0) at /<redacted>/libntirpc/src/work_pool.c:181 wpt = 0x7f3c300008c0 pool = 0x7f3c48993940 <svc_work_pool> have = 0x0 ts = {tv_sec = 1608803814, tv_nsec = 833467718} rc = 0 spawn = false __func__ = "work_pool_thread" #4 0x00007f3c46d0fea5 in start_thread () from /lib64/libpthread.so.0 No symbol table info available. #5 0x00007f3c466168dd in clone () from /lib64/libc.so.6 No symbol table info available. I am assuming that you would need to chenck the xp_type member in the SVCXPRT structure? However, the members of the latter are lost in the stack since during rearm, we obtain the sr_rec as follows: int svc_rqst_rearm_events(SVCXPRT *xprt) { struct rpc_dplx_rec *rec = REC_XPRT(xprt); struct svc_rqst_rec *sr_rec = (struct svc_rqst_rec *)rec->ev_p; Here, ev_p is a pointer and it seems to me we will not be able to obtain rec from *sr_rec with a container_of() kind macro since ev_p is not being referenced. Do you have another way to ascertain if the FDs polled have the UDP descriptor in them? Thanks, Anirban
What I was thinking of was going through the rbtree in svc_xprt_fd and checking the xp_ops in them to see which function set they have. One of them should be the svc_dg_rendezvous* functions, which would be the main UDP listener. It also has pktinfo in xp_pktinfo, which might help. It's xp_fd can be cross referenced with netstat output, and we're primarily interested in it's xp_refcnt field. svc_xprt_fd is a global, so it should be accessible from any stack in ntirpc. Daniel On 1/17/21 7:24 PM, anirban.chalcogen@gmail.com wrote:
Hi Daniel or Frank,
We spoke about this issue on weekly call just over a week ago. I remember Daniel's advice on that call was to dig into the Ganesha core dump and try to extract the communication channel for each fd from the svc_rqst_epoll_loop() calls and verify that the UDP listen socket for NFS is being epoll'd on. I'm not sure however, the data is present in that stack that would actually allow us to make that call.
(gdb) bt full #0 0x00007f3c46616eb3 in epoll_wait () from /lib64/libc.so.6 No symbol table info available. #1 0x00007f3c4876f04c in svc_rqst_epoll_loop (sr_rec=0x4ae8c10) at /<redacted>/libntirpc/src/svc_rqst.c:1013 cc = 0x7f3c46d13eb4 <pthread_cond_timedwait@@GLIBC_2.3.2+516> n = 0x0 ts = {tv_sec = 2750901, tv_nsec = 954488941} timeout_ms = 29000 expire_ms = -1544065341 n_events = 32572 __func__ = "svc_rqst_epoll_loop" #2 0x00007f3c4876f199 in svc_rqst_run_task (wpe=0x4ae8c10) at /<redacted>libntirpc/src/svc_rqst.c:1065 sr_rec = 0x4ae8c10 finished = false __func__ = "svc_rqst_run_task" #3 0x00007f3c48777dca in work_pool_thread (arg=0x7f3c300008c0) at /<redacted>/libntirpc/src/work_pool.c:181 wpt = 0x7f3c300008c0 pool = 0x7f3c48993940 <svc_work_pool> have = 0x0 ts = {tv_sec = 1608803814, tv_nsec = 833467718} rc = 0 spawn = false __func__ = "work_pool_thread" #4 0x00007f3c46d0fea5 in start_thread () from /lib64/libpthread.so.0 No symbol table info available. #5 0x00007f3c466168dd in clone () from /lib64/libc.so.6 No symbol table info available.
I am assuming that you would need to chenck the xp_type member in the SVCXPRT structure? However, the members of the latter are lost in the stack since during rearm, we obtain the sr_rec as follows:
int svc_rqst_rearm_events(SVCXPRT *xprt) { struct rpc_dplx_rec *rec = REC_XPRT(xprt); struct svc_rqst_rec *sr_rec = (struct svc_rqst_rec *)rec->ev_p;
Here, ev_p is a pointer and it seems to me we will not be able to obtain rec from *sr_rec with a container_of() kind macro since ev_p is not being referenced. Do you have another way to ascertain if the FDs polled have the UDP descriptor in them?
Thanks, Anirban _______________________________________________ Devel mailing list -- devel@lists.nfs-ganesha.org To unsubscribe send an email to devel-leave@lists.nfs-ganesha.org
Hi Daniel, I noticed something odd about the /proc/[pid/fdinfo data we obtained at the time we collected the core for ganesha. Basically, if you see here, <pre>190:anon_inode:[eventpoll] pos: 0 flags: 02000002 mnt_id: 10 tfd: 194 events: 40000000 data: c2 tfd: 196 events: 40000019 data: c4 tfd: 198 events: 40000019 data: c6 tfd: 189 events: 2019 data: bd tfd: 200 events: 40000019 data: c8 191:socket:[426759494] pos: 0 flags: 04002 mnt_id: 8 192:socket:[426759495] pos: 0 flags: 04002 mnt_id: 8 193:anon_inode:[eventpoll] pos: 0 flags: 02000002 mnt_id: 10 tfd: 192 events: 2019 data: c0 tfd: 199 events: 40000019 data: c7 tfd: 197 events: 40000019 data: c5 tfd: 195 events: 40000019 data: c3 tfd: 201 events: 40000019 data: c9 194:socket:[426759496] pos: 0 flags: 04002 mnt_id: 8 195:socket:[426759497] pos: 0 flags: 02 mnt_id: 8 </pre> 194 is the UDP socket. Iis is armed to the epoll_fd 190. If you see its event list, it has only the EPOLLONESHOT event tagged to it and no EPOLLIN. Does that mean that somehow we are left not listening of new messages on the UDP socket? Thanks, Anirban
It could very well mean that. I have no idea how it could happen, since we always set events to EPOLLIN | EPOLLONESHOT (or on v3 and later EPOLLOUT | EPOLLONESHOT | EPOLLET), and never set just EPOLLONESHOT. That would indicate a kernel bug to me, I think. Daniel On 1/27/21 10:39 PM, anirban.chalcogen@gmail.com wrote:
Hi Daniel,
I noticed something odd about the /proc/[pid/fdinfo data we obtained at the time we collected the core for ganesha. Basically, if you see here,
<pre>190:anon_inode:[eventpoll] pos: 0 flags: 02000002 mnt_id: 10 tfd: 194 events: 40000000 data: c2 tfd: 196 events: 40000019 data: c4 tfd: 198 events: 40000019 data: c6 tfd: 189 events: 2019 data: bd tfd: 200 events: 40000019 data: c8 191:socket:[426759494] pos: 0 flags: 04002 mnt_id: 8 192:socket:[426759495] pos: 0 flags: 04002 mnt_id: 8 193:anon_inode:[eventpoll] pos: 0 flags: 02000002 mnt_id: 10 tfd: 192 events: 2019 data: c0 tfd: 199 events: 40000019 data: c7 tfd: 197 events: 40000019 data: c5 tfd: 195 events: 40000019 data: c3 tfd: 201 events: 40000019 data: c9 194:socket:[426759496] pos: 0 flags: 04002 mnt_id: 8 195:socket:[426759497] pos: 0 flags: 02 mnt_id: 8 </pre>
194 is the UDP socket. Iis is armed to the epoll_fd 190. If you see its event list, it has only the EPOLLONESHOT event tagged to it and no EPOLLIN. Does that mean that somehow we are left not listening of new messages on the UDP socket?
Thanks, Anirban _______________________________________________ Devel mailing list -- devel@lists.nfs-ganesha.org To unsubscribe send an email to devel-leave@lists.nfs-ganesha.org
I believe that rather than a kernel bug, this is entirely possible if, after we receive an event on the UDP socket, we somehow do not rearm it afterwards. I tested this out with a small program: <pre><font color="#4E9A06">char</font> buf[<font color="#CC0000">1024</font>]; <font color="#4E9A06">int</font> main() <span style="background-color:#34E2E2">{</span> <font color="#4E9A06">struct</font> epoll_event ev, events[MAX_EVENTS]; <font color="#4E9A06">int</font> udp_sock, nfds, epollfd; <font color="#4E9A06">struct</font> sockaddr_in server_addr; <font color="#AF5F00">if</font> ((udp_sock = socket(AF_INET, SOCK_DGRAM, <font color="#CC0000">0</font>)) == -<font color="#CC0000">1</font>) { perror(<font color="#CC0000">"udp_sock: socket"</font>); exit(<font color="#CC0000">EXIT_FAILURE</font>); } epollfd = epoll_create1(<font color="#CC0000">0</font>); <font color="#AF5F00">if</font> (epollfd == -<font color="#CC0000">1</font>) { perror(<font color="#CC0000">"epoll_create1"</font>); exit(<font color="#CC0000">EXIT_FAILURE</font>); } server_addr.sin_family = AF_INET; server_addr.sin_port = htons(<font color="#CC0000">12345</font>); server_addr.sin_addr.s_addr = inet_addr(<font color="#CC0000">"127.0.0.1"</font>); <font color="#AF5F00">if</font> (bind(udp_sock, (<font color="#4E9A06">struct</font> sockaddr*)&server_addr, <font color="#AF5F00">sizeof</font>(server_addr)) < <font color="#CC0000">0</font>) { perror(<font color="#CC0000">"bind"</font>); exit(<font color="#CC0000">EXIT_FAILURE</font>); } ev.events = EPOLLONESHOT | EPOLLIN; ev.data.fd = udp_sock; <font color="#AF5F00">if</font> (epoll_ctl(epollfd, EPOLL_CTL_ADD, udp_sock, &ev) == -<font color="#CC0000">1</font>) { perror(<font color="#CC0000">"epoll_ctl: listen_sock"</font>); exit(<font color="#CC0000">EXIT_FAILURE</font>); } <font color="#AF5F00">for</font> (;;) { <font color="#4E9A06">int</font> n; nfds = epoll_wait(epollfd, events, MAX_EVENTS, -<font color="#CC0000">1</font>); <font color="#AF5F00">if</font> (nfds == -<font color="#CC0000">1</font>) { perror(<font color="#CC0000">"epoll_wait"</font>); exit(<font color="#CC0000">EXIT_FAILURE</font>); } <font color="#AF5F00">for</font> (n = <font color="#CC0000">0</font>; n < nfds; ++n) { <font color="#AF5F00">if</font> (events[n].data.fd == udp_sock) recv(udp_sock, buf, <font color="#CC0000">1024</font>, <font color="#CC0000">0</font>); } } <font color="#AF5F00">return</font> <font color="#CC0000">0</font>; <span style="background-color:#34E2E2">}</span> </pre> So, here I am receiving an event at the udp socket and then I do not rearm it for the next iteration. It appears that after the first message is received, the EPOLLONESHOT flag remains but the rest of them are cleared. To wit, <pre>[anirban@localhost test]$ cat /proc/6265/fdinfo/* pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 02 mnt_id: 7 pos: 0 flags: 02 mnt_id: 10 tfd: 3 events: 40000019 data: 40071000000003 [anirban@localhost test]$ echo "test" | nc -u 127.0.0.1 12345 # Send a message to the UDP socket [anirban@localhost test]$ [anirban@localhost test]$ cat /proc/6265/fdinfo/* pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 02 mnt_id: 7 pos: 0 flags: 02 mnt_id: 10 tfd: 3 events: 40000000 data: 40071000000003 [anirban@localhost test]$</pre> So, unless we unhook and re-hook the udp socket after each event, we might have to figure out why the re-arm is not happening. As an aside, there seems to be a major difference in where the rearm happens between 2.5.3 and 2.7. In 2.5, it is explicitly called in the nfs_rpc_dispatcher_thread, while in 2.7, it is only called from within ntirpc. Thanks, Anirban
Oops, let me resend the source code. It seems copy-as-html caused problems here. #include <stdio.h> #include <stdlib.h> #include <sys/types.h> #include <sys/socket.h> #include <arpa/inet.h> #include <netinet/in.h> #include <sys/epoll.h> #define MAX_EVENTS 10 char buf[1024]; int main() { struct epoll_event ev, events[MAX_EVENTS]; int udp_sock, nfds, epollfd; struct sockaddr_in server_addr; if ((udp_sock = socket(AF_INET, SOCK_DGRAM, 0)) == -1) { perror("udp_sock: socket"); exit(EXIT_FAILURE); } epollfd = epoll_create1(0); if (epollfd == -1) { perror("epoll_create1"); exit(EXIT_FAILURE); } server_addr.sin_family = AF_INET; server_addr.sin_port = htons(12345); server_addr.sin_addr.s_addr = inet_addr("127.0.0.1"); if (bind(udp_sock, (struct sockaddr*)&server_addr, sizeof(server_addr)) < 0) { perror("bind"); exit(EXIT_FAILURE); } ev.events = EPOLLONESHOT | EPOLLIN; ev.data.fd = udp_sock; if (epoll_ctl(epollfd, EPOLL_CTL_ADD, udp_sock, &ev) == -1) { perror("epoll_ctl: listen_sock"); exit(EXIT_FAILURE); } for (;;) { int n; nfds = epoll_wait(epollfd, events, MAX_EVENTS, -1); if (nfds == -1) { perror("epoll_wait"); exit(EXIT_FAILURE); } for (n = 0; n < nfds; ++n) { if (events[n].data.fd == udp_sock) recv(udp_sock, buf, 1024, 0); } } return 0; }
In 1.7, we will always re-arm the UDP socket unless recvmsg() returned an error other than EINTR. And in that case, we'll close the socket. Daniel On 1/28/21 2:07 PM, anirban.chalcogen@gmail.com wrote:
I believe that rather than a kernel bug, this is entirely possible if, after we receive an event on the UDP socket, we somehow do not rearm it afterwards. I tested this out with a small program:
<pre><font color="#4E9A06">char</font> buf[<font color="#CC0000">1024</font>];
<font color="#4E9A06">int</font> main() <span style="background-color:#34E2E2">{</span> <font color="#4E9A06">struct</font> epoll_event ev, events[MAX_EVENTS]; <font color="#4E9A06">int</font> udp_sock, nfds, epollfd; <font color="#4E9A06">struct</font> sockaddr_in server_addr;
<font color="#AF5F00">if</font> ((udp_sock = socket(AF_INET, SOCK_DGRAM, <font color="#CC0000">0</font>)) == -<font color="#CC0000">1</font>) { perror(<font color="#CC0000">"udp_sock: socket"</font>); exit(<font color="#CC0000">EXIT_FAILURE</font>); }
epollfd = epoll_create1(<font color="#CC0000">0</font>); <font color="#AF5F00">if</font> (epollfd == -<font color="#CC0000">1</font>) { perror(<font color="#CC0000">"epoll_create1"</font>); exit(<font color="#CC0000">EXIT_FAILURE</font>); }
server_addr.sin_family = AF_INET; server_addr.sin_port = htons(<font color="#CC0000">12345</font>); server_addr.sin_addr.s_addr = inet_addr(<font color="#CC0000">"127.0.0.1"</font>);
<font color="#AF5F00">if</font> (bind(udp_sock, (<font color="#4E9A06">struct</font> sockaddr*)&server_addr, <font color="#AF5F00">sizeof</font>(server_addr)) < <font color="#CC0000">0</font>) { perror(<font color="#CC0000">"bind"</font>); exit(<font color="#CC0000">EXIT_FAILURE</font>); }
ev.events = EPOLLONESHOT | EPOLLIN; ev.data.fd = udp_sock; <font color="#AF5F00">if</font> (epoll_ctl(epollfd, EPOLL_CTL_ADD, udp_sock, &ev) == -<font color="#CC0000">1</font>) { perror(<font color="#CC0000">"epoll_ctl: listen_sock"</font>); exit(<font color="#CC0000">EXIT_FAILURE</font>); }
<font color="#AF5F00">for</font> (;;) { <font color="#4E9A06">int</font> n;
nfds = epoll_wait(epollfd, events, MAX_EVENTS, -<font color="#CC0000">1</font>); <font color="#AF5F00">if</font> (nfds == -<font color="#CC0000">1</font>) { perror(<font color="#CC0000">"epoll_wait"</font>); exit(<font color="#CC0000">EXIT_FAILURE</font>); }
<font color="#AF5F00">for</font> (n = <font color="#CC0000">0</font>; n < nfds; ++n) { <font color="#AF5F00">if</font> (events[n].data.fd == udp_sock) recv(udp_sock, buf, <font color="#CC0000">1024</font>, <font color="#CC0000">0</font>); } } <font color="#AF5F00">return</font> <font color="#CC0000">0</font>; <span style="background-color:#34E2E2">}</span> </pre>
So, here I am receiving an event at the udp socket and then I do not rearm it for the next iteration. It appears that after the first message is received, the EPOLLONESHOT flag remains but the rest of them are cleared. To wit,
<pre>[anirban@localhost test]$ cat /proc/6265/fdinfo/* pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 02 mnt_id: 7 pos: 0 flags: 02 mnt_id: 10 tfd: 3 events: 40000019 data: 40071000000003 [anirban@localhost test]$ echo "test" | nc -u 127.0.0.1 12345 # Send a message to the UDP socket [anirban@localhost test]$ [anirban@localhost test]$ cat /proc/6265/fdinfo/* pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 0100002 mnt_id: 23 pos: 0 flags: 02 mnt_id: 7 pos: 0 flags: 02 mnt_id: 10 tfd: 3 events: 40000000 data: 40071000000003 [anirban@localhost test]$</pre>
So, unless we unhook and re-hook the udp socket after each event, we might have to figure out why the re-arm is not happening. As an aside, there seems to be a major difference in where the rearm happens between 2.5.3 and 2.7. In 2.5, it is explicitly called in the nfs_rpc_dispatcher_thread, while in 2.7, it is only called from within ntirpc.
Thanks, Anirban _______________________________________________ Devel mailing list -- devel@lists.nfs-ganesha.org To unsubscribe send an email to devel-leave@lists.nfs-ganesha.org
And, I think I have it. It seems there are rather simple ways to sabotage the UDP link in Ganesha 2.7 by sending spurious messages. Look at the following: static enum xprt_stat svc_dg_rendezvous(SVCXPRT *xprt) { /* ... */ rlen = recvmsg(newxprt->xp_fd, mesgp, 0); if (sp->sa_family == (sa_family_t) 0xffff) { svc_dg_xprt_free(su); return (XPRT_DIED); } if (rlen == -1 && errno == EINTR) goto again; if (rlen == -1 || (rlen < (ssize_t) (4 * sizeof(u_int32_t)))) { svc_dg_xprt_free(su); return (XPRT_DIED); } if (unlikely(svc_rqst_rearm_events(xprt))) { I was able to reproduce the issue simply by sending an UDP message less than 16 bytes long. Also, to note, the svc_dg_xprt_free() does not actually close the UDP fd, maybe because it is still added to an epoll_fd() and close() returns an error (guessing, haven't verified yet). IMO, if we get a spurious message, especially given that it's UDP, we should simply ignore it and move on rather than tear down the whole channel? Thanks, Anirban P.s. In 2.5.3, from what I understand, we don't actually do an XPRT_DIED and even for messages < 16 bytes, we always rearm afterwards which is why customer only saw the problem after upgrading to 2.7.
Good catch. Comments inline. On 2/7/21 4:20 PM, anirban.chalcogen@gmail.com wrote:
And, I think I have it. It seems there are rather simple ways to sabotage the UDP link in Ganesha 2.7 by sending spurious messages. Look at the following:
static enum xprt_stat svc_dg_rendezvous(SVCXPRT *xprt) { /* ... */
rlen = recvmsg(newxprt->xp_fd, mesgp, 0);
if (sp->sa_family == (sa_family_t) 0xffff) { svc_dg_xprt_free(su); return (XPRT_DIED); }
if (rlen == -1 && errno == EINTR) goto again; if (rlen == -1 || (rlen < (ssize_t) (4 * sizeof(u_int32_t)))) { svc_dg_xprt_free(su); return (XPRT_DIED); }
if (unlikely(svc_rqst_rearm_events(xprt))) {
I was able to reproduce the issue simply by sending an UDP message less than 16 bytes long. Also, to note, the svc_dg_xprt_free() does not actually close the UDP fd, maybe because it is still added to an epoll_fd() and close() returns an error (guessing, haven't verified yet).
Actually, it looks like it doesn't destroy the xprt at all, just frees it. So it's presumably dangling in the trees, and pointing to invalid memory. This is bad, and would eventually cause memory corruption or segfault, I think.
IMO, if we get a spurious message, especially given that it's UDP, we should simply ignore it and move on rather than tear down the whole channel?
This seems plausible. We should explore this. Daniel
Just created a pull request on ntirpc with the changes at https://github.com/nfs-ganesha/ntirpc/pull/226. It seems just moving the check for msg len below the rearm ought to do the trick and it did when I tested it but let me know if you think it doesn't play nice with anything else in the code such as refcnt. Thanks, Anirban
participants (2)
-
anirban.chalcogen＠gmail.com -
Daniel Gryniewicz