Re: [Linuxptp-devel] [PATCH 2/3] clock: Dump unexpected packets received on the error queues of sockets
> -Original Message-
> From: Vladimir Oltean
> Sent: Tuesday, December 17, 2019 12:34 PM
> To: Keller, Jacob E
> Cc: richardcoch...@gmail.com; linuxptp-devel@lists.sourceforge.net
> Subject: Re: [Linuxptp-devel] [PATCH 2/3] clock: Dump unexpected packets
> received on the error queues of sockets
>
> On Tue, 17 Dec 2019 at 22:04, Keller, Jacob E
> wrote:
>
> > > -Original Message-
> > > From: Vladimir Oltean
> > > Sent: Monday, December 16, 2019 3:11 PM
> > > To: richardcoch...@gmail.com
> > > Cc: linuxptp-devel@lists.sourceforge.net
> > > Subject: [Linuxptp-devel] [PATCH 2/3] clock: Dump unexpected packets
> received
> > > on the error queues of sockets
> > > For messages that the application does not / no longer expects, such as
> > > TX timestamps delivered late, duplicate TX timestamps, general
> > > exceptional messages enqueued by the kernel in the socket error queue
> > > etc, ptp4l will be taken by surprise in clock_poll() by these, and will
> > > think that there is data, since POLLIN is set (but in fact in the socket
> > > error queue etc, ptp4l will be taken by surprise in clock_poll() by
> > > these, and will think that there is data, since POLLIN is set (but in
> > > fact POLLERR is also set, and this has an entirely different meaning).
> >
> > This double parenthetical is a bit hard to parse.
> >
>
> Sorry, this is hard for me to understand too. The paragraph should have been:
>
> For messages that the application does not / no longer expects, such as
> TX timestamps delivered late, duplicate TX timestamps, general
> exceptional messages enqueued by the kernel in the socket error queue
> etc, ptp4l will be taken by surprise in clock_poll() by these, and will
> think that there is data, since POLLIN is set (but in fact POLLERR is
> also set, and this has an entirely different meaning), and will attempt
> to dequeue them from the wrong queue, which is empty.
>
That sounds better. It still feels a bit like a run-on sentence. Maybe
something like:
For messages that the application does not / no longer expects, such as Tx
timestamps delivered late, duplicate Tx timestamps, or general exceptional
messages enqueued by the kernel in the socket error queue, ptp4l will be taken
by surprise in clock_poll(). It will think there is data, since POLLIN is set.
In fact, POLLERR is also set which gives an entirely different meaning. Because
of this, ptp4l will attempt to dequeue messages from the wrong (empty) queue.
>
> > >
> > > A very, very simple reproducer is to take a DSA switch and run:
> > >
> > > tcpdump -i eth0 -j adapter_unsynced
> > >
> > > on its DSA master net device. The above command will enable timestamping
> > > on that net device, and if both the DSA switch and the master support
> > > PTP, this will make the kernel send duplicate TX timestamps for every
> > > sent event packet, which will completely kill ptp4l until a reboot, with
> > > no indication whatsoever of what's going on.
> > >
> > > Since the messages on the error queue are unexpected, we have no need
> > > for them. And they can be in theory anything, so simply hex dumping
> > > their content and moving along sounds like a good idea.
> > >
> > > Printing them to the user is optional (and helpful), but reading them is
> > > not. With this patch, even with extraneous data delivered by a buggy
> > > kernel (which the application now loudly complains about), the
> > > synchronization keeps chugging along. Otherwise the application starts
> > > reordering packets in recvmsg() due to misinterpreting which socket
> > > queue has data available.
> > >
> > > Signed-off-by: Vladimir Oltean
> > > ---
> > > clock.c | 11 +++
> > > msg.c | 12
> > > msg.h | 7 +++
> > > 3 files changed, 30 insertions(+)
> > >
> > > diff --git a/clock.c b/clock.c
> > > index 146576ac589c..768bbb49513d 100644
> > > --- a/clock.c
> > > +++ b/clock.c
> > > @@ -1508,6 +1508,17 @@ int clock_poll(struct clock *c)
> > > LIST_FOREACH(p, >ports, list) {
> > > /* Let the ports handle their events. */
> > > for (i = 0; i < N_POLLFD; i++) {
> > > + if (cur[i].revents & POLLERR) {
> > > + unsigned char pkt[1600];
> > > +
> > > + cnt = recv(cur[i].fd, pkt, sizeof(pkt),
> > > +MSG_ERRQUEUE);
> > > + pr_err("Unexpected data on socket err
> > > queue:");
> > > + msg_raw_dump(pkt, cnt);
> > > +
> > > + continue;
> > > + }
> > > +
> >
> > Does it makes sense to always print these at pr_err level? I suppose we
> > almost
> never expect messages besides Tx timestamps, so warning loudly is better than
> only warning if you enable the higher debug printing.. However.. with this
> change
> it almost feels like these are now ignored/handled properly and thus not an
Re: [Linuxptp-devel] [PATCH 2/3] clock: Dump unexpected packets received on the error queues of sockets
On Tue, 17 Dec 2019 at 22:04, Keller, Jacob E wrote:
> > -Original Message-
> > From: Vladimir Oltean
> > Sent: Monday, December 16, 2019 3:11 PM
> > To: richardcoch...@gmail.com
> > Cc: linuxptp-devel@lists.sourceforge.net
> > Subject: [Linuxptp-devel] [PATCH 2/3] clock: Dump unexpected packets
> > received
> > on the error queues of sockets
> > For messages that the application does not / no longer expects, such as
> > TX timestamps delivered late, duplicate TX timestamps, general
> > exceptional messages enqueued by the kernel in the socket error queue
> > etc, ptp4l will be taken by surprise in clock_poll() by these, and will
> > think that there is data, since POLLIN is set (but in fact in the socket
> > error queue etc, ptp4l will be taken by surprise in clock_poll() by
> > these, and will think that there is data, since POLLIN is set (but in
> > fact POLLERR is also set, and this has an entirely different meaning).
>
> This double parenthetical is a bit hard to parse.
>
Sorry, this is hard for me to understand too. The paragraph should have been:
For messages that the application does not / no longer expects, such as
TX timestamps delivered late, duplicate TX timestamps, general
exceptional messages enqueued by the kernel in the socket error queue
etc, ptp4l will be taken by surprise in clock_poll() by these, and will
think that there is data, since POLLIN is set (but in fact POLLERR is
also set, and this has an entirely different meaning), and will attempt
to dequeue them from the wrong queue, which is empty.
> >
> > A very, very simple reproducer is to take a DSA switch and run:
> >
> > tcpdump -i eth0 -j adapter_unsynced
> >
> > on its DSA master net device. The above command will enable timestamping
> > on that net device, and if both the DSA switch and the master support
> > PTP, this will make the kernel send duplicate TX timestamps for every
> > sent event packet, which will completely kill ptp4l until a reboot, with
> > no indication whatsoever of what's going on.
> >
> > Since the messages on the error queue are unexpected, we have no need
> > for them. And they can be in theory anything, so simply hex dumping
> > their content and moving along sounds like a good idea.
> >
> > Printing them to the user is optional (and helpful), but reading them is
> > not. With this patch, even with extraneous data delivered by a buggy
> > kernel (which the application now loudly complains about), the
> > synchronization keeps chugging along. Otherwise the application starts
> > reordering packets in recvmsg() due to misinterpreting which socket
> > queue has data available.
> >
> > Signed-off-by: Vladimir Oltean
> > ---
> > clock.c | 11 +++
> > msg.c | 12
> > msg.h | 7 +++
> > 3 files changed, 30 insertions(+)
> >
> > diff --git a/clock.c b/clock.c
> > index 146576ac589c..768bbb49513d 100644
> > --- a/clock.c
> > +++ b/clock.c
> > @@ -1508,6 +1508,17 @@ int clock_poll(struct clock *c)
> > LIST_FOREACH(p, >ports, list) {
> > /* Let the ports handle their events. */
> > for (i = 0; i < N_POLLFD; i++) {
> > + if (cur[i].revents & POLLERR) {
> > + unsigned char pkt[1600];
> > +
> > + cnt = recv(cur[i].fd, pkt, sizeof(pkt),
> > +MSG_ERRQUEUE);
> > + pr_err("Unexpected data on socket err
> > queue:");
> > + msg_raw_dump(pkt, cnt);
> > +
> > + continue;
> > + }
> > +
>
> Does it makes sense to always print these at pr_err level? I suppose we
> almost never expect messages besides Tx timestamps, so warning loudly is
> better than only warning if you enable the higher debug printing.. However..
> with this change it almost feels like these are now ignored/handled properly
> and thus not an issue so printing them at like pr_debug might make more sense?
For my particular case, this is dead code because of the kernel fix.
The other "[PATCH 3/3] port: Signal sync/follow-up mismatch events
loudly" is dead code because of this one.
For anybody else, I suppose that this is the beginning of the end of
what ptp4l will tell them anyway. So I'm not too concerned that it's
too loud. It isn't guarded by anything else, it is the other way
around. First you poll on the fd, then you recvmsg and process it to
see what it is.
>
> Hmm. I think I'm fine with this either way.
>
> Thanks,
> Jake
Thanks,
-Vladimir
___
Linuxptp-devel mailing list
Linuxptp-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/linuxptp-devel
Re: [Linuxptp-devel] [PATCH 3/3] port: Signal sync/follow-up mismatch events loudly
> -Original Message- > From: Vladimir Oltean > Sent: Monday, December 16, 2019 3:11 PM > To: richardcoch...@gmail.com > Cc: linuxptp-devel@lists.sourceforge.net > Subject: [Linuxptp-devel] [PATCH 3/3] port: Signal sync/follow-up mismatch > events loudly > > Ptp4l is too silent when receiving, for whatever reason, out of order > messages. If the reordering is persistent (which is either a broken > network, or a broken kernel), the behavior looks like a complete > synchronization stall, since the application is designed to never > attempt to recover from such a condition. > > At least save some people some debugging hours and be loud when the > application reaches this code path. > Excellent! This one makes sense to me. Thanks, Jake ___ Linuxptp-devel mailing list Linuxptp-devel@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/linuxptp-devel
Re: [Linuxptp-devel] [PATCH 1/3] ptp4l: Call recvmsg() with the MSG_DONTWAIT flag
> -Original Message-
> From: Vladimir Oltean
> Sent: Monday, December 16, 2019 3:10 PM
> To: richardcoch...@gmail.com
> Cc: linuxptp-devel@lists.sourceforge.net
> Subject: [Linuxptp-devel] [PATCH 1/3] ptp4l: Call recvmsg() with the
> MSG_DONTWAIT flag
>
> The application's main event loop (clock_poll) is woken up by poll() and
> dispatches the socket receive queue events to the corresponding ports as
> needed.
>
> So it is a bug if poll() wakes up the process for data availability on a
> socket's receive queue, and then recvmsg(), called immediately
> afterwards, goes to sleep trying to retrieve it. This patch will
> generate an error that will be propagated to the user if this condition
> happens.
>
> Can it happen?
>
> As of this patch, ptp4l uses the SO_SELECT_ERR_QUEUE socket option,
> which means that poll() will wake the process up, with revents ==
> (POLLIN | POLLERR), if data is available in the error queue. But
> clock_poll() does not check POLLERR, just POLLIN, and draws the wrong
> conclusion that there is data available in the receive queue (when it is
> in fact available in the error queue).
>
> When the above condition happens, recvmsg() will sleep typically for a
> whole sync interval waiting for data on the event socket, and will be
> woken up when the new real frame arrives. It will not dequeue follow-up
> messages during this time (which are sent to the general message socket)
> and when it does, it will already be late for them (their seqid will be
> out of order). So it will drop them and everything that comes after. The
> synchronization process will fail.
>
> The above condition shouldn't typically happen, but exceptional kernel
> events will trigger it. It helps to be strict in ptp4l in order for
> those events to not blow up in even stranger symptoms unrelated to the
> root cause of the problem.
>
Yep, makes sense.
> Signed-off-by: Vladimir Oltean
> ---
> raw.c | 2 +-
> udp.c | 2 +-
> udp6.c | 2 +-
> 3 files changed, 3 insertions(+), 3 deletions(-)
>
> diff --git a/raw.c b/raw.c
> index f1c92b9f8d90..c0a8cd80855f 100644
> --- a/raw.c
> +++ b/raw.c
> @@ -278,7 +278,7 @@ static int raw_recv(struct transport *t, int fd, void
> *buf, int
> buflen,
> buflen += hlen;
> hdr = (struct eth_hdr *) ptr;
>
> - cnt = sk_receive(fd, ptr, buflen, addr, hwts, 0);
> + cnt = sk_receive(fd, ptr, buflen, addr, hwts, MSG_DONTWAIT);
>
So basically we just indicate that we do not want to sleep. Good.
This makes sense to me.
Thanks,
Jake
> if (cnt >= 0)
> cnt -= hlen;
> diff --git a/udp.c b/udp.c
> index 48af482b4526..eb1617872f37 100644
> --- a/udp.c
> +++ b/udp.c
> @@ -210,7 +210,7 @@ no_event:
> static int udp_recv(struct transport *t, int fd, void *buf, int buflen,
> struct address *addr, struct hw_timestamp *hwts)
> {
> - return sk_receive(fd, buf, buflen, addr, hwts, 0);
> + return sk_receive(fd, buf, buflen, addr, hwts, MSG_DONTWAIT);
> }
>
> static int udp_send(struct transport *t, struct fdarray *fda,
> diff --git a/udp6.c b/udp6.c
> index 74ebc7f0cf09..06c6fad2160f 100644
> --- a/udp6.c
> +++ b/udp6.c
> @@ -227,7 +227,7 @@ no_event:
> static int udp6_recv(struct transport *t, int fd, void *buf, int buflen,
>struct address *addr, struct hw_timestamp *hwts)
> {
> - return sk_receive(fd, buf, buflen, addr, hwts, 0);
> + return sk_receive(fd, buf, buflen, addr, hwts, MSG_DONTWAIT);
> }
>
> static int udp6_send(struct transport *t, struct fdarray *fda,
> --
> 2.17.1
>
>
>
> ___
> Linuxptp-devel mailing list
> Linuxptp-devel@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/linuxptp-devel
___
Linuxptp-devel mailing list
Linuxptp-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/linuxptp-devel
Re: [Linuxptp-devel] [PATCH 0/3] More strict checking against kernel bugs
> -Original Message- > From: Vladimir Oltean > Sent: Monday, December 16, 2019 3:10 PM > To: richardcoch...@gmail.com > Cc: linuxptp-devel@lists.sourceforge.net > Subject: [Linuxptp-devel] [PATCH 0/3] More strict checking against kernel bugs > > The reordering issue reported by me initially on the linuxptp-devel > list [0] with the sja1105 DSA driver turned out not to be a reordering > issue at all, in fact. > > Due to a kernel bug described in this patch [1], the DSA driver was in > race with the master Ethernet driver and would occasionally (very > rarely) deliver 2 TX timestamps to ptp4l on the event socket. > > The first TX timestamp is consumed in-band in the raw_send function. > The second is caught by the main poll() syscall in the main ptp4l event > loop - clock_poll(). > > When poll() sees the second TX-timestamped skb, it returns with revents > == (POLLIN | POLLERR). But the main loop only checks for POLLIN, and > says "yay, there's data!". So it proceeds to call recvmsg() with flags=0 > (instead of MSG_ERRQUEUE), so it doesn't see any data in > sk->sk_receive_queue. So, surprise, false alarm, the data that woke it > up was in sk->sk_error_queue. The ptp4l process goes to sleep waiting > for data. > > It sleeps for a whole sync interval. > > When it wakes up, it wakes up with the next sync, even though the > previous sync's follow-up may have arrived in the meantime. > > Apparent reordering. > > Ptp4l does not print anything, it just appears to freeze. > > So this patch set aims to improves the error reporting in ptp4l, such > that tracing back to the root cause is easier next time, and the problem > does not blow up into other, completely unrelated things. > Nice analysis. Thanks, Jake > [0]: https://sourceforge.net/p/linuxptp/mailman/message/36773629/ > [1]: https://patchwork.ozlabs.org/patch/1210871/ > > Vladimir Oltean (3): > ptp4l: Call recvmsg() with the MSG_DONTWAIT flag > clock: Dump unexpected packets received on the error queues of sockets > port: Signal sync/follow-up mismatch events loudly > > clock.c | 11 +++ > msg.c | 12 > msg.h | 7 +++ > port.c | 21 + > raw.c | 2 +- > udp.c | 2 +- > udp6.c | 2 +- > 7 files changed, 54 insertions(+), 3 deletions(-) > > -- > 2.17.1 > > > > ___ > Linuxptp-devel mailing list > Linuxptp-devel@lists.sourceforge.net > https://lists.sourceforge.net/lists/listinfo/linuxptp-devel ___ Linuxptp-devel mailing list Linuxptp-devel@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/linuxptp-devel
