flaky tc_redirect/tc_redirect_dtime

flaky tc_redirect/tc_redirect_dtime

[Alexei Starovoitov]

Hi Martin,

I remember you tried to fix tc_redirect/tc_redirect_dtime flakiness,
but it is still flaky.
Just running test_progs -t tc_redirect/tc_redirect_dtime
in a loop it will fail after 30-50 iterations in my VM and always with:

test_inet_dtime:PASS:setns src 0 nsec
(network_helpers.c:253: errno: Operation now in progress) Failed to
connect to server
close_netns:PASS:setns 0 nsec
test_inet_dtime:FAIL:connect_to_fd unexpected connect_to_fd: actual -1
< expected 0

I've added this hack:
+again:
        nstoken = open_netns(NS_SRC);
        if (!ASSERT_OK_PTR(nstoken, "setns src"))
                goto done;
@@ -573,6 +575,11 @@ static void test_inet_dtime(int family, int type,
const char *addr, __u16 port)
        if (!ASSERT_GE(client_fd, 0, "connect_to_fd"))
                goto done;

+       if (i++ < 1000 && 0) {
+               printf("XXXX %d\n", i);
+               close(client_fd);
+               goto again;
+       }

and realized that only the first connect can succeed.
The 2nd connect always fails.
So I suspect bpf prog sees first stray packet, acts on it,
but the actual connect request comes 2nd and it fails.

I tried to understand what's going on inside bpf prog,
but the test is too complicated.
Please take a look when you have a chance.

I also added:
@@ -857,7 +864,7 @@ static void test_tc_redirect_dtime(struct
netns_setup_result *setup_result)
                goto done;

        test_tcp_clear_dtime(skel);
-
+if (0) {
        test_tcp_dtime(skel, AF_INET, true);
        test_tcp_dtime(skel, AF_INET6, true);
        test_udp_dtime(skel, AF_INET, true);
@@ -878,7 +885,7 @@ static void test_tc_redirect_dtime(struct
netns_setup_result *setup_result)
        test_tcp_dtime(skel, AF_INET6, false);
        test_udp_dtime(skel, AF_INET, false);
        test_udp_dtime(skel, AF_INET6, false);
-
+}
to speed up a test a bit.

Re: flaky tc_redirect/tc_redirect_dtime

[Martin KaFai Lau]

On 1/13/24 1:09 PM, Alexei Starovoitov wrote:
> Hi Martin,
> 
> I remember you tried to fix tc_redirect/tc_redirect_dtime flakiness,
> but it is still flaky.
> Just running test_progs -t tc_redirect/tc_redirect_dtime
> in a loop it will fail after 30-50 iterations in my VM and always with:
> 
> test_inet_dtime:PASS:setns src 0 nsec
> (network_helpers.c:253: errno: Operation now in progress) Failed to
> connect to server
> close_netns:PASS:setns 0 nsec
> test_inet_dtime:FAIL:connect_to_fd unexpected connect_to_fd: actual -1
> < expected 0
> 
> I've added this hack:
> +again:
>          nstoken = open_netns(NS_SRC);
>          if (!ASSERT_OK_PTR(nstoken, "setns src"))
>                  goto done;
> @@ -573,6 +575,11 @@ static void test_inet_dtime(int family, int type,
> const char *addr, __u16 port)
>          if (!ASSERT_GE(client_fd, 0, "connect_to_fd"))
>                  goto done;
> 
> +       if (i++ < 1000 && 0) {
> +               printf("XXXX %d\n", i);
> +               close(client_fd);
> +               goto again;
> +       }
> 
> and realized that only the first connect can succeed.
> The 2nd connect always fails.
> So I suspect bpf prog sees first stray packet, acts on it,
> but the actual connect request comes 2nd and it fails.
> 
> I tried to understand what's going on inside bpf prog,
> but the test is too complicated.
> Please take a look when you have a chance.
> 
> I also added:
> @@ -857,7 +864,7 @@ static void test_tc_redirect_dtime(struct
> netns_setup_result *setup_result)
>                  goto done;
> 
>          test_tcp_clear_dtime(skel);
> -
> +if (0) {
>          test_tcp_dtime(skel, AF_INET, true);
>          test_tcp_dtime(skel, AF_INET6, true);
>          test_udp_dtime(skel, AF_INET, true);
> @@ -878,7 +885,7 @@ static void test_tc_redirect_dtime(struct
> netns_setup_result *setup_result)
>          test_tcp_dtime(skel, AF_INET6, false);
>          test_udp_dtime(skel, AF_INET, false);
>          test_udp_dtime(skel, AF_INET6, false);
> -
> +}
> to speed up a test a bit.

