Unexpected PACKET_TX_TIMESTAMP Messages

Unexpected PACKET_TX_TIMESTAMP Messages

[Matt Sandy]

I've been playing around with raw sockets and timestamps, but seem to
be getting strange timestamp data back on the errqueue. Specifically,
if I am creating a socket(AF_PACKET, SOCK_RAW, htons(ETH_P_IP)) and
requesting SO_TIMESTAMPING_NEW with options 0x4DF. I am not modifying
the flags with control messages.

On both send and receive, I get the expected
SOL_SOCKET/SO_TIMESTAMPING_NEW cmsg (in errqueue on send, in the
message itself on receive), and it contains what appears to be valid
timestamps in the ts[0] field. On send, however, I receive an
additional cmsg with level = SOL_PACKET/PACKET_TX_TIMESTAMP, whose
content is just the fixed value `char[16] { 42, 0, 0, 0, 4, <zeros>
}`.

Any ideas why I'd be getting the SOL_PACKET message on transmit, and
why its payload is clearly not a valid timestamp? In case it matters,
this is on an Intel I210 nic using the igb driver.

Re: Unexpected PACKET_TX_TIMESTAMP Messages

[Willem de Bruijn]

On Fri, Jul 17, 2020 at 1:52 PM Matt Sandy <mooseboys@gmail.com> wrote:
>
> I've been playing around with raw sockets and timestamps, but seem to
> be getting strange timestamp data back on the errqueue. Specifically,
> if I am creating a socket(AF_PACKET, SOCK_RAW, htons(ETH_P_IP)) and
> requesting SO_TIMESTAMPING_NEW with options 0x4DF. I am not modifying
> the flags with control messages.
>
> On both send and receive, I get the expected
> SOL_SOCKET/SO_TIMESTAMPING_NEW cmsg (in errqueue on send, in the
> message itself on receive), and it contains what appears to be valid
> timestamps in the ts[0] field. On send, however, I receive an
> additional cmsg with level = SOL_PACKET/PACKET_TX_TIMESTAMP, whose
> content is just the fixed value `char[16] { 42, 0, 0, 0, 4, <zeros>
> }`.
>
> Any ideas why I'd be getting the SOL_PACKET message on transmit, and
> why its payload is clearly not a valid timestamp? In case it matters,
> this is on an Intel I210 nic using the igb driver.

This is not a char[16], but a struct sock_extended_err.

The first four bytes correspond to __u32 ee_errno, where 42 is ENOMSG.
The fifth byte is __u8 ee_origin, where 4 corresponds to
SO_EE_ORIGIN_TIMESTAMPING.

This is metadata stored along with the skb by __skb_complete_tx_timestamp.
This helps demultiplex timestamps received from the error queue from
other messages.

Additionally, in the case of timestamps it may include additional
associated information:

        serr->ee.ee_info = tstype;
        serr->opt_stats = opt_stats;
        serr->header.h4.iif = skb->dev ? skb->dev->ifindex : 0;
        if (sk->sk_tsflags & SOF_TIMESTAMPING_OPT_ID) {
                serr->ee.ee_data = skb_shinfo(skb)->tskey;
                if (sk->sk_protocol == IPPROTO_TCP &&
                    sk->sk_type == SOCK_STREAM)
                        serr->ee.ee_data -= sk->sk_tskey;
        }

The fact that the field after ee_origin is zero means that this is a
timestamp captured at device transmit (SCM_TSTAMP_SND), for instance.

The csmg_level and type themselves are chosen on recv errqueue in
packet_recvmsg:

        if (flags & MSG_ERRQUEUE) {
                err = sock_recv_errqueue(sk, msg, len,
                                         SOL_PACKET, PACKET_TX_TIMESTAMP);
                goto out;
        }

Re: Unexpected PACKET_TX_TIMESTAMP Messages

[Matt Sandy]

Got it, thanks! This makes a lot more sense. tl;dr: it's metadata
about the corresponding SOL_SOCKET/SO_TIMESTAMPING cmsg. It also looks
like passing OPT_ID as a socket option should auto-increment the
ee_data field on send. This was the first message sent on the socket
though so I'd expect zero anyway.

On Fri, Jul 17, 2020 at 3:51 PM Willem de Bruijn
<willemdebruijn.kernel@gmail.com> wrote:
>
> On Fri, Jul 17, 2020 at 1:52 PM Matt Sandy <mooseboys@gmail.com> wrote:
> >
> > I've been playing around with raw sockets and timestamps, but seem to
> > be getting strange timestamp data back on the errqueue. Specifically,
> > if I am creating a socket(AF_PACKET, SOCK_RAW, htons(ETH_P_IP)) and
> > requesting SO_TIMESTAMPING_NEW with options 0x4DF. I am not modifying
> > the flags with control messages.
> >
> > On both send and receive, I get the expected
> > SOL_SOCKET/SO_TIMESTAMPING_NEW cmsg (in errqueue on send, in the
> > message itself on receive), and it contains what appears to be valid
> > timestamps in the ts[0] field. On send, however, I receive an
> > additional cmsg with level = SOL_PACKET/PACKET_TX_TIMESTAMP, whose
> > content is just the fixed value `char[16] { 42, 0, 0, 0, 4, <zeros>
> > }`.
> >
> > Any ideas why I'd be getting the SOL_PACKET message on transmit, and
> > why its payload is clearly not a valid timestamp? In case it matters,
> > this is on an Intel I210 nic using the igb driver.
>
> This is not a char[16], but a struct sock_extended_err.
>
> The first four bytes correspond to __u32 ee_errno, where 42 is ENOMSG.
> The fifth byte is __u8 ee_origin, where 4 corresponds to
> SO_EE_ORIGIN_TIMESTAMPING.
>
> This is metadata stored along with the skb by __skb_complete_tx_timestamp.
> This helps demultiplex timestamps received from the error queue from
> other messages.
>
> Additionally, in the case of timestamps it may include additional
> associated information:
>
>         serr->ee.ee_info = tstype;
>         serr->opt_stats = opt_stats;
>         serr->header.h4.iif = skb->dev ? skb->dev->ifindex : 0;
>         if (sk->sk_tsflags & SOF_TIMESTAMPING_OPT_ID) {
>                 serr->ee.ee_data = skb_shinfo(skb)->tskey;
>                 if (sk->sk_protocol == IPPROTO_TCP &&
>                     sk->sk_type == SOCK_STREAM)
>                         serr->ee.ee_data -= sk->sk_tskey;
>         }
>
> The fact that the field after ee_origin is zero means that this is a
> timestamp captured at device transmit (SCM_TSTAMP_SND), for instance.
>
> The csmg_level and type themselves are chosen on recv errqueue in
> packet_recvmsg:
>
>         if (flags & MSG_ERRQUEUE) {
>                 err = sock_recv_errqueue(sk, msg, len,
>                                          SOL_PACKET, PACKET_TX_TIMESTAMP);
>                 goto out;
>         }