[PATCH net-next] selftests: return failure when timestamps can't be parsed

[PATCH net-next] selftests: return failure when timestamps can't be parsed

[Jason Xing]

From: Jason Xing <kernelxing@tencent.com>

When I was trying to modify the tx timestamping feature, I found that
running "./txtimestamp -4 -C -L 127.0.0.1" didn't reflect the fact
properly.

In this selftest file, we respectively test three tx generation flags.
With the generation and report flag enabled, we expect that the timestamp
must be returned to the userspace unless 1) generating the timestamp
fails, 2) reporting the timestamp fails. So we should test if the
timestamps can be read and parsed succuessfuly in txtimestamp.c, or
else there is a bug in the kernel.

After adding the check so that running ./txtimestamp will reflect the
result correctly like this if there is an error in kernel:
protocol:     TCP
payload:      10
server port:  9000

family:       INET
test SND
    USR: 1725458477 s 667997 us (seq=0, len=0)
Failed to parse timestamps
    USR: 1725458477 s 718128 us (seq=0, len=0)
Failed to parse timestamps
    USR: 1725458477 s 768273 us (seq=0, len=0)
Failed to parse timestamps
    USR: 1725458477 s 818416 us (seq=0, len=0)
Failed to parse timestamps
...

Signed-off-by: Jason Xing <kernelxing@tencent.com>
---
I'm not sure if I should also check if the cur->tv_sec or cur->tv_nsec
is zero in __print_timestamp(). Could it be valid when either of
them is zero?
---
 tools/testing/selftests/net/txtimestamp.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/tools/testing/selftests/net/txtimestamp.c b/tools/testing/selftests/net/txtimestamp.c
index ec60a16c9307..b69aae840a67 100644
--- a/tools/testing/selftests/net/txtimestamp.c
+++ b/tools/testing/selftests/net/txtimestamp.c
@@ -358,6 +358,10 @@ static void __recv_errmsg_cmsg(struct msghdr *msg, int payload_len)
 
 	if (batch > 1)
 		fprintf(stderr, "batched %d timestamps\n", batch);
+	else if (!batch) {
+		fprintf(stderr, "Failed to parse timestamps\n");
+		test_failed = true;
+	}
 }
 
 static int recv_errmsg(int fd)
-- 
2.37.3

Re: [PATCH net-next] selftests: return failure when timestamps can't be parsed

[Willem de Bruijn]

Jason Xing wrote:
> From: Jason Xing <kernelxing@tencent.com>
> 
> When I was trying to modify the tx timestamping feature, I found that
> running "./txtimestamp -4 -C -L 127.0.0.1" didn't reflect the fact
> properly.

Did not reflect what fact? Sorry, I don't entirely follow the issue
you raise.

> In this selftest file, we respectively test three tx generation flags.
> With the generation and report flag enabled, we expect that the timestamp
> must be returned to the userspace unless 1) generating the timestamp
> fails, 2) reporting the timestamp fails. So we should test if the
> timestamps can be read and parsed succuessfuly in txtimestamp.c, or

typo: successfully

> else there is a bug in the kernel.
> 
> After adding the check so that running ./txtimestamp will reflect the
> result correctly like this if there is an error in kernel:
> protocol:     TCP
> payload:      10
> server port:  9000
> 
> family:       INET
> test SND
>     USR: 1725458477 s 667997 us (seq=0, len=0)
> Failed to parse timestamps
>     USR: 1725458477 s 718128 us (seq=0, len=0)
> Failed to parse timestamps
>     USR: 1725458477 s 768273 us (seq=0, len=0)
> Failed to parse timestamps
>     USR: 1725458477 s 818416 us (seq=0, len=0)
> Failed to parse timestamps
> ...
> 
> Signed-off-by: Jason Xing <kernelxing@tencent.com>
> ---
> I'm not sure if I should also check if the cur->tv_sec or cur->tv_nsec
> is zero in __print_timestamp(). Could it be valid when either of
> them is zero?

tv_nsec can be zero. tv_sec cannot.

