Re: [PATCH v4] can: mcp251xfd: fix infinite loop when xmit fails

[Vitor Soares <ivitro@gmail.com>]

Hi Marc,

On Mon, 2024-05-06 at 17:14 +0200, Marc Kleine-Budde wrote:
> On 06.05.2024 15:49:18, Vitor Soares wrote:
> > From: Vitor Soares <vitor.soares@toradex.com>
> > 
> > When the mcp251xfd_start_xmit() function fails, the driver stops
> > processing messages, and the interrupt routine does not return,
> > running indefinitely even after killing the running application.
> > 
> > Error messages:
> > [  441.298819] mcp251xfd spi2.0 can0: ERROR in mcp251xfd_start_xmit: -16
> > [  441.306498] mcp251xfd spi2.0 can0: Transmit Event FIFO buffer not empty.
> > (seq=0x000017c7, tef_tail=0x000017cf, tef_head=0x000017d0,
> > tx_head=0x000017d3).
> > ... and repeat forever.
> > 
> > The issue can be triggered when multiple devices share the same
> > SPI interface. And there is concurrent access to the bus.
> > 
> > The problem occurs because tx_ring->head increments even if
> > mcp251xfd_start_xmit() fails. Consequently, the driver skips one
> > TX package while still expecting a response in
> > mcp251xfd_handle_tefif_one().
> > 
> > This patch resolves the issue by decreasing tx_ring->head and removing
> > the skb from the echo stack if mcp251xfd_start_xmit() fails.
> > Consequently, the package is dropped not been possible to re-transmit.
> > 
> > Fixes: 55e5b97f003e ("can: mcp25xxfd: add driver for Microchip MCP25xxFD SPI
> > CAN")
> > Cc: stable@vger.kernel.org
> > Signed-off-by: Vitor Soares <vitor.soares@toradex.com>
> > ---
> > With this approach, some packages get lost in concurrent SPI bus access
> > due to can_put_echo_skb() being called before mcp251xfd_tx_obj_write().
> > The can_put_echo_skb() calls can_create_echo_skb() that consumes the
> > original skb
> > resulting in a Kernel NULL pointer dereference error if return
> > NETDEV_TX_BUSY on
> > mcp251xfd_tx_obj_write() failure.
> > A potential solution would be to change the code to use spi_sync(), which
> > would
> > wait for SPI bus to be unlocked. Any thoughts about this?
> 
> This is not an option. I think you need a echo_skb function that does
> the necessary cleanup, something like:
> 
> void can_remove_echo_skb(struct net_device *dev, unsigned int idx)
> {
>         struct can_priv *priv = netdev_priv(dev);
> 
>         priv->echo_skb[idx] = NULL;
> }
> 
> I think you can open-code the "priv->echo_skb[idx] = NULL;" directly in
> the driver.
> 
> And you have to take care of calling netdev_completed_queue(priv->ndev,
> 1, frame_len);

I have tried this approach and got the following trace:

------------[ cut here ]------------
refcount_t: underflow; use-after-free.
WARNING: CPU: 0 PID: 858 at lib/refcount.c:28 refcount_warn_saturate+0xf4/0x144
Modules linked in: can_raw can tpm_tis_spi tpm_tis_core 8021q garp stp mrp llc
rf6
CPU: 0 PID: 858 Comm: cansend Not tainted 6.9.0-rc6-00132-g31a65174a15c-dirty
#16
Hardware name: Toradex Verdin iMX8M Mini WB on Verdin Development Board (DT)
pstate: 60000005 (nZCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
pc : refcount_warn_saturate+0xf4/0x144
lr : refcount_warn_saturate+0xf4/0x144
sp : ffff800080003cc0
x29: ffff800080003cc0 x28: 0000000000000101 x27: ffff0000060ba0ac
x26: 0000000000000000 x25: 0000000000000000 x24: ffff800080003ea4
x23: ffff8000816f9000 x22: 0000000000000000 x21: 0000000000000000
x20: ffff000009e8196c x19: ffff000009e81800 x18: 0000000000000006
x17: ffff7ffffe6dc000 x16: ffff800080000000 x15: 072007200720072e
x14: 0765076507720766 x13: ffff8000817124e0 x12: 000000000000056a
x11: 00000000000001ce x10: ffff80008176a4e0 x9 : ffff8000817124e0
x8 : 00000000ffffefff x7 : ffff80008176a4e0 x6 : 80000000fffff000
x5 : 0000000000000000 x4 : 0000000000000000 x3 : 0000000000000000
x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffff000003754500
Call trace
refcount_warn_saturate+0xf4/0x144
sock_wfree+0x158/0x248
skb_release_head_state+0x2c/0x144
kfree_skb_reason+0x30/0xb0
can_dropped_invalid_skb+0x3c/0x17c [can_dev]
mcp251xfd_start_xmit+0x78/0x4e0 [mcp251xfd]
dev_hard_start_xmit+0x98/0x118
sch_direct_xmit+0x88/0x37c
__qdisc_run+0x118/0x66c
net_tx_action+0x158/0x218
__do_softirq+0x10c/0x264
____do_softirq+0x10/0x1c
call_on_irq_stack+0x24/0x4c
do_softirq_own_stack+0x1c/0x28
do_softirq+0x54/0x6c
__local_bh_enable_ip+0x8c/0x98
__dev_queue_xmit+0x224/0xd84
can_send+0xd4/0x2a4 [can
raw_sendmsg+0x270/0x3a0 [can_raw]
sock_write_iter+0xa4/0x110
vfs_write+0x2f0/0x358
ksys_write+0xe8/0x104
__arm64_sys_write+0x1c/0x28
invoke_syscall+0x48/0x118
el0_svc_common.constprop.0+0xc0/0xe0
do_el0_svc+0x1c/0x28
el0_svc+0x34/0xdc
el0t_64_sync_handler+0x100/0x12c
el0t_64_sync+0x190/0x194
--[ end trace 0000000000000000 ]---

My understanding is that can_create_echo_skb() does consume_skb(), which frees
the original skb and when the stack retry to transmit again it is not there.

In consequence of this, I moved the consume_skb() from can_create_echo_skb() to
the driver and I could do can_free_echo_skb() and return NETDEV_TX_BUSY without
issues on my tests.

...
err = mcp251xfd_tx_obj_write(priv, tx_obj);
if (err) {
	tx_ring->head--;

	if (!echo_err) {
		can_free_echo_skb(ndev, tx_head, &frame_len);
		netdev_completed_queue(ndev, 1, frame_len);
	}

	if (mcp251xfd_get_tx_free(tx_ring))
		netif_wake_queue(ndev);

	if (err == -EBUSY)
		return NETDEV_TX_BUSY;

	stats->tx_dropped++;
	if (net_ratelimit())
		netdev_err(priv->ndev,
				"ERROR in %s: %d\n", __func__, err);
}

consume_skb(skb);
...


> 
> Another option would be to start a workqueue and use spi_sync() in case
> the spi_async() is busy.
> 
> regards,
> Marc
> 

Meanwhile, I wonder if there is anything to add to the current patch so I can
address this topic in another patchset.

Best regards,
Vitor Soares