diff mbox series

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

Message ID 20240904144446.41274-1-kerneljasonxing@gmail.com (mailing list archive)
State Changes Requested
Delegated to: Netdev Maintainers
Headers show
Series [net-next] selftests: return failure when timestamps can't be parsed | expand

Checks

Context Check Description
netdev/series_format success Single patches do not need cover letters
netdev/tree_selection success Clearly marked for net-next
netdev/ynl success Generated files up to date; no warnings/errors; no diff in generated;
netdev/fixes_present success Fixes tag not required for -next series
netdev/header_inline success No static functions without inline keyword in header files
netdev/build_32bit success Errors and warnings before: 7 this patch: 7
netdev/build_tools success Errors and warnings before: 0 this patch: 0
netdev/cc_maintainers success CCed 6 of 6 maintainers
netdev/build_clang success Errors and warnings before: 7 this patch: 7
netdev/verify_signedoff success Signed-off-by tag matches author and committer
netdev/deprecated_api success None detected
netdev/check_selftest success No net selftest shell script
netdev/verify_fixes success No Fixes tag
netdev/build_allmodconfig_warn success Errors and warnings before: 7 this patch: 7
netdev/checkpatch success total: 0 errors, 0 warnings, 0 checks, 10 lines checked
netdev/build_clang_rust success No Rust files in patch. Skipping build
netdev/kdoc success Errors and warnings before: 0 this patch: 0
netdev/source_inline success Was 0 now: 0
netdev/contest success net-next-2024-09-04--21-00 (tests: 718)

Commit Message

Jason Xing Sept. 4, 2024, 2:44 p.m. UTC
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(+)

Comments

Willem de Bruijn Sept. 4, 2024, 9:16 p.m. UTC | #1
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
>
Jason Xing Sept. 4, 2024, 9:49 p.m. UTC | #2
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
Jason Xing Sept. 5, 2024, 11:04 a.m. UTC | #3
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
Jason Xing Sept. 5, 2024, 1:40 p.m. UTC | #4
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
diff mbox series

Patch

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)