Re: [cel:topic-shmem-stable-dir-cookies] [shmem] 5fd403eb6c: WARNING:inconsistent_lock_state

[Chuck Lever III <chuck.lever@oracle.com>]

> On Apr 12, 2023, at 3:34 PM, Jeff Layton <jlayton@kernel.org> wrote:
> 
> On Wed, 2023-04-12 at 19:09 +0000, Chuck Lever III wrote:
>> 
>>> On Apr 12, 2023, at 3:05 PM, Jeff Layton <jlayton@kernel.org> wrote:
>>> 
>>> On Wed, 2023-04-12 at 18:03 +0000, Chuck Lever III wrote:
>>>> 
>>>> 
>>>>> On Apr 10, 2023, at 8:36 PM, kernel test robot <yujie.liu@intel.com>
>>>>> wrote:
>>>>> 
>>>>> Hello,
>>>>> 
>>>>> kernel test robot noticed "WARNING:inconsistent_lock_state" on:
>>>>> 
>>>>> commit: 5fd403eb6c181c63a3aacd55d92b80256a0670cf ("shmem: stable
>>>>> directory cookies")
>>>>> git://git.kernel.org/cgit/linux/kernel/git/cel/linux topic-shmem-
>>>>> stable-dir-cookies
>>>>> 
>>>>> in testcase: boot
>>>>> 
>>>>> compiler: gcc-11
>>>>> test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2
>>>>> -m 16G
>>>>> 
>>>>> (please refer to attached dmesg/kmsg for entire log/backtrace)
>>>>> 
>>>>> 
>>>>> If you fix the issue, kindly add following tag
>>>>>> Reported-by: kernel test robot <yujie.liu@intel.com>
>>>>>> Link:
>>>>> https://lore.kernel.org/oe-lkp/202304101606.79aea62f-yujie.liu@intel.com
>>>>> 
>>>>> 
>>>>> [   21.279213][    C0] WARNING: inconsistent lock state
>>>>> [   21.279668][    C0] 6.3.0-rc5-00001-g5fd403eb6c18 #1 Not tainted
>>>>> [   21.280199][    C0] --------------------------------
>>>>> [   21.280657][    C0] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W}
>>>>> usage.
>>>>> [   21.281238][    C0] swapper/0/0 [HC0[0]:SC1[1]:HE0:SE0] takes:
>>>>> [ 21.281773][ C0] ffff8881102e9b50 (&xa->xa_lock#3){+.?.}-{2:2}, at:
>>>>> xa_destroy (lib/xarray.c:2214)
>>>>> [   21.283140][    C0] {SOFTIRQ-ON-W} state was registered at:
>>>>> [ 21.283640][ C0] __lock_acquire (kernel/locking/lockdep.c:5010) 
>>>>> [ 21.284089][ C0] lock_acquire (kernel/locking/lockdep.c:467
>>>>> kernel/locking/lockdep.c:5671 kernel/locking/lockdep.c:5634)
>>>>> [ 21.284513][ C0] _raw_spin_lock
>>>>> (include/linux/spinlock_api_smp.h:134 kernel/locking/spinlock.c:154)
>>>>> [ 21.284937][ C0] shmem_doff_add (include/linux/xarray.h:965
>>>>> mm/shmem.c:2943) 
>>>>> [ 21.285375][ C0] shmem_mknod (mm/shmem.c:3014) 
>>>>> [ 21.285791][ C0] vfs_mknod (fs/namei.c:3916) 
>>>>> [ 21.286195][ C0] devtmpfs_work_loop (drivers/base/devtmpfs.c:228
>>>>> drivers/base/devtmpfs.c:393 drivers/base/devtmpfs.c:408)
>>>>> [ 21.286653][ C0] devtmpfsd (devtmpfs.c:?) 
>>>>> [ 21.287046][ C0] kthread (kernel/kthread.c:376) 
>>>>> [ 21.287441][ C0] ret_from_fork (arch/x86/entry/entry_64.S:314) 
>>>>> [   21.287864][    C0] irq event stamp: 167451
>>>>> [ 21.288264][ C0] hardirqs last enabled at (167450):
>>>>> kasan_quarantine_put (arch/x86/include/asm/irqflags.h:42
>>>>> (discriminator 1) arch/x86/include/asm/irqflags.h:77 (discriminator
>>>>> 1) arch/x86/include/asm/irqflags.h:135 (discriminator 1)
>>>>> mm/kasan/quarantine.c:242 (discriminator 1)) 
>>>>> [ 21.289095][ C0] hardirqs last disabled at (167451):
>>>>> _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:108
>>>>> kernel/locking/spinlock.c:162)
>>>>> [ 21.289969][ C0] softirqs last enabled at (167330): __do_softirq
>>>>> (kernel/softirq.c:415 kernel/softirq.c:600)
>>>>> [ 21.290755][ C0] softirqs last disabled at (167355): irq_exit_rcu
>>>>> (kernel/softirq.c:445 kernel/softirq.c:650 kernel/softirq.c:640
>>>>> kernel/softirq.c:662)
>>>>> [   21.291540][    C0]
>>>>> [   21.291540][    C0] other info that might help us debug this:
>>>>> [   21.292230][    C0]  Possible unsafe locking scenario:
>>>>> [   21.292230][    C0]
>>>>> [   21.292905][    C0]        CPU0
>>>>> [   21.293235][    C0]        ----
>>>>> [   21.293575][    C0]   lock(&xa->xa_lock#3);
>>>>> [   21.293987][    C0]   <Interrupt>
>>>>> [   21.294327][    C0]     lock(&xa->xa_lock#3);
>>>>> [   21.294753][    C0]
>>>>> [   21.294753][    C0]  *** DEADLOCK ***
>>>>> [   21.294753][    C0]
>>>>> [   21.295483][    C0] 1 lock held by swapper/0/0:
>>>>> [ 21.295914][ C0] #0: ffffffff8597a260 (rcu_callback){....}-{0:0},
>>>>> at: rcu_do_batch (kernel/rcu/tree.c:2104)
>>>> 
>>>> It appears that RCU is trying to evict a tmpfs directory inode
>>>> prematurely.
>>>> lockdep catches this because someone else is trying to add an entry to
>>>> it
>>>> while RCU is trying to free it. Classic use-after-free.
>>>> 
>>>> Jeff, the only new iput() in this patch is the one you suggested in
>>>> shmem_symlink(). Are you sure it is needed (and also correct)?
>>>> 
>>> 
>>> The code in your topic-shmem-stable-dir-cookies branch looks correct to
>>> me. After shmem_get_inode, it holds an inode reference and that must be
>>> explicitly put on error, unless you attach it to the dentry (via
>>> d_instantiate).
>>> 
>>> I'm not sure how to interpret this. The log is a bit of a mess. It looks
>>> it ended up in some sort of recursive call into the same xarray due to
>>> an interrupt?
>> 
>> I think it's easier to see if you look at the dmesg.xz that was
>> attached to the original report.
>> 
>> The thing calling xa_destroy is being invoked from i_callback,
>> which is the RCU-deferred "inode destroy" method. It's running
>> in softIRQ context.
>> 
> 
> Right, but why is it trying to add an entry to an xarray that is being
> destroyed?

I think because the directory inode's reference count is too low,
and it's being destroyed too early (ie, while there are still
legitimate users).


> Or maybe it isn't, and lockdep is just confused and is
> classifying the various per-inode xarrays together? I have a hard time
> interpreting these reports sometimes. :-/
> 
>> 
>>> One thing that looks suspicious to me is that this patch has the call to
>>> shmem_doff_map_destroy in free_inode (which is the RCU callback). I
>>> think you probably want to do that in destroy_inode instead since that
>>> involves taking locks and such.
>> 
>> I'll have a look!
>> 
> 
> Cool, I think that's probably safest here. In principle, the xarray
> should be empty when we get to this point so there ought not be much to
> do anyway.

I expected that shmem_free_in_core_inode() was invoked later than
shmem_destroy_inode(), after everything had been completely torn
down.

I'm shooting in the dark with the fix, though. I can't make heads
or tails of the job file that was attached, so I don't have a
reproducer.


--
Chuck Lever