Freeing active kobject in pps_device_destruct

Freeing active kobject in pps_device_destruct

[Sasha Levin]

Hi,

Fuzzing with syzkaller on the latest -next kernel produced this error:

[ 1167.390182] WARNING: CPU: 14 PID: 607 at lib/debugobjects.c:263 debug_print_object+0x1c4/0x1e0()
(active state 0) object type: timer_list hint: delayed_work_timer_fn+0x0/0x90
[ 1167.392644] Modules linked in:
[ 1167.393120] CPU: 14 PID: 607 Comm: kworker/14:1 Tainted: G        W       4.4.0-rc2-next-20151126 sasha-00005-g00d303e-dirty #2651
[ 1167.394563] Workqueue: events kobject_delayed_cleanup
[ 1167.395226]  000000000000000e 000000006f32b107 ffff8806b83478b8 fffffffface6b5bb
[ 1167.396254]  ffff8806b8347928 ffff8806b7b80000 ffffffffb515c7a0 ffff8806b83478f8
[ 1167.397403]  ffffffffab3531d3 ffffffffaced0194 ffffed00d7068f21 ffffffffb515c7a0
[ 1167.398499] Call Trace:
[ 1167.398891]  [<fffffffface6b5bb>] dump_stack+0x72/0xb7
[ 1167.399516]  [<ffffffffab3531d3>] warn_slowpath_common+0x113/0x140
[ 1167.401705]  [<ffffffffab3532cb>] warn_slowpath_fmt+0xcb/0x100
[ 1167.404799]  [<ffffffffaced0194>] debug_print_object+0x1c4/0x1e0
[ 1167.406723]  [<ffffffffaced1035>] __debug_check_no_obj_freed+0x215/0x7a0
[ 1167.409634]  [<ffffffffaced2b6c>] debug_check_no_obj_freed+0x2c/0x40
[ 1167.410301]  [<ffffffffab7aac4c>] kfree+0x1fc/0x2f0
[ 1167.410734]  [<ffffffffb1f7a447>] pps_device_destruct+0x107/0x110
[ 1167.413495]  [<fffffffface715ad>] kobject_delayed_cleanup+0x34d/0x3b0
[ 1167.414049]  [<ffffffffab39fa37>] process_one_work+0xab7/0x13b0
[ 1167.417188]  [<ffffffffab3a0c6d>] worker_thread+0x93d/0xd20
[ 1167.418782]  [<ffffffffab3b34a0>] kthread+0x290/0x2b0
[ 1167.422467]  [<ffffffffb4a1290f>] ret_from_fork+0x3f/0x70


Thanks,
Sasha

Re: Freeing active kobject in pps_device_destruct

[Vegard Nossum]

On 27 November 2015 at 05:30, Sasha Levin <sasha.levin@oracle.com> wrote:
> Hi,
>
> Fuzzing with syzkaller on the latest -next kernel produced this error:
>
> [ 1167.390182] WARNING: CPU: 14 PID: 607 at lib/debugobjects.c:263 debug_print_object+0x1c4/0x1e0()
> (active state 0) object type: timer_list hint: delayed_work_timer_fn+0x0/0x90
> [ 1167.392644] Modules linked in:
> [ 1167.393120] CPU: 14 PID: 607 Comm: kworker/14:1 Tainted: G        W       4.4.0-rc2-next-20151126 sasha-00005-g00d303e-dirty #2651
> [ 1167.394563] Workqueue: events kobject_delayed_cleanup
> [ 1167.395226]  000000000000000e 000000006f32b107 ffff8806b83478b8 fffffffface6b5bb
> [ 1167.396254]  ffff8806b8347928 ffff8806b7b80000 ffffffffb515c7a0 ffff8806b83478f8
> [ 1167.397403]  ffffffffab3531d3 ffffffffaced0194 ffffed00d7068f21 ffffffffb515c7a0
> [ 1167.398499] Call Trace:
> [ 1167.398891]  [<fffffffface6b5bb>] dump_stack+0x72/0xb7
> [ 1167.399516]  [<ffffffffab3531d3>] warn_slowpath_common+0x113/0x140
> [ 1167.401705]  [<ffffffffab3532cb>] warn_slowpath_fmt+0xcb/0x100
> [ 1167.404799]  [<ffffffffaced0194>] debug_print_object+0x1c4/0x1e0
> [ 1167.406723]  [<ffffffffaced1035>] __debug_check_no_obj_freed+0x215/0x7a0
> [ 1167.409634]  [<ffffffffaced2b6c>] debug_check_no_obj_freed+0x2c/0x40
> [ 1167.410301]  [<ffffffffab7aac4c>] kfree+0x1fc/0x2f0
> [ 1167.410734]  [<ffffffffb1f7a447>] pps_device_destruct+0x107/0x110
> [ 1167.413495]  [<fffffffface715ad>] kobject_delayed_cleanup+0x34d/0x3b0
> [ 1167.414049]  [<ffffffffab39fa37>] process_one_work+0xab7/0x13b0
> [ 1167.417188]  [<ffffffffab3a0c6d>] worker_thread+0x93d/0xd20
> [ 1167.418782]  [<ffffffffab3b34a0>] kthread+0x290/0x2b0
> [ 1167.422467]  [<ffffffffb4a1290f>] ret_from_fork+0x3f/0x70

Reviving this thread as I got something very close to that on latest
linus/master during boot:

