Message-ID: <185285b3-9428-5051-5d07-8a49d6ba75c1@alu.unizg.hr>
Date:   Thu, 9 Mar 2023 00:17:40 +0100
From:   Mirsad Goran Todorovac <mirsad.todorovac@....unizg.hr>
To:     Andy Shevchenko <andriy.shevchenko@...el.com>
Cc:     Bartosz Golaszewski <brgl@...ev.pl>, linux-gpio@...r.kernel.org,
        Linus Walleij <linus.walleij@...aro.org>,
        linux-kernel@...r.kernel.org,
        Thorsten Leemhuis <regressions@...mhuis.info>
Subject: Re: INFO: REPRODUCED: memory leak in gpio device in 6.2-rc6

On 08. 03. 2023. 16:20, Andy Shevchenko wrote:
> On Wed, Mar 08, 2023 at 02:11:39PM +0100, Mirsad Todorovac wrote:
>> On 2/28/23 00:13, Andy Shevchenko wrote:
> 
> ...
> 
>>>> The logs are extensive if you are willing to skim over them, but I believe the interesting
>>>> part is this:
>>>
>>> I'm not sure I understand where the problem is.
>>>
>>>> [ 4830.764748] kobject: 'gpio-sim' (000000005b8d0726): kobject_release, parent 000000007425b13f (delayed 750)
>>>> [ 4833.908238] kobject: 'gpio-sim' (000000005b8d0726): kobject_cleanup, parent 000000007425b13f
>>>> [ 4833.908244] kobject: 'gpio-sim' (000000005b8d0726): auto cleanup kobject_del
>>>> [ 4833.908245] kobject: 'gpio-sim' (000000005b8d0726): auto cleanup 'remove' event
>>>> [ 4833.908247] kobject: 'gpio-sim' (000000005b8d0726): kobject_uevent_env
>>>> [ 4833.908273] kobject: 'gpio-sim' (000000005b8d0726): fill_kobj_path: path = '/bus/platform/drivers/gpio-sim'
>>>> [ 4833.908311] kobject: 'gpio-sim' (000000005b8d0726): calling ktype release
>>>> [ 4833.908315] kobject: 'gpio-sim': free name
>>>> [ 4834.932303] kobject: 'gpio_sim' (0000000096ea0bb1): kobject_release, parent 0000000093357d30 (delayed 250)
>>>> [ 4835.952388] kobject: 'gpio_sim' (0000000096ea0bb1): kobject_cleanup, parent 0000000093357d30
>>>> [ 4835.952413] kobject: 'gpio_sim' (0000000096ea0bb1): auto cleanup kobject_del
>>>> [ 4835.952415] kobject: 'gpio_sim' (0000000096ea0bb1): auto cleanup 'remove' event
>>>> [ 4835.952416] kobject: 'gpio_sim' (0000000096ea0bb1): kobject_uevent_env
>>>> [ 4835.952424] kobject: 'gpio_sim' (0000000096ea0bb1): fill_kobj_path: path = '/module/gpio_sim'
>>>> [ 4835.952445] kobject: 'gpio_sim' (0000000096ea0bb1): calling ktype release
>>>> [ 4835.952448] kobject: 'gpio_sim': free name
>>>>
>>>> Or, with CONFIG_DEBUG_DEVRES=y, it looks like this:
>>>
>>> I don't see that been enabled (it requires to pass a command line option to the kernel).
>>
>> I don't think I have found this command line option to LK.
>>
>> So far it seems that the kobject_release() was called for both /bus/platform/drivers/gpio-sim
>> and /module/gpio_sim . Is there soemthing I'm missing?
> 
> Have you read the code in drivers/base/devres.c?
> 
> https://elixir.bootlin.com/linux/v6.3-rc1/source/drivers/base/devres.c#L53

Actually, it was in the manual all the time, but I have missed it somehow:
https://cateee.net/lkddb/web-lkddb/DEBUG_DEVRES.html

Here is the log (DEVRES debug was not in dmesg output, so after rsyslog dies,
there is no output to debug deallocs past that point):

https://domac.alu.hr/~mtodorov/linux/bugreports/gpio/devres_trace.log

Note that last 5 lines occur after `rmmod gpio-sim`:

