kernfs/rtc: circular dependency between kernfs and ops_lock

kernfs/rtc: circular dependency between kernfs and ops_lock

[Sasha Levin]

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel I've stumbled on 
the following (now with pretty line numbers!) spew:

[  218.132898] ======================================================
[  218.133902] [ INFO: possible circular locking dependency detected ]
[  218.134820] 3.14.0-rc3-next-20140221-sasha-00008-g0e660cf-dirty #116 Tainted: G        W
[  218.135911] -------------------------------------------------------
[  218.136842] trinity-c47/11528 is trying to acquire lock:
[  218.137613]  (&rtc->ops_lock){+.+.+.}, at: [<drivers/rtc/interface.c:42>] rtc_read_time+0x2b/0x60
[  218.138909]
[  218.138909] but task is already holding lock:
[  218.139802]  (s_active#20){++++.+}, at: [<fs/kernfs/file.c:99>] kernfs_seq_start+0x34/0xa0
[  218.140087]
[  218.140087] which lock already depends on the new lock.
[  218.140087]
[  218.140087]
[  218.140087] the existing dependency chain (in reverse order) is:
[  218.140087]
-> #1 (s_active#20){++++.+}:
[  218.140087]        [<kernel/locking/lockdep.c:1945 kernel/locking/lockdep.c:2131>] 
validate_chain+0x6ca/0x7c0
[  218.140087]        [<kernel/locking/lockdep.c:3182>] __lock_acquire+0x4ad/0x580
[  218.140087]        [<arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3602>] 
lock_acquire+0x182/0x1d0
[  218.140087]        [<arch/x86/include/asm/atomic.h:26 fs/kernfs/dir.c:349>] kernfs_drain+0xb8/0x180
[  218.140087]        [<fs/kernfs/dir.c:1031>] __kernfs_remove+0x10b/0x1d0
[  218.140087]        [<fs/kernfs/dir.c:1226>] kernfs_remove_by_name_ns+0x79/0xb0
[  218.140087]        [<fs/sysfs/group.c:28>] remove_files+0x31/0x70
[  218.140087]        [<fs/sysfs/group.c:228>] sysfs_remove_group+0x7e/0xb0
[  218.140087]        [<fs/sysfs/group.c:250>] sysfs_remove_groups+0x32/0x50
[  218.140087]        [<drivers/base/core.c:524>] device_remove_attrs+0x6d/0x90
[  218.140087]        [<drivers/base/core.c:1206>] device_del+0x135/0x1c0
[  218.140087]        [<drivers/base/core.c:1237>] device_unregister+0x50/0x60
[  218.140087]        [<drivers/rtc/class.c:273>] rtc_device_unregister+0x4f/0x80
[  218.140087]        [<include/linux/ioport.h:166 drivers/rtc/rtc-cmos.c:805>] 
cmos_do_probe+0x3b0/0x3f0
[  218.157097]        [<drivers/rtc/rtc-cmos.c:1153>] cmos_platform_probe+0x46/0x4e
[  218.157097]        [<drivers/base/platform.c:487>] platform_drv_probe+0x36/0x90
[  218.157097]        [<drivers/base/dd.c:292>] really_probe+0x11f/0x2f0
[  218.157097]        [<include/linux/pm_runtime.h:189 drivers/base/dd.c:383>] 
driver_probe_device+0x83/0xb0
[  218.157097]        [<drivers/base/dd.c:460>] __driver_attach+0x69/0xa0
[  218.157097]        [<drivers/base/bus.c:311>] bus_for_each_dev+0x66/0xc0
[  218.157097]        [<drivers/base/dd.c:480>] driver_attach+0x19/0x20
[  218.157097]        [<drivers/base/bus.c:692>] bus_add_driver+0x116/0x240
[  218.157097]        [<drivers/base/driver.c:167>] driver_register+0xa8/0xf0
[  218.157097]        [<drivers/base/platform.c:542>] __platform_driver_register+0x45/0x50
[  218.157097]        [<drivers/base/platform.c:590>] platform_driver_probe+0x1f/0xc0
[  218.157097]        [<drivers/rtc/rtc-cmos.c:1200>] cmos_init+0x3f/0x77
[  218.157097]        [<init/main.c:696>] do_one_initcall+0xc2/0x1e0
[  218.157097]        [<init/main.c:761 init/main.c:770 init/main.c:789>] do_basic_setup+0x9c/0xbf
[  218.157097]        [<init/main.c:913>] kernel_init_freeable+0x2d1/0x354
[  218.157097]        [<init/main.c:842>] kernel_init+0x9/0xf0
[  218.157097]        [<arch/x86/kernel/entry_64.S:555>] ret_from_fork+0x7c/0xb0
[  218.157097]
-> #0 (&rtc->ops_lock){+.+.+.}:
[  218.157097]        [<kernel/locking/lockdep.c:1840>] check_prev_add+0x13f/0x560
[  218.157097]        [<kernel/locking/lockdep.c:1945 kernel/locking/lockdep.c:2131>] 
validate_chain+0x6ca/0x7c0
[  218.157097]        [<kernel/locking/lockdep.c:3182>] __lock_acquire+0x4ad/0x580
[  218.157097]        [<arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3602>] 
lock_acquire+0x182/0x1d0
[  218.157097]        [<kernel/locking/mutex.c:470 kernel/locking/mutex.c:600>] 
mutex_lock_interruptible_nested+0x6a/0x600
[  218.157097]        [<drivers/rtc/interface.c:42>] rtc_read_time+0x2b/0x60
[  218.157097]        [<drivers/rtc/rtc-sysfs.c:56>] time_show+0x15/0x40
[  218.157097]        [<drivers/base/core.c:122>] dev_attr_show+0x22/0x50
[  218.157097]        [<fs/sysfs/file.c:62>] sysfs_kf_seq_show+0xa8/0x130
[  218.157097]        [<fs/kernfs/file.c:155>] kernfs_seq_show+0x21/0x30
[  218.157097]        [<fs/seq_file.c:109>] traverse+0xd8/0x1f0
[  218.157097]        [<fs/seq_file.c:179>] seq_read+0x5c/0x430
[  218.157097]        [<fs/kernfs/file.c:230>] kernfs_fop_read+0x24/0x40
[  218.157097]        [<fs/read_write.c:396>] vfs_read+0xb4/0x180
[  218.157097]        [<include/linux/file.h:36 fs/read_write.c:545 fs/read_write.c:532>] 
SyS_pread64+0x67/0x90
[  218.157097]        [<arch/x86/kernel/entry_64.S:749>] tracesys+0xdd/0xe2
[  218.157097]
[  218.157097] other info that might help us debug this:
[  218.157097]
[  218.157097]  Possible unsafe locking scenario:
[  218.157097]
[  218.157097]        CPU0                    CPU1
[  218.157097]        ----                    ----
[  218.157097]   lock(s_active#20);
[  218.157097]                                lock(&rtc->ops_lock);
[  218.157097]                                lock(s_active#20);
[  218.157097]   lock(&rtc->ops_lock);
[  218.157097]
[  218.157097]  *** DEADLOCK ***
[  218.157097]
[  218.157097] 3 locks held by trinity-c47/11528:
[  218.157097]  #0:  (&p->lock){+.+.+.}, at: [<fs/seq_file.c:175>] seq_read+0x3a/0x430
[  218.157097]  #1:  (&of->mutex){+.+.+.}, at: [<fs/kernfs/file.c:99>] kernfs_seq_start+0x2c/0xa0
[  218.157097]  #2:  (s_active#20){++++.+}, at: [<fs/kernfs/file.c:99>] kernfs_seq_start+0x34/0xa0
[  218.157097]
[  218.157097] stack backtrace:
[  218.157097] CPU: 8 PID: 11528 Comm: trinity-c47 Tainted: G        W 
3.14.0-rc3-next-20140221-sasha-00008-g0e660cf-dirty #116
[  218.157097]  0000000000000000 ffff8806a74dba18 ffffffff843894c8 0000000000000000
[  218.157097]  0000000000000000 ffff8806a74dba68 ffffffff811a0379 ffff8806a74dba88
[  218.157097]  ffff8806a74dba88 ffff8806a74dba68 ffff8806a96d0d38 ffff8806a96d0d70
[  218.157097] Call Trace:
[  218.157097]  [<lib/dump_stack.c:52>] dump_stack+0x52/0x7f
[  218.157097]  [<kernel/locking/lockdep.c:1213>] print_circular_bug+0x129/0x160
[  218.157097]  [<kernel/locking/lockdep.c:1840>] check_prev_add+0x13f/0x560
[  218.157097]  [<arch/x86/include/asm/paravirt.h:192 arch/x86/kernel/tsc.c:305>] ? 
sched_clock+0x1d/0x30
[  218.157097]  [<kernel/locking/lockdep.c:1945 kernel/locking/lockdep.c:2131>] 
validate_chain+0x6ca/0x7c0
[  218.157097]  [<kernel/locking/lockdep.c:3182>] __lock_acquire+0x4ad/0x580
[  218.157097]  [<arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3602>] 
lock_acquire+0x182/0x1d0
[  218.157097]  [<drivers/rtc/interface.c:42>] ? rtc_read_time+0x2b/0x60
[  218.157097]  [<kernel/locking/mutex.c:470 kernel/locking/mutex.c:600>] 
mutex_lock_interruptible_nested+0x6a/0x600
[  218.157097]  [<drivers/rtc/interface.c:42>] ? rtc_read_time+0x2b/0x60
[  218.157097]  [<kernel/locking/lockdep.c:3189>] ? __lock_acquire+0x4cd/0x580
[  218.157097]  [<drivers/rtc/interface.c:42>] ? rtc_read_time+0x2b/0x60
[  218.157097]  [<drivers/rtc/interface.c:42>] rtc_read_time+0x2b/0x60
[  218.157097]  [<drivers/rtc/rtc-sysfs.c:56>] time_show+0x15/0x40
[  218.157097]  [<drivers/base/core.c:122>] dev_attr_show+0x22/0x50
[  218.157097]  [<fs/sysfs/file.c:33>] ? sysfs_file_ops+0x30/0x60
[  218.157097]  [<fs/sysfs/file.c:62>] sysfs_kf_seq_show+0xa8/0x130
[  218.157097]  [<fs/kernfs/file.c:155>] kernfs_seq_show+0x21/0x30
[  218.157097]  [<fs/seq_file.c:109>] traverse+0xd8/0x1f0
[  218.157097]  [<fs/seq_file.c:179>] seq_read+0x5c/0x430
[  218.157097]  [<security/security.c:677>] ? security_file_permission+0x85/0x90
[  218.157097]  [<fs/kernfs/file.c:230>] kernfs_fop_read+0x24/0x40
[  218.157097]  [<fs/read_write.c:396>] vfs_read+0xb4/0x180
[  218.157097]  [<include/linux/file.h:36 fs/read_write.c:545 fs/read_write.c:532>] 
SyS_pread64+0x67/0x90
[  218.157097]  [<arch/x86/kernel/entry_64.S:749>] tracesys+0xdd/0xe2


Thanks,
Sasha

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Tejun Heo]

Hello,

On Sat, Feb 22, 2014 at 12:51:42PM -0500, Sasha Levin wrote:
> While fuzzing with trinity inside a KVM tools guest running the
> latest -next kernel I've stumbled on the following (now with pretty
> line numbers!) spew:

Heh, that's pretty awesome.

> [  218.132898] ======================================================
> [  218.133902] [ INFO: possible circular locking dependency detected ]
> [  218.134820] 3.14.0-rc3-next-20140221-sasha-00008-g0e660cf-dirty #116 Tainted: G        W
> [  218.135911] -------------------------------------------------------
> [  218.136842] trinity-c47/11528 is trying to acquire lock:
> [  218.137613]  (&rtc->ops_lock){+.+.+.}, at: [<drivers/rtc/interface.c:42>] rtc_read_time+0x2b/0x60
> [  218.138909]
> [  218.138909] but task is already holding lock:
> [  218.139802]  (s_active#20){++++.+}, at: [<fs/kernfs/file.c:99>] kernfs_seq_start+0x34/0xa0
> [  218.140087]
> [  218.140087] which lock already depends on the new lock.

The problem is rtc_device_unregister().  It grabs rtc->ops_lock and
then tries to remove the sysfs files.  Some of those sysfs file
implementations acquire rtc->ops_lock, so it of course can lead to
deadlocks.  One can't try to delete a sysfs file which acquires a lock
while holding the same lock.

Thanks.

-- 
tejun

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Alessandro Zummo]

On Sat, 22 Feb 2014 15:52:17 -0500
Tejun Heo <tj@kernel.org> wrote:

> The problem is rtc_device_unregister().  It grabs rtc->ops_lock and
> then tries to remove the sysfs files.  Some of those sysfs file
> implementations acquire rtc->ops_lock, so it of course can lead to
> deadlocks.  One can't try to delete a sysfs file which acquires a lock
> while holding the same lock.

 Pretty interesting indeed. One option would be to remove
 the sys files before acquiring the lock. But I wonder
 if this could lead to other issues.

-- 

 Best regards,

 Alessandro Zummo,
  Tower Technologies - Torino, Italy

  http://www.towertech.it

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Sasha Levin]