EXT4-fs (dm-1): mounted filesystem with ordered data mode. Opts: (null)
kobject: 'dm-0' (ffff8801ce7c37d0): kobject_release, parent
(null) (delayed 250)
kobject: 'queue' (ffff8801cf29be48): kobject_release, parent
(null) (delayed 500)
------------[ cut here ]------------
WARNING: CPU: 2 PID: 107 at lib/debugobjects.c:263 debug_print_object+0xe4/0x100
ODEBUG: free active (active state 0) object type: timer_list hint:
delayed_work_timer_fn+0x0/0x50
Modules linked in: btrfs xor raid6_pq dm_crypt dm_multipath mmc_block
crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel
aes_x86_64 lrw gf128mul glue_helper ablk_helper i915 cryptd i2c_alg
scopyarea sysfillrect ahci sysimgblt fb_sys_fops e1000e sdhci_pci
libahci ptp sdhci drm pps_core wmi video jitterentropy_rng drbg
ansi_cprng
CPU: 2 PID: 107 Comm: kworker/2:2 Tainted: G        W       4.7.0-rc4+ #411
Hardware name: LENOVO 2349E48/2349E48, BIOS G1ET41WW (1.16 ) 05/25/2012
Workqueue: events kobject_delayed_cleanup
ffffffff816a6ed4 ffff8800356cf940 ffffffff81672645 ffff8800356cf9b8
0000000000000000 ffff8800356cf988 ffffffff810c46b1 ffff8800356c4000
0000010782369da1 ffffed0006ad9f33 0000000000000000 ffffffff81e8e660
Call Trace:
[<ffffffff81672645>] dump_stack+0x82/0xbd
[<ffffffff810c46b1>] __warn+0x111/0x130
[<ffffffff810c4767>] warn_slowpath_fmt+0x97/0xb0
[<ffffffff816a6ed4>] debug_print_object+0xe4/0x100
[<ffffffff816a87c1>] debug_check_no_obj_freed+0x3d1/0x430
[<ffffffff8132c563>] kfree+0x103/0x2f0
[<ffffffff8163af91>] disk_release+0x141/0x180
[<ffffffff818bcc5a>] device_release+0x4a/0x100
[<ffffffff816763ac>] kobject_delayed_cleanup+0x6c/0xb0
[<ffffffff810f698d>] process_one_work+0x46d/0xa60
[<ffffffff810f700b>] worker_thread+0x8b/0x730
[<ffffffff81100fe2>] kthread+0x192/0x1b0
[<ffffffff81d6240f>] ret_from_fork+0x1f/0x40
---[ end trace f15c6ecaa58bd794 ]---
Adding 8105980k swap on /dev/mapper/ubuntu-swap_1.  Priority:-1
extents:1 across:8105980k SSFS
EXT4-fs (dm-1): re-mounted. Opts: errors=remount-ro

As far as I can tell, it seems like a general problem with
kobject_delayed_cleanup() OR delayed work handling. debugobjects is
complaining about the timer used to delay the work is still "active"
(not as in hasn't fired but as in not destroyed) when disk_release()
does the kfree on the struct gendisk (the timer is
gendisk::part0::__dev::kobj::release::timer -- yes, quite a path!).

Are we missing a del_timer() somewhere in kernel/workqueue.c for
delayed work handling (e.g. process_one_work())?

Adding some more timer/workqueue/debug objects people on Cc.


Vegard

Re: Freeing active kobject in pps_device_destruct

[Thomas Gleixner]

On Sat, 25 Jun 2016, Vegard Nossum wrote:
> On 27 November 2015 at 05:30, Sasha Levin <sasha.levin@oracle.com> wrote:

> > (active state 0) object type: timer_list hint: delayed_work_timer_fn+0x0/0x90

> > [ 1167.394563] Workqueue: events kobject_delayed_cleanup

> > [ 1167.410301]  [<ffffffffab7aac4c>] kfree+0x1fc/0x2f0
> > [ 1167.410734]  [<ffffffffb1f7a447>] pps_device_destruct+0x107/0x110
> > [ 1167.413495]  [<fffffffface715ad>] kobject_delayed_cleanup+0x34d/0x3b0
> > [ 1167.414049]  [<ffffffffab39fa37>] process_one_work+0xab7/0x13b0
> > [ 1167.417188]  [<ffffffffab3a0c6d>] worker_thread+0x93d/0xd20
> > [ 1167.418782]  [<ffffffffab3b34a0>] kthread+0x290/0x2b0
> > [ 1167.422467]  [<ffffffffb4a1290f>] ret_from_fork+0x3f/0x70

> ODEBUG: free active (active state 0) object type: timer_list hint:
> delayed_work_timer_fn+0x0/0x50

> [<ffffffff8132c563>] kfree+0x103/0x2f0
> [<ffffffff8163af91>] disk_release+0x141/0x180
> [<ffffffff818bcc5a>] device_release+0x4a/0x100
> [<ffffffff816763ac>] kobject_delayed_cleanup+0x6c/0xb0
> [<ffffffff810f698d>] process_one_work+0x46d/0xa60
> [<ffffffff810f700b>] worker_thread+0x8b/0x730
> [<ffffffff81100fe2>] kthread+0x192/0x1b0
> [<ffffffff81d6240f>] ret_from_fork+0x1f/0x40

> As far as I can tell, it seems like a general problem with
> kobject_delayed_cleanup() OR delayed work handling. debugobjects is
> complaining about the timer used to delay the work is still "active"
> (not as in hasn't fired but as in not destroyed) when disk_release()

State active means: The timer is queued and has not yet fired.

Which is completely confusing because the delayed work will only be processed
after the timer has fired. And when the timer fires it is deactivated in debug
objects before the callback function is invoked.

So it's really puzzling why the debug objects state of the timer would be
ODEBUG_STATE_ACTIVE, which is the only way that the debug objects free check
can trigger.

Confused!

	tglx