linux-kernel - Re: [sock_def_readable] WARNING: bad unlock balance detected!

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
Hash Suite for Android: free password hash cracker in your pocket
[<prev] [next>] [<thread-prev] [day] [month] [year] [list]
Message-ID: <20171107123029.s3mtvajiyj6hgdgv@wfg-t540p.sh.intel.com>
Date:   Tue, 7 Nov 2017 20:30:29 +0800
From:   Fengguang Wu <fengguang.wu@...el.com>
To:     netdev@...r.kernel.org
Cc:     linux-kernel@...r.kernel.org,
        Linus Torvalds <torvalds@...ux-foundation.org>,
        Pavel Emelyanov <xemul@...nvz.org>,
        "David S. Miller" <davem@...emloft.net>,
        Eric Dumazet <edumazet@...gle.com>,
        Peter Zijlstra <peterz@...radead.org>
Subject: Re: [sock_def_readable] WARNING: bad unlock balance detected!

Sorry please ignore this report -- according to Peter:

This is fixed by commit:

  02a7c234e540 ("rcu: Suppress lockdep false-positive ->boost_mtx complaints")

The problem is that RCU boosting was mixing futex and !futex rt_mutex
ops.

On Tue, Nov 07, 2017 at 12:34:15PM +0800, Fengguang Wu wrote:
>FYI, this warning shows up in both v4.14-rc8 and v4.13:
>
>[  144.578809] br-lan: port 1(eth0) entered disabled state
>[  144.581360] device eth0 left promiscuous mode
>[  144.582699] br-lan: port 1(eth0) entered disabled state
>[  144.685012]
>[  144.685370] =====================================
>[  144.686093] WARNING: bad unlock balance detected!
>[  144.686816] 4.14.0-rc8 #158 Not tainted
>[  144.687420] -------------------------------------
>[  144.688132] ubus/19703 is trying to release lock (rcu_preempt_state) at:
>[  144.688911] [<c10e4348>] rcu_read_unlock_special+0x5f8/0x620
>[  144.689621] but there are no more locks to release!
>[  144.690374]
>[  144.690374] other info that might help us debug this:
>[  144.691407] 1 lock held by ubus/19703:
>[  144.692009]  #0:  (rcu_read_lock){....}, at: [<c2f043d0>] sock_def_readable+0x0/0x100
>[  144.693212]
>[  144.693212] stack backtrace:
>[  144.693980] CPU: 0 PID: 19703 Comm: ubus Not tainted 4.14.0-rc8 #158
>[  144.694923] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>[  144.696168] Call Trace:
>[  144.696632]  dump_stack+0x16/0x1c
>[  144.697195]  print_unlock_imbalance_bug+0xb9/0xd0
>[  144.697940]  ? rcu_read_unlock_special+0x5f8/0x620
>[  144.698673]  ? rcu_read_unlock_special+0x5f8/0x620
>[  144.699390]  lock_release+0x1cc/0x490
>[  144.699990]  ? rcu_gp_kthread_wake+0x34/0x50
>[  144.700678]  ? rcu_read_unlock_special+0x5f8/0x620
>[  144.701431]  rt_mutex_unlock+0x1e/0xb0
>[  144.702048]  rcu_read_unlock_special+0x5f8/0x620
>[  144.702774]  __rcu_read_unlock+0xa7/0xb0
>[  144.703422]  sock_def_readable+0xd1/0x100
>[  144.704073]  unix_stream_sendmsg+0x2d1/0x4d0
>[  144.704755]  sock_sendmsg+0x2d/0x70
>[  144.705334]  ___sys_sendmsg+0x390/0x3a0
>[  144.705963]  ? kvm_clock_read+0x31/0x80
>[  144.706569]  ? kvm_sched_clock_read+0x9/0x20
>[  144.707250]  ? sched_clock+0x9/0x10
>[  144.707834]  ? sched_clock_cpu+0x1a/0x1e0
>[  144.708473]  ? pvclock_clocksource_read+0xd5/0x230
>[  144.709216]  ? kvm_clock_read+0x31/0x80
>[  144.709850]  ? kvm_sched_clock_read+0x9/0x20
>[  144.710526]  ? sched_clock+0x9/0x10
>[  144.711082]  ? sched_clock_cpu+0x1a/0x1e0
>[  144.711714]  ? __fget_light+0xb7/0xf0
>[  144.712301]  ? sockfd_lookup_light+0xd3/0x120
>[  144.713002]  __sys_sendmsg+0x59/0x90
>[  144.713585]  SyS_socketcall+0x9e4/0xb20
>[  144.714204]  do_int80_syscall_32+0x95/0x290
>[  144.714883]  entry_INT80_32+0x2f/0x2f
>[  144.715491] EIP: 0xb7f3e595
>[  144.715985] EFLAGS: 00000292 CPU: 0
>[  144.716566] EAX: ffffffda EBX: 00000010 ECX: bffff678 EDX: b7f83ff4
>[  144.717474] ESI: bffff678 EDI: bffff6c4 EBP: bffff708 ESP: bffff668
>[  144.718374]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b
>procd: - reboot -
>[  145.174700] Unregister pv shared memory for cpu 0
>
>Here is another one, called from unix_stream_connect():
>
>Please press Enter to activate this console.
>[   46.373661] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
>[   46.376639] 8021q: adding VLAN 0 to HW filter on device eth0
>[   46.507035]
>[   46.507329] =====================================
>[   46.507940] WARNING: bad unlock balance detected!
>[   46.508543] 4.14.0-rc8 #158 Not tainted
>[   46.509048] -------------------------------------
>[   46.509648] fw3/1185 is trying to release lock (rcu_preempt_state) at:
>[   46.510452] [<c10e4348>] rcu_read_unlock_special+0x5f8/0x620
>[   46.511147] but there are no more locks to release!
>[   46.511766]
>[   46.511766] other info that might help us debug this:
>[   46.512591] 1 lock held by fw3/1185:
>[   46.513070]  #0:  (rcu_read_lock){....}, at: [<c2f043d0>] sock_def_readable+0x0/0x100
>[   46.514074]
>[   46.514074] stack backtrace:
>[   46.514684] CPU: 0 PID: 1185 Comm: fw3 Not tainted 4.14.0-rc8 #158
>[   46.515440] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>[   46.516463] Call Trace:
>[   46.516831]  dump_stack+0x16/0x1c
>[   46.517288]  print_unlock_imbalance_bug+0xb9/0xd0
>[   46.517896]  ? rcu_read_unlock_special+0x5f8/0x620
>[   46.518512]  ? rcu_read_unlock_special+0x5f8/0x620
>[   46.519113]  lock_release+0x1cc/0x490
>[   46.519604]  ? rcu_read_unlock_special+0x5f8/0x620
>[   46.520208]  ? _raw_spin_unlock_irqrestore+0x86/0xd0
>[   46.520840]  rt_mutex_unlock+0x1e/0xb0
>[   46.521341]  rcu_read_unlock_special+0x5f8/0x620
>[   46.521936]  __rcu_read_unlock+0xa7/0xb0
>[   46.522460]  sock_def_readable+0xd1/0x100
>[   46.522993]  unix_stream_connect+0x633/0x680
>[   46.523552]  SYSC_connect+0x107/0x120
>[   46.524046]  SyS_socketcall+0x384/0xb20
>[   46.524562]  ? SyS_fcntl64+0x103/0x2e0
>[   46.525060]  do_int80_syscall_32+0x95/0x290
>[   46.525610]  entry_INT80_32+0x2f/0x2f
>[   46.526099] EIP: 0xb7e97384
>[   46.526505] EFLAGS: 00000296 CPU: 0
>[   46.526977] EAX: ffffffda EBX: 00000003 ECX: bf988038 EDX: b7edd000
>[   46.527741] ESI: bf988038 EDI: bf9880e0 EBP: bf988098 ESP: bf988028
>[   46.528505]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b
>[   46.607747] 8021q: adding VLAN 0 to HW filter on device eth0
>LKP: HOSTNAME vm-lkp-nhm-dp1-openwrt-ia32-6, MAC , kernel 4.14.0-rc8 158, serial console /dev/ttyS0
>
>Here is the call trace in older v4.13 kernel:
>
>Please press Enter to activate this console.
>[   85.464260] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
>[   85.470410] 8021q: adding VLAN 0 to HW filter on device eth0
>[   85.585813]
>[   85.586196] =====================================
>[   85.586870] WARNING: bad unlock balance detected!
>[   85.587555] 4.13.0 #1 Not tainted
>[   85.588098] -------------------------------------
>[   85.588792] ubus/1179 is trying to release lock (rcu_preempt_state) at:
>[   85.589707] [<c10e5840>] rcu_read_unlock_special+0x580/0x5b0
>[   85.590494] but there are no more locks to release!
>[   85.591196]
>[   85.591196] other info that might help us debug this:
>[   85.592201] 1 lock held by ubus/1179:
>[   85.592781]  #0:  (rcu_read_lock){......}, at: [<c2eadff0>] sock_def_readable+0x0/0x100
>[   85.593930]
>[   85.593930] stack backtrace:
>[   85.594694] CPU: 0 PID: 1179 Comm: ubus Not tainted 4.13.0 #1
>[   85.595474] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>[   85.596647] Call Trace:
>[   85.597091]  dump_stack+0x16/0x1c
>[   85.597626]  print_unlock_imbalance_bug+0xb9/0xd0
>[   85.598309]  ? rcu_read_unlock_special+0x580/0x5b0
>[   85.599009]  ? rcu_read_unlock_special+0x580/0x5b0
>[   85.599713]  lock_release+0x1cc/0x490
>[   85.600320]  ? rcu_gp_kthread_wake+0x34/0x50
>[   85.600968]  ? rcu_read_unlock_special+0x580/0x5b0
>[   85.601653]  rt_mutex_unlock+0x1e/0xb0
>[   85.602227]  rcu_read_unlock_special+0x580/0x5b0
>[   85.602893]  __rcu_read_unlock+0xa7/0xb0
>[   85.603490]  sock_def_readable+0xd1/0x100
>[   85.604093]  unix_stream_connect+0x633/0x680
>[   85.604724]  SYSC_connect+0x107/0x120
>[   85.605290]  SyS_socketcall+0x384/0xb20
>[   85.605871]  ? SyS_fcntl64+0x103/0x2e0
>[   85.606446]  do_int80_syscall_32+0x95/0x1b0
>[   85.607063]  entry_INT80_32+0x2f/0x2f
>[   85.607639] EIP: 0xb7f21384
>[   85.608131] EFLAGS: 00000296 CPU: 0
>[   85.608678] EAX: ffffffda EBX: 00000003 ECX: bf923748 EDX: b7f67000
>[   85.609519] ESI: bf923748 EDI: bf9237f0 EBP: bf9237a8 ESP: bf923738
>[   85.610353]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b
>[   85.686243] 8021q: adding VLAN 0 to HW filter on device eth0
>LKP: HOSTNAME vm-intel12-openwrt-i386-5, MAC , kernel 4.13.0 1, serial console /dev/ttyS0
>[   87.726663] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
>[   87.852942] 8021q: adding VLAN 0 to HW filter on device eth0
>
>Thanks,
>Fengguang