On 02/24/2014 06:04 AM, Alessandro Zummo wrote:
> On Sat, 22 Feb 2014 15:52:17 -0500
> Tejun Heo <tj@kernel.org> wrote:
>
>> The problem is rtc_device_unregister().  It grabs rtc->ops_lock and
>> then tries to remove the sysfs files.  Some of those sysfs file
>> implementations acquire rtc->ops_lock, so it of course can lead to
>> deadlocks.  One can't try to delete a sysfs file which acquires a lock
>> while holding the same lock.
>
>   Pretty interesting indeed. One option would be to remove
>   the sys files before acquiring the lock. But I wonder
>   if this could lead to other issues.
>

Ping? Seems this thing got lost.


Thanks,
Sasha

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Alessandro Zummo]

On Tue, 25 Mar 2014 17:52:30 -0400
Sasha Levin <sasha.levin@oracle.com> wrote:

> >
> >   Pretty interesting indeed. One option would be to remove
> >   the sys files before acquiring the lock. But I wonder
> >   if this could lead to other issues.
> >  
> 
> Ping? Seems this thing got lost.

 What if we move

   rtc_sysfs_del_device(rtc);

 before acquiring the lock?

diff --git a/drivers/rtc/class.c b/drivers/rtc/class.c
index 589351e..a0c19a3 100644
--- a/drivers/rtc/class.c
+++ b/drivers/rtc/class.c
@@ -261,11 +261,13 @@ EXPORT_SYMBOL_GPL(rtc_device_register);
 void rtc_device_unregister(struct rtc_device *rtc)
 {
        if (get_device(&rtc->dev) != NULL) {
+
+               rtc_sysfs_del_device(rtc);
+
                mutex_lock(&rtc->ops_lock);
                /* remove innards of this RTC, then disable it, before
                 * letting any rtc_class_open() users access it again
                 */
-               rtc_sysfs_del_device(rtc);
                rtc_dev_del_device(rtc);
                rtc_proc_del_device(rtc);
                device_unregister(&rtc->dev);


-- 

 Best regards,

 Alessandro Zummo,
  Tower Technologies - Torino, Italy

  http://www.towertech.it

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Sasha Levin]

On 03/25/2014 06:39 PM, Alessandro Zummo wrote:
> On Tue, 25 Mar 2014 17:52:30 -0400
> Sasha Levin <sasha.levin@oracle.com> wrote:
>
>>>
>>>    Pretty interesting indeed. One option would be to remove
>>>    the sys files before acquiring the lock. But I wonder
>>>    if this could lead to other issues.
>>>
>>
>> Ping? Seems this thing got lost.
>
>   What if we move
>
>     rtc_sysfs_del_device(rtc);
>
>   before acquiring the lock?

Trying it now, I'll leave it going for a week and see if it reproduces.


Thanks,
Sasha

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Sasha Levin]

