* [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks
@ 2015-06-23 16:59 Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 1/8] Bluetooth: L2CAP ERTM shutdown protect sk and chan Dean Jenkins
` (8 more replies)
0 siblings, 9 replies; 23+ messages in thread
From: Dean Jenkins @ 2015-06-23 16:59 UTC (permalink / raw)
To: linux-bluetooth
Cc: marcel, gustavo, johan.hedberg, Joshua_Frkuska, Dean Jenkins
Details of the issue are described in the thread
[RFC] Bluetooth ERTM L2CAP deadlocks (hung tasks) due to l2cap_sock_shutdown()
and kernel.org Bugzilla https://bugzilla.kernel.org/show_bug.cgi?id=99301
Summary
=======
a) __l2cap_wait_ack() gets stuck in an infinite loop whilst waiting for
I frame acknowledgements (ACK is S or I frame from the remote device).
The infinite loop occurs because the waiting loop's condition never becomes
false. __l2cap_wait_ack() periodically sleeps for upto 200ms as
timeo = schedule_timeout(timeo); may return early with no signal event,
so is unclear why it wakes-up early.
b) The L2CAP threads for processing received frames and error recovery
timers become blocked on a mutex held by l2cap_sock_shutdown() which
prevents updating of the loop condition in __l2cap_wait_ack().
Therefore a deadlock occurs with mutex_lock(&conn->chan_lock).
This deadlock was observed by us on kernels 3.8 upto bluetooth-next on x86 and
ARM based platforms including the Raspberry Pi kernel 3.18.14+
The testcase is simple to reproduce the hung tasks, please wait upto 10 minutes
to observe the hung tasks:
On a laptop or other suitable device use the command:
l2test -i hci0 -X ertm -d
This command listens for connections with optional L2CAP ERTM supported and
dumps out the received data.
On the unit under test use the command:
l2test -s -b 1024 -B /dev/urandom -X ertm -P 4113 <lap_BT_ADDR>
This command sends 1024 bytes to the laptop via PSM 4113 used by l2test over
an ERTM channel. The command line shows:
l2test -s -b 1024 -B /dev/urandom -X ertm -P 4113 5C:F3:70:68:BA:DD
l2test[10366]: Connected to 5C:F3:70:68:BA:DD (bredr, psm 4113, scid 64)
l2test[10366]: Local device 5C:F3:70:68:BA:DA (bredr, psm 4113, scid 64)
l2test[10366]: Options [imtu 672, omtu 672, flush_to 65535, mode 3, handle 11, class 0x000000, priority 0, rcvbuf 163840]
l2test[10366]: Sending ...
l2test[10366]: Closing channel ...
Note that the channel fails to close because l2cap_sock_shutdown() is prevented
from returning due to __l2cap_wait_ack being stuck in an infinite loop.
Example hung tasks are:
[ 601.116119] INFO: task kworker/0:1:19 blocked for more than 120 seconds.
[ 601.116156] Not tainted 3.18.11+ #781
[ 601.116169] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 601.116183] kworker/0:1 D c054cbcc 0 19 2 0x00000000
[ 601.116537] Workqueue: events l2cap_retrans_timeout [bluetooth]
[ 601.116685] [<c054cbcc>] (__schedule) from [<c054cfa4>] (schedule+0x40/0x8c)
[ 601.116727] [<c054cfa4>] (schedule) from [<c054d3c8>] (schedule_preempt_disabled+0x30/0x40)
[ 601.116812] [<c054d3c8>] (schedule_preempt_disabled) from [<c054ee14>] (__mutex_lock_slowpath+0xb8/0x18c)
[ 601.116856] [<c054ee14>] (__mutex_lock_slowpath) from [<c054ef20>] (mutex_lock+0x38/0x3c)
[ 601.117085] [<c054ef20>] (mutex_lock) from [<bf05173c>] (l2cap_retrans_timeout+0x24/0x5c [bluetooth])
[ 601.117371] [<bf05173c>] (l2cap_retrans_timeout [bluetooth]) from [<c003aa68>] (process_one_work+0x13c/0x444)
[ 601.117410] [<c003aa68>] (process_one_work) from [<c003b954>] (worker_thread+0x190/0x580)
[ 601.117445] [<c003b954>] (worker_thread) from [<c003fdb4>] (kthread+0xd8/0xf4)
[ 601.117488] [<c003fdb4>] (kthread) from [<c000e8c8>] (ret_from_fork+0x14/0x20)
[ 601.117569] INFO: task kworker/u3:2:327 blocked for more than 120 seconds.
[ 601.117588] Not tainted 3.18.11+ #781
[ 601.117601] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 601.117614] kworker/u3:2 D c054cbcc 0 327 2 0x00000000
[ 601.117806] Workqueue: hci0 hci_rx_work [bluetooth]
[ 601.117941] [<c054cbcc>] (__schedule) from [<c054cfa4>] (schedule+0x40/0x8c)
[ 601.117981] [<c054cfa4>] (schedule) from [<c054d3c8>] (schedule_preempt_disabled+0x30/0x40)
[ 601.118056] [<c054d3c8>] (schedule_preempt_disabled) from [<c054ee14>] (__mutex_lock_slowpath+0xb8/0x18c)
[ 601.118092] [<c054ee14>] (__mutex_lock_slowpath) from [<c054ef20>] (mutex_lock+0x38/0x3c)
[ 601.118307] [<c054ef20>] (mutex_lock) from [<bf04d2c8>] (l2cap_get_chan_by_scid+0x28/0x98 [bluetooth])
[ 601.118696] [<bf04d2c8>] (l2cap_get_chan_by_scid [bluetooth]) from [<bf054590>] (l2cap_recv_frame+0xa4/0x2cec [bluetooth])
[ 601.119146] [<bf054590>] (l2cap_recv_frame [bluetooth]) from [<bf058194>] (l2cap_recv_acldata+0x214/0x22c [bluetooth])
[ 601.119559] [<bf058194>] (l2cap_recv_acldata [bluetooth]) from [<bf02bf88>] (hci_rx_work+0x180/0x288 [bluetooth])
[ 601.119801] [<bf02bf88>] (hci_rx_work [bluetooth]) from [<c003aa68>] (process_one_work+0x13c/0x444)
[ 601.119839] [<c003aa68>] (process_one_work) from [<c003b954>] (worker_thread+0x190/0x580)
[ 601.119883] [<c003b954>] (worker_thread) from [<c003fdb4>] (kthread+0xd8/0xf4)
[ 601.119919] [<c003fdb4>] (kthread) from [<c000e8c8>] (ret_from_fork+0x14/0x20)
This is not an exhaustive list, there are other hung task flavours.
Solution
========
The solution is to reorganise l2cap_sock_shutdown() to reveal the purpose of
the function. The function shuts down the L2CAP channel but in the case when the
channel type is ERTM, __l2cap_wait_ack() is called to wait for acknowledgements
before the channel is shutdown.
There is some concurrency protection by using a lock on sk to prevent
multiple instances of l2cap_sock_shutdown() from running.
SHUTDOWN_MASK is used to inhibit new I frames and other PDUs from being
queued. Setting this flag was moved to before calling __l2cap_wait_ack() so that
the loop would not be waiting indefinitely for ACKs. There is some risk here
of not sending all pending data, however, an arbitrary cut-off point is needed
otherwise the shutdown could be held off during periods of heavy traffic. This
may need improving to inhibit only new I frames.
Extra protection to the sk and chan structures was added to prevent those
structures being freed whilst the locks were not held. This is defensive and
perhaps unnecessary.
__l2cap_wait_ack() was modified to be only called when necessary and the
while loop was replaced by a do while loop because there must be at least 1
waiting period. References to chan->conn were replaced by chan->state so that
the mutex locks could be removed. Also waiting for ACKs is only valid whilst the
connection is in the BT_CONNECTED state.
The scope of chan locking was reduced so that processing of received frames
and error handling routines could operate whilst waiting for ACKs.
Additionally, for __l2cap_wait_ack() a 10 second maximum wait limit was
implemented to prevent __l2cap_wait_ack() getting stuck in an infinite loop.
If no expected ACKs arrive then the channel is disconnected and the error
code -ENOLINK is returned to indicate that not all data was ACK'ed.
Testing
=======
This has been tested in kernels 3.8 and 3.14 on an ARM based board for a
commercial product. Results show that the hung tasks no longer occur.
Note that the failure scenario was Media player media browsing. Waiting for
ACK's is unimportant in this scenario because it does not matter whether
a media browsing request such as "get item" was successfully transferred at the
point of shutting down the channel.
These v2 patches have not been tested on a bluetooth-next based build. However,
sjanc on the Bluetooth IRC channel tested the v1 patches using the PTS testcases
and found no regressions. If v2 were to be tested, then similar results to v1
should be seen.
v2 changes
==========
0007-Bluetooth-__l2cap_wait_ack-use-msecs_to_jiffies.patch was introduced
to tidy-up the original code's use of HZ. Now msecs_to_jiffies() is used
instead of HZ. This was done in response to review comments.
0008-Bluetooth-__l2cap_wait_ack-add-defensive-timeout.patch was introduced
to replace the v1 0007 patch. The solution now uses a 10 second jiffy based
timeout mechanism instead of a loop counter limit. The new solution is more
accurate and easier to maintain than the loop counter limit.
Risks
=====
The mutex lock mutex_lock(&conn->chan_lock) has been removed whilst
l2cap_chan_close() runs in l2cap_sock_shutdown(). l2cap_chan_lock(chan) is
protecting l2cap_chan_close() against concurrent procedural handling events for
the channel at the L2CAP level.
Analysis indicates chan->conn is used as an indication that the underlying ACL
connection is still up. l2cap_chan_del() sets chan->conn = NULL and all calls to
l2cap_chan_del() seem to be done with the l2cap_chan_lock(chan) held. Therefore,
it should not be possible for chan->conn to become unexpectedly NULL during the
execution of l2cap_chan_close(). The locking seems to be sufficient.
Patchset
========
Patches are based on bluetooth-next:
Dean Jenkins (8):
Bluetooth: L2CAP ERTM shutdown protect sk and chan
Bluetooth: Make __l2cap_wait_ack more efficient
Bluetooth: Unwind l2cap_sock_shutdown()
Bluetooth: l2cap_sock_shutdown() remove mutex_lock calls
Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking
Bluetooth: Add BT_DBG to l2cap_sock_shutdown()
Bluetooth: __l2cap_wait_ack() use msecs_to_jiffies()
Bluetooth: __l2cap_wait_ack() add defensive timeout
include/net/bluetooth/l2cap.h | 2 ++
net/bluetooth/l2cap_sock.c | 74 +++++++++++++++++++++++++++----------------
2 files changed, 49 insertions(+), 27 deletions(-)
--
1.8.5.6
^ permalink raw reply [flat|nested] 23+ messages in thread
* [PATCH v2 1/8] Bluetooth: L2CAP ERTM shutdown protect sk and chan
2015-06-23 16:59 [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Dean Jenkins
@ 2015-06-23 16:59 ` Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 2/8] Bluetooth: Make __l2cap_wait_ack more efficient Dean Jenkins
` (7 subsequent siblings)
8 siblings, 0 replies; 23+ messages in thread
From: Dean Jenkins @ 2015-06-23 16:59 UTC (permalink / raw)
To: linux-bluetooth
Cc: marcel, gustavo, johan.hedberg, Joshua_Frkuska, Dean Jenkins,
Kautuk Consul
During execution of l2cap_sock_shutdown() which might
sleep, the sk and chan structures can be in an unlocked
condition which potentially allows the structures to be
freed by other running threads. Therefore, there is a
possibility of a malfunction or memory reuse after being
freed.
Keep the sk and chan structures alive during the
execution of l2cap_sock_shutdown() by using their
respective hold and put functions. This allows the structures
to be freeable at the end of l2cap_sock_shutdown().
Signed-off-by: Kautuk Consul <Kautuk_Consul@mentor.com>
Signed-off-by: Dean Jenkins <Dean_Jenkins@mentor.com>
---
net/bluetooth/l2cap_sock.c | 8 ++++++++
1 file changed, 8 insertions(+)
diff --git a/net/bluetooth/l2cap_sock.c b/net/bluetooth/l2cap_sock.c
index 2442877..3794c23 100644
--- a/net/bluetooth/l2cap_sock.c
+++ b/net/bluetooth/l2cap_sock.c
@@ -1098,7 +1098,12 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
if (!sk)
return 0;
+ /* prevent sk structure from being freed whilst unlocked */
+ sock_hold(sk);
+
chan = l2cap_pi(sk)->chan;
+ /* prevent chan structure from being freed whilst unlocked */
+ l2cap_chan_hold(chan);
conn = chan->conn;
BT_DBG("chan %p state %s", chan, state_to_string(chan->state));
@@ -1134,6 +1139,9 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
if (conn)
mutex_unlock(&conn->chan_lock);
+ l2cap_chan_put(chan);
+ sock_put(sk);
+
return err;
}
--
1.8.5.6
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 2/8] Bluetooth: Make __l2cap_wait_ack more efficient
2015-06-23 16:59 [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 1/8] Bluetooth: L2CAP ERTM shutdown protect sk and chan Dean Jenkins
@ 2015-06-23 16:59 ` Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 3/8] Bluetooth: Unwind l2cap_sock_shutdown() Dean Jenkins
` (6 subsequent siblings)
8 siblings, 0 replies; 23+ messages in thread
From: Dean Jenkins @ 2015-06-23 16:59 UTC (permalink / raw)
To: linux-bluetooth
Cc: marcel, gustavo, johan.hedberg, Joshua_Frkuska, Dean Jenkins
Use chan->state instead of chan->conn because waiting
for ACK's is only possible in the BT_CONNECTED state.
Also avoids reference to the conn structure so makes
locking easier.
Only call __l2cap_wait_ack() when the needed condition
of chan->unacked_frames > 0 && chan->state == BT_CONNECTED
is true and convert the while loop to a do while loop.
__l2cap_wait_ack() change the function prototype to
pass in the chan variable as chan is already available
in the calling function l2cap_sock_shutdown(). Avoids
locking issues.
Signed-off-by: Dean Jenkins <Dean_Jenkins@mentor.com>
---
net/bluetooth/l2cap_sock.c | 16 ++++++++++------
1 file changed, 10 insertions(+), 6 deletions(-)
diff --git a/net/bluetooth/l2cap_sock.c b/net/bluetooth/l2cap_sock.c
index 3794c23..2904288 100644
--- a/net/bluetooth/l2cap_sock.c
+++ b/net/bluetooth/l2cap_sock.c
@@ -1054,16 +1054,15 @@ static void l2cap_sock_kill(struct sock *sk)
sock_put(sk);
}
-static int __l2cap_wait_ack(struct sock *sk)
+static int __l2cap_wait_ack(struct sock *sk, struct l2cap_chan *chan)
{
- struct l2cap_chan *chan = l2cap_pi(sk)->chan;
DECLARE_WAITQUEUE(wait, current);
int err = 0;
int timeo = HZ/5;
add_wait_queue(sk_sleep(sk), &wait);
set_current_state(TASK_INTERRUPTIBLE);
- while (chan->unacked_frames > 0 && chan->conn) {
+ do {
if (!timeo)
timeo = HZ/5;
@@ -1080,7 +1079,10 @@ static int __l2cap_wait_ack(struct sock *sk)
err = sock_error(sk);
if (err)
break;
- }
+
+ } while (chan->unacked_frames > 0 &&
+ chan->state == BT_CONNECTED);
+
set_current_state(TASK_RUNNING);
remove_wait_queue(sk_sleep(sk), &wait);
return err;
@@ -1115,8 +1117,10 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
lock_sock(sk);
if (!sk->sk_shutdown) {
- if (chan->mode == L2CAP_MODE_ERTM)
- err = __l2cap_wait_ack(sk);
+ if (chan->mode == L2CAP_MODE_ERTM &&
+ chan->unacked_frames > 0 &&
+ chan->state == BT_CONNECTED)
+ err = __l2cap_wait_ack(sk, chan);
sk->sk_shutdown = SHUTDOWN_MASK;
--
1.8.5.6
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 3/8] Bluetooth: Unwind l2cap_sock_shutdown()
2015-06-23 16:59 [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 1/8] Bluetooth: L2CAP ERTM shutdown protect sk and chan Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 2/8] Bluetooth: Make __l2cap_wait_ack more efficient Dean Jenkins
@ 2015-06-23 16:59 ` Dean Jenkins
2015-07-13 11:07 ` Johan Hedberg
2015-06-23 16:59 ` [PATCH v2 4/8] Bluetooth: l2cap_sock_shutdown() remove mutex_lock calls Dean Jenkins
` (5 subsequent siblings)
8 siblings, 1 reply; 23+ messages in thread
From: Dean Jenkins @ 2015-06-23 16:59 UTC (permalink / raw)
To: linux-bluetooth
Cc: marcel, gustavo, johan.hedberg, Joshua_Frkuska, Dean Jenkins
l2cap_sock_shutdown() is designed to only action shutdown
of the channel when shutdown is not already in progress.
Therefore, reorganise the code flow by adding a goto
to jump to the end of function handling when shutdown is
already being actioned. This removes one level of code
indentation and make the code more readable.
Note that the line
sk->sk_shutdown = SHUTDOWN_MASK;
has been moved to before waiting for ACKs. This is a
different behaviour to the old code. This line will inhibit
new PDUs being created during the waiting for ACKs period
so no new I frames will be sent and hence no additional ACKs
will be need to be waited for.
Signed-off-by: Dean Jenkins <Dean_Jenkins@mentor.com>
---
net/bluetooth/l2cap_sock.c | 44 ++++++++++++++++++++++++--------------------
1 file changed, 24 insertions(+), 20 deletions(-)
diff --git a/net/bluetooth/l2cap_sock.c b/net/bluetooth/l2cap_sock.c
index 2904288..78d1466 100644
--- a/net/bluetooth/l2cap_sock.c
+++ b/net/bluetooth/l2cap_sock.c
@@ -1100,6 +1100,13 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
if (!sk)
return 0;
+ lock_sock(sk);
+
+ if (sk->sk_shutdown)
+ goto shutdown_already;
+
+ sk->sk_shutdown = SHUTDOWN_MASK;
+
/* prevent sk structure from being freed whilst unlocked */
sock_hold(sk);
@@ -1114,30 +1121,21 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
mutex_lock(&conn->chan_lock);
l2cap_chan_lock(chan);
- lock_sock(sk);
- if (!sk->sk_shutdown) {
- if (chan->mode == L2CAP_MODE_ERTM &&
- chan->unacked_frames > 0 &&
- chan->state == BT_CONNECTED)
- err = __l2cap_wait_ack(sk, chan);
+ if (chan->mode == L2CAP_MODE_ERTM &&
+ chan->unacked_frames > 0 &&
+ chan->state == BT_CONNECTED)
+ err = __l2cap_wait_ack(sk, chan);
- sk->sk_shutdown = SHUTDOWN_MASK;
-
- release_sock(sk);
- l2cap_chan_close(chan, 0);
- lock_sock(sk);
-
- if (sock_flag(sk, SOCK_LINGER) && sk->sk_lingertime &&
- !(current->flags & PF_EXITING))
- err = bt_sock_wait_state(sk, BT_CLOSED,
- sk->sk_lingertime);
- }
+ release_sock(sk);
+ l2cap_chan_close(chan, 0);
+ lock_sock(sk);
- if (!err && sk->sk_err)
- err = -sk->sk_err;
+ if (sock_flag(sk, SOCK_LINGER) && sk->sk_lingertime &&
+ !(current->flags & PF_EXITING))
+ err = bt_sock_wait_state(sk, BT_CLOSED,
+ sk->sk_lingertime);
- release_sock(sk);
l2cap_chan_unlock(chan);
if (conn)
@@ -1146,6 +1144,12 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
l2cap_chan_put(chan);
sock_put(sk);
+shutdown_already:
+ if (!err && sk->sk_err)
+ err = -sk->sk_err;
+
+ release_sock(sk);
+
return err;
}
--
1.8.5.6
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 4/8] Bluetooth: l2cap_sock_shutdown() remove mutex_lock calls
2015-06-23 16:59 [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Dean Jenkins
` (2 preceding siblings ...)
2015-06-23 16:59 ` [PATCH v2 3/8] Bluetooth: Unwind l2cap_sock_shutdown() Dean Jenkins
@ 2015-06-23 16:59 ` Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 5/8] Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking Dean Jenkins
` (4 subsequent siblings)
8 siblings, 0 replies; 23+ messages in thread
From: Dean Jenkins @ 2015-06-23 16:59 UTC (permalink / raw)
To: linux-bluetooth
Cc: marcel, gustavo, johan.hedberg, Joshua_Frkuska, Dean Jenkins
Remove the calls
mutex_lock(&conn->chan_lock);
mutex_unlock(&conn->chan_lock);
because the conn structure is no longer being referenced in
l2cap_sock_shutdown() as instead the chan->state is being used
to determince the channel connection state.
Signed-off-by: Dean Jenkins <Dean_Jenkins@mentor.com>
---
net/bluetooth/l2cap_sock.c | 8 --------
1 file changed, 8 deletions(-)
diff --git a/net/bluetooth/l2cap_sock.c b/net/bluetooth/l2cap_sock.c
index 78d1466..b81cb36 100644
--- a/net/bluetooth/l2cap_sock.c
+++ b/net/bluetooth/l2cap_sock.c
@@ -1092,7 +1092,6 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
{
struct sock *sk = sock->sk;
struct l2cap_chan *chan;
- struct l2cap_conn *conn;
int err = 0;
BT_DBG("sock %p, sk %p", sock, sk);
@@ -1113,13 +1112,9 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
chan = l2cap_pi(sk)->chan;
/* prevent chan structure from being freed whilst unlocked */
l2cap_chan_hold(chan);
- conn = chan->conn;
BT_DBG("chan %p state %s", chan, state_to_string(chan->state));
- if (conn)
- mutex_lock(&conn->chan_lock);
-
l2cap_chan_lock(chan);
if (chan->mode == L2CAP_MODE_ERTM &&
@@ -1138,9 +1133,6 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
l2cap_chan_unlock(chan);
- if (conn)
- mutex_unlock(&conn->chan_lock);
-
l2cap_chan_put(chan);
sock_put(sk);
--
1.8.5.6
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 5/8] Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking
2015-06-23 16:59 [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Dean Jenkins
` (3 preceding siblings ...)
2015-06-23 16:59 ` [PATCH v2 4/8] Bluetooth: l2cap_sock_shutdown() remove mutex_lock calls Dean Jenkins
@ 2015-06-23 16:59 ` Dean Jenkins
2015-07-13 10:26 ` Johan Hedberg
2015-06-23 16:59 ` [PATCH v2 6/8] Bluetooth: Add BT_DBG to l2cap_sock_shutdown() Dean Jenkins
` (3 subsequent siblings)
8 siblings, 1 reply; 23+ messages in thread
From: Dean Jenkins @ 2015-06-23 16:59 UTC (permalink / raw)
To: linux-bluetooth
Cc: marcel, gustavo, johan.hedberg, Joshua_Frkuska, Dean Jenkins
The only place where chan locking is needed is the call to
l2cap_chan_close(chan, 0) which if necessary closes the channel.
Therefore, move the l2cap_chan_lock(chan) and
l2cap_chan_lock(chan) locking calls to around
l2cap_chan_close(chan, 0).
This allows __l2cap_wait_ack(sk, chan) to be called with no
chan locks being held so L2CAP messaging over the ACL link
can be done unimpaired.
Signed-off-by: Dean Jenkins <Dean_Jenkins@mentor.com>
---
net/bluetooth/l2cap_sock.c | 6 ++----
1 file changed, 2 insertions(+), 4 deletions(-)
diff --git a/net/bluetooth/l2cap_sock.c b/net/bluetooth/l2cap_sock.c
index b81cb36..bdf8f4c 100644
--- a/net/bluetooth/l2cap_sock.c
+++ b/net/bluetooth/l2cap_sock.c
@@ -1115,24 +1115,22 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
BT_DBG("chan %p state %s", chan, state_to_string(chan->state));
- l2cap_chan_lock(chan);
-
if (chan->mode == L2CAP_MODE_ERTM &&
chan->unacked_frames > 0 &&
chan->state == BT_CONNECTED)
err = __l2cap_wait_ack(sk, chan);
+ l2cap_chan_lock(chan);
release_sock(sk);
l2cap_chan_close(chan, 0);
lock_sock(sk);
+ l2cap_chan_unlock(chan);
if (sock_flag(sk, SOCK_LINGER) && sk->sk_lingertime &&
!(current->flags & PF_EXITING))
err = bt_sock_wait_state(sk, BT_CLOSED,
sk->sk_lingertime);
- l2cap_chan_unlock(chan);
-
l2cap_chan_put(chan);
sock_put(sk);
--
1.8.5.6
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 6/8] Bluetooth: Add BT_DBG to l2cap_sock_shutdown()
2015-06-23 16:59 [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Dean Jenkins
` (4 preceding siblings ...)
2015-06-23 16:59 ` [PATCH v2 5/8] Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking Dean Jenkins
@ 2015-06-23 16:59 ` Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 7/8] Bluetooth: __l2cap_wait_ack() use msecs_to_jiffies() Dean Jenkins
` (2 subsequent siblings)
8 siblings, 0 replies; 23+ messages in thread
From: Dean Jenkins @ 2015-06-23 16:59 UTC (permalink / raw)
To: linux-bluetooth
Cc: marcel, gustavo, johan.hedberg, Joshua_Frkuska, Dean Jenkins
Add helpful BT_DBG debug to l2cap_sock_shutdown()
and __l2cap_wait_ack() so that the code flow can
be analysed.
Signed-off-by: Dean Jenkins <Dean_Jenkins@mentor.com>
---
net/bluetooth/l2cap_sock.c | 4 ++++
1 file changed, 4 insertions(+)
diff --git a/net/bluetooth/l2cap_sock.c b/net/bluetooth/l2cap_sock.c
index bdf8f4c..fdc140e 100644
--- a/net/bluetooth/l2cap_sock.c
+++ b/net/bluetooth/l2cap_sock.c
@@ -1063,6 +1063,8 @@ static int __l2cap_wait_ack(struct sock *sk, struct l2cap_chan *chan)
add_wait_queue(sk_sleep(sk), &wait);
set_current_state(TASK_INTERRUPTIBLE);
do {
+ BT_DBG("Waiting for %d ACKs", chan->unacked_frames);
+
if (!timeo)
timeo = HZ/5;
@@ -1140,6 +1142,8 @@ shutdown_already:
release_sock(sk);
+ BT_DBG("err: %d", err);
+
return err;
}
--
1.8.5.6
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 7/8] Bluetooth: __l2cap_wait_ack() use msecs_to_jiffies()
2015-06-23 16:59 [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Dean Jenkins
` (5 preceding siblings ...)
2015-06-23 16:59 ` [PATCH v2 6/8] Bluetooth: Add BT_DBG to l2cap_sock_shutdown() Dean Jenkins
@ 2015-06-23 16:59 ` Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 8/8] Bluetooth: __l2cap_wait_ack() add defensive timeout Dean Jenkins
2015-07-09 8:42 ` [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Marcel Holtmann
8 siblings, 0 replies; 23+ messages in thread
From: Dean Jenkins @ 2015-06-23 16:59 UTC (permalink / raw)
To: linux-bluetooth
Cc: marcel, gustavo, johan.hedberg, Joshua_Frkuska, Dean Jenkins
Use msecs_to_jiffies() instead of using HZ so that it
is easier to specify the time in milliseconds.
Also add a #define L2CAP_WAIT_ACK_POLL_PERIOD to specify the 200ms
polling period so that it is defined in a single place.
Signed-off-by: Dean Jenkins <Dean_Jenkins@mentor.com>
---
include/net/bluetooth/l2cap.h | 1 +
net/bluetooth/l2cap_sock.c | 4 ++--
2 files changed, 3 insertions(+), 2 deletions(-)
diff --git a/include/net/bluetooth/l2cap.h b/include/net/bluetooth/l2cap.h
index 2239a37..3dcad41 100644
--- a/include/net/bluetooth/l2cap.h
+++ b/include/net/bluetooth/l2cap.h
@@ -55,6 +55,7 @@
#define L2CAP_INFO_TIMEOUT msecs_to_jiffies(4000)
#define L2CAP_MOVE_TIMEOUT msecs_to_jiffies(4000)
#define L2CAP_MOVE_ERTX_TIMEOUT msecs_to_jiffies(60000)
+#define L2CAP_WAIT_ACK_POLL_PERIOD msecs_to_jiffies(200)
#define L2CAP_A2MP_DEFAULT_MTU 670
diff --git a/net/bluetooth/l2cap_sock.c b/net/bluetooth/l2cap_sock.c
index fdc140e..2c09ec1 100644
--- a/net/bluetooth/l2cap_sock.c
+++ b/net/bluetooth/l2cap_sock.c
@@ -1058,7 +1058,7 @@ static int __l2cap_wait_ack(struct sock *sk, struct l2cap_chan *chan)
{
DECLARE_WAITQUEUE(wait, current);
int err = 0;
- int timeo = HZ/5;
+ int timeo = L2CAP_WAIT_ACK_POLL_PERIOD;
add_wait_queue(sk_sleep(sk), &wait);
set_current_state(TASK_INTERRUPTIBLE);
@@ -1066,7 +1066,7 @@ static int __l2cap_wait_ack(struct sock *sk, struct l2cap_chan *chan)
BT_DBG("Waiting for %d ACKs", chan->unacked_frames);
if (!timeo)
- timeo = HZ/5;
+ timeo = L2CAP_WAIT_ACK_POLL_PERIOD;
if (signal_pending(current)) {
err = sock_intr_errno(timeo);
--
1.8.5.6
^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v2 8/8] Bluetooth: __l2cap_wait_ack() add defensive timeout
2015-06-23 16:59 [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Dean Jenkins
` (6 preceding siblings ...)
2015-06-23 16:59 ` [PATCH v2 7/8] Bluetooth: __l2cap_wait_ack() use msecs_to_jiffies() Dean Jenkins
@ 2015-06-23 16:59 ` Dean Jenkins
2015-07-09 8:42 ` [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Marcel Holtmann
8 siblings, 0 replies; 23+ messages in thread
From: Dean Jenkins @ 2015-06-23 16:59 UTC (permalink / raw)
To: linux-bluetooth
Cc: marcel, gustavo, johan.hedberg, Joshua_Frkuska, Dean Jenkins
Add a timeout to prevent the do while loop running in an
infinite loop. This ensures that the channel will be
instructed to close within 10 seconds so prevents
l2cap_sock_shutdown() getting stuck forever.
Returns -ENOLINK when the timeout is reached. The channel
will be subequently closed and not all data will be ACK'ed.
Signed-off-by: Dean Jenkins <Dean_Jenkins@mentor.com>
---
include/net/bluetooth/l2cap.h | 1 +
net/bluetooth/l2cap_sock.c | 12 +++++++++++-
2 files changed, 12 insertions(+), 1 deletion(-)
diff --git a/include/net/bluetooth/l2cap.h b/include/net/bluetooth/l2cap.h
index 3dcad41..c98afc0 100644
--- a/include/net/bluetooth/l2cap.h
+++ b/include/net/bluetooth/l2cap.h
@@ -56,6 +56,7 @@
#define L2CAP_MOVE_TIMEOUT msecs_to_jiffies(4000)
#define L2CAP_MOVE_ERTX_TIMEOUT msecs_to_jiffies(60000)
#define L2CAP_WAIT_ACK_POLL_PERIOD msecs_to_jiffies(200)
+#define L2CAP_WAIT_ACK_TIMEOUT msecs_to_jiffies(10000)
#define L2CAP_A2MP_DEFAULT_MTU 670
diff --git a/net/bluetooth/l2cap_sock.c b/net/bluetooth/l2cap_sock.c
index 2c09ec1..f967749 100644
--- a/net/bluetooth/l2cap_sock.c
+++ b/net/bluetooth/l2cap_sock.c
@@ -1059,11 +1059,16 @@ static int __l2cap_wait_ack(struct sock *sk, struct l2cap_chan *chan)
DECLARE_WAITQUEUE(wait, current);
int err = 0;
int timeo = L2CAP_WAIT_ACK_POLL_PERIOD;
+ /* Timeout to prevent infinite loop */
+ unsigned long timeout = jiffies + L2CAP_WAIT_ACK_TIMEOUT;
add_wait_queue(sk_sleep(sk), &wait);
set_current_state(TASK_INTERRUPTIBLE);
do {
- BT_DBG("Waiting for %d ACKs", chan->unacked_frames);
+ BT_DBG("Waiting for %d ACKs, timeout %04d ms",
+ chan->unacked_frames,
+ time_after(jiffies, timeout) ? 0 :
+ jiffies_to_msecs(timeout - jiffies));
if (!timeo)
timeo = L2CAP_WAIT_ACK_POLL_PERIOD;
@@ -1082,6 +1087,11 @@ static int __l2cap_wait_ack(struct sock *sk, struct l2cap_chan *chan)
if (err)
break;
+ if (time_after(jiffies, timeout)) {
+ err = -ENOLINK;
+ break;
+ }
+
} while (chan->unacked_frames > 0 &&
chan->state == BT_CONNECTED);
--
1.8.5.6
^ permalink raw reply related [flat|nested] 23+ messages in thread
* Re: [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks
2015-06-23 16:59 [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Dean Jenkins
` (7 preceding siblings ...)
2015-06-23 16:59 ` [PATCH v2 8/8] Bluetooth: __l2cap_wait_ack() add defensive timeout Dean Jenkins
@ 2015-07-09 8:42 ` Marcel Holtmann
2015-07-09 9:36 ` Johan Hedberg
8 siblings, 1 reply; 23+ messages in thread
From: Marcel Holtmann @ 2015-07-09 8:42 UTC (permalink / raw)
To: Dean Jenkins
Cc: linux-bluetooth, Gustavo F. Padovan, Johan Hedberg, Joshua_Frkuska
Hi Dean,
> Details of the issue are described in the thread
> [RFC] Bluetooth ERTM L2CAP deadlocks (hung tasks) due to l2cap_sock_shutdown()
> and kernel.org Bugzilla https://bugzilla.kernel.org/show_bug.cgi?id=99301
>
> Summary
> =======
>
> a) __l2cap_wait_ack() gets stuck in an infinite loop whilst waiting for
> I frame acknowledgements (ACK is S or I frame from the remote device).
> The infinite loop occurs because the waiting loop's condition never becomes
> false. __l2cap_wait_ack() periodically sleeps for upto 200ms as
> timeo = schedule_timeout(timeo); may return early with no signal event,
> so is unclear why it wakes-up early.
>
> b) The L2CAP threads for processing received frames and error recovery
> timers become blocked on a mutex held by l2cap_sock_shutdown() which
> prevents updating of the loop condition in __l2cap_wait_ack().
>
> Therefore a deadlock occurs with mutex_lock(&conn->chan_lock).
>
> This deadlock was observed by us on kernels 3.8 upto bluetooth-next on x86 and
> ARM based platforms including the Raspberry Pi kernel 3.18.14+
>
> The testcase is simple to reproduce the hung tasks, please wait upto 10 minutes
> to observe the hung tasks:
>
> On a laptop or other suitable device use the command:
> l2test -i hci0 -X ertm -d
> This command listens for connections with optional L2CAP ERTM supported and
> dumps out the received data.
>
> On the unit under test use the command:
> l2test -s -b 1024 -B /dev/urandom -X ertm -P 4113 <lap_BT_ADDR>
> This command sends 1024 bytes to the laptop via PSM 4113 used by l2test over
> an ERTM channel. The command line shows:
>
> l2test -s -b 1024 -B /dev/urandom -X ertm -P 4113 5C:F3:70:68:BA:DD
> l2test[10366]: Connected to 5C:F3:70:68:BA:DD (bredr, psm 4113, scid 64)
> l2test[10366]: Local device 5C:F3:70:68:BA:DA (bredr, psm 4113, scid 64)
> l2test[10366]: Options [imtu 672, omtu 672, flush_to 65535, mode 3, handle 11, class 0x000000, priority 0, rcvbuf 163840]
> l2test[10366]: Sending ...
> l2test[10366]: Closing channel ...
>
> Note that the channel fails to close because l2cap_sock_shutdown() is prevented
> from returning due to __l2cap_wait_ack being stuck in an infinite loop.
>
> Example hung tasks are:
>
> [ 601.116119] INFO: task kworker/0:1:19 blocked for more than 120 seconds.
> [ 601.116156] Not tainted 3.18.11+ #781
> [ 601.116169] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 601.116183] kworker/0:1 D c054cbcc 0 19 2 0x00000000
> [ 601.116537] Workqueue: events l2cap_retrans_timeout [bluetooth]
> [ 601.116685] [<c054cbcc>] (__schedule) from [<c054cfa4>] (schedule+0x40/0x8c)
> [ 601.116727] [<c054cfa4>] (schedule) from [<c054d3c8>] (schedule_preempt_disabled+0x30/0x40)
> [ 601.116812] [<c054d3c8>] (schedule_preempt_disabled) from [<c054ee14>] (__mutex_lock_slowpath+0xb8/0x18c)
> [ 601.116856] [<c054ee14>] (__mutex_lock_slowpath) from [<c054ef20>] (mutex_lock+0x38/0x3c)
> [ 601.117085] [<c054ef20>] (mutex_lock) from [<bf05173c>] (l2cap_retrans_timeout+0x24/0x5c [bluetooth])
> [ 601.117371] [<bf05173c>] (l2cap_retrans_timeout [bluetooth]) from [<c003aa68>] (process_one_work+0x13c/0x444)
> [ 601.117410] [<c003aa68>] (process_one_work) from [<c003b954>] (worker_thread+0x190/0x580)
> [ 601.117445] [<c003b954>] (worker_thread) from [<c003fdb4>] (kthread+0xd8/0xf4)
> [ 601.117488] [<c003fdb4>] (kthread) from [<c000e8c8>] (ret_from_fork+0x14/0x20)
> [ 601.117569] INFO: task kworker/u3:2:327 blocked for more than 120 seconds.
> [ 601.117588] Not tainted 3.18.11+ #781
> [ 601.117601] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 601.117614] kworker/u3:2 D c054cbcc 0 327 2 0x00000000
> [ 601.117806] Workqueue: hci0 hci_rx_work [bluetooth]
> [ 601.117941] [<c054cbcc>] (__schedule) from [<c054cfa4>] (schedule+0x40/0x8c)
> [ 601.117981] [<c054cfa4>] (schedule) from [<c054d3c8>] (schedule_preempt_disabled+0x30/0x40)
> [ 601.118056] [<c054d3c8>] (schedule_preempt_disabled) from [<c054ee14>] (__mutex_lock_slowpath+0xb8/0x18c)
> [ 601.118092] [<c054ee14>] (__mutex_lock_slowpath) from [<c054ef20>] (mutex_lock+0x38/0x3c)
> [ 601.118307] [<c054ef20>] (mutex_lock) from [<bf04d2c8>] (l2cap_get_chan_by_scid+0x28/0x98 [bluetooth])
> [ 601.118696] [<bf04d2c8>] (l2cap_get_chan_by_scid [bluetooth]) from [<bf054590>] (l2cap_recv_frame+0xa4/0x2cec [bluetooth])
> [ 601.119146] [<bf054590>] (l2cap_recv_frame [bluetooth]) from [<bf058194>] (l2cap_recv_acldata+0x214/0x22c [bluetooth])
> [ 601.119559] [<bf058194>] (l2cap_recv_acldata [bluetooth]) from [<bf02bf88>] (hci_rx_work+0x180/0x288 [bluetooth])
> [ 601.119801] [<bf02bf88>] (hci_rx_work [bluetooth]) from [<c003aa68>] (process_one_work+0x13c/0x444)
> [ 601.119839] [<c003aa68>] (process_one_work) from [<c003b954>] (worker_thread+0x190/0x580)
> [ 601.119883] [<c003b954>] (worker_thread) from [<c003fdb4>] (kthread+0xd8/0xf4)
> [ 601.119919] [<c003fdb4>] (kthread) from [<c000e8c8>] (ret_from_fork+0x14/0x20)
>
> This is not an exhaustive list, there are other hung task flavours.
>
> Solution
> ========
>
> The solution is to reorganise l2cap_sock_shutdown() to reveal the purpose of
> the function. The function shuts down the L2CAP channel but in the case when the
> channel type is ERTM, __l2cap_wait_ack() is called to wait for acknowledgements
> before the channel is shutdown.
>
> There is some concurrency protection by using a lock on sk to prevent
> multiple instances of l2cap_sock_shutdown() from running.
>
> SHUTDOWN_MASK is used to inhibit new I frames and other PDUs from being
> queued. Setting this flag was moved to before calling __l2cap_wait_ack() so that
> the loop would not be waiting indefinitely for ACKs. There is some risk here
> of not sending all pending data, however, an arbitrary cut-off point is needed
> otherwise the shutdown could be held off during periods of heavy traffic. This
> may need improving to inhibit only new I frames.
>
> Extra protection to the sk and chan structures was added to prevent those
> structures being freed whilst the locks were not held. This is defensive and
> perhaps unnecessary.
>
> __l2cap_wait_ack() was modified to be only called when necessary and the
> while loop was replaced by a do while loop because there must be at least 1
> waiting period. References to chan->conn were replaced by chan->state so that
> the mutex locks could be removed. Also waiting for ACKs is only valid whilst the
> connection is in the BT_CONNECTED state.
>
> The scope of chan locking was reduced so that processing of received frames
> and error handling routines could operate whilst waiting for ACKs.
>
> Additionally, for __l2cap_wait_ack() a 10 second maximum wait limit was
> implemented to prevent __l2cap_wait_ack() getting stuck in an infinite loop.
> If no expected ACKs arrive then the channel is disconnected and the error
> code -ENOLINK is returned to indicate that not all data was ACK'ed.
>
> Testing
> =======
>
> This has been tested in kernels 3.8 and 3.14 on an ARM based board for a
> commercial product. Results show that the hung tasks no longer occur.
>
> Note that the failure scenario was Media player media browsing. Waiting for
> ACK's is unimportant in this scenario because it does not matter whether
> a media browsing request such as "get item" was successfully transferred at the
> point of shutting down the channel.
>
> These v2 patches have not been tested on a bluetooth-next based build. However,
> sjanc on the Bluetooth IRC channel tested the v1 patches using the PTS testcases
> and found no regressions. If v2 were to be tested, then similar results to v1
> should be seen.
>
> v2 changes
> ==========
>
> 0007-Bluetooth-__l2cap_wait_ack-use-msecs_to_jiffies.patch was introduced
> to tidy-up the original code's use of HZ. Now msecs_to_jiffies() is used
> instead of HZ. This was done in response to review comments.
>
> 0008-Bluetooth-__l2cap_wait_ack-add-defensive-timeout.patch was introduced
> to replace the v1 0007 patch. The solution now uses a 10 second jiffy based
> timeout mechanism instead of a loop counter limit. The new solution is more
> accurate and easier to maintain than the loop counter limit.
>
> Risks
> =====
>
> The mutex lock mutex_lock(&conn->chan_lock) has been removed whilst
> l2cap_chan_close() runs in l2cap_sock_shutdown(). l2cap_chan_lock(chan) is
> protecting l2cap_chan_close() against concurrent procedural handling events for
> the channel at the L2CAP level.
>
> Analysis indicates chan->conn is used as an indication that the underlying ACL
> connection is still up. l2cap_chan_del() sets chan->conn = NULL and all calls to
> l2cap_chan_del() seem to be done with the l2cap_chan_lock(chan) held. Therefore,
> it should not be possible for chan->conn to become unexpectedly NULL during the
> execution of l2cap_chan_close(). The locking seems to be sufficient.
>
> Patchset
> ========
>
> Patches are based on bluetooth-next:
>
> Dean Jenkins (8):
> Bluetooth: L2CAP ERTM shutdown protect sk and chan
> Bluetooth: Make __l2cap_wait_ack more efficient
> Bluetooth: Unwind l2cap_sock_shutdown()
> Bluetooth: l2cap_sock_shutdown() remove mutex_lock calls
> Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking
> Bluetooth: Add BT_DBG to l2cap_sock_shutdown()
> Bluetooth: __l2cap_wait_ack() use msecs_to_jiffies()
> Bluetooth: __l2cap_wait_ack() add defensive timeout
>
> include/net/bluetooth/l2cap.h | 2 ++
> net/bluetooth/l2cap_sock.c | 74 +++++++++++++++++++++++++++----------------
> 2 files changed, 49 insertions(+), 27 deletions(-)
all 8 patches have been applied to bluetooth-next tree.
Regards
Marcel
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks
2015-07-09 8:42 ` [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Marcel Holtmann
@ 2015-07-09 9:36 ` Johan Hedberg
2015-07-09 9:56 ` Johan Hedberg
2015-07-09 9:58 ` Dean Jenkins
0 siblings, 2 replies; 23+ messages in thread
From: Johan Hedberg @ 2015-07-09 9:36 UTC (permalink / raw)
To: Marcel Holtmann; +Cc: Dean Jenkins, linux-bluetooth, Joshua_Frkuska
Hi,
On Thu, Jul 09, 2015, Marcel Holtmann wrote:
> > Dean Jenkins (8):
> > Bluetooth: L2CAP ERTM shutdown protect sk and chan
> > Bluetooth: Make __l2cap_wait_ack more efficient
> > Bluetooth: Unwind l2cap_sock_shutdown()
> > Bluetooth: l2cap_sock_shutdown() remove mutex_lock calls
> > Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking
> > Bluetooth: Add BT_DBG to l2cap_sock_shutdown()
> > Bluetooth: __l2cap_wait_ack() use msecs_to_jiffies()
> > Bluetooth: __l2cap_wait_ack() add defensive timeout
> >
> > include/net/bluetooth/l2cap.h | 2 ++
> > net/bluetooth/l2cap_sock.c | 74 +++++++++++++++++++++++++++----------------
> > 2 files changed, 49 insertions(+), 27 deletions(-)
>
> all 8 patches have been applied to bluetooth-next tree.
I'm getting the following now when running our l2cap-tester tool:
[Jul 9 12:34] ======================================================
[ +0.000298] [ INFO: possible circular locking dependency detected ]
[ +0.000298] 4.1.0-rc4+ #1356 Not tainted
[ +0.000165] -------------------------------------------------------
[ +0.000288] l2cap-tester/10613 is trying to acquire lock:
[ +0.000000] (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+...}, at: [<f942807e>] lock_sock+0xa/0xc [bluetooth]
[ +0.000336]
but task is already holding lock:
[ +0.000000] (&chan->lock/1){+.+...}, at: [<f94283b6>] l2cap_chan_lock+0x13/0x15 [bluetooth]
[ +0.000000]
which lock already depends on the new lock.
[ +0.000000]
the existing dependency chain (in reverse order) is:
[ +0.000000]
-> #1 (&chan->lock/1){+.+...}:
[ +0.000000] [<c1064917>] lock_acquire+0xdd/0x14f
[ +0.000000] [<c13ff419>] mutex_lock_nested+0x54/0x393
[ +0.000000] [<f94283b6>] l2cap_chan_lock+0x13/0x15 [bluetooth]
[ +0.000000] [<f9428ec1>] l2cap_sock_shutdown+0x28c/0x327 [bluetooth]
[ +0.000000] [<f942937a>] l2cap_sock_release+0x57/0xa5 [bluetooth]
[ +0.000000] [<c1318032>] sock_release+0x19/0x6b
[ +0.000000] [<c1318094>] sock_close+0x10/0x14
[ +0.000000] [<c10e808a>] __fput+0xd6/0x162
[ +0.000000] [<c10e8146>] ____fput+0xd/0xf
[ +0.000000] [<c1049bc8>] task_work_run+0x7e/0xa4
[ +0.000000] [<c1001d1e>] do_notify_resume+0x3c/0x3f
[ +0.000000] [<c1402730>] work_notifysig+0x29/0x31
[ +0.000000]
-> #0 (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+...}:
[ +0.000000] [<c1064396>] __lock_acquire+0x98c/0xbfb
[ +0.000000] [<c1064917>] lock_acquire+0xdd/0x14f
[ +0.000000] [<c131cb86>] lock_sock_nested+0x63/0x7d
[ +0.000000] [<f942807e>] lock_sock+0xa/0xc [bluetooth]
[ +0.000000] [<f9428ed9>] l2cap_sock_shutdown+0x2a4/0x327 [bluetooth]
[ +0.000000] [<f942937a>] l2cap_sock_release+0x57/0xa5 [bluetooth]
[ +0.000000] [<c1318032>] sock_release+0x19/0x6b
[ +0.000000] [<c1318094>] sock_close+0x10/0x14
[ +0.000000] [<c10e808a>] __fput+0xd6/0x162
[ +0.000000] [<c10e8146>] ____fput+0xd/0xf
[ +0.000000] [<c1049bc8>] task_work_run+0x7e/0xa4
[ +0.000000] [<c1001d1e>] do_notify_resume+0x3c/0x3f
[ +0.000000] [<c1402730>] work_notifysig+0x29/0x31
[ +0.000000]
other info that might help us debug this:
[ +0.000000] Possible unsafe locking scenario:
[ +0.000000] CPU0 CPU1
[ +0.000000] ---- ----
[ +0.000000] lock(&chan->lock/1);
[ +0.000000] lock(sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP);
[ +0.000000] lock(&chan->lock/1);
[ +0.000000] lock(sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP);
[ +0.000000]
*** DEADLOCK ***
[ +0.000000] 1 lock held by l2cap-tester/10613:
[ +0.000000] #0: (&chan->lock/1){+.+...}, at: [<f94283b6>] l2cap_chan_lock+0x13/0x15 [bluetooth]
[ +0.000000]
stack backtrace:
[ +0.000000] CPU: 1 PID: 10613 Comm: l2cap-tester Not tainted 4.1.0-rc4+ #1356
[ +0.000000] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
[ +0.000000] 00000000 00000000 f1acbde4 c13fd7f8 c1c2d760 f1acbe14 c1062c61 c15f5534
[ +0.000000] c15f5427 c15f53ef c15f5410 c15f53ef f1acbe48 f537f380 f537f7fc f537f380
[ +0.000000] f537f814 f1acbe78 c1064396 f537f7fc 00000000 00000000 c1c2ffc0 00000000
[ +0.000000] Call Trace:
[ +0.000000] [<c13fd7f8>] dump_stack+0x49/0x73
[ +0.000000] [<c1062c61>] print_circular_bug+0x190/0x19d
[ +0.000000] [<c1064396>] __lock_acquire+0x98c/0xbfb
[ +0.000000] [<c1064917>] lock_acquire+0xdd/0x14f
[ +0.000000] [<f942807e>] ? lock_sock+0xa/0xc [bluetooth]
[ +0.000000] [<c131cb86>] lock_sock_nested+0x63/0x7d
[ +0.000000] [<f942807e>] ? lock_sock+0xa/0xc [bluetooth]
[ +0.000000] [<f942807e>] lock_sock+0xa/0xc [bluetooth]
[ +0.000000] [<f9428ed9>] l2cap_sock_shutdown+0x2a4/0x327 [bluetooth]
[ +0.000000] [<f9401112>] ? bt_sock_unlink+0x16/0x54 [bluetooth]
[ +0.000000] [<c1402276>] ? _raw_write_unlock+0x2c/0x3e
[ +0.000000] [<f942937a>] l2cap_sock_release+0x57/0xa5 [bluetooth]
[ +0.000000] [<f942937a>] ? l2cap_sock_release+0x57/0xa5 [bluetooth]
[ +0.000000] [<c1318032>] sock_release+0x19/0x6b
[ +0.000000] [<c1318032>] ? sock_release+0x19/0x6b
[ +0.000000] [<c1318094>] sock_close+0x10/0x14
[ +0.000000] [<c10e808a>] __fput+0xd6/0x162
[ +0.000000] [<c10e8146>] ____fput+0xd/0xf
[ +0.000000] [<c1049bc8>] task_work_run+0x7e/0xa4
[ +0.000000] [<c1001d1e>] do_notify_resume+0x3c/0x3f
[ +0.000000] [<c1402730>] work_notifysig+0x29/0x31
Johan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks
2015-07-09 9:36 ` Johan Hedberg
@ 2015-07-09 9:56 ` Johan Hedberg
2015-07-09 9:58 ` Dean Jenkins
1 sibling, 0 replies; 23+ messages in thread
From: Johan Hedberg @ 2015-07-09 9:56 UTC (permalink / raw)
To: Marcel Holtmann, Dean Jenkins, linux-bluetooth, Joshua_Frkuska
Hi,
On Thu, Jul 09, 2015, Johan Hedberg wrote:
> On Thu, Jul 09, 2015, Marcel Holtmann wrote:
> > > Dean Jenkins (8):
> > > Bluetooth: L2CAP ERTM shutdown protect sk and chan
> > > Bluetooth: Make __l2cap_wait_ack more efficient
> > > Bluetooth: Unwind l2cap_sock_shutdown()
> > > Bluetooth: l2cap_sock_shutdown() remove mutex_lock calls
> > > Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking
> > > Bluetooth: Add BT_DBG to l2cap_sock_shutdown()
> > > Bluetooth: __l2cap_wait_ack() use msecs_to_jiffies()
> > > Bluetooth: __l2cap_wait_ack() add defensive timeout
> > >
> > > include/net/bluetooth/l2cap.h | 2 ++
> > > net/bluetooth/l2cap_sock.c | 74 +++++++++++++++++++++++++++----------------
> > > 2 files changed, 49 insertions(+), 27 deletions(-)
> >
> > all 8 patches have been applied to bluetooth-next tree.
>
> I'm getting the following now when running our l2cap-tester tool:
>
> [Jul 9 12:34] ======================================================
> [ +0.000298] [ INFO: possible circular locking dependency detected ]
> [ +0.000298] 4.1.0-rc4+ #1356 Not tainted
> [ +0.000165] -------------------------------------------------------
> [ +0.000288] l2cap-tester/10613 is trying to acquire lock:
> [ +0.000000] (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+...}, at: [<f942807e>] lock_sock+0xa/0xc [bluetooth]
> [ +0.000336]
> but task is already holding lock:
> [ +0.000000] (&chan->lock/1){+.+...}, at: [<f94283b6>] l2cap_chan_lock+0x13/0x15 [bluetooth]
> [ +0.000000]
> which lock already depends on the new lock.
>
> [ +0.000000]
> the existing dependency chain (in reverse order) is:
> [ +0.000000]
> -> #1 (&chan->lock/1){+.+...}:
> [ +0.000000] [<c1064917>] lock_acquire+0xdd/0x14f
> [ +0.000000] [<c13ff419>] mutex_lock_nested+0x54/0x393
> [ +0.000000] [<f94283b6>] l2cap_chan_lock+0x13/0x15 [bluetooth]
> [ +0.000000] [<f9428ec1>] l2cap_sock_shutdown+0x28c/0x327 [bluetooth]
> [ +0.000000] [<f942937a>] l2cap_sock_release+0x57/0xa5 [bluetooth]
> [ +0.000000] [<c1318032>] sock_release+0x19/0x6b
> [ +0.000000] [<c1318094>] sock_close+0x10/0x14
> [ +0.000000] [<c10e808a>] __fput+0xd6/0x162
> [ +0.000000] [<c10e8146>] ____fput+0xd/0xf
> [ +0.000000] [<c1049bc8>] task_work_run+0x7e/0xa4
> [ +0.000000] [<c1001d1e>] do_notify_resume+0x3c/0x3f
> [ +0.000000] [<c1402730>] work_notifysig+0x29/0x31
> [ +0.000000]
> -> #0 (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+...}:
> [ +0.000000] [<c1064396>] __lock_acquire+0x98c/0xbfb
> [ +0.000000] [<c1064917>] lock_acquire+0xdd/0x14f
> [ +0.000000] [<c131cb86>] lock_sock_nested+0x63/0x7d
> [ +0.000000] [<f942807e>] lock_sock+0xa/0xc [bluetooth]
> [ +0.000000] [<f9428ed9>] l2cap_sock_shutdown+0x2a4/0x327 [bluetooth]
> [ +0.000000] [<f942937a>] l2cap_sock_release+0x57/0xa5 [bluetooth]
> [ +0.000000] [<c1318032>] sock_release+0x19/0x6b
> [ +0.000000] [<c1318094>] sock_close+0x10/0x14
> [ +0.000000] [<c10e808a>] __fput+0xd6/0x162
> [ +0.000000] [<c10e8146>] ____fput+0xd/0xf
> [ +0.000000] [<c1049bc8>] task_work_run+0x7e/0xa4
> [ +0.000000] [<c1001d1e>] do_notify_resume+0x3c/0x3f
> [ +0.000000] [<c1402730>] work_notifysig+0x29/0x31
> [ +0.000000]
> other info that might help us debug this:
>
> [ +0.000000] Possible unsafe locking scenario:
>
> [ +0.000000] CPU0 CPU1
> [ +0.000000] ---- ----
> [ +0.000000] lock(&chan->lock/1);
> [ +0.000000] lock(sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP);
> [ +0.000000] lock(&chan->lock/1);
> [ +0.000000] lock(sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP);
> [ +0.000000]
> *** DEADLOCK ***
>
> [ +0.000000] 1 lock held by l2cap-tester/10613:
> [ +0.000000] #0: (&chan->lock/1){+.+...}, at: [<f94283b6>] l2cap_chan_lock+0x13/0x15 [bluetooth]
> [ +0.000000]
> stack backtrace:
> [ +0.000000] CPU: 1 PID: 10613 Comm: l2cap-tester Not tainted 4.1.0-rc4+ #1356
> [ +0.000000] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
> [ +0.000000] 00000000 00000000 f1acbde4 c13fd7f8 c1c2d760 f1acbe14 c1062c61 c15f5534
> [ +0.000000] c15f5427 c15f53ef c15f5410 c15f53ef f1acbe48 f537f380 f537f7fc f537f380
> [ +0.000000] f537f814 f1acbe78 c1064396 f537f7fc 00000000 00000000 c1c2ffc0 00000000
> [ +0.000000] Call Trace:
> [ +0.000000] [<c13fd7f8>] dump_stack+0x49/0x73
> [ +0.000000] [<c1062c61>] print_circular_bug+0x190/0x19d
> [ +0.000000] [<c1064396>] __lock_acquire+0x98c/0xbfb
> [ +0.000000] [<c1064917>] lock_acquire+0xdd/0x14f
> [ +0.000000] [<f942807e>] ? lock_sock+0xa/0xc [bluetooth]
> [ +0.000000] [<c131cb86>] lock_sock_nested+0x63/0x7d
> [ +0.000000] [<f942807e>] ? lock_sock+0xa/0xc [bluetooth]
> [ +0.000000] [<f942807e>] lock_sock+0xa/0xc [bluetooth]
> [ +0.000000] [<f9428ed9>] l2cap_sock_shutdown+0x2a4/0x327 [bluetooth]
> [ +0.000000] [<f9401112>] ? bt_sock_unlink+0x16/0x54 [bluetooth]
> [ +0.000000] [<c1402276>] ? _raw_write_unlock+0x2c/0x3e
> [ +0.000000] [<f942937a>] l2cap_sock_release+0x57/0xa5 [bluetooth]
> [ +0.000000] [<f942937a>] ? l2cap_sock_release+0x57/0xa5 [bluetooth]
> [ +0.000000] [<c1318032>] sock_release+0x19/0x6b
> [ +0.000000] [<c1318032>] ? sock_release+0x19/0x6b
> [ +0.000000] [<c1318094>] sock_close+0x10/0x14
> [ +0.000000] [<c10e808a>] __fput+0xd6/0x162
> [ +0.000000] [<c10e8146>] ____fput+0xd/0xf
> [ +0.000000] [<c1049bc8>] task_work_run+0x7e/0xa4
> [ +0.000000] [<c1001d1e>] do_notify_resume+0x3c/0x3f
> [ +0.000000] [<c1402730>] work_notifysig+0x29/0x31
I wanted to follow up that it's the very first test case that just does
a socket() + close() that triggers this. It may well be that there are
other lockdep issues hidden, but since the kernel suppresses them after
the first one we'll only see once this one is fixed.
Johan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks
2015-07-09 9:36 ` Johan Hedberg
2015-07-09 9:56 ` Johan Hedberg
@ 2015-07-09 9:58 ` Dean Jenkins
2015-07-09 10:06 ` Marcel Holtmann
2015-07-09 10:14 ` Johan Hedberg
1 sibling, 2 replies; 23+ messages in thread
From: Dean Jenkins @ 2015-07-09 9:58 UTC (permalink / raw)
To: Marcel Holtmann, linux-bluetooth, Joshua_Frkuska
Hi Johan,
Please can you point to me to some details on how to use the
l2cap-tester tool so that I can attempt to look into this issue.
Thanks,
Regards,
Dean
On 09/07/15 10:36, Johan Hedberg wrote:
> Hi,
>
> On Thu, Jul 09, 2015, Marcel Holtmann wrote:
>>> Dean Jenkins (8):
>>> Bluetooth: L2CAP ERTM shutdown protect sk and chan
>>> Bluetooth: Make __l2cap_wait_ack more efficient
>>> Bluetooth: Unwind l2cap_sock_shutdown()
>>> Bluetooth: l2cap_sock_shutdown() remove mutex_lock calls
>>> Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking
>>> Bluetooth: Add BT_DBG to l2cap_sock_shutdown()
>>> Bluetooth: __l2cap_wait_ack() use msecs_to_jiffies()
>>> Bluetooth: __l2cap_wait_ack() add defensive timeout
>>>
>>> include/net/bluetooth/l2cap.h | 2 ++
>>> net/bluetooth/l2cap_sock.c | 74 +++++++++++++++++++++++++++----------------
>>> 2 files changed, 49 insertions(+), 27 deletions(-)
>> all 8 patches have been applied to bluetooth-next tree.
> I'm getting the following now when running our l2cap-tester tool:
>
> [Jul 9 12:34] ======================================================
> [ +0.000298] [ INFO: possible circular locking dependency detected ]
> [ +0.000298] 4.1.0-rc4+ #1356 Not tainted
> [ +0.000165] -------------------------------------------------------
> [ +0.000288] l2cap-tester/10613 is trying to acquire lock:
> [ +0.000000] (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+...}, at: [<f942807e>] lock_sock+0xa/0xc [bluetooth]
> [ +0.000336]
> but task is already holding lock:
> [ +0.000000] (&chan->lock/1){+.+...}, at: [<f94283b6>] l2cap_chan_lock+0x13/0x15 [bluetooth]
> [ +0.000000]
> which lock already depends on the new lock.
>
> [ +0.000000]
> the existing dependency chain (in reverse order) is:
> [ +0.000000]
> -> #1 (&chan->lock/1){+.+...}:
> [ +0.000000] [<c1064917>] lock_acquire+0xdd/0x14f
> [ +0.000000] [<c13ff419>] mutex_lock_nested+0x54/0x393
> [ +0.000000] [<f94283b6>] l2cap_chan_lock+0x13/0x15 [bluetooth]
> [ +0.000000] [<f9428ec1>] l2cap_sock_shutdown+0x28c/0x327 [bluetooth]
> [ +0.000000] [<f942937a>] l2cap_sock_release+0x57/0xa5 [bluetooth]
> [ +0.000000] [<c1318032>] sock_release+0x19/0x6b
> [ +0.000000] [<c1318094>] sock_close+0x10/0x14
> [ +0.000000] [<c10e808a>] __fput+0xd6/0x162
> [ +0.000000] [<c10e8146>] ____fput+0xd/0xf
> [ +0.000000] [<c1049bc8>] task_work_run+0x7e/0xa4
> [ +0.000000] [<c1001d1e>] do_notify_resume+0x3c/0x3f
> [ +0.000000] [<c1402730>] work_notifysig+0x29/0x31
> [ +0.000000]
> -> #0 (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+...}:
> [ +0.000000] [<c1064396>] __lock_acquire+0x98c/0xbfb
> [ +0.000000] [<c1064917>] lock_acquire+0xdd/0x14f
> [ +0.000000] [<c131cb86>] lock_sock_nested+0x63/0x7d
> [ +0.000000] [<f942807e>] lock_sock+0xa/0xc [bluetooth]
> [ +0.000000] [<f9428ed9>] l2cap_sock_shutdown+0x2a4/0x327 [bluetooth]
> [ +0.000000] [<f942937a>] l2cap_sock_release+0x57/0xa5 [bluetooth]
> [ +0.000000] [<c1318032>] sock_release+0x19/0x6b
> [ +0.000000] [<c1318094>] sock_close+0x10/0x14
> [ +0.000000] [<c10e808a>] __fput+0xd6/0x162
> [ +0.000000] [<c10e8146>] ____fput+0xd/0xf
> [ +0.000000] [<c1049bc8>] task_work_run+0x7e/0xa4
> [ +0.000000] [<c1001d1e>] do_notify_resume+0x3c/0x3f
> [ +0.000000] [<c1402730>] work_notifysig+0x29/0x31
> [ +0.000000]
> other info that might help us debug this:
>
> [ +0.000000] Possible unsafe locking scenario:
>
> [ +0.000000] CPU0 CPU1
> [ +0.000000] ---- ----
> [ +0.000000] lock(&chan->lock/1);
> [ +0.000000] lock(sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP);
> [ +0.000000] lock(&chan->lock/1);
> [ +0.000000] lock(sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP);
> [ +0.000000]
> *** DEADLOCK ***
>
> [ +0.000000] 1 lock held by l2cap-tester/10613:
> [ +0.000000] #0: (&chan->lock/1){+.+...}, at: [<f94283b6>] l2cap_chan_lock+0x13/0x15 [bluetooth]
> [ +0.000000]
> stack backtrace:
> [ +0.000000] CPU: 1 PID: 10613 Comm: l2cap-tester Not tainted 4.1.0-rc4+ #1356
> [ +0.000000] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
> [ +0.000000] 00000000 00000000 f1acbde4 c13fd7f8 c1c2d760 f1acbe14 c1062c61 c15f5534
> [ +0.000000] c15f5427 c15f53ef c15f5410 c15f53ef f1acbe48 f537f380 f537f7fc f537f380
> [ +0.000000] f537f814 f1acbe78 c1064396 f537f7fc 00000000 00000000 c1c2ffc0 00000000
> [ +0.000000] Call Trace:
> [ +0.000000] [<c13fd7f8>] dump_stack+0x49/0x73
> [ +0.000000] [<c1062c61>] print_circular_bug+0x190/0x19d
> [ +0.000000] [<c1064396>] __lock_acquire+0x98c/0xbfb
> [ +0.000000] [<c1064917>] lock_acquire+0xdd/0x14f
> [ +0.000000] [<f942807e>] ? lock_sock+0xa/0xc [bluetooth]
> [ +0.000000] [<c131cb86>] lock_sock_nested+0x63/0x7d
> [ +0.000000] [<f942807e>] ? lock_sock+0xa/0xc [bluetooth]
> [ +0.000000] [<f942807e>] lock_sock+0xa/0xc [bluetooth]
> [ +0.000000] [<f9428ed9>] l2cap_sock_shutdown+0x2a4/0x327 [bluetooth]
> [ +0.000000] [<f9401112>] ? bt_sock_unlink+0x16/0x54 [bluetooth]
> [ +0.000000] [<c1402276>] ? _raw_write_unlock+0x2c/0x3e
> [ +0.000000] [<f942937a>] l2cap_sock_release+0x57/0xa5 [bluetooth]
> [ +0.000000] [<f942937a>] ? l2cap_sock_release+0x57/0xa5 [bluetooth]
> [ +0.000000] [<c1318032>] sock_release+0x19/0x6b
> [ +0.000000] [<c1318032>] ? sock_release+0x19/0x6b
> [ +0.000000] [<c1318094>] sock_close+0x10/0x14
> [ +0.000000] [<c10e808a>] __fput+0xd6/0x162
> [ +0.000000] [<c10e8146>] ____fput+0xd/0xf
> [ +0.000000] [<c1049bc8>] task_work_run+0x7e/0xa4
> [ +0.000000] [<c1001d1e>] do_notify_resume+0x3c/0x3f
> [ +0.000000] [<c1402730>] work_notifysig+0x29/0x31
>
> Johan
--
Dean Jenkins
Embedded Software Engineer
Linux Transportation Solutions
Mentor Embedded Software Division
Mentor Graphics (UK) Ltd.
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks
2015-07-09 9:58 ` Dean Jenkins
@ 2015-07-09 10:06 ` Marcel Holtmann
2015-07-09 10:14 ` Johan Hedberg
1 sibling, 0 replies; 23+ messages in thread
From: Marcel Holtmann @ 2015-07-09 10:06 UTC (permalink / raw)
To: Dean Jenkins; +Cc: linux-bluetooth, Joshua_Frkuska
Hi Dean,
please refrain from top-posting on this mailing list.
> Please can you point to me to some details on how to use the l2cap-tester tool so that I can attempt to look into this issue.
And the easiest way to run this for testing is this way:
./tools/test-runner --kernel bzImage -- ./tools/l2cap-tester
If you have qemu installed. If available it should use KVM, but that would mean some sort of x86 based system ;)
In case you are on a target machine, just run ./tools/l2cap-tester.
Regards
Marcel
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks
2015-07-09 9:58 ` Dean Jenkins
2015-07-09 10:06 ` Marcel Holtmann
@ 2015-07-09 10:14 ` Johan Hedberg
1 sibling, 0 replies; 23+ messages in thread
From: Johan Hedberg @ 2015-07-09 10:14 UTC (permalink / raw)
To: Dean Jenkins; +Cc: Marcel Holtmann, linux-bluetooth, Joshua_Frkuska
Hi Dean,
On Thu, Jul 09, 2015, Dean Jenkins wrote:
> Please can you point to me to some details on how to use the l2cap-tester
> tool so that I can attempt to look into this issue.
First of all, please avoid top-posting on this list.
Regarding l2cap-tester, there's really nothing special needed except for
the hci_vhci module and running the tool as root. However, as I pointed
out what was causing this you shouldn't even need l2cap-tester, but just
create an L2CAP socket with any tool. The more important thing is to
have the right config options in the kernel. I've got at least the
following:
CONFIG_LOCKDEP_SUPPORT=y
CONFIG_DEBUG_SPINLOCK=y
CONFIG_DEBUG_LOCK_ALLOC=y
CONFIG_PROVE_LOCKING=y
CONFIG_LOCKDEP=y
CONFIG_DEBUG_MUTEXES=y
I'd guess only the "LOCKDEP" ones are really needed, but not completely
sure about it.
I was kind of half expecting you to already be familiar with
l2cap-tester since you were submitting patches to L2CAP, but I guess
it's never too late :) Either way it'd be good if you could also look
into adding new test cases to the tool that specifically exercise the
code paths that you were fixing.
Johan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 5/8] Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking
2015-06-23 16:59 ` [PATCH v2 5/8] Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking Dean Jenkins
@ 2015-07-13 10:26 ` Johan Hedberg
2015-07-13 11:12 ` Johan Hedberg
0 siblings, 1 reply; 23+ messages in thread
From: Johan Hedberg @ 2015-07-13 10:26 UTC (permalink / raw)
To: Dean Jenkins; +Cc: linux-bluetooth, marcel, Joshua_Frkuska
Hi Dean,
On Tue, Jun 23, 2015, Dean Jenkins wrote:
> @@ -1115,24 +1115,22 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
>
> BT_DBG("chan %p state %s", chan, state_to_string(chan->state));
>
> - l2cap_chan_lock(chan);
> -
> if (chan->mode == L2CAP_MODE_ERTM &&
> chan->unacked_frames > 0 &&
> chan->state == BT_CONNECTED)
> err = __l2cap_wait_ack(sk, chan);
>
> + l2cap_chan_lock(chan);
> release_sock(sk);
> l2cap_chan_close(chan, 0);
This l2cap_chan_close() could call l2cap_chan_del() which in turn could
could call list_del(&chan->list). This list is protected using
conn->chan_lock which you removed in your previous (4/8) patch from
l2cap_sock_shutdown().
Because of the missing mutex_lock(&conn->chan_lock) I now occasionally
get a race condition triggered which crashes the kernel. The following
was triggered with "l2cap-tester -p "L2CAP LE ATT Client - Success":
[ +22.878792] BUG: unable to handle kernel paging request at 6b6b68cf
[ +0.000423] IP: [<f83b6bee>] l2cap_chan_lock+0x6/0x15 [bluetooth]
[ +0.000300] *pde = 00000000
[ +0.000104] Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ +0.000272] Modules linked in: btusb btintel btbcm btrtl hci_vhci rfcomm bluetooth_6lowpan bluetooth
[ +0.000517] CPU: 0 PID: 1012 Comm: kworker/u5:2 Not tainted 4.1.0+ #1359
[ +0.000308] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
[ +0.000342] Workqueue: hci0 hci_rx_work [bluetooth]
[ +0.000000] task: f5655140 ti: f22b8000 task.ti: f22b8000
[ +0.000000] EIP: 0060:[<f83b6bee>] EFLAGS: 00010212 CPU: 0
[ +0.000000] EIP is at l2cap_chan_lock+0x6/0x15 [bluetooth]
[ +0.000000] EAX: 6b6b6b83 EBX: 6b6b68bf ECX: c1053dad EDX: 00000001
[ +0.000000] ESI: f53c4580 EDI: f22ccd70 EBP: f22b9dc8 ESP: f22b9d78
[ +0.000000] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ +0.000000] CR0: 8005003b CR2: 6b6b68cf CR3: 3216f000 CR4: 00000690
[ +0.000000] Stack:
[ +0.000000] f22b9dc8 f83bcb01 00000000 00000000 f83da1f4 f53c4593 f22ccea4 f5655140
[ +0.000000] f83da1c0 00000246 f52ef654 f22cce9c f22b9ddc c13fa8ff 00000000 f83a2b95
[ +0.000000] f83da1f4 f83da4e0 f53c4580 f22b9de4 f22b9df4 f83a2bb4 f53c4580 f53c4580
[ +0.000000] Call Trace:
[ +0.000000] [<f83bcb01>] ? l2cap_connect_cfm+0x1d2/0x2f2 [bluetooth]
[ +0.000000] [<c13fa8ff>] ? mutex_lock_nested+0x32f/0x346
[ +0.000000] [<f83a2b95>] ? hci_connect_cfm+0x18/0x5d [bluetooth]
[ +0.000000] [<f83a2bb4>] hci_connect_cfm+0x37/0x5d [bluetooth]
[ +0.000000] [<f83a2bb4>] ? hci_connect_cfm+0x37/0x5d [bluetooth]
[ +0.000000] [<f83a7228>] hci_le_meta_evt+0x445/0x801 [bluetooth]
[ +0.000000] [<c10e57f9>] ? kmem_cache_free+0x135/0x189
[ +0.000000] [<c1327f4b>] ? __kfree_skb+0x61/0x64
[ +0.000000] [<c1327f4b>] ? __kfree_skb+0x61/0x64
[ +0.000000] [<f83a9136>] hci_event_packet+0x1b52/0x2090 [bluetooth]
[ +0.000000] [<c1327799>] ? skb_dequeue+0x17/0x32
[ +0.000000] [<c10653cf>] ? trace_hardirqs_on+0xb/0xd
[ +0.000000] [<c13fcf20>] ? _raw_spin_unlock_irqrestore+0x44/0x57
[ +0.000000] [<f839ba46>] hci_rx_work+0xf1/0x28b [bluetooth]
[ +0.000000] [<f839ba46>] ? hci_rx_work+0xf1/0x28b [bluetooth]
[ +0.000000] [<c1048352>] ? process_one_work+0x152/0x432
[ +0.000000] [<c1048432>] process_one_work+0x232/0x432
[ +0.000000] [<c1048432>] ? process_one_work+0x232/0x432
[ +0.000000] [<c1048a4c>] worker_thread+0x1b8/0x255
[ +0.000000] [<c1048894>] ? rescuer_thread+0x23c/0x23c
[ +0.000000] [<c1048894>] ? rescuer_thread+0x23c/0x23c
[ +0.000000] [<c104c878>] kthread+0x91/0x96
[ +0.000000] [<c13fd581>] ret_from_kernel_thread+0x21/0x30
[ +0.000000] [<c104c7e7>] ? __kthread_parkme+0x72/0x72
[ +0.000000] Code: f8 04 b3 02 74 11 68 04 5f 3d f8 68 68 d3 3d f8 e8 bd a2 e3 c8 58 5a 8d 65 f4 88 d8 5b 5e 5f 5d 8d 67 f8 5f c3 55 05 c4 02 00 00 <8b> 90 4c fd ff ff 89 e5 e8 d5 39 04 c9 5d c3 55 89 e5 56 53 3e
[ +0.000000] EIP: [<f83b6bee>] l2cap_chan_lock+0x6/0x15 [bluetooth] SS:ESP 0068:f22b9d78
[ +0.000000] CR2: 000000006b6b68cf
To me this looks like the connected transition racing with user space
closing the socket in question (hence triggering l2cap_sock_shutdown).
It doesn't happen everytime, but it's not the only l2cap-tester case
that I've seen triggering this crash. If you just keep running
"l2cap-tester -q" over and over again you should quite quickly see the
issue.
Johan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 3/8] Bluetooth: Unwind l2cap_sock_shutdown()
2015-06-23 16:59 ` [PATCH v2 3/8] Bluetooth: Unwind l2cap_sock_shutdown() Dean Jenkins
@ 2015-07-13 11:07 ` Johan Hedberg
2015-07-13 17:31 ` Dean Jenkins
0 siblings, 1 reply; 23+ messages in thread
From: Johan Hedberg @ 2015-07-13 11:07 UTC (permalink / raw)
To: Dean Jenkins; +Cc: linux-bluetooth, marcel, Joshua_Frkuska
Hi Dean,
On Tue, Jun 23, 2015, Dean Jenkins wrote:
> --- a/net/bluetooth/l2cap_sock.c
> +++ b/net/bluetooth/l2cap_sock.c
> @@ -1100,6 +1100,13 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
> if (!sk)
> return 0;
>
> + lock_sock(sk);
> +
> + if (sk->sk_shutdown)
> + goto shutdown_already;
> +
> + sk->sk_shutdown = SHUTDOWN_MASK;
> +
> /* prevent sk structure from being freed whilst unlocked */
> sock_hold(sk);
>
> @@ -1114,30 +1121,21 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
> mutex_lock(&conn->chan_lock);
>
> l2cap_chan_lock(chan);
> - lock_sock(sk);
I guess this is at least part of the reason for the lockdep warnings we
started getting after your patches. The order of these locks should
always be l2cap_chan_lock() and then lock_sock(). Any other order
exposes us to potential deadlocks and the kernel lockdep system rightly
warns about it.
Do you think you'll be able to fix this as well as the missing
mutex_lock(&conn->chan_lock) issue this week? Otherwise we'll need to
consider reverting your patches since it's quite clear we can't make any
bluetooth-next pull requests with the current state of the tree.
Johan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 5/8] Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking
2015-07-13 10:26 ` Johan Hedberg
@ 2015-07-13 11:12 ` Johan Hedberg
0 siblings, 0 replies; 23+ messages in thread
From: Johan Hedberg @ 2015-07-13 11:12 UTC (permalink / raw)
To: Dean Jenkins, linux-bluetooth, marcel, Joshua_Frkuska
Hi,
On Mon, Jul 13, 2015, Johan Hedberg wrote:
> On Tue, Jun 23, 2015, Dean Jenkins wrote:
> > @@ -1115,24 +1115,22 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
> >
> > BT_DBG("chan %p state %s", chan, state_to_string(chan->state));
> >
> > - l2cap_chan_lock(chan);
> > -
> > if (chan->mode == L2CAP_MODE_ERTM &&
> > chan->unacked_frames > 0 &&
> > chan->state == BT_CONNECTED)
> > err = __l2cap_wait_ack(sk, chan);
> >
> > + l2cap_chan_lock(chan);
> > release_sock(sk);
> > l2cap_chan_close(chan, 0);
>
> This l2cap_chan_close() could call l2cap_chan_del() which in turn could
> could call list_del(&chan->list). This list is protected using
> conn->chan_lock which you removed in your previous (4/8) patch from
> l2cap_sock_shutdown().
Here's a full trace of another crash related to the same code path, this
time the teardown_cb() that happens through the l2cap_chan_close() call.
The l2cap-tester case that triggered it was "L2CAP LE Server - Success".
I had debug logs enabled for l2cap_sock.c and l2cap_core.c:
[ +0.000239] l2cap_sock_init: sk f2322a30
[ +0.000193] l2cap_sock_bind: sk f2322a30
[ +0.000161] l2cap_sock_connect: sk f2322a30
[ +0.000171] l2cap_chan_connect: 00:aa:01:00:00:00 -> 00:aa:01:01:00:00 (type 1) psm 0x80
[ +0.000647] l2cap_sock_release: sock f1a84c00, sk f2322a30
[ +0.000638] l2cap_sock_shutdown: sock f1a84c00, sk f2322a30
[ +0.000601] l2cap_chan_hold: chan f22a5c20 orig refcnt 2
[ +0.000404] l2cap_sock_shutdown: chan f22a5c20 state BT_BOUND
[ +0.000267] l2cap_chan_close: chan f22a5c20 state BT_BOUND
[ +0.000241] l2cap_sock_teardown_cb: chan f22a5c20 state BT_BOUND
[ +0.000272] l2cap_chan_put: chan f22a5c20 orig refcnt 3
[ +0.000226] l2cap_sock_shutdown: err: 0
[ +0.000153] l2cap_sock_kill: sk f2322a30 state BT_BOUND
[ +0.000317] l2cap_chan_put: chan f22a5c20 orig refcnt 2
[ +0.000331] l2cap_sock_destruct: sk f2322a30
[ +0.000355] l2cap_chan_put: chan f22a5c20 orig refcnt 1
[ +0.000345] l2cap_chan_destroy: chan f22a5c20
[ +0.016398] l2cap_chan_create: chan f2322a30
[ +0.000642] l2cap_sock_create: sock f1a86d00
[ +0.000467] l2cap_chan_create: chan f23212c0
[ +0.000247] l2cap_chan_hold: chan f23212c0 orig refcnt 1
[ +0.000264] l2cap_sock_init: sk f2323390
[ +0.000188] l2cap_sock_bind: sk f2323390
[ +0.000170] l2cap_sock_connect: sk f2323390
[ +0.000182] l2cap_chan_connect: 00:aa:01:00:00:00 -> 00:aa:01:01:00:00 (type 1) psm 0x80
[ +0.001553] l2cap_conn_add: hcon f22edf90 conn f4ee65a0 hchan f2341dd0
[ +0.000619] __l2cap_chan_add: conn f4ee65a0, psm 0x80, dcid 0x0000
[ +0.000322] l2cap_chan_hold: chan f23212c0 orig refcnt 2
[ +0.000264] l2cap_state_change: chan f23212c0 BT_BOUND -> BT_CONNECT
[ +0.000331] l2cap_chan_hold: chan f23212c0 orig refcnt 3
[ +0.003096] l2cap_connect_cfm: hcon f22edf90 bdaddr 00:aa:01:01:00:00 status 0
[ +0.000335] l2cap_chan_hold: chan f2322a30 orig refcnt 1
[ +0.000219] l2cap_chan_create: chan f2320e10
[ +0.000158] __l2cap_chan_add: conn f4ee65a0, psm 0x00, dcid 0x0006
[ +0.000257] l2cap_chan_hold: chan f2320e10 orig refcnt 1
[ +0.000210] l2cap_chan_put: chan f2322a30 orig refcnt 2
[ +0.000205] l2cap_conn_ready: conn f4ee65a0
[ +0.000154] l2cap_chan_hold: chan f2320e10 orig refcnt 2
[ +0.000210] l2cap_build_cmd: conn f4ee65a0, code 0x14, ident 0x01, len 10
[ +0.000303] l2cap_send_cmd: code 0x14
[ +0.000185] l2cap_le_conn_ready: hci0 conn f4ee65a0
[ +0.000236] process_pending_rx:
[ +0.003520] l2cap_recv_acldata: conn f4ee65a0 len 18 flags 0x2
[ +0.000460] l2cap_recv_frame: len 14, cid 0x0005
[ +0.000202] l2cap_le_sig_channel: code 0x15 len 10 id 0x01
[ +0.000248] l2cap_le_connect_rsp: dcid 0x0000 mtu 23 mps 23 credits 1 result 0x02
[ +0.000353] l2cap_chan_put: chan f23212c0 orig refcnt 4
[ +0.000227] l2cap_chan_del: chan f23212c0, conn f4ee65a0, err 111, state BT_CONNECT
[ +0.000362] l2cap_sock_teardown_cb: chan f23212c0 state BT_CONNECT
[ +0.000283] l2cap_chan_put: chan f23212c0 orig refcnt 3
[ +0.001285] l2cap_sock_release: sock f1a86d00, sk f2323390
[ +0.000232] l2cap_sock_shutdown: sock f1a86d00, sk f2323390
[ +0.000232] l2cap_chan_hold: chan f23212c0 orig refcnt 2
[ +0.000211] l2cap_sock_shutdown: chan f23212c0 state BT_CLOSED
[ +0.000398] l2cap_chan_close: chan f23212c0 state BT_CLOSED
[ +0.000463] l2cap_sock_teardown_cb: chan f23212c0 state BT_CLOSED
[ +0.000445] l2cap_chan_put: chan f23212c0 orig refcnt 3
[ +0.000314] l2cap_sock_shutdown: err: 0
[ +0.000194] l2cap_sock_kill: sk f2323390 state BT_CLOSED
[ +0.000227] l2cap_chan_put: chan f23212c0 orig refcnt 2
[ +0.000204] l2cap_sock_destruct: sk f2323390
[ +0.000156] l2cap_chan_put: chan f23212c0 orig refcnt 1
[ +0.000204] l2cap_chan_destroy: chan f23212c0
[ +0.000606] l2cap_disconn_cfm: hcon f22edf90 reason 22
[ +0.000214] l2cap_conn_del: hcon f22edf90 conn f4ee65a0, err 103
[ +0.000246] l2cap_chan_hold: chan f2320e10 orig refcnt 3
[ +0.000217] l2cap_chan_del: chan f2320e10, conn f4ee65a0, err 103, state BT_CONNECTED
[ +0.000414] l2cap_chan_put: chan f2320e10 orig refcnt 4
[ +0.000466] l2cap_chan_put: chan f2320e10 orig refcnt 3
[ +0.000359] l2cap_chan_put: chan f2320e10 orig refcnt 2
[ +0.027471] l2cap_chan_put: chan f2322a30 orig refcnt 1
[ +0.000474] l2cap_chan_destroy: chan f2322a30
[ +0.025638] l2cap_chan_create: chan f52daa30
[ +0.000359] l2cap_sock_create: sock f1a87600
[ +0.000181] l2cap_chan_create: chan f52daee0
[ +0.000159] l2cap_chan_hold: chan f52daee0 orig refcnt 1
[ +0.000210] l2cap_sock_init: sk f52d84b0
[ +0.000159] l2cap_sock_bind: sk f52d84b0
[ +0.000145] l2cap_sock_listen: sk f52d84b0 backlog 5
[ +0.001394] l2cap_connect_cfm: hcon f22ece30 bdaddr 00:aa:01:01:00:00 status 0
[ +0.000537] l2cap_conn_add: hcon f22ece30 conn f4fef310 hchan f4faa330
[ +0.000446] l2cap_chan_hold: chan f52daa30 orig refcnt 1
[ +0.000375] l2cap_chan_create: chan f52d8e10
[ +0.000271] __l2cap_chan_add: conn f4fef310, psm 0x00, dcid 0x0006
[ +0.000403] l2cap_chan_hold: chan f52d8e10 orig refcnt 1
[ +0.000332] l2cap_chan_put: chan f52daa30 orig refcnt 2
[ +0.000356] l2cap_conn_ready: conn f4fef310
[ +0.000245] l2cap_chan_hold: chan f52d8e10 orig refcnt 2
[ +0.000334] l2cap_le_conn_ready: hci0 conn f4fef310
[ +0.000414] l2cap_build_cmd: conn f4fef310, code 0x12, ident 0x01, len 8
[ +0.000470] l2cap_send_cmd: code 0x12
[ +0.000246] process_pending_rx:
[ +0.004040] l2cap_sock_release: sock f1a87600, sk f52d84b0
[ +0.000400] l2cap_sock_shutdown: sock f1a87600, sk f52d84b0
[ +0.000391] l2cap_chan_hold: chan f52daee0 orig refcnt 2
[ +0.000373] l2cap_sock_shutdown: chan f52daee0 state BT_LISTEN
[ +0.000416] l2cap_chan_close: chan f52daee0 state BT_LISTEN
[ +0.000390] l2cap_sock_teardown_cb: chan f52daee0 state BT_LISTEN
[ +0.000072] l2cap_recv_acldata: conn f4fef310 len 18 flags 0x2
[ +0.000002] l2cap_recv_frame: len 14, cid 0x0005
[ +0.000002] l2cap_le_sig_channel: code 0x14 len 10 id 0x01
[ +0.000002] l2cap_le_connect_req: psm 0x80 scid 0x0041 mtu 32 mps 32
[ +0.000003] l2cap_chan_hold: chan f52daee0 orig refcnt 3
[ +0.002304] l2cap_sock_cleanup_listen: parent f52d84b0 state BT_LISTEN
[ +0.000464] l2cap_chan_put: chan f52daee0 orig refcnt 4
[ +0.000363] l2cap_sock_shutdown: err: 0
[ +0.000035] l2cap_chan_create: chan f22a5770
[ +0.000001] l2cap_chan_hold: chan f22a5770 orig refcnt 1
[ +0.000002] l2cap_sock_init: sk f22a5c20
[ +0.000003] __l2cap_chan_add: conn f4fef310, psm 0x80, dcid 0x0041
[ +0.000001] l2cap_chan_hold: chan f22a5770 orig refcnt 2
[ +0.000001] l2cap_chan_hold: chan f22a5770 orig refcnt 3
[ +0.000010] l2cap_chan_put: chan f22a5770 orig refcnt 4
[ +0.000002] l2cap_sock_ready_cb: sk f22a5c20, parent f52d84b0
[ +0.000002] l2cap_chan_put: chan f52daee0 orig refcnt 3
[ +0.000001] l2cap_build_cmd: conn f4fef310, code 0x15, ident 0x01, len 10
[ +0.000026] l2cap_send_cmd: code 0x15
[ +0.000056] l2cap_recv_acldata: conn f4fef310 len 10 flags 0x2
[ +0.000002] l2cap_recv_frame: len 6, cid 0x0005
[ +0.000001] l2cap_le_sig_channel: code 0x13 len 2 id 0x01
[ +0.005157] l2cap_sock_kill: sk f52d84b0 state BT_CLOSED
[ +0.000379] l2cap_chan_put: chan f52daee0 orig refcnt 2
[ +0.000369] l2cap_sock_destruct: sk f52d84b0
[ +0.000275] l2cap_chan_put: chan f52daee0 orig refcnt 1
[ +0.000350] l2cap_chan_destroy: chan f52daee0
[ +0.000295] l2cap_disconn_cfm: hcon f22ece30 reason 22
[ +0.000207] l2cap_conn_del: hcon f22ece30 conn f4fef310, err 103
[ +0.000284] l2cap_chan_hold: chan f22a5770 orig refcnt 3
[ +0.000236] l2cap_chan_del: chan f22a5770, conn f4fef310, err 103, state BT_CONNECTED
[ +0.000381] l2cap_sock_teardown_cb: chan f22a5770 state BT_CONNECTED
[ +0.000287] ------------[ cut here ]------------
[ +0.000188] WARNING: CPU: 0 PID: 830 at lib/list_debug.c:59 __list_del_entry+0x3f/0x71()
[ +0.000378] list_del corruption. prev->next should be f22a5ee0, but was 6b6b6b6b
[ +0.000535] Modules linked in: btusb btintel btbcm btrtl hci_vhci rfcomm bluetooth_6lowpan bluetooth
[ +0.000818] CPU: 0 PID: 830 Comm: l2cap-tester Not tainted 4.1.0+ #1359
[ +0.000493] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
[ +0.001082] 00000000 00000000 f52efdd8 c13f89bb f52efe00 f52efdf0 c1037089 c11efa16
[ +0.000792] 6b6b6b6b f22a5ee0 f52efe50 f52efe08 c10370cb 00000009 f52efe00 c1613939
[ +0.000828] f52efe1c f52efe28 c11efa16 c1613843 0000003b c1613939 f22a5ee0 6b6b6b6b
[ +0.000916] Call Trace:
[ +0.000115] [<c13f89bb>] dump_stack+0x49/0x73
[ +0.000285] [<c1037089>] warn_slowpath_common+0x83/0x9a
[ +0.000364] [<c11efa16>] ? __list_del_entry+0x3f/0x71
[ +0.000340] [<c10370cb>] warn_slowpath_fmt+0x2b/0x2f
[ +0.000330] [<c11efa16>] __list_del_entry+0x3f/0x71
[ +0.000340] [<f9401202>] bt_accept_unlink+0x47/0x84 [bluetooth]
[ +0.000413] [<f94298bb>] l2cap_sock_teardown_cb+0x178/0x19e [bluetooth]
[ +0.000435] [<f94298bb>] ? l2cap_sock_teardown_cb+0x178/0x19e [bluetooth]
[ +0.000482] [<f94209ad>] l2cap_chan_del+0x5d/0x14d [bluetooth]
[ +0.000410] [<f94209ad>] ? l2cap_chan_del+0x5d/0x14d [bluetooth]
[ +0.000531] [<f9423976>] l2cap_conn_del+0x109/0x17b [bluetooth]
[ +0.000418] [<f9423976>] ? l2cap_conn_del+0x109/0x17b [bluetooth]
[ +0.000422] [<f940aa20>] ? hci_conn_hash_flush+0x62/0xba [bluetooth]
[ +0.000371] [<f9423a31>] l2cap_disconn_cfm+0x49/0x50 [bluetooth]
[ +0.000265] [<f9423a31>] ? l2cap_disconn_cfm+0x49/0x50 [bluetooth]
[ +0.000268] [<f940aa3e>] hci_conn_hash_flush+0x80/0xba [bluetooth]
[ +0.000265] [<f9405abe>] hci_dev_do_close+0x25f/0x3ac [bluetooth]
[ +0.000261] [<f9405abe>] ? hci_dev_do_close+0x25f/0x3ac [bluetooth]
[ +0.000294] [<f9408006>] hci_unregister_dev+0x6c/0x1d6 [bluetooth]
[ +0.000332] [<f9408006>] ? hci_unregister_dev+0x6c/0x1d6 [bluetooth]
[ +0.000680] [<f800e075>] vhci_release+0x28/0x47 [hci_vhci]
[ +0.000361] [<f800e075>] ? vhci_release+0x28/0x47 [hci_vhci]
[ +0.000376] [<c10eaae6>] __fput+0xd6/0x162
[ +0.000252] [<c10eaba2>] ____fput+0xd/0xf
[ +0.000240] [<c104b293>] task_work_run+0x69/0x8b
[ +0.000288] [<c1001ef7>] do_notify_resume+0x3c/0x3f
[ +0.000314] [<c13fd7f0>] work_notifysig+0x29/0x31
[ +0.000296] ---[ end trace 3124333c67133c65 ]---
[ +0.000283] BUG: unable to handle kernel paging request at 6b6b6b6b
[ +0.000442] IP: [<6b6b6b6b>] 0x6b6b6b6b
[ +0.000234] *pde = 00000000
[ +0.000149] Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ +0.000058] Modules linked in: btusb btintel btbcm btrtl hci_vhci rfcomm bluetooth_6lowpan bluetooth
[ +0.000000] CPU: 0 PID: 830 Comm: l2cap-tester Tainted: G W 4.1.0+ #1359
[ +0.000000] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
[ +0.001736] =============================================================================
[ +0.000002] BUG kmalloc-1024 (Tainted: G W ): Poison overwritten
[ +0.000000] -----------------------------------------------------------------------------
[ +0.000002] INFO: 0xf52d86d0-0xf52d86d0. First byte 0x6a instead of 0x6b
[ +0.000004] INFO: Allocated in sk_prot_alloc+0x7f/0xda age=11 cpu=0 pid=830
[ +0.000002] __slab_alloc.constprop.67+0x205/0x3aa
[ +0.000001] __kmalloc+0x9a/0x123
[ +0.000001] sk_prot_alloc+0x7f/0xda
[ +0.000001] sk_alloc+0x1e/0x5c
[ +0.000020] l2cap_sock_alloc.constprop.5+0x26/0x9c [bluetooth]
[ +0.000019] l2cap_sock_create+0x7a/0xc2 [bluetooth]
[ +0.000012] bt_sock_create+0x80/0xbb [bluetooth]
[ +0.000002] __sock_create+0x145/0x1c7
[ +0.000001] sock_create+0x29/0x2e
[ +0.000002] SYSC_socket+0x22/0x7d
[ +0.000001] SYSC_socketcall+0x78/0x383
[ +0.000002] SyS_socketcall+0x13/0x15
[ +0.000002] sysenter_after_call+0x0/0x24
[ +0.000002] INFO: Freed in sk_destruct+0x119/0x133 age=5 cpu=0 pid=830
[ +0.000001] __slab_free+0x41/0x26a
[ +0.000001] kfree+0x145/0x191
[ +0.000001] sk_destruct+0x119/0x133
[ +0.000002] __sk_free+0x63/0x7c
[ +0.000001] sk_free+0x18/0x1a
[ +0.000017] sock_put+0xf/0x11 [bluetooth]
[ +0.000017] l2cap_sock_kill+0x6c/0x71 [bluetooth]
[ +0.000017] l2cap_sock_release+0x97/0xa5 [bluetooth]
[ +0.000002] sock_release+0x19/0x6b
[ +0.000001] sock_close+0x10/0x14
[ +0.000002] __fput+0xd6/0x162
[ +0.000001] ____fput+0xd/0xf
[ +0.000002] task_work_run+0x69/0x8b
[ +0.000002] do_notify_resume+0x3c/0x3f
[ +0.000001] work_notifysig+0x29/0x31
[ +0.000001] INFO: Slab 0xf6fd2b00 objects=13 used=13 fp=0x (null) flags=0x35004080
[ +0.000001] INFO: Object 0xf52d84b0 @offset=1200 fp=0xf52daee0
[ +0.000002] Bytes b4 f52d84a0: 00 00 00 00 55 00 ff ff 5a 5a 5a 5a 5a 5a 5a 5a ....U...ZZZZZZZZ
[ +0.000002] Object f52d84b0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d84c0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d84d0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d84e0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d84f0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8500: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8510: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8520: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8530: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8540: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8550: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8560: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8570: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8580: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000000] Object f52d8590: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d85a0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000002] Object f52d85b0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d85c0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000000] Object f52d85d0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000006] Object f52d85e0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d85f0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8600: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8610: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8620: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8630: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8640: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8650: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8660: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8670: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8680: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8690: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d86a0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d86b0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d86c0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d86d0: 6a 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b jkkkkkkkkkkkkkkk
[ +0.000001] Object f52d86e0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d86f0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8700: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8710: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8720: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8730: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8740: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8750: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8760: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000000] Object f52d8770: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000002] Object f52d8780: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8790: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d87a0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d87b0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d87c0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000000] Object f52d87d0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d87e0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d87f0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8800: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8810: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8820: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8830: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8840: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8850: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8860: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000003] Object f52d8870: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8880: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d8890: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
[ +0.000001] Object f52d88a0: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk.
[ +0.000001] Redzone f52d88b0: bb bb bb bb ....
[ +0.000001] Padding f52d8958: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ
[ +0.000002] CPU: 1 PID: 94 Comm: systemd-journal Tainted: G B W 4.1.0+ #1359
[ +0.000001] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.8.1-20150318_183358- 04/01/2014
[ +0.000004] 00000000 00000000 f4daf79c c13f89bb f6001780 f4daf7b4 c10e3d9c f52d8000
[ +0.000004] 0000006b f52d86d0 f52d86d1 f4daf7d8 c10e3e1c f52d84b0 f6fd2b00 f52d86d0
[ +0.000004] f6001780 f6001780 f52d84b0 f52d88b0 f4daf804 c10e40e0 c15fe0cd f52d84b0
[ +0.000001] Call Trace:
[ +0.000002] [<c13f89bb>] dump_stack+0x49/0x73
[ +0.000002] [<c10e3d9c>] print_trailer+0xec/0xf4
[ +0.000002] [<c10e3e1c>] check_bytes_and_report+0x78/0xae
[ +0.000001] [<c10e40e0>] check_object+0xe9/0x172
[ +0.000002] [<c10e47e6>] alloc_debug_processing+0x51/0xdd
[ +0.000002] [<c10e4a77>] __slab_alloc.constprop.67+0x205/0x3aa
[ +0.000005] [<c1241a22>] ? virtqueue_add+0x7a/0x29a
[ +0.000002] [<c1241a22>] ? virtqueue_add+0x7a/0x29a
[ +0.000003] [<c1065b77>] ? __lock_acquire+0x586/0xc02
[ +0.000002] [<c1062f8a>] ? arch_local_irq_save+0x8/0xb
[ +0.000002] [<c10e4cb6>] __kmalloc+0x9a/0x123
[ +0.000001] [<c10e4cb6>] ? __kmalloc+0x9a/0x123
[ +0.000002] [<c1241a22>] ? virtqueue_add+0x7a/0x29a
[ +0.000002] [<c1241a22>] virtqueue_add+0x7a/0x29a
[ +0.000001] [<c10e43b0>] ? deactivate_slab+0x116/0x1fa
[ +0.000002] [<c1241c94>] virtqueue_add_sgs+0x52/0x5a
[ +0.000002] [<c1241c94>] ? virtqueue_add_sgs+0x52/0x5a
[ +0.000002] [<c12a4091>] __virtblk_add_req+0x12a/0x132
[ +0.000003] [<c12a4216>] ? virtio_queue_rq+0x11d/0x1cd
[ +0.000003] [<c13fcd0e>] ? _raw_spin_lock_irqsave+0x3e/0x47
[ +0.000001] [<c12a423c>] virtio_queue_rq+0x143/0x1cd
[ +0.000004] [<c11d16b3>] __blk_mq_run_hw_queue+0x178/0x25e
[ +0.000002] [<c11d14c2>] blk_mq_run_hw_queue+0x53/0xcc
[ +0.000002] [<c11d26d3>] blk_mq_insert_requests+0xfe/0x15e
[ +0.000003] [<c11d2ccd>] blk_mq_flush_plug_list+0xb4/0xbe
[ +0.000003] [<c11cb3da>] blk_flush_plug_list+0x79/0x17b
[ +0.000002] [<c11c8777>] ? rcu_read_unlock+0x52/0x54
[ +0.000002] [<c11caa8a>] ? blk_account_io_start+0x112/0x118
[ +0.000002] [<c11d27f7>] blk_sq_make_request+0xc4/0x110
[ +0.000002] [<c11c9c28>] generic_make_request+0x82/0xb5
[ +0.000002] [<c11c9d1a>] submit_bio+0xbf/0xc7
[ +0.000003] [<c11c3dc0>] ? bio_add_page+0x78/0x82
[ +0.000002] [<c11cfdda>] blkdev_issue_zeroout+0x1d0/0x229
[ +0.000012] [<c1156bab>] ext4_ext_zeroout.isra.32+0x6b/0x80
[ +0.000003] [<c115ae85>] ext4_ext_handle_unwritten_extents+0x64f/0x99f
[ +0.000003] [<c115b5bb>] ext4_ext_map_blocks+0x3bf/0xba2
[ +0.000003] [<c113bd25>] ? ext4_map_blocks+0x214/0x37c
[ +0.000003] [<c13fc082>] ? down_write+0x38/0x49
[ +0.000001] [<c113bd45>] ext4_map_blocks+0x234/0x37c
[ +0.000002] [<c113dec7>] mpage_map_and_submit_extent+0xfd/0x5aa
[ +0.000003] [<c113aabf>] ? mpage_prepare_extent_to_map+0x1b4/0x1be
[ +0.000003] [<c113e72c>] ext4_writepages+0x3b8/0x5eb
[ +0.000002] [<c1062f8a>] ? arch_local_irq_save+0x8/0xb
[ +0.000006] [<c10c156f>] do_writepages+0x1c/0x29
[ +0.000003] [<c10b9d9c>] __filemap_fdatawrite_range+0x59/0x65
[ +0.000003] [<c10b9e3c>] filemap_write_and_wait_range+0x28/0x5e
[ +0.000002] [<c1137239>] ext4_sync_file+0x1c4/0x3ba
[ +0.000002] [<c110c9c4>] vfs_fsync_range+0x74/0x86
[ +0.000002] [<c110c9ef>] vfs_fsync+0x19/0x1b
[ +0.000002] [<c110cb7a>] do_fsync+0x2c/0x42
[ +0.000003] [<c110cd64>] SyS_fsync+0x12/0x14
[ +0.000002] [<c13fd688>] sysenter_do_call+0x12/0x12
[ +0.000002] FIX kmalloc-1024: Restoring 0xf52d86d0-0xf52d86d0=0x6b
[ +0.000001] FIX kmalloc-1024: Marking all objects used
[ -0.002108] task: f2284100 ti: f52ee000 task.ti: f52ee000
[ +0.000000] EIP: 0060:[<6b6b6b6b>] EFLAGS: 00010202 CPU: 0
[ +0.000000] EIP is at 0x6b6b6b6b
[ +0.000000] EAX: f52d84b0 EBX: f22a5c20 ECX: f52efe00 EDX: f52d84b0
[ +0.000000] ESI: 00000067 EDI: f22a5770 EBP: f52efe68 ESP: f52efe4c
[ +0.000000] DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
[ +0.000000] CR0: 8005003b CR2: 6b6b6b6b CR3: 322f3000 CR4: 00000690
[ +0.000000] Stack:
[ +0.000000] f94298c6 00000286 f52d84b0 f52efe88 f22a5770 f4fef310 f52efe78 f52efe88
[ +0.000000] f94209ad 00000067 f94209ad 00000000 f4fef310 f22a5770 f52efe98 f52efeb8
[ +0.000000] f9423976 f22ece30 f9423976 f52d8e10 f4fef43c f4fef444 00000067 f940aa20
[ +0.000000] Call Trace:
[ +0.000000] [<f94298c6>] ? l2cap_sock_teardown_cb+0x183/0x19e [bluetooth]
[ +0.000000] [<f94209ad>] l2cap_chan_del+0x5d/0x14d [bluetooth]
[ +0.000000] [<f94209ad>] ? l2cap_chan_del+0x5d/0x14d [bluetooth]
[ +0.000000] [<f9423976>] l2cap_conn_del+0x109/0x17b [bluetooth]
[ +0.000000] [<f9423976>] ? l2cap_conn_del+0x109/0x17b [bluetooth]
[ +0.000000] [<f940aa20>] ? hci_conn_hash_flush+0x62/0xba [bluetooth]
[ +0.000000] [<f9423a31>] l2cap_disconn_cfm+0x49/0x50 [bluetooth]
[ +0.000000] [<f9423a31>] ? l2cap_disconn_cfm+0x49/0x50 [bluetooth]
[ +0.000000] [<f940aa3e>] hci_conn_hash_flush+0x80/0xba [bluetooth]
[ +0.000000] [<f9405abe>] hci_dev_do_close+0x25f/0x3ac [bluetooth]
[ +0.000000] [<f9405abe>] ? hci_dev_do_close+0x25f/0x3ac [bluetooth]
[ +0.000000] [<f9408006>] hci_unregister_dev+0x6c/0x1d6 [bluetooth]
[ +0.000000] [<f9408006>] ? hci_unregister_dev+0x6c/0x1d6 [bluetooth]
[ +0.000000] [<f800e075>] vhci_release+0x28/0x47 [hci_vhci]
[ +0.000000] [<f800e075>] ? vhci_release+0x28/0x47 [hci_vhci]
[ +0.000000] [<c10eaae6>] __fput+0xd6/0x162
[ +0.000000] [<c10eaba2>] ____fput+0xd/0xf
[ +0.000000] [<c104b293>] task_work_run+0x69/0x8b
[ +0.000000] [<c1001ef7>] do_notify_resume+0x3c/0x3f
[ +0.000000] [<c13fd7f0>] work_notifysig+0x29/0x31
[ +0.000000] Code: Bad EIP value.
[ +0.000000] EIP: [<6b6b6b6b>] 0x6b6b6b6b SS:ESP 0068:f52efe4c
[ +0.000000] CR2: 000000006b6b6b6b
Johan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 3/8] Bluetooth: Unwind l2cap_sock_shutdown()
2015-07-13 11:07 ` Johan Hedberg
@ 2015-07-13 17:31 ` Dean Jenkins
2015-07-14 10:47 ` Johan Hedberg
2015-07-16 8:08 ` Johan Hedberg
0 siblings, 2 replies; 23+ messages in thread
From: Dean Jenkins @ 2015-07-13 17:31 UTC (permalink / raw)
To: linux-bluetooth, marcel, Joshua_Frkuska
Hi Johan,
On 13/07/15 12:07, Johan Hedberg wrote:
> Hi Dean,
>
> On Tue, Jun 23, 2015, Dean Jenkins wrote:
>> --- a/net/bluetooth/l2cap_sock.c
>> +++ b/net/bluetooth/l2cap_sock.c
>> @@ -1100,6 +1100,13 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
>> if (!sk)
>> return 0;
>>
>> + lock_sock(sk);
>> +
>> + if (sk->sk_shutdown)
>> + goto shutdown_already;
>> +
>> + sk->sk_shutdown = SHUTDOWN_MASK;
>> +
>> /* prevent sk structure from being freed whilst unlocked */
>> sock_hold(sk);
>>
>> @@ -1114,30 +1121,21 @@ static int l2cap_sock_shutdown(struct socket *sock, int how)
>> mutex_lock(&conn->chan_lock);
>>
>> l2cap_chan_lock(chan);
>> - lock_sock(sk);
> I guess this is at least part of the reason for the lockdep warnings we
> started getting after your patches. The order of these locks should
> always be l2cap_chan_lock() and then lock_sock(). Any other order
> exposes us to potential deadlocks and the kernel lockdep system rightly
> warns about it.
>
> Do you think you'll be able to fix this as well as the missing
> mutex_lock(&conn->chan_lock) issue this week? Otherwise we'll need to
> consider reverting your patches since it's quite clear we can't make any
> bluetooth-next pull requests with the current state of the tree.
I think it would be wise to revert the changes as I am unable to
guarantee that I get time to propose a fix during this week. I will try
to work on a v3 patchset based on your feedback.
The use of the
mutex_lock(&conn->chan_lock)
is troublesome because the underlying conn connection can disappear
whilst waiting for acks, that is why I eliminated the conn variable and
used chan->state instead. Is there an atomic method to check conn and
take the lock ?
I did some lockdep checking on our ARM kernel 3.14 but I get an
unrelated early lockdep report. This might be why we did not see any
lockdep issue for L2CAP. I think we might have a patch to force multiple
lockdeps to be reported, I will need to investigate.
I am trying to work out how to build l2cap-tester for a cross-compiled
ARM environment which was built from bitbake. I suspect I need to create
a bitbake recipe to build l2cap-tester, perhaps a recipe already exists
in Yocto ?
I now have a PTS dongle but I am having difficulties understanding how
to run any of the test cases. Do you have any hints ?
Thanks,
Regards,
Dean
--
Dean Jenkins
Embedded Software Engineer
Linux Transportation Solutions
Mentor Embedded Software Division
Mentor Graphics (UK) Ltd.
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 3/8] Bluetooth: Unwind l2cap_sock_shutdown()
2015-07-13 17:31 ` Dean Jenkins
@ 2015-07-14 10:47 ` Johan Hedberg
2015-07-16 8:08 ` Johan Hedberg
1 sibling, 0 replies; 23+ messages in thread
From: Johan Hedberg @ 2015-07-14 10:47 UTC (permalink / raw)
To: Dean Jenkins; +Cc: linux-bluetooth, marcel, Joshua_Frkuska
Hi Dean,
On Mon, Jul 13, 2015, Dean Jenkins wrote:
> The use of the
>
> mutex_lock(&conn->chan_lock)
>
> is troublesome because the underlying conn connection can disappear whilst
> waiting for acks, that is why I eliminated the conn variable and used
> chan->state instead. Is there an atomic method to check conn and take the
> lock ?
There might be some more elegant way to solve this whole issue (maybe
with RCU helpers or something like that), but at least the following
could work, I think:
static struct l2cap_conn *lock_conn(struct l2cap_chan *chan)
{
struct l2cap_conn *conn;
l2cap_chan_lock(chan);
if (chan->conn)
conn = l2cap_conn_get(chan->conn);
else
conn = NULL;
l2cap_chan_unlock(chan);
if (conn)
mutex_lock(&conn->chan_lock);
return conn;
}
static void unlock_conn(struct l2cap_conn *conn)
{
if (conn) {
mutex_unlock(&conn->chan_lock);
l2cap_conn_put(conn);
}
}
{
...
conn = lock_conn(chan);
l2cap_chan_lock(chan);
l2cap_chan_close(chan, 0);
l2cap_chan_unlock(chan);
unlock_conn(conn);
...
}
Johan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 3/8] Bluetooth: Unwind l2cap_sock_shutdown()
2015-07-13 17:31 ` Dean Jenkins
2015-07-14 10:47 ` Johan Hedberg
@ 2015-07-16 8:08 ` Johan Hedberg
2015-07-16 8:37 ` Dean Jenkins
1 sibling, 1 reply; 23+ messages in thread
From: Johan Hedberg @ 2015-07-16 8:08 UTC (permalink / raw)
To: Dean Jenkins; +Cc: linux-bluetooth, marcel, Joshua_Frkuska
Hi Dean,
On Mon, Jul 13, 2015, Dean Jenkins wrote:
> >Do you think you'll be able to fix this as well as the missing
> >mutex_lock(&conn->chan_lock) issue this week? Otherwise we'll need to
> >consider reverting your patches since it's quite clear we can't make any
> >bluetooth-next pull requests with the current state of the tree.
>
> I think it would be wise to revert the changes as I am unable to guarantee
> that I get time to propose a fix during this week. I will try to work on a
> v3 patchset based on your feedback.
I went ahead and pushed a rebased tree with your patches 3/8, 4/8 and
5/8 removed. The other five were either harmless or good fixes. So
if/when you have new patches please base them against the new tree.
Johan
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 3/8] Bluetooth: Unwind l2cap_sock_shutdown()
2015-07-16 8:08 ` Johan Hedberg
@ 2015-07-16 8:37 ` Dean Jenkins
2015-07-30 11:51 ` Marcel Holtmann
0 siblings, 1 reply; 23+ messages in thread
From: Dean Jenkins @ 2015-07-16 8:37 UTC (permalink / raw)
To: linux-bluetooth, marcel, Joshua_Frkuska
Hi Johan,
On 16/07/15 09:08, Johan Hedberg wrote:
> Hi Dean,
>
> On Mon, Jul 13, 2015, Dean Jenkins wrote:
>>> Do you think you'll be able to fix this as well as the missing
>>> mutex_lock(&conn->chan_lock) issue this week? Otherwise we'll need to
>>> consider reverting your patches since it's quite clear we can't make any
>>> bluetooth-next pull requests with the current state of the tree.
>> I think it would be wise to revert the changes as I am unable to guarantee
>> that I get time to propose a fix during this week. I will try to work on a
>> v3 patchset based on your feedback.
> I went ahead and pushed a rebased tree with your patches 3/8, 4/8 and
> 5/8 removed. The other five were either harmless or good fixes. So
> if/when you have new patches please base them against the new tree.
>
>
Thanks for the information. I shall endeavour to fix the locking issues
but it will take me some days.
Regards,
Dean
--
Dean Jenkins
Embedded Software Engineer
Linux Transportation Solutions
Mentor Embedded Software Division
Mentor Graphics (UK) Ltd.
^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v2 3/8] Bluetooth: Unwind l2cap_sock_shutdown()
2015-07-16 8:37 ` Dean Jenkins
@ 2015-07-30 11:51 ` Marcel Holtmann
0 siblings, 0 replies; 23+ messages in thread
From: Marcel Holtmann @ 2015-07-30 11:51 UTC (permalink / raw)
To: Dean Jenkins; +Cc: linux-bluetooth, Joshua_Frkuska
Hi Dean,
>>>> Do you think you'll be able to fix this as well as the missing
>>>> mutex_lock(&conn->chan_lock) issue this week? Otherwise we'll need to
>>>> consider reverting your patches since it's quite clear we can't make any
>>>> bluetooth-next pull requests with the current state of the tree.
>>> I think it would be wise to revert the changes as I am unable to guarantee
>>> that I get time to propose a fix during this week. I will try to work on a
>>> v3 patchset based on your feedback.
>> I went ahead and pushed a rebased tree with your patches 3/8, 4/8 and
>> 5/8 removed. The other five were either harmless or good fixes. So
>> if/when you have new patches please base them against the new tree.
>>
>>
> Thanks for the information. I shall endeavour to fix the locking issues but it will take me some days.
any updates?
Regards
Marcel
^ permalink raw reply [flat|nested] 23+ messages in thread
end of thread, other threads:[~2015-07-30 11:51 UTC | newest]
Thread overview: 23+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2015-06-23 16:59 [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 1/8] Bluetooth: L2CAP ERTM shutdown protect sk and chan Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 2/8] Bluetooth: Make __l2cap_wait_ack more efficient Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 3/8] Bluetooth: Unwind l2cap_sock_shutdown() Dean Jenkins
2015-07-13 11:07 ` Johan Hedberg
2015-07-13 17:31 ` Dean Jenkins
2015-07-14 10:47 ` Johan Hedberg
2015-07-16 8:08 ` Johan Hedberg
2015-07-16 8:37 ` Dean Jenkins
2015-07-30 11:51 ` Marcel Holtmann
2015-06-23 16:59 ` [PATCH v2 4/8] Bluetooth: l2cap_sock_shutdown() remove mutex_lock calls Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 5/8] Bluetooth: l2cap_sock_shutdown() reduce scope of chan locking Dean Jenkins
2015-07-13 10:26 ` Johan Hedberg
2015-07-13 11:12 ` Johan Hedberg
2015-06-23 16:59 ` [PATCH v2 6/8] Bluetooth: Add BT_DBG to l2cap_sock_shutdown() Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 7/8] Bluetooth: __l2cap_wait_ack() use msecs_to_jiffies() Dean Jenkins
2015-06-23 16:59 ` [PATCH v2 8/8] Bluetooth: __l2cap_wait_ack() add defensive timeout Dean Jenkins
2015-07-09 8:42 ` [PATCH v2 0/8] Avoid L2CAP ERTM shutdown hung tasks Marcel Holtmann
2015-07-09 9:36 ` Johan Hedberg
2015-07-09 9:56 ` Johan Hedberg
2015-07-09 9:58 ` Dean Jenkins
2015-07-09 10:06 ` Marcel Holtmann
2015-07-09 10:14 ` Johan Hedberg
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.