Re: [PATCH v2] net/failsafe: link_update request crashing at boot

Re: [PATCH v2] net/failsafe: link_update request crashing at boot

[Vipul Ashri]

[-- Attachment #1: Type: text/plain, Size: 9314 bytes --]

Hi Gaetan



Sorry for very late reply, we were busy working on 21.11 integration.

Although we have adopted this code internally for us but I am sharing the patch to opensource for community benefit.



This is specific case of AZURE setup with our very customized complex environment.

Let me share the logs with traceback first

SECONDARY PROCESS

timestamp=1633598184

TCZ0.0.0 Cycle 152 (Build 1832)

signal 11 (Segmentation fault), address is 0x31117bbce6c8 from 0x47d08b1



[bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv      (+   0xf4) - sp = 0x7fffef3fd110, ip = 0x3acdc54

[bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv               (+  0x159) - sp = 0x7fffef3fdc20, ip = 0x3acdf29

[bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+  0x104) - sp = 0x7fffef3fdf00, ip = 0x274d4c4

[bt]: ( 4) _L_unlock_18                                  (+   0x2c) - sp = 0x7fffef3fdf80, ip = 0x7ffff7bce630

[bt]: ( 5) rte_eth_dev_attach_secondary                  (+   0x21) - sp = 0x7fffef3fec50, ip = 0x47d08b1

[bt]: ( 6) rte_eth_from_ring                             (+ 0x3438) - sp = 0x7fffef3fec80, ip = 0x4e49da8

[bt]: ( 7) _init                                         (+ 0xa1b8) - sp = 0x7fffef3feec0, ip = 0x12e0368

[bt]: ( 8) local_dev_probe                               (+   0xac) - sp = 0x7fffef3feef0, ip = 0x478fd2c

[bt]: ( 9) rte_uuid_unparse                              (+  0x274) - sp = 0x7fffef3fef30, ip = 0x47a3e94

[bt]: (10) rte_eal_vfio_get_vf_token                     (+   0xd7) - sp = 0x7fffef3ff110, ip = 0x47b04b7

[bt]: (11) eal_hugepage_info_read                        (+  0x602) - sp = 0x7fffef3ff170, ip = 0x47b2cd2

[bt]: (12) start_thread                                  (+   0xc5) - sp = 0x7fffef3ff220, ip = 0x7ffff7bc6ea5

[bt]: (13) clone                                         (+   0x6d) - sp = 0x7fffef3ff2c0, ip = 0x7ffff004096d

EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request

EAL: Cannot send request to primary

EAL: Failed to send hotplug request to primary

net_failsafe: Failed to probe devargs net_tap_vsc0

EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request

EAL: Cannot send request to primary

EAL: Failed to send hotplug request to primary

net_failsafe: Failed to probe devargs net_tap_vsc1

EAL: No legacy callbacks, legacy socket not created

EAL: Drop mp reply: eal_dev_mp_request



PRIMARY PROCESS

timestamp=1633598196

TCZ0.0.0 Cycle 152 (Build 1832)

signal 11 (Segmentation fault), address is 0x38 from 0x9d8fbe



[bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv      (+   0xf4) - sp = 0x7fffecf41150, ip = 0x100dd44

[bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv               (+  0x159) - sp = 0x7fffecf41c60, ip = 0x100e019

[bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+  0x104) - sp = 0x7fffecf41f40, ip = 0xff4894

[bt]: ( 4) _L_unlock_18                                  (+   0x2c) - sp = 0x7fffecf41fc0, ip = 0x7ffff61d9630

[bt]: ( 5) failsafe_eth_dev_close                        (+  0x65e) - sp = 0x7fffecf42c90, ip = 0x9d8fbe

[bt]: ( 6) rte_eth_link_get_nowait                       (+   0x6a) - sp = 0x7fffecf42cf0, ip = 0x62fa0a

[bt]: ( 7) _ZN11StatsThread9statsLoopEP10CustomObject      (+  0x33e) - sp = 0x7fffecf42d20, ip = 0xedea2e

[bt]: ( 8) _ZN11StatsThread9statsLoopEP10CustomObject      (+  0x8dc) - sp = 0x7fffecf42d90, ip = 0xedefcc

[bt]: ( 9) ThreadFunction                                (+   0xe6) - sp = 0x7fffecf42db0, ip = 0x7ffff6b477e6

[bt]: (10) start_thread                                  (+   0xc5) - sp = 0x7fffecf42de0, ip = 0x7ffff61d1ea5

[bt]: (11) clone                                         (+   0x6d) - sp = 0x7fffecf42e80, ip = 0x7ffff0a6b96d







DPDK 20.11.2

core mask is 00000000000000000000000000004000

DPDK Custom Process initialized with 2 ports

the min max TxQ is maxTxQueues 16

Using 1 RxQs for port 0 (# F-core=1)

Using 1 RxQs for port 3 (# F-core=1)

Core 14 (port=0, rxQ=0) kni_ring=(nil)

Core 14 (port=3, rxQ=0) kni_ring=(nil)

Core 14 txN = 0

Thread for core 14 using ring from usbc of 0x31117b29bb00

Ring size must be powers of 2, adjusting from 8196 to 16384

Thread for core 14 using ring from MEDIA of 0x31117b27b840

Encaps Memory Zone= 48044 sizeof encaps = 60

Trace Memory Zone= 272

Policy Memory Zone= 8196 sizeof policy = 240

link status for port 0 is 1

link status for port 3 is 1

PORT 0 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)

PORT 0 is polling for link-change, interrupts disabled

[DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists

[DPDK] net_failsafe: Failed to create flow on sub_device 1

add_flow(): create() fails for port 0; Reason: overlapping rules or Kernel too old for flower support

Error adding broadcast flow

PORT 3 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)

PORT 3 is polling for link-change, interrupts disabled

[DPDK] EAL: Failed to hotplug add device on primary

[DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists

[DPDK] net_failsafe: Failed to create flow on sub_device 1

add_flow(): create() fails for port 3; Reason: overlapping rules or Kernel too old for flower support

Error adding broadcast flow

Cmd Thread is available

Capture object initialized

init :Stats Thread is available

ifLinkUpdate: Sending OperStatus for port=0 stat=1

ifLinkUpdate: Port 0 Link Change - speed 40000 Mbps - full-duplex

[DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request

[DPDK] EAL: rte_mp_request_sync failed

[DPDK] EAL: Failed to send hotplug request to secondary

[DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request

[DPDK] EAL: rte_mp_request_sync failed

[DPDK] EAL: Failed to hotplug add device on primary

[DPDK] Invalid port_id=2

[DPDK] net_failsafe: Operation rte_eth_stats_get failed for sub_device 1 with error -19



There is some race at secondary process and primary got crashed because its data-structures and partially filled.

Let me know if you need GDB analysis, I can share with next reply if you are still unsatisfied. GDB analysis will be bigger.

Thanks!



Regards

Vipul



-----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



On Thu, Oct 21, 2021, at 23:42, vipul.ashri@oracle.com<mailto:vipul.ashri@oracle.com> wrote:

> From: Vipul Ashri <vipul.ashri@oracle.com<mailto:vipul.ashri@oracle.com>>

>

> failsafe crashed while sending early link_update request during boot

> time initialization.

> Based on debugging we found failsafe device was good but sub- devices

> were progressing towards initialization and SUBOPS macro where

> expanding macro gives [partial_dev]->dev_ops->link_update()

> execution of which triggered crash because dev_ops==0. similar crash

> seen at failsafe_eth_dev_close()

>

> Failsafe driver need a separate check for subdevices similar to

> "RTE_ETH_VALID_PORTID_OR_ERR_RET(port_id, -ENODEV);" which is called

> to almost every eth_dev function.

>

> Fixes: a46f8d5 ("net/failsafe: add fail-safe PMD")

> Cc: stable@dpdk.org<mailto:stable@dpdk.org>

> Signed-off-by: Vipul Ashri <vipul.ashri@oracle.com<mailto:vipul.ashri@oracle.com>>



Hello Vipul,



I'm sorry for the delay, I missed your fix on the mailing list.



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.



It is really surprising to me, because there aren't many ways for a sub-device to become DEV_ACTIVE.



The only two ways are



  * by executing 'fs_dev_configure()', which will first execute

    rte_eth_dev_configure() on the sub-device, and on error would

    stop *without* setting DEV_ACTIVE.

    rte_eth_dev_configure() will itself execute

    RTE_ETH_VALID_PORTID_OR_ERR_RET(port_id, -ENODEV), so it would

    return negative errno and fs_dev_configure() would abort.



  * by executing 'fs_dev_remove()' and the sub-device was 'DEV_STARTED'

    to begin with, then it is retrograded to DEV_ACTIVE once stopped.



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.



Could describe in more detail the execution?

In particular, setting the EAL log-level to debug with the option:

' --log-level pmd.net.failsafe:debug '

for example while using testpmd or your DPDK app.

It should show ethdev level accesses to the sub-devices, and error values.



Best regards,

--

Gaetan Rivet

[-- Attachment #2: Type: text/html, Size: 20571 bytes --]

Re: [PATCH v2] net/failsafe: link_update request crashing at boot

[Stephen Hemminger]

On Mon, 14 Feb 2022 13:09:19 +0000
Vipul Ashri <vipul.ashri@oracle.com> wrote:

> PORT 0 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
> 
> PORT 0 is polling for link-change, interrupts disabled
> 
> [DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists

Looks like secondary process support doesn't work with the flow rules logic.
Maybe after that you are into error paths that may not recover correctly??

Re: [PATCH v2] net/failsafe: link_update request crashing at boot

[Ferruh Yigit]

On 10/17/2023 5:43 PM, Stephen Hemminger wrote:
> On Tue, 15 Feb 2022 22:16:28 +0530
> Vipul Ashri <vipul.ashri@oracle.com> wrote:
> 
>> On 2/14/2022 10:24 PM, Stephen Hemminger wrote:
>>> On Mon, 14 Feb 2022 13:09:19 +0000
>>> Vipul Ashri <vipul.ashri@oracle.com> wrote:
>>>  
>>>> PORT 0 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
>>>>
>>>> PORT 0 is polling for link-change, interrupts disabled
>>>>
>>>> [DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists  
>>> Looks like secondary process support doesn't work with the flow rules logic.
>>> Maybe after that you are into error paths that may not recover correctly??  
>> Thanks! Stephen for looking at my analysis,
>>
>> yes some hotplug synchronization issue between eal_intr_thread and primary
>> thread, but we are able to recover with this patch.
>>
>> Reason is this fail-safe flow is inside our custom added boot-time 
>> polling to
>> update DPDK stats and calling ifindex ioctl to get interface data. 
>> Ideally we
>> should not start polling so early. but moreover calling ifindex ioctl is 
>> generic
>> functionality and should not break failsafe. We added this patch and 
>> gracefully
>> prevented the so many multiple crashes.
>>
>> Setup details :
>> Azure testbed with Accelerated Networking(SRIOV) enabled, failsafe using 
>> tap +
>> mellanox driver.
> 
> I don't work for Azure anymore, so can't really test this.
> A short explanation why this patch is stalled.
> 
> It seems like this patch is trying to avoid a crash when an earlier problem
> occurred, it is ok to do that but the original problem is still there
> and the testing it is impossible without having modified application.
> For the normal user, this just adds more always true checks in the
> configuration path. Ok, but it does add clutter.
> 
> Since failsafe should be deprecated fixing this seems less relevant
> as well.
>

As we are at the beginning of a new release, it is cleanup time.

This patch is originally from 2021, firstly sorry for not able to
conclude it timely.


@Vipul, is this patch still valid? Are you still using failsafe actively?


@Gaetan, what is the status of the failsafe driver? I am aware it was
kind of temporary solution, is it still required or actively used?
We are not getting much failsafe patches, but when we do it is sometimes
taking time to have the review, should we seek for more help there, what
do you think?


@Vipul, @Geatan, instead of dragging this old patch, would you be OK if
I update it as change requested, and you send a fresh version on top of
latest code if it is still valid?


Thanks,
ferruh

Re: [PATCH v2] net/failsafe: link_update request crashing at boot

[Stephen Hemminger]

On Tue, 15 Feb 2022 22:16:28 +0530
Vipul Ashri <vipul.ashri@oracle.com> wrote:

> On 2/14/2022 10:24 PM, Stephen Hemminger wrote:
> > On Mon, 14 Feb 2022 13:09:19 +0000
> > Vipul Ashri <vipul.ashri@oracle.com> wrote:
> >  
> >> PORT 0 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
> >>
> >> PORT 0 is polling for link-change, interrupts disabled
> >>
> >> [DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists  
> > Looks like secondary process support doesn't work with the flow rules logic.
> > Maybe after that you are into error paths that may not recover correctly??  
> Thanks! Stephen for looking at my analysis,
> 
> yes some hotplug synchronization issue between eal_intr_thread and primary
> thread, but we are able to recover with this patch.
> 
> Reason is this fail-safe flow is inside our custom added boot-time 
> polling to
> update DPDK stats and calling ifindex ioctl to get interface data. 
> Ideally we
> should not start polling so early. but moreover calling ifindex ioctl is 
> generic
> functionality and should not break failsafe. We added this patch and 
> gracefully
> prevented the so many multiple crashes.
> 
> Setup details :
> Azure testbed with Accelerated Networking(SRIOV) enabled, failsafe using 
> tap +
> mellanox driver.

I don't work for Azure anymore, so can't really test this.
A short explanation why this patch is stalled.

It seems like this patch is trying to avoid a crash when an earlier problem
occurred, it is ok to do that but the original problem is still there
and the testing it is impossible without having modified application.
For the normal user, this just adds more always true checks in the
configuration path. Ok, but it does add clutter.

Since failsafe should be deprecated fixing this seems less relevant
as well.

Re: [PATCH v2] net/failsafe: link_update request crashing at boot

[Ferruh Yigit]

On 2/15/2022 4:24 PM, Vipul Ashri wrote:
> On 11/22/2021 3:53 PM, Gaëtan Rivet wrote:
>> Could describe in more detail the execution?
>> In particular, setting the EAL log-level to debug with the option:
>> ' --log-level pmd.net.failsafe:debug '
>> for example while using testpmd or your DPDK app.
>> It should show ethdev level accesses to the sub-devices, and error values.
>>
>> Best regards,
> 
> Hi Gaetan
> 
> Sorry for very late reply, we were busy working on 21.11 integration.
> 
> Although we have adopted this code internally for us but I am sharing the patch to opensource for community benefit.
> 
> This is specific case of AZURE setup with our very customized complex environment.
> 
> Let me share the logs with trace-back first
> ==================================================================================================================
> SECONDARY PROCESS
> timestamp=1633598184
> TCZ0.0.0 Cycle 152 (Build 1832)
> signal 11 (Segmentation fault), address is 0x31117bbce6c8 from 0x47d08b1
> 
> [bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv      (+   0xf4) - sp = 0x7fffef3fd110, ip = 0x3acdc54
> [bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv               (+  0x159) - sp = 0x7fffef3fdc20, ip = 0x3acdf29
> [bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+  0x104) - sp = 0x7fffef3fdf00, ip = 0x274d4c4
> [bt]: ( 4) _L_unlock_18                                  (+   0x2c) - sp = 0x7fffef3fdf80, ip = 0x7ffff7bce630
> [bt]: ( 5) rte_eth_dev_attach_secondary                  (+   0x21) - sp = 0x7fffef3fec50, ip = 0x47d08b1
> [bt]: ( 6) rte_eth_from_ring                             (+ 0x3438) - sp = 0x7fffef3fec80, ip = 0x4e49da8
> [bt]: ( 7) _init                                         (+ 0xa1b8) - sp = 0x7fffef3feec0, ip = 0x12e0368
> [bt]: ( 8) local_dev_probe                               (+   0xac) - sp = 0x7fffef3feef0, ip = 0x478fd2c
> [bt]: ( 9) rte_uuid_unparse                              (+  0x274) - sp = 0x7fffef3fef30, ip = 0x47a3e94
> [bt]: (10) rte_eal_vfio_get_vf_token                     (+   0xd7) - sp = 0x7fffef3ff110, ip = 0x47b04b7
> [bt]: (11) eal_hugepage_info_read                        (+  0x602) - sp = 0x7fffef3ff170, ip = 0x47b2cd2
> [bt]: (12) start_thread                                  (+   0xc5) - sp = 0x7fffef3ff220, ip = 0x7ffff7bc6ea5
> [bt]: (13) clone                                         (+   0x6d) - sp = 0x7fffef3ff2c0, ip = 0x7ffff004096d
> EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request
> EAL: Cannot send request to primary
> EAL: Failed to send hotplug request to primary
> net_failsafe: Failed to probe devargs net_tap_vsc0
> EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request
> EAL: Cannot send request to primary
> EAL: Failed to send hotplug request to primary
> net_failsafe: Failed to probe devargs net_tap_vsc1
> EAL: No legacy callbacks, legacy socket not created
> EAL: Drop mp reply: eal_dev_mp_request
> ==================================================================================================================
> PRIMARY PROCESS
> timestamp=1633598196
> TCZ0.0.0 Cycle 152 (Build 1832)
> signal 11 (Segmentation fault), address is 0x38 from 0x9d8fbe
> 
> [bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv      (+   0xf4) - sp = 0x7fffecf41150, ip = 0x100dd44
> [bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv               (+  0x159) - sp = 0x7fffecf41c60, ip = 0x100e019
> [bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+  0x104) - sp = 0x7fffecf41f40, ip = 0xff4894
> [bt]: ( 4) _L_unlock_18                                  (+   0x2c) - sp = 0x7fffecf41fc0, ip = 0x7ffff61d9630
> [bt]: ( 5) failsafe_eth_dev_close                        (+  0x65e) - sp = 0x7fffecf42c90, ip = 0x9d8fbe
> [bt]: ( 6) rte_eth_link_get_nowait                       (+   0x6a) - sp = 0x7fffecf42cf0, ip = 0x62fa0a
> [bt]: ( 7) _ZN11StatsThread9statsLoopEP10CustomObject      (+  0x33e) - sp = 0x7fffecf42d20, ip = 0xedea2e
> [bt]: ( 8) _ZN11StatsThread9statsLoopEP10CustomObject      (+  0x8dc) - sp = 0x7fffecf42d90, ip = 0xedefcc
> [bt]: ( 9) ThreadFunction                                (+   0xe6) - sp = 0x7fffecf42db0, ip = 0x7ffff6b477e6
> [bt]: (10) start_thread                                  (+   0xc5) - sp = 0x7fffecf42de0, ip = 0x7ffff61d1ea5
> [bt]: (11) clone                                         (+   0x6d) - sp = 0x7fffecf42e80, ip = 0x7ffff0a6b96d
> 
> ==================================================================================================================
> DPDK 20.11.2
> core mask is 00000000000000000000000000004000
> DPDK Custom Process initialized with 2 ports
> the min max TxQ is maxTxQueues 16
> Using 1 RxQs for port 0 (# F-core=1)
> Using 1 RxQs for port 3 (# F-core=1)
> Core 14 (port=0, rxQ=0) kni_ring=(nil)
> Core 14 (port=3, rxQ=0) kni_ring=(nil)
> Core 14 txN = 0
> Thread for core 14 using ring from usbc of 0x31117b29bb00
> Ring size must be powers of 2, adjusting from 8196 to 16384
> Thread for core 14 using ring from MEDIA of 0x31117b27b840
> Encaps Memory Zone= 48044 sizeof encaps = 60
> Trace Memory Zone= 272
> Policy Memory Zone= 8196 sizeof policy = 240
> link status for port 0 is 1
> link status for port 3 is 1
> PORT 0 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
> PORT 0 is polling for link-change, interrupts disabled
> [DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists
> [DPDK] net_failsafe: Failed to create flow on sub_device 1
> add_flow(): create() fails for port 0; Reason: overlapping rules or Kernel too old for flower support
> Error adding broadcast flow
> PORT 3 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
> PORT 3 is polling for link-change, interrupts disabled
> [DPDK] EAL: Failed to hotplug add device on primary
> [DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists
> [DPDK] net_failsafe: Failed to create flow on sub_device 1
> add_flow(): create() fails for port 3; Reason: overlapping rules or Kernel too old for flower support
> Error adding broadcast flow
> Cmd Thread is available
> Capture object initialized
> init :Stats Thread is available
> ifLinkUpdate: Sending OperStatus for port=0 stat=1
> ifLinkUpdate: Port 0 Link Change - speed 40000 Mbps - full-duplex
> [DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request
> [DPDK] EAL: rte_mp_request_sync failed
> [DPDK] EAL: Failed to send hotplug request to secondary
> [DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request
> [DPDK] EAL: rte_mp_request_sync failed
> [DPDK] EAL: Failed to hotplug add device on primary
> [DPDK] Invalid port_id=2
> [DPDK] net_failsafe: Operation rte_eth_stats_get failed for sub_device 1 with error -19
> 
> There is some race at secondary process and primary got crashed because its data-structures and partially filled.
> Let me know if you need GDB analysis, I can share with next reply if you are still unsatisfied. GDB analysis will be bigger.
> Thanks!
> 
> 

Hi Gaëtan,

This is a very old patch, I don't know if it is still valid or if Vipul
still pursues the issue, but do you need more data or do you have
comment on how to proceed?

Re: [PATCH v2] net/failsafe: link_update request crashing at boot

[Vipul Ashri]

On 2/14/2022 10:24 PM, Stephen Hemminger wrote:
> On Mon, 14 Feb 2022 13:09:19 +0000
> Vipul Ashri <vipul.ashri@oracle.com> wrote:
>
>> PORT 0 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
>>
>> PORT 0 is polling for link-change, interrupts disabled
>>
>> [DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists
> Looks like secondary process support doesn't work with the flow rules logic.
> Maybe after that you are into error paths that may not recover correctly??
Thanks! Stephen for looking at my analysis,

yes some hotplug synchronization issue between eal_intr_thread and primary
thread, but we are able to recover with this patch.

Reason is this fail-safe flow is inside our custom added boot-time 
polling to
update DPDK stats and calling ifindex ioctl to get interface data. 
Ideally we
should not start polling so early. but moreover calling ifindex ioctl is 
generic
functionality and should not break failsafe. We added this patch and 
gracefully
prevented the so many multiple crashes.

Setup details :
Azure testbed with Accelerated Networking(SRIOV) enabled, failsafe using 
tap +
mellanox driver.

Warm Regards

Re: [PATCH v2] net/failsafe: link_update request crashing at boot

[Vipul Ashri]

[-- Attachment #1: Type: text/plain, Size: 7496 bytes --]

On 11/22/2021 3:53 PM, Gaëtan Rivet wrote:
> Could describe in more detail the execution?
> In particular, setting the EAL log-level to debug with the option:
> ' --log-level pmd.net.failsafe:debug'
> for example while using testpmd or your DPDK app.
> It should show ethdev level accesses to the sub-devices, and error values.
>
> Best regards,

Hi Gaetan

Sorry for very late reply, we were busy working on 21.11 integration.

Although we have adopted this code internally for us but I am sharing the patch to opensource for community benefit.

This is specific case of AZURE setup with our very customized complex environment.

Let me share the logs with trace-back first
==================================================================================================================
SECONDARY PROCESS
timestamp=1633598184
TCZ0.0.0 Cycle 152 (Build 1832)
signal 11 (Segmentation fault), address is 0x31117bbce6c8 from 0x47d08b1

[bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv      (+   0xf4) - sp = 0x7fffef3fd110, ip = 0x3acdc54
[bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv               (+  0x159) - sp = 0x7fffef3fdc20, ip = 0x3acdf29
[bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+  0x104) - sp = 0x7fffef3fdf00, ip = 0x274d4c4
[bt]: ( 4) _L_unlock_18                                  (+   0x2c) - sp = 0x7fffef3fdf80, ip = 0x7ffff7bce630
[bt]: ( 5) rte_eth_dev_attach_secondary                  (+   0x21) - sp = 0x7fffef3fec50, ip = 0x47d08b1
[bt]: ( 6) rte_eth_from_ring                             (+ 0x3438) - sp = 0x7fffef3fec80, ip = 0x4e49da8
[bt]: ( 7) _init                                         (+ 0xa1b8) - sp = 0x7fffef3feec0, ip = 0x12e0368
[bt]: ( 8) local_dev_probe                               (+   0xac) - sp = 0x7fffef3feef0, ip = 0x478fd2c
[bt]: ( 9) rte_uuid_unparse                              (+  0x274) - sp = 0x7fffef3fef30, ip = 0x47a3e94
[bt]: (10) rte_eal_vfio_get_vf_token                     (+   0xd7) - sp = 0x7fffef3ff110, ip = 0x47b04b7
[bt]: (11) eal_hugepage_info_read                        (+  0x602) - sp = 0x7fffef3ff170, ip = 0x47b2cd2
[bt]: (12) start_thread                                  (+   0xc5) - sp = 0x7fffef3ff220, ip = 0x7ffff7bc6ea5
[bt]: (13) clone                                         (+   0x6d) - sp = 0x7fffef3ff2c0, ip = 0x7ffff004096d
EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request
EAL: Cannot send request to primary
EAL: Failed to send hotplug request to primary
net_failsafe: Failed to probe devargs net_tap_vsc0
EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request
EAL: Cannot send request to primary
EAL: Failed to send hotplug request to primary
net_failsafe: Failed to probe devargs net_tap_vsc1
EAL: No legacy callbacks, legacy socket not created
EAL: Drop mp reply: eal_dev_mp_request
==================================================================================================================
PRIMARY PROCESS
timestamp=1633598196
TCZ0.0.0 Cycle 152 (Build 1832)
signal 11 (Segmentation fault), address is 0x38 from 0x9d8fbe

[bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv      (+   0xf4) - sp = 0x7fffecf41150, ip = 0x100dd44
[bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv               (+  0x159) - sp = 0x7fffecf41c60, ip = 0x100e019
[bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+  0x104) - sp = 0x7fffecf41f40, ip = 0xff4894
[bt]: ( 4) _L_unlock_18                                  (+   0x2c) - sp = 0x7fffecf41fc0, ip = 0x7ffff61d9630
[bt]: ( 5) failsafe_eth_dev_close                        (+  0x65e) - sp = 0x7fffecf42c90, ip = 0x9d8fbe
[bt]: ( 6) rte_eth_link_get_nowait                       (+   0x6a) - sp = 0x7fffecf42cf0, ip = 0x62fa0a
[bt]: ( 7) _ZN11StatsThread9statsLoopEP10CustomObject      (+  0x33e) - sp = 0x7fffecf42d20, ip = 0xedea2e
[bt]: ( 8) _ZN11StatsThread9statsLoopEP10CustomObject      (+  0x8dc) - sp = 0x7fffecf42d90, ip = 0xedefcc
[bt]: ( 9) ThreadFunction                                (+   0xe6) - sp = 0x7fffecf42db0, ip = 0x7ffff6b477e6
[bt]: (10) start_thread                                  (+   0xc5) - sp = 0x7fffecf42de0, ip = 0x7ffff61d1ea5
[bt]: (11) clone                                         (+   0x6d) - sp = 0x7fffecf42e80, ip = 0x7ffff0a6b96d

==================================================================================================================
DPDK 20.11.2
core mask is 00000000000000000000000000004000
DPDK Custom Process initialized with 2 ports
the min max TxQ is maxTxQueues 16
Using 1 RxQs for port 0 (# F-core=1)
Using 1 RxQs for port 3 (# F-core=1)
Core 14 (port=0, rxQ=0) kni_ring=(nil)
Core 14 (port=3, rxQ=0) kni_ring=(nil)
Core 14 txN = 0
Thread for core 14 using ring from usbc of 0x31117b29bb00
Ring size must be powers of 2, adjusting from 8196 to 16384
Thread for core 14 using ring from MEDIA of 0x31117b27b840
Encaps Memory Zone= 48044 sizeof encaps = 60
Trace Memory Zone= 272
Policy Memory Zone= 8196 sizeof policy = 240
link status for port 0 is 1
link status for port 3 is 1
PORT 0 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
PORT 0 is polling for link-change, interrupts disabled
[DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists
[DPDK] net_failsafe: Failed to create flow on sub_device 1
add_flow(): create() fails for port 0; Reason: overlapping rules or Kernel too old for flower support
Error adding broadcast flow
PORT 3 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
PORT 3 is polling for link-change, interrupts disabled
[DPDK] EAL: Failed to hotplug add device on primary
[DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists
[DPDK] net_failsafe: Failed to create flow on sub_device 1
add_flow(): create() fails for port 3; Reason: overlapping rules or Kernel too old for flower support
Error adding broadcast flow
Cmd Thread is available
Capture object initialized
init :Stats Thread is available
ifLinkUpdate: Sending OperStatus for port=0 stat=1
ifLinkUpdate: Port 0 Link Change - speed 40000 Mbps - full-duplex
[DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request
[DPDK] EAL: rte_mp_request_sync failed
[DPDK] EAL: Failed to send hotplug request to secondary
[DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request
[DPDK] EAL: rte_mp_request_sync failed
[DPDK] EAL: Failed to hotplug add device on primary
[DPDK] Invalid port_id=2
[DPDK] net_failsafe: Operation rte_eth_stats_get failed for sub_device 1 with error -19

There is some race at secondary process and primary got crashed because its data-structures and partially filled.
Let me know if you need GDB analysis, I can share with next reply if you are still unsatisfied. GDB analysis will be bigger.
Thanks!

Regards

[-- Attachment #2: Type: text/html, Size: 10093 bytes --]

Re: [PATCH v2] net/failsafe: link_update request crashing at boot

[vipul.ashri]

From: Gaëtan Rivet <grive@u256.net>

>On Thu, Oct 21, 2021, at 23:42, vipul.ashri@oracle.com wrote:
>> From: Vipul Ashri <vipul.ashri@oracle.com>
>>
>> failsafe crashed while sending early link_update request during
>> boot time initialization.
>> Based on debugging we found failsafe device was good but sub-
>> devices were progressing towards initialization and SUBOPS macro
>> where expanding macro gives [partial_dev]->dev_ops->link_update()
>> execution of which triggered crash because dev_ops==0. similar
>> crash seen at failsafe_eth_dev_close()
>>
>> Failsafe driver need a separate check for subdevices similar to
>> "RTE_ETH_VALID_PORTID_OR_ERR_RET(port_id, -ENODEV);" which is
>> called to almost every eth_dev function.
>>
>> Fixes: a46f8d5 ("net/failsafe: add fail-safe PMD")
>> Cc: stable@dpdk.org
>> Signed-off-by: Vipul Ashri <vipul.ashri@oracle.com>
>
>Hello Vipul,
>
>I'm sorry for the delay, I missed your fix on the mailing list.
>
>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.
>
>It is really surprising to me, because there aren't many ways for a sub-device
>to become DEV_ACTIVE.
>
>The only two ways are
>
>  * by executing 'fs_dev_configure()', which will first execute
>    rte_eth_dev_configure() on the sub-device, and on error would
>    stop *without* setting DEV_ACTIVE.
>    rte_eth_dev_configure() will itself execute
>    RTE_ETH_VALID_PORTID_OR_ERR_RET(port_id, -ENODEV), so it would
>    return negative errno and fs_dev_configure() would abort.
>
>  * by executing 'fs_dev_remove()' and the sub-device was 'DEV_STARTED'
>    to begin with, then it is retrograded to DEV_ACTIVE once stopped.
>
>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.
>
>Could describe in more detail the execution?
>In particular, setting the EAL log-level to debug with the option:
>' --log-level pmd.net.failsafe:debug '
>for example while using testpmd or your DPDK app.
>It should show ethdev level accesses to the sub-devices, and error values.
>
>Best regards,
>-- 
>Gaetan Rivet

Hi Gaetan

Sorry for very late reply, we were busy working on 21.11 integration.
Although we have adopted this code internally for us but I am sharing the patch to opensource for community benefit.

This is specific case of AZURE setup with our very customized complex environment.

Let me share the logs with traceback first
==================================================================================================================
SECONDARY PROCESS
timestamp=1633598184
TCZ0.0.0 Cycle 152 (Build 1832)
signal 11 (Segmentation fault), address is 0x31117bbce6c8 from 0x47d08b1

[bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv      (+   0xf4) - sp = 0x7fffef3fd110, ip = 0x3acdc54
[bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv               (+  0x159) - sp = 0x7fffef3fdc20, ip = 0x3acdf29
[bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+  0x104) - sp = 0x7fffef3fdf00, ip = 0x274d4c4
[bt]: ( 4) _L_unlock_18                                  (+   0x2c) - sp = 0x7fffef3fdf80, ip = 0x7ffff7bce630
[bt]: ( 5) rte_eth_dev_attach_secondary                  (+   0x21) - sp = 0x7fffef3fec50, ip = 0x47d08b1
[bt]: ( 6) rte_eth_from_ring                             (+ 0x3438) - sp = 0x7fffef3fec80, ip = 0x4e49da8
[bt]: ( 7) _init                                         (+ 0xa1b8) - sp = 0x7fffef3feec0, ip = 0x12e0368
[bt]: ( 8) local_dev_probe                               (+   0xac) - sp = 0x7fffef3feef0, ip = 0x478fd2c
[bt]: ( 9) rte_uuid_unparse                              (+  0x274) - sp = 0x7fffef3fef30, ip = 0x47a3e94
[bt]: (10) rte_eal_vfio_get_vf_token                     (+   0xd7) - sp = 0x7fffef3ff110, ip = 0x47b04b7
[bt]: (11) eal_hugepage_info_read                        (+  0x602) - sp = 0x7fffef3ff170, ip = 0x47b2cd2
[bt]: (12) start_thread                                  (+   0xc5) - sp = 0x7fffef3ff220, ip = 0x7ffff7bc6ea5
[bt]: (13) clone                                         (+   0x6d) - sp = 0x7fffef3ff2c0, ip = 0x7ffff004096d
EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request
EAL: Cannot send request to primary
EAL: Failed to send hotplug request to primary
net_failsafe: Failed to probe devargs net_tap_vsc0
EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request
EAL: Cannot send request to primary
EAL: Failed to send hotplug request to primary
net_failsafe: Failed to probe devargs net_tap_vsc1
EAL: No legacy callbacks, legacy socket not created
EAL: Drop mp reply: eal_dev_mp_request
==================================================================================================================
PRIMARY PROCESS
timestamp=1633598196
TCZ0.0.0 Cycle 152 (Build 1832)
signal 11 (Segmentation fault), address is 0x38 from 0x9d8fbe

[bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv      (+   0xf4) - sp = 0x7fffecf41150, ip = 0x100dd44
[bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv               (+  0x159) - sp = 0x7fffecf41c60, ip = 0x100e019
[bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+  0x104) - sp = 0x7fffecf41f40, ip = 0xff4894
[bt]: ( 4) _L_unlock_18                                  (+   0x2c) - sp = 0x7fffecf41fc0, ip = 0x7ffff61d9630
[bt]: ( 5) failsafe_eth_dev_close                        (+  0x65e) - sp = 0x7fffecf42c90, ip = 0x9d8fbe
[bt]: ( 6) rte_eth_link_get_nowait                       (+   0x6a) - sp = 0x7fffecf42cf0, ip = 0x62fa0a
[bt]: ( 7) _ZN11StatsThread9statsLoopEP10CustomObject      (+  0x33e) - sp = 0x7fffecf42d20, ip = 0xedea2e
[bt]: ( 8) _ZN11StatsThread9statsLoopEP10CustomObject      (+  0x8dc) - sp = 0x7fffecf42d90, ip = 0xedefcc
[bt]: ( 9) ThreadFunction                                (+   0xe6) - sp = 0x7fffecf42db0, ip = 0x7ffff6b477e6
[bt]: (10) start_thread                                  (+   0xc5) - sp = 0x7fffecf42de0, ip = 0x7ffff61d1ea5
[bt]: (11) clone                                         (+   0x6d) - sp = 0x7fffecf42e80, ip = 0x7ffff0a6b96d

==================================================================================================================
DPDK 20.11.2
core mask is 00000000000000000000000000004000
DPDK Custom Process initialized with 2 ports
the min max TxQ is maxTxQueues 16
Using 1 RxQs for port 0 (# F-core=1)
Using 1 RxQs for port 3 (# F-core=1)
Core 14 (port=0, rxQ=0) kni_ring=(nil)
Core 14 (port=3, rxQ=0) kni_ring=(nil)
Core 14 txN = 0
Thread for core 14 using ring from usbc of 0x31117b29bb00
Ring size must be powers of 2, adjusting from 8196 to 16384
Thread for core 14 using ring from MEDIA of 0x31117b27b840
Encaps Memory Zone= 48044 sizeof encaps = 60
Trace Memory Zone= 272
Policy Memory Zone= 8196 sizeof policy = 240
link status for port 0 is 1
link status for port 3 is 1
PORT 0 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
PORT 0 is polling for link-change, interrupts disabled
[DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists
[DPDK] net_failsafe: Failed to create flow on sub_device 1
add_flow(): create() fails for port 0; Reason: overlapping rules or Kernel too old for flower support
Error adding broadcast flow
PORT 3 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
PORT 3 is polling for link-change, interrupts disabled
[DPDK] EAL: Failed to hotplug add device on primary
[DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists
[DPDK] net_failsafe: Failed to create flow on sub_device 1
add_flow(): create() fails for port 3; Reason: overlapping rules or Kernel too old for flower support
Error adding broadcast flow
Cmd Thread is available
Capture object initialized
init :Stats Thread is available
ifLinkUpdate: Sending OperStatus for port=0 stat=1
ifLinkUpdate: Port 0 Link Change - speed 40000 Mbps - full-duplex
[DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request
[DPDK] EAL: rte_mp_request_sync failed
[DPDK] EAL: Failed to send hotplug request to secondary
[DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request
[DPDK] EAL: rte_mp_request_sync failed
[DPDK] EAL: Failed to hotplug add device on primary
[DPDK] Invalid port_id=2
[DPDK] net_failsafe: Operation rte_eth_stats_get failed for sub_device 1 with error -19

There is some race at secondary process and primary got crashed because its data-structures and partially filled.
Let me know if you need GDB analysis, I can share with next reply if you are still unsatisfied. GDB analysis will be bigger.
Thanks!

Regards

Re: [PATCH v2] net/failsafe: link_update request crashing at boot

[vipul.ashri]

From: Gaëtan Rivet <grive@u256.net>

>On Thu, Oct 21, 2021, at 23:42, vipul.ashri@oracle.com wrote:
>> From: Vipul Ashri <vipul.ashri@oracle.com>
>>
>> failsafe crashed while sending early link_update request during
>> boot time initialization.
>> Based on debugging we found failsafe device was good but sub-
>> devices were progressing towards initialization and SUBOPS macro
>> where expanding macro gives [partial_dev]->dev_ops->link_update()
>> execution of which triggered crash because dev_ops==0. similar
>> crash seen at failsafe_eth_dev_close()
>>
>> Failsafe driver need a separate check for subdevices similar to
>> "RTE_ETH_VALID_PORTID_OR_ERR_RET(port_id, -ENODEV);" which is
>> called to almost every eth_dev function.
>>
>> Fixes: a46f8d5 ("net/failsafe: add fail-safe PMD")
>> Cc: stable@dpdk.org
>> Signed-off-by: Vipul Ashri <vipul.ashri@oracle.com>
>
>Hello Vipul,
>
>I'm sorry for the delay, I missed your fix on the mailing list.
>
>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.
>
>It is really surprising to me, because there aren't many ways for a sub-device
>to become DEV_ACTIVE.
>
>The only two ways are
>
>  * by executing 'fs_dev_configure()', which will first execute
>    rte_eth_dev_configure() on the sub-device, and on error would
>    stop *without* setting DEV_ACTIVE.
>    rte_eth_dev_configure() will itself execute
>    RTE_ETH_VALID_PORTID_OR_ERR_RET(port_id, -ENODEV), so it would
>    return negative errno and fs_dev_configure() would abort.
>
>  * by executing 'fs_dev_remove()' and the sub-device was 'DEV_STARTED'
>    to begin with, then it is retrograded to DEV_ACTIVE once stopped.
>
>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.
>
>Could describe in more detail the execution?
>In particular, setting the EAL log-level to debug with the option:
>' --log-level pmd.net.failsafe:debug '
>for example while using testpmd or your DPDK app.
>It should show ethdev level accesses to the sub-devices, and error values.
>
>Best regards,
>-- 
>Gaetan Rivet

Hi Gaetan

Sorry for very late reply, we were busy working on 21.11 integration.
Although we have adopted this code internally for us but I am sharing the patch to opensource for community benefit.

This is specific case of AZURE setup with our very customized complex environment.

Let me share the logs with traceback first
==================================================================================================================
SECONDARY PROCESS
timestamp=1633598184
TCZ0.0.0 Cycle 152 (Build 1832)
signal 11 (Segmentation fault), address is 0x31117bbce6c8 from 0x47d08b1

[bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv      (+   0xf4) - sp = 0x7fffef3fd110, ip = 0x3acdc54
[bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv               (+  0x159) - sp = 0x7fffef3fdc20, ip = 0x3acdf29
[bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+  0x104) - sp = 0x7fffef3fdf00, ip = 0x274d4c4
[bt]: ( 4) _L_unlock_18                                  (+   0x2c) - sp = 0x7fffef3fdf80, ip = 0x7ffff7bce630
[bt]: ( 5) rte_eth_dev_attach_secondary                  (+   0x21) - sp = 0x7fffef3fec50, ip = 0x47d08b1
[bt]: ( 6) rte_eth_from_ring                             (+ 0x3438) - sp = 0x7fffef3fec80, ip = 0x4e49da8
[bt]: ( 7) _init                                         (+ 0xa1b8) - sp = 0x7fffef3feec0, ip = 0x12e0368
[bt]: ( 8) local_dev_probe                               (+   0xac) - sp = 0x7fffef3feef0, ip = 0x478fd2c
[bt]: ( 9) rte_uuid_unparse                              (+  0x274) - sp = 0x7fffef3fef30, ip = 0x47a3e94
[bt]: (10) rte_eal_vfio_get_vf_token                     (+   0xd7) - sp = 0x7fffef3ff110, ip = 0x47b04b7
[bt]: (11) eal_hugepage_info_read                        (+  0x602) - sp = 0x7fffef3ff170, ip = 0x47b2cd2
[bt]: (12) start_thread                                  (+   0xc5) - sp = 0x7fffef3ff220, ip = 0x7ffff7bc6ea5
[bt]: (13) clone                                         (+   0x6d) - sp = 0x7fffef3ff2c0, ip = 0x7ffff004096d
EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request
EAL: Cannot send request to primary
EAL: Failed to send hotplug request to primary
net_failsafe: Failed to probe devargs net_tap_vsc0
EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket:eal_dev_mp_request
EAL: Cannot send request to primary
EAL: Failed to send hotplug request to primary
net_failsafe: Failed to probe devargs net_tap_vsc1
EAL: No legacy callbacks, legacy socket not created
EAL: Drop mp reply: eal_dev_mp_request
==================================================================================================================
PRIMARY PROCESS
timestamp=1633598196
TCZ0.0.0 Cycle 152 (Build 1832)
signal 11 (Segmentation fault), address is 0x38 from 0x9d8fbe

[bt]: ( 1) _Z18snprintf_backtraceRPciiP9siginfo_tPv      (+   0xf4) - sp = 0x7fffecf41150, ip = 0x100dd44
[bt]: ( 2) _Z13crit_err_hdlriP9siginfo_tPv               (+  0x159) - sp = 0x7fffecf41c60, ip = 0x100e019
[bt]: ( 3) _ZN13SignalAdapter12handleSignalEiP9siginfo_tPv (+  0x104) - sp = 0x7fffecf41f40, ip = 0xff4894
[bt]: ( 4) _L_unlock_18                                  (+   0x2c) - sp = 0x7fffecf41fc0, ip = 0x7ffff61d9630
[bt]: ( 5) failsafe_eth_dev_close                        (+  0x65e) - sp = 0x7fffecf42c90, ip = 0x9d8fbe
[bt]: ( 6) rte_eth_link_get_nowait                       (+   0x6a) - sp = 0x7fffecf42cf0, ip = 0x62fa0a
[bt]: ( 7) _ZN11StatsThread9statsLoopEP10CustomObject      (+  0x33e) - sp = 0x7fffecf42d20, ip = 0xedea2e
[bt]: ( 8) _ZN11StatsThread9statsLoopEP10CustomObject      (+  0x8dc) - sp = 0x7fffecf42d90, ip = 0xedefcc
[bt]: ( 9) ThreadFunction                                (+   0xe6) - sp = 0x7fffecf42db0, ip = 0x7ffff6b477e6
[bt]: (10) start_thread                                  (+   0xc5) - sp = 0x7fffecf42de0, ip = 0x7ffff61d1ea5
[bt]: (11) clone                                         (+   0x6d) - sp = 0x7fffecf42e80, ip = 0x7ffff0a6b96d

==================================================================================================================
DPDK 20.11.2
core mask is 00000000000000000000000000004000
DPDK Custom Process initialized with 2 ports
the min max TxQ is maxTxQueues 16
Using 1 RxQs for port 0 (# F-core=1)
Using 1 RxQs for port 3 (# F-core=1)
Core 14 (port=0, rxQ=0) kni_ring=(nil)
Core 14 (port=3, rxQ=0) kni_ring=(nil)
Core 14 txN = 0
Thread for core 14 using ring from usbc of 0x31117b29bb00
Ring size must be powers of 2, adjusting from 8196 to 16384
Thread for core 14 using ring from MEDIA of 0x31117b27b840
Encaps Memory Zone= 48044 sizeof encaps = 60
Trace Memory Zone= 272
Policy Memory Zone= 8196 sizeof policy = 240
link status for port 0 is 1
link status for port 3 is 1
PORT 0 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
PORT 0 is polling for link-change, interrupts disabled
[DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists
[DPDK] net_failsafe: Failed to create flow on sub_device 1
add_flow(): create() fails for port 0; Reason: overlapping rules or Kernel too old for flower support
Error adding broadcast flow
PORT 3 supports 16 rx queues and 16 tx queues (driver_name = net_failsafe, driver_type = 16)
PORT 3 is polling for link-change, interrupts disabled
[DPDK] EAL: Failed to hotplug add device on primary
[DPDK] tap_flow_create(): Kernel refused TC filter rule creation (17): File exists
[DPDK] net_failsafe: Failed to create flow on sub_device 1
add_flow(): create() fails for port 3; Reason: overlapping rules or Kernel too old for flower support
Error adding broadcast flow
Cmd Thread is available
Capture object initialized
init :Stats Thread is available
ifLinkUpdate: Sending OperStatus for port=0 stat=1
ifLinkUpdate: Port 0 Link Change - speed 40000 Mbps - full-duplex
[DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request
[DPDK] EAL: rte_mp_request_sync failed
[DPDK] EAL: Failed to send hotplug request to secondary
[DPDK] EAL: Fail to recv reply for request /var/run/dpdk/oracusbc/mp_socket_2934_298e9db8d1:eal_dev_mp_request
[DPDK] EAL: rte_mp_request_sync failed
[DPDK] EAL: Failed to hotplug add device on primary
[DPDK] Invalid port_id=2
[DPDK] net_failsafe: Operation rte_eth_stats_get failed for sub_device 1 with error -19

There is some race at secondary process and primary got crashed because its data-structures and partially filled.
Let me know if you need GDB analysis, I can share with next reply if you are still unsatisfied. GDB analysis will be bigger.
Thanks!

Regards

[PATCH v2] net/failsafe: link_update request crashing at boot

[vipul.ashri]

From: Vipul Ashri <vipul.ashri@oracle.com>

failsafe crashed while sending early link_update request during
boot time initialization.
Based on debugging we found failsafe device was good but sub-
devices were progressing towards initialization and SUBOPS macro
where expanding macro gives [partial_dev]->dev_ops->link_update()
execution of which triggered crash because dev_ops==0. similar
crash seen at failsafe_eth_dev_close()

Failsafe driver need a separate check for subdevices similar to
"RTE_ETH_VALID_PORTID_OR_ERR_RET(port_id, -ENODEV);" which is
called to almost every eth_dev function.

Fixes: a46f8d5 ("net/failsafe: add fail-safe PMD")
Cc: stable@dpdk.org
Signed-off-by: Vipul Ashri <vipul.ashri@oracle.com>
---
 drivers/net/failsafe/failsafe_ops.c     | 45 +++++++++++++++++++++++--
 drivers/net/failsafe/failsafe_private.h |  6 ++++
 2 files changed, 49 insertions(+), 2 deletions(-)

diff --git a/drivers/net/failsafe/failsafe_ops.c b/drivers/net/failsafe/failsafe_ops.c
index 29de39910c..8e128b9802 100644
--- a/drivers/net/failsafe/failsafe_ops.c
+++ b/drivers/net/failsafe/failsafe_ops.c
@@ -371,7 +371,8 @@ fs_rx_queue_release(struct rte_eth_dev *dev, uint16_t qid)
 		close(rxq->event_fd);
 	FOREACH_SUBDEV_STATE(sdev, i, dev, DEV_ACTIVE) {
 		if (ETH(sdev)->data->rx_queues != NULL &&
-		    ETH(sdev)->data->rx_queues[rxq->qid] != NULL)
+			ETH(sdev)->data->rx_queues[rxq->qid] != NULL &&
+			SUBDEV_VALID_PORTID(sdev))
 			SUBOPS(sdev, rx_queue_release)(ETH(sdev), rxq->qid);
 	}
 	dev->data->rx_queues[rxq->qid] = NULL;
@@ -405,6 +406,12 @@ fs_rx_queue_setup(struct rte_eth_dev *dev,
 	fs_lock(dev, 0);
 	if (rx_conf->rx_deferred_start) {
 		FOREACH_SUBDEV_STATE(sdev, i, dev, DEV_PROBED) {
+			if (!SUBDEV_VALID_PORTID(sdev)) {
+				ERROR("%s: Invalid sub-device port_id=%u\n",
+					__func__, PORT_ID(sdev));
+				fs_unlock(dev, 0);
+				return -ENODEV;
+			}
 			if (SUBOPS(sdev, rx_queue_start) == NULL) {
 				ERROR("Rx queue deferred start is not "
 					"supported for subdevice %d", i);
@@ -548,7 +555,8 @@ fs_tx_queue_release(struct rte_eth_dev *dev, uint16_t qid)
 	fs_lock(dev, 0);
 	FOREACH_SUBDEV_STATE(sdev, i, dev, DEV_ACTIVE) {
 		if (ETH(sdev)->data->tx_queues != NULL &&
-		    ETH(sdev)->data->tx_queues[txq->qid] != NULL)
+			ETH(sdev)->data->tx_queues[txq->qid] != NULL &&
+			SUBDEV_VALID_PORTID(sdev))
 			SUBOPS(sdev, tx_queue_release)(ETH(sdev), txq->qid);
 	}
 	dev->data->tx_queues[txq->qid] = NULL;
@@ -571,6 +579,12 @@ fs_tx_queue_setup(struct rte_eth_dev *dev,
 	fs_lock(dev, 0);
 	if (tx_conf->tx_deferred_start) {
 		FOREACH_SUBDEV_STATE(sdev, i, dev, DEV_PROBED) {
+			if (!SUBDEV_VALID_PORTID(sdev)) {
+				ERROR("%s: Invalid sub-device port_id=%u\n",
+					__func__, PORT_ID(sdev));
+				fs_unlock(dev, 0);
+				return -ENODEV;
+			}
 			if (SUBOPS(sdev, tx_queue_start) == NULL) {
 				ERROR("Tx queue deferred start is not "
 					"supported for subdevice %d", i);
@@ -645,6 +659,12 @@ failsafe_eth_dev_close(struct rte_eth_dev *dev)
 	fs_lock(dev, 0);
 	failsafe_hotplug_alarm_cancel(dev);
 	if (PRIV(dev)->state == DEV_STARTED) {
+		if (!rte_eth_dev_is_valid_port(dev->data->port_id)) {
+			ERROR("%s: Invalid sub-device port_id=%u\n",
+				__func__, dev->data->port_id);
+			fs_unlock(dev, 0);
+			return -ENODEV;
+		}
 		ret = dev->dev_ops->dev_stop(dev);
 		if (ret != 0) {
 			fs_unlock(dev, 0);
@@ -827,6 +847,12 @@ fs_link_update(struct rte_eth_dev *dev,
 
 	fs_lock(dev, 0);
 	FOREACH_SUBDEV_STATE(sdev, i, dev, DEV_ACTIVE) {
+		if (!SUBDEV_VALID_PORTID(sdev)) {
+			ERROR("%s: Invalid Sub-device port_id=%u\n",
+				__func__, PORT_ID(sdev));
+			fs_unlock(dev, 0);
+			return -ENODEV;
+		}
 		DEBUG("Calling link_update on sub_device %d", i);
 		ret = (SUBOPS(sdev, link_update))(ETH(sdev), wait_to_complete);
 		if (ret && ret != -1 && sdev->remove == 0 &&
@@ -1249,6 +1275,15 @@ fs_dev_supported_ptypes_get(struct rte_eth_dev *dev)
 		goto unlock;
 	}
 	edev = ETH(sdev);
+
+	if (!SUBDEV_VALID_PORTID(sdev)) {
+		ERROR("%s: Invalid TX_SUBDEV port_id=%u\n",
+			__func__, PORT_ID(sdev));
+		rte_errno = -ENODEV;
+		ret = NULL;
+		goto unlock;
+	}
+
 	/* ENOTSUP: counts as no supported ptypes */
 	if (SUBOPS(sdev, dev_supported_ptypes_get) == NULL) {
 		ret = NULL;
@@ -1324,6 +1359,12 @@ fs_flow_ctrl_get(struct rte_eth_dev *dev,
 		ret = 0;
 		goto unlock;
 	}
+	if (!SUBDEV_VALID_PORTID(sdev)) {
+		ERROR("%s: Invalid TX_SUBDEV port_id=%u\n",
+			__func__, PORT_ID(sdev));
+		ret = -ENODEV;
+		goto unlock;
+	}
 	if (SUBOPS(sdev, flow_ctrl_get) == NULL) {
 		ret = -ENOTSUP;
 		goto unlock;
diff --git a/drivers/net/failsafe/failsafe_private.h b/drivers/net/failsafe/failsafe_private.h
index cd39d103c6..0227060bcb 100644
--- a/drivers/net/failsafe/failsafe_private.h
+++ b/drivers/net/failsafe/failsafe_private.h
@@ -308,6 +308,12 @@ extern int failsafe_mac_from_arg;
 	 : (PRIV(dev)->subs[PRIV(dev)->subs_tx].state < DEV_PROBED ? NULL \
 	 : &PRIV(dev)->subs[PRIV(dev)->subs_tx]))
 
+/**
+ * check for fail-safe sub-device valid port
+ */
+#define SUBDEV_VALID_PORTID(s) \
+	rte_eth_dev_is_valid_port(PORT_ID(s))
+
 /**
  * s:   (struct sub_device *)
  * ops: (struct eth_dev_ops) member
-- 
2.35.1.windows.2

Re: [PATCH v2] net/failsafe: link_update request crashing at boot

[Gaëtan Rivet]

On Thu, Oct 21, 2021, at 23:42, vipul.ashri@oracle.com wrote:
> From: Vipul Ashri <vipul.ashri@oracle.com>
>
> failsafe crashed while sending early link_update request during
> boot time initialization.
> Based on debugging we found failsafe device was good but sub-
> devices were progressing towards initialization and SUBOPS macro
> where expanding macro gives [partial_dev]->dev_ops->link_update()
> execution of which triggered crash because dev_ops==0. similar
> crash seen at failsafe_eth_dev_close()
>
> Failsafe driver need a separate check for subdevices similar to
> "RTE_ETH_VALID_PORTID_OR_ERR_RET(port_id, -ENODEV);" which is
> called to almost every eth_dev function.
>
> Fixes: a46f8d5 ("net/failsafe: add fail-safe PMD")
> Cc: stable@dpdk.org
> Signed-off-by: Vipul Ashri <vipul.ashri@oracle.com>

Hello Vipul,

I'm sorry for the delay, I missed your fix on the mailing list.

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.

It is really surprising to me, because there aren't many ways for a sub-device
to become DEV_ACTIVE.

The only two ways are

  * by executing 'fs_dev_configure()', which will first execute
    rte_eth_dev_configure() on the sub-device, and on error would
    stop *without* setting DEV_ACTIVE.
    rte_eth_dev_configure() will itself execute
    RTE_ETH_VALID_PORTID_OR_ERR_RET(port_id, -ENODEV), so it would
    return negative errno and fs_dev_configure() would abort.

  * by executing 'fs_dev_remove()' and the sub-device was 'DEV_STARTED'
    to begin with, then it is retrograded to DEV_ACTIVE once stopped.

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.

Could describe in more detail the execution?
In particular, setting the EAL log-level to debug with the option:
' --log-level pmd.net.failsafe:debug '
for example while using testpmd or your DPDK app.
It should show ethdev level accesses to the sub-devices, and error values.

Best regards,
-- 
Gaetan Rivet