On 03/25/2014 08:19 PM, Sasha Levin wrote:
> On 03/25/2014 06:39 PM, Alessandro Zummo wrote:
>> On Tue, 25 Mar 2014 17:52:30 -0400
>> Sasha Levin <sasha.levin@oracle.com> wrote:
>>
>>>>
>>>>    Pretty interesting indeed. One option would be to remove
>>>>    the sys files before acquiring the lock. But I wonder
>>>>    if this could lead to other issues.
>>>>
>>>
>>> Ping? Seems this thing got lost.
>>
>>   What if we move
>>
>>     rtc_sysfs_del_device(rtc);
>>
>>   before acquiring the lock?
>
> Trying it now, I'll leave it going for a week and see if it reproduces.

Look good, thanks!


Thanks,
Sasha

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Sasha Levin]

On 03/29/2014 08:28 PM, Sasha Levin wrote:
> On 03/25/2014 08:19 PM, Sasha Levin wrote:
>> On 03/25/2014 06:39 PM, Alessandro Zummo wrote:
>>> On Tue, 25 Mar 2014 17:52:30 -0400
>>> Sasha Levin <sasha.levin@oracle.com> wrote:
>>>
>>>>>
>>>>>    Pretty interesting indeed. One option would be to remove
>>>>>    the sys files before acquiring the lock. But I wonder
>>>>>    if this could lead to other issues.
>>>>>
>>>>
>>>> Ping? Seems this thing got lost.
>>>
>>>   What if we move
>>>
>>>     rtc_sysfs_del_device(rtc);
>>>
>>>   before acquiring the lock?
>>
>> Trying it now, I'll leave it going for a week and see if it reproduces.
>
> Look good, thanks!

