BUG: BISECTED: memleak in vfs_write()

BUG: BISECTED: memleak in vfs_write()

[Mirsad Goran Todorovac]

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

Hi all,

I came across a memory leak with the vanilla mainline Torvalds tree kernel
with MGLRU and CONFIG_KMEMLEAK enabled:

unreferenced object 0xffff8d7c92ad5180 (size 192):
  comm "ftracetest", pid 2738512, jiffies 4335176273 (age 4842.976s)
  hex dump (first 32 bytes):
    c0 59 ad 92 7c 8d ff ff 60 dd d7 31 7c 8d ff ff  .Y..|...`..1|...
    60 55 df 97 ff ff ff ff 09 00 02 00 00 00 00 00  `U..............
  backtrace:
    [<ffffffff965d9bf0>] __kmem_cache_alloc_node+0x1e0/0x340
    [<ffffffff96556dda>] kmalloc_trace+0x2a/0xa0
    [<ffffffff964382fc>] tracing_log_err+0x16c/0x1b0
    [<ffffffff96451963>] append_filter_err+0x113/0x1d0
    [<ffffffff96453c0a>] create_event_filter+0xba/0xe0
    [<ffffffff96454b18>] set_trigger_filter+0x98/0x160
    [<ffffffff96456554>] event_trigger_parse+0x104/0x180
    [<ffffffff96455823>] trigger_process_regex+0xc3/0x110
    [<ffffffff964558f7>] event_trigger_write+0x77/0xe0
    [<ffffffff96623a41>] vfs_write+0xd1/0x420
    [<ffffffff9662413b>] ksys_write+0x7b/0x100
    [<ffffffff966241e9>] __x64_sys_write+0x19/0x20
    [<ffffffff971c9188>] do_syscall_64+0x58/0x80
    [<ffffffff972000aa>] entry_SYSCALL_64_after_hwframe+0x72/0xdc
unreferenced object 0xffff8d7b076be000 (size 32):
  comm "ftracetest", pid 2738512, jiffies 4335176273 (age 4842.976s)
  hex dump (first 32 bytes):
    0a 20 20 43 6f 6d 6d 61 6e 64 3a 20 61 0a 00 00  .  Command: a...
    00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  backtrace:
    [<ffffffff965d9bf0>] __kmem_cache_alloc_node+0x1e0/0x340
    [<ffffffff96557a8d>] __kmalloc+0x4d/0xd0
    [<ffffffff96438314>] tracing_log_err+0x184/0x1b0
    [<ffffffff96451963>] append_filter_err+0x113/0x1d0
    [<ffffffff96453c0a>] create_event_filter+0xba/0xe0
    [<ffffffff96454b18>] set_trigger_filter+0x98/0x160
    [<ffffffff96456554>] event_trigger_parse+0x104/0x180
    [<ffffffff96455823>] trigger_process_regex+0xc3/0x110
    [<ffffffff964558f7>] event_trigger_write+0x77/0xe0
    [<ffffffff96623a41>] vfs_write+0xd1/0x420
    [<ffffffff9662413b>] ksys_write+0x7b/0x100
    [<ffffffff966241e9>] __x64_sys_write+0x19/0x20
    [<ffffffff971c9188>] do_syscall_64+0x58/0x80
    [<ffffffff972000aa>] entry_SYSCALL_64_after_hwframe+0x72/0xdc
