tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?

tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?

[Dirk Behme]

Hi,

using drivers/tty/serial/sh-sci.c (on 4.14.x Renesas BSP) what is quite 
similar to [1] we got [2].

Analyzing this we found that in sci_dma_rx_timer_fn() s->chan_rx is NULL.

Is there any chance that there is a race condition where the timer 
function sci_dma_rx_timer_fn() is called while s->chan_rx is 
invalidated, already. E.g. via 
sci_dma_rx_chan_invalidate()/sci_dma_rx_release()? Or anything else?

Any idea?

Best regards

Dirk

[1] 
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/tty/serial/sh-sci.c

[2]

Unable to handle kernel NULL pointer dereference at virtual address 00000000
Mem abort info:
   Exception class = DABT (current EL), IL = 32 bits
   SET = 0, FnV = 0
   EA = 0, S1PTW = 0
Data abort info:
   ISV = 0, ISS = 0x00000006
   CM = 0, WnR = 0
user pgtable: 4k pages, 48-bit VAs, pgd = ffff80061f6ba000
[0000000000000000] *pgd=000000065f6c0003, *pud=000000065f6bf003, 
*pmd=0000000000000000
Internal error: Oops: 96000006 [#1] PREEMPT SMP
Process (pid: 3983, stack limit = 0xffff000009540000)
CPU: 2 PID: 3983 Tainted: G         C      4.14.327-ltsi #1
Hardware name: Bosch custom board based on r8a7796 (DT)
pc : sci_dma_rx_timer_fn+0x64/0x194
lr : sci_dma_rx_timer_fn+0x3c/0x194
sp : ffff000008013df0 pstate : 600001c5
x29: ffff000008013df0 x28: ffff0000084055e8
x27: 00000060cce93e4e x26: 0000000000000003
x25: ffff000008c48b38 x24: 0000000000000000
x23: 00000000000001c0 x22: ffff000008d98708
x21: ffff000008999000 x20: 0000000000000000
x19: ffff000008d98810 x18: 00004000362715f6
x17: 00000039f1fc5610 x16: 00000039f22bd748
x15: 000007b1e26dc9d4 x14: 000112a7eb4cd8a2
x13: 00000000631508c6 x12: 0000000000000028
x11: 0101010101010101 x10: 0000000000000000
x9 : 00000000000000cc x8 : ffff800696c04500
x7 : 0000000000000064 x6 : ffff000008d98b08
x5 : ffff00000a923e31 x4 : ffff80069ff09580
x3 : ffff00000a923e30 x2 : 0000000000000000
x1 : 00000000ffffffea x0 : 0000000000000000
Call trace:
  sci_dma_rx_timer_fn+0x64/0x194
  __hrtimer_run_queues+0x19c/0x2f8
  hrtimer_interrupt+0xa0/0x1b0
  arch_timer_handler_phys+0x28/0x3c
  handle_percpu_devid_irq+0xbc/0x268
  generic_handle_irq+0x18/0x2c
  __handle_domain_irq+0xa8/0xac
  gic_handle_irq+0x68/0xa8
  el0_irq_naked+0x50/0x5c
Code: 6b00003f 54000101 52800034 f941aac0 (f9400002)
---[ end trace 07c3c96aa9b5135e ]---
Kernel panic - not syncing: Fatal exception in interrupt
SMP: stopping secondary CPUs
Kernel Offset: disabled
CPU features: 0x61002004
Memory Limit: 6016 MB
Rebooting in 3 seconds..

RE: tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?

[Biju Das]

Hi Dirk,

Thanks for the report.

Q1) How can we trigger this condition?

Q2) Do you see any messages "Failed submitting Rx DMA descriptor\n" in logs?

Cheers,
Biju