Or not...

Hit it again during overnight fuzzing:


[ 1288.605629] ======================================================
[ 1288.606622] [ INFO: possible circular locking dependency detected ]
[ 1288.607544] 3.14.0-rc8-next-20140328-sasha-00016-geb1c595-dirty #297 Tainted: G
   W
[ 1288.608861] -------------------------------------------------------
[ 1288.609719] trinity-c79/32073 is trying to acquire lock:
[ 1288.610463]  (&rtc->ops_lock){+.+.+.}, at: [<ffffffff9b3683a0>] rtc_read_time+0x30/0x
70
[ 1288.610490]
[ 1288.610490] but task is already holding lock:
[ 1288.610490]  (s_active#19){++++.+}, at: [<ffffffff99391264>] kernfs_seq_start+0x44/0x
a0
[ 1288.610490]
[ 1288.610490] which lock already depends on the new lock.
[ 1288.610490]
[ 1288.610490]
[ 1288.610490] the existing dependency chain (in reverse order) is:
[ 1288.610490]
-> #1 (s_active#19){++++.+}:
[ 1288.610490]        [<ffffffff991c5faa>] lock_acquire+0x19a/0x240
[ 1288.610490]        [<ffffffff9938f690>] __kernfs_remove+0x180/0x320
[ 1288.610490]        [<ffffffff993909dc>] kernfs_remove_by_name_ns+0x7c/0xb0
[ 1288.610490]        [<ffffffff993932e1>] remove_files.isra.1+0x51/0x80
[ 1288.610490]        [<ffffffff99393393>] sysfs_remove_group+0x83/0xb0
[ 1288.610490]        [<ffffffff993933fb>] sysfs_remove_groups+0x3b/0x60
[ 1288.610490]        [<ffffffff9a0caf62>] device_remove_groups+0x12/0x20
[ 1288.610490]        [<ffffffff9a0cafd8>] device_remove_attrs+0x68/0x80
[ 1288.610490]        [<ffffffff9a0cb147>] device_del+0x157/0x1c0
[ 1288.610490]        [<ffffffff9a0cb208>] device_unregister+0x58/0x70
[ 1288.610490]        [<ffffffff9b3677a3>] rtc_device_unregister+0x53/0x80
[ 1288.610490]        [<ffffffff9b36dcc3>] cmos_do_probe+0x3b3/0x400
[ 1288.610490]        [<ffffffff9f35ccf2>] cmos_platform_probe+0x44/0x4d
[ 1288.610490]        [<ffffffff9a0d0b02>] platform_drv_probe+0x32/0x90
[ 1288.610490]        [<ffffffff9a0cee45>] driver_probe_device+0x175/0x370
[ 1288.610490]        [<ffffffff9a0cf0c4>] __driver_attach+0x84/0xc0
[ 1288.610490]        [<ffffffff9a0cccd9>] bus_for_each_dev+0x69/0xb0
[ 1288.610490]        [<ffffffff9a0ce67e>] driver_attach+0x1e/0x20
[ 1288.610490]        [<ffffffff9a0ce2b8>] bus_add_driver+0x138/0x260
[ 1288.610490]        [<ffffffff9a0cf8a8>] driver_register+0x98/0xe0
[ 1288.610490]        [<ffffffff9a0d097a>] __platform_driver_register+0x4a/0x50
[ 1288.610490]        [<ffffffff9a0d09a4>] platform_driver_probe+0x24/0xc0
[ 1288.610490]        [<ffffffff9f35cc4b>] cmos_init+0x3c/0x74
[ 1288.610490]        [<ffffffff9900216a>] do_one_initcall+0xca/0x1d0
[ 1288.610490]        [<ffffffff9f2b7128>] kernel_init_freeable+0x1d5/0x26c
[ 1288.610490]        [<ffffffff9c49baae>] kernel_init+0xe/0x100
[ 1288.610490]        [<ffffffff9c50defc>] ret_from_fork+0x7c/0xb0
[ 1288.610490]
-> #0 (&rtc->ops_lock){+.+.+.}:
[ 1288.610490]        [<ffffffff991c4e24>] __lock_acquire+0x1804/0x2120
[ 1288.610490]        [<ffffffff991c5faa>] lock_acquire+0x19a/0x240
[ 1288.610490]        [<ffffffff9c4ff07f>] mutex_lock_interruptible_nested+0x6f/0x680
[ 1288.610490]        [<ffffffff9b3683a0>] rtc_read_time+0x30/0x70
[ 1288.610490]        [<ffffffff9b36a99a>] date_show+0x1a/0x50
[ 1288.610490]        [<ffffffff9a0c9f50>] dev_attr_show+0x20/0x60
[ 1288.610490]        [<ffffffff993923f8>] sysfs_kf_seq_show+0x98/0x110
[ 1288.610490]        [<ffffffff99390c16>] kernfs_seq_show+0x26/0x30
[ 1288.610490]        [<ffffffff9932ef8c>] seq_read+0x19c/0x3a0
[ 1288.610490]        [<ffffffff99391657>] kernfs_fop_read+0x47/0x160
[ 1288.610490]        [<ffffffff99306034>] vfs_read+0xb4/0x190
[ 1288.610490]        [<ffffffff993062c2>] SyS_read+0x52/0xc0
[ 1288.610490]        [<ffffffff9c50e1d8>] tracesys+0xe1/0xe6
[ 1288.610490]
[ 1288.610490] other info that might help us debug this:
[ 1288.610490]
[ 1288.610490]  Possible unsafe locking scenario:
[ 1288.610490]
[ 1288.610490]        CPU0                    CPU1
[ 1288.610490]        ----                    ----
[ 1288.610490]   lock(s_active#19);
[ 1288.610490]                                lock(&rtc->ops_lock);
[ 1288.610490]                                lock(s_active#19);
[ 1288.610490]   lock(&rtc->ops_lock);
[ 1288.610490]
[ 1288.610490]  *** DEADLOCK ***
[ 1288.610490]
[ 1288.610490] 4 locks held by trinity-c79/32073:
[ 1288.610490]  #0:  (&f->f_pos_lock){+.+.+.}, at: [<ffffffff99327fb4>] __fdget_pos+0x44/0x50
[ 1288.610490]  #1:  (&p->lock){+.+.+.}, at: [<ffffffff9932ee2d>] seq_read+0x3d/0x3a0
[ 1288.610490]  #2:  (&of->mutex){+.+.+.}, at: [<ffffffff9939125c>] kernfs_seq_start+0x3c/0xa0
[ 1288.610490]  #3:  (s_active#19){++++.+}, at: [<ffffffff99391264>] kernfs_seq_start+0x44/0xa0
[ 1288.610490]
[ 1288.610490] stack backtrace:
[ 1288.610490] CPU: 1 PID: 32073 Comm: trinity-c79 Tainted: G        W     3.14.0-rc8-next-20140328-sasha-00016-geb1c595-dirty #297
[ 1288.610490]  ffffffff9f9efb40 ffff88062c785ad8 ffffffff9c4b8507 0000000000000000
[ 1288.610490]  ffffffff9f9efb40 ffff88062c785b28 ffffffff9c4ab007 0000000000000004
[ 1288.610490]  ffff88062c785bb8 ffff88062c785b28 ffff88062c630d98 ffff88062c630dd0
[ 1288.610490] Call Trace:
[ 1288.610490]  [<ffffffff9c4b8507>] dump_stack+0x4f/0x7c
[ 1288.610490]  [<ffffffff9c4ab007>] print_circular_bug+0x1fb/0x20c
[ 1288.610490]  [<ffffffff991c4e24>] __lock_acquire+0x1804/0x2120
[ 1288.610490]  [<ffffffff990b9b84>] ? kvm_clock_read+0x24/0x40
[ 1288.610490]  [<ffffffff9907aab5>] ? sched_clock+0x15/0x20
[ 1288.610490]  [<ffffffff991c5faa>] lock_acquire+0x19a/0x240
[ 1288.610490]  [<ffffffff9b3683a0>] ? rtc_read_time+0x30/0x70
[ 1288.610490]  [<ffffffff9c4ff07f>] mutex_lock_interruptible_nested+0x6f/0x680
[ 1288.610490]  [<ffffffff9b3683a0>] ? rtc_read_time+0x30/0x70
[ 1288.610490]  [<ffffffff9c4aec22>] ? __slab_alloc+0x5c8/0x637
[ 1288.610490]  [<ffffffff9b3683a0>] ? rtc_read_time+0x30/0x70
[ 1288.610490]  [<ffffffff9b3683a0>] rtc_read_time+0x30/0x70
[ 1288.610490]  [<ffffffff9b36a99a>] date_show+0x1a/0x50
[ 1288.610490]  [<ffffffff9a0c9f50>] dev_attr_show+0x20/0x60
[ 1288.610490]  [<ffffffff993922a5>] ? sysfs_file_ops+0x35/0x80
[ 1288.610490]  [<ffffffff993923f8>] sysfs_kf_seq_show+0x98/0x110
[ 1288.610490]  [<ffffffff99390c16>] kernfs_seq_show+0x26/0x30
[ 1288.610490]  [<ffffffff9932ef8c>] seq_read+0x19c/0x3a0
[ 1288.610490]  [<ffffffff99391657>] kernfs_fop_read+0x47/0x160
[ 1288.610490]  [<ffffffff99306034>] vfs_read+0xb4/0x190
[ 1288.610490]  [<ffffffff993062c2>] SyS_read+0x52/0xc0
[ 1288.610490]  [<ffffffff9c50e1d8>] tracesys+0xe1/0xe6


Thanks,
Sasha

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Alessandro Zummo]

On Sun, 30 Mar 2014 12:04:16 -0400
Sasha Levin <sasha.levin@oracle.com> wrote:

> > Look good, thanks!  
> 
> Or not...
> 
> Hit it again during overnight fuzzing:
> 

 I think this is a different bug, please try this.

diff --git a/drivers/rtc/rtc-cmos.c b/drivers/rtc/rtc-cmos.c
index cae212f..2c77d8e 100644
--- a/drivers/rtc/rtc-cmos.c
+++ b/drivers/rtc/rtc-cmos.c
@@ -712,6 +712,20 @@ cmos_do_probe(struct device *dev, struct resource *ports, int rtc_irq)
 		}
 	}
 