unreferenced object 0xffff8d7c92ad59c0 (size 192):
  comm "ftracetest", pid 2738512, jiffies 4335176280 (age 4843.088s)
  hex dump (first 32 bytes):
    c0 5c ad 92 7c 8d ff ff 80 51 ad 92 7c 8d ff ff  .\..|....Q..|...
    60 55 df 97 ff ff ff ff 01 00 0b 00 00 00 00 00  `U..............
  backtrace:
    [<ffffffff965d9bf0>] __kmem_cache_alloc_node+0x1e0/0x340
    [<ffffffff96556dda>] kmalloc_trace+0x2a/0xa0
    [<ffffffff964382fc>] tracing_log_err+0x16c/0x1b0
    [<ffffffff96451963>] append_filter_err+0x113/0x1d0
    [<ffffffff96453c0a>] create_event_filter+0xba/0xe0
    [<ffffffff96454b18>] set_trigger_filter+0x98/0x160
    [<ffffffff96456554>] event_trigger_parse+0x104/0x180
    [<ffffffff96455823>] trigger_process_regex+0xc3/0x110
    [<ffffffff964558f7>] event_trigger_write+0x77/0xe0
    [<ffffffff96623a41>] vfs_write+0xd1/0x420
    [<ffffffff9662413b>] ksys_write+0x7b/0x100
    [<ffffffff966241e9>] __x64_sys_write+0x19/0x20
    [<ffffffff971c9188>] do_syscall_64+0x58/0x80
    [<ffffffff972000aa>] entry_SYSCALL_64_after_hwframe+0x72/0xdc

The bug was noticed on Lenovo desktop 10TX000VCR (LENOVO_MT_10TX_BU_Lenovo_FM_V530S-07ICB)
running AlmaLinux 8.7 (Stone Smilodon), a CentOS clone, with the compiler:

mtodorov@domac:~/linux/kernel/linux_torvalds$ gcc --version
gcc (Debian 8.3.0-6) 8.3.0
Copyright (C) 2018 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
mtodorov@domac:~/linux/kernel/linux_torvalds$ 

Bisecting gave the following culprit commit:

git bisect good a92ce570c81dc0feaeb12a429b4bc65686d17967
# good: [c6f613e5f35b0e2154d5ca12f0e8e0be0c19be9a] ipmi/watchdog: use strscpy() to instead of strncpy()
git bisect good c6f613e5f35b0e2154d5ca12f0e8e0be0c19be9a
# good: [90b12f423d3c8a89424c7bdde18e1923dfd0941e] Merge tag 'for-linus-6.2-1' of https://github.com/cminyard/linux-ipmi
git bisect good 90b12f423d3c8a89424c7bdde18e1923dfd0941e
# first bad commit: [71946a25f357a51dcce849367501d7fb04c0465b] Merge tag 'mmc-v6.2' of git://git.kernel.org/pub/scm/linux/kernel/git/ulfh/mmc

The commit was merged on December 13th 2022.

It is a huge commit.

The selftests/ftrace/ftracetest triggers this leak, sometimes several times in a run.
ftracetest requires root permission to run, but I haven't yet realised whether a non-superuser
could devise an automated script to abuse this leak exhausting all kernel's memory.

Non-root user gets a EPERM error when trying to access /proc/sys/kernel internals:

[marvin@pc-mtodorov linux_torvalds]$ tools/testing/selftests/ftrace/ftracetest 
Error: this must be run by root user
tools/testing/selftests/ftrace/ftracetest: line 46: /proc/sys/kernel/sched_rt_runtime_us: Permission denied
[marvin@pc-mtodorov linux_torvalds]$ 

Hope this helps.

According to the Code of Conduct, I have Cc:-ed maintainers from get_maintainers.pl and
I will add Thorsten because this is sort of a regression :-)

Regards,
Mirsad

-- 
Mirsad Goran Todorovac
Sistem inženjer
Grafički fakultet | Akademija likovnih umjetnosti
Sveučilište u Zagrebu
 
System engineer
Faculty of Graphic Arts | Academy of Fine Arts
University of Zagreb, Republic of Croatia
The European Union

[-- Attachment #2: config-6.1.0-rc1-mglru-kmemlk-00007-g6dbd4341b9da.xz --]
[-- Type: application/x-xz, Size: 56680 bytes --]

Re: [BUG RESEND] [BISECTED]: selftest: ftracetest: memleak in vfs_write()

[Mirsad Goran Todorovac]

Hi,

No progress on this bug report, so it is still unpatched in 6.3-rc5 so I am
submitting again.

Please see the relevant data at the bottom:

On 27. 01. 2023. 19:36, Mirsad Goran Todorovac wrote:
> Hi all,
> 
> I came across a memory leak with the vanilla mainline Torvalds tree kernel
> with MGLRU and CONFIG_KMEMLEAK enabled:
> 
> unreferenced object 0xffff8d7c92ad5180 (size 192):
>   comm "ftracetest", pid 2738512, jiffies 4335176273 (age 4842.976s)
>   hex dump (first 32 bytes):
>     c0 59 ad 92 7c 8d ff ff 60 dd d7 31 7c 8d ff ff  .Y..|...`..1|...
>     60 55 df 97 ff ff ff ff 09 00 02 00 00 00 00 00  `U..............
>   backtrace:
>     [<ffffffff965d9bf0>] __kmem_cache_alloc_node+0x1e0/0x340
>     [<ffffffff96556dda>] kmalloc_trace+0x2a/0xa0
>     [<ffffffff964382fc>] tracing_log_err+0x16c/0x1b0
>     [<ffffffff96451963>] append_filter_err+0x113/0x1d0
>     [<ffffffff96453c0a>] create_event_filter+0xba/0xe0
>     [<ffffffff96454b18>] set_trigger_filter+0x98/0x160
>     [<ffffffff96456554>] event_trigger_parse+0x104/0x180
>     [<ffffffff96455823>] trigger_process_regex+0xc3/0x110
>     [<ffffffff964558f7>] event_trigger_write+0x77/0xe0
>     [<ffffffff96623a41>] vfs_write+0xd1/0x420
>     [<ffffffff9662413b>] ksys_write+0x7b/0x100
>     [<ffffffff966241e9>] __x64_sys_write+0x19/0x20
>     [<ffffffff971c9188>] do_syscall_64+0x58/0x80
>     [<ffffffff972000aa>] entry_SYSCALL_64_after_hwframe+0x72/0xdc
> unreferenced object 0xffff8d7b076be000 (size 32):
>   comm "ftracetest", pid 2738512, jiffies 4335176273 (age 4842.976s)
>   hex dump (first 32 bytes):
>     0a 20 20 43 6f 6d 6d 61 6e 64 3a 20 61 0a 00 00  .  Command: a...
>     00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
>   backtrace:
>     [<ffffffff965d9bf0>] __kmem_cache_alloc_node+0x1e0/0x340
>     [<ffffffff96557a8d>] __kmalloc+0x4d/0xd0
>     [<ffffffff96438314>] tracing_log_err+0x184/0x1b0
>     [<ffffffff96451963>] append_filter_err+0x113/0x1d0
>     [<ffffffff96453c0a>] create_event_filter+0xba/0xe0
>     [<ffffffff96454b18>] set_trigger_filter+0x98/0x160
>     [<ffffffff96456554>] event_trigger_parse+0x104/0x180
>     [<ffffffff96455823>] trigger_process_regex+0xc3/0x110
>     [<ffffffff964558f7>] event_trigger_write+0x77/0xe0
>     [<ffffffff96623a41>] vfs_write+0xd1/0x420
>     [<ffffffff9662413b>] ksys_write+0x7b/0x100
>     [<ffffffff966241e9>] __x64_sys_write+0x19/0x20
>     [<ffffffff971c9188>] do_syscall_64+0x58/0x80
>     [<ffffffff972000aa>] entry_SYSCALL_64_after_hwframe+0x72/0xdc
> unreferenced object 0xffff8d7c92ad59c0 (size 192):
>   comm "ftracetest", pid 2738512, jiffies 4335176280 (age 4843.088s)
>   hex dump (first 32 bytes):
>     c0 5c ad 92 7c 8d ff ff 80 51 ad 92 7c 8d ff ff  .\..|....Q..|...
>     60 55 df 97 ff ff ff ff 01 00 0b 00 00 00 00 00  `U..............
>   backtrace:
>     [<ffffffff965d9bf0>] __kmem_cache_alloc_node+0x1e0/0x340
>     [<ffffffff96556dda>] kmalloc_trace+0x2a/0xa0
>     [<ffffffff964382fc>] tracing_log_err+0x16c/0x1b0
>     [<ffffffff96451963>] append_filter_err+0x113/0x1d0
>     [<ffffffff96453c0a>] create_event_filter+0xba/0xe0
>     [<ffffffff96454b18>] set_trigger_filter+0x98/0x160
>     [<ffffffff96456554>] event_trigger_parse+0x104/0x180
>     [<ffffffff96455823>] trigger_process_regex+0xc3/0x110
>     [<ffffffff964558f7>] event_trigger_write+0x77/0xe0
>     [<ffffffff96623a41>] vfs_write+0xd1/0x420
>     [<ffffffff9662413b>] ksys_write+0x7b/0x100
>     [<ffffffff966241e9>] __x64_sys_write+0x19/0x20
>     [<ffffffff971c9188>] do_syscall_64+0x58/0x80
>     [<ffffffff972000aa>] entry_SYSCALL_64_after_hwframe+0x72/0xdc
> 
> The bug was noticed on Lenovo desktop 10TX000VCR (LENOVO_MT_10TX_BU_Lenovo_FM_V530S-07ICB)
> running AlmaLinux 8.7 (Stone Smilodon), a CentOS clone, with the compiler:
> 
> mtodorov@domac:~/linux/kernel/linux_torvalds$ gcc --version
> gcc (Debian 8.3.0-6) 8.3.0
> Copyright (C) 2018 Free Software Foundation, Inc.
> This is free software; see the source for copying conditions.  There is NO
> warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
> mtodorov@domac:~/linux/kernel/linux_torvalds$ 
> 
> Bisecting gave the following culprit commit:
> 
> git bisect good a92ce570c81dc0feaeb12a429b4bc65686d17967
> # good: [c6f613e5f35b0e2154d5ca12f0e8e0be0c19be9a] ipmi/watchdog: use strscpy() to instead of strncpy()
> git bisect good c6f613e5f35b0e2154d5ca12f0e8e0be0c19be9a
> # good: [90b12f423d3c8a89424c7bdde18e1923dfd0941e] Merge tag 'for-linus-6.2-1' of https://github.com/cminyard/linux-ipmi
> git bisect good 90b12f423d3c8a89424c7bdde18e1923dfd0941e
> # first bad commit: [71946a25f357a51dcce849367501d7fb04c0465b] Merge tag 'mmc-v6.2' of git://git.kernel.org/pub/scm/linux/kernel/git/ulfh/mmc
> 
> The commit was merged on December 13th 2022.
> 
> It is a huge commit.
> 
> The selftests/ftrace/ftracetest triggers this leak, sometimes several times in a run.
> ftracetest requires root permission to run, but I haven't yet realised whether a non-superuser
> could devise an automated script to abuse this leak exhausting all kernel's memory.
> 
> Non-root user gets a EPERM error when trying to access /proc/sys/kernel internals:
> 
> [marvin@pc-mtodorov linux_torvalds]$ tools/testing/selftests/ftrace/ftracetest 
> Error: this must be run by root user
> tools/testing/selftests/ftrace/ftracetest: line 46: /proc/sys/kernel/sched_rt_runtime_us: Permission denied
> [marvin@pc-mtodorov linux_torvalds]$ 
> 
> Hope this helps.
> 
> According to the Code of Conduct, I have Cc:-ed maintainers from get_maintainers.pl and
> I will add Thorsten because this is sort of a regression :-)

