6:24 p.m.
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@(a)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
8 a.m.
New subject: Issue with Ganesha not processing UDP NULL proc requests from AMD
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(a)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@(a)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(a)lists.nfs-ganesha.org
To unsubscribe send an email to devel-leave(a)lists.nfs-ganesha.org
9:39 p.m.
New subject: Issue with Ganesha not processing UDP NULL proc requests from AMD
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
8:22 a.m.
New subject: Issue with Ganesha not processing UDP NULL proc requests from AMD
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(a)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(a)lists.nfs-ganesha.org
To unsubscribe send an email to devel-leave(a)lists.nfs-ganesha.org
1:07 p.m.
New subject: Issue with Ganesha not processing UDP NULL proc requests from AMD
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
1:14 p.m.
New subject: Issue with Ganesha not processing UDP NULL proc requests from AMD
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;
}
8:38 a.m.
New subject: Issue with Ganesha not processing UDP NULL proc requests from AMD
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(a)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(a)lists.nfs-ganesha.org
To unsubscribe send an email to devel-leave(a)lists.nfs-ganesha.org
3:20 p.m.
New subject: Issue with Ganesha not processing UDP NULL proc requests from AMD
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.
8:46 a.m.
New subject: Issue with Ganesha not processing UDP NULL proc requests from AMD
Good catch. Comments inline.
On 2/7/21 4:20 PM, anirban.chalcogen(a)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
9:15 p.m.
New subject: Issue with Ganesha not processing UDP NULL proc requests from AMD
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
1155
days inactive
1187
days old
9 comments
2 participants
participants (2)
-
anirban.chalcogen＠gmail.com -
Daniel Gryniewicz