+	spin_lock_irq(&rtc_lock);
+	rtc_control = CMOS_READ(RTC_CONTROL);
+	spin_unlock_irq(&rtc_lock);
+
+	/* FIXME:
+	 * <asm-generic/rtc.h> doesn't know 12-hour mode either.
+	 */
+	if (is_valid_irq(rtc_irq) && !(rtc_control & RTC_24H)) {
+		dev_warn(dev, "only 24-hr supported\n");
+		retval = -ENXIO;
+		goto cleanup0;
+	}
+
+
 	cmos_rtc.dev = dev;
 	dev_set_drvdata(dev, &cmos_rtc);
 
@@ -739,49 +753,49 @@ cmos_do_probe(struct device *dev, struct resource *ports, int rtc_irq)
 	/* disable irqs */
 	cmos_irq_disable(&cmos_rtc, RTC_PIE | RTC_AIE | RTC_UIE);
 
-	rtc_control = CMOS_READ(RTC_CONTROL);
-
 	spin_unlock_irq(&rtc_lock);
 
-	/* FIXME:
-	 * <asm-generic/rtc.h> doesn't know 12-hour mode either.
-	 */
-	if (is_valid_irq(rtc_irq) && !(rtc_control & RTC_24H)) {
-		dev_warn(dev, "only 24-hr supported\n");
-		retval = -ENXIO;
-		goto cleanup1;
-	}
-
 	if (is_valid_irq(rtc_irq)) {
-		irq_handler_t rtc_cmos_int_handler;
+
+		irq_handler_t rtc_cmos_int_handler = NULL;
 
 		if (is_hpet_enabled()) {
-			rtc_cmos_int_handler = hpet_rtc_interrupt;
+
 			retval = hpet_register_irq_handler(cmos_interrupt);
 			if (retval) {
 				dev_warn(dev, "hpet_register_irq_handler "
 						" failed in rtc_init().");
-				goto cleanup1;
+			} else {
+				rtc_cmos_int_handler = hpet_rtc_interrupt;
 			}
-		} else
+		} else {
 			rtc_cmos_int_handler = cmos_interrupt;
+		}
 