The debug output is like follows:

unreferenced object 0xffff93a3dc2d1e18 (size 192):
  comm "ftracetest", pid 12451, jiffies 4295087353 (age 463.476s)
  hex dump (first 32 bytes):
    20 08 2d dc a3 93 ff ff c0 bd 5d cd a3 93 ff ff   .-.......].....
    c0 bf 85 b6 ff ff ff ff 09 00 02 00 00 00 00 00  ................
  backtrace:
    [<ffffffffb4afb23c>] slab_post_alloc_hook+0x8c/0x3e0
    [<ffffffffb4b02b19>] __kmem_cache_alloc_node+0x1d9/0x2a0
    [<ffffffffb4a7693e>] kmalloc_trace+0x2e/0xc0
    [<ffffffffb493a8fb>] tracing_log_err+0x18b/0x1d0
    [<ffffffffb4959049>] append_filter_err.isra.13+0x119/0x190
    [<ffffffffb495a89f>] create_filter+0xbf/0xe0
    [<ffffffffb495ab10>] create_event_filter+0x10/0x20
    [<ffffffffb495c040>] set_trigger_filter+0xa0/0x180
    [<ffffffffb495d745>] event_trigger_parse+0xf5/0x160
    [<ffffffffb495c889>] trigger_process_regex+0xc9/0x120
    [<ffffffffb495c976>] event_trigger_write+0x86/0xf0
    [<ffffffffb4b52dc2>] vfs_write+0xf2/0x520
    [<ffffffffb4b533d8>] ksys_write+0x68/0xe0
    [<ffffffffb4b5347e>] __x64_sys_write+0x1e/0x30
    [<ffffffffb586619c>] do_syscall_64+0x5c/0x90
    [<ffffffffb5a000ae>] entry_SYSCALL_64_after_hwframe+0x72/0xdc
