<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40"> <head> <meta http-equiv="Content-Type" content="text/html; charset=iso-8859-1"> <meta name="Generator" content="Microsoft Word 15 (filtered medium)"> <style></style> </head> <body lang="EN-US" link="#0563C1" vlink="#954F72" style="word-wrap:break-word"> <div class="WordSection1"> Hi Gaetan<o:p></o:p> <o:p> </o:p> Sorry for very late reply, we were busy working on 21.11 integration.<o:p></o:p> Although we have adopted this code internally for us but I am sharing the patch to opensource for community benefit.<o:p></o:p> <o:p> </o:p> This is specific case of AZURE setup with our very customized complex environment.<o:p></o:p> <o:p></o:p> Let me share the logs with traceback first<o:p></o:p> <table class="MsoTableGrid" border="1" cellspacing="0" cellpadding="0" style="border-collapse:collapse;border:none"> <tbody> <tr> <td width="875" valign="top" style="width:656.6pt;border:solid windowtext 1.0pt;padding:0in 5.4pt 0in 5.4pt"> SECONDARY PROCESS<o:p></o:p> timestamp=1633598184<o:p></o:p> TCZ0.0.0 Cycle 152 (Build 1832)<o:p></o:p> signal 11 (Segmentation fault), address is 0x31117bbce6c8 from 0x47d08b1<o:p></o:p> <o:p> </o:p> [bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv (+ 0xf4) - sp = 0x7fffef3fd110, ip = 0x3acdc54<o:p></o:p> [bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv (+ 0x159) - sp = 0x7fffef3fdc20, ip = 0x3acdf29<o:p></o:p> [bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+ 0x104) - sp = 0x7fffef3fdf00, ip = 0x274d4c4<o:p></o:p> [bt]: ( 4) _L_unlock_18 (+ 0x2c) - sp = 0x7fffef3fdf80, ip = 0x7ffff7bce630<o:p></o:p> [bt]: ( 5) rte_eth_dev_attach_secondary (+ 0x21) - sp = 0x7fffef3fec50, ip = 0x47d08b1<o:p></o:p> [bt]: ( 6) rte_eth_from_ring (+ 0x3438) - sp = 0x7fffef3fec80, ip = 0x4e49da8<o:p></o:p> [bt]: ( 7) _init (+ 0xa1b8) - sp = 0x7fffef3feec0, ip = 0x12e0368<o:p></o:p> [bt]: ( 8) local_dev_probe (+ 0xac) - sp = 0x7fffef3feef0, ip = 0x478fd2c<o:p></o:p> [bt]: ( 9) rte_uuid_unparse (+ 0x274) - sp = 0x7fffef3fef30, ip = 0x47a3e94<o:p></o:p> [bt]: (10) rte_eal_vfio_get_vf_token (+ 0xd7) - sp = 0x7fffef3ff110, ip = 0x47b04b7<o:p></o:p> [bt]: (11) eal_hugepage_info_read (+ 0x602) - sp = 0x7fffef3ff170, ip = 0x47b2cd2<o:p></o:p> [bt]: (12) start_thread (+ 0xc5) - sp = 0x7fffef3ff220, ip = 0x7ffff7bc6ea5<o:p></o:p> [bt]: (13) clone (+ 0x6d) - sp = 0x7fffef3ff2c0, ip = 0x7ffff004096d<o:p></o:p> EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request<o:p></o:p> EAL: Cannot send request to primary<o:p></o:p> EAL: Failed to send hotplug request to primary<o:p></o:p> net_failsafe: Failed to probe devargs net_tap_vsc0<o:p></o:p> EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request<o:p></o:p> EAL: Cannot send request to primary<o:p></o:p> EAL: Failed to send hotplug request to primary<o:p></o:p> net_failsafe: Failed to probe devargs net_tap_vsc1<o:p></o:p> EAL: No legacy callbacks, legacy socket not created<o:p></o:p> EAL: Drop mp reply: eal_dev_mp_request<o:p></o:p> <o:p> </o:p> PRIMARY PROCESS<o:p></o:p> timestamp=1633598196<o:p></o:p> TCZ0.0.0 Cycle 152 (Build 1832)<o:p></o:p> signal 11 (Segmentation fault), address is 0x38 from 0x9d8fbe<o:p></o:p> <o:p> </o:p> [bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv (+ 0xf4) - sp = 0x7fffecf41150, ip = 0x100dd44<o:p></o:p> [bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv (+ 0x159) - sp = 0x7fffecf41c60, ip = 0x100e019<o:p></o:p> [bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+ 0x104) - sp = 0x7fffecf41f40, ip = 0xff4894<o:p></o:p> [bt]: ( 4) _L_unlock_18 (+ 0x2c) - sp = 0x7fffecf41fc0, ip = 0x7ffff61d9630<o:p></o:p> [bt]: ( 5) failsafe_eth_dev_close (+ 0x65e) - sp = 0x7fffecf42c90, ip = 0x9d8fbe<o:p></o:p> [bt]: ( 6) rte_eth_link_get_nowait (+ 0x6a) - sp = 0x7fffecf42cf0, ip = 0x62fa0a<o:p></o:p> [bt]: ( 7) _ZN11StatsThread9statsLoopEP10CustomObject (+ 0x33e) - sp = 0x7fffecf42d20, ip = 0xedea2e<o:p></o:p> [bt]: ( 8) _ZN11StatsThread9statsLoopEP10CustomObject (+ 0x8dc) - sp = 0x7fffecf42d90, ip = 0xedefcc<o:p></o:p> [bt]: ( 9) ThreadFunction (+ 0xe6) - sp = 0x7fffecf42db0, ip = 0x7ffff6b477e6<o:p></o:p> [bt]: (10) start_thread (+ 0xc5) - sp = 0x7fffecf42de0, ip = 0x7ffff61d1ea5<o:p></o:p> [bt]: (11) clone (+ 0x6d) - sp = 0x7fffecf42e80, ip = 0x7ffff0a6b96d<o:p></o:p> <o:p> </o:p> <o:p> </o:p> <o:p> </o:p> DPDK 20.11.2<o:p></o:p> core mask is 00000000000000000000000000004000<o:p></o:p> DPDK Custom Process initialized with 2 ports<o:p></o:p> the min max TxQ is maxTxQueues 16<o:p></o:p> Using 1 RxQs for port 0 (# F-core=1)<o:p></o:p> Using 1 RxQs for port 3 (# F-core=1)<o:p></o:p> Core 14 (port=0, rxQ=0) kni_ring=(nil)<o:p></o:p> Core 14 (port=3, rxQ=0) kni_ring=(nil)<o:p></o:p> Core 14 txN = 0<o:p></o:p> Thread for core 14 using ring from usbc of 0x31117b29bb00<o:p></o:p> Ring size must be powers of 2, adjusting from 8196 to 16384<o:p></o:p> Thread for core 14 using ring from MEDIA of 0x31117b27b840<o:p></o:p> Encaps Memory Zone= 48044 sizeof encaps = 60<o:p></o:p> Trace Memory Zone= 272<o:p></o:p> Policy Memory Zone= 8196 sizeof policy = 240<o:p></o:p> link status for port 0 is 1<o:p></o:p> link status for port 3 is 1<o:p></o:p> PORT 0 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)<o:p></o:p> PORT 0 is polling for link-change, interrupts disabled<o:p></o:p> [DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists<o:p></o:p> [DPDK] net_failsafe: Failed to create flow on sub_device 1<o:p></o:p> add_flow(): create() fails for port 0; Reason: overlapping rules or Kernel too old for flower support<o:p></o:p> Error adding broadcast flow<o:p></o:p> PORT 3 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)<o:p></o:p> PORT 3 is polling for link-change, interrupts disabled<o:p></o:p> [DPDK] EAL: Failed to hotplug add device on primary<o:p></o:p> [DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists<o:p></o:p> [DPDK] net_failsafe: Failed to create flow on sub_device 1<o:p></o:p> add_flow(): create() fails for port 3; Reason: overlapping rules or Kernel too old for flower support<o:p></o:p> Error adding broadcast flow<o:p></o:p> Cmd Thread is available<o:p></o:p> Capture object initialized<o:p></o:p> init :Stats Thread is available<o:p></o:p> ifLinkUpdate: Sending OperStatus for port=0 stat=1<o:p></o:p> ifLinkUpdate: Port 0 Link Change - speed 40000 Mbps - full-duplex<o:p></o:p> [DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request<o:p></o:p> [DPDK] EAL: rte_mp_request_sync failed<o:p></o:p> [DPDK] EAL: Failed to send hotplug request to secondary<o:p></o:p> [DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request<o:p></o:p> [DPDK] EAL: rte_mp_request_sync failed<o:p></o:p> [DPDK] EAL: Failed to hotplug add device on primary<o:p></o:p> [DPDK] Invalid port_id=2<o:p></o:p> [DPDK] net_failsafe: Operation rte_eth_stats_get failed for sub_device 1 with error -19<o:p></o:p> </td> </tr> </tbody> </table> <o:p> </o:p> There is some race at secondary process and primary got crashed because its data-structures and partially filled.<o:p></o:p> Let me know if you need GDB analysis, I can share with next reply if you are still unsatisfied. GDB analysis will be bigger.<o:p></o:p> Thanks!<o:p></o:p> <o:p> </o:p> Regards<o:p></o:p> Vipul<o:p></o:p> <o:p> </o:p> -----Original Message----- From: Ga�tan Rivet <grive@u256.net> Sent: Monday, November 22, 2021 3:53 PM To: Vipul Ashri <vipul.ashri@oracle.com>; dev@dpdk.org Cc: stable@dpdk.org Subject: [External] : Re: [PATCH v2] net/failsafe: link_update request crashing at boot <o:p> </o:p> On Thu, Oct 21, 2021, at 23:42, <a href="mailto:vipul.ashri@oracle.com"> vipul.ashri@oracle.com</a> wrote:<o:p></o:p> > From: Vipul Ashri <<a href="mailto:vipul.ashri@oracle.com">vipul.ashri@oracle.com</a>><o:p></o:p> ><o:p> </o:p> > failsafe crashed while sending early link_update request during boot <o:p></o:p> > time initialization.<o:p></o:p> > Based on debugging we found failsafe device was good but sub- devices <o:p></o:p> > were progressing towards initialization and SUBOPS macro where <o:p></o:p> > expanding macro gives [partial_dev]->dev_ops->link_update()<o:p></o:p> > execution of which triggered crash because dev_ops==0. similar crash <o:p></o:p> > seen at failsafe_eth_dev_close()<o:p></o:p> ><o:p> </o:p> > Failsafe driver need a separate check for subdevices similar to <o:p></o:p> > "RTE_ETH_VALID_PORTID_OR_ERR_RET(port_id, -ENODEV);" which is called <o:p></o:p> > to almost every eth_dev function.<o:p></o:p> ><o:p> </o:p> > Fixes: a46f8d5 ("net/failsafe: add fail-safe PMD")<o:p></o:p> > Cc: <a href="mailto:stable@dpdk.org">stable@dpdk.org</a><o:p></o:p> > Signed-off-by: Vipul Ashri <<a href="mailto:vipul.ashri@oracle.com">vipul.ashri@oracle.com</a>><o:p></o:p> <o:p> </o:p> Hello Vipul,<o:p></o:p> <o:p> </o:p> I'm sorry for the delay, I missed your fix on the mailing list.<o:p></o:p> <o:p> </o:p> IIUC, the issue is that failsafe finished init and received an ethdev operation call, but one of its sub-device, although marked DEV_ACTIVE, has its eth_dev->dev_ops field NULL.<o:p></o:p> <o:p> </o:p> It is really surprising to me, because there aren't many ways for a sub-device to become DEV_ACTIVE.<o:p></o:p> <o:p> </o:p> The only two ways are<o:p></o:p> <o:p> </o:p> * by executing 'fs_dev_configure()', which will first execute<o:p></o:p> rte_eth_dev_configure() on the sub-device, and on error would<o:p></o:p> stop *without* setting DEV_ACTIVE.<o:p></o:p> rte_eth_dev_configure() will itself execute<o:p></o:p> RTE_ETH_VALID_PORTID_OR_ERR_RET(port_id, -ENODEV), so it would<o:p></o:p> return negative errno and fs_dev_configure() would abort.<o:p></o:p> <o:p> </o:p> * by executing 'fs_dev_remove()' and the sub-device was 'DEV_STARTED'<o:p></o:p> to begin with, then it is retrograded to DEV_ACTIVE once stopped.<o:p></o:p> <o:p> </o:p> So I don't understand yet how it is possible for a sub-device to become DEV_ACTIVE while its eth_dev->dev_ops are NULL. It seems more like a bug, memory corruption or just an unexpected execution pattern.<o:p></o:p> <o:p> </o:p> Could describe in more detail the execution?<o:p></o:p> In particular, setting the EAL log-level to debug with the option:<o:p></o:p> ' --log-level pmd.net.failsafe:debug '<o:p></o:p> for example while using testpmd or your DPDK app.<o:p></o:p> It should show ethdev level accesses to the sub-devices, and error values.<o:p></o:p> <o:p> </o:p> Best regards,<o:p></o:p> --<o:p></o:p> Gaetan Rivet<o:p></o:p> </div> </body> </html>