-		retval = request_irq(rtc_irq, rtc_cmos_int_handler,
-				0, dev_name(&cmos_rtc.rtc->dev),
-				cmos_rtc.rtc);
-		if (retval < 0) {
-			dev_dbg(dev, "IRQ %d is already in use\n", rtc_irq);
-			goto cleanup1;
+		if (rtc_cmos_int_handler) {
+			retval = request_irq(rtc_irq, rtc_cmos_int_handler,
+					0, dev_name(&cmos_rtc.rtc->dev),
+					cmos_rtc.rtc);
+			if (retval < 0) {
+
+				dev_err(dev, "IRQ %d is already in use\n", rtc_irq);
+
+				cmos_rtc.irq = -1;
+
+				if (is_hpet_enabled()) {
+					hpet_unregister_irq_handler(cmos_interrupt);
+				}
+			}
 		}
 	}
+
 	hpet_rtc_timer_init();
 
 	/* export at least the first block of NVRAM */
 	nvram.size = address_space - NVRAM_OFFSET;
 	retval = sysfs_create_bin_file(&dev->kobj, &nvram);
 	if (retval < 0) {
-		dev_dbg(dev, "can't create nvram file? %d\n", retval);
-		goto cleanup2;
+		dev_err(dev, "can't create nvram file? %d\n", retval);
 	}
 
 	dev_info(dev, "%s%s, %zd bytes nvram%s\n",
@@ -795,12 +809,6 @@ cmos_do_probe(struct device *dev, struct resource *ports, int rtc_irq)
 
 	return 0;
 
-cleanup2:
-	if (is_valid_irq(rtc_irq))
-		free_irq(rtc_irq, cmos_rtc.rtc);
-cleanup1:
-	cmos_rtc.dev = NULL;
-	rtc_device_unregister(cmos_rtc.rtc);
 cleanup0:
 	release_region(ports->start, resource_size(ports));
 	return retval;
@@ -823,8 +831,12 @@ static void __exit cmos_do_remove(struct device *dev)
 	sysfs_remove_bin_file(&dev->kobj, &nvram);
 
 	if (is_valid_irq(cmos->irq)) {
+
 		free_irq(cmos->irq, cmos->rtc);
-		hpet_unregister_irq_handler(cmos_interrupt);
+
+		if (is_hpet_enabled()) {
+			hpet_unregister_irq_handler(cmos_interrupt);
+		}
 	}
 
 	rtc_device_unregister(cmos->rtc);



-- 

 Best regards,

 Alessandro Zummo,
  Tower Technologies - Torino, Italy

  http://www.towertech.it

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Lars-Peter Clausen]

