| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20171215195146.cqzlol3ld5qafprt@inn>
Date: Sat, 16 Dec 2017 03:51:46 +0800
From: kernel test robot <fengguang.wu@...el.com>
To: Eric Dumazet <eric.dumazet@...il.com>
Cc: David Miller <davem@...emloft.net>,
netdev <netdev@...r.kernel.org>, lkp@...org
Subject: [tcp] dc37ac1840: WARNING:inconsistent_lock_state
FYI, we noticed the following commit (built with gcc-7):
commit: dc37ac18402fcfc98d80ed009ed73042252b2dda ("Revert "tcp: must block bh in __inet_twsk_hashdance()"")
url: https://github.com/0day-ci/linux/commits/Eric-Dumazet/Revert-tcp-must-block-bh-in-__inet_twsk_hashdance/20171205-020634
in testcase: boot
on test machine: qemu-system-x86_64 -enable-kvm -cpu host -smp 2 -m 1G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+-------------------------------------------------------+------------+------------+
| | f6454f80e8 | dc37ac1840 |
+-------------------------------------------------------+------------+------------+
| boot_successes | 27 | 15 |
| boot_failures | 0 | 11 |
| WARNING:inconsistent_lock_state | 0 | 8 |
| inconsistent{IN-SOFTIRQ-W}->{SOFTIRQ-ON-W}usage | 0 | 8 |
| RIP:_raw_spin_unlock_irqrestore | 0 | 1 |
| WARNING:possible_circular_locking_dependency_detected | 0 | 2 |
+-------------------------------------------------------+------------+------------+
[ 44.184799] WARNING: inconsistent lock state
[ 44.186120] 4.14.0-13367-gdc37ac1 #56 Not tainted
[ 44.187320] --------------------------------
[ 44.188597] inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage.
[ 44.190145] curl/7587 [HC0[0]:SC0[0]:HE1:SE1] takes:
[ 44.191354] (&(&tcp_hashinfo.bhash[i].lock)->rlock){+.?.}, at: [<ffffffffbbc434c2>] __inet_twsk_hashdance+0x4a/0x100
[ 44.194104] {IN-SOFTIRQ-W} state was registered at:
[ 44.210346] _raw_spin_lock+0x30/0x61
[ 44.211575] __inet_twsk_hashdance+0x4a/0x100
[ 44.212627] tcp_time_wait+0x1a6/0x1d7
[ 44.213565] tcp_rcv_state_process+0xbf4/0xd3e
[ 44.214638] tcp_v4_do_rcv+0x112/0x130
[ 44.215822] tcp_v4_rcv+0x693/0xa81
[ 44.216757] ip_local_deliver_finish+0x1ca/0x2e6
[ 44.217786] ip_local_deliver+0x1b3/0x1c6
[ 44.218982] ip_rcv+0x3f4/0x432
[ 44.220108] __netif_receive_skb_core+0x8ab/0x921
[ 44.221237] netif_receive_skb_internal+0x270/0x2da
[ 44.222328] napi_gro_receive+0x147/0x17d
[ 44.223572] e1000_clean_rx_irq+0x2e1/0x3ee
[ 44.224602] e1000_clean+0x541/0x693
[ 44.225549] net_rx_action+0x14c/0x3e7
[ 44.226510] __do_softirq+0x204/0x427
[ 44.227661] run_ksoftirqd+0x21/0x76
[ 44.228603] smpboot_thread_fn+0x1a9/0x1c0
[ 44.229507] kthread+0x160/0x168
[ 44.230367] ret_from_fork+0x24/0x30
[ 44.231545] irq event stamp: 10517
[ 44.232429] hardirqs last enabled at (10517): [<ffffffffbbd5fa72>] _raw_spin_unlock_irqrestore+0x44/0x58
[ 44.234341] hardirqs last disabled at (10516): [<ffffffffbbd5f87c>] _raw_spin_lock_irqsave+0x22/0x7f
[ 44.236739] softirqs last enabled at (10512): [<ffffffffbbd63d5b>] __do_softirq+0x3eb/0x427
[ 44.238619] softirqs last disabled at (10495): [<ffffffffbbd611aa>] do_softirq_own_stack+0x2a/0x40
[ 44.240765]
[ 44.240765] other info that might help us debug this:
[ 44.242296] Possible unsafe locking scenario:
[ 44.242296]
[ 44.244132] CPU0
[ 44.244914] ----
[ 44.245592] lock(&(&tcp_hashinfo.bhash[i].lock)->rlock);
[ 44.246740] <Interrupt>
[ 44.247735] lock(&(&tcp_hashinfo.bhash[i].lock)->rlock);
[ 44.248851]
[ 44.248851] *** DEADLOCK ***
[ 44.248851]
[ 44.250828] 1 lock held by curl/7587:
[ 44.251970] #0: (sk_lock-AF_INET){+.+.}, at: [<ffffffffbbc49c1c>] tcp_close+0x18/0x392
[ 44.253672]
[ 44.253672] stack backtrace:
[ 44.255076] CPU: 0 PID: 7587 Comm: curl Not tainted 4.14.0-13367-gdc37ac1 #56
[ 44.256625] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 44.258549] Call Trace:
[ 44.259499] dump_stack+0x85/0xbc
[ 44.260457] mark_lock+0x38b/0x4de
[ 44.261447] __lock_acquire+0x3de/0x10f5
[ 44.262643] lock_acquire+0x195/0x1c7
[ 44.263768] ? __inet_twsk_hashdance+0x4a/0x100
[ 44.265051] _raw_spin_lock+0x30/0x61
[ 44.266086] ? __inet_twsk_hashdance+0x4a/0x100
[ 44.267241] __inet_twsk_hashdance+0x4a/0x100
[ 44.268470] tcp_time_wait+0x1a6/0x1d7
[ 44.269460] tcp_fin+0x6e/0x331
[ 44.270534] tcp_data_queue+0x13a/0x926
[ 44.271729] tcp_rcv_state_process+0xcb5/0xd3e
[ 44.272889] ? __schedule+0x9ee/0xa43
[ 44.273903] ? tcp_v4_do_rcv+0x112/0x130
[ 44.274950] tcp_v4_do_rcv+0x112/0x130
[ 44.276182] __release_sock+0xa7/0xe3
[ 44.277199] release_sock+0x2b/0x9e
[ 44.278319] tcp_close+0x1c5/0x392
[ 44.279368] inet_release+0x4c/0x51
[ 44.280388] sock_release+0x1a/0x71
[ 44.281357] sock_close+0xe/0x11
[ 44.282316] __fput+0xf3/0x1ac
[ 44.283371] task_work_run+0x79/0xa0
[ 44.284486] exit_to_usermode_loop+0x5e/0x8d
[ 44.285637] syscall_return_slowpath+0x102/0x115
[ 44.286774] entry_SYSCALL_64_fastpath+0x94/0x96
[ 44.288120] RIP: 0033:0x7fd97149a18d
[ 44.289280] RSP: 002b:00007ffe5571a8e0 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
[ 44.291494] RAX: 0000000000000000 RBX: 000055856d304600 RCX: 00007fd97149a18d
[ 44.293010] RDX: 0000000000000000 RSI: 0000000000000004 RDI: 0000000000000004
[ 44.294505] RBP: 0000000000000004 R08: 000055856d2d29b0 R09: 00007fd971d4b700
[ 44.296192] R10: 0000000000000002 R11: 0000000000000293 R12: 0000000000000000
[ 44.297867] R13: 00007ffe5571ab18 R14: 0000000000000000 R15: 0000000000000000
[ 44.484870] /usr/bin/curl -sSf http://inn:80/~lkp/cgi-bin/lkp-jobfile-append-var?job_file=/lkp/scheduled/vm-lkp-hsw01-1G-2/boot-1-debian-x86_64-2016-08-31.cgz-dc37ac18402fcfc98d80ed009ed73042252b2dda-20171216-58701-yuk48v-2.yaml&loadavg=0.81%200.23%200.08%201/98%207600&start_time=1513354011&end_time=1513354012&version=/lkp/lkp/.src-20171215-153827& -o /dev/null
[ 44.484884]
[ 44.853238] /usr/bin/curl -sSf http://inn:80/~lkp/cgi-bin/lkp-jobfile-append-var?job_file=/lkp/scheduled/vm-lkp-hsw01-1G-2/boot-1-debian-x86_64-2016-08-31.cgz-dc37ac18402fcfc98d80ed009ed73042252b2dda-20171216-58701-yuk48v-2.yaml&job_state=finished -o /dev/null
[ 44.853253]
[ 45.224575] LKP: rebooting
[ 45.224585]
Elapsed time: 50
#!/bin/bash
# To reproduce,
# 1) save job-script and this script (both are attached in 0day report email)
# 2) run this script with your compiled kernel and optional env $INSTALL_MOD_PATH
kernel=$1
To reproduce:
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
Thanks,
lkp
View attachment "config-4.14.0-13367-gdc37ac1" of type "text/plain" (119542 bytes)
View attachment "job-script" of type "text/plain" (4199 bytes)
Download attachment "dmesg.xz" of type "application/x-xz" (17208 bytes)
Powered by blists - more mailing lists