Re: [PATCH net] virtio_net: Do not pull payload in skb->head

[Guenter Roeck <linux@roeck-us.net>]

On 4/11/21 2:43 PM, Eric Dumazet wrote:
> On Sun, Apr 11, 2021 at 11:32 PM Guenter Roeck <linux@roeck-us.net> wrote:
>>
>> On 4/11/21 2:23 PM, Eric Dumazet wrote:
>>> On Sun, Apr 11, 2021 at 10:37 PM Guenter Roeck <linux@roeck-us.net> wrote:
>>>>
>>>> On 4/11/21 8:06 AM, Eric Dumazet wrote:
>>>>> On Sun, Apr 11, 2021 at 3:43 PM Guenter Roeck <linux@roeck-us.net> wrote:
>>>>>
>>>>>> This patch causes a virtio-net interface failure when booting sh4 images
>>>>>> in qemu. The test case is nothing special: Just try to get an IP address
>>>>>> using udhcpc. If it fails, udhcpc reports:
>>>>>>
>>>>>> udhcpc: started, v1.33.0
>>>>>> udhcpc: sending discover
>>>>>> FAIL
>>>>>>
>>>>>
>>>>> Can you investigate where the incoming packet is dropped ?
>>>>>
>>>>
>>>> Unless I am missing something, packets are not dropped. It looks more
>>>> like udhcpc gets bad indigestion in the receive path and exits immediately.
>>>> Plus, it doesn't happen all the time; sometimes it receives the discover
>>>> response and is able to obtain an IP address.
>>>>
>>>> Overall this is quite puzzling since udhcpc exits immediately when the problem
>>>> is seen, no matter which option I give it on the command line; it should not
>>>> really do that.
>>>
>>>
>>> Could you strace both cases and report differences you can spot ?
>>>
>>> strace -o STRACE -f -s 1000 udhcpc
>>>
>>
>> I'll give it a try. It will take a while; I'll need to add strace to my root
>> file systems first.
>>
>> As a quick hack, I added some debugging into the kernel; it looks like
>> the data part of the dhcp discover response may get lost with your patch
>> in place.
> 
> Data is not lost, the payload is whole contained in skb frags, which
> was expected from my patch.
> 
> Maybe this sh arch does something wrong in this case.
> 
> This could be checksuming...
> 
> Please check
> 
> nstat -n
> <run udhcpc>
> nstat
> 

Does that tell you anything ?

/ # nstat -n
/ # udhcpc -n -q
udhcpc: started, v1.33.0
udhcpc: sending discover
/ # nstat
#kernel
IpInReceives                    1                  0.0
IpInDelivers                    1                  0.0
UdpIgnoredMulti                 1                  0.0
IpExtInBcastPkts                1                  0.0
IpExtInOctets                   576                0.0
IpExtInBcastOctets              576                0.0
IpExtInNoECTPkts                1                  0.0

Also, one interesting detail is that the problem is not seen all the time,
even with your patch in place. Not sure if I mentioned that before. strace
output in the success case (same image, with patch in place) looks as follows.

130   write(2, "udhcpc: sending discover\n", 25) = 25
130   socket(AF_PACKET, SOCK_DGRAM, htons(ETH_P_IP)) = 6
130   bind(6, {sa_family=AF_PACKET, sll_protocol=htons(ETH_P_IP), sll_ifindex=if_nametoindex("eth0"), sll_hatype=ARPHRD_NETROM, sll_pkttype=PACKET_HOST, sll_halen=6, sll_addr=[0xff, 0xff, 0xff, 0xf
130   sendto(6, "E\0\1H\0\0\0\0@\21y\246\0\0\0\0\377\377\377\377\0D\0C\0014\227r\1\1\6\0\5\16\36P\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0RT\0\0224V\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0
130   close(6)                          = 0
130   fcntl64(5, F_SETFD, FD_CLOEXEC)   = 0
130   clock_gettime64(CLOCK_MONOTONIC, {tv_sec=25, tv_nsec=202168729}) = 0
130   poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 3000) = 1 ([{fd=5, revents=POLLIN}])
130   read(3, 0x7bf47a73, 1)            = -1 EAGAIN (Resource temporarily unavailable)
130   recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="E\20\2@\0\10\0\0@\21l\224\n\0\2\2\377\377\377\377\0C\0D\2,\230\23\2\1\6\0\5\16\36P\0\0\0\0\0\0\0\0\n\0\2\17\n\0\2\2\0\0\0\0RT\0\0
130   clock_gettime64(CLOCK_MONOTONIC, {tv_sec=25, tv_nsec=205504062}) = 0
130   fcntl64(5, F_SETFD, FD_CLOEXEC)   = 0
130   socket(AF_INET, SOCK_RAW, IPPROTO_RAW) = 6
130   ioctl(6, SIOCGIFINDEX, {ifr_name="eth0", }) = 0
130   ioctl(6, SIOCGIFHWADDR, {ifr_name="eth0", ifr_hwaddr={sa_family=ARPHRD_ETHER, sa_data=52:54:00:12:34:56}}) = 0
130   close(6)                          = 0
130   clock_gettime64(CLOCK_MONOTONIC, {tv_sec=25, tv_nsec=208676862}) = 0
130   write(2, "udhcpc: sending select for 10.0.2.15\n", 37) = 37
130   socket(AF_PACKET, SOCK_DGRAM, htons(ETH_P_IP)) = 6
130   bind(6, {sa_family=AF_PACKET, sll_protocol=htons(ETH_P_IP), sll_ifindex=if_nametoindex("eth0"), sll_hatype=ARPHRD_NETROM, sll_pkttype=PACKET_HOST, sll_halen=6, sll_addr=[0xff, 0xff, 0xff, 0xf
130   sendto(6, "E\0\1H\0\0\0\0@\21y\246\0\0\0\0\377\377\377\377\0D\0C\0014\25Y\1\1\6\0\5\16\36P\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0RT\0\0224V\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\
130   close(6)                          = 0
130   fcntl64(5, F_SETFD, FD_CLOEXEC)   = 0
130   clock_gettime64(CLOCK_MONOTONIC, {tv_sec=25, tv_nsec=213060729}) = 0
130   poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 3000) = 1 ([{fd=5, revents=POLLIN}])
130   read(3, 0x7bf47a73, 1)            = -1 EAGAIN (Resource temporarily unavailable)
130   recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="E\20\2@\0\t\0\0@\21l\223\n\0\2\2\377\377\377\377\0C\0D\2,\225\23\2\1\6\0\5\16\36P\0\0\0\0\0\0\0\0\n\0\2\17\n\0\2\2\0\0\0\0RT\0\02
130   clock_gettime64(CLOCK_MONOTONIC, {tv_sec=25, tv_nsec=215453662}) = 0
130   write(2, "udhcpc: lease of 10.0.2.15 obtained, lease time 86400\n", 54) = 54

In that case, the output of nstat is as follows.

/ # nstat
#kernel
IpInReceives                    2                  0.0
IpInDelivers                    2                  0.0
UdpIgnoredMulti                 2                  0.0
IpExtInBcastPkts                2                  0.0
IpExtInOctets                   1152               0.0
IpExtInBcastOctets              1152               0.0
IpExtInNoECTPkts                2                  0.0

Guenter