unreferenced object 0xffff93a3873dda20 (size 32):
  comm "ftracetest", pid 12451, jiffies 4295087353 (age 463.476s)
  hex dump (first 32 bytes):
    0a 20 20 43 6f 6d 6d 61 6e 64 3a 20 61 0a 00 00  .  Command: a...
    00 00 cc cc cc cc cc cc cc cc cc cc cc cc cc cc  ................
  backtrace:
    [<ffffffffb4afb23c>] slab_post_alloc_hook+0x8c/0x3e0
    [<ffffffffb4b02b19>] __kmem_cache_alloc_node+0x1d9/0x2a0
    [<ffffffffb4a77785>] __kmalloc+0x55/0x160
    [<ffffffffb493a913>] tracing_log_err+0x1a3/0x1d0
    [<ffffffffb4959049>] append_filter_err.isra.13+0x119/0x190
    [<ffffffffb495a89f>] create_filter+0xbf/0xe0
    [<ffffffffb495ab10>] create_event_filter+0x10/0x20
    [<ffffffffb495c040>] set_trigger_filter+0xa0/0x180
    [<ffffffffb495d745>] event_trigger_parse+0xf5/0x160
    [<ffffffffb495c889>] trigger_process_regex+0xc9/0x120
    [<ffffffffb495c976>] event_trigger_write+0x86/0xf0
    [<ffffffffb4b52dc2>] vfs_write+0xf2/0x520
    [<ffffffffb4b533d8>] ksys_write+0x68/0xe0
    [<ffffffffb4b5347e>] __x64_sys_write+0x1e/0x30
    [<ffffffffb586619c>] do_syscall_64+0x5c/0x90
    [<ffffffffb5a000ae>] entry_SYSCALL_64_after_hwframe+0x72/0xdc