> -----Original Message-----
> From: Dirk Behme <dirk.behme@de.bosch.com>
> Sent: Thursday, April 11, 2024 1:41 PM
> To: Linux-Renesas <linux-renesas-soc@vger.kernel.org>
> Cc: Biju Das <biju.das.jz@bp.renesas.com>; Geert Uytterhoeven <geert+renesas@glider.be>
> Subject: tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?
> 
> Hi,
> 
> using drivers/tty/serial/sh-sci.c (on 4.14.x Renesas BSP) what is quite similar to [1] we got [2].
> 
> Analyzing this we found that in sci_dma_rx_timer_fn() s->chan_rx is NULL.
> 
> Is there any chance that there is a race condition where the timer function sci_dma_rx_timer_fn()
> is called while s->chan_rx is invalidated, already. E.g. via
> sci_dma_rx_chan_invalidate()/sci_dma_rx_release()? Or anything else?
> 
> Any idea?
> 
> Best regards
> 
> Dirk
> 
> [1]
> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/tty/serial/sh-sci.c
> 
> [2]
> 
> Unable to handle kernel NULL pointer dereference at virtual address 00000000 Mem abort info:
>    Exception class = DABT (current EL), IL = 32 bits
>    SET = 0, FnV = 0
>    EA = 0, S1PTW = 0
> Data abort info:
>    ISV = 0, ISS = 0x00000006
>    CM = 0, WnR = 0
> user pgtable: 4k pages, 48-bit VAs, pgd = ffff80061f6ba000 [0000000000000000]
> *pgd=000000065f6c0003, *pud=000000065f6bf003,
> *pmd=0000000000000000
> Internal error: Oops: 96000006 [#1] PREEMPT SMP Process (pid: 3983, stack limit =
> 0xffff000009540000)
> CPU: 2 PID: 3983 Tainted: G         C      4.14.327-ltsi #1
> Hardware name: Bosch custom board based on r8a7796 (DT) pc : sci_dma_rx_timer_fn+0x64/0x194 lr :
> sci_dma_rx_timer_fn+0x3c/0x194 sp : ffff000008013df0 pstate : 600001c5
> x29: ffff000008013df0 x28: ffff0000084055e8
> x27: 00000060cce93e4e x26: 0000000000000003
> x25: ffff000008c48b38 x24: 0000000000000000
> x23: 00000000000001c0 x22: ffff000008d98708
> x21: ffff000008999000 x20: 0000000000000000
> x19: ffff000008d98810 x18: 00004000362715f6
> x17: 00000039f1fc5610 x16: 00000039f22bd748
> x15: 000007b1e26dc9d4 x14: 000112a7eb4cd8a2
> x13: 00000000631508c6 x12: 0000000000000028
> x11: 0101010101010101 x10: 0000000000000000
> x9 : 00000000000000cc x8 : ffff800696c04500
> x7 : 0000000000000064 x6 : ffff000008d98b08
> x5 : ffff00000a923e31 x4 : ffff80069ff09580
> x3 : ffff00000a923e30 x2 : 0000000000000000
> x1 : 00000000ffffffea x0 : 0000000000000000 Call trace:
>   sci_dma_rx_timer_fn+0x64/0x194
>   __hrtimer_run_queues+0x19c/0x2f8
>   hrtimer_interrupt+0xa0/0x1b0
>   arch_timer_handler_phys+0x28/0x3c
>   handle_percpu_devid_irq+0xbc/0x268
>   generic_handle_irq+0x18/0x2c
>   __handle_domain_irq+0xa8/0xac
>   gic_handle_irq+0x68/0xa8
>   el0_irq_naked+0x50/0x5c
> Code: 6b00003f 54000101 52800034 f941aac0 (f9400002) ---[ end trace 07c3c96aa9b5135e ]--- Kernel
> panic - not syncing: Fatal exception in interrupt
> SMP: stopping secondary CPUs
> Kernel Offset: disabled
> CPU features: 0x61002004
> Memory Limit: 6016 MB
> Rebooting in 3 seconds..

Re: RE: tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?

[Dirk Behme]

Hi Biju,

