Re: [RFC][PATCH v2 00/31] timers: Use del_timer_shutdown() before freeing timers

[Steven Rostedt]

On Thu, 27 Oct 2022 11:58:59 -0700
Guenter Roeck <linux@xxxxxxxxxxxx> wrote:

> On 10/27/22 08:05, Steven Rostedt wrote:
> > Back in April, I posted an RFC patch set to help mitigate a common issue
> > where a timer gets armed just before it is freed, and when the timer
> > goes off, it crashes in the timer code without any evidence of who the
> > culprit was. I got side tracked and never finished up on that patch set.
> > Since this type of crash is still our #1 crash we are seeing in the field,
> > it has become a priority again to finish it.
> > 
> > This is v2 of that patch set. Thomas Gleixner posted an untested version
> > that makes timer->function NULL as the flag that it is shutdown. I took that
> > code, tested it (fixed it up), added more comments, and changed the
> > name to del_timer_shutdown() as Linus had asked. I also converted it to use
> > WARN_ON_ONCE() instead of just WARN_ON() as Linus asked for that too.
> >   
> 
> I rebased the series on top of v6.1-rc2 and gave it a try. Unfortunately it
> blows up in my face, first with
> 
> [   16.212535] ------------[ cut here ]------------
> [   16.212887] ODEBUG: free active (active state 0) object type: timer_list hint: tcp_write_timer+0x0/0x190
> [   16.213725] WARNING: CPU: 0 PID: 310 at lib/debugobjects.c:502 debug_print_object+0xb8/0x100
> 
> which, of course, might be real, but after a couple of those I get
> 
> [   16.325257] Insufficient stack space to handle exception!
> [   16.325326] ESR: 0x0000000096000047 -- DABT (current EL)
> [   16.325355] FAR: 0xffff800008677fe0
> [   16.325366] Task stack:     [0xffff800008678000..0xffff80000867c000]
> [   16.325376] IRQ stack:      [0xffff800008000000..0xffff800008004000]
> [   16.325387] Overflow stack: [0xffff51e19feab300..0xffff51e19feac300]
> [   16.325406] CPU: 0 PID: 310 Comm: telnet Tainted: G        W        N 6.1.0-rc2-00032-g895257c4037a #1
> [   16.325425] Hardware name: linux,dummy-virt (DT)
> [   16.325434] pstate: 400000c5 (nZcv daIF -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
> [   16.325450] pc : mark_lock+0x4/0x620
> [   16.325482] lr : __lock_acquire+0x3e8/0x1950
> [   16.325493] sp : ffff800008678090
> [   16.325499] x29: ffff800008678090 x28: ffff51e18651ccc0 x27: ffffc690a5583000
> [   16.325530] x26: ffff51e18651d590 x25: 0000000000000001 x24: 0000000000000001
> [   16.325552] x23: 0000000000000001 x22: 0000000000000028 x21: ffff51e18651d568
> [   16.325571] x20: ffffc690a61b5710 x19: 0000000000000000 x18: ffffffffffffffff
> [   16.325589] x17: 6e6968207473696c x16: 5f72656d6974203a x15: 6570797420746365
> [   16.325608] x14: 6a626f2029302065 x13: ffffc690a55a78c0 x12: 00000000000c02e7
> [   16.325626] x11: 0000000030fa562e x10: ffffc690a5a9f208 x9 : ffffc690a5a9f200
> [   16.325645] x8 : ffff51e18651ccc0 x7 : 0000000000000000 x6 : 000000000002e9fa
> [   16.325663] x5 : 0000000000000028 x4 : 0000000000000002 x3 : 00000000000c0003
> [   16.325681] x2 : 0000000000000008 x1 : ffff51e18651d590 x0 : ffff51e18651ccc0
> [   16.325902] Kernel panic - not syncing: kernel stack overflow
> [   16.325992] CPU: 0 PID: 310 Comm: telnet Tainted: G        W        N 6.1.0-rc2-00032-g895257c4037a #1
> [   16.326008] Hardware name: linux,dummy-virt (DT)
> [   16.326026] Call trace:
> [   16.326031]  dump_backtrace.part.0+0xe0/0xf0
> [   16.326048]  show_stack+0x18/0x40
> [   16.326058]  dump_stack_lvl+0x9c/0xd8
> [   16.326073]  dump_stack+0x18/0x34
> [   16.326083]  panic+0x194/0x38c
> [   16.326093]  nmi_panic+0xac/0xb0
> [   16.326103]  panic_bad_stack+0x104/0x124
> [   16.326113]  handle_bad_stack+0x34/0xe0
> [   16.326124]  __bad_stack+0x78/0x7c
> [   16.326134]  mark_lock+0x4/0x620
> [   16.326144]  lock_acquire.part.0+0xf0/0x26c
> [   16.326155]  lock_acquire+0x68/0x84
> [   16.326166]  _raw_spin_lock_irqsave+0x70/0x150
> [   16.326178]  debug_object_assert_init+0xa0/0x1a4
> [   16.326193]  __try_to_del_timer_sync+0x40/0xdc
> [   16.326207]  __del_timer_sync+0xa4/0x100
> [   16.326218]  timer_fixup_free+0x2c/0x54
> [   16.326229]  debug_object_free.part.0+0x188/0x1b0
> ...
> (many more of those)
> ...
> [   16.329989]  timer_fixup_free+0x40/0x54

Ah, I see the issue here. Looks like the timer_fixup_free() is calling
itself and crashing.

Let me take a look into that. I didn't touch the fixup code, and there
could be an assumption there that it's behaving with the old approach.

-- Steve


> [   16.329996]  __debug_check_no_obj_freed+0x1ec/0x25c
> [   16.330003]  debug_check_no_obj_freed+0x20/0x90
> [   16.330009]  slab_free_freelist_hook.constprop.0+0xac/0x1b0
> [   16.330019]  kmem_cache_free+0x1ac/0x500
> [   16.330026]  __sk_destruct+0x140/0x2a0
> [   16.330035]  sk_destruct+0x54/0x64
> [   16.330042]  __sk_free+0x74/0x120
> [   16.330048]  sk_free+0x64/0x8c
> [   16.330055]  tcp_close+0x94/0xc0
> [   16.330064]  inet_release+0x50/0xb0
> [   16.330071]  __sock_release+0x44/0xbc
> [   16.330076]  sock_close+0x18/0x30
> [   16.330081]  __fput+0x84/0x270
> [   16.330088]  ____fput+0x10/0x20
> [   16.330094]  task_work_run+0x88/0xf0
> [   16.330102]  do_exit+0x334/0xafc
> [   16.330108]  do_group_exit+0x34/0x90
> [   16.330115]  __arm64_sys_exit_group+0x18/0x20
> [   16.330121]  invoke_syscall+0x48/0x114
> [   16.330133]  el0_svc_common.constprop.0+0x60/0x11c
> [   16.330146]  do_el0_svc+0x30/0xd0
> [   16.330157]  el0_svc+0x48/0xc0
> [   16.330170]  el0t_64_sync_handler+0xbc/0x13c
> [   16.330179]  el0t_64_sync+0x18c/0x190
> [   16.330645] Kernel Offset: 0x46909ae00000 from 0xffff800008000000
> [   16.330664] PHYS_OFFSET: 0xffffae1ec0000000
> [   16.330686] CPU features: 0x22000,2033c080,0000421b
> [   16.330752] Memory Limit: none
> 
> This is with arm64_defconfig plus various debug options.
> Running the same test with v6.0.4 produces no errors, and neither
> does running it with v6.1-rc2-105-gb229b6ca5abb (current mainline).
> 
> Guenter