Please find the complete debug info at the URL:

https://domac.alu.unizg.hr/~mtodorov/linux/bugreports/ftracetest/

Bisect log is [edited]:

> git bisect good a92ce570c81dc0feaeb12a429b4bc65686d17967
> # good: [c6f613e5f35b0e2154d5ca12f0e8e0be0c19be9a] ipmi/watchdog: use strscpy() to instead of strncpy()
> git bisect good c6f613e5f35b0e2154d5ca12f0e8e0be0c19be9a
> # good: [90b12f423d3c8a89424c7bdde18e1923dfd0941e] Merge tag 'for-linus-6.2-1' of https://github.com/cminyard/linux-ipmi
> git bisect good 90b12f423d3c8a89424c7bdde18e1923dfd0941e
> # first bad commit: [71946a25f357a51dcce849367501d7fb04c0465b] Merge tag 'mmc-v6.2' of git://git.kernel.org/pub/scm/linux/kernel/git/ulfh/mmc
> 
> The commit was merged on December 13th 2022.

The amount of applied diffs in the culprit commit 71946a25f357a51dcce849367501d7fb04c0465b
prevents me from bisecting further - I do not know which changes depend of which, and which
can be tested independently.

Hopefully I might come up with a reproducer, but I need some feedback first. Maybe there
are ways to narrow down the lines of code that could have caused the leaks, yet I am
completely new to the kernel/trace subtree.