On 11.04.2024 14:54, Biju Das wrote:
> Hi Dirk,
> 
> Thanks for the report.
> 
> Q1) How can we trigger this condition?

I don't think we can at the moment :( We have seen this only once, so 
far. Therefore I assume a subtle race.

> Q2) Do you see any messages "Failed submitting Rx DMA descriptor\n" in logs?

That message is written on dev_warn level:

./sh-sci.c:1342:        dev_warn(port->dev, "Failed submitting Rx DMA 
descriptor\n");

Unfortunately, the exception log given below [2] is extracted from a 
persistent error logging system on the device which doesn't record 
messages on dev_warn() level. So we don't have the complete console log.

Many thanks for answering that fast! :)

Best regards

Dirk


>> -----Original Message-----
>> From: Dirk Behme <dirk.behme@de.bosch.com>
>> Sent: Thursday, April 11, 2024 1:41 PM
>> To: Linux-Renesas <linux-renesas-soc@vger.kernel.org>
>> Cc: Biju Das <biju.das.jz@bp.renesas.com>; Geert Uytterhoeven <geert+renesas@glider.be>
>> Subject: tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?
>>
>> Hi,
>>
>> using drivers/tty/serial/sh-sci.c (on 4.14.x Renesas BSP) what is quite similar to [1] we got [2].
>>
>> Analyzing this we found that in sci_dma_rx_timer_fn() s->chan_rx is NULL.
>>
>> Is there any chance that there is a race condition where the timer function sci_dma_rx_timer_fn()
>> is called while s->chan_rx is invalidated, already. E.g. via
>> sci_dma_rx_chan_invalidate()/sci_dma_rx_release()? Or anything else?
>>
>> Any idea?
>>
>> Best regards
>>
>> Dirk
>>
>> [1]
>> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/tty/serial/sh-sci.c
>>
>> [2]
>>
>> Unable to handle kernel NULL pointer dereference at virtual address 00000000 Mem abort info:
>>     Exception class = DABT (current EL), IL = 32 bits
>>     SET = 0, FnV = 0
>>     EA = 0, S1PTW = 0
>> Data abort info:
>>     ISV = 0, ISS = 0x00000006
>>     CM = 0, WnR = 0
>> user pgtable: 4k pages, 48-bit VAs, pgd = ffff80061f6ba000 [0000000000000000]
>> *pgd=000000065f6c0003, *pud=000000065f6bf003,
>> *pmd=0000000000000000
>> Internal error: Oops: 96000006 [#1] PREEMPT SMP Process (pid: 3983, stack limit =
>> 0xffff000009540000)
>> CPU: 2 PID: 3983 Tainted: G         C      4.14.327-ltsi #1
>> Hardware name: Bosch custom board based on r8a7796 (DT) pc : sci_dma_rx_timer_fn+0x64/0x194 lr :
>> sci_dma_rx_timer_fn+0x3c/0x194 sp : ffff000008013df0 pstate : 600001c5
>> x29: ffff000008013df0 x28: ffff0000084055e8
>> x27: 00000060cce93e4e x26: 0000000000000003
>> x25: ffff000008c48b38 x24: 0000000000000000
>> x23: 00000000000001c0 x22: ffff000008d98708
>> x21: ffff000008999000 x20: 0000000000000000
>> x19: ffff000008d98810 x18: 00004000362715f6
>> x17: 00000039f1fc5610 x16: 00000039f22bd748
>> x15: 000007b1e26dc9d4 x14: 000112a7eb4cd8a2
>> x13: 00000000631508c6 x12: 0000000000000028
>> x11: 0101010101010101 x10: 0000000000000000
>> x9 : 00000000000000cc x8 : ffff800696c04500
>> x7 : 0000000000000064 x6 : ffff000008d98b08
>> x5 : ffff00000a923e31 x4 : ffff80069ff09580
>> x3 : ffff00000a923e30 x2 : 0000000000000000
>> x1 : 00000000ffffffea x0 : 0000000000000000 Call trace:
>>    sci_dma_rx_timer_fn+0x64/0x194
>>    __hrtimer_run_queues+0x19c/0x2f8
>>    hrtimer_interrupt+0xa0/0x1b0
>>    arch_timer_handler_phys+0x28/0x3c
>>    handle_percpu_devid_irq+0xbc/0x268
>>    generic_handle_irq+0x18/0x2c
>>    __handle_domain_irq+0xa8/0xac
>>    gic_handle_irq+0x68/0xa8
>>    el0_irq_naked+0x50/0x5c
>> Code: 6b00003f 54000101 52800034 f941aac0 (f9400002) ---[ end trace 07c3c96aa9b5135e ]--- Kernel
>> panic - not syncing: Fatal exception in interrupt
>> SMP: stopping secondary CPUs
>> Kernel Offset: disabled
>> CPU features: 0x61002004
>> Memory Limit: 6016 MB
>> Rebooting in 3 seconds..