> ---
>  tools/testing/selftests/net/txtimestamp.c | 4 ++++
>  1 file changed, 4 insertions(+)
> 
> diff --git a/tools/testing/selftests/net/txtimestamp.c b/tools/testing/selftests/net/txtimestamp.c
> index ec60a16c9307..b69aae840a67 100644
> --- a/tools/testing/selftests/net/txtimestamp.c
> +++ b/tools/testing/selftests/net/txtimestamp.c
> @@ -358,6 +358,10 @@ static void __recv_errmsg_cmsg(struct msghdr *msg, int payload_len)
>  
>  	if (batch > 1)
>  		fprintf(stderr, "batched %d timestamps\n", batch);
> +	else if (!batch) {
> +		fprintf(stderr, "Failed to parse timestamps\n");
> +		test_failed = true;
> +	}

nit: if adding braces around one side of a branch, then add to both (all).

This is not so much a parsing failure as that no timestamps arrived.

More importantly, this function gets called also if
recvmsg(fd, .., MSG_ERRQUEUE) returned 0:

        if (ret >= 0) {
                __recv_errmsg_cmsg(&msg, ret);

That seems counterintuitive, as there is no data. But this was
introduced with cfg_loop_nodata (SOF_TIMESTAMPING_OPT_TSONLY). When
there may be packets looped, just 0B packets. In those cases we also
expect timestamps.

But, can __recv_errmsg_cmsg now also be called when there truly is
nothing on the error queue? It is a non-blocking read, after all.

Judging from

                while (!recv_errmsg(fd)) {}

The caller can. But if there is nothing waiting it returns -1 with
EAGAIN:

        ret = recvmsg(fd, &msg, MSG_ERRQUEUE);
        if (ret == -1 && errno != EAGAIN)
                error(1, errno, "recvmsg");

So long story short, subject to a few nits your patch sounds okay to
me (but it's not entirely trivial that that is so: sharing so that you
also double check, thanks).

>  }
>  
>  static int recv_errmsg(int fd)
> -- 
> 2.37.3
> 

Re: [PATCH net-next] selftests: return failure when timestamps can't be parsed

[Jason Xing]

On Thu, Sep 5, 2024 at 5:16 AM Willem de Bruijn
<willemdebruijn.kernel@gmail.com> wrote:
>
> Jason Xing wrote:
> > From: Jason Xing <kernelxing@tencent.com>
> >
> > When I was trying to modify the tx timestamping feature, I found that
> > running "./txtimestamp -4 -C -L 127.0.0.1" didn't reflect the fact
> > properly.
>
> Did not reflect what fact? Sorry, I don't entirely follow the issue
> you raise.

I was trying to say if someone writes a bug in the timestamping
feature, the selftest probably returns pass value instead of failure.

I will explicitly report the case I met.

>
> > In this selftest file, we respectively test three tx generation flags.
> > With the generation and report flag enabled, we expect that the timestamp
> > must be returned to the userspace unless 1) generating the timestamp
> > fails, 2) reporting the timestamp fails. So we should test if the
> > timestamps can be read and parsed succuessfuly in txtimestamp.c, or
>
> typo: successfully

Will update it.

>
> > else there is a bug in the kernel.
> >
> > After adding the check so that running ./txtimestamp will reflect the
> > result correctly like this if there is an error in kernel:
> > protocol:     TCP
> > payload:      10
> > server port:  9000
> >
> > family:       INET
> > test SND
> >     USR: 1725458477 s 667997 us (seq=0, len=0)
> > Failed to parse timestamps
> >     USR: 1725458477 s 718128 us (seq=0, len=0)
> > Failed to parse timestamps
> >     USR: 1725458477 s 768273 us (seq=0, len=0)
> > Failed to parse timestamps
> >     USR: 1725458477 s 818416 us (seq=0, len=0)
> > Failed to parse timestamps
> > ...
> >
> > Signed-off-by: Jason Xing <kernelxing@tencent.com>
> > ---
> > I'm not sure if I should also check if the cur->tv_sec or cur->tv_nsec
> > is zero in __print_timestamp(). Could it be valid when either of
> > them is zero?
>
> tv_nsec can be zero. tv_sec cannot.

Thanks. Now I am learning :)