Mar  8 23:23:55 pc-mtodorov kernel: kobject: 'gpio-sim' (00000000f0ead702): kobject_release, parent 00000000bb6cefbb (delayed 500)
Mar  8 23:23:55 pc-mtodorov kernel: kobject: 'drivers' (000000004fba12b9): kobject_release, parent 000000002c2cc344 (delayed 750)
Mar  8 23:23:55 pc-mtodorov kernel: kobject: 'holders' (00000000bfd7f234): kobject_release, parent 000000002c2cc344 (delayed 750)
Mar  8 23:23:55 pc-mtodorov kernel: kobject: 'notes' (00000000f2d17f82): kobject_release, parent 000000002c2cc344 (delayed 250)
Mar  8 23:23:59 pc-mtodorov kernel: kobject: 'gpio_sim' (000000002c2cc344): kobject_release, parent 00000000061436c2 (delayed 250)

>> However, I've found one relatively unrelated failure to call kobject_release().
>> This happens during shutdown, after the syslog is shutdown, so I can only provide
>> a screenshot as a proof and for diagnostics:
>>
>> https://domac.alu.hr/~mtodorov/linux/bugreports/integrity/20230308_123748.jpg
>>
>> https://domac.alu.hr/~mtodorov/linux/bugreports/integrity/20230308_123752.jpg
>>
>> I failed to locate the driver and responsible maintainers to the present moment.
>> It is happening on shutdown and it isn't that critical IMHO, except if it shows
>> some other problem in the code :-/
> 
> Congrats, you found a real issue somewhere.  `git grep` usually helps
> with this, like `git grep -n -w '"integrity"'` shows a few files, most
> likely security/integrity/iint.c is the culprit.

Looking more closely, this seems to be suspicious:

DEFINE_LSM(integrity) = {
	.name = "integrity",
	.init = integrity_iintcache_init,
};

.release member is missing.

However, struct lsm_info doesn't have the "release" member, so I wonder
what called release() in the first place?

https://elixir.bootlin.com/linux/v6.3-rc1/source/include/linux/lsm_hooks.h#L1733

struct lsm_info {
	const char *name;	/* Required. */
	enum lsm_order order;	/* Optional: default is LSM_ORDER_MUTABLE */
	unsigned long flags;	/* Optional: flags describing LSM */
	int *enabled;		/* Optional: controlled by CONFIG_LSM */
	int (*init)(void);	/* Required. */
	struct lsm_blob_sizes *blobs; /* Optional: for blob sharing. */
};

extern struct lsm_info __start_lsm_info[], __end_lsm_info[];
extern struct lsm_info __start_early_lsm_info[], __end_early_lsm_info[];

#define DEFINE_LSM(lsm)							\
	static struct lsm_info __lsm_##lsm				\
		__used __section(".lsm_info.init")			\
		__aligned(sizeof(unsigned long))

But maybe the object is just deallocated and doesn't need kobject cleanup?
Actually it allocated "iint_cache".

Just a thought - if lsm_info had a release() member, it would be simple to
fix this:

 static int __init integrity_iintcache_init(void)
 { 
 	iint_cache =
 	    kmem_cache_create("iint_cache", sizeof(struct integrity_iint_cache),
 			      0, SLAB_PANIC, init_once);
 	return 0;
 }
 
+static void integrity_iintcache_destroy(void)
+{
+	kmem_cache_destroy(iint_cache);
+}

 DEFINE_LSM(integrity) = {
	.name = "integrity",
 	.init = integrity_iintcache_init,
+	.release = integrity_iintcache_destroy,
 };

However, modifying include/linux/lsm_hooks.h is not for the faint of the heart,
I suppose.

But it seems too simple (too good to be true) that they just forgot to destroy
cache, maybe something is still alive when module is unloaded?

I still can't figure out what calls release() for "integrity" and where is the 
"integrity" kobject allocated?

