================================
WARNING: inconsistent lock state
4.14.305-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
syz-executor.0/11578 [HC0[0]:SC1[1]:HE1:SE0] takes:
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff867dde51>] spin_lock include/linux/spinlock.h:317 [inline]
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff867dde51>] rxrpc_put_one_client_conn net/rxrpc/conn_client.c:905 [inline]
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff867dde51>] rxrpc_put_client_conn+0x661/0xac0 net/rxrpc/conn_client.c:957
{SOFTIRQ-ON-W} state was registered at:
lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:152
spin_lock include/linux/spinlock.h:317 [inline]
rxrpc_get_client_conn net/rxrpc/conn_client.c:306 [inline]
rxrpc_connect_call+0x2bb/0x3e10 net/rxrpc/conn_client.c:692
rxrpc_new_client_call+0x8f4/0x1a10 net/rxrpc/call_object.c:276
rxrpc_new_client_call_for_sendmsg net/rxrpc/sendmsg.c:531 [inline]
rxrpc_do_sendmsg+0x8dc/0xfb0 net/rxrpc/sendmsg.c:583
rxrpc_sendmsg+0x3cf/0x5f0 net/rxrpc/af_rxrpc.c:543
sock_sendmsg_nosec net/socket.c:646 [inline]
sock_sendmsg+0xb5/0x100 net/socket.c:656
___sys_sendmsg+0x6c8/0x800 net/socket.c:2062
__sys_sendmsg+0xa3/0x120 net/socket.c:2096
SYSC_sendmsg net/socket.c:2107 [inline]
SyS_sendmsg+0x27/0x40 net/socket.c:2103
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x5e/0xd3
irq event stamp: 39752
hardirqs last enabled at (39752): [<ffffffff8724f359>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
hardirqs last enabled at (39752): [<ffffffff8724f359>] _raw_spin_unlock_irqrestore+0x79/0xe0 kernel/locking/spinlock.c:192
hardirqs last disabled at (39751): [<ffffffff8724efe6>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (39751): [<ffffffff8724efe6>] _raw_spin_lock_irqsave+0x66/0xc0 kernel/locking/spinlock.c:160
softirqs last enabled at (38828): [<ffffffff8760068b>] __do_softirq+0x68b/0x9ff kernel/softirq.c:314
softirqs last disabled at (39691): [<ffffffff81322e33>] invoke_softirq kernel/softirq.c:368 [inline]
softirqs last disabled at (39691): [<ffffffff81322e33>] irq_exit+0x193/0x240 kernel/softirq.c:409
other info that might help us debug this:
Possible unsafe locking scenario:
CPU0
----
lock(&(&local->client_conns_lock)->rlock);
<Interrupt>
lock(&(&local->client_conns_lock)->rlock);
*** DEADLOCK ***
3 locks held by syz-executor.0/11578:
#0: (sb_writers#6){.+.+}, at: [<ffffffff818729c8>] file_start_write include/linux/fs.h:2714 [inline]
#0: (sb_writers#6){.+.+}, at: [<ffffffff818729c8>] vfs_write+0x3d8/0x4d0 fs/read_write.c:543
#1: (&sb->s_type->i_mutex_key#15){+.+.}, at: [<ffffffff81693f09>] inode_lock include/linux/fs.h:719 [inline]
#1: (&sb->s_type->i_mutex_key#15){+.+.}, at: [<ffffffff81693f09>] generic_file_write_iter+0x99/0x650 mm/filemap.c:3205
#2: (rcu_callback){....}, at: [<ffffffff8146ee1e>] __rcu_reclaim kernel/rcu/rcu.h:185 [inline]
#2: (rcu_callback){....}, at: [<ffffffff8146ee1e>] rcu_do_batch kernel/rcu/tree.c:2699 [inline]
#2: (rcu_callback){....}, at: [<ffffffff8146ee1e>] invoke_rcu_callbacks kernel/rcu/tree.c:2962 [inline]
#2: (rcu_callback){....}, at: [<ffffffff8146ee1e>] __rcu_process_callbacks kernel/rcu/tree.c:2929 [inline]
#2: (rcu_callback){....}, at: [<ffffffff8146ee1e>] rcu_process_callbacks+0x84e/0x1180 kernel/rcu/tree.c:2946
stack backtrace:
CPU: 0 PID: 11578 Comm: syz-executor.0 Not tainted 4.14.305-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/21/2023
Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x1b2/0x281 lib/dump_stack.c:58
print_usage_bug.cold+0x42e/0x570 kernel/locking/lockdep.c:2589
valid_state kernel/locking/lockdep.c:2602 [inline]
mark_lock_irq kernel/locking/lockdep.c:2796 [inline]
mark_lock+0xb4d/0x1050 kernel/locking/lockdep.c:3194
mark_irqflags kernel/locking/lockdep.c:3072 [inline]
__lock_acquire+0xc81/0x3f20 kernel/locking/lockdep.c:3448
lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:152
spin_lock include/linux/spinlock.h:317 [inline]
rxrpc_put_one_client_conn net/rxrpc/conn_client.c:905 [inline]
rxrpc_put_client_conn+0x661/0xac0 net/rxrpc/conn_client.c:957
rxrpc_put_connection net/rxrpc/ar-internal.h:862 [inline]
rxrpc_rcu_destroy_call+0x83/0x190 net/rxrpc/call_object.c:653
__rcu_reclaim kernel/rcu/rcu.h:195 [inline]
rcu_do_batch kernel/rcu/tree.c:2699 [inline]
invoke_rcu_callbacks kernel/rcu/tree.c:2962 [inline]
__rcu_process_callbacks kernel/rcu/tree.c:2929 [inline]
rcu_process_callbacks+0x780/0x1180 kernel/rcu/tree.c:2946
__do_softirq+0x24d/0x9ff kernel/softirq.c:288
invoke_softirq kernel/softirq.c:368 [inline]
irq_exit+0x193/0x240 kernel/softirq.c:409
exiting_irq arch/x86/include/asm/apic.h:638 [inline]
smp_apic_timer_interrupt+0x141/0x5e0 arch/x86/kernel/apic/apic.c:1106
apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:796
</IRQ>
RIP: 0010:get_current arch/x86/include/asm/current.h:15 [inline]
RIP: 0010:__sanitizer_cov_trace_pc+0x0/0x50 kernel/kcov.c:60
RSP: 0018:ffff88805335fb70 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff10
RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffffc90005bb2000
RDX: 0000000000040000 RSI: ffffffff81688fc3 RDI: ffff88805335fd50
RBP: ffff8880af07bd80 R08: 0000000000001000 R09: ffffea0001378640
R10: ffff88804de19fff R11: 0000000000000000 R12: 0000000000001000
R13: 0000000000000000 R14: ffff88805335fdb8 R15: 0000000000e3f000
generic_perform_write+0x186/0x430 mm/filemap.c:3055
__generic_file_write_iter+0x227/0x590 mm/filemap.c:3180
generic_file_write_iter+0x36f/0x650 mm/filemap.c:3208
call_write_iter include/linux/fs.h:1780 [inline]
new_sync_write fs/read_write.c:469 [inline]
__vfs_write+0x44c/0x630 fs/read_write.c:482
vfs_write+0x17f/0x4d0 fs/read_write.c:544
SYSC_write fs/read_write.c:590 [inline]
SyS_write+0xf2/0x210 fs/read_write.c:582
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x5e/0xd3
RIP: 0033:0x7f64369d7e7f
RSP: 002b:00007f6434f97f10 EFLAGS: 00000293 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f64369d7e7f
RDX: 00000000013bd7ef RSI: 00007f642cb78000 RDI: 0000000000000003
RBP: 00007f642cb78000 R08: 0000000000000000 R09: 00000000000054e0
R10: 00000000013bd7ef R11: 0000000000000293 R12: 0000000000000000
R13: 00007f6434f97fdc R14: 00007f6434f97fe0 R15: 0000000020000142
audit: type=1804 audit(1677027485.482:408): pid=11578 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.0" name="/root/syzkaller-testdir1624314343/syzkaller.BVkh14/60/bus" dev="sda1" ino=13891 res=1
audit: type=1804 audit(1677027485.512:409): pid=11578 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="ToMToU" comm="syz-executor.0" name="/root/syzkaller-testdir1624314343/syzkaller.BVkh14/60/bus" dev="sda1" ino=13891 res=1
ntfs: volume version 3.1.
audit: type=1804 audit(1677027486.752:410): pid=11661 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.0" name="/root/syzkaller-testdir1624314343/syzkaller.BVkh14/61/bus" dev="sda1" ino=13880 res=1
audit: type=1804 audit(1677027486.752:411): pid=11661 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="ToMToU" comm="syz-executor.0" name="/root/syzkaller-testdir1624314343/syzkaller.BVkh14/61/bus" dev="sda1" ino=13880 res=1
kvm: vcpu 0: requested 128 ns lapic timer period limited to 500000 ns
audit: type=1804 audit(1677027487.962:412): pid=11712 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.0" name="/root/syzkaller-testdir1624314343/syzkaller.BVkh14/62/bus" dev="sda1" ino=13879 res=1
audit: type=1804 audit(1677027487.962:413): pid=11712 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="ToMToU" comm="syz-executor.0" name="/root/syzkaller-testdir1624314343/syzkaller.BVkh14/62/bus" dev="sda1" ino=13879 res=1
unregister_netdevice: waiting for ip6gre0 to become free. Usage count = -1
kvm: vcpu 0: requested 128 ns lapic timer period limited to 500000 ns
audit: type=1800 audit(1677027488.642:414): pid=11775 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.4" name="file0" dev="sda1" ino=14215 res=0
audit: type=1804 audit(1677027488.652:415): pid=11775 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.4" name="/root/syzkaller-testdir4073173088/syzkaller.gx03Vo/74/file0" dev="sda1" ino=14215 res=1
9pnet: Insufficient options for proto=fd
audit: type=1804 audit(1677027488.652:416): pid=11775 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="ToMToU" comm="syz-executor.4" name="/root/syzkaller-testdir4073173088/syzkaller.gx03Vo/74/file0" dev="sda1" ino=14215 res=1
9pnet: Insufficient options for proto=fd
kvm: vcpu 0: requested 128 ns lapic timer period limited to 500000 ns
9pnet: Insufficient options for proto=fd
9pnet: Insufficient options for proto=fd
kvm: vcpu 0: requested 128 ns lapic timer period limited to 500000 ns
audit: type=1800 audit(1677027490.483:417): pid=11835 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.1" name="file0" dev="sda1" ino=13921 res=0
audit: type=1800 audit(1677027490.533:418): pid=11834 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.4" name="file0" dev="sda1" ino=14219 res=0
audit: type=1804 audit(1677027490.703:419): pid=11835 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.1" name="/root/syzkaller-testdir1453942664/syzkaller.tAtoRd/66/file0" dev="sda1" ino=13921 res=1