Thanks for the tips to reproduce it. I will look into it.

Re: flaky tc_redirect/tc_redirect_dtime

[Martin KaFai Lau]

On 1/15/24 7:09 AM, Martin KaFai Lau wrote:
> On 1/13/24 1:09 PM, Alexei Starovoitov wrote:
>> Hi Martin,
>>
>> I remember you tried to fix tc_redirect/tc_redirect_dtime flakiness,
>> but it is still flaky.
>> Just running test_progs -t tc_redirect/tc_redirect_dtime
>> in a loop it will fail after 30-50 iterations in my VM and always with:
>>
>> test_inet_dtime:PASS:setns src 0 nsec
>> (network_helpers.c:253: errno: Operation now in progress) Failed to
>> connect to server

This is likely caused by the missing the accept() due to the new "goto again;". 
The acceptq is full, server drops the SYN, the second client connect() then 
becomes in-progress or timed out.

It is different from what usually happened in the CI: 
https://github.com/kernel-patches/bpf/actions/runs/7495413543/job/20406821195

2024-01-12T00:46:14.2454623Z (network_helpers.c:253: errno: No route to host) 
Failed to connect to server

"errno: No route to host" should be EHOSTUNREACH returned from the connect().

It is usually the very first connect(). The later connects to the same IPv6 
address are fine. It could be some delay in the routing entry or in the source 
address coming up but I don't spot anything useful now. I can't reproduce in my 
local environment. I will try a little harder. If I cannot find anything, I will 
post a patch to add some tracing to narrow it down further.

>> close_netns:PASS:setns 0 nsec
>> test_inet_dtime:FAIL:connect_to_fd unexpected connect_to_fd: actual -1
>> < expected 0
>>
>> I've added this hack:
>> +again:
>>          nstoken = open_netns(NS_SRC);
>>          if (!ASSERT_OK_PTR(nstoken, "setns src"))
>>                  goto done;
>> @@ -573,6 +575,11 @@ static void test_inet_dtime(int family, int type,
>> const char *addr, __u16 port)
>>          if (!ASSERT_GE(client_fd, 0, "connect_to_fd"))
>>                  goto done;
>>
>> +       if (i++ < 1000 && 0) {
>> +               printf("XXXX %d\n", i);
>> +               close(client_fd);
>> +               goto again;
>> +       }
>>
>> and realized that only the first connect can succeed.
>> The 2nd connect always fails.
>> So I suspect bpf prog sees first stray packet, acts on it,
>> but the actual connect request comes 2nd and it fails.
>>
>> I tried to understand what's going on inside bpf prog,
>> but the test is too complicated.
>> Please take a look when you have a chance.
>>
>> I also added:
>> @@ -857,7 +864,7 @@ static void test_tc_redirect_dtime(struct
>> netns_setup_result *setup_result)
>>                  goto done;
>>
>>          test_tcp_clear_dtime(skel);
>> -
>> +if (0) {
>>          test_tcp_dtime(skel, AF_INET, true);
>>          test_tcp_dtime(skel, AF_INET6, true);
>>          test_udp_dtime(skel, AF_INET, true);
>> @@ -878,7 +885,7 @@ static void test_tc_redirect_dtime(struct
>> netns_setup_result *setup_result)
>>          test_tcp_dtime(skel, AF_INET6, false);
>>          test_udp_dtime(skel, AF_INET, false);
>>          test_udp_dtime(skel, AF_INET6, false);
>> -
>> +}
>> to speed up a test a bit.
> 
> Thanks for the tips to reproduce it. I will look into it.
>