Re: tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?

[Wolfram Sang]

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

Hi Dirk,

thanks for this report!

> Is there any chance that there is a race condition where the timer function
> sci_dma_rx_timer_fn() is called while s->chan_rx is invalidated, already.
> E.g. via sci_dma_rx_chan_invalidate()/sci_dma_rx_release()? Or anything
> else?

Sounds a bit like the TMIO race condition you recently reported and
which we luckily fixed meanwhile.

I could have a look next week. Or do you want to handle it, Geert and /
or Biju?

Happy hacking everyone,

   Wolfram


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

RE: tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?

[Biju Das]

Hi Wolfram,

> -----Original Message-----
> From: Wolfram Sang <wsa+renesas@sang-engineering.com>
> Subject: Re: tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?
> 
> Hi Dirk,
> 
> thanks for this report!
> 
> > Is there any chance that there is a race condition where the timer
> > function
> > sci_dma_rx_timer_fn() is called while s->chan_rx is invalidated, already.
> > E.g. via sci_dma_rx_chan_invalidate()/sci_dma_rx_release()? Or
> > anything else?
> 
> Sounds a bit like the TMIO race condition you recently reported and which we luckily fixed
> meanwhile.
> 
> I could have a look next week. Or do you want to handle it, Geert and / or Biju?

FYI, Currently I am loaded with RZ future devices activity. So, I don't have time
to check. Geert/Wolfram, please support this issue.

Cheers,
Biju

Re: tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?

[Wolfram Sang]

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

Hi Dirk,

> Analyzing this we found that in sci_dma_rx_timer_fn() s->chan_rx is NULL.

Again, good catch. Thank you! Here is the outcome of my first debugging
session...

> Is there any chance that there is a race condition where the timer function
> sci_dma_rx_timer_fn() is called while s->chan_rx is invalidated, already.
> E.g. via sci_dma_rx_chan_invalidate()/sci_dma_rx_release()? Or anything
> else?

Only 'sci_dma_rx_chan_invalidate' clears s->chan_rx. I think these paths
involving 'sci_dma_rx_chan_invalidate' are OK:

sci_dma_rx_chan_invalidate <- sci_dma_rx_release <- sci_free_dma ...

A) <- sci_startup (no issue because interrupts could not be requested
                   and RX DMA is started in an interrupt)

B) <- sci_shutdown (no issue because 'hrtimer_cancel' has been called
		    before freeing DMA)

This path also seems ok:

sci_dma_rx_chan_invalidate <- sci_dma_rx_submit (error path)
  <- sci_rx_interrupt (no issue because timer is started after
		       'sci_dma_rx_submit')

This path looks problematic:

sci_dma_rx_chan_invalidate <- sci_dma_rx_complete (error path)

The timer is started before DMA is set up. In the unlikely event of the
DMA setup failing, s->chan_rx will be cleared while the timer has
already been started. This is in deed a very rare condition.

