| Message ID | 20210825184745.2680830-1-fallentree@fb.com (mailing list archive) |
|---|---|
| State | Accepted |
| Delegated to: | BPF |
| Headers | show |
| Series | [bpf-next] selftests/bpf: reduce more flakyness in sockmap_listen | expand |
On Wed, Aug 25, 2021 at 2:07 PM Yucong Sun <fallentree@fb.com> wrote: > > This patch adds similar retry logic to more places where read() is used, to > reduce flakyness in slow CI environment. > > Signed-off-by: Yucong Sun <fallentree@fb.com> > --- > .../selftests/bpf/prog_tests/sockmap_listen.c | 19 ++++++++++++++++--- > 1 file changed, 16 insertions(+), 3 deletions(-) > > diff --git a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > index 6a5df28f9a3d..5c5979046523 100644 > --- a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > +++ b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > @@ -949,6 +949,7 @@ static void redir_to_connected(int family, int sotype, int sock_mapfd, > int err, n; > u32 key; > char b; > + int retries = 100; > > zero_verdict_count(verd_mapfd); > > @@ -1001,10 +1002,15 @@ static void redir_to_connected(int family, int sotype, int sock_mapfd, > goto close_peer1; > if (pass != 1) > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > - > +again: > n = read(c0, &b, 1); > - if (n < 0) > + if (n < 0) { > + if (errno == EAGAIN && retries--) { TCP was fixed differently in commit 30b4cb36b111 ("selftests/bpf: Fix spurious failures in accept due to EAGAIN"). Would a similar approach work here?
> TCP was fixed differently in > commit 30b4cb36b111 ("selftests/bpf: Fix spurious failures in accept > due to EAGAIN"). > Would a similar approach work here? > I think so, will send a update patch to switch all read to poll_read() instead.
Reporting back: I tried a select() based approach, (as attached below)
but unfortunately it doesn't seem to work. During testing, I am
always getting full timeout errors as the socket never seems to become
ready to read(). My guess is that this has something to do with the
sockets being created through sockpair() , but I am unable to confirm.
On the other hand, the previous patch approach works perfectly fine, I
would still like to request to apply that instead.
diff --git a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c
b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c
index 5c5979046523..247e8b7a6911 100644
--- a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c
+++ b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c
@@ -949,7 +949,6 @@ static void redir_to_connected(int family, int
sotype, int sock_mapfd,
int err, n;
u32 key;
char b;
- int retries = 100;
zero_verdict_count(verd_mapfd);
@@ -1002,15 +1001,12 @@ static void redir_to_connected(int family, int
sotype, int sock_mapfd,
goto close_peer1;
if (pass != 1)
FAIL("%s: want pass count 1, have %d", log_prefix, pass);
-again:
+
+ if (poll_read(c0, IO_TIMEOUT_SEC))
+ FAIL_ERRNO("%s: read", log_prefix);
n = read(c0, &b, 1);
- if (n < 0) {
- if (errno == EAGAIN && retries--) {
- usleep(1000);
- goto again;
- }
+ if (n < 0)
FAIL_ERRNO("%s: read", log_prefix);
- }
if (n == 0)
FAIL("%s: incomplete read", log_prefix);
@@ -1571,7 +1567,6 @@ static void unix_redir_to_connected(int sotype,
int sock_mapfd,
const char *log_prefix = redir_mode_str(mode);
int c0, c1, p0, p1;
unsigned int pass;
- int retries = 100;
int err, n;
int sfd[2];
u32 key;
@@ -1606,15 +1601,11 @@ static void unix_redir_to_connected(int
sotype, int sock_mapfd,
if (pass != 1)
FAIL("%s: want pass count 1, have %d", log_prefix, pass);
-again:
+ if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC))
+ FAIL_ERRNO("%s: read", log_prefix);
n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1);
- if (n < 0) {
- if (errno == EAGAIN && retries--) {
- usleep(1000);
- goto again;
- }
+ if (n < 0)
FAIL_ERRNO("%s: read", log_prefix);
- }
if (n == 0)
FAIL("%s: incomplete read", log_prefix);
@@ -1748,7 +1739,6 @@ static void udp_redir_to_connected(int family,
int sock_mapfd, int verd_mapfd,
const char *log_prefix = redir_mode_str(mode);
int c0, c1, p0, p1;
unsigned int pass;
- int retries = 100;
int err, n;
u32 key;
char b;
@@ -1781,15 +1771,11 @@ static void udp_redir_to_connected(int family,
int sock_mapfd, int verd_mapfd,
if (pass != 1)
FAIL("%s: want pass count 1, have %d", log_prefix, pass);
-again:
+ if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC * 10))
+ FAIL_ERRNO("%s: read", log_prefix);
n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1);
- if (n < 0) {
- if (errno == EAGAIN && retries--) {
- usleep(1000);
- goto again;
- }
+ if (n < 0)
FAIL_ERRNO("%s: read", log_prefix);
- }
if (n == 0)
FAIL("%s: incomplete read", log_prefix);
@@ -1841,7 +1827,6 @@ static void inet_unix_redir_to_connected(int
family, int type, int sock_mapfd,
const char *log_prefix = redir_mode_str(mode);
int c0, c1, p0, p1;
unsigned int pass;
- int retries = 100;
int err, n;
int sfd[2];
u32 key;
@@ -1876,15 +1861,11 @@ static void inet_unix_redir_to_connected(int
family, int type, int sock_mapfd,
if (pass != 1)
FAIL("%s: want pass count 1, have %d", log_prefix, pass);
-again:
+ if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC))
+ FAIL_ERRNO("%s: read", log_prefix);
n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1);
- if (n < 0) {
- if (errno == EAGAIN && retries--) {
- usleep(1000);
- goto again;
- }
+ if (n < 0)
FAIL_ERRNO("%s: read", log_prefix);
- }
if (n == 0)
FAIL("%s: incomplete read", log_prefix);
@@ -1932,7 +1913,6 @@ static void unix_inet_redir_to_connected(int
family, int type, int sock_mapfd,
int sfd[2];
u32 key;
char b;
- int retries = 100;
zero_verdict_count(verd_mapfd);
@@ -1963,15 +1943,11 @@ static void unix_inet_redir_to_connected(int
family, int type, int sock_mapfd,
if (pass != 1)
FAIL("%s: want pass count 1, have %d", log_prefix, pass);
-again:
+ if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC))
+ FAIL_ERRNO("%s: read", log_prefix);
n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1);
- if (n < 0) {
- if (errno == EAGAIN && retries--) {
- usleep(1000);
- goto again;
- }
+ if (n < 0)
FAIL_ERRNO("%s: read", log_prefix);
- }
if (n == 0)
FAIL("%s: incomplete read", log_prefix);
On Thu, Aug 26, 2021 at 11:18 AM sunyucong@gmail.com <sunyucong@gmail.com> wrote: > > Reporting back: I tried a select() based approach, (as attached below) > but unfortunately it doesn't seem to work. During testing, I am > always getting full timeout errors as the socket never seems to become > ready to read(). My guess is that this has something to do with the > sockets being created through sockpair() , but I am unable to confirm. > > On the other hand, the previous patch approach works perfectly fine, I > would still like to request to apply that instead. Ok. Applied your earlier patch, but it's a short term workaround. select() should work for af_unix. I suspect something got broken with the redirect. Cong, Jiang, could you please take a look ? > > diff --git a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > index 5c5979046523..247e8b7a6911 100644 > --- a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > +++ b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > @@ -949,7 +949,6 @@ static void redir_to_connected(int family, int > sotype, int sock_mapfd, > int err, n; > u32 key; > char b; > - int retries = 100; > > zero_verdict_count(verd_mapfd); > > @@ -1002,15 +1001,12 @@ static void redir_to_connected(int family, int > sotype, int sock_mapfd, > goto close_peer1; > if (pass != 1) > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > -again: > + > + if (poll_read(c0, IO_TIMEOUT_SEC)) > + FAIL_ERRNO("%s: read", log_prefix); > n = read(c0, &b, 1); > - if (n < 0) { > - if (errno == EAGAIN && retries--) { > - usleep(1000); > - goto again; > - } > + if (n < 0) > FAIL_ERRNO("%s: read", log_prefix); > - } > if (n == 0) > FAIL("%s: incomplete read", log_prefix); > > @@ -1571,7 +1567,6 @@ static void unix_redir_to_connected(int sotype, > int sock_mapfd, > const char *log_prefix = redir_mode_str(mode); > int c0, c1, p0, p1; > unsigned int pass; > - int retries = 100; > int err, n; > int sfd[2]; > u32 key; > @@ -1606,15 +1601,11 @@ static void unix_redir_to_connected(int > sotype, int sock_mapfd, > if (pass != 1) > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > -again: > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC)) > + FAIL_ERRNO("%s: read", log_prefix); > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > - if (n < 0) { > - if (errno == EAGAIN && retries--) { > - usleep(1000); > - goto again; > - } > + if (n < 0) > FAIL_ERRNO("%s: read", log_prefix); > - } > if (n == 0) > FAIL("%s: incomplete read", log_prefix); > > @@ -1748,7 +1739,6 @@ static void udp_redir_to_connected(int family, > int sock_mapfd, int verd_mapfd, > const char *log_prefix = redir_mode_str(mode); > int c0, c1, p0, p1; > unsigned int pass; > - int retries = 100; > int err, n; > u32 key; > char b; > @@ -1781,15 +1771,11 @@ static void udp_redir_to_connected(int family, > int sock_mapfd, int verd_mapfd, > if (pass != 1) > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > -again: > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC * 10)) > + FAIL_ERRNO("%s: read", log_prefix); > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > - if (n < 0) { > - if (errno == EAGAIN && retries--) { > - usleep(1000); > - goto again; > - } > + if (n < 0) > FAIL_ERRNO("%s: read", log_prefix); > - } > if (n == 0) > FAIL("%s: incomplete read", log_prefix); > > @@ -1841,7 +1827,6 @@ static void inet_unix_redir_to_connected(int > family, int type, int sock_mapfd, > const char *log_prefix = redir_mode_str(mode); > int c0, c1, p0, p1; > unsigned int pass; > - int retries = 100; > int err, n; > int sfd[2]; > u32 key; > @@ -1876,15 +1861,11 @@ static void inet_unix_redir_to_connected(int > family, int type, int sock_mapfd, > if (pass != 1) > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > -again: > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC)) > + FAIL_ERRNO("%s: read", log_prefix); > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > - if (n < 0) { > - if (errno == EAGAIN && retries--) { > - usleep(1000); > - goto again; > - } > + if (n < 0) > FAIL_ERRNO("%s: read", log_prefix); > - } > if (n == 0) > FAIL("%s: incomplete read", log_prefix); > > @@ -1932,7 +1913,6 @@ static void unix_inet_redir_to_connected(int > family, int type, int sock_mapfd, > int sfd[2]; > u32 key; > char b; > - int retries = 100; > > zero_verdict_count(verd_mapfd); > > @@ -1963,15 +1943,11 @@ static void unix_inet_redir_to_connected(int > family, int type, int sock_mapfd, > if (pass != 1) > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > -again: > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC)) > + FAIL_ERRNO("%s: read", log_prefix); > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > - if (n < 0) { > - if (errno == EAGAIN && retries--) { > - usleep(1000); > - goto again; > - } > + if (n < 0) > FAIL_ERRNO("%s: read", log_prefix); > - } > if (n == 0) > FAIL("%s: incomplete read", log_prefix);
I don't think it's AF_UNIX alone, I'm getting select() timeout for all family: ./test_progs:udp_redir_to_connected:1775: ingress: read: Timer expired udp_redir_to_connected:FAIL:1775 #120/36 sockmap_listen/sockmap IPv4 test_udp_redir:FAIL ./test_progs:inet_unix_redir_to_connected:1865: ingress: read: Timer expired inet_unix_redir_to_connected:FAIL:1865 ./test_progs:inet_unix_redir_to_connected:1865: ingress: read: Timer expired inet_unix_redir_to_connected:FAIL:1865 ./test_progs:unix_inet_redir_to_connected:1947: ingress: read: Timer expired unix_inet_redir_to_connected:FAIL:1947 ./test_progs:unix_inet_redir_to_connected:1947: ingress: read: Timer expired unix_inet_redir_to_connected:FAIL:1947 ... ./test_progs:udp_redir_to_connected:1775: ingress: read: Timer expired udp_redir_to_connected:FAIL:1775 #120/73 sockmap_listen/sockmap IPv6 test_udp_redir:FAIL ./test_progs:inet_unix_redir_to_connected:1865: ingress: read: Timer expired inet_unix_redir_to_connected:FAIL:1865 ./test_progs:inet_unix_redir_to_connected:1865: ingress: read: Timer expired inet_unix_redir_to_connected:FAIL:1865 ./test_progs:unix_inet_redir_to_connected:1947: ingress: read: Timer expired unix_inet_redir_to_connected:FAIL:1947 ./test_progs:unix_inet_redir_to_connected:1947: ingress: read: Timer expired unix_inet_redir_to_connected:FAIL:1947 #120/74 sockmap_listen/sockmap IPv6 test_udp_unix_redir:FAIL ./test_progs:unix_redir_to_connected:1605: ingress: read: Timer expired unix_redir_to_connected:FAIL:1605 #120/75 sockmap_listen/sockmap Unix test_unix_redir:FAIL ./test_progs:unix_redir_to_connected:1605: ingress: read: Timer expired unix_redir_to_connected:FAIL:1605 On Thu, Aug 26, 2021 at 12:07 PM Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote: > > On Thu, Aug 26, 2021 at 11:18 AM sunyucong@gmail.com > <sunyucong@gmail.com> wrote: > > > > Reporting back: I tried a select() based approach, (as attached below) > > but unfortunately it doesn't seem to work. During testing, I am > > always getting full timeout errors as the socket never seems to become > > ready to read(). My guess is that this has something to do with the > > sockets being created through sockpair() , but I am unable to confirm. > > > > On the other hand, the previous patch approach works perfectly fine, I > > would still like to request to apply that instead. > > Ok. Applied your earlier patch, but it's a short term workaround. > select() should work for af_unix. > I suspect something got broken with the redirect. > Cong, Jiang, > could you please take a look ? > > > > > diff --git a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > > b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > > index 5c5979046523..247e8b7a6911 100644 > > --- a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > > +++ b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > > @@ -949,7 +949,6 @@ static void redir_to_connected(int family, int > > sotype, int sock_mapfd, > > int err, n; > > u32 key; > > char b; > > - int retries = 100; > > > > zero_verdict_count(verd_mapfd); > > > > @@ -1002,15 +1001,12 @@ static void redir_to_connected(int family, int > > sotype, int sock_mapfd, > > goto close_peer1; > > if (pass != 1) > > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > -again: > > + > > + if (poll_read(c0, IO_TIMEOUT_SEC)) > > + FAIL_ERRNO("%s: read", log_prefix); > > n = read(c0, &b, 1); > > - if (n < 0) { > > - if (errno == EAGAIN && retries--) { > > - usleep(1000); > > - goto again; > > - } > > + if (n < 0) > > FAIL_ERRNO("%s: read", log_prefix); > > - } > > if (n == 0) > > FAIL("%s: incomplete read", log_prefix); > > > > @@ -1571,7 +1567,6 @@ static void unix_redir_to_connected(int sotype, > > int sock_mapfd, > > const char *log_prefix = redir_mode_str(mode); > > int c0, c1, p0, p1; > > unsigned int pass; > > - int retries = 100; > > int err, n; > > int sfd[2]; > > u32 key; > > @@ -1606,15 +1601,11 @@ static void unix_redir_to_connected(int > > sotype, int sock_mapfd, > > if (pass != 1) > > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > > > -again: > > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC)) > > + FAIL_ERRNO("%s: read", log_prefix); > > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > > - if (n < 0) { > > - if (errno == EAGAIN && retries--) { > > - usleep(1000); > > - goto again; > > - } > > + if (n < 0) > > FAIL_ERRNO("%s: read", log_prefix); > > - } > > if (n == 0) > > FAIL("%s: incomplete read", log_prefix); > > > > @@ -1748,7 +1739,6 @@ static void udp_redir_to_connected(int family, > > int sock_mapfd, int verd_mapfd, > > const char *log_prefix = redir_mode_str(mode); > > int c0, c1, p0, p1; > > unsigned int pass; > > - int retries = 100; > > int err, n; > > u32 key; > > char b; > > @@ -1781,15 +1771,11 @@ static void udp_redir_to_connected(int family, > > int sock_mapfd, int verd_mapfd, > > if (pass != 1) > > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > > > -again: > > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC * 10)) > > + FAIL_ERRNO("%s: read", log_prefix); > > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > > - if (n < 0) { > > - if (errno == EAGAIN && retries--) { > > - usleep(1000); > > - goto again; > > - } > > + if (n < 0) > > FAIL_ERRNO("%s: read", log_prefix); > > - } > > if (n == 0) > > FAIL("%s: incomplete read", log_prefix); > > > > @@ -1841,7 +1827,6 @@ static void inet_unix_redir_to_connected(int > > family, int type, int sock_mapfd, > > const char *log_prefix = redir_mode_str(mode); > > int c0, c1, p0, p1; > > unsigned int pass; > > - int retries = 100; > > int err, n; > > int sfd[2]; > > u32 key; > > @@ -1876,15 +1861,11 @@ static void inet_unix_redir_to_connected(int > > family, int type, int sock_mapfd, > > if (pass != 1) > > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > > > -again: > > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC)) > > + FAIL_ERRNO("%s: read", log_prefix); > > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > > - if (n < 0) { > > - if (errno == EAGAIN && retries--) { > > - usleep(1000); > > - goto again; > > - } > > + if (n < 0) > > FAIL_ERRNO("%s: read", log_prefix); > > - } > > if (n == 0) > > FAIL("%s: incomplete read", log_prefix); > > > > @@ -1932,7 +1913,6 @@ static void unix_inet_redir_to_connected(int > > family, int type, int sock_mapfd, > > int sfd[2]; > > u32 key; > > char b; > > - int retries = 100; > > > > zero_verdict_count(verd_mapfd); > > > > @@ -1963,15 +1943,11 @@ static void unix_inet_redir_to_connected(int > > family, int type, int sock_mapfd, > > if (pass != 1) > > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > > > -again: > > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC)) > > + FAIL_ERRNO("%s: read", log_prefix); > > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > > - if (n < 0) { > > - if (errno == EAGAIN && retries--) { > > - usleep(1000); > > - goto again; > > - } > > + if (n < 0) > > FAIL_ERRNO("%s: read", log_prefix); > > - } > > if (n == 0) > > FAIL("%s: incomplete read", log_prefix);
On Thu, Aug 26, 2021 at 12:24 PM sunyucong@gmail.com <sunyucong@gmail.com> wrote: > > I don't think it's AF_UNIX alone, I'm getting select() timeout for all family: > > ./test_progs:udp_redir_to_connected:1775: ingress: read: Timer expired > udp_redir_to_connected:FAIL:1775 > #120/36 sockmap_listen/sockmap IPv4 test_udp_redir:FAIL > ./test_progs:inet_unix_redir_to_connected:1865: ingress: read: Timer expired > inet_unix_redir_to_connected:FAIL:1865 That's something different. It's ETIME and not EAGAIN. Do you see IO_TIMEOUT_SEC==30 seconds elapsed between these lines? No matter how slow the qemu setup is, the test shouldn't wait that long. > ./test_progs:inet_unix_redir_to_connected:1865: ingress: read: Timer expired > inet_unix_redir_to_connected:FAIL:1865 > ./test_progs:unix_inet_redir_to_connected:1947: ingress: read: Timer expired > unix_inet_redir_to_connected:FAIL:1947 > ./test_progs:unix_inet_redir_to_connected:1947: ingress: read: Timer expired > unix_inet_redir_to_connected:FAIL:1947 > ... > ./test_progs:udp_redir_to_connected:1775: ingress: read: Timer expired > udp_redir_to_connected:FAIL:1775 > #120/73 sockmap_listen/sockmap IPv6 test_udp_redir:FAIL > ./test_progs:inet_unix_redir_to_connected:1865: ingress: read: Timer expired > inet_unix_redir_to_connected:FAIL:1865 > ./test_progs:inet_unix_redir_to_connected:1865: ingress: read: Timer expired > inet_unix_redir_to_connected:FAIL:1865 > ./test_progs:unix_inet_redir_to_connected:1947: ingress: read: Timer expired > unix_inet_redir_to_connected:FAIL:1947 > ./test_progs:unix_inet_redir_to_connected:1947: ingress: read: Timer expired > unix_inet_redir_to_connected:FAIL:1947 > #120/74 sockmap_listen/sockmap IPv6 test_udp_unix_redir:FAIL > ./test_progs:unix_redir_to_connected:1605: ingress: read: Timer expired > unix_redir_to_connected:FAIL:1605 > #120/75 sockmap_listen/sockmap Unix test_unix_redir:FAIL > ./test_progs:unix_redir_to_connected:1605: ingress: read: Timer expired > unix_redir_to_connected:FAIL:1605 > > On Thu, Aug 26, 2021 at 12:07 PM Alexei Starovoitov > <alexei.starovoitov@gmail.com> wrote: > > > > On Thu, Aug 26, 2021 at 11:18 AM sunyucong@gmail.com > > <sunyucong@gmail.com> wrote: > > > > > > Reporting back: I tried a select() based approach, (as attached below) > > > but unfortunately it doesn't seem to work. During testing, I am > > > always getting full timeout errors as the socket never seems to become > > > ready to read(). My guess is that this has something to do with the > > > sockets being created through sockpair() , but I am unable to confirm. > > > > > > On the other hand, the previous patch approach works perfectly fine, I > > > would still like to request to apply that instead. > > > > Ok. Applied your earlier patch, but it's a short term workaround. > > select() should work for af_unix. > > I suspect something got broken with the redirect. > > Cong, Jiang, > > could you please take a look ? > > > > > > > > diff --git a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > > > b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > > > index 5c5979046523..247e8b7a6911 100644 > > > --- a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > > > +++ b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c > > > @@ -949,7 +949,6 @@ static void redir_to_connected(int family, int > > > sotype, int sock_mapfd, > > > int err, n; > > > u32 key; > > > char b; > > > - int retries = 100; > > > > > > zero_verdict_count(verd_mapfd); > > > > > > @@ -1002,15 +1001,12 @@ static void redir_to_connected(int family, int > > > sotype, int sock_mapfd, > > > goto close_peer1; > > > if (pass != 1) > > > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > > -again: > > > + > > > + if (poll_read(c0, IO_TIMEOUT_SEC)) > > > + FAIL_ERRNO("%s: read", log_prefix); > > > n = read(c0, &b, 1); > > > - if (n < 0) { > > > - if (errno == EAGAIN && retries--) { > > > - usleep(1000); > > > - goto again; > > > - } > > > + if (n < 0) > > > FAIL_ERRNO("%s: read", log_prefix); > > > - } > > > if (n == 0) > > > FAIL("%s: incomplete read", log_prefix); > > > > > > @@ -1571,7 +1567,6 @@ static void unix_redir_to_connected(int sotype, > > > int sock_mapfd, > > > const char *log_prefix = redir_mode_str(mode); > > > int c0, c1, p0, p1; > > > unsigned int pass; > > > - int retries = 100; > > > int err, n; > > > int sfd[2]; > > > u32 key; > > > @@ -1606,15 +1601,11 @@ static void unix_redir_to_connected(int > > > sotype, int sock_mapfd, > > > if (pass != 1) > > > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > > > > > -again: > > > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC)) > > > + FAIL_ERRNO("%s: read", log_prefix); > > > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > > > - if (n < 0) { > > > - if (errno == EAGAIN && retries--) { > > > - usleep(1000); > > > - goto again; > > > - } > > > + if (n < 0) > > > FAIL_ERRNO("%s: read", log_prefix); > > > - } > > > if (n == 0) > > > FAIL("%s: incomplete read", log_prefix); > > > > > > @@ -1748,7 +1739,6 @@ static void udp_redir_to_connected(int family, > > > int sock_mapfd, int verd_mapfd, > > > const char *log_prefix = redir_mode_str(mode); > > > int c0, c1, p0, p1; > > > unsigned int pass; > > > - int retries = 100; > > > int err, n; > > > u32 key; > > > char b; > > > @@ -1781,15 +1771,11 @@ static void udp_redir_to_connected(int family, > > > int sock_mapfd, int verd_mapfd, > > > if (pass != 1) > > > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > > > > > -again: > > > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC * 10)) > > > + FAIL_ERRNO("%s: read", log_prefix); > > > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > > > - if (n < 0) { > > > - if (errno == EAGAIN && retries--) { > > > - usleep(1000); > > > - goto again; > > > - } > > > + if (n < 0) > > > FAIL_ERRNO("%s: read", log_prefix); > > > - } > > > if (n == 0) > > > FAIL("%s: incomplete read", log_prefix); > > > > > > @@ -1841,7 +1827,6 @@ static void inet_unix_redir_to_connected(int > > > family, int type, int sock_mapfd, > > > const char *log_prefix = redir_mode_str(mode); > > > int c0, c1, p0, p1; > > > unsigned int pass; > > > - int retries = 100; > > > int err, n; > > > int sfd[2]; > > > u32 key; > > > @@ -1876,15 +1861,11 @@ static void inet_unix_redir_to_connected(int > > > family, int type, int sock_mapfd, > > > if (pass != 1) > > > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > > > > > -again: > > > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC)) > > > + FAIL_ERRNO("%s: read", log_prefix); > > > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > > > - if (n < 0) { > > > - if (errno == EAGAIN && retries--) { > > > - usleep(1000); > > > - goto again; > > > - } > > > + if (n < 0) > > > FAIL_ERRNO("%s: read", log_prefix); > > > - } > > > if (n == 0) > > > FAIL("%s: incomplete read", log_prefix); > > > > > > @@ -1932,7 +1913,6 @@ static void unix_inet_redir_to_connected(int > > > family, int type, int sock_mapfd, > > > int sfd[2]; > > > u32 key; > > > char b; > > > - int retries = 100; > > > > > > zero_verdict_count(verd_mapfd); > > > > > > @@ -1963,15 +1943,11 @@ static void unix_inet_redir_to_connected(int > > > family, int type, int sock_mapfd, > > > if (pass != 1) > > > FAIL("%s: want pass count 1, have %d", log_prefix, pass); > > > > > > -again: > > > + if (poll_read(mode == REDIR_INGRESS ? p0 : c0, IO_TIMEOUT_SEC)) > > > + FAIL_ERRNO("%s: read", log_prefix); > > > n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); > > > - if (n < 0) { > > > - if (errno == EAGAIN && retries--) { > > > - usleep(1000); > > > - goto again; > > > - } > > > + if (n < 0) > > > FAIL_ERRNO("%s: read", log_prefix); > > > - } > > > if (n == 0) > > > FAIL("%s: incomplete read", log_prefix);
On Thu, Aug 26, 2021 at 2:05 PM Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote: > > On Thu, Aug 26, 2021 at 12:24 PM sunyucong@gmail.com > <sunyucong@gmail.com> wrote: > > > > I don't think it's AF_UNIX alone, I'm getting select() timeout for all family: > > > > ./test_progs:udp_redir_to_connected:1775: ingress: read: Timer expired > > udp_redir_to_connected:FAIL:1775 > > #120/36 sockmap_listen/sockmap IPv4 test_udp_redir:FAIL > > ./test_progs:inet_unix_redir_to_connected:1865: ingress: read: Timer expired > > inet_unix_redir_to_connected:FAIL:1865 > > That's something different. It's ETIME and not EAGAIN. > Do you see IO_TIMEOUT_SEC==30 seconds elapsed between these lines? > No matter how slow the qemu setup is, the test shouldn't wait that long. Yes, I do see 30s passes before failure, failure code is ETIME because it was set in poll_read() function.
On Thu, Aug 26, 2021 at 12:08 PM Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote: > > On Thu, Aug 26, 2021 at 11:18 AM sunyucong@gmail.com > <sunyucong@gmail.com> wrote: > > > > Reporting back: I tried a select() based approach, (as attached below) > > but unfortunately it doesn't seem to work. During testing, I am > > always getting full timeout errors as the socket never seems to become > > ready to read(). My guess is that this has something to do with the > > sockets being created through sockpair() , but I am unable to confirm. > > > > On the other hand, the previous patch approach works perfectly fine, I > > would still like to request to apply that instead. > > Ok. Applied your earlier patch, but it's a short term workaround. > select() should work for af_unix. > I suspect something got broken with the redirect. > Cong, Jiang, > could you please take a look ? Like I mentioned before, I suspect there is some delay in one of the queues on the way or there is a worker wakeup latency. I will try adding some tracepoints to see if I can capture it. Thanks.
On Tue, Aug 31, 2021 at 12:33 PM Cong Wang <xiyou.wangcong@gmail.com> wrote: > Like I mentioned before, I suspect there is some delay in one of > the queues on the way or there is a worker wakeup latency. > I will try adding some tracepoints to see if I can capture it. > I tried to revert this patch locally to reproduce the EAGAIN failure, but even after repeating the sockmap_listen test hundreds of times, I didn't see any failure here. If you are still interested in this issue, I'd suggest you adding some tracepoints to see what happens to kworker or the packet queues. It does not look like a sockmap bug, otherwise I would be able to reproduce it here. Thanks.
On Wed, Sep 1, 2021 at 9:33 PM Cong Wang <xiyou.wangcong@gmail.com> wrote: > > On Tue, Aug 31, 2021 at 12:33 PM Cong Wang <xiyou.wangcong@gmail.com> wrote: > > Like I mentioned before, I suspect there is some delay in one of > > the queues on the way or there is a worker wakeup latency. > > I will try adding some tracepoints to see if I can capture it. > > > > I tried to revert this patch locally to reproduce the EAGAIN > failure, but even after repeating the sockmap_listen test hundreds > of times, I didn't see any failure here. > > If you are still interested in this issue, I'd suggest you adding some > tracepoints to see what happens to kworker or the packet queues. > > It does not look like a sockmap bug, otherwise I would be able to > reproduce it here. > Cong, the issue is not that read() sometimes returns EAGAIN. It is that when using select on the redirected socket, it will hang forever. > Thanks.
On Wed, Sep 1, 2021 at 8:35 PM sunyucong@gmail.com <sunyucong@gmail.com> wrote: > > On Wed, Sep 1, 2021 at 9:33 PM Cong Wang <xiyou.wangcong@gmail.com> wrote: > > > > On Tue, Aug 31, 2021 at 12:33 PM Cong Wang <xiyou.wangcong@gmail.com> wrote: > > > Like I mentioned before, I suspect there is some delay in one of > > > the queues on the way or there is a worker wakeup latency. > > > I will try adding some tracepoints to see if I can capture it. > > > > > > > I tried to revert this patch locally to reproduce the EAGAIN > > failure, but even after repeating the sockmap_listen test hundreds > > of times, I didn't see any failure here. > > > > If you are still interested in this issue, I'd suggest you adding some > > tracepoints to see what happens to kworker or the packet queues. > > > > It does not look like a sockmap bug, otherwise I would be able to > > reproduce it here. > > > > Cong, the issue is not that read() sometimes returns EAGAIN. > > It is that when using select on the redirected socket, it will hang forever. Hmm? We don't use any select(), do we? Before your patch, I used a for loop. With your patch, it is a loop with usleep(). Actually I just reproduced this EAGAIN issue here. I ran `git revert` but it didn't actually revert your patch for some reason, so I had to manually remove those usleep() and finally reproduced it. I used strace -ttt to get the time spent on 100 times of read(), it is about 0.2ms in total. However, runqslower shows the kworker wakeup latency can be 10+ms: 19:29:16 kworker/2:0 19836 14071 19:29:18 kworker/1:0 19836 14369 19:29:20 ksoftirqd/2 19794 12731 19:29:20 kworker/2:0 23 11059 19:29:21 kworker/1:0 19836 11020 So clearly repeating read() for 100 times is too far away from the worst delay. And the wakeup latency is only part of the packet latency, so in other words, in the worst scenario a packet can be delayed for more than 10ms, which is roughly 5000 times of read(). Anyway, this is a not a bug in sockmap, it is a problem of not using blocking mode in sockmap_listen tests. Thanks.
Hi Cong, sorry for the back and forth. Let me clarify the problem here:
If you apply following patch on bpf-next, running ./test_progs -t
sockmap_listen and you will observe full timeout on all the select()
calls for these read() , it looks like select() won't work on
redirected socket, which I think is a issue, but would love to hear
what you think.
diff --git a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c
b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c
index 5c5979046523..fe9ba7c51d8f 100644
--- a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c
+++ b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c
@@ -1002,15 +1002,9 @@ static void redir_to_connected(int family, int
sotype, int sock_mapfd,
goto close_peer1;
if (pass != 1)
FAIL("%s: want pass count 1, have %d", log_prefix, pass);
-again:
- n = read(c0, &b, 1);
- if (n < 0) {
- if (errno == EAGAIN && retries--) {
- usleep(1000);
- goto again;
- }
+ n = recv_timeout(c0, &b, 1, 0, IO_TIMEOUT_SEC);
+ if (n < 0)
FAIL_ERRNO("%s: read", log_prefix);
- }
if (n == 0)
FAIL("%s: incomplete read", log_prefix);
@@ -1606,15 +1600,9 @@ static void unix_redir_to_connected(int sotype,
int sock_mapfd,
if (pass != 1)
FAIL("%s: want pass count 1, have %d", log_prefix, pass);
-again:
- n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1);
- if (n < 0) {
- if (errno == EAGAIN && retries--) {
- usleep(1000);
- goto again;
- }
+ n = recv_timeout(mode == REDIR_INGRESS ? p0 : c0, &b, 1, 0,
IO_TIMEOUT_SEC);
+ if (n < 0)
FAIL_ERRNO("%s: read", log_prefix);
- }
if (n == 0)
FAIL("%s: incomplete read", log_prefix);
@@ -1781,15 +1769,9 @@ static void udp_redir_to_connected(int family,
int sock_mapfd, int verd
_mapfd,
if (pass != 1)
FAIL("%s: want pass count 1, have %d", log_prefix, pass);
-again:
- n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1);
- if (n < 0) {
- if (errno == EAGAIN && retries--) {
- usleep(1000);
- goto again;
- }
+ n = recv_timeout(mode == REDIR_INGRESS ? p0 : c0, &b, 1, 0,
IO_TIMEOUT_SEC);
+ if (n < 0)
FAIL_ERRNO("%s: read", log_prefix);
- }
if (n == 0)
FAIL("%s: incomplete read", log_prefix);
@@ -1876,15 +1858,9 @@ static void inet_unix_redir_to_connected(int
family, int type, int sock_mapfd,
if (pass != 1)
FAIL("%s: want pass count 1, have %d", log_prefix, pass);
-again:
- n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1);
- if (n < 0) {
- if (errno == EAGAIN && retries--) {
- usleep(1000);
- goto again;
- }
+ n = recv_timeout(mode == REDIR_INGRESS ? p0 : c0, &b, 1, 0,
IO_TIMEOUT_SEC);
+ if (n < 0)
FAIL_ERRNO("%s: read", log_prefix);
- }
if (n == 0)
FAIL("%s: incomplete read", log_prefix);
@@ -1963,15 +1939,9 @@ static void unix_inet_redir_to_connected(int
family, int type, int sock_mapfd,
if (pass != 1)
FAIL("%s: want pass count 1, have %d", log_prefix, pass);
-again:
- n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1);
- if (n < 0) {
- if (errno == EAGAIN && retries--) {
- usleep(1000);
- goto again;
- }
+ n = recv_timeout(mode == REDIR_INGRESS ? p0 : c0, &b, 1, 0,
IO_TIMEOUT_SEC);
+ if (n < 0)
FAIL_ERRNO("%s: read", log_prefix);
- }
if (n == 0)
FAIL("%s: incomplete read", log_prefix);
And the error log is
./test_progs -t sockmap_listen
[ 6.568737] bpf_testmod: loading out-of-tree module taints kernel.
#120/1 sockmap_listen/sockmap IPv4 TCP test_insert_invalid:OK
#120/2 sockmap_listen/sockmap IPv4 TCP test_insert_opened:OK
#120/3 sockmap_listen/sockmap IPv4 TCP test_insert_bound:OK
#120/4 sockmap_listen/sockmap IPv4 TCP test_insert:OK
#120/5 sockmap_listen/sockmap IPv4 TCP test_delete_after_insert:OK
#120/6 sockmap_listen/sockmap IPv4 TCP test_delete_after_close:OK
#120/7 sockmap_listen/sockmap IPv4 TCP test_lookup_after_insert:OK
#120/8 sockmap_listen/sockmap IPv4 TCP test_lookup_after_delete:OK
#120/9 sockmap_listen/sockmap IPv4 TCP test_lookup_32_bit_value:OK
#120/10 sockmap_listen/sockmap IPv4 TCP test_update_existing:OK
#120/11 sockmap_listen/sockmap IPv4 TCP test_destroy_orphan_child:OK
#120/12 sockmap_listen/sockmap IPv4 TCP test_syn_recv_insert_delete:OK
#120/13 sockmap_listen/sockmap IPv4 TCP test_race_insert_listen:OK
#120/14 sockmap_listen/sockmap IPv4 TCP test_clone_after_delete:OK
#120/15 sockmap_listen/sockmap IPv4 TCP test_accept_after_delete:OK
#120/16 sockmap_listen/sockmap IPv4 TCP test_accept_before_delete:OK
#120/17 sockmap_listen/sockmap IPv4 UDP test_insert_invalid:OK
#120/18 sockmap_listen/sockmap IPv4 UDP test_insert_opened:OK
#120/19 sockmap_listen/sockmap IPv4 UDP test_insert:OK
#120/20 sockmap_listen/sockmap IPv4 UDP test_delete_after_insert:OK
#120/21 sockmap_listen/sockmap IPv4 UDP test_delete_after_close:OK
#120/22 sockmap_listen/sockmap IPv4 UDP test_lookup_after_insert:OK
#120/23 sockmap_listen/sockmap IPv4 UDP test_lookup_after_delete:OK
#120/24 sockmap_listen/sockmap IPv4 UDP test_lookup_32_bit_value:OK
#120/25 sockmap_listen/sockmap IPv4 UDP test_update_existing:OK
#120/26 sockmap_listen/sockmap IPv4 test_skb_redir_to_connected:OK
#120/27 sockmap_listen/sockmap IPv4 test_skb_redir_to_listening:OK
#120/28 sockmap_listen/sockmap IPv4 test_msg_redir_to_connected:OK
#120/29 sockmap_listen/sockmap IPv4 test_msg_redir_to_listening:OK
#120/30 sockmap_listen/sockmap IPv4 TCP test_reuseport_select_listening:OK
#120/31 sockmap_listen/sockmap IPv4 TCP test_reuseport_select_connected:OK
#120/32 sockmap_listen/sockmap IPv4 TCP test_reuseport_mixed_groups:OK
#120/33 sockmap_listen/sockmap IPv4 UDP test_reuseport_select_listening:OK
#120/34 sockmap_listen/sockmap IPv4 UDP test_reuseport_select_connected:OK
#120/35 sockmap_listen/sockmap IPv4 UDP test_reuseport_mixed_groups:OK
./test_progs:udp_redir_to_connected:1774: ingress: read: Timer expired
udp_redir_to_connected:FAIL:1774
#120/36 sockmap_listen/sockmap IPv4 test_udp_redir:FAIL
./test_progs:inet_unix_redir_to_connected:1863: ingress: read: Timer expired
inet_unix_redir_to_connected:FAIL:1863
./test_progs:inet_unix_redir_to_connected:1863: ingress: read: Timer expired
inet_unix_redir_to_connected:FAIL:1863
./test_progs:unix_inet_redir_to_connected:1944: ingress: read: Timer expired
unix_inet_redir_to_connected:FAIL:1944
./test_progs:unix_inet_redir_to_connected:1944: ingress: read: Timer expired
unix_inet_redir_to_connected:FAIL:1944
#120/37 sockmap_listen/sockmap IPv4 test_udp_unix_redir:FAIL
#120/38 sockmap_listen/sockmap IPv6 TCP test_insert_invalid:OK
#120/39 sockmap_listen/sockmap IPv6 TCP test_insert_opened:OK
#120/40 sockmap_listen/sockmap IPv6 TCP test_insert_bound:OK
#120/41 sockmap_listen/sockmap IPv6 TCP test_insert:OK
#120/42 sockmap_listen/sockmap IPv6 TCP test_delete_after_insert:OK
#120/43 sockmap_listen/sockmap IPv6 TCP test_delete_after_close:OK
#120/44 sockmap_listen/sockmap IPv6 TCP test_lookup_after_insert:OK
#120/45 sockmap_listen/sockmap IPv6 TCP test_lookup_after_delete:OK
#120/46 sockmap_listen/sockmap IPv6 TCP test_lookup_32_bit_value:OK
#120/47 sockmap_listen/sockmap IPv6 TCP test_update_existing:OK
#120/48 sockmap_listen/sockmap IPv6 TCP test_destroy_orphan_child:OK
#120/49 sockmap_listen/sockmap IPv6 TCP test_syn_recv_insert_delete:OK
#120/50 sockmap_listen/sockmap IPv6 TCP test_race_insert_listen:OK
#120/51 sockmap_listen/sockmap IPv6 TCP test_clone_after_delete:OK
#120/52 sockmap_listen/sockmap IPv6 TCP test_accept_after_delete:OK
#120/53 sockmap_listen/sockmap IPv6 TCP test_accept_before_delete:OK
#120/54 sockmap_listen/sockmap IPv6 UDP test_insert_invalid:OK
#120/55 sockmap_listen/sockmap IPv6 UDP test_insert_opened:OK
#120/56 sockmap_listen/sockmap IPv6 UDP test_insert:OK
#120/57 sockmap_listen/sockmap IPv6 UDP test_delete_after_insert:OK
#120/58 sockmap_listen/sockmap IPv6 UDP test_delete_after_close:OK
#120/59 sockmap_listen/sockmap IPv6 UDP test_lookup_after_insert:OK
#120/60 sockmap_listen/sockmap IPv6 UDP test_lookup_after_delete:OK
#120/61 sockmap_listen/sockmap IPv6 UDP test_lookup_32_bit_value:OK
#120/62 sockmap_listen/sockmap IPv6 UDP test_update_existing:OK
#120/63 sockmap_listen/sockmap IPv6 test_skb_redir_to_connected:OK
#120/64 sockmap_listen/sockmap IPv6 test_skb_redir_to_listening:OK
#120/65 sockmap_listen/sockmap IPv6 test_msg_redir_to_connected:OK
#120/66 sockmap_listen/sockmap IPv6 test_msg_redir_to_listening:OK
#120/67 sockmap_listen/sockmap IPv6 TCP test_reuseport_select_listening:OK
#120/68 sockmap_listen/sockmap IPv6 TCP test_reuseport_select_connected:OK
#120/69 sockmap_listen/sockmap IPv6 TCP test_reuseport_mixed_groups:OK
#120/70 sockmap_listen/sockmap IPv6 UDP test_reuseport_select_listening:OK
#120/71 sockmap_listen/sockmap IPv6 UDP test_reuseport_select_connected:OK
#120/72 sockmap_listen/sockmap IPv6 UDP test_reuseport_mixed_groups:OK
./test_progs:udp_redir_to_connected:1774: ingress: read: Timer expired
udp_redir_to_connected:FAIL:1774
#120/73 sockmap_listen/sockmap IPv6 test_udp_redir:FAIL
./test_progs:inet_unix_redir_to_connected:1863: ingress: read: Timer expired
inet_unix_redir_to_connected:FAIL:1863
./test_progs:inet_unix_redir_to_connected:1863: ingress: read: Timer expired
inet_unix_redir_to_connected:FAIL:1863
./test_progs:unix_inet_redir_to_connected:1944: ingress: read: Timer expired
unix_inet_redir_to_connected:FAIL:1944
./test_progs:unix_inet_redir_to_connected:1944: ingress: read: Timer expired
unix_inet_redir_to_connected:FAIL:1944
#120/74 sockmap_listen/sockmap IPv6 test_udp_unix_redir:FAIL
./test_progs:unix_redir_to_connected:1605: ingress: read: Timer expired
unix_redir_to_connected:FAIL:1605
#120/75 sockmap_listen/sockmap Unix test_unix_redir:FAIL
./test_progs:unix_redir_to_connected:1605: ingress: read: Timer expired
unix_redir_to_connected:FAIL:1605
#120/76 sockmap_listen/sockmap Unix test_unix_redir:FAIL
#120/77 sockmap_listen/sockhash IPv4 TCP test_insert_invalid:OK
#120/78 sockmap_listen/sockhash IPv4 TCP test_insert_opened:OK
#120/79 sockmap_listen/sockhash IPv4 TCP test_insert_bound:OK
#120/80 sockmap_listen/sockhash IPv4 TCP test_insert:OK
#120/81 sockmap_listen/sockhash IPv4 TCP test_delete_after_insert:OK
#120/82 sockmap_listen/sockhash IPv4 TCP test_delete_after_close:OK
#120/83 sockmap_listen/sockhash IPv4 TCP test_lookup_after_insert:OK
#120/84 sockmap_listen/sockhash IPv4 TCP test_lookup_after_delete:OK
#120/85 sockmap_listen/sockhash IPv4 TCP test_lookup_32_bit_value:OK
#120/86 sockmap_listen/sockhash IPv4 TCP test_update_existing:OK
#120/87 sockmap_listen/sockhash IPv4 TCP test_destroy_orphan_child:OK
#120/88 sockmap_listen/sockhash IPv4 TCP test_syn_recv_insert_delete:OK
#120/89 sockmap_listen/sockhash IPv4 TCP test_race_insert_listen:OK
#120/90 sockmap_listen/sockhash IPv4 TCP test_clone_after_delete:OK
#120/91 sockmap_listen/sockhash IPv4 TCP test_accept_after_delete:OK
#120/92 sockmap_listen/sockhash IPv4 TCP test_accept_before_delete:OK
#120/93 sockmap_listen/sockhash IPv4 UDP test_insert_invalid:OK
#120/94 sockmap_listen/sockhash IPv4 UDP test_insert_opened:OK
#120/95 sockmap_listen/sockhash IPv4 UDP test_insert:OK
#120/96 sockmap_listen/sockhash IPv4 UDP test_delete_after_insert:OK
#120/97 sockmap_listen/sockhash IPv4 UDP test_delete_after_close:OK
#120/98 sockmap_listen/sockhash IPv4 UDP test_lookup_after_insert:OK
#120/99 sockmap_listen/sockhash IPv4 UDP test_lookup_after_delete:OK
#120/100 sockmap_listen/sockhash IPv4 UDP test_lookup_32_bit_value:OK
#120/101 sockmap_listen/sockhash IPv4 UDP test_update_existing:OK
#120/102 sockmap_listen/sockhash IPv4 test_skb_redir_to_connected:OK
#120/103 sockmap_listen/sockhash IPv4 test_skb_redir_to_listening:OK
#120/104 sockmap_listen/sockhash IPv4 test_msg_redir_to_connected:OK
#120/105 sockmap_listen/sockhash IPv4 test_msg_redir_to_listening:OK
#120/106 sockmap_listen/sockhash IPv4 TCP test_reuseport_select_listening:OK
#120/107 sockmap_listen/sockhash IPv4 TCP test_reuseport_select_connected:OK
#120/108 sockmap_listen/sockhash IPv4 TCP test_reuseport_mixed_groups:OK
#120/109 sockmap_listen/sockhash IPv4 UDP test_reuseport_select_listening:OK
#120/110 sockmap_listen/sockhash IPv4 UDP test_reuseport_select_connected:OK
#120/111 sockmap_listen/sockhash IPv4 UDP test_reuseport_mixed_groups:OK
./test_progs:udp_redir_to_connected:1774: ingress: read: Timer expired
udp_redir_to_connected:FAIL:1774
#120/112 sockmap_listen/sockhash IPv4 test_udp_redir:FAIL
./test_progs:inet_unix_redir_to_connected:1863: ingress: read: Timer expired
inet_unix_redir_to_connected:FAIL:1863
./test_progs:inet_unix_redir_to_connected:1863: ingress: read: Timer expired
inet_unix_redir_to_connected:FAIL:1863
./test_progs:unix_inet_redir_to_connected:1944: ingress: read: Timer expired
unix_inet_redir_to_connected:FAIL:1944
./test_progs:unix_inet_redir_to_connected:1944: ingress: read: Timer expired
unix_inet_redir_to_connected:FAIL:1944
#120/113 sockmap_listen/sockhash IPv4 test_udp_unix_redir:FAIL
#120/114 sockmap_listen/sockhash IPv6 TCP test_insert_invalid:OK
#120/115 sockmap_listen/sockhash IPv6 TCP test_insert_opened:OK
#120/116 sockmap_listen/sockhash IPv6 TCP test_insert_bound:OK
#120/117 sockmap_listen/sockhash IPv6 TCP test_insert:OK
#120/118 sockmap_listen/sockhash IPv6 TCP test_delete_after_insert:OK
#120/119 sockmap_listen/sockhash IPv6 TCP test_delete_after_close:OK
#120/120 sockmap_listen/sockhash IPv6 TCP test_lookup_after_insert:OK
#120/121 sockmap_listen/sockhash IPv6 TCP test_lookup_after_delete:OK
#120/122 sockmap_listen/sockhash IPv6 TCP test_lookup_32_bit_value:OK
#120/123 sockmap_listen/sockhash IPv6 TCP test_update_existing:OK
#120/124 sockmap_listen/sockhash IPv6 TCP test_destroy_orphan_child:OK
#120/125 sockmap_listen/sockhash IPv6 TCP test_syn_recv_insert_delete:OK
#120/126 sockmap_listen/sockhash IPv6 TCP test_race_insert_listen:OK
#120/127 sockmap_listen/sockhash IPv6 TCP test_clone_after_delete:OK
#120/128 sockmap_listen/sockhash IPv6 TCP test_accept_after_delete:OK
#120/129 sockmap_listen/sockhash IPv6 TCP test_accept_before_delete:OK
#120/130 sockmap_listen/sockhash IPv6 UDP test_insert_invalid:OK
#120/131 sockmap_listen/sockhash IPv6 UDP test_insert_opened:OK
#120/132 sockmap_listen/sockhash IPv6 UDP test_insert:OK
#120/133 sockmap_listen/sockhash IPv6 UDP test_delete_after_insert:OK
#120/134 sockmap_listen/sockhash IPv6 UDP test_delete_after_close:OK
#120/135 sockmap_listen/sockhash IPv6 UDP test_lookup_after_insert:OK
#120/136 sockmap_listen/sockhash IPv6 UDP test_lookup_after_delete:OK
#120/137 sockmap_listen/sockhash IPv6 UDP test_lookup_32_bit_value:OK
#120/138 sockmap_listen/sockhash IPv6 UDP test_update_existing:OK
#120/139 sockmap_listen/sockhash IPv6 test_skb_redir_to_connected:OK
#120/140 sockmap_listen/sockhash IPv6 test_skb_redir_to_listening:OK
#120/141 sockmap_listen/sockhash IPv6 test_msg_redir_to_connected:OK
#120/142 sockmap_listen/sockhash IPv6 test_msg_redir_to_listening:OK
#120/143 sockmap_listen/sockhash IPv6 TCP test_reuseport_select_listening:OK
#120/144 sockmap_listen/sockhash IPv6 TCP test_reuseport_select_connected:OK
#120/145 sockmap_listen/sockhash IPv6 TCP test_reuseport_mixed_groups:OK
#120/146 sockmap_listen/sockhash IPv6 UDP test_reuseport_select_listening:OK
#120/147 sockmap_listen/sockhash IPv6 UDP test_reuseport_select_connected:OK
#120/148 sockmap_listen/sockhash IPv6 UDP test_reuseport_mixed_groups:OK
./test_progs:udp_redir_to_connected:1774: ingress: read: Timer expired
udp_redir_to_connected:FAIL:1774
#120/149 sockmap_listen/sockhash IPv6 test_udp_redir:FAIL
./test_progs:inet_unix_redir_to_connected:1863: ingress: read: Timer expired
inet_unix_redir_to_connected:FAIL:1863
./test_progs:inet_unix_redir_to_connected:1863: ingress: read: Timer expired
inet_unix_redir_to_connected:FAIL:1863
./test_progs:unix_inet_redir_to_connected:1944: ingress: read: Timer expired
unix_inet_redir_to_connected:FAIL:1944
./test_progs:unix_inet_redir_to_connected:1944: ingress: read: Timer expired
unix_inet_redir_to_connected:FAIL:1944
#120/150 sockmap_listen/sockhash IPv6 test_udp_unix_redir:FAIL
./test_progs:unix_redir_to_connected:1605: ingress: read: Timer expired
unix_redir_to_connected:FAIL:1605
#120/151 sockmap_listen/sockhash Unix test_unix_redir:FAIL
./test_progs:unix_redir_to_connected:1605: ingress: read: Timer expired
unix_redir_to_connected:FAIL:1605
#120/152 sockmap_listen/sockhash Unix test_unix_redir:FAIL
#120 sockmap_listen:FAIL
Summary: 0/140 PASSED, 0 SKIPPED, 13 FAILED
On Fri, Sep 3, 2021 at 7:44 PM Cong Wang <xiyou.wangcong@gmail.com> wrote:
>
> On Wed, Sep 1, 2021 at 8:35 PM sunyucong@gmail.com <sunyucong@gmail.com> wrote:
> >
> > On Wed, Sep 1, 2021 at 9:33 PM Cong Wang <xiyou.wangcong@gmail.com> wrote:
> > >
> > > On Tue, Aug 31, 2021 at 12:33 PM Cong Wang <xiyou.wangcong@gmail.com> wrote:
> > > > Like I mentioned before, I suspect there is some delay in one of
> > > > the queues on the way or there is a worker wakeup latency.
> > > > I will try adding some tracepoints to see if I can capture it.
> > > >
> > >
> > > I tried to revert this patch locally to reproduce the EAGAIN
> > > failure, but even after repeating the sockmap_listen test hundreds
> > > of times, I didn't see any failure here.
> > >
> > > If you are still interested in this issue, I'd suggest you adding some
> > > tracepoints to see what happens to kworker or the packet queues.
> > >
> > > It does not look like a sockmap bug, otherwise I would be able to
> > > reproduce it here.
> > >
> >
> > Cong, the issue is not that read() sometimes returns EAGAIN.
> >
> > It is that when using select on the redirected socket, it will hang forever.
>
> Hmm? We don't use any select(), do we? Before your patch, I used
> a for loop. With your patch, it is a loop with usleep().
>
> Actually I just reproduced this EAGAIN issue here. I ran `git revert`
> but it didn't actually revert your patch for some reason, so I had to
> manually remove those usleep() and finally reproduced it.
>
> I used strace -ttt to get the time spent on 100 times of read(), it is
> about 0.2ms in total. However, runqslower shows the kworker wakeup
> latency can be 10+ms:
>
> 19:29:16 kworker/2:0 19836 14071
> 19:29:18 kworker/1:0 19836 14369
> 19:29:20 ksoftirqd/2 19794 12731
> 19:29:20 kworker/2:0 23 11059
> 19:29:21 kworker/1:0 19836 11020
>
> So clearly repeating read() for 100 times is too far away from the worst
> delay. And the wakeup latency is only part of the packet latency, so in
> other words, in the worst scenario a packet can be delayed for more
> than 10ms, which is roughly 5000 times of read().
>
> Anyway, this is a not a bug in sockmap, it is a problem of not using
> blocking mode in sockmap_listen tests.
>
> Thanks.
Hi Cong, want to make sure this doesn't fall through, any thoughts on this? Cheers.
On Mon, Sep 6, 2021 at 7:24 PM sunyucong@gmail.com <sunyucong@gmail.com> wrote: > > Hi Cong, sorry for the back and forth. Let me clarify the problem here: > > If you apply following patch on bpf-next, running ./test_progs -t > sockmap_listen and you will observe full timeout on all the select() > calls for these read() , it looks like select() won't work on > redirected socket, which I think is a issue, but would love to hear > what you think. Ah, I see, we do call the original ->sk_data_ready() when redirecting the packet, via sk_psock_data_ready(), however it looks like those ->poll() still reads the original queues (e.g. ->sk_receive_queue) but misses the sockmap queues (psock->ingress_skb). Let me think about the right fix of this. Thanks a lot for the details!
diff --git a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c index 6a5df28f9a3d..5c5979046523 100644 --- a/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c +++ b/tools/testing/selftests/bpf/prog_tests/sockmap_listen.c @@ -949,6 +949,7 @@ static void redir_to_connected(int family, int sotype, int sock_mapfd, int err, n; u32 key; char b; + int retries = 100; zero_verdict_count(verd_mapfd); @@ -1001,10 +1002,15 @@ static void redir_to_connected(int family, int sotype, int sock_mapfd, goto close_peer1; if (pass != 1) FAIL("%s: want pass count 1, have %d", log_prefix, pass); - +again: n = read(c0, &b, 1); - if (n < 0) + if (n < 0) { + if (errno == EAGAIN && retries--) { + usleep(1000); + goto again; + } FAIL_ERRNO("%s: read", log_prefix); + } if (n == 0) FAIL("%s: incomplete read", log_prefix); @@ -1926,6 +1932,7 @@ static void unix_inet_redir_to_connected(int family, int type, int sock_mapfd, int sfd[2]; u32 key; char b; + int retries = 100; zero_verdict_count(verd_mapfd); @@ -1956,9 +1963,15 @@ static void unix_inet_redir_to_connected(int family, int type, int sock_mapfd, if (pass != 1) FAIL("%s: want pass count 1, have %d", log_prefix, pass); +again: n = read(mode == REDIR_INGRESS ? p0 : c0, &b, 1); - if (n < 0) + if (n < 0) { + if (errno == EAGAIN && retries--) { + usleep(1000); + goto again; + } FAIL_ERRNO("%s: read", log_prefix); + } if (n == 0) FAIL("%s: incomplete read", log_prefix);
This patch adds similar retry logic to more places where read() is used, to reduce flakyness in slow CI environment. Signed-off-by: Yucong Sun <fallentree@fb.com> --- .../selftests/bpf/prog_tests/sockmap_listen.c | 19 ++++++++++++++++--- 1 file changed, 16 insertions(+), 3 deletions(-)