Apologies for not Cc:ing Ulf nine weeks ago, but it was an omission, not deliberate act.

Best regards,
Mirsad

-- 
Mirsad Goran Todorovac
Sistem inženjer
Grafički fakultet | Akademija likovnih umjetnosti
Sveučilište u Zagrebu
 
System engineer
Faculty of Graphic Arts | Academy of Fine Arts
University of Zagreb, Republic of Croatia
The European Union

"I see something approaching fast ... Will it be friends with me?"

Re: [BUG RESEND] [BISECTED]: selftest: ftracetest: memleak in vfs_write()

[Eric Biggers]

Hi Mirsad,

On Tue, Apr 04, 2023 at 09:52:10PM +0200, Mirsad Goran Todorovac wrote:
>   backtrace:
>     [<ffffffffb4afb23c>] slab_post_alloc_hook+0x8c/0x3e0
>     [<ffffffffb4b02b19>] __kmem_cache_alloc_node+0x1d9/0x2a0
>     [<ffffffffb4a77785>] __kmalloc+0x55/0x160
>     [<ffffffffb493a913>] tracing_log_err+0x1a3/0x1d0
>     [<ffffffffb4959049>] append_filter_err.isra.13+0x119/0x190
>     [<ffffffffb495a89f>] create_filter+0xbf/0xe0
>     [<ffffffffb495ab10>] create_event_filter+0x10/0x20
>     [<ffffffffb495c040>] set_trigger_filter+0xa0/0x180
>     [<ffffffffb495d745>] event_trigger_parse+0xf5/0x160
>     [<ffffffffb495c889>] trigger_process_regex+0xc9/0x120
>     [<ffffffffb495c976>] event_trigger_write+0x86/0xf0
>     [<ffffffffb4b52dc2>] vfs_write+0xf2/0x520
>     [<ffffffffb4b533d8>] ksys_write+0x68/0xe0
>     [<ffffffffb4b5347e>] __x64_sys_write+0x1e/0x30
>     [<ffffffffb586619c>] do_syscall_64+0x5c/0x90
>     [<ffffffffb5a000ae>] entry_SYSCALL_64_after_hwframe+0x72/0xdc
> 
> Please find the complete debug info at the URL:
> 
> https://domac.alu.unizg.hr/~mtodorov/linux/bugreports/ftracetest/
> 
> Bisect log is [edited]:
> 
> > git bisect good a92ce570c81dc0feaeb12a429b4bc65686d17967
> > # good: [c6f613e5f35b0e2154d5ca12f0e8e0be0c19be9a] ipmi/watchdog: use strscpy() to instead of strncpy()
> > git bisect good c6f613e5f35b0e2154d5ca12f0e8e0be0c19be9a
> > # good: [90b12f423d3c8a89424c7bdde18e1923dfd0941e] Merge tag 'for-linus-6.2-1' of https://github.com/cminyard/linux-ipmi
> > git bisect good 90b12f423d3c8a89424c7bdde18e1923dfd0941e
> > # first bad commit: [71946a25f357a51dcce849367501d7fb04c0465b] Merge tag 'mmc-v6.2' of git://git.kernel.org/pub/scm/linux/kernel/git/ulfh/mmc
> > 
> > The commit was merged on December 13th 2022.
> 
> The amount of applied diffs in the culprit commit 71946a25f357a51dcce849367501d7fb04c0465b
> prevents me from bisecting further - I do not know which changes depend of which, and which
> can be tested independently.
> 
> Hopefully I might come up with a reproducer, but I need some feedback first. Maybe there
> are ways to narrow down the lines of code that could have caused the leaks, yet I am
> completely new to the kernel/trace subtree.
> 
> Apologies for not Cc:ing Ulf nine weeks ago, but it was an omission, not deliberate act.
> 