>
> > ---
> >  tools/testing/selftests/net/txtimestamp.c | 4 ++++
> >  1 file changed, 4 insertions(+)
> >
> > diff --git a/tools/testing/selftests/net/txtimestamp.c b/tools/testing/selftests/net/txtimestamp.c
> > index ec60a16c9307..b69aae840a67 100644
> > --- a/tools/testing/selftests/net/txtimestamp.c
> > +++ b/tools/testing/selftests/net/txtimestamp.c
> > @@ -358,6 +358,10 @@ static void __recv_errmsg_cmsg(struct msghdr *msg, int payload_len)
> >
> >       if (batch > 1)
> >               fprintf(stderr, "batched %d timestamps\n", batch);
> > +     else if (!batch) {
> > +             fprintf(stderr, "Failed to parse timestamps\n");
> > +             test_failed = true;
> > +     }
>
> nit: if adding braces around one side of a branch, then add to both (all).

I see.

>
> This is not so much a parsing failure as that no timestamps arrived.
>
> More importantly, this function gets called also if
> recvmsg(fd, .., MSG_ERRQUEUE) returned 0:
>
>         if (ret >= 0) {
>                 __recv_errmsg_cmsg(&msg, ret);
>
> That seems counterintuitive, as there is no data. But this was
> introduced with cfg_loop_nodata (SOF_TIMESTAMPING_OPT_TSONLY). When
> there may be packets looped, just 0B packets. In those cases we also
> expect timestamps.

Right, It does make sense.

>
> But, can __recv_errmsg_cmsg now also be called when there truly is
> nothing on the error queue? It is a non-blocking read, after all.
>
> Judging from
>
>                 while (!recv_errmsg(fd)) {}
>
> The caller can. But if there is nothing waiting it returns -1 with
> EAGAIN:
>
>         ret = recvmsg(fd, &msg, MSG_ERRQUEUE);
>         if (ret == -1 && errno != EAGAIN)
>                 error(1, errno, "recvmsg");
>
> So long story short, subject to a few nits your patch sounds okay to
> me (but it's not entirely trivial that that is so: sharing so that you
> also double check, thanks).

Thanks for pointing out this one. I will rewrite this patch/patch
series tomorrow with your questions resolved.

Thanks,
Jason

Re: [PATCH net-next] selftests: return failure when timestamps can't be parsed

[Jason Xing]

On Thu, Sep 5, 2024 at 5:16 AM Willem de Bruijn
<willemdebruijn.kernel@gmail.com> wrote:
>
> Jason Xing wrote:
> > From: Jason Xing <kernelxing@tencent.com>
> >
> > When I was trying to modify the tx timestamping feature, I found that
> > running "./txtimestamp -4 -C -L 127.0.0.1" didn't reflect the fact
> > properly.
>
> Did not reflect what fact? Sorry, I don't entirely follow the issue
> you raise.
>
> > In this selftest file, we respectively test three tx generation flags.
> > With the generation and report flag enabled, we expect that the timestamp
> > must be returned to the userspace unless 1) generating the timestamp
> > fails, 2) reporting the timestamp fails. So we should test if the
> > timestamps can be read and parsed succuessfuly in txtimestamp.c, or
>
> typo: successfully
>
> > else there is a bug in the kernel.
> >
> > After adding the check so that running ./txtimestamp will reflect the
> > result correctly like this if there is an error in kernel:
> > protocol:     TCP
> > payload:      10
> > server port:  9000
> >
> > family:       INET
> > test SND
> >     USR: 1725458477 s 667997 us (seq=0, len=0)
> > Failed to parse timestamps
> >     USR: 1725458477 s 718128 us (seq=0, len=0)
> > Failed to parse timestamps
> >     USR: 1725458477 s 768273 us (seq=0, len=0)
> > Failed to parse timestamps
> >     USR: 1725458477 s 818416 us (seq=0, len=0)
> > Failed to parse timestamps
> > ...
> >
> > Signed-off-by: Jason Xing <kernelxing@tencent.com>
> > ---
> > I'm not sure if I should also check if the cur->tv_sec or cur->tv_nsec
> > is zero in __print_timestamp(). Could it be valid when either of
> > them is zero?
>
> tv_nsec can be zero. tv_sec cannot.
>
> > ---
> >  tools/testing/selftests/net/txtimestamp.c | 4 ++++
> >  1 file changed, 4 insertions(+)
> >
> > diff --git a/tools/testing/selftests/net/txtimestamp.c b/tools/testing/selftests/net/txtimestamp.c
> > index ec60a16c9307..b69aae840a67 100644
> > --- a/tools/testing/selftests/net/txtimestamp.c
> > +++ b/tools/testing/selftests/net/txtimestamp.c
> > @@ -358,6 +358,10 @@ static void __recv_errmsg_cmsg(struct msghdr *msg, int payload_len)
> >
> >       if (batch > 1)
> >               fprintf(stderr, "batched %d timestamps\n", batch);
> > +     else if (!batch) {
> > +             fprintf(stderr, "Failed to parse timestamps\n");
> > +             test_failed = true;
> > +     }
>
> nit: if adding braces around one side of a branch, then add to both (all).
>
> This is not so much a parsing failure as that no timestamps arrived.
>
> More importantly, this function gets called also if
> recvmsg(fd, .., MSG_ERRQUEUE) returned 0:
>
>         if (ret >= 0) {
>                 __recv_errmsg_cmsg(&msg, ret);
>
> That seems counterintuitive, as there is no data. But this was
> introduced with cfg_loop_nodata (SOF_TIMESTAMPING_OPT_TSONLY). When
> there may be packets looped, just 0B packets. In those cases we also
> expect timestamps.
>
> But, can __recv_errmsg_cmsg now also be called when there truly is
> nothing on the error queue? It is a non-blocking read, after all.

Today I re-read this paragraph. I think we were just past each other.

I would like to check that if the reporting timestamp with someone's
patch applied someday wouldn't work, the txtimestamp should return
failure to warn the submitter. That is to say, we succeed to generate
the skb with timestamp but failed to report it like this:

diff --git a/net/ipv4/tcp.c b/net/ipv4/tcp.c
index 8a5680b4e786..65f7947322cd 100644
--- a/net/ipv4/tcp.c
+++ b/net/ipv4/tcp.c
@@ -2274,7 +2274,7 @@ void tcp_recv_timestamp(struct msghdr *msg,
const struct sock *sk,
                        }
                }