On 03/31/2014 11:46 AM, Alessandro Zummo wrote:
> On Sun, 30 Mar 2014 12:04:16 -0400
> Sasha Levin <sasha.levin@oracle.com> wrote:
>
>>> Look good, thanks!
>>
>> Or not...
>>
>> Hit it again during overnight fuzzing:
>>
>
>   I think this is a different bug, please try this.

It's the same bug, device_unregister(&rtc->dev) will try to unregister all 
sysfs files attached to the device and that function is still called with 
the rtc mutex held.

- Lars

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Alessandro Zummo]

On Mon, 31 Mar 2014 11:52:36 +0200
Lars-Peter Clausen <lars@metafoo.de> wrote:

> It's the same bug, device_unregister(&rtc->dev) will try to unregister all 
> sysfs files attached to the device and that function is still called with 
> the rtc mutex held.

 rtc-cmos tries to unregister the rtc device in the probe function,
 which should not be done. 

 the last patches fixes it. I'll keep trying to trigger the bug on my systems.

-- 

 Best regards,

 Alessandro Zummo,
  Tower Technologies - Torino, Italy

  http://www.towertech.it

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Lars-Peter Clausen]

On 03/31/2014 12:43 PM, Alessandro Zummo wrote:
> On Mon, 31 Mar 2014 11:52:36 +0200
> Lars-Peter Clausen <lars@metafoo.de> wrote:
>
>> It's the same bug, device_unregister(&rtc->dev) will try to unregister all
>> sysfs files attached to the device and that function is still called with
>> the rtc mutex held.
>
>   rtc-cmos tries to unregister the rtc device in the probe function,
>   which should not be done.
>
>   the last patches fixes it. I'll keep trying to trigger the bug on my systems.
>

It doesn't really matter where it is unregistered. device_unregister() will 
(somewhere down it's callchain) take the kernfs lock, hence it must be 
callled with the rtc mutex being held.

- Lars

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Alessandro Zummo]

On Mon, 31 Mar 2014 13:07:10 +0200
Lars-Peter Clausen <lars@metafoo.de> wrote:

> It doesn't really matter where it is unregistered. device_unregister() will 
> (somewhere down it's callchain) take the kernfs lock, hence it must be 
> callled with the rtc mutex being held.

 Maybe device_remove_attrs could be called in the rtc base class,
 before the device removal?

-- 

 Best regards,

 Alessandro Zummo,
  Tower Technologies - Torino, Italy

  http://www.towertech.it

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Lars-Peter Clausen]

