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

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

[Eric Dumazet]

From: Eric Dumazet <edumazet@google.com>

Xuan Zhuo reported that commit 3226b158e67c ("net: avoid 32 x truesize
under-estimation for tiny skbs") brought  a ~10% performance drop.

The reason for the performance drop was that GRO was forced
to chain sk_buff (using skb_shinfo(skb)->frag_list), which
uses more memory but also cause packet consumers to go over
a lot of overhead handling all the tiny skbs.

It turns out that virtio_net page_to_skb() has a wrong strategy :
It allocates skbs with GOOD_COPY_LEN (128) bytes in skb->head, then
copies 128 bytes from the page, before feeding the packet to GRO stack.

This was suboptimal before commit 3226b158e67c ("net: avoid 32 x truesize
under-estimation for tiny skbs") because GRO was using 2 frags per MSS,
meaning we were not packing MSS with 100% efficiency.

Fix is to pull only the ethernet header in page_to_skb()

Then, we change virtio_net_hdr_to_skb() to pull the missing
headers, instead of assuming they were already pulled by callers.

This fixes the performance regression, but could also allow virtio_net
to accept packets with more than 128bytes of headers.

Many thanks to Xuan Zhuo for his report, and his tests/help.

Fixes: 3226b158e67c ("net: avoid 32 x truesize under-estimation for tiny skbs")
Reported-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
Link: https://www.spinics.net/lists/netdev/msg731397.html
Co-Developed-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
Signed-off-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
Signed-off-by: Eric Dumazet <edumazet@google.com>
Cc: "Michael S. Tsirkin" <mst@redhat.com>
Cc: Jason Wang <jasowang@redhat.com>
Cc: virtualization@lists.linux-foundation.org
---
 drivers/net/virtio_net.c   | 10 +++++++---
 include/linux/virtio_net.h | 14 +++++++++-----
 2 files changed, 16 insertions(+), 8 deletions(-)

diff --git a/drivers/net/virtio_net.c b/drivers/net/virtio_net.c
index 82e520d2cb1229a0c7b9fd0def3e4a7135536478..0824e6999e49957f7aaf7c990f6259792d42f32b 100644
--- a/drivers/net/virtio_net.c
+++ b/drivers/net/virtio_net.c
@@ -406,9 +406,13 @@ static struct sk_buff *page_to_skb(struct virtnet_info *vi,
 	offset += hdr_padded_len;
 	p += hdr_padded_len;
 
-	copy = len;
-	if (copy > skb_tailroom(skb))
-		copy = skb_tailroom(skb);
+	/* Copy all frame if it fits skb->head, otherwise
+	 * we let virtio_net_hdr_to_skb() and GRO pull headers as needed.
+	 */
+	if (len <= skb_tailroom(skb))
+		copy = len;
+	else
+		copy = ETH_HLEN + metasize;
 	skb_put_data(skb, p, copy);
 
 	if (metasize) {
diff --git a/include/linux/virtio_net.h b/include/linux/virtio_net.h
index 98775d7fa69632e2c2da30b581a666f7fbb94b64..b465f8f3e554f27ced45c35f54f113cf6dce1f07 100644
--- a/include/linux/virtio_net.h
+++ b/include/linux/virtio_net.h
@@ -65,14 +65,18 @@ static inline int virtio_net_hdr_to_skb(struct sk_buff *skb,
 	skb_reset_mac_header(skb);
 
 	if (hdr->flags & VIRTIO_NET_HDR_F_NEEDS_CSUM) {
-		u16 start = __virtio16_to_cpu(little_endian, hdr->csum_start);
-		u16 off = __virtio16_to_cpu(little_endian, hdr->csum_offset);
+		u32 start = __virtio16_to_cpu(little_endian, hdr->csum_start);
+		u32 off = __virtio16_to_cpu(little_endian, hdr->csum_offset);
+		u32 needed = start + max_t(u32, thlen, off + sizeof(__sum16));
+
+		if (!pskb_may_pull(skb, needed))
+			return -EINVAL;
 
 		if (!skb_partial_csum_set(skb, start, off))
 			return -EINVAL;
 
 		p_off = skb_transport_offset(skb) + thlen;
-		if (p_off > skb_headlen(skb))
+		if (!pskb_may_pull(skb, p_off))
 			return -EINVAL;
 	} else {
 		/* gso packets without NEEDS_CSUM do not set transport_offset.
@@ -102,14 +106,14 @@ static inline int virtio_net_hdr_to_skb(struct sk_buff *skb,
 			}
 
 			p_off = keys.control.thoff + thlen;
-			if (p_off > skb_headlen(skb) ||
+			if (!pskb_may_pull(skb, p_off) ||
 			    keys.basic.ip_proto != ip_proto)
 				return -EINVAL;
 
 			skb_set_transport_header(skb, keys.control.thoff);
 		} else if (gso_type) {
 			p_off = thlen;
-			if (p_off > skb_headlen(skb))
+			if (!pskb_may_pull(skb, p_off))
 				return -EINVAL;
 		}
 	}
-- 
2.31.0.208.g409f899ff0-goog

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

[Jason Wang]

在 2021/4/2 下午9:26, Eric Dumazet 写道:
> From: Eric Dumazet <edumazet@google.com>
>
> Xuan Zhuo reported that commit 3226b158e67c ("net: avoid 32 x truesize
> under-estimation for tiny skbs") brought  a ~10% performance drop.
>
> The reason for the performance drop was that GRO was forced
> to chain sk_buff (using skb_shinfo(skb)->frag_list), which
> uses more memory but also cause packet consumers to go over
> a lot of overhead handling all the tiny skbs.
>
> It turns out that virtio_net page_to_skb() has a wrong strategy :
> It allocates skbs with GOOD_COPY_LEN (128) bytes in skb->head, then
> copies 128 bytes from the page, before feeding the packet to GRO stack.
>
> This was suboptimal before commit 3226b158e67c ("net: avoid 32 x truesize
> under-estimation for tiny skbs") because GRO was using 2 frags per MSS,
> meaning we were not packing MSS with 100% efficiency.
>
> Fix is to pull only the ethernet header in page_to_skb()
>
> Then, we change virtio_net_hdr_to_skb() to pull the missing
> headers, instead of assuming they were already pulled by callers.
>
> This fixes the performance regression, but could also allow virtio_net
> to accept packets with more than 128bytes of headers.
>
> Many thanks to Xuan Zhuo for his report, and his tests/help.
>
> Fixes: 3226b158e67c ("net: avoid 32 x truesize under-estimation for tiny skbs")
> Reported-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
> Link: https://www.spinics.net/lists/netdev/msg731397.html
> Co-Developed-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
> Signed-off-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
> Signed-off-by: Eric Dumazet <edumazet@google.com>
> Cc: "Michael S. Tsirkin" <mst@redhat.com>
> Cc: Jason Wang <jasowang@redhat.com>
> Cc: virtualization@lists.linux-foundation.org
> ---


Acked-by: Jason Wang <jasowang@redhat.com>


>   drivers/net/virtio_net.c   | 10 +++++++---
>   include/linux/virtio_net.h | 14 +++++++++-----
>   2 files changed, 16 insertions(+), 8 deletions(-)
>
> diff --git a/drivers/net/virtio_net.c b/drivers/net/virtio_net.c
> index 82e520d2cb1229a0c7b9fd0def3e4a7135536478..0824e6999e49957f7aaf7c990f6259792d42f32b 100644
> --- a/drivers/net/virtio_net.c
> +++ b/drivers/net/virtio_net.c
> @@ -406,9 +406,13 @@ static struct sk_buff *page_to_skb(struct virtnet_info *vi,
>   	offset += hdr_padded_len;
>   	p += hdr_padded_len;
>   
> -	copy = len;
> -	if (copy > skb_tailroom(skb))
> -		copy = skb_tailroom(skb);
> +	/* Copy all frame if it fits skb->head, otherwise
> +	 * we let virtio_net_hdr_to_skb() and GRO pull headers as needed.
> +	 */
> +	if (len <= skb_tailroom(skb))
> +		copy = len;
> +	else
> +		copy = ETH_HLEN + metasize;
>   	skb_put_data(skb, p, copy);
>   
>   	if (metasize) {
> diff --git a/include/linux/virtio_net.h b/include/linux/virtio_net.h
> index 98775d7fa69632e2c2da30b581a666f7fbb94b64..b465f8f3e554f27ced45c35f54f113cf6dce1f07 100644
> --- a/include/linux/virtio_net.h
> +++ b/include/linux/virtio_net.h
> @@ -65,14 +65,18 @@ static inline int virtio_net_hdr_to_skb(struct sk_buff *skb,
>   	skb_reset_mac_header(skb);
>   
>   	if (hdr->flags & VIRTIO_NET_HDR_F_NEEDS_CSUM) {
> -		u16 start = __virtio16_to_cpu(little_endian, hdr->csum_start);
> -		u16 off = __virtio16_to_cpu(little_endian, hdr->csum_offset);
> +		u32 start = __virtio16_to_cpu(little_endian, hdr->csum_start);
> +		u32 off = __virtio16_to_cpu(little_endian, hdr->csum_offset);
> +		u32 needed = start + max_t(u32, thlen, off + sizeof(__sum16));
> +
> +		if (!pskb_may_pull(skb, needed))
> +			return -EINVAL;
>   
>   		if (!skb_partial_csum_set(skb, start, off))
>   			return -EINVAL;
>   
>   		p_off = skb_transport_offset(skb) + thlen;
> -		if (p_off > skb_headlen(skb))
> +		if (!pskb_may_pull(skb, p_off))
>   			return -EINVAL;
>   	} else {
>   		/* gso packets without NEEDS_CSUM do not set transport_offset.
> @@ -102,14 +106,14 @@ static inline int virtio_net_hdr_to_skb(struct sk_buff *skb,
>   			}
>   
>   			p_off = keys.control.thoff + thlen;
> -			if (p_off > skb_headlen(skb) ||
> +			if (!pskb_may_pull(skb, p_off) ||
>   			    keys.basic.ip_proto != ip_proto)
>   				return -EINVAL;
>   
>   			skb_set_transport_header(skb, keys.control.thoff);
>   		} else if (gso_type) {
>   			p_off = thlen;
> -			if (p_off > skb_headlen(skb))
> +			if (!pskb_may_pull(skb, p_off))
>   				return -EINVAL;
>   		}
>   	}

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

[Michael S. Tsirkin]

On Fri, Apr 02, 2021 at 06:26:02AM -0700, Eric Dumazet wrote:
> From: Eric Dumazet <edumazet@google.com>
> 
> Xuan Zhuo reported that commit 3226b158e67c ("net: avoid 32 x truesize
> under-estimation for tiny skbs") brought  a ~10% performance drop.
> 
> The reason for the performance drop was that GRO was forced
> to chain sk_buff (using skb_shinfo(skb)->frag_list), which
> uses more memory but also cause packet consumers to go over
> a lot of overhead handling all the tiny skbs.
> 
> It turns out that virtio_net page_to_skb() has a wrong strategy :
> It allocates skbs with GOOD_COPY_LEN (128) bytes in skb->head, then
> copies 128 bytes from the page, before feeding the packet to GRO stack.
> 
> This was suboptimal before commit 3226b158e67c ("net: avoid 32 x truesize
> under-estimation for tiny skbs") because GRO was using 2 frags per MSS,
> meaning we were not packing MSS with 100% efficiency.
> 
> Fix is to pull only the ethernet header in page_to_skb()
> 
> Then, we change virtio_net_hdr_to_skb() to pull the missing
> headers, instead of assuming they were already pulled by callers.
> 
> This fixes the performance regression, but could also allow virtio_net
> to accept packets with more than 128bytes of headers.
> 
> Many thanks to Xuan Zhuo for his report, and his tests/help.
> 
> Fixes: 3226b158e67c ("net: avoid 32 x truesize under-estimation for tiny skbs")
> Reported-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
> Link: https://www.spinics.net/lists/netdev/msg731397.html
> Co-Developed-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
> Signed-off-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
> Signed-off-by: Eric Dumazet <edumazet@google.com>
> Cc: "Michael S. Tsirkin" <mst@redhat.com>
> Cc: Jason Wang <jasowang@redhat.com>
> Cc: virtualization@lists.linux-foundation.org

Acked-by: Michael S. Tsirkin <mst@redhat.com>

Thanks a lot for looking into this, Eric and Xuan Zhuo !

> ---
>  drivers/net/virtio_net.c   | 10 +++++++---
>  include/linux/virtio_net.h | 14 +++++++++-----
>  2 files changed, 16 insertions(+), 8 deletions(-)
> 
> diff --git a/drivers/net/virtio_net.c b/drivers/net/virtio_net.c
> index 82e520d2cb1229a0c7b9fd0def3e4a7135536478..0824e6999e49957f7aaf7c990f6259792d42f32b 100644
> --- a/drivers/net/virtio_net.c
> +++ b/drivers/net/virtio_net.c
> @@ -406,9 +406,13 @@ static struct sk_buff *page_to_skb(struct virtnet_info *vi,
>  	offset += hdr_padded_len;
>  	p += hdr_padded_len;
>  
> -	copy = len;
> -	if (copy > skb_tailroom(skb))
> -		copy = skb_tailroom(skb);
> +	/* Copy all frame if it fits skb->head, otherwise
> +	 * we let virtio_net_hdr_to_skb() and GRO pull headers as needed.
> +	 */
> +	if (len <= skb_tailroom(skb))
> +		copy = len;
> +	else
> +		copy = ETH_HLEN + metasize;
>  	skb_put_data(skb, p, copy);
>  
>  	if (metasize) {
> diff --git a/include/linux/virtio_net.h b/include/linux/virtio_net.h
> index 98775d7fa69632e2c2da30b581a666f7fbb94b64..b465f8f3e554f27ced45c35f54f113cf6dce1f07 100644
> --- a/include/linux/virtio_net.h
> +++ b/include/linux/virtio_net.h
> @@ -65,14 +65,18 @@ static inline int virtio_net_hdr_to_skb(struct sk_buff *skb,
>  	skb_reset_mac_header(skb);
>  
>  	if (hdr->flags & VIRTIO_NET_HDR_F_NEEDS_CSUM) {
> -		u16 start = __virtio16_to_cpu(little_endian, hdr->csum_start);
> -		u16 off = __virtio16_to_cpu(little_endian, hdr->csum_offset);
> +		u32 start = __virtio16_to_cpu(little_endian, hdr->csum_start);
> +		u32 off = __virtio16_to_cpu(little_endian, hdr->csum_offset);
> +		u32 needed = start + max_t(u32, thlen, off + sizeof(__sum16));
> +
> +		if (!pskb_may_pull(skb, needed))
> +			return -EINVAL;
>  
>  		if (!skb_partial_csum_set(skb, start, off))
>  			return -EINVAL;
>  
>  		p_off = skb_transport_offset(skb) + thlen;
> -		if (p_off > skb_headlen(skb))
> +		if (!pskb_may_pull(skb, p_off))
>  			return -EINVAL;
>  	} else {
>  		/* gso packets without NEEDS_CSUM do not set transport_offset.
> @@ -102,14 +106,14 @@ static inline int virtio_net_hdr_to_skb(struct sk_buff *skb,
>  			}
>  
>  			p_off = keys.control.thoff + thlen;
> -			if (p_off > skb_headlen(skb) ||
> +			if (!pskb_may_pull(skb, p_off) ||
>  			    keys.basic.ip_proto != ip_proto)
>  				return -EINVAL;
>  
>  			skb_set_transport_header(skb, keys.control.thoff);
>  		} else if (gso_type) {
>  			p_off = thlen;
> -			if (p_off > skb_headlen(skb))
> +			if (!pskb_may_pull(skb, p_off))
>  				return -EINVAL;
>  		}
>  	}
> -- 
> 2.31.0.208.g409f899ff0-goog

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

[Guenter Roeck]

Hi,

On Fri, Apr 02, 2021 at 06:26:02AM -0700, Eric Dumazet wrote:
> From: Eric Dumazet <edumazet@google.com>
> 
> Xuan Zhuo reported that commit 3226b158e67c ("net: avoid 32 x truesize
> under-estimation for tiny skbs") brought  a ~10% performance drop.
> 
> The reason for the performance drop was that GRO was forced
> to chain sk_buff (using skb_shinfo(skb)->frag_list), which
> uses more memory but also cause packet consumers to go over
> a lot of overhead handling all the tiny skbs.
> 
> It turns out that virtio_net page_to_skb() has a wrong strategy :
> It allocates skbs with GOOD_COPY_LEN (128) bytes in skb->head, then
> copies 128 bytes from the page, before feeding the packet to GRO stack.
> 
> This was suboptimal before commit 3226b158e67c ("net: avoid 32 x truesize
> under-estimation for tiny skbs") because GRO was using 2 frags per MSS,
> meaning we were not packing MSS with 100% efficiency.
> 
> Fix is to pull only the ethernet header in page_to_skb()
> 
> Then, we change virtio_net_hdr_to_skb() to pull the missing
> headers, instead of assuming they were already pulled by callers.
> 
> This fixes the performance regression, but could also allow virtio_net
> to accept packets with more than 128bytes of headers.
> 
> Many thanks to Xuan Zhuo for his report, and his tests/help.
> 
> Fixes: 3226b158e67c ("net: avoid 32 x truesize under-estimation for tiny skbs")
> Reported-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
> Link: https://www.spinics.net/lists/netdev/msg731397.html
> Co-Developed-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
> Signed-off-by: Xuan Zhuo <xuanzhuo@linux.alibaba.com>
> Signed-off-by: Eric Dumazet <edumazet@google.com>
> Cc: "Michael S. Tsirkin" <mst@redhat.com>
> Cc: Jason Wang <jasowang@redhat.com>
> Cc: virtualization@lists.linux-foundation.org

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

After the failure, ifconfig shows no error:

eth0      Link encap:Ethernet  HWaddr 52:54:00:12:34:56
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:1 errors:0 dropped:0 overruns:0 frame:0
          TX packets:1 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:590 (590.0 B)  TX bytes:342 (342.0 B)

This happens with almost every boot. The problem disappears after reverting
this patch.

Guenter

---
bisect log:
# bad: [52e44129fba5cfc4e351fdb5e45849afc74d9a53] Merge branch 'for-5.12-fixes' of git://git.kernel.org/pub/scm/linux/kernel/git/dennis/percpu
# good: [f40ddce88593482919761f74910f42f4b84c004b] Linux 5.11
git bisect start 'HEAD' 'v5.11'
# good: [d99676af540c2dc829999928fb81c58c80a1dce4] Merge tag 'drm-next-2021-02-19' of git://anongit.freedesktop.org/drm/drm
git bisect good d99676af540c2dc829999928fb81c58c80a1dce4
# good: [c4fbde84fedeaf513ec96f0c6ed3f352bdcd61d6] Merge tag 'sfi-removal-5.12-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
git bisect good c4fbde84fedeaf513ec96f0c6ed3f352bdcd61d6
# good: [b1dd9bf688b0dcc5a34dca660de46c7570bd9243] net: phy: broadcom: Fix RGMII delays for BCM50160 and BCM50610M
git bisect good b1dd9bf688b0dcc5a34dca660de46c7570bd9243
# good: [e138138003eb3b3d06cc91cf2e8c5dec77e2a31e] Merge git://git.kernel.org/pub/scm/linux/kernel/git/netdev/net
git bisect good e138138003eb3b3d06cc91cf2e8c5dec77e2a31e
# good: [dbaa5d1c254e1b565caee9ac7b526a9b7267d4c4] Merge branch 'parisc-5.12-3' of git://git.kernel.org/pub/scm/linux/kernel/git/deller/parisc-linux
git bisect good dbaa5d1c254e1b565caee9ac7b526a9b7267d4c4
# bad: [1ffbc7ea91606e4abd10eb60de5367f1c86daf5e] net: sched: sch_teql: fix null-pointer dereference
git bisect bad 1ffbc7ea91606e4abd10eb60de5367f1c86daf5e
# good: [9256ce33110174decc04caf6ef733409012e5b1c] Merge branch '40GbE' of git://git.kernel.org/pub/scm/linux/kernel/git/tnguy/net-queue
git bisect good 9256ce33110174decc04caf6ef733409012e5b1c
# bad: [3cf1482852825bdf8cc4e4f09346262c80ad5cbe] Merge branch 'ethtool-link_mode'
git bisect bad 3cf1482852825bdf8cc4e4f09346262c80ad5cbe
# bad: [0f6925b3e8da0dbbb52447ca8a8b42b371aac7db] virtio_net: Do not pull payload in skb->head
git bisect bad 0f6925b3e8da0dbbb52447ca8a8b42b371aac7db
# good: [6dcc4e38386950abf9060784631622dfc4df9577] Merge branch 'AF_XDP Socket Creation Fixes'
git bisect good 6dcc4e38386950abf9060784631622dfc4df9577
# good: [630e4576f83accf90366686f39808d665d8dbecc] net-ipv6: bugfix - raw & sctp - switch to ipv6_can_nonlocal_bind()
git bisect good 630e4576f83accf90366686f39808d665d8dbecc
# good: [22f69de18ee86e81dc41253869e5dd963ccea429] Merge branch 'hns3-fixes'
git bisect good 22f69de18ee86e81dc41253869e5dd963ccea429
# good: [b25b343db0526669947a427e9a31bac91d29bb06] net: broadcom: bcm4908enet: Fix a double free in bcm4908_enet_dma_alloc
git bisect good b25b343db0526669947a427e9a31bac91d29bb06
# first bad commit: [0f6925b3e8da0dbbb52447ca8a8b42b371aac7db] virtio_net: Do not pull payload in skb->head

---
qemu command line:

qemu-system-sh4 -M r2d -kernel ./arch/sh/boot/zImage -no-reboot \
	-snapshot \
	-drive file=rootfs.ext2,format=raw,if=ide \
	-device virtio-net,netdev=net0 -netdev user,id=net0 \
	-append "root=/dev/sda console=ttySC1,115200 earlycon=scif,mmio16,0xffe80000 noiotrap" \
	-serial null -serial stdio -nographic -monitor null

The root file system is
	https://github.com/groeck/linux-build-test/blob/master/rootfs/sh/rootfs.ext2.gz
It was generated with buildroot version 2021.02.

To reproduce the problem, just run the qemu command and look for "Network
interface test [passed|failed]".

AFAICS any qemu version can be used to reproduce the problem.

---
defconfig:

CONFIG_SYSVIPC=y
CONFIG_LOG_BUF_SHIFT=14
CONFIG_BLK_DEV_INITRD=y
CONFIG_SLAB=y
CONFIG_PROFILING=y
CONFIG_CPU_SUBTYPE_SH7751R=y
CONFIG_MEMORY_START=0x0c000000
CONFIG_SH_RTS7751R2D=y
CONFIG_RTS7751R2D_PLUS=y
CONFIG_HEARTBEAT=y
CONFIG_MODULES=y
CONFIG_FLATMEM_MANUAL=y
CONFIG_NET=y
CONFIG_PACKET=y
CONFIG_UNIX=y
CONFIG_INET=y
# CONFIG_IPV6 is not set
CONFIG_PCI=y
CONFIG_HOTPLUG_PCI=y
CONFIG_DEVTMPFS=y
CONFIG_DEVTMPFS_MOUNT=y
CONFIG_MTD=y
CONFIG_MTD_CMDLINE_PARTS=y
CONFIG_MTD_BLOCK=y
CONFIG_MTD_CFI=y
CONFIG_MTD_CFI_AMDSTD=y
CONFIG_MTD_PHYSMAP=y
CONFIG_BLK_DEV_RAM=y
CONFIG_VIRTIO_BLK=y
CONFIG_BLK_DEV_NVME=y
CONFIG_BLK_DEV_SD=y
CONFIG_BLK_DEV_SR=y
CONFIG_MEGARAID_SAS=y
CONFIG_SCSI_SYM53C8XX_2=y
CONFIG_SCSI_DC395x=y
CONFIG_SCSI_AM53C974=y
CONFIG_SCSI_VIRTIO=y
CONFIG_ATA=y
CONFIG_PATA_PLATFORM=y
CONFIG_FUSION=y
CONFIG_FUSION_SAS=y
CONFIG_NETDEVICES=y
CONFIG_VIRTIO_NET=y
CONFIG_PCNET32=y
CONFIG_NET_TULIP=y
CONFIG_TULIP=y
CONFIG_E100=y
CONFIG_E1000=y
CONFIG_E1000E=y
CONFIG_NE2K_PCI=y
CONFIG_8139CP=y
CONFIG_8139TOO=y
# CONFIG_8139TOO_PIO is not set
CONFIG_USB_USBNET=y
# CONFIG_INPUT_KEYBOARD is not set
# CONFIG_INPUT_MOUSE is not set
# CONFIG_SERIO is not set
CONFIG_SERIAL_8250=y
CONFIG_SERIAL_SH_SCI=y
CONFIG_HW_RANDOM=y
CONFIG_SPI=y
CONFIG_SPI_SH_SCI=y
# CONFIG_PTP_1588_CLOCK is not set
CONFIG_MFD_SM501=y
CONFIG_FB=y
CONFIG_FB_SH_MOBILE_LCDC=m
CONFIG_FB_SM501=y
CONFIG_FRAMEBUFFER_CONSOLE=y
CONFIG_LOGO=y
# CONFIG_LOGO_LINUX_MONO is not set
# CONFIG_LOGO_LINUX_VGA16 is not set
# CONFIG_LOGO_LINUX_CLUT224 is not set
# CONFIG_LOGO_SUPERH_MONO is not set
# CONFIG_LOGO_SUPERH_VGA16 is not set
CONFIG_SOUND=y
CONFIG_SND=m
CONFIG_SND_YMFPCI=m
CONFIG_HID_GYRATION=y
CONFIG_HID_PANTHERLORD=y
CONFIG_HID_PETALYNX=y
CONFIG_HID_SAMSUNG=y
CONFIG_HID_SUNPLUS=y
CONFIG_USB=y
CONFIG_USB_ANNOUNCE_NEW_DEVICES=y
CONFIG_USB_XHCI_HCD=y
CONFIG_USB_EHCI_HCD=y
CONFIG_USB_OHCI_HCD=y
CONFIG_USB_STORAGE=y
CONFIG_USB_UAS=y
CONFIG_MMC=y
CONFIG_MMC_SDHCI=y
CONFIG_MMC_SDHCI_PCI=y
CONFIG_RTC_CLASS=y
CONFIG_RTC_DRV_R9701=y
CONFIG_VIRTIO_PCI=y
CONFIG_VIRTIO_BALLOON=y
CONFIG_VIRTIO_MMIO=y
CONFIG_EXT2_FS=y
CONFIG_ISO9660_FS=y
CONFIG_MSDOS_FS=y
CONFIG_VFAT_FS=y
CONFIG_PROC_KCORE=y
CONFIG_TMPFS=y
CONFIG_MINIX_FS=y
CONFIG_NLS_CODEPAGE_932=y
CONFIG_CRC_T10DIF=y
CONFIG_DEBUG_FS=y

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

[Eric Dumazet]

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 ?

perf record -a -g -e skb:kfree_skb "udhcpc"
perf report

Thanks !

(Some layer might need a pskb_may_pull())


> After the failure, ifconfig shows no error:
>
> eth0      Link encap:Ethernet  HWaddr 52:54:00:12:34:56
>           UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
>           RX packets:1 errors:0 dropped:0 overruns:0 frame:0
>           TX packets:1 errors:0 dropped:0 overruns:0 carrier:0
>           collisions:0 txqueuelen:1000
>           RX bytes:590 (590.0 B)  TX bytes:342 (342.0 B)
>
> This happens with almost every boot. The problem disappears after reverting
> this patch.
>
> Guenter
>
> ---
> bisect log:
> # bad: [52e44129fba5cfc4e351fdb5e45849afc74d9a53] Merge branch 'for-5.12-fixes' of git://git.kernel.org/pub/scm/linux/kernel/git/dennis/percpu
> # good: [f40ddce88593482919761f74910f42f4b84c004b] Linux 5.11
> git bisect start 'HEAD' 'v5.11'
> # good: [d99676af540c2dc829999928fb81c58c80a1dce4] Merge tag 'drm-next-2021-02-19' of git://anongit.freedesktop.org/drm/drm
> git bisect good d99676af540c2dc829999928fb81c58c80a1dce4
> # good: [c4fbde84fedeaf513ec96f0c6ed3f352bdcd61d6] Merge tag 'sfi-removal-5.12-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
> git bisect good c4fbde84fedeaf513ec96f0c6ed3f352bdcd61d6
> # good: [b1dd9bf688b0dcc5a34dca660de46c7570bd9243] net: phy: broadcom: Fix RGMII delays for BCM50160 and BCM50610M
> git bisect good b1dd9bf688b0dcc5a34dca660de46c7570bd9243
> # good: [e138138003eb3b3d06cc91cf2e8c5dec77e2a31e] Merge git://git.kernel.org/pub/scm/linux/kernel/git/netdev/net
> git bisect good e138138003eb3b3d06cc91cf2e8c5dec77e2a31e
> # good: [dbaa5d1c254e1b565caee9ac7b526a9b7267d4c4] Merge branch 'parisc-5.12-3' of git://git.kernel.org/pub/scm/linux/kernel/git/deller/parisc-linux
> git bisect good dbaa5d1c254e1b565caee9ac7b526a9b7267d4c4
> # bad: [1ffbc7ea91606e4abd10eb60de5367f1c86daf5e] net: sched: sch_teql: fix null-pointer dereference
> git bisect bad 1ffbc7ea91606e4abd10eb60de5367f1c86daf5e
> # good: [9256ce33110174decc04caf6ef733409012e5b1c] Merge branch '40GbE' of git://git.kernel.org/pub/scm/linux/kernel/git/tnguy/net-queue
> git bisect good 9256ce33110174decc04caf6ef733409012e5b1c
> # bad: [3cf1482852825bdf8cc4e4f09346262c80ad5cbe] Merge branch 'ethtool-link_mode'
> git bisect bad 3cf1482852825bdf8cc4e4f09346262c80ad5cbe
> # bad: [0f6925b3e8da0dbbb52447ca8a8b42b371aac7db] virtio_net: Do not pull payload in skb->head
> git bisect bad 0f6925b3e8da0dbbb52447ca8a8b42b371aac7db
> # good: [6dcc4e38386950abf9060784631622dfc4df9577] Merge branch 'AF_XDP Socket Creation Fixes'
> git bisect good 6dcc4e38386950abf9060784631622dfc4df9577
> # good: [630e4576f83accf90366686f39808d665d8dbecc] net-ipv6: bugfix - raw & sctp - switch to ipv6_can_nonlocal_bind()
> git bisect good 630e4576f83accf90366686f39808d665d8dbecc
> # good: [22f69de18ee86e81dc41253869e5dd963ccea429] Merge branch 'hns3-fixes'
> git bisect good 22f69de18ee86e81dc41253869e5dd963ccea429
> # good: [b25b343db0526669947a427e9a31bac91d29bb06] net: broadcom: bcm4908enet: Fix a double free in bcm4908_enet_dma_alloc
> git bisect good b25b343db0526669947a427e9a31bac91d29bb06
> # first bad commit: [0f6925b3e8da0dbbb52447ca8a8b42b371aac7db] virtio_net: Do not pull payload in skb->head
>
> ---
> qemu command line:
>
> qemu-system-sh4 -M r2d -kernel ./arch/sh/boot/zImage -no-reboot \
>         -snapshot \
>         -drive file=rootfs.ext2,format=raw,if=ide \
>         -device virtio-net,netdev=net0 -netdev user,id=net0 \
>         -append "root=/dev/sda console=ttySC1,115200 earlycon=scif,mmio16,0xffe80000 noiotrap" \
>         -serial null -serial stdio -nographic -monitor null
>
> The root file system is
>         https://github.com/groeck/linux-build-test/blob/master/rootfs/sh/rootfs.ext2.gz
> It was generated with buildroot version 2021.02.
>
> To reproduce the problem, just run the qemu command and look for "Network
> interface test [passed|failed]".
>
> AFAICS any qemu version can be used to reproduce the problem.
>
> ---
> defconfig:
>
> CONFIG_SYSVIPC=y
> CONFIG_LOG_BUF_SHIFT=14
> CONFIG_BLK_DEV_INITRD=y
> CONFIG_SLAB=y
> CONFIG_PROFILING=y
> CONFIG_CPU_SUBTYPE_SH7751R=y
> CONFIG_MEMORY_START=0x0c000000
> CONFIG_SH_RTS7751R2D=y
> CONFIG_RTS7751R2D_PLUS=y
> CONFIG_HEARTBEAT=y
> CONFIG_MODULES=y
> CONFIG_FLATMEM_MANUAL=y
> CONFIG_NET=y
> CONFIG_PACKET=y
> CONFIG_UNIX=y
> CONFIG_INET=y
> # CONFIG_IPV6 is not set
> CONFIG_PCI=y
> CONFIG_HOTPLUG_PCI=y
> CONFIG_DEVTMPFS=y
> CONFIG_DEVTMPFS_MOUNT=y
> CONFIG_MTD=y
> CONFIG_MTD_CMDLINE_PARTS=y
> CONFIG_MTD_BLOCK=y
> CONFIG_MTD_CFI=y
> CONFIG_MTD_CFI_AMDSTD=y
> CONFIG_MTD_PHYSMAP=y
> CONFIG_BLK_DEV_RAM=y
> CONFIG_VIRTIO_BLK=y
> CONFIG_BLK_DEV_NVME=y
> CONFIG_BLK_DEV_SD=y
> CONFIG_BLK_DEV_SR=y
> CONFIG_MEGARAID_SAS=y
> CONFIG_SCSI_SYM53C8XX_2=y
> CONFIG_SCSI_DC395x=y
> CONFIG_SCSI_AM53C974=y
> CONFIG_SCSI_VIRTIO=y
> CONFIG_ATA=y
> CONFIG_PATA_PLATFORM=y
> CONFIG_FUSION=y
> CONFIG_FUSION_SAS=y
> CONFIG_NETDEVICES=y
> CONFIG_VIRTIO_NET=y
> CONFIG_PCNET32=y
> CONFIG_NET_TULIP=y
> CONFIG_TULIP=y
> CONFIG_E100=y
> CONFIG_E1000=y
> CONFIG_E1000E=y
> CONFIG_NE2K_PCI=y
> CONFIG_8139CP=y
> CONFIG_8139TOO=y
> # CONFIG_8139TOO_PIO is not set
> CONFIG_USB_USBNET=y
> # CONFIG_INPUT_KEYBOARD is not set
> # CONFIG_INPUT_MOUSE is not set
> # CONFIG_SERIO is not set
> CONFIG_SERIAL_8250=y
> CONFIG_SERIAL_SH_SCI=y
> CONFIG_HW_RANDOM=y
> CONFIG_SPI=y
> CONFIG_SPI_SH_SCI=y
> # CONFIG_PTP_1588_CLOCK is not set
> CONFIG_MFD_SM501=y
> CONFIG_FB=y
> CONFIG_FB_SH_MOBILE_LCDC=m
> CONFIG_FB_SM501=y
> CONFIG_FRAMEBUFFER_CONSOLE=y
> CONFIG_LOGO=y
> # CONFIG_LOGO_LINUX_MONO is not set
> # CONFIG_LOGO_LINUX_VGA16 is not set
> # CONFIG_LOGO_LINUX_CLUT224 is not set
> # CONFIG_LOGO_SUPERH_MONO is not set
> # CONFIG_LOGO_SUPERH_VGA16 is not set
> CONFIG_SOUND=y
> CONFIG_SND=m
> CONFIG_SND_YMFPCI=m
> CONFIG_HID_GYRATION=y
> CONFIG_HID_PANTHERLORD=y
> CONFIG_HID_PETALYNX=y
> CONFIG_HID_SAMSUNG=y
> CONFIG_HID_SUNPLUS=y
> CONFIG_USB=y
> CONFIG_USB_ANNOUNCE_NEW_DEVICES=y
> CONFIG_USB_XHCI_HCD=y
> CONFIG_USB_EHCI_HCD=y
> CONFIG_USB_OHCI_HCD=y
> CONFIG_USB_STORAGE=y
> CONFIG_USB_UAS=y
> CONFIG_MMC=y
> CONFIG_MMC_SDHCI=y
> CONFIG_MMC_SDHCI_PCI=y
> CONFIG_RTC_CLASS=y
> CONFIG_RTC_DRV_R9701=y
> CONFIG_VIRTIO_PCI=y
> CONFIG_VIRTIO_BALLOON=y
> CONFIG_VIRTIO_MMIO=y
> CONFIG_EXT2_FS=y
> CONFIG_ISO9660_FS=y
> CONFIG_MSDOS_FS=y
> CONFIG_VFAT_FS=y
> CONFIG_PROC_KCORE=y
> CONFIG_TMPFS=y
> CONFIG_MINIX_FS=y
> CONFIG_NLS_CODEPAGE_932=y
> CONFIG_CRC_T10DIF=y
> CONFIG_DEBUG_FS=y

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

[Guenter Roeck]

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.

Guenter

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

[Eric Dumazet]

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

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

[Guenter Roeck]

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.

dhcp discover response with patch in place (bad):

virtio_net virtio0 eth0: __udp4_lib_rcv: data 0x8ca4cc44 head 0x8ca4cc00 tail 0x8ca4cc4c len 556 datalen 548 caller ip_protocol_deliver_rcu+0xac/0x178
00000000: 70 c1 a9 8c 00 00 00 00 00 00 00 00 20 ee c3 7b 34 00 e0 7b 08 00 00 00 00 00 00 00 00 00 00 00  p........... ..{4..{............
00000020: 60 c8 ff ff ff ff ff ff 52 55 0a 00 02 02 08 00 45 10 02 40 00 00 00 00 40 11 6c 9c 0a 00 02 02  `.......RU......E..@....@.l.....
00000040: ff ff ff ff 00 43 00 44 02 2c e1 21 00 00 00 00 f0 6f a4 7b 00 00 80 00 ff ff ff ff 7f 45 4c 46  .....C.D.,.!.....o.{.........ELF
                      ^^ udp header
                                  ^^^^^ UDP length (556)
                                              ^^ start of UDP data (dhcp discover reply)
00000060: 01 01 01 00 00 00 00 00 00 00 00 00 02 00 2a 00 01 00 00 00 b0 6e 40 00 34 00 00 00 2c f6 0a 00  ..............*......n@.4...,...
00000080: 17 00 00 00 34 00 20 00 08 00 28 00 16 00 15 00 06 00 00 00 34 00 00 00 34 00 40 00 34 00 40 00  ....4. ...(.........4...4.@.4.@.
000000a0: 00 01 00 00 00 01 00 00 04 00 00 00 04 00 00 00 03 00 00 00 34 01 00 00 34 01 40 00 34 01 40 00  ....................4...4.@.4.@.
000000c0: 15 00 00 00 15 00 00 00 04 00 00 00 01 00 00 00 01 00 00 00 00 00 00 00 00 00 40 00 00 00 40 00  ..........................@...@.
000000e0: 1c e2 0a 00 1c e2 0a 00 05 00 00 00 00 00 01 00 01 00 00 00 38 ef 0a 00 38 ef 4b 00 38 ef 4b 00  ....................8...8.K.8.K.
00000100: 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00 00  ................................
00000120: b8 00 00 00 00 4c f9 8f 24 02 00 00 36 00 00 00 50 e5 74 64 88 e0 0a 00 88 e0 4a 00 88 e0 4a 00  .....L..$...6...P.td......J...J.
00000140: 2c 00 00 00 2c 00 00 00 04 00 00 00 04 00 00 00 51 e5 74 64 00 00 00 00 00 00 00 00 00 00 00 00  ,...,...........Q.td............
00000160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
00000180: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
000001a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
000001c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
000001e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
00000200: 1c 63 5a 8c 00 3e a4 8c 88 f9 50 8c 0c ce a4 8c 0c ce a4 8c 24 81 a1 8c 00 00 00 00 1c 5c 5a 8c  .cZ..>....P.........$........\Z.
00000220: 04 b8 a5 8c 01 00 00 00 03 00 00 00                                                              ............

dhcp discover response with patch reverted (ok):

virtio_net virtio0 eth0: __udp4_lib_rcv: data 0x8ca4ca44 head 0x8ca4ca00 tail 0x8ca4cb00 len 556 datalen 368 caller ip_protocol_deliver_rcu+0xac/0x178
                                                              ^^^^^^^^^^      ^^^^^^^^^^                 ^^^
00000000: 4c bd ab 8c 00 00 00 00 00 00 00 00 20 2e 85 7b 34 00 e0 7b 08 00 00 00 00 00 00 00 00 00 00 00  L........... ..{4..{............
00000020: 40 9a ff ff ff ff ff ff 52 55 0a 00 02 02 08 00 45 10 02 40 00 00 00 00 40 11 6c 9c 0a 00 02 02  @.......RU......E..@....@.l.....
                                                                ^^^^^ ip length (576)
00000040: ff ff ff ff 00 43 00 44 02 2c 06 18 02 01 06 00 e6 fd ce 5b 00 00 00 00 00 00 00 00 0a 00 02 0f  .....C.D.,.........[............
                      ^^ udp header
                                  ^^^^^ UDP length (556)
                                              ^^ start of UDP data
00000060: 0a 00 02 02 00 00 00 00 52 54 00 12 34 56 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ........RT..4V..................
00000080: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
000000a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
000000c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
000000e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
00000100: 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 00 00 00  ................................
00000120: b8 00 00 00 00 4d f9 8f 70 01 00 00 ea 00 00 00 50 e5 74 64 88 e0 0a 00 88 e0 4a 00 88 e0 4a 00  .....M..p.......P.td......J...J.
00000140: 2c 00 00 00 2c 00 00 00 04 00 00 00 04 00 00 00 51 e5 74 64 00 00 00 00 00 00 00 00 00 00 00 00  ,...,...........Q.td............
00000160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
00000180: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
000001a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
000001c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
000001e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
00000200: 00 00 00 00 00 00 00 00 06 00 01 00 54 cc a4 8c 08 00 00 00 02 00 00 00 00 00 00 00 01 00 00 00  ............T...................
00000220: 08 00 00 00 00 00 00 00 14 cd a4 8c                                                              ............

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

[Eric Dumazet]

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


>
> dhcp discover response with patch in place (bad):
>
> virtio_net virtio0 eth0: __udp4_lib_rcv: data 0x8ca4cc44 head 0x8ca4cc00 tail 0x8ca4cc4c len 556 datalen 548 caller ip_protocol_deliver_rcu+0xac/0x178
> 00000000: 70 c1 a9 8c 00 00 00 00 00 00 00 00 20 ee c3 7b 34 00 e0 7b 08 00 00 00 00 00 00 00 00 00 00 00  p........... ..{4..{............
> 00000020: 60 c8 ff ff ff ff ff ff 52 55 0a 00 02 02 08 00 45 10 02 40 00 00 00 00 40 11 6c 9c 0a 00 02 02  `.......RU......E..@....@.l.....
> 00000040: ff ff ff ff 00 43 00 44 02 2c e1 21 00 00 00 00 f0 6f a4 7b 00 00 80 00 ff ff ff ff 7f 45 4c 46  .....C.D.,.!.....o.{.........ELF
>                       ^^ udp header
>                                   ^^^^^ UDP length (556)
>                                               ^^ start of UDP data (dhcp discover reply)
> 00000060: 01 01 01 00 00 00 00 00 00 00 00 00 02 00 2a 00 01 00 00 00 b0 6e 40 00 34 00 00 00 2c f6 0a 00  ..............*......n@.4...,...
> 00000080: 17 00 00 00 34 00 20 00 08 00 28 00 16 00 15 00 06 00 00 00 34 00 00 00 34 00 40 00 34 00 40 00  ....4. ...(.........4...4.@.4.@.
> 000000a0: 00 01 00 00 00 01 00 00 04 00 00 00 04 00 00 00 03 00 00 00 34 01 00 00 34 01 40 00 34 01 40 00  ....................4...4.@.4.@.
> 000000c0: 15 00 00 00 15 00 00 00 04 00 00 00 01 00 00 00 01 00 00 00 00 00 00 00 00 00 40 00 00 00 40 00  ..........................@...@.
> 000000e0: 1c e2 0a 00 1c e2 0a 00 05 00 00 00 00 00 01 00 01 00 00 00 38 ef 0a 00 38 ef 4b 00 38 ef 4b 00  ....................8...8.K.8.K.
> 00000100: 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00 00  ................................
> 00000120: b8 00 00 00 00 4c f9 8f 24 02 00 00 36 00 00 00 50 e5 74 64 88 e0 0a 00 88 e0 4a 00 88 e0 4a 00  .....L..$...6...P.td......J...J.
> 00000140: 2c 00 00 00 2c 00 00 00 04 00 00 00 04 00 00 00 51 e5 74 64 00 00 00 00 00 00 00 00 00 00 00 00  ,...,...........Q.td............
> 00000160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 00000180: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 000001a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 000001c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 000001e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 00000200: 1c 63 5a 8c 00 3e a4 8c 88 f9 50 8c 0c ce a4 8c 0c ce a4 8c 24 81 a1 8c 00 00 00 00 1c 5c 5a 8c  .cZ..>....P.........$........\Z.
> 00000220: 04 b8 a5 8c 01 00 00 00 03 00 00 00                                                              ............
>
> dhcp discover response with patch reverted (ok):
>
> virtio_net virtio0 eth0: __udp4_lib_rcv: data 0x8ca4ca44 head 0x8ca4ca00 tail 0x8ca4cb00 len 556 datalen 368 caller ip_protocol_deliver_rcu+0xac/0x178
>                                                               ^^^^^^^^^^      ^^^^^^^^^^                 ^^^
> 00000000: 4c bd ab 8c 00 00 00 00 00 00 00 00 20 2e 85 7b 34 00 e0 7b 08 00 00 00 00 00 00 00 00 00 00 00  L........... ..{4..{............
> 00000020: 40 9a ff ff ff ff ff ff 52 55 0a 00 02 02 08 00 45 10 02 40 00 00 00 00 40 11 6c 9c 0a 00 02 02  @.......RU......E..@....@.l.....
>                                                                 ^^^^^ ip length (576)
> 00000040: ff ff ff ff 00 43 00 44 02 2c 06 18 02 01 06 00 e6 fd ce 5b 00 00 00 00 00 00 00 00 0a 00 02 0f  .....C.D.,.........[............
>                       ^^ udp header
>                                   ^^^^^ UDP length (556)
>                                               ^^ start of UDP data
> 00000060: 0a 00 02 02 00 00 00 00 52 54 00 12 34 56 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ........RT..4V..................
> 00000080: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 000000a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 000000c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 000000e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 00000100: 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 00 00 00  ................................
> 00000120: b8 00 00 00 00 4d f9 8f 70 01 00 00 ea 00 00 00 50 e5 74 64 88 e0 0a 00 88 e0 4a 00 88 e0 4a 00  .....M..p.......P.td......J...J.
> 00000140: 2c 00 00 00 2c 00 00 00 04 00 00 00 04 00 00 00 51 e5 74 64 00 00 00 00 00 00 00 00 00 00 00 00  ,...,...........Q.td............
> 00000160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 00000180: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 000001a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 000001c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 000001e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................
> 00000200: 00 00 00 00 00 00 00 00 06 00 01 00 54 cc a4 8c 08 00 00 00 02 00 00 00 00 00 00 00 01 00 00 00  ............T...................
> 00000220: 08 00 00 00 00 00 00 00 14 cd a4 8c                                                              ............

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

[Guenter Roeck]

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
> 

Another tool to install.

While that builds, output from strace:

# strace -o /tmp/STRACE  -f -s 1000 udhcpc -n -q
udhcpc: started, v1.33.0
udhcpc: sending discover
udhcpc: received SIGTERM

and:

...
136   socket(AF_PACKET, SOCK_DGRAM, htons(ETH_P_IP)) = 5
136   bind(5, {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=0}, 20) = 0
136   setsockopt(5, SOL_PACKET, PACKET_AUXDATA, [1], 4) = 0
136   fcntl64(5, F_SETFD, FD_CLOEXEC)   = 0
136   socket(AF_INET, SOCK_RAW, IPPROTO_RAW) = 6
136   ioctl(6, SIOCGIFINDEX, {ifr_name="eth0", }) = 0
136   ioctl(6, SIOCGIFHWADDR, {ifr_name="eth0", ifr_hwaddr={sa_family=ARPHRD_ETHER, sa_data=52:54:00:12:34:56}}) = 0
136   close(6)                          = 0
136   clock_gettime64(CLOCK_MONOTONIC, {tv_sec=161, tv_nsec=2180242}) = 0
136   write(2, "udhcpc: sending discover\n", 25) = 25
136   socket(AF_PACKET, SOCK_DGRAM, htons(ETH_P_IP)) = 6
136   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, 0xff, 0xff, 0xff]}, 20) = 0
136   sendto(6, "E\0\1H\0\0\0\0@\21y\246\0\0\0\0\377\377\377\377\0D\0C\0014\200\256\1\1\6\0\257\321\212P\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\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\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\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\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\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\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\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\0\0c\202Sc5\1\1=\7\1RT\0\0224V9\2\2@7\7\1\3\6\f\17\34*<\fudhcp 1.33.0\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 328, 0, {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, 0xff, 0xff, 0xff]}, 20

Guenter

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

[Eric Dumazet]

On Mon, Apr 12, 2021 at 12:07 AM Guenter Roeck <linux@roeck-us.net> wrote:
>
> 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
> >
>
> Another tool to install.
>
> While that builds, output from strace:
>
> # strace -o /tmp/STRACE  -f -s 1000 udhcpc -n -q
> udhcpc: started, v1.33.0
> udhcpc: sending discover
> udhcpc: received SIGTERM
>
> and:
>
> ...
> 136   socket(AF_PACKET, SOCK_DGRAM, htons(ETH_P_IP)) = 5
> 136   bind(5, {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=0}, 20) = 0
> 136   setsockopt(5, SOL_PACKET, PACKET_AUXDATA, [1], 4) = 0
> 136   fcntl64(5, F_SETFD, FD_CLOEXEC)   = 0
> 136   socket(AF_INET, SOCK_RAW, IPPROTO_RAW) = 6
> 136   ioctl(6, SIOCGIFINDEX, {ifr_name="eth0", }) = 0
> 136   ioctl(6, SIOCGIFHWADDR, {ifr_name="eth0", ifr_hwaddr={sa_family=ARPHRD_ETHER, sa_data=52:54:00:12:34:56}}) = 0
> 136   close(6)                          = 0
> 136   clock_gettime64(CLOCK_MONOTONIC, {tv_sec=161, tv_nsec=2180242}) = 0
> 136   write(2, "udhcpc: sending discover\n", 25) = 25
> 136   socket(AF_PACKET, SOCK_DGRAM, htons(ETH_P_IP)) = 6
> 136   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, 0xff, 0xff, 0xff]}, 20) = 0
> 136   sendto(6, "E\0\1H\0\0\0\0@\21y\246\0\0\0\0\377\377\377\377\0D\0C\0014\200\256\1\1\6\0\257\321\212P\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\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\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\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\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\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\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\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\0\0c\202Sc5\1\1=\7\1RT\0\0224V9\2\2@7\7\1\3\6\f\17\34*<\fudhcp 1.33.0\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 328, 0, {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, 0xff, 0xff, 0xff]}, 20

This does not make sense really. You cut the thing so it is hard to
give a verdict.

Please post the whole strace output.

Thanks.

>
> Guenter

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

[Eric Dumazet]

On Mon, Apr 12, 2021 at 7:48 AM Eric Dumazet <edumazet@google.com> wrote:
>

> give a verdict.
>
> Please post the whole strace output.
>
> Thanks.

Also please add -tt option to strace so that we have an idea of time
delays just in case.

Thanks.

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

[Guenter Roeck]

Hi Eric,

On Mon, Apr 12, 2021 at 07:53:43AM +0200, Eric Dumazet wrote:
> On Mon, Apr 12, 2021 at 7:48 AM Eric Dumazet <edumazet@google.com> wrote:
> >
> 
> > give a verdict.
> >
> > Please post the whole strace output.
> >
> > Thanks.
> 
> Also please add -tt option to strace so that we have an idea of time
> delays just in case.
> 

The exact command as executed is:

strace -tt -o /tmp/STRACE -f -s 1000 udhcpc -n -q

Log is below. This is the complete log: nothing was truncated, neither
at the beginning nor at the end. The log ends with sendto().

Hope this helps,

Guenter

---
148   00:01:14.802467 execve("/sbin/udhcpc", ["udhcpc", "-n", "-q"], 0x7bbbbe10 /* 11 vars */) = 0
148   00:01:14.804496 set_tid_address(0x295faf94) = 148
148   00:01:14.805081 brk(NULL)         = 0x4c0000
148   00:01:14.805495 brk(0x4c2000)     = 0x4c2000
148   00:01:14.805998 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
148   00:01:14.806750 mprotect(0x295f8000, 4096, PROT_READ) = 0
148   00:01:14.807524 mprotect(0x4be000, 4096, PROT_READ) = 0
148   00:01:14.808169 getuid32()        = 0
148   00:01:14.808670 open("/dev/null", O_RDWR|O_LARGEFILE) = 3
148   00:01:14.809415 close(3)          = 0
148   00:01:14.809886 pipe([3, 0])      = 3
148   00:01:14.810373 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
148   00:01:14.810827 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0
148   00:01:14.811274 fcntl64(3, F_GETFL) = 0 (flags O_RDONLY)
148   00:01:14.811703 fcntl64(3, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
148   00:01:14.812156 fcntl64(4, F_GETFL) = 0x1 (flags O_WRONLY)
148   00:01:14.812602 fcntl64(4, F_SETFL, O_WRONLY|O_NONBLOCK|O_LARGEFILE) = 0
148   00:01:14.813088 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
148   00:01:14.813648 rt_sigaction(SIGUSR1, {sa_handler=0x4328b0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x295b6a2a}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
148   00:01:14.814381 rt_sigaction(SIGUSR2, {sa_handler=0x4328b0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x295b6a2a}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
148   00:01:14.815106 rt_sigaction(SIGTERM, {sa_handler=0x4328b0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x295b6a2a}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
148   00:01:14.815910 socket(AF_INET, SOCK_RAW, IPPROTO_RAW) = 5
148   00:01:14.816484 ioctl(5, SIOCGIFINDEX, {ifr_name="eth0", }) = 0
148   00:01:14.817111 ioctl(5, SIOCGIFHWADDR, {ifr_name="eth0", ifr_hwaddr={sa_family=ARPHRD_ETHER, sa_data=52:54:00:12:34:56}}) = 0
148   00:01:14.818042 close(5)          = 0
148   00:01:14.818660 write(2, "udhcpc: started, v1.33.0\n", 25) = 25
148   00:01:14.819387 clock_gettime64(CLOCK_MONOTONIC, {tv_sec=74, tv_nsec=819590988}) = 0
148   00:01:14.820117 vfork( <unfinished ...>
149   00:01:14.820652 execve("/usr/share/udhcpc/default.script", ["/usr/share/udhcpc/default.script", "deconfig"], 0x295fbfb0 /* 12 vars */ <unfinished ...>
148   00:01:14.821800 <... vfork resumed>) = 149
148   00:01:14.822606 wait4(149,  <unfinished ...>
149   00:01:14.823007 <... execve resumed>) = 0
149   00:01:14.823559 set_tid_address(0x295faf94) = 149
149   00:01:14.824135 brk(NULL)         = 0x4c0000
149   00:01:14.824568 brk(0x4c2000)     = 0x4c2000
149   00:01:14.824983 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
149   00:01:14.825728 mprotect(0x295f8000, 4096, PROT_READ) = 0
149   00:01:14.826526 mprotect(0x4be000, 4096, PROT_READ) = 0
149   00:01:14.827180 getuid32()        = 0
149   00:01:14.827748 getpid()          = 149
149   00:01:14.828221 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295ea000
149   00:01:14.828963 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
149   00:01:14.829549 rt_sigaction(SIGCHLD, {sa_handler=0x4379f4, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
149   00:01:14.830347 getppid()         = 148
149   00:01:14.830837 uname({sysname="Linux", nodename="buildroot", ...}) = 0
149   00:01:14.831484 statx(AT_FDCWD, "/tmp", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=STATX_ATTR_MOUNT_ROOT, stx_mode=S_IFDIR|S_ISVTX|0777, stx_size=140, ...}) = 0
149   00:01:14.832588 statx(AT_FDCWD, ".", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=STATX_ATTR_MOUNT_ROOT, stx_mode=S_IFDIR|S_ISVTX|0777, stx_size=140, ...}) = 0
149   00:01:14.833685 open("/usr/share/udhcpc/default.script", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
149   00:01:14.834370 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
149   00:01:14.834866 fcntl64(3, F_DUPFD_CLOEXEC, 10) = 10
149   00:01:14.835292 fcntl64(10, F_SETFD, FD_CLOEXEC) = 0
149   00:01:14.835741 close(3)          = 0
149   00:01:14.836188 rt_sigaction(SIGINT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
149   00:01:14.836753 rt_sigaction(SIGINT, {sa_handler=0x4379f4, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
149   00:01:14.837374 rt_sigaction(SIGQUIT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
149   00:01:14.837985 rt_sigaction(SIGQUIT, {sa_handler=SIG_IGN, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
149   00:01:14.838602 rt_sigaction(SIGTERM, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
149   00:01:14.839200 read(10, "#!/bin/sh\n\n# udhcpc script edited by Tim Riker <Tim@Rikers.org>\n\n[ -z \"$1\" ] && echo \"Error: should be called from udhcpc\" && exit 1\n\nRESOLV_CONF=\"/etc/resolv.conf\"\n[ -e $RESOLV_CONF ] || touch $RESOLV_CONF\n[ -n \"$broadcast\" ] && BROADCAST=\"broadcast $broadcast\"\n[ -n \"$subnet\" ] && NETMASK=\"netmask $subnet\"\n# Handle stateful DHCPv6 like DHCPv4\n[ -n \"$ipv6\" ] && ip=\"$ipv6/128\"\n\nif [ -z \"${IF_WAIT_DELAY}\" ]; then\n\tIF_WAIT_DELAY=10\nfi\n\nwait_for_ipv6_default_route() {\n\tprintf \"Waiting for IPv6 default route to appear\"\n\twhile [ $IF_WAIT_DELAY -gt 0 ]; do\n\t\tif ip -6 route list | grep -q default; then\n\t\t\tprintf \"\\n\"\n\t\t\treturn\n\t\tfi\n\t\tsleep 1\n\t\tprintf \".\"\n\t\t: $((IF_WAIT_DELAY -= 1))\n\tdone\n\tprintf \" timeout!\\n\"\n}\n\ncase \"$1\" in\n\tdeconfig)\n\t\t/sbin/ifconfig $interface up\n\t\t/sbin/ifconfig $interface 0.0.0.0\n\n\t\t# drop info from this interface\n\t\t# resolv.conf may be a symlink to /tmp/, so take care\n\t\tTMPFILE=$(mktemp)\n\t\tgrep -vE \"# $interface\\$\" $RESOLV_CONF > $TMPFILE\n\t\tcat $TMPFILE > $RESOLV_CONF\n\t\t"..., 1023) = 1023
149   00:01:14.840495 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295eb000
149   00:01:14.841488 statx(AT_FDCWD, "/etc/resolv.conf", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=27, ...}) = 0
149   00:01:14.845240 read(10, "-x /usr/sbin/avahi-autoipd ]; then\n\t\t\t/usr/sbin/avahi-autoipd -c $interface && /usr/sbin/avahi-autoipd -k $interface\n\t\tfi\n\t\t;;\n\n\tleasefail|nak)\n\t\tif [ -x /usr/sbin/avahi-autoipd ]; then\n\t\t\t/usr/sbin/avahi-autoipd -c $interface || /usr/sbin/avahi-autoipd -wD $interface --no-chroot\n\t\tfi\n\t\t;;\n\n\trenew|bound)\n\t\tif [ -x /usr/sbin/avahi-autoipd ]; then\n\t\t\t/usr/sbin/avahi-autoipd -c $interface && /usr/sbin/avahi-autoipd -k $interface\n\t\tfi\n\t\t/sbin/ifconfig $interface $ip $BROADCAST $NETMASK\n\t\tif [ -n \"$ipv6\" ] ; then\n\t\t\twait_for_ipv6_default_route\n\t\tfi\n\n\t\t# RFC3442: If the DHCP server returns both a Classless\n\t\t# Static Routes option and a Router option, the DHCP\n\t\t# client MUST ignore the Router option.\n\t\tif [ -n \"$staticroutes\" ]; then\n\t\t\techo \"deleting routers\"\n\t\t\troute -n | while read dest gw mask flags metric ref use iface; do\n\t\t\t\t[ \"$iface\" != \"$interface\" -o \"$gw\" = \"0.0.0.0\" ] || \\\n\t\t\t\t\troute del -net \"$dest\" netmask \"$mask\" gw \"$gw\" dev \"$interface\"\n\t\t\tdone\n\n\t\t\t# format: dest1/mask gw1"..., 1023) = 1023
149   00:01:14.847204 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295ec000
149   00:01:14.848965 read(10, "set -- $staticroutes\n\t\t\twhile [ -n \"$1\" -a -n \"$2\" ]; do\n\t\t\t\troute add -net \"$1\" gw \"$2\" dev \"$interface\"\n\t\t\t\tshift 2\n\t\t\tdone\n\t\telif [ -n \"$router\" ] ; then\n\t\t\techo \"deleting routers\"\n\t\t\twhile route del default gw 0.0.0.0 dev $interface 2> /dev/null; do\n\t\t\t\t:\n\t\t\tdone\n\n\t\t\tfor i in $router ; do\n\t\t\t\troute add default gw $i dev $interface\n\t\t\tdone\n\t\tfi\n\n\t\t# drop info from this interface\n\t\t# resolv.conf may be a symlink to /tmp/, so take care\n\t\tTMPFILE=$(mktemp)\n\t\tgrep -vE \"# $interface\\$\" $RESOLV_CONF > $TMPFILE\n\t\tcat $TMPFILE > $RESOLV_CONF\n\t\trm -f $TMPFILE\n\n\t\t# prefer rfc3397 domain search list (option 119) if available\n\t\tif [ -n \"$search\" ]; then\n\t\t\tsearch_list=$search\n\t\telif [ -n \"$domain\" ]; then\n\t\t\tsearch_list=$domain\n\t\tfi\n\n\t\t[ -n \"$search_list\" ] &&\n\t\t\techo \"search $search_list # $interface\" >> $RESOLV_CONF\n\n\t\tfor i in $dns ; do\n\t\t\techo adding dns $i\n\t\t\techo \"nameserver $i # $interface\" >> $RESOLV_CONF\n\t\tdone\n\t\t;;\nesac\n\nHOOK_DIR=\"$0.d\"\nfor hook in \"${HOOK_DIR}/\"*; do\n    [ -f \"${hook"..., 1023) = 1023
149   00:01:14.850631 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295ed000
149   00:01:14.852772 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
149   00:01:14.853427 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
149   00:01:14.854067 fork()            = 150
149   00:01:14.854756 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
149   00:01:14.855340 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
149   00:01:14.855911 wait4(-1,  <unfinished ...>
150   00:01:14.856325 gettid()          = 150
150   00:01:14.856883 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
150   00:01:14.857476 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
150   00:01:14.858144 close(10)         = 0
150   00:01:14.858604 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
150   00:01:14.859379 execve("/sbin/ifconfig", ["/sbin/ifconfig", "eth0", "up"], 0x295eda04 /* 12 vars */) = 0
150   00:01:14.862391 set_tid_address(0x295faf94) = 150
150   00:01:14.863655 brk(NULL)         = 0x4c0000
150   00:01:14.864532 brk(0x4c2000)     = 0x4c2000
150   00:01:14.865440 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
150   00:01:14.867189 mprotect(0x295f8000, 4096, PROT_READ) = 0
150   00:01:14.869004 mprotect(0x4be000, 4096, PROT_READ) = 0
150   00:01:14.870087 getuid32()        = 0
150   00:01:14.870621 socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
150   00:01:14.871171 ioctl(3, SIOCGIFFLAGS, {ifr_name="eth0", ifr_flags=IFF_UP|IFF_BROADCAST|IFF_RUNNING|IFF_MULTICAST}) = 0
150   00:01:14.871909 ioctl(3, SIOCSIFFLAGS, {ifr_name="eth0", ifr_flags=IFF_UP|IFF_BROADCAST|IFF_RUNNING|IFF_MULTICAST}) = 0
150   00:01:14.872659 exit_group(0)     = ?
150   00:01:14.873240 +++ exited with 0 +++
149   00:01:14.873549 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 150
149   00:01:14.874007 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=150, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
149   00:01:14.874460 sigreturn()       = 150
149   00:01:14.874828 wait4(-1, 0x7b8b8964, WNOHANG, NULL) = -1 ECHILD (No child process)
149   00:01:14.875593 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
149   00:01:14.876216 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
149   00:01:14.876812 fork()            = 151
149   00:01:14.877442 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
149   00:01:14.878210 rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
151   00:01:14.878585 gettid( <unfinished ...>
149   00:01:14.878827 <... rt_sigprocmask resumed>NULL, 8) = 0
151   00:01:14.879189 <... gettid resumed>) = 151
149   00:01:14.879636 wait4(-1,  <unfinished ...>
151   00:01:14.879908 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
151   00:01:14.880474 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
151   00:01:14.881077 close(10)         = 0
151   00:01:14.881578 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
151   00:01:14.882387 execve("/sbin/ifconfig", ["/sbin/ifconfig", "eth0", "0.0.0.0"], 0x295eda04 /* 12 vars */) = 0
151   00:01:14.884044 set_tid_address(0x295faf94) = 151
151   00:01:14.884600 brk(NULL)         = 0x4c0000
151   00:01:14.884991 brk(0x4c2000)     = 0x4c2000
151   00:01:14.885424 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
151   00:01:14.886221 mprotect(0x295f8000, 4096, PROT_READ) = 0
151   00:01:14.886999 mprotect(0x4be000, 4096, PROT_READ) = 0
151   00:01:14.887634 getuid32()        = 0
151   00:01:14.888176 socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
151   00:01:14.888763 ioctl(3, SIOCSIFADDR, {ifr_name="eth0", ifr_addr={sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("0.0.0.0")}}) = 0
151   00:01:14.890126 ioctl(3, SIOCGIFFLAGS, {ifr_name="eth0", ifr_flags=IFF_UP|IFF_BROADCAST|IFF_RUNNING|IFF_MULTICAST}) = 0
151   00:01:14.890830 ioctl(3, SIOCSIFFLAGS, {ifr_name="eth0", ifr_flags=IFF_UP|IFF_BROADCAST|IFF_RUNNING|IFF_MULTICAST}) = 0
151   00:01:14.891587 exit_group(0)     = ?
151   00:01:14.892248 +++ exited with 0 +++
149   00:01:14.892437 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 151
149   00:01:14.892855 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=151, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
149   00:01:14.893283 sigreturn()       = 151
149   00:01:14.893676 wait4(-1, 0x7b8b8964, WNOHANG, NULL) = -1 ECHILD (No child process)
149   00:01:14.894402 pipe([3, 0])      = 3
149   00:01:14.894941 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
149   00:01:14.895579 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
149   00:01:14.896185 fork()            = 152
149   00:01:14.896824 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
149   00:01:14.897379 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
149   00:01:14.898012 close(4)          = 0
149   00:01:14.898493 read(3,  <unfinished ...>
152   00:01:14.898909 gettid()          = 152
152   00:01:14.899453 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
152   00:01:14.900073 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
152   00:01:14.900694 close(10)         = 0
152   00:01:14.901215 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
152   00:01:14.901947 close(3)          = 0
152   00:01:14.902386 dup2(4, 1)        = 1
152   00:01:14.902828 close(4)          = 0
152   00:01:14.903493 statx(AT_FDCWD, "/sbin/mktemp", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b867c) = -1 ENOENT (No such file or directory)
152   00:01:14.904350 statx(AT_FDCWD, "/usr/sbin/mktemp", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b867c) = -1 ENOENT (No such file or directory)
152   00:01:14.905219 statx(AT_FDCWD, "/bin/mktemp", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|S_ISUID|0755, stx_size=719260, ...}) = 0
152   00:01:14.906411 execve("/bin/mktemp", ["mktemp"], 0x295ed9e4 /* 12 vars */) = 0
152   00:01:14.908077 set_tid_address(0x295faf94) = 152
152   00:01:14.908657 brk(NULL)         = 0x4c0000
152   00:01:14.909091 brk(0x4c2000)     = 0x4c2000
152   00:01:14.909509 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
152   00:01:14.910324 mprotect(0x295f8000, 4096, PROT_READ) = 0
152   00:01:14.911111 mprotect(0x4be000, 4096, PROT_READ) = 0
152   00:01:14.911775 getuid32()        = 0
152   00:01:14.912527 clock_gettime64(CLOCK_REALTIME, {tv_sec=74, tv_nsec=912746788}) = 0
152   00:01:14.913100 open("/tmp/tmp.kJfCJh", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) = 3
152   00:01:14.913909 ioctl(1, _IOC(_IOC_READ, 0x74, 0x68, 0x8), 0x7ba83d58) = -1 ENOTTY (Not a tty)
152   00:01:14.914501 writev(1, [{iov_base="/tmp/tmp.kJfCJh", iov_len=15}, {iov_base="\n", iov_len=1}], 2) = 16
149   00:01:14.915257 <... read resumed>"/tmp/tmp.kJfCJh\n", 128) = 16
152   00:01:14.915787 exit_group(0 <unfinished ...>
149   00:01:14.916074 read(3,  <unfinished ...>
152   00:01:14.916360 <... exit_group resumed>) = ?
152   00:01:14.916808 +++ exited with 0 +++
149   00:01:14.916995 <... read resumed>"", 128) = 0
149   00:01:14.917317 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=152, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
149   00:01:14.917754 sigreturn()       = 0
149   00:01:14.918225 close(3)          = 0
149   00:01:14.918716 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 152
149   00:01:14.919344 wait4(-1, 0x7b8b887c, WNOHANG, NULL) = -1 ECHILD (No child process)
149   00:01:14.920220 open("/tmp/tmp.kJfCJh", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 3
149   00:01:14.921007 fcntl64(1, F_DUPFD_CLOEXEC, 10) = 11
149   00:01:14.921455 fcntl64(11, F_SETFD, FD_CLOEXEC) = 0
149   00:01:14.921995 dup2(3, 1)        = 1
149   00:01:14.922436 close(3)          = 0
149   00:01:14.922910 statx(AT_FDCWD, "/sbin/grep", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b8868) = -1 ENOENT (No such file or directory)
149   00:01:14.923774 statx(AT_FDCWD, "/usr/sbin/grep", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b8868) = -1 ENOENT (No such file or directory)
149   00:01:14.924634 statx(AT_FDCWD, "/bin/grep", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|S_ISUID|0755, stx_size=719260, ...}) = 0
149   00:01:14.925771 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
149   00:01:14.926468 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
149   00:01:14.927060 fork()            = 153
149   00:01:14.927718 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
149   00:01:14.928310 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
149   00:01:14.928897 wait4(-1,  <unfinished ...>
153   00:01:14.929332 gettid()          = 153
153   00:01:14.929944 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
153   00:01:14.930555 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
153   00:01:14.931195 close(10)         = 0
153   00:01:14.931657 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
153   00:01:14.932491 execve("/bin/grep", ["grep", "-vE", "# eth0$", "/etc/resolv.conf"], 0x295eda3c /* 12 vars */) = 0
153   00:01:14.934241 set_tid_address(0x295faf94) = 153
153   00:01:14.934826 brk(NULL)         = 0x4c0000
153   00:01:14.935235 brk(0x4c2000)     = 0x4c2000
153   00:01:14.935675 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
153   00:01:14.936442 mprotect(0x295f8000, 4096, PROT_READ) = 0
153   00:01:14.937215 mprotect(0x4be000, 4096, PROT_READ) = 0
153   00:01:14.937884 getuid32()        = 0
153   00:01:14.938548 open("/etc/resolv.conf", O_RDONLY|O_LARGEFILE) = 3
153   00:01:14.939278 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295ea000
153   00:01:14.939984 read(3, "nameserver 10.0.2.3 # eth0\n", 1024) = 27
153   00:01:14.940648 mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295eb000
153   00:01:14.941526 munmap(0x295eb000, 8192) = 0
153   00:01:14.942271 read(3, "", 1024) = 0
153   00:01:14.942796 close(3)          = 0
153   00:01:14.943267 munmap(0x295ea000, 4096) = 0
153   00:01:14.943777 exit_group(1)     = ?
153   00:01:14.944421 +++ exited with 1 +++
149   00:01:14.944623 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 1}], 0, NULL) = 153
149   00:01:14.945037 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=153, si_uid=0, si_status=1, si_utime=0, si_stime=0} ---
149   00:01:14.945505 sigreturn()       = 153
149   00:01:14.945946 wait4(-1, 0x7b8b89bc, WNOHANG, NULL) = -1 ECHILD (No child process)
149   00:01:14.946566 dup2(11, 1)       = 1
149   00:01:14.947085 close(11)         = 0
149   00:01:14.947752 open("/etc/resolv.conf", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 3
149   00:01:14.948764 fcntl64(1, F_DUPFD_CLOEXEC, 10) = 11
149   00:01:14.949223 fcntl64(11, F_SETFD, FD_CLOEXEC) = 0
149   00:01:14.949681 dup2(3, 1)        = 1
149   00:01:14.950166 close(3)          = 0
149   00:01:14.950615 statx(AT_FDCWD, "/sbin/cat", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b8894) = -1 ENOENT (No such file or directory)
149   00:01:14.951450 statx(AT_FDCWD, "/usr/sbin/cat", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b8894) = -1 ENOENT (No such file or directory)
149   00:01:14.952318 statx(AT_FDCWD, "/bin/cat", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|S_ISUID|0755, stx_size=719260, ...}) = 0
149   00:01:14.953416 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
149   00:01:14.954072 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
149   00:01:14.954710 fork()            = 154
149   00:01:14.955371 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
149   00:01:14.955915 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
149   00:01:14.956480 wait4(-1,  <unfinished ...>
154   00:01:14.956911 gettid()          = 154
154   00:01:14.957469 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
154   00:01:14.958107 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
154   00:01:14.958726 close(10)         = 0
154   00:01:14.959220 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
154   00:01:14.960010 execve("/bin/cat", ["cat", "/tmp/tmp.kJfCJh"], 0x295eda0c /* 12 vars */) = 0
154   00:01:14.961650 set_tid_address(0x295faf94) = 154
154   00:01:14.962260 brk(NULL)         = 0x4c0000
154   00:01:14.962677 brk(0x4c2000)     = 0x4c2000
154   00:01:14.963093 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
154   00:01:14.963855 mprotect(0x295f8000, 4096, PROT_READ) = 0
154   00:01:14.964649 mprotect(0x4be000, 4096, PROT_READ) = 0
154   00:01:14.965332 getuid32()        = 0
154   00:01:14.965963 open("/tmp/tmp.kJfCJh", O_RDONLY|O_LARGEFILE) = 3
154   00:01:14.966693 sendfile64(1, 3, NULL, 16777216) = 0
154   00:01:14.967225 close(3)          = 0
154   00:01:14.967771 exit_group(0)     = ?
154   00:01:14.968431 +++ exited with 0 +++
149   00:01:14.968637 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 154
149   00:01:14.969062 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=154, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
149   00:01:14.969524 sigreturn()       = 154
149   00:01:14.970021 wait4(-1, 0x7b8b89e8, WNOHANG, NULL) = -1 ECHILD (No child process)
149   00:01:14.970630 dup2(11, 1)       = 1
149   00:01:14.971135 close(11)         = 0
149   00:01:14.971803 statx(AT_FDCWD, "/sbin/rm", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b88c0) = -1 ENOENT (No such file or directory)
149   00:01:14.972693 statx(AT_FDCWD, "/usr/sbin/rm", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b88c0) = -1 ENOENT (No such file or directory)
149   00:01:14.973506 statx(AT_FDCWD, "/bin/rm", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|S_ISUID|0755, stx_size=719260, ...}) = 0
149   00:01:14.974668 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
149   00:01:14.975332 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
149   00:01:14.975936 fork()            = 155
149   00:01:14.976585 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
149   00:01:14.977166 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
149   00:01:14.977733 wait4(-1,  <unfinished ...>
155   00:01:14.978296 gettid()          = 155
155   00:01:14.978860 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
155   00:01:14.979466 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
155   00:01:14.980076 close(10)         = 0
155   00:01:14.980557 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
155   00:01:14.981350 execve("/bin/rm", ["rm", "-f", "/tmp/tmp.kJfCJh"], 0x295eda04 /* 12 vars */) = 0
155   00:01:14.983082 set_tid_address(0x295faf94) = 155
155   00:01:14.983662 brk(NULL)         = 0x4c0000
155   00:01:14.984120 brk(0x4c2000)     = 0x4c2000
155   00:01:14.984536 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
155   00:01:14.985336 mprotect(0x295f8000, 4096, PROT_READ) = 0
155   00:01:14.986187 mprotect(0x4be000, 4096, PROT_READ) = 0
155   00:01:14.986851 getuid32()        = 0
155   00:01:14.987464 statx(AT_FDCWD, "/tmp/tmp.kJfCJh", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0600, stx_size=0, ...}) = 0
155   00:01:14.988583 unlink("/tmp/tmp.kJfCJh") = 0
155   00:01:14.989318 exit_group(0)     = ?
155   00:01:14.989984 +++ exited with 0 +++
149   00:01:14.990176 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 155
149   00:01:14.990593 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=155, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
149   00:01:14.991041 sigreturn()       = 155
149   00:01:14.991439 wait4(-1, 0x7b8b8a14, WNOHANG, NULL) = -1 ECHILD (No child process)
149   00:01:14.992291 statx(AT_FDCWD, "/usr/sbin/avahi-autoipd", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b87c0) = -1 ENOENT (No such file or directory)
149   00:01:14.993194 munmap(0x295ed000, 4096) = 0
149   00:01:14.993755 munmap(0x295ec000, 4096) = 0
149   00:01:14.994865 read(10, " continue\n    \"${hook}\" \"${@}\"\ndone\n\nexit 0\n", 1023) = 44
149   00:01:14.995743 mmap2(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295ec000
149   00:01:14.996482 open("/usr/share/udhcpc/default.script.d/", O_RDONLY|O_LARGEFILE|O_CLOEXEC|O_DIRECTORY) = 3
149   00:01:14.997188 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
149   00:01:14.997687 mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295f0000
149   00:01:14.998402 getdents64(3, 0x295f0088 /* 2 entries */, 2048) = 48
149   00:01:14.999027 getdents64(3, 0x295f0088 /* 0 entries */, 2048) = 0
149   00:01:14.999576 close(3)          = 0
149   00:01:15.000076 munmap(0x295f0000, 8192) = 0
149   00:01:15.000603 munmap(0x295ec000, 16384) = 0
149   00:01:15.001370 statx(AT_FDCWD, "/usr/share/udhcpc/default.script.d/*", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b87d0) = -1 ENOENT (No such file or directory)
149   00:01:15.002240 statx(AT_FDCWD, "/usr/share/udhcpc/default.script.d/*", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b87bc) = -1 ENOENT (No such file or directory)
149   00:01:15.003345 exit_group(0)     = ?
149   00:01:15.003998 +++ exited with 0 +++
148   00:01:15.004204 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 149
148   00:01:15.004606 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=149, si_uid=0, si_status=0, si_utime=0, si_stime=2} ---
148   00:01:15.005134 socket(AF_PACKET, SOCK_DGRAM, htons(ETH_P_IP)) = 5
148   00:01:15.005673 bind(5, {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=0}, 20) = 0
148   00:01:15.006493 setsockopt(5, SOL_PACKET, PACKET_AUXDATA, [1], 4) = 0
148   00:01:15.007093 fcntl64(5, F_SETFD, FD_CLOEXEC) = 0
148   00:01:15.007594 socket(AF_INET, SOCK_RAW, IPPROTO_RAW) = 6
148   00:01:15.008067 ioctl(6, SIOCGIFINDEX, {ifr_name="eth0", }) = 0
148   00:01:15.008670 ioctl(6, SIOCGIFHWADDR, {ifr_name="eth0", ifr_hwaddr={sa_family=ARPHRD_ETHER, sa_data=52:54:00:12:34:56}}) = 0
148   00:01:15.009520 close(6)          = 0
148   00:01:15.010058 clock_gettime64(CLOCK_MONOTONIC, {tv_sec=75, tv_nsec=10264188}) = 0
148   00:01:15.010691 write(2, "udhcpc: sending discover\n", 25) = 25
148   00:01:15.011397 socket(AF_PACKET, SOCK_DGRAM, htons(ETH_P_IP)) = 6
148   00:01:15.011946 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, 0xff, 0xff, 0xff]}, 20) = 0
148   00:01:15.012830 sendto(6, "E\0\1H\0\0\0\0@\21y\246\0\0\0\0\377\377\377\377\0D\0C\0014!~\1\1\6\0\272\352\336g\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\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\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\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\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\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\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\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\0\0c\202Sc5\1\1=\7\1RT\0\0224V9\2\2@7\7\1\3\6\f\17\34*<\fudhcp 1.33.0\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 328, 0, {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, 0xff, 0xff, 0xff]}, 20

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

[Eric Dumazet]

On Mon, Apr 12, 2021 at 8:23 AM Guenter Roeck <linux@roeck-us.net> wrote:
>
> Hi Eric,
>
> On Mon, Apr 12, 2021 at 07:53:43AM +0200, Eric Dumazet wrote:
> > On Mon, Apr 12, 2021 at 7:48 AM Eric Dumazet <edumazet@google.com> wrote:
> > >
> >
> > > give a verdict.
> > >
> > > Please post the whole strace output.
> > >
> > > Thanks.
> >
> > Also please add -tt option to strace so that we have an idea of time
> > delays just in case.
> >
>
> The exact command as executed is:
>
> strace -tt -o /tmp/STRACE -f -s 1000 udhcpc -n -q
>
> Log is below. This is the complete log: nothing was truncated, neither
> at the beginning nor at the end. The log ends with sendto().
>
> Hope this helps,
>
> Guenter
>
> ---
> 148   00:01:14.802467 execve("/sbin/udhcpc", ["udhcpc", "-n", "-q"], 0x7bbbbe10 /* 11 vars */) = 0
> 148   00:01:14.804496 set_tid_address(0x295faf94) = 148
> 148   00:01:14.805081 brk(NULL)         = 0x4c0000
> 148   00:01:14.805495 brk(0x4c2000)     = 0x4c2000
> 148   00:01:14.805998 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
> 148   00:01:14.806750 mprotect(0x295f8000, 4096, PROT_READ) = 0
> 148   00:01:14.807524 mprotect(0x4be000, 4096, PROT_READ) = 0
> 148   00:01:14.808169 getuid32()        = 0
> 148   00:01:14.808670 open("/dev/null", O_RDWR|O_LARGEFILE) = 3
> 148   00:01:14.809415 close(3)          = 0
> 148   00:01:14.809886 pipe([3, 0])      = 3
> 148   00:01:14.810373 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
> 148   00:01:14.810827 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0
> 148   00:01:14.811274 fcntl64(3, F_GETFL) = 0 (flags O_RDONLY)
> 148   00:01:14.811703 fcntl64(3, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
> 148   00:01:14.812156 fcntl64(4, F_GETFL) = 0x1 (flags O_WRONLY)
> 148   00:01:14.812602 fcntl64(4, F_SETFL, O_WRONLY|O_NONBLOCK|O_LARGEFILE) = 0
> 148   00:01:14.813088 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
> 148   00:01:14.813648 rt_sigaction(SIGUSR1, {sa_handler=0x4328b0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x295b6a2a}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
> 148   00:01:14.814381 rt_sigaction(SIGUSR2, {sa_handler=0x4328b0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x295b6a2a}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
> 148   00:01:14.815106 rt_sigaction(SIGTERM, {sa_handler=0x4328b0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x295b6a2a}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
> 148   00:01:14.815910 socket(AF_INET, SOCK_RAW, IPPROTO_RAW) = 5
> 148   00:01:14.816484 ioctl(5, SIOCGIFINDEX, {ifr_name="eth0", }) = 0
> 148   00:01:14.817111 ioctl(5, SIOCGIFHWADDR, {ifr_name="eth0", ifr_hwaddr={sa_family=ARPHRD_ETHER, sa_data=52:54:00:12:34:56}}) = 0
> 148   00:01:14.818042 close(5)          = 0
> 148   00:01:14.818660 write(2, "udhcpc: started, v1.33.0\n", 25) = 25
> 148   00:01:14.819387 clock_gettime64(CLOCK_MONOTONIC, {tv_sec=74, tv_nsec=819590988}) = 0
> 148   00:01:14.820117 vfork( <unfinished ...>
> 149   00:01:14.820652 execve("/usr/share/udhcpc/default.script", ["/usr/share/udhcpc/default.script", "deconfig"], 0x295fbfb0 /* 12 vars */ <unfinished ...>
> 148   00:01:14.821800 <... vfork resumed>) = 149
> 148   00:01:14.822606 wait4(149,  <unfinished ...>
> 149   00:01:14.823007 <... execve resumed>) = 0
> 149   00:01:14.823559 set_tid_address(0x295faf94) = 149
> 149   00:01:14.824135 brk(NULL)         = 0x4c0000
> 149   00:01:14.824568 brk(0x4c2000)     = 0x4c2000
> 149   00:01:14.824983 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
> 149   00:01:14.825728 mprotect(0x295f8000, 4096, PROT_READ) = 0
> 149   00:01:14.826526 mprotect(0x4be000, 4096, PROT_READ) = 0
> 149   00:01:14.827180 getuid32()        = 0
> 149   00:01:14.827748 getpid()          = 149
> 149   00:01:14.828221 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295ea000
> 149   00:01:14.828963 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
> 149   00:01:14.829549 rt_sigaction(SIGCHLD, {sa_handler=0x4379f4, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
> 149   00:01:14.830347 getppid()         = 148
> 149   00:01:14.830837 uname({sysname="Linux", nodename="buildroot", ...}) = 0
> 149   00:01:14.831484 statx(AT_FDCWD, "/tmp", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=STATX_ATTR_MOUNT_ROOT, stx_mode=S_IFDIR|S_ISVTX|0777, stx_size=140, ...}) = 0
> 149   00:01:14.832588 statx(AT_FDCWD, ".", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=STATX_ATTR_MOUNT_ROOT, stx_mode=S_IFDIR|S_ISVTX|0777, stx_size=140, ...}) = 0
> 149   00:01:14.833685 open("/usr/share/udhcpc/default.script", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
> 149   00:01:14.834370 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
> 149   00:01:14.834866 fcntl64(3, F_DUPFD_CLOEXEC, 10) = 10
> 149   00:01:14.835292 fcntl64(10, F_SETFD, FD_CLOEXEC) = 0
> 149   00:01:14.835741 close(3)          = 0
> 149   00:01:14.836188 rt_sigaction(SIGINT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
> 149   00:01:14.836753 rt_sigaction(SIGINT, {sa_handler=0x4379f4, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
> 149   00:01:14.837374 rt_sigaction(SIGQUIT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
> 149   00:01:14.837985 rt_sigaction(SIGQUIT, {sa_handler=SIG_IGN, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
> 149   00:01:14.838602 rt_sigaction(SIGTERM, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
> 149   00:01:14.839200 read(10, "#!/bin/sh\n\n# udhcpc script edited by Tim Riker <Tim@Rikers.org>\n\n[ -z \"$1\" ] && echo \"Error: should be called from udhcpc\" && exit 1\n\nRESOLV_CONF=\"/etc/resolv.conf\"\n[ -e $RESOLV_CONF ] || touch $RESOLV_CONF\n[ -n \"$broadcast\" ] && BROADCAST=\"broadcast $broadcast\"\n[ -n \"$subnet\" ] && NETMASK=\"netmask $subnet\"\n# Handle stateful DHCPv6 like DHCPv4\n[ -n \"$ipv6\" ] && ip=\"$ipv6/128\"\n\nif [ -z \"${IF_WAIT_DELAY}\" ]; then\n\tIF_WAIT_DELAY=10\nfi\n\nwait_for_ipv6_default_route() {\n\tprintf \"Waiting for IPv6 default route to appear\"\n\twhile [ $IF_WAIT_DELAY -gt 0 ]; do\n\t\tif ip -6 route list | grep -q default; then\n\t\t\tprintf \"\\n\"\n\t\t\treturn\n\t\tfi\n\t\tsleep 1\n\t\tprintf \".\"\n\t\t: $((IF_WAIT_DELAY -= 1))\n\tdone\n\tprintf \" timeout!\\n\"\n}\n\ncase \"$1\" in\n\tdeconfig)\n\t\t/sbin/ifconfig $interface up\n\t\t/sbin/ifconfig $interface 0.0.0.0\n\n\t\t# drop info from this interface\n\t\t# resolv.conf may be a symlink to /tmp/, so take care\n\t\tTMPFILE=$(mktemp)\n\t\tgrep -vE \"# $interface\\$\" $RESOLV_CONF > $TMPFILE\n\t\tcat $TMPFILE > $RESOLV_CONF\n\t\t"..., 1023) = 1023
> 149   00:01:14.840495 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295eb000
> 149   00:01:14.841488 statx(AT_FDCWD, "/etc/resolv.conf", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=27, ...}) = 0
> 149   00:01:14.845240 read(10, "-x /usr/sbin/avahi-autoipd ]; then\n\t\t\t/usr/sbin/avahi-autoipd -c $interface && /usr/sbin/avahi-autoipd -k $interface\n\t\tfi\n\t\t;;\n\n\tleasefail|nak)\n\t\tif [ -x /usr/sbin/avahi-autoipd ]; then\n\t\t\t/usr/sbin/avahi-autoipd -c $interface || /usr/sbin/avahi-autoipd -wD $interface --no-chroot\n\t\tfi\n\t\t;;\n\n\trenew|bound)\n\t\tif [ -x /usr/sbin/avahi-autoipd ]; then\n\t\t\t/usr/sbin/avahi-autoipd -c $interface && /usr/sbin/avahi-autoipd -k $interface\n\t\tfi\n\t\t/sbin/ifconfig $interface $ip $BROADCAST $NETMASK\n\t\tif [ -n \"$ipv6\" ] ; then\n\t\t\twait_for_ipv6_default_route\n\t\tfi\n\n\t\t# RFC3442: If the DHCP server returns both a Classless\n\t\t# Static Routes option and a Router option, the DHCP\n\t\t# client MUST ignore the Router option.\n\t\tif [ -n \"$staticroutes\" ]; then\n\t\t\techo \"deleting routers\"\n\t\t\troute -n | while read dest gw mask flags metric ref use iface; do\n\t\t\t\t[ \"$iface\" != \"$interface\" -o \"$gw\" = \"0.0.0.0\" ] || \\\n\t\t\t\t\troute del -net \"$dest\" netmask \"$mask\" gw \"$gw\" dev \"$interface\"\n\t\t\tdone\n\n\t\t\t# format: dest1/mask gw1"..., 1023) = 1023
> 149   00:01:14.847204 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295ec000
> 149   00:01:14.848965 read(10, "set -- $staticroutes\n\t\t\twhile [ -n \"$1\" -a -n \"$2\" ]; do\n\t\t\t\troute add -net \"$1\" gw \"$2\" dev \"$interface\"\n\t\t\t\tshift 2\n\t\t\tdone\n\t\telif [ -n \"$router\" ] ; then\n\t\t\techo \"deleting routers\"\n\t\t\twhile route del default gw 0.0.0.0 dev $interface 2> /dev/null; do\n\t\t\t\t:\n\t\t\tdone\n\n\t\t\tfor i in $router ; do\n\t\t\t\troute add default gw $i dev $interface\n\t\t\tdone\n\t\tfi\n\n\t\t# drop info from this interface\n\t\t# resolv.conf may be a symlink to /tmp/, so take care\n\t\tTMPFILE=$(mktemp)\n\t\tgrep -vE \"# $interface\\$\" $RESOLV_CONF > $TMPFILE\n\t\tcat $TMPFILE > $RESOLV_CONF\n\t\trm -f $TMPFILE\n\n\t\t# prefer rfc3397 domain search list (option 119) if available\n\t\tif [ -n \"$search\" ]; then\n\t\t\tsearch_list=$search\n\t\telif [ -n \"$domain\" ]; then\n\t\t\tsearch_list=$domain\n\t\tfi\n\n\t\t[ -n \"$search_list\" ] &&\n\t\t\techo \"search $search_list # $interface\" >> $RESOLV_CONF\n\n\t\tfor i in $dns ; do\n\t\t\techo adding dns $i\n\t\t\techo \"nameserver $i # $interface\" >> $RESOLV_CONF\n\t\tdone\n\t\t;;\nesac\n\nHOOK_DIR=\"$0.d\"\nfor hook in \"${HOOK_DIR}/\"*; do\n    [ -f \"${hook"..., 1023) = 1023
> 149   00:01:14.850631 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295ed000
> 149   00:01:14.852772 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
> 149   00:01:14.853427 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
> 149   00:01:14.854067 fork()            = 150
> 149   00:01:14.854756 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 149   00:01:14.855340 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> 149   00:01:14.855911 wait4(-1,  <unfinished ...>
> 150   00:01:14.856325 gettid()          = 150
> 150   00:01:14.856883 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 150   00:01:14.857476 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> 150   00:01:14.858144 close(10)         = 0
> 150   00:01:14.858604 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
> 150   00:01:14.859379 execve("/sbin/ifconfig", ["/sbin/ifconfig", "eth0", "up"], 0x295eda04 /* 12 vars */) = 0
> 150   00:01:14.862391 set_tid_address(0x295faf94) = 150
> 150   00:01:14.863655 brk(NULL)         = 0x4c0000
> 150   00:01:14.864532 brk(0x4c2000)     = 0x4c2000
> 150   00:01:14.865440 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
> 150   00:01:14.867189 mprotect(0x295f8000, 4096, PROT_READ) = 0
> 150   00:01:14.869004 mprotect(0x4be000, 4096, PROT_READ) = 0
> 150   00:01:14.870087 getuid32()        = 0
> 150   00:01:14.870621 socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
> 150   00:01:14.871171 ioctl(3, SIOCGIFFLAGS, {ifr_name="eth0", ifr_flags=IFF_UP|IFF_BROADCAST|IFF_RUNNING|IFF_MULTICAST}) = 0
> 150   00:01:14.871909 ioctl(3, SIOCSIFFLAGS, {ifr_name="eth0", ifr_flags=IFF_UP|IFF_BROADCAST|IFF_RUNNING|IFF_MULTICAST}) = 0
> 150   00:01:14.872659 exit_group(0)     = ?
> 150   00:01:14.873240 +++ exited with 0 +++
> 149   00:01:14.873549 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 150
> 149   00:01:14.874007 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=150, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
> 149   00:01:14.874460 sigreturn()       = 150
> 149   00:01:14.874828 wait4(-1, 0x7b8b8964, WNOHANG, NULL) = -1 ECHILD (No child process)
> 149   00:01:14.875593 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
> 149   00:01:14.876216 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
> 149   00:01:14.876812 fork()            = 151
> 149   00:01:14.877442 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 149   00:01:14.878210 rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
> 151   00:01:14.878585 gettid( <unfinished ...>
> 149   00:01:14.878827 <... rt_sigprocmask resumed>NULL, 8) = 0
> 151   00:01:14.879189 <... gettid resumed>) = 151
> 149   00:01:14.879636 wait4(-1,  <unfinished ...>
> 151   00:01:14.879908 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 151   00:01:14.880474 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> 151   00:01:14.881077 close(10)         = 0
> 151   00:01:14.881578 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
> 151   00:01:14.882387 execve("/sbin/ifconfig", ["/sbin/ifconfig", "eth0", "0.0.0.0"], 0x295eda04 /* 12 vars */) = 0
> 151   00:01:14.884044 set_tid_address(0x295faf94) = 151
> 151   00:01:14.884600 brk(NULL)         = 0x4c0000
> 151   00:01:14.884991 brk(0x4c2000)     = 0x4c2000
> 151   00:01:14.885424 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
> 151   00:01:14.886221 mprotect(0x295f8000, 4096, PROT_READ) = 0
> 151   00:01:14.886999 mprotect(0x4be000, 4096, PROT_READ) = 0
> 151   00:01:14.887634 getuid32()        = 0
> 151   00:01:14.888176 socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
> 151   00:01:14.888763 ioctl(3, SIOCSIFADDR, {ifr_name="eth0", ifr_addr={sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("0.0.0.0")}}) = 0
> 151   00:01:14.890126 ioctl(3, SIOCGIFFLAGS, {ifr_name="eth0", ifr_flags=IFF_UP|IFF_BROADCAST|IFF_RUNNING|IFF_MULTICAST}) = 0
> 151   00:01:14.890830 ioctl(3, SIOCSIFFLAGS, {ifr_name="eth0", ifr_flags=IFF_UP|IFF_BROADCAST|IFF_RUNNING|IFF_MULTICAST}) = 0
> 151   00:01:14.891587 exit_group(0)     = ?
> 151   00:01:14.892248 +++ exited with 0 +++
> 149   00:01:14.892437 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 151
> 149   00:01:14.892855 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=151, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
> 149   00:01:14.893283 sigreturn()       = 151
> 149   00:01:14.893676 wait4(-1, 0x7b8b8964, WNOHANG, NULL) = -1 ECHILD (No child process)
> 149   00:01:14.894402 pipe([3, 0])      = 3
> 149   00:01:14.894941 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
> 149   00:01:14.895579 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
> 149   00:01:14.896185 fork()            = 152
> 149   00:01:14.896824 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 149   00:01:14.897379 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> 149   00:01:14.898012 close(4)          = 0
> 149   00:01:14.898493 read(3,  <unfinished ...>
> 152   00:01:14.898909 gettid()          = 152
> 152   00:01:14.899453 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 152   00:01:14.900073 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> 152   00:01:14.900694 close(10)         = 0
> 152   00:01:14.901215 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
> 152   00:01:14.901947 close(3)          = 0
> 152   00:01:14.902386 dup2(4, 1)        = 1
> 152   00:01:14.902828 close(4)          = 0
> 152   00:01:14.903493 statx(AT_FDCWD, "/sbin/mktemp", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b867c) = -1 ENOENT (No such file or directory)
> 152   00:01:14.904350 statx(AT_FDCWD, "/usr/sbin/mktemp", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b867c) = -1 ENOENT (No such file or directory)
> 152   00:01:14.905219 statx(AT_FDCWD, "/bin/mktemp", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|S_ISUID|0755, stx_size=719260, ...}) = 0
> 152   00:01:14.906411 execve("/bin/mktemp", ["mktemp"], 0x295ed9e4 /* 12 vars */) = 0
> 152   00:01:14.908077 set_tid_address(0x295faf94) = 152
> 152   00:01:14.908657 brk(NULL)         = 0x4c0000
> 152   00:01:14.909091 brk(0x4c2000)     = 0x4c2000
> 152   00:01:14.909509 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
> 152   00:01:14.910324 mprotect(0x295f8000, 4096, PROT_READ) = 0
> 152   00:01:14.911111 mprotect(0x4be000, 4096, PROT_READ) = 0
> 152   00:01:14.911775 getuid32()        = 0
> 152   00:01:14.912527 clock_gettime64(CLOCK_REALTIME, {tv_sec=74, tv_nsec=912746788}) = 0
> 152   00:01:14.913100 open("/tmp/tmp.kJfCJh", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) = 3
> 152   00:01:14.913909 ioctl(1, _IOC(_IOC_READ, 0x74, 0x68, 0x8), 0x7ba83d58) = -1 ENOTTY (Not a tty)
> 152   00:01:14.914501 writev(1, [{iov_base="/tmp/tmp.kJfCJh", iov_len=15}, {iov_base="\n", iov_len=1}], 2) = 16
> 149   00:01:14.915257 <... read resumed>"/tmp/tmp.kJfCJh\n", 128) = 16
> 152   00:01:14.915787 exit_group(0 <unfinished ...>
> 149   00:01:14.916074 read(3,  <unfinished ...>
> 152   00:01:14.916360 <... exit_group resumed>) = ?
> 152   00:01:14.916808 +++ exited with 0 +++
> 149   00:01:14.916995 <... read resumed>"", 128) = 0
> 149   00:01:14.917317 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=152, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
> 149   00:01:14.917754 sigreturn()       = 0
> 149   00:01:14.918225 close(3)          = 0
> 149   00:01:14.918716 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 152
> 149   00:01:14.919344 wait4(-1, 0x7b8b887c, WNOHANG, NULL) = -1 ECHILD (No child process)
> 149   00:01:14.920220 open("/tmp/tmp.kJfCJh", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 3
> 149   00:01:14.921007 fcntl64(1, F_DUPFD_CLOEXEC, 10) = 11
> 149   00:01:14.921455 fcntl64(11, F_SETFD, FD_CLOEXEC) = 0
> 149   00:01:14.921995 dup2(3, 1)        = 1
> 149   00:01:14.922436 close(3)          = 0
> 149   00:01:14.922910 statx(AT_FDCWD, "/sbin/grep", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b8868) = -1 ENOENT (No such file or directory)
> 149   00:01:14.923774 statx(AT_FDCWD, "/usr/sbin/grep", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b8868) = -1 ENOENT (No such file or directory)
> 149   00:01:14.924634 statx(AT_FDCWD, "/bin/grep", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|S_ISUID|0755, stx_size=719260, ...}) = 0
> 149   00:01:14.925771 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
> 149   00:01:14.926468 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
> 149   00:01:14.927060 fork()            = 153
> 149   00:01:14.927718 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 149   00:01:14.928310 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> 149   00:01:14.928897 wait4(-1,  <unfinished ...>
> 153   00:01:14.929332 gettid()          = 153
> 153   00:01:14.929944 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 153   00:01:14.930555 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> 153   00:01:14.931195 close(10)         = 0
> 153   00:01:14.931657 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
> 153   00:01:14.932491 execve("/bin/grep", ["grep", "-vE", "# eth0$", "/etc/resolv.conf"], 0x295eda3c /* 12 vars */) = 0
> 153   00:01:14.934241 set_tid_address(0x295faf94) = 153
> 153   00:01:14.934826 brk(NULL)         = 0x4c0000
> 153   00:01:14.935235 brk(0x4c2000)     = 0x4c2000
> 153   00:01:14.935675 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
> 153   00:01:14.936442 mprotect(0x295f8000, 4096, PROT_READ) = 0
> 153   00:01:14.937215 mprotect(0x4be000, 4096, PROT_READ) = 0
> 153   00:01:14.937884 getuid32()        = 0
> 153   00:01:14.938548 open("/etc/resolv.conf", O_RDONLY|O_LARGEFILE) = 3
> 153   00:01:14.939278 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295ea000
> 153   00:01:14.939984 read(3, "nameserver 10.0.2.3 # eth0\n", 1024) = 27
> 153   00:01:14.940648 mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295eb000
> 153   00:01:14.941526 munmap(0x295eb000, 8192) = 0
> 153   00:01:14.942271 read(3, "", 1024) = 0
> 153   00:01:14.942796 close(3)          = 0
> 153   00:01:14.943267 munmap(0x295ea000, 4096) = 0
> 153   00:01:14.943777 exit_group(1)     = ?
> 153   00:01:14.944421 +++ exited with 1 +++
> 149   00:01:14.944623 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 1}], 0, NULL) = 153
> 149   00:01:14.945037 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=153, si_uid=0, si_status=1, si_utime=0, si_stime=0} ---
> 149   00:01:14.945505 sigreturn()       = 153
> 149   00:01:14.945946 wait4(-1, 0x7b8b89bc, WNOHANG, NULL) = -1 ECHILD (No child process)
> 149   00:01:14.946566 dup2(11, 1)       = 1
> 149   00:01:14.947085 close(11)         = 0
> 149   00:01:14.947752 open("/etc/resolv.conf", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 3
> 149   00:01:14.948764 fcntl64(1, F_DUPFD_CLOEXEC, 10) = 11
> 149   00:01:14.949223 fcntl64(11, F_SETFD, FD_CLOEXEC) = 0
> 149   00:01:14.949681 dup2(3, 1)        = 1
> 149   00:01:14.950166 close(3)          = 0
> 149   00:01:14.950615 statx(AT_FDCWD, "/sbin/cat", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b8894) = -1 ENOENT (No such file or directory)
> 149   00:01:14.951450 statx(AT_FDCWD, "/usr/sbin/cat", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b8894) = -1 ENOENT (No such file or directory)
> 149   00:01:14.952318 statx(AT_FDCWD, "/bin/cat", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|S_ISUID|0755, stx_size=719260, ...}) = 0
> 149   00:01:14.953416 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
> 149   00:01:14.954072 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
> 149   00:01:14.954710 fork()            = 154
> 149   00:01:14.955371 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 149   00:01:14.955915 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> 149   00:01:14.956480 wait4(-1,  <unfinished ...>
> 154   00:01:14.956911 gettid()          = 154
> 154   00:01:14.957469 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 154   00:01:14.958107 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> 154   00:01:14.958726 close(10)         = 0
> 154   00:01:14.959220 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
> 154   00:01:14.960010 execve("/bin/cat", ["cat", "/tmp/tmp.kJfCJh"], 0x295eda0c /* 12 vars */) = 0
> 154   00:01:14.961650 set_tid_address(0x295faf94) = 154
> 154   00:01:14.962260 brk(NULL)         = 0x4c0000
> 154   00:01:14.962677 brk(0x4c2000)     = 0x4c2000
> 154   00:01:14.963093 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
> 154   00:01:14.963855 mprotect(0x295f8000, 4096, PROT_READ) = 0
> 154   00:01:14.964649 mprotect(0x4be000, 4096, PROT_READ) = 0
> 154   00:01:14.965332 getuid32()        = 0
> 154   00:01:14.965963 open("/tmp/tmp.kJfCJh", O_RDONLY|O_LARGEFILE) = 3
> 154   00:01:14.966693 sendfile64(1, 3, NULL, 16777216) = 0
> 154   00:01:14.967225 close(3)          = 0
> 154   00:01:14.967771 exit_group(0)     = ?
> 154   00:01:14.968431 +++ exited with 0 +++
> 149   00:01:14.968637 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 154
> 149   00:01:14.969062 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=154, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
> 149   00:01:14.969524 sigreturn()       = 154
> 149   00:01:14.970021 wait4(-1, 0x7b8b89e8, WNOHANG, NULL) = -1 ECHILD (No child process)
> 149   00:01:14.970630 dup2(11, 1)       = 1
> 149   00:01:14.971135 close(11)         = 0
> 149   00:01:14.971803 statx(AT_FDCWD, "/sbin/rm", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b88c0) = -1 ENOENT (No such file or directory)
> 149   00:01:14.972693 statx(AT_FDCWD, "/usr/sbin/rm", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b88c0) = -1 ENOENT (No such file or directory)
> 149   00:01:14.973506 statx(AT_FDCWD, "/bin/rm", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|S_ISUID|0755, stx_size=719260, ...}) = 0
> 149   00:01:14.974668 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
> 149   00:01:14.975332 rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
> 149   00:01:14.975936 fork()            = 155
> 149   00:01:14.976585 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 149   00:01:14.977166 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> 149   00:01:14.977733 wait4(-1,  <unfinished ...>
> 155   00:01:14.978296 gettid()          = 155
> 155   00:01:14.978860 rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1 RT_2], NULL, 8) = 0
> 155   00:01:14.979466 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> 155   00:01:14.980076 close(10)         = 0
> 155   00:01:14.980557 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x295b6a2a}, NULL, 8) = 0
> 155   00:01:14.981350 execve("/bin/rm", ["rm", "-f", "/tmp/tmp.kJfCJh"], 0x295eda04 /* 12 vars */) = 0
> 155   00:01:14.983082 set_tid_address(0x295faf94) = 155
> 155   00:01:14.983662 brk(NULL)         = 0x4c0000
> 155   00:01:14.984120 brk(0x4c2000)     = 0x4c2000
> 155   00:01:14.984536 mmap2(0x4c0000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4c0000
> 155   00:01:14.985336 mprotect(0x295f8000, 4096, PROT_READ) = 0
> 155   00:01:14.986187 mprotect(0x4be000, 4096, PROT_READ) = 0
> 155   00:01:14.986851 getuid32()        = 0
> 155   00:01:14.987464 statx(AT_FDCWD, "/tmp/tmp.kJfCJh", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0600, stx_size=0, ...}) = 0
> 155   00:01:14.988583 unlink("/tmp/tmp.kJfCJh") = 0
> 155   00:01:14.989318 exit_group(0)     = ?
> 155   00:01:14.989984 +++ exited with 0 +++
> 149   00:01:14.990176 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 155
> 149   00:01:14.990593 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=155, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
> 149   00:01:14.991041 sigreturn()       = 155
> 149   00:01:14.991439 wait4(-1, 0x7b8b8a14, WNOHANG, NULL) = -1 ECHILD (No child process)
> 149   00:01:14.992291 statx(AT_FDCWD, "/usr/sbin/avahi-autoipd", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b87c0) = -1 ENOENT (No such file or directory)
> 149   00:01:14.993194 munmap(0x295ed000, 4096) = 0
> 149   00:01:14.993755 munmap(0x295ec000, 4096) = 0
> 149   00:01:14.994865 read(10, " continue\n    \"${hook}\" \"${@}\"\ndone\n\nexit 0\n", 1023) = 44
> 149   00:01:14.995743 mmap2(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295ec000
> 149   00:01:14.996482 open("/usr/share/udhcpc/default.script.d/", O_RDONLY|O_LARGEFILE|O_CLOEXEC|O_DIRECTORY) = 3
> 149   00:01:14.997188 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
> 149   00:01:14.997687 mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x295f0000
> 149   00:01:14.998402 getdents64(3, 0x295f0088 /* 2 entries */, 2048) = 48
> 149   00:01:14.999027 getdents64(3, 0x295f0088 /* 0 entries */, 2048) = 0
> 149   00:01:14.999576 close(3)          = 0
> 149   00:01:15.000076 munmap(0x295f0000, 8192) = 0
> 149   00:01:15.000603 munmap(0x295ec000, 16384) = 0
> 149   00:01:15.001370 statx(AT_FDCWD, "/usr/share/udhcpc/default.script.d/*", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b87d0) = -1 ENOENT (No such file or directory)
> 149   00:01:15.002240 statx(AT_FDCWD, "/usr/share/udhcpc/default.script.d/*", AT_STATX_SYNC_AS_STAT, STATX_BASIC_STATS, 0x7b8b87bc) = -1 ENOENT (No such file or directory)
> 149   00:01:15.003345 exit_group(0)     = ?
> 149   00:01:15.003998 +++ exited with 0 +++
> 148   00:01:15.004204 <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 149
> 148   00:01:15.004606 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=149, si_uid=0, si_status=0, si_utime=0, si_stime=2} ---
> 148   00:01:15.005134 socket(AF_PACKET, SOCK_DGRAM, htons(ETH_P_IP)) = 5
> 148   00:01:15.005673 bind(5, {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=0}, 20) = 0
> 148   00:01:15.006493 setsockopt(5, SOL_PACKET, PACKET_AUXDATA, [1], 4) = 0
> 148   00:01:15.007093 fcntl64(5, F_SETFD, FD_CLOEXEC) = 0
> 148   00:01:15.007594 socket(AF_INET, SOCK_RAW, IPPROTO_RAW) = 6
> 148   00:01:15.008067 ioctl(6, SIOCGIFINDEX, {ifr_name="eth0", }) = 0
> 148   00:01:15.008670 ioctl(6, SIOCGIFHWADDR, {ifr_name="eth0", ifr_hwaddr={sa_family=ARPHRD_ETHER, sa_data=52:54:00:12:34:56}}) = 0
> 148   00:01:15.009520 close(6)          = 0
> 148   00:01:15.010058 clock_gettime64(CLOCK_MONOTONIC, {tv_sec=75, tv_nsec=10264188}) = 0
> 148   00:01:15.010691 write(2, "udhcpc: sending discover\n", 25) = 25
> 148   00:01:15.011397 socket(AF_PACKET, SOCK_DGRAM, htons(ETH_P_IP)) = 6
> 148   00:01:15.011946 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, 0xff, 0xff, 0xff]}, 20) = 0
> 148   00:01:15.012830 sendto(6, "E\0\1H\0\0\0\0@\21y\246\0\0\0\0\377\377\377\377\0D\0C\0014!~\1\1\6\0\272\352\336g\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\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\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\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\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\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\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\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\0\0c\202Sc5\1\1=\7\1RT\0\0224V9\2\2@7\7\1\3\6\f\17\34*<\fudhcp 1.33.0\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 328, 0, {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, 0xff, 0xff, 0xff]}, 20

Ok, so we do not know how this process died ?

Something else is fishy, maybe with strace ?

Thanks.

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

[Guenter Roeck]

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