The problem is that I cannot trigger the code patch so far. It is easy
to force 'sci_dma_rx_complete' to bail out but, so far, I couldn't get
it called.

Nonetheless, given this broken error path, I suggest two fixes which
I'll send out as RFC in some minutes.

All the best,

   Wolfram


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?

[Geert Uytterhoeven]

Hi Wolfram,

On Tue, Apr 16, 2024 at 1:49 PM Wolfram Sang
<wsa+renesas@sang-engineering.com> wrote:
> > Analyzing this we found that in sci_dma_rx_timer_fn() s->chan_rx is NULL.
>
> Again, good catch. Thank you! Here is the outcome of my first debugging
> session...
>
> > Is there any chance that there is a race condition where the timer function
> > sci_dma_rx_timer_fn() is called while s->chan_rx is invalidated, already.
> > E.g. via sci_dma_rx_chan_invalidate()/sci_dma_rx_release()? Or anything
> > else?
>
> Only 'sci_dma_rx_chan_invalidate' clears s->chan_rx. I think these paths
> involving 'sci_dma_rx_chan_invalidate' are OK:
>
> sci_dma_rx_chan_invalidate <- sci_dma_rx_release <- sci_free_dma ...
>
> A) <- sci_startup (no issue because interrupts could not be requested
>                    and RX DMA is started in an interrupt)
>
> B) <- sci_shutdown (no issue because 'hrtimer_cancel' has been called
>                     before freeing DMA)
>
> This path also seems ok:
>
> sci_dma_rx_chan_invalidate <- sci_dma_rx_submit (error path)
>   <- sci_rx_interrupt (no issue because timer is started after
>                        'sci_dma_rx_submit')
>
> This path looks problematic:
>
> sci_dma_rx_chan_invalidate <- sci_dma_rx_complete (error path)
>
> The timer is started before DMA is set up. In the unlikely event of the
> DMA setup failing, s->chan_rx will be cleared while the timer has
> already been started. This is in deed a very rare condition.

Or when the previous (still running) timer expires...

> The problem is that I cannot trigger the code patch so far. It is easy
> to force 'sci_dma_rx_complete' to bail out but, so far, I couldn't get
> it called.

Note that DMA is disabled for the serial console, cfr. the check for
uart_console() in sci_request_dma().  For testing, you can just remove
that check.

Also, plain text typing (on the serial console, or on a getty running
on a secondary port) does not trigger a DMA RX transfer.  Pasting
a block of text larger than the FIFO size to the terminal should
trigger DMA RX.

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?

[Wolfram Sang]

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


> > The timer is started before DMA is set up. In the unlikely event of the
> > DMA setup failing, s->chan_rx will be cleared while the timer has
> > already been started. This is in deed a very rare condition.
> 
> Or when the previous (still running) timer expires...

Yes, ack.

> Note that DMA is disabled for the serial console, cfr. the check for
> uart_console() in sci_request_dma().  For testing, you can just remove
> that check.

I didn't test with the console but with the other debug port of a
Salvator-X board.

> Also, plain text typing (on the serial console, or on a getty running
> on a secondary port) does not trigger a DMA RX transfer.  Pasting
> a block of text larger than the FIFO size to the terminal should
> trigger DMA RX.

I dd'ed random data to the port. '/proc/interrupts/' showed some DMA
triggers but no indication of that code path. I need to recheck.
Probably my fault somewhere, but I need to finish another task first.
I'll come back here after this.

Thanks for also looking into it, Geert!


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: tty: serial: sh-sci: hrtimer not properly canceled on chan_rx invalidation?

[Wolfram Sang]

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

Dirk,

> using drivers/tty/serial/sh-sci.c (on 4.14.x Renesas BSP) what is quite
> similar to [1] we got [2].

Do you know if the system was about to shutdown/reboot? Taking locking
into account, I only see a race condition when shutting down. Perhaps it
is this one already or I still haven't found it yet.


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]