On 03/31/2014 02:03 PM, Alessandro Zummo wrote:
> On Mon, 31 Mar 2014 13:07:10 +0200
> Lars-Peter Clausen <lars@metafoo.de> wrote:
>
>> It doesn't really matter where it is unregistered. device_unregister() will
>> (somewhere down it's callchain) take the kernfs lock, hence it must be
>> callled with the rtc mutex being held.
>
>   Maybe device_remove_attrs could be called in the rtc base class,
>   before the device removal?
>

Just move the device_unregister() call outside the lock. I think the only 
thing that needs to be protected is the ops = NULL assignment. Moving the 
unregister after the unlock also means that the extra 
get_device()/put_device() pair can be removed.

Re: kernfs/rtc: circular dependency between kernfs and ops_lock

[Sasha Levin]

On 03/31/2014 08:19 AM, Lars-Peter Clausen wrote:
> On 03/31/2014 02:03 PM, Alessandro Zummo wrote:
>> On Mon, 31 Mar 2014 13:07:10 +0200
>> Lars-Peter Clausen <lars@metafoo.de> wrote:
>>
>>> It doesn't really matter where it is unregistered. device_unregister() will
>>> (somewhere down it's callchain) take the kernfs lock, hence it must be
>>> callled with the rtc mutex being held.
>>
>>   Maybe device_remove_attrs could be called in the rtc base class,
>>   before the device removal?
>>
> 
> Just move the device_unregister() call outside the lock. I think the only thing that needs to be protected is the ops = NULL assignment. Moving the unregister after the unlock also means that the extra get_device()/put_device() pair can be removed.

That seems to cause errors on boot:

[   23.714976] BUG: unable to handle kernel NULL pointer dereference at 0000000000000090
[   23.716017] IP: [<ffffffffb438ee5f>] kernfs_find_ns+0x1f/0x160
[   23.716620] PGD 0
[   23.716843] Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[   23.717448] Dumping ftrace buffer:
[   23.717861]    (ftrace buffer empty)
[   23.718233] Modules linked in:
[   23.718561] CPU: 2 PID: 1 Comm: swapper/0 Not tainted 3.14.0-next-20140402-sasha-00013-g0cfaf7e-dirty #364
[   23.719523] task: ffff8806ec5b0000 ti: ffff88003e284000 task.ti: ffff88003e284000
[   23.720134] RIP: 0010:[<ffffffffb438ee5f>]  [<ffffffffb438ee5f>] kernfs_find_ns+0x1f/0x160
[   23.720134] RSP: 0000:ffff88003e285af8  EFLAGS: 00010292
[   23.720134] RAX: 0000000080000000 RBX: 0000000000000000 RCX: 0000000000000006
[   23.720134] RDX: 0000000000000000 RSI: ffffffffb78bd6c0 RDI: 0000000000000000
[   23.720134] RBP: ffff88003e285b28 R08: 0000000000000000 R09: 0000000000000000
[   23.720134] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[   23.720134] R13: ffffffffb78bd6c0 R14: 0000000000000000 R15: 0000000000000008
[   23.720134] FS:  0000000000000000(0000) GS:ffff8800bec00000(0000) knlGS:0000000000000000
[   23.720134] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[   23.720134] CR2: 0000000000000090 CR3: 0000000038e2c000 CR4: 00000000000006a0
[   23.720134] Stack:
[   23.720134]  ffff88003e285b28 0000000000000000 ffffffffb78bd6c0 0000000000000000
[   23.720134]  0000000000000080 0000000000000008 ffff88003e285b58 ffffffffb438f0be
[   23.720134]  ffff880000000010 ffffffffb9c0f6c0 ffff8800bdd89148 ffffffffb8e430b0
[   23.720134] Call Trace:
[   23.720134]  [<ffffffffb438f0be>] kernfs_find_and_get_ns+0x3e/0x70
[   23.730419] kobject: 'tlan' (ffff88026bf2a760): kobject_cleanup, parent ffff8803ec71efe8
[   23.730422] kobject: 'tlan' (ffff88026bf2a760): auto cleanup 'remove' event
[   23.730424] kobject: 'tlan' (ffff88026bf2a760): kobject_uevent_env
[   23.730460] kobject: 'tlan' (ffff88026bf2a760): fill_kobj_path: path = '/bus/pci/drivers/tlan'
[   23.730559] kobject: 'tlan' (ffff88026bf2a760): auto cleanup kobject_del
[   23.720134]  [<ffffffffb439392d>] sysfs_unmerge_group+0x1d/0x70
[   23.720134]  [<ffffffffb50d858b>] dpm_sysfs_remove+0x2b/0x70
[   23.720134]  [<ffffffffb50cdd97>] device_del+0x47/0x1c0
[   23.720134]  [<ffffffffb50cdf68>] device_unregister+0x58/0x70
[   23.720134]  [<ffffffffb636bb95>] rtc_device_unregister+0x65/0x80
[   23.720134]  [<ffffffffb63720a3>] cmos_do_probe+0x3b3/0x400
[   23.720134]  [<ffffffffba35ddd3>] cmos_platform_probe+0x44/0x4d
[   23.720134]  [<ffffffffb50d3862>] platform_drv_probe+0x32/0x90
[   23.720134]  [<ffffffffb50d1ba5>] driver_probe_device+0x175/0x370
[   23.720134]  [<ffffffffb50d1e24>] __driver_attach+0x84/0xc0
[   23.720134]  [<ffffffffb50d1da0>] ? driver_probe_device+0x370/0x370
[   23.720134]  [<ffffffffb50cfa39>] bus_for_each_dev+0x69/0xb0
[   23.720134]  [<ffffffffb50d13de>] driver_attach+0x1e/0x20
[   23.720134]  [<ffffffffb50d1018>] bus_add_driver+0x138/0x260
[   23.720134]  [<ffffffffba35dcf0>] ? bq4802_driver_init+0x14/0x14
[   23.720134]  [<ffffffffb50d2608>] driver_register+0x98/0xe0
[   23.720134]  [<ffffffffba35dcf0>] ? bq4802_driver_init+0x14/0x14
[   23.720134]  [<ffffffffb50d36da>] __platform_driver_register+0x4a/0x50
[   23.720134]  [<ffffffffb50d3704>] platform_driver_probe+0x24/0xc0
[   23.720134]  [<ffffffffba35dcf0>] ? bq4802_driver_init+0x14/0x14
[   23.720134]  [<ffffffffba35dd2c>] cmos_init+0x3c/0x74
[   23.720134]  [<ffffffffb400216a>] do_one_initcall+0xca/0x1d0
[   23.720134]  [<ffffffffb4185100>] ? parse_args+0x280/0x460
[   23.720134]  [<ffffffffba2b8128>] kernel_init_freeable+0x1d5/0x26c
[   23.720134]  [<ffffffffba2b7848>] ? loglevel+0x31/0x31
[   23.720134]  [<ffffffffb74a1fe0>] ? rest_init+0x140/0x140
[   23.720134]  [<ffffffffb74a1fee>] kernel_init+0xe/0x100
[   23.720134]  [<ffffffffb7514b7c>] ret_from_fork+0x7c/0xb0
[   23.720134]  [<ffffffffb74a1fe0>] ? rest_init+0x140/0x140
[   23.720134] Code: 8b 75 f8 c9 c3 0f 1f 80 00 00 00 00 66 66 66 66 90 55 48 89 e5 41 57 41 56 49 89 d6 41 55 49 89 f5 41 54 49 89 fc 53 48 83 ec 08 <0f> b7 87 90 00 00 00 8b 15 d4 00 7d 05 48 8b 5f 78 66 c1 e8 05
[   23.720134] RIP  [<ffffffffb438ee5f>] kernfs_find_ns+0x1f/0x160
[   23.720134]  RSP <ffff88003e285af8>
[   23.720134] CR2: 0000000000000090


Thanks,
Sasha