>>>>>>>>> Or maybe the chip->gc.parent should be changed to something else (actual GPIO
>>>>>>>>> device, but then it's unclear how to provide the attributes in non-racy way
>>>>>>>> Really, dunno. I have to repeat that my learning curve cannot adapt so quickly.
>>>>>>>>
>>>>>>>> I merely gave the report of KMEMLEAK, otherwise I am not a Linux kernel
>>>>>>>> device expert nor would be appropriate to try the craft not earned ;-)
>>>>
>>>> With all of these additional debugging, cat /sys/kernel/debug/kmemleak
>>>> showed nothing new.
>>>>
>>>> I believe this is reasonably safe.
>>>>
>>>> However, I was unsuccessful in seeing gpio trace, even with
>>>> echo 1 > /sys/kernel/tracing/events/gpio/enable ... :-/
>>>
>>> It's available in the trace buffer (you need to read a documentation to
>>> understand how it works).
>>
>> Still working on that, had other tasks to do ... So far I got to this:
>>
>>  1020  echo "1" > /sys/kernel/tracing/events/gpio/enable
>>  1021  more /sys/kernel/tracing/trace
>>  1022  cd ~marvin/linux/kernel/linux_torvalds/tools/testing/selftests/gpio/
>>  1023  ls
>>  1024  ./gpio-sim.sh
>>  1025  more /sys/kernel/tracing/trace
>> # tracer: nop
>> #
>> # entries-in-buffer/entries-written: 9/9   #P:6
>> #
>> #                                _-----=> irqs-off/BH-disabled
>> #                               / _----=> need-resched
>> #                              | / _---=> hardirq/softirq
>> #                              || / _--=> preempt-depth
>> #                              ||| / _-=> migrate-disable
>> #                              |||| /     delay
>> #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
>> #              | |         |   |||||     |         |
>>      gpio-sim.sh-21157   [000] .....  2705.538025: gpio_direction: 560  in (0)
>>  gpio-mockup-cde-21471   [000] .....  2705.579730: gpio_direction: 564  in (0)
>>  gpio-mockup-cde-21471   [000] .....  2705.579745: gpio_value: 564 get 1
>>  gpio-mockup-cde-21478   [003] .....  2705.589475: gpio_direction: 565  in (0)
>>  gpio-mockup-cde-21478   [003] .....  2705.589488: gpio_value: 565 get 0
>>  gpio-mockup-cde-21561   [003] .....  2705.721427: gpio_value: 589 set 1
>>  gpio-mockup-cde-21561   [003] .....  2705.721427: gpio_direction: 589 out (0)
>>  gpio-mockup-cde-21595   [000] .....  2705.855861: gpio_direction: 597  in (0)
>>  gpio-mockup-cde-21595   [000] .....  2705.855875: gpio_value: 597 get 1
> 
>> I hope I did this right. However, I have to play a bit with these results before
>> I could make any interpretation.
> 
> Yes. Just be sure you have all data dumped.

The trace from this run is:

[root@...mtodorov gpio]# more /sys/kernel/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 18/18   #P:6
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
     gpio-sim.sh-4199    [004] .....  1271.367102: gpio_direction: 560  in (0)
 gpio-mockup-cde-4514    [004] .....  1271.406523: gpio_direction: 564  in (0)
 gpio-mockup-cde-4514    [004] .....  1271.406537: gpio_value: 564 get 1
 gpio-mockup-cde-4521    [004] .....  1271.416032: gpio_direction: 565  in (0)
 gpio-mockup-cde-4521    [004] .....  1271.416045: gpio_value: 565 get 0
 gpio-mockup-cde-4601    [000] .....  1271.537872: gpio_value: 589 set 1
 gpio-mockup-cde-4601    [000] .....  1271.537873: gpio_direction: 589 out (0)
 gpio-mockup-cde-4626    [002] .....  1271.669199: gpio_direction: 597  in (0)
 gpio-mockup-cde-4626    [002] .....  1271.669212: gpio_value: 597 get 1
     gpio-sim.sh-4742    [001] .....  1472.168366: gpio_direction: 560  in (0)
 gpio-mockup-cde-5055    [003] .....  1472.207338: gpio_direction: 564  in (0)
 gpio-mockup-cde-5055    [003] .....  1472.207351: gpio_value: 564 get 1
 gpio-mockup-cde-5062    [003] .....  1472.216635: gpio_direction: 565  in (0)
 gpio-mockup-cde-5062    [003] .....  1472.216646: gpio_value: 565 get 0
 gpio-mockup-cde-5142    [002] .....  1472.338589: gpio_value: 589 set 1
 gpio-mockup-cde-5142    [002] .....  1472.338589: gpio_direction: 589 out (0)
 gpio-mockup-cde-5167    [000] .....  1472.469917: gpio_direction: 597  in (0)
 gpio-mockup-cde-5167    [000] .....  1472.469934: gpio_value: 597 get 1
[root@...mtodorov gpio]# 

>> I just wanted to provide some feedback.
> 
> Thanks.

Not at all, I am really having a great time while assisting your team. :-)

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

Powered by blists - more mailing lists