| Message ID | 20210402132602.3659282-1-eric.dumazet@gmail.com |
|---|---|
| State | New |
| Headers | show |
| Series | [net] virtio_net: Do not pull payload in skb->head | expand |
在 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; > } > }
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
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
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
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
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
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 ............
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 ............
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
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
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
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.
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
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.
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; } }