This looks like an issue with the tracing subsystem.  I appreciate that you've
now added the tracing maintainers to Cc.  I don't think your bisection to commit
71946a25f357 ("Merge tag 'mmc-v6.2' ...") is correct; that looks unrelated.

- Eric

Re: [BUG RESEND] [BISECTED]: selftest: ftracetest: memleak in vfs_write()

[Steven Rostedt]

On Tue, 4 Apr 2023 15:07:44 -0700
Eric Biggers <ebiggers@kernel.org> wrote:

> This looks like an issue with the tracing subsystem.  I appreciate that you've
> now added the tracing maintainers to Cc.  I don't think your bisection to commit
> 71946a25f357 ("Merge tag 'mmc-v6.2' ...") is correct; that looks unrelated.

No that is not the correct commit. I think I see the issue. The error log
of a tracing instance doesn't seem to be freed if the instance is removed.

I'm guessing this can cause the bug:

 # cd /sys/kernel/tracincg
 # mkdir instances/foo
 # echo 'p:nothing no_function_here' > instances/foo/dynamic_events
 # rmdir instances/foo

I haven't tried the above commands so there may be a syntax error, but I
bet that would cause the issue. Basically, you need to create an instance,
cause a syntax error in creating something (which will add to the error log
list that shows the error), and then delete the instance.

I don't see where it would clean up the error log in that case, and it
would get leaked.

I'll write up a patch to fix this today (after confirming that does indeed
cause a leak).

-- Steve

Re: [BUG RESEND] [BISECTED]: selftest: ftracetest: memleak in vfs_write()

[Steven Rostedt]

On Tue, 4 Apr 2023 18:24:28 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Tue, 4 Apr 2023 15:07:44 -0700
> Eric Biggers <ebiggers@kernel.org> wrote:
> 
> > This looks like an issue with the tracing subsystem.  I appreciate that you've
> > now added the tracing maintainers to Cc.  I don't think your bisection to commit
> > 71946a25f357 ("Merge tag 'mmc-v6.2' ...") is correct; that looks unrelated.  
> 
> No that is not the correct commit. I think I see the issue. The error log
> of a tracing instance doesn't seem to be freed if the instance is removed.
> 
> I'm guessing this can cause the bug:
> 
>  # cd /sys/kernel/tracincg
>  # mkdir instances/foo
>  # echo 'p:nothing no_function_here' > instances/foo/dynamic_events

OK, it required me to touch a trigger as dynamic_events only exists in the
top level (and the bug report shows a filter):

 # echo 'hist:keys=x' > instances/foo/events/sched/sched_switch/trigger

>  # rmdir instances/foo
> 

Anyway, I was able to reproduce the leak. Can you test this patch?

-- Steve

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 8ae51f1dea8e..352a804b016d 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -9516,6 +9516,7 @@ static int __remove_instance(struct trace_array *tr)
 	tracefs_remove(tr->dir);
 	free_percpu(tr->last_func_repeats);
 	free_trace_buffers(tr);
