audit: type=1804 audit(1677356200.568:7): pid=10765 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.4" name="/root/syzkaller-testdir535438970/syzkaller.tAnOLg/40/file0" dev="sda1" ino=13871 res=1
================================
WARNING: inconsistent lock state
4.14.307-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
kauditd/1938 [HC0[0]:SC1[1]:HE1:SE0] takes:
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff867de3a1>] spin_lock include/linux/spinlock.h:317 [inline]
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff867de3a1>] rxrpc_put_one_client_conn net/rxrpc/conn_client.c:905 [inline]
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff867de3a1>] 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: 1812
hardirqs last enabled at (1812): [<ffffffff8724fcb9>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
hardirqs last enabled at (1812): [<ffffffff8724fcb9>] _raw_spin_unlock_irqrestore+0x79/0xe0 kernel/locking/spinlock.c:192
hardirqs last disabled at (1811): [<ffffffff8724f946>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (1811): [<ffffffff8724f946>] _raw_spin_lock_irqsave+0x66/0xc0 kernel/locking/spinlock.c:160
softirqs last enabled at (1726): [<ffffffff8760068b>] __do_softirq+0x68b/0x9ff kernel/softirq.c:314
softirqs last disabled at (1773): [<ffffffff81322e63>] invoke_softirq kernel/softirq.c:368 [inline]
softirqs last disabled at (1773): [<ffffffff81322e63>] 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 ***
2 locks held by kauditd/1938:
#0: (console_lock){+.+.}, at: [<ffffffff814443a8>] vprintk_func+0x58/0x160 kernel/printk/printk_safe.c:409
#1: (rcu_callback){....}, at: [<ffffffff8146ee4e>] __rcu_reclaim kernel/rcu/rcu.h:185 [inline]
#1: (rcu_callback){....}, at: [<ffffffff8146ee4e>] rcu_do_batch kernel/rcu/tree.c:2699 [inline]
#1: (rcu_callback){....}, at: [<ffffffff8146ee4e>] invoke_rcu_callbacks kernel/rcu/tree.c:2962 [inline]
#1: (rcu_callback){....}, at: [<ffffffff8146ee4e>] __rcu_process_callbacks kernel/rcu/tree.c:2929 [inline]
#1: (rcu_callback){....}, at: [<ffffffff8146ee4e>] rcu_process_callbacks+0x84e/0x1180 kernel/rcu/tree.c:2946
stack backtrace:
CPU: 1 PID: 1938 Comm: kauditd Not tainted 4.14.307-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 02/16/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:arch_local_irq_restore arch/x86/include/asm/paravirt.h:779 [inline]
RIP: 0010:console_unlock+0xbeb/0xf20 kernel/printk/printk.c:2417
RSP: 0018:ffff8880b11bfc18 EFLAGS: 00000297 ORIG_RAX: ffffffffffffff10
RAX: ffff8880b11b41c0 RBX: 0000000000000200 RCX: 1ffff1101623694d
RDX: 0000000000000000 RSI: ffff8880b11b4a48 RDI: 0000000000000297
RBP: 0000000000000000 R08: ffffffff8b9d1ff8 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff83d28810
R13: ffffffff8961f2b0 R14: dffffc0000000000 R15: 0000000000000101
vprintk_emit+0x224/0x620 kernel/printk/printk.c:1925
vprintk_func+0x58/0x160 kernel/printk/printk_safe.c:409
printk+0x9e/0xbc kernel/printk/printk.c:1998
kauditd_printk_skb kernel/audit.c:506 [inline]
kauditd_hold_skb.cold+0x3f/0x4e kernel/audit.c:541
kauditd_send_queue+0x189/0x1b0 kernel/audit.c:726
kauditd_thread+0x4a5/0x630 kernel/audit.c:850
kthread+0x30d/0x420 kernel/kthread.c:232
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:406
xt_conntrack: cannot load conntrack support for proto=2
NILFS (loop3): segctord starting. Construction interval = 5 seconds, CP frequency < 30 seconds
xt_conntrack: cannot load conntrack support for proto=2
audit: type=1800 audit(1677356202.098:8): pid=10842 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.5" name="file0" dev="sda1" ino=14069 res=0
xt_conntrack: cannot load conntrack support for proto=2
NILFS (loop3): segctord starting. Construction interval = 5 seconds, CP frequency < 30 seconds
audit: type=1804 audit(1677356202.098:9): pid=10842 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.5" name="/root/syzkaller-testdir2225182600/syzkaller.7IFxHS/30/file0" dev="sda1" ino=14069 res=1
audit: type=1800 audit(1677356202.098:10): pid=10844 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.4" name="file0" dev="sda1" ino=14070 res=0
audit: type=1804 audit(1677356202.108:11): pid=10844 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.4" name="/root/syzkaller-testdir535438970/syzkaller.tAnOLg/41/file0" dev="sda1" ino=14070 res=1
NILFS (loop0): segctord starting. Construction interval = 5 seconds, CP frequency < 30 seconds
audit: type=1800 audit(1677356203.038:12): pid=10864 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.5" name="file0" dev="sda1" ino=14075 res=0
audit: type=1804 audit(1677356203.038:13): pid=10864 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.5" name="/root/syzkaller-testdir2225182600/syzkaller.7IFxHS/31/file0" dev="sda1" ino=14075 res=1
NILFS (loop3): segctord starting. Construction interval = 5 seconds, CP frequency < 30 seconds
audit: type=1800 audit(1677356203.038:14): pid=10866 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.4" name="file0" dev="sda1" ino=14076 res=0
NILFS (loop3): segctord starting. Construction interval = 5 seconds, CP frequency < 30 seconds
audit: type=1804 audit(1677356203.048:15): pid=10866 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.4" name="/root/syzkaller-testdir535438970/syzkaller.tAnOLg/42/file0" dev="sda1" ino=14076 res=1
NILFS (loop0): segctord starting. Construction interval = 5 seconds, CP frequency < 30 seconds
audit: type=1800 audit(1677356203.918:16): pid=10885 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.5" name="file0" dev="sda1" ino=14076 res=0
audit: type=1804 audit(1677356203.918:17): pid=10885 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.5" name="/root/syzkaller-testdir2225182600/syzkaller.7IFxHS/32/file0" dev="sda1" ino=14076 res=1
audit: type=1800 audit(1677356203.928:18): pid=10886 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.4" name="file0" dev="sda1" ino=14081 res=0
audit: type=1804 audit(1677356203.928:19): pid=10886 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.4" name="/root/syzkaller-testdir535438970/syzkaller.tAnOLg/43/file0" dev="sda1" ino=14081 res=1
NILFS (loop0): segctord starting. Construction interval = 5 seconds, CP frequency < 30 seconds
audit: type=1800 audit(1677356204.488:20): pid=10901 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.1" name="file0" dev="sda1" ino=14072 res=0
audit: type=1804 audit(1677356204.498:21): pid=10901 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.1" name="/root/syzkaller-testdir1629043744/syzkaller.bEp7LY/34/file0" dev="sda1" ino=14072 res=1
audit: type=1800 audit(1677356204.738:22): pid=10903 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.5" name="file0" dev="sda1" ino=14073 res=0
bridge: RTM_NEWNEIGH with invalid ether address
audit: type=1804 audit(1677356204.738:23): pid=10903 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.5" name="/root/syzkaller-testdir2225182600/syzkaller.7IFxHS/33/file0" dev="sda1" ino=14073 res=1
bridge: RTM_NEWNEIGH with invalid ether address
9pnet_virtio: no channels available for device 127.0.0.1
bridge: RTM_NEWNEIGH with invalid ether address
bridge: RTM_NEWNEIGH with invalid ether address
9pnet_virtio: no channels available for device 127.0.0.1
9pnet_virtio: no channels available for device 127.0.0.1
9pnet_virtio: no channels available for device 127.0.0.1
9pnet_virtio: no channels available for device 127.0.0.1
9pnet_virtio: no channels available for device 127.0.0.1
9pnet_virtio: no channels available for device 127.0.0.1
9pnet_virtio: no channels available for device 127.0.0.1
9pnet_virtio: no channels available for device 127.0.0.1
9pnet_virtio: no channels available for device 127.0.0.1
9pnet_virtio: no channels available for device 127.0.0.1