-               if (READ_ONCE(sk->sk_tsflags) & SOF_TIMESTAMPING_SOFTWARE)
+               if (!(READ_ONCE(sk->sk_tsflags) & SOF_TIMESTAMPING_SOFTWARE))
                        has_timestamping = true;
                else
                        tss->ts[0] = (struct timespec64) {0};

which I intentionally wrote is used to show one stupid bug as an
example. The txtimestamp test should spot it :)

Thanks,
Jason

Re: [PATCH net-next] selftests: return failure when timestamps can't be parsed

[Jason Xing]

On Thu, Sep 5, 2024 at 7:04 PM Jason Xing <kerneljasonxing@gmail.com> wrote:
>
> On Thu, Sep 5, 2024 at 5:16 AM Willem de Bruijn
> <willemdebruijn.kernel@gmail.com> wrote:
> >
> > Jason Xing wrote:
> > > From: Jason Xing <kernelxing@tencent.com>
> > >
> > > When I was trying to modify the tx timestamping feature, I found that
> > > running "./txtimestamp -4 -C -L 127.0.0.1" didn't reflect the fact
> > > properly.
> >
> > Did not reflect what fact? Sorry, I don't entirely follow the issue
> > you raise.
> >
> > > In this selftest file, we respectively test three tx generation flags.
> > > With the generation and report flag enabled, we expect that the timestamp
> > > must be returned to the userspace unless 1) generating the timestamp
> > > fails, 2) reporting the timestamp fails. So we should test if the
> > > timestamps can be read and parsed succuessfuly in txtimestamp.c, or
> >
> > typo: successfully
> >
> > > else there is a bug in the kernel.
> > >
> > > After adding the check so that running ./txtimestamp will reflect the
> > > result correctly like this if there is an error in kernel:
> > > protocol:     TCP
> > > payload:      10
> > > server port:  9000
> > >
> > > family:       INET
> > > test SND
> > >     USR: 1725458477 s 667997 us (seq=0, len=0)
> > > Failed to parse timestamps
> > >     USR: 1725458477 s 718128 us (seq=0, len=0)
> > > Failed to parse timestamps
> > >     USR: 1725458477 s 768273 us (seq=0, len=0)
> > > Failed to parse timestamps
> > >     USR: 1725458477 s 818416 us (seq=0, len=0)
> > > Failed to parse timestamps
> > > ...
> > >
> > > Signed-off-by: Jason Xing <kernelxing@tencent.com>
> > > ---
> > > I'm not sure if I should also check if the cur->tv_sec or cur->tv_nsec
> > > is zero in __print_timestamp(). Could it be valid when either of
> > > them is zero?
> >
> > tv_nsec can be zero. tv_sec cannot.
> >
> > > ---
> > >  tools/testing/selftests/net/txtimestamp.c | 4 ++++
> > >  1 file changed, 4 insertions(+)
> > >
> > > diff --git a/tools/testing/selftests/net/txtimestamp.c b/tools/testing/selftests/net/txtimestamp.c
> > > index ec60a16c9307..b69aae840a67 100644
> > > --- a/tools/testing/selftests/net/txtimestamp.c
> > > +++ b/tools/testing/selftests/net/txtimestamp.c
> > > @@ -358,6 +358,10 @@ static void __recv_errmsg_cmsg(struct msghdr *msg, int payload_len)
> > >
> > >       if (batch > 1)
> > >               fprintf(stderr, "batched %d timestamps\n", batch);
> > > +     else if (!batch) {
> > > +             fprintf(stderr, "Failed to parse timestamps\n");
> > > +             test_failed = true;
> > > +     }
> >
> > nit: if adding braces around one side of a branch, then add to both (all).
> >
> > This is not so much a parsing failure as that no timestamps arrived.
> >
> > More importantly, this function gets called also if
> > recvmsg(fd, .., MSG_ERRQUEUE) returned 0:
> >
> >         if (ret >= 0) {
> >                 __recv_errmsg_cmsg(&msg, ret);
> >
> > That seems counterintuitive, as there is no data. But this was
> > introduced with cfg_loop_nodata (SOF_TIMESTAMPING_OPT_TSONLY). When
> > there may be packets looped, just 0B packets. In those cases we also
> > expect timestamps.
> >
> > But, can __recv_errmsg_cmsg now also be called when there truly is
> > nothing on the error queue? It is a non-blocking read, after all.
>
> Today I re-read this paragraph. I think we were just past each other.
>
> I would like to check that if the reporting timestamp with someone's
> patch applied someday wouldn't work, the txtimestamp should return
> failure to warn the submitter. That is to say, we succeed to generate
> the skb with timestamp but failed to report it like this:
>
> diff --git a/net/ipv4/tcp.c b/net/ipv4/tcp.c
> index 8a5680b4e786..65f7947322cd 100644
> --- a/net/ipv4/tcp.c
> +++ b/net/ipv4/tcp.c
> @@ -2274,7 +2274,7 @@ void tcp_recv_timestamp(struct msghdr *msg,
> const struct sock *sk,
>                         }
>                 }
>
> -               if (READ_ONCE(sk->sk_tsflags) & SOF_TIMESTAMPING_SOFTWARE)
> +               if (!(READ_ONCE(sk->sk_tsflags) & SOF_TIMESTAMPING_SOFTWARE))
>                         has_timestamping = true;
>                 else
>                         tss->ts[0] = (struct timespec64) {0};

If so, rxtimestamp test will fail. Let me correct myself here.

>
> which I intentionally wrote is used to show one stupid bug as an
> example. The txtimestamp test should spot it :)

Sorry, not in tcp_recv_timestamp, but like in __sock_recv_timestamp:

j@@ -946,7 +946,7 @@ void __sock_recv_timestamp(struct msghdr *msg,
struct sock *sk,

        memset(&tss, 0, sizeof(tss));
        tsflags = READ_ONCE(sk->sk_tsflags);
-       if ((tsflags & SOF_TIMESTAMPING_SOFTWARE) &&
+       if (!(tsflags & SOF_TIMESTAMPING_SOFTWARE) &&
            ktime_to_timespec64_cond(skb->tstamp, tss.ts + 0))
                empty = 0;
        if (shhwtstamps &&

This error/bug cannot be noticed by txtimestamp before this patch.

It's just an example which helps me clarify my thoughts.

>
> Thanks,
> Jason