+	clear_tracing_err_log(tr);
 
 	for (i = 0; i < tr->nr_topts; i++) {
 		kfree(tr->topts[i].topts);

Re: [BUG RESEND] [BISECTED]: selftest: ftracetest: memleak in vfs_write()

[Mirsad Goran Todorovac]

On 05. 04. 2023. 00:07, Eric Biggers wrote:
> Hi Mirsad,
> 
> On Tue, Apr 04, 2023 at 09:52:10PM +0200, Mirsad Goran Todorovac wrote:
>>   backtrace:
>>     [<ffffffffb4afb23c>] slab_post_alloc_hook+0x8c/0x3e0
>>     [<ffffffffb4b02b19>] __kmem_cache_alloc_node+0x1d9/0x2a0
>>     [<ffffffffb4a77785>] __kmalloc+0x55/0x160
>>     [<ffffffffb493a913>] tracing_log_err+0x1a3/0x1d0
>>     [<ffffffffb4959049>] append_filter_err.isra.13+0x119/0x190
>>     [<ffffffffb495a89f>] create_filter+0xbf/0xe0
>>     [<ffffffffb495ab10>] create_event_filter+0x10/0x20
>>     [<ffffffffb495c040>] set_trigger_filter+0xa0/0x180
>>     [<ffffffffb495d745>] event_trigger_parse+0xf5/0x160
>>     [<ffffffffb495c889>] trigger_process_regex+0xc9/0x120
>>     [<ffffffffb495c976>] event_trigger_write+0x86/0xf0
>>     [<ffffffffb4b52dc2>] vfs_write+0xf2/0x520
>>     [<ffffffffb4b533d8>] ksys_write+0x68/0xe0
>>     [<ffffffffb4b5347e>] __x64_sys_write+0x1e/0x30
>>     [<ffffffffb586619c>] do_syscall_64+0x5c/0x90
>>     [<ffffffffb5a000ae>] entry_SYSCALL_64_after_hwframe+0x72/0xdc
>>
>> Please find the complete debug info at the URL:
>>
>> https://domac.alu.unizg.hr/~mtodorov/linux/bugreports/ftracetest/
>>
>> Bisect log is [edited]:
>>
>>> git bisect good a92ce570c81dc0feaeb12a429b4bc65686d17967
>>> # good: [c6f613e5f35b0e2154d5ca12f0e8e0be0c19be9a] ipmi/watchdog: use strscpy() to instead of strncpy()
>>> git bisect good c6f613e5f35b0e2154d5ca12f0e8e0be0c19be9a
>>> # good: [90b12f423d3c8a89424c7bdde18e1923dfd0941e] Merge tag 'for-linus-6.2-1' of https://github.com/cminyard/linux-ipmi
>>> git bisect good 90b12f423d3c8a89424c7bdde18e1923dfd0941e
>>> # first bad commit: [71946a25f357a51dcce849367501d7fb04c0465b] Merge tag 'mmc-v6.2' of git://git.kernel.org/pub/scm/linux/kernel/git/ulfh/mmc
>>>
>>> The commit was merged on December 13th 2022.
>>
>> The amount of applied diffs in the culprit commit 71946a25f357a51dcce849367501d7fb04c0465b
>> prevents me from bisecting further - I do not know which changes depend of which, and which
>> can be tested independently.
>>
>> Hopefully I might come up with a reproducer, but I need some feedback first. Maybe there
>> are ways to narrow down the lines of code that could have caused the leaks, yet I am
>> completely new to the kernel/trace subtree.
>>
>> Apologies for not Cc:ing Ulf nine weeks ago, but it was an omission, not deliberate act.
>>
> 
> This looks like an issue with the tracing subsystem.  I appreciate that you've
> now added the tracing maintainers to Cc.  I don't think your bisection to commit
> 71946a25f357 ("Merge tag 'mmc-v6.2' ...") is correct; that looks unrelated.
> 
> - Eric

Hi, Eric,

In the light of Steven's correct fix, you are obviously right, so I will investigate
where the bisect went wrong.

I should have added selftest/ftrace/ftracetest developers already on Jan 27th, and it
would be fixed for 6.2 already :-/

The good news is that I seem to be improving in hunting down the memleaks. Hopefully
I will hunt down a real security exploit?

All the best.

Best regards,
Mirsad

-- 
Mirsad Goran Todorovac
Sistem inženjer
Grafički fakultet | Akademija likovnih umjetnosti
Sveučilište u Zagrebu
 
System engineer
Faculty of Graphic Arts | Academy of Fine Arts
University of Zagreb, Republic of Croatia
The European Union

"I see something approaching fast ... Will it be friends with me?"