Since 2.6.32 we are seeing kernel panics like:
[10651.110229] Unable to handle kernel paging request at virtual
address 6b6b6b6b
[10651.111968] Internal error: Oops: 5 [#1] PREEMPT
[10651.113952] CPU: 0 ? ?Tainted: G ? ? ? ?W ? (2.6.32-59979-gd0c97db #1)
[10651.114624] PC is at rfcomm_run+0xa04/0xdbc
<...>
[10651.406188] [<c031ad24>] (rfcomm_run+0xa04/0xdbc) from [<c006ce30>]
(kthread+0x78/0x80)
[10651.406585] [<c006ce30>] (kthread+0x78/0x80) from [<c002793c>]
(kernel_thread_exit+0x0/0x8)
(rfcomm_run() is all inlined so theres not much of a stack trace))
This is a use-after-free on struct rfcomm_session s in the call chain
rfcomm_run() -> rfcomm_process_sessions() -> rfcomm_process_dlcs() ->
list_for_each_safe(p, n, &s->dlcs). The only way this can happen is if
there is an unbalanced refcount on the rfcomm session.
We found that reverting the patch
9e726b17422bade75fba94e625cd35fd1353e682 "Bluetooth: Fix rejected
connection not disconnecting ACL link" fixes the issue for us. The
patch itself looks ok, I added some logging to check the new refcounts
in the patch are balanced and they are. However if I remove the new
calls to rfcomm_session_put() and rfcomm_session_hold() the crash is
resolved. I also found that we can crash without hitting
rfcomm_session_timeout(), so its not related to Marcel's recent patch
to remove the scheduling-while-atomic warning.
9e726b17422bade75fba94e625cd35fd1353e682 does lead to a delay in
calling rfcomm_session_del() due to the extra refcount while waiting
for the new timeout. I believe that this delay has revealed some more
subtle problem elsewhere that causes an unbalanced refcount and then
the kernel panic.
I have debug kernel logs and hci logs - they are too large to send to
the list but I can send them directly to anyone interested in
debugging.
We see this crash frequently with a number of headsets since 2.6.32,
but not reliably. I do have a 100% repro case with the Nuvi Garmin,
with these exact steps:
1) Make sure Nuvi is unpaired, Bluez stack is unpaired, and kernel has
been rebooted since unpairing.
2) Initiate device discovery, pairing, and handsfree connection from Nuvi
3) Observe HFP rfcomm connect briefly, then disconnect, and kernel panic
Our short-term solution is unfortunately to revert
9e726b17422bade75fba94e625cd35fd1353e682.
Nick
Nick Pelly wrote:
> On Sat, Feb 20, 2010 at 12:17 AM, Dave Young <[email protected]> wrote:
>> On Thu, Feb 18, 2010 at 1:04 PM, Nick Pelly <[email protected]> wrote:
>>> Since 2.6.32 we are seeing kernel panics like:
>>>
>>> [10651.110229] Unable to handle kernel paging request at virtual
>>> address 6b6b6b6b
>>> [10651.111968] Internal error: Oops: 5 [#1] PREEMPT
>>> [10651.113952] CPU: 0 Tainted: G W (2.6.32-59979-gd0c97db #1)
>>> [10651.114624] PC is at rfcomm_run+0xa04/0xdbc
>>> <...>
>>> [10651.406188] [<c031ad24>] (rfcomm_run+0xa04/0xdbc) from [<c006ce30>]
>>> (kthread+0x78/0x80)
>>> [10651.406585] [<c006ce30>] (kthread+0x78/0x80) from [<c002793c>]
>>> (kernel_thread_exit+0x0/0x8)
>>>
>>> (rfcomm_run() is all inlined so theres not much of a stack trace))
l2cap socket status might change while rfcomm is processing frames. And
that makes rfcomm_process_rx to do double rfcomm_session_put() for
incoming session reference. We cannot use sk_state.
Could you try with this patch if it helps to your problems also? My OPP
problems went away with this patch.
I moved rfcomm_session_put() for incoming session to
rfcomm_session_close in order to get more clear _hold()/_put() pairs.
--
Ville
On Sat, Feb 20, 2010 at 12:17 AM, Dave Young <[email protected]> wrote:
> On Thu, Feb 18, 2010 at 1:04 PM, Nick Pelly <[email protected]> wrote:
>> Since 2.6.32 we are seeing kernel panics like:
>>
>> [10651.110229] Unable to handle kernel paging request at virtual
>> address 6b6b6b6b
>> [10651.111968] Internal error: Oops: 5 [#1] PREEMPT
>> [10651.113952] CPU: 0 ? ?Tainted: G ? ? ? ?W ? (2.6.32-59979-gd0c97db #1)
>> [10651.114624] PC is at rfcomm_run+0xa04/0xdbc
>> <...>
>> [10651.406188] [<c031ad24>] (rfcomm_run+0xa04/0xdbc) from [<c006ce30>]
>> (kthread+0x78/0x80)
>> [10651.406585] [<c006ce30>] (kthread+0x78/0x80) from [<c002793c>]
>> (kernel_thread_exit+0x0/0x8)
>>
>> (rfcomm_run() is all inlined so theres not much of a stack trace))
>
> Could you make rfcomm_process_sessions to be not inlined, and get new
> kernel logs?
I'm not using a stock kernel, so i'm not sure how the kernel trace
will help, but the un-inlined stack that I decoded against my vmlinux
is:
>> This is a use-after-free on struct rfcomm_session s in the call chain
>> rfcomm_run() -> rfcomm_process_sessions() -> rfcomm_process_dlcs() ->
>> list_for_each_safe(p, n, &s->dlcs)
PS - 9e726b17422b is definitely not the root cause, we've now seen the
same crash with this patch reverted (but it is much harder to
reproduce with 9e726b17422b reverted).
Nick
On Thu, Feb 18, 2010 at 1:04 PM, Nick Pelly <[email protected]> wrote:
> Since 2.6.32 we are seeing kernel panics like:
>
> [10651.110229] Unable to handle kernel paging request at virtual
> address 6b6b6b6b
> [10651.111968] Internal error: Oops: 5 [#1] PREEMPT
> [10651.113952] CPU: 0 Tainted: G W (2.6.32-59979-gd0c97db #1)
> [10651.114624] PC is at rfcomm_run+0xa04/0xdbc
> <...>
> [10651.406188] [<c031ad24>] (rfcomm_run+0xa04/0xdbc) from [<c006ce30>]
> (kthread+0x78/0x80)
> [10651.406585] [<c006ce30>] (kthread+0x78/0x80) from [<c002793c>]
> (kernel_thread_exit+0x0/0x8)
>
> (rfcomm_run() is all inlined so theres not much of a stack trace))
Could you make rfcomm_process_sessions to be not inlined, and get new
kernel logs?
>
> This is a use-after-free on struct rfcomm_session s in the call chain
> rfcomm_run() -> rfcomm_process_sessions() -> rfcomm_process_dlcs() ->
> list_for_each_safe(p, n, &s->dlcs). The only way this can happen is if
> there is an unbalanced refcount on the rfcomm session.
>
> We found that reverting the patch
> 9e726b17422bade75fba94e625cd35fd1353e682 "Bluetooth: Fix rejected
> connection not disconnecting ACL link" fixes the issue for us. The
> patch itself looks ok, I added some logging to check the new refcounts
> in the patch are balanced and they are. However if I remove the new
> calls to rfcomm_session_put() and rfcomm_session_hold() the crash is
> resolved. I also found that we can crash without hitting
> rfcomm_session_timeout(), so its not related to Marcel's recent patch
> to remove the scheduling-while-atomic warning.
>
> 9e726b17422bade75fba94e625cd35fd1353e682 does lead to a delay in
> calling rfcomm_session_del() due to the extra refcount while waiting
> for the new timeout. I believe that this delay has revealed some more
> subtle problem elsewhere that causes an unbalanced refcount and then
> the kernel panic.
>
> I have debug kernel logs and hci logs - they are too large to send to
> the list but I can send them directly to anyone interested in
> debugging.
>
> We see this crash frequently with a number of headsets since 2.6.32,
> but not reliably. I do have a 100% repro case with the Nuvi Garmin,
> with these exact steps:
> 1) Make sure Nuvi is unpaired, Bluez stack is unpaired, and kernel has
> been rebooted since unpairing.
> 2) Initiate device discovery, pairing, and handsfree connection from Nuvi
> 3) Observe HFP rfcomm connect briefly, then disconnect, and kernel panic
>
> Our short-term solution is unfortunately to revert
> 9e726b17422bade75fba94e625cd35fd1353e682.
>
> Nick
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bluetooth" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>
--
Regards
dave
Hi nick,
ext Nick Pelly wrote:
> Since 2.6.32 we are seeing kernel panics like:
>
> [10651.110229] Unable to handle kernel paging request at virtual
> address 6b6b6b6b
> [10651.111968] Internal error: Oops: 5 [#1] PREEMPT
> [10651.113952] CPU: 0 Tainted: G W (2.6.32-59979-gd0c97db #1)
> [10651.114624] PC is at rfcomm_run+0xa04/0xdbc
> <...>
> [10651.406188] [<c031ad24>] (rfcomm_run+0xa04/0xdbc) from [<c006ce30>]
> (kthread+0x78/0x80)
> [10651.406585] [<c006ce30>] (kthread+0x78/0x80) from [<c002793c>]
> (kernel_thread_exit+0x0/0x8)
>
> (rfcomm_run() is all inlined so theres not much of a stack trace))
>
> This is a use-after-free on struct rfcomm_session s in the call chain
> rfcomm_run() -> rfcomm_process_sessions() -> rfcomm_process_dlcs() ->
> list_for_each_safe(p, n, &s->dlcs). The only way this can happen is if
> there is an unbalanced refcount on the rfcomm session.
>
I have seen same traces.
> We found that reverting the patch
> 9e726b17422bade75fba94e625cd35fd1353e682 "Bluetooth: Fix rejected
> connection not disconnecting ACL link" fixes the issue for us. The
> patch itself looks ok, I added some logging to check the new refcounts
> in the patch are balanced and they are. However if I remove the new
> calls to rfcomm_session_put() and rfcomm_session_hold() the crash is
> resolved. I also found that we can crash without hitting
> rfcomm_session_timeout(), so its not related to Marcel's recent patch
> to remove the scheduling-while-atomic warning.
>
> 9e726b17422bade75fba94e625cd35fd1353e682 does lead to a delay in
> calling rfcomm_session_del() due to the extra refcount while waiting
> for the new timeout. I believe that this delay has revealed some more
> subtle problem elsewhere that causes an unbalanced refcount and then
> the kernel panic.
>
> I have debug kernel logs and hci logs - they are too large to send to
> the list but I can send them directly to anyone interested in
> debugging.
>
> We see this crash frequently with a number of headsets since 2.6.32,
> but not reliably. I do have a 100% repro case with the Nuvi Garmin,
> with these exact steps:
> 1) Make sure Nuvi is unpaired, Bluez stack is unpaired, and kernel has
> been rebooted since unpairing.
> 2) Initiate device discovery, pairing, and handsfree connection from Nuvi
> 3) Observe HFP rfcomm connect briefly, then disconnect, and kernel panic
>
Some OBEX cases also trigger this same problem. I don't have exact steps
right now. I'll try to dig some more information.
--
Ville
Hi,
On Tue, Mar 9, 2010 at 9:31 AM, Nick Pelly <[email protected]> wrote:
> On Mon, Mar 8, 2010 at 11:19 PM, Ville Tervo <[email protected]> wrote:
>> Tervo Ville (Nokia-D/Helsinki) wrote:
>>>
>>> l2cap socket status might change while rfcomm is processing frames. And
>>> that makes rfcomm_process_rx to do double rfcomm_session_put() for incoming
>>> session reference. We cannot use sk_state.
>>>
>>> Could you try with this patch if it helps to your problems also? My OPP
>>> problems went away with this patch.
>>>
>>> I moved rfcomm_session_put() for incoming session to rfcomm_session_close
>>> in order to get more clear _hold()/_put() pairs.
>>>
>>>
>>
>> Any comments about the patch in previous mail?
>
> Your patch looks sane to me, although I know enough of the Bluez
> rfcomm state machine to know that I don't know it that well :)
We have tested this patch and it looks to be working. Shall we apply it?
Regards,
Andrei
On Mon, Mar 8, 2010 at 11:19 PM, Ville Tervo <[email protected]> wrote:
> Tervo Ville (Nokia-D/Helsinki) wrote:
>>
>> l2cap socket status might change while rfcomm is processing frames. And
>> that makes rfcomm_process_rx to do double rfcomm_session_put() for incoming
>> session reference. We cannot use sk_state.
>>
>> Could you try with this patch if it helps to your problems also? My OPP
>> problems went away with this patch.
>>
>> I moved rfcomm_session_put() for incoming session to rfcomm_session_close
>> in order to get more clear _hold()/_put() pairs.
>>
>>
>
> Any comments about the patch in previous mail?
Your patch looks sane to me, although I know enough of the Bluez
rfcomm state machine to know that I don't know it that well :)
Nick
Tervo Ville (Nokia-D/Helsinki) wrote:
>
> l2cap socket status might change while rfcomm is processing frames. And
> that makes rfcomm_process_rx to do double rfcomm_session_put() for
> incoming session reference. We cannot use sk_state.
>
> Could you try with this patch if it helps to your problems also? My OPP
> problems went away with this patch.
>
> I moved rfcomm_session_put() for incoming session to
> rfcomm_session_close in order to get more clear _hold()/_put() pairs.
>
>
Any comments about the patch in previous mail?
--
Ville
Hi All ,
I have seen a similar issue when testing my device with Motorola 17 mono
headset . The use-case tried was as follows :
1)Pair connect device to Motorola H17
2)Power up Bluetooth on my device
3)Power back Bluetooth on the device .
On repeating this sequence for around 10-15 times I see the following kernel
panic . Trace shown as below .
Can you let me know your comments on this ?
<6>[ 1100.245300] Bluetooth:
<6>[ 1100.247985] Bluetooth:
<6>[ 1100.251068] Bluetooth: sock ca817360, sk cbe32e00
<6>[ 1100.263336] Bluetooth: sock ca817360, sk cbe32e00
<6>[ 1100.268524] Bluetooth: sock cbe32e00 state 4
<6>[ 1100.273468] Bluetooth: sk cbe32e00 state 4 socket ca817360
<6>[ 1100.279296] Bluetooth: parent cbe32e00
<6>[ 1100.283325] Bluetooth: sock d3832080 state 7
<6>[ 1100.287872] Bluetooth: hu db514b00 count 52 rx_state 0 rx_count 0
<6>[ 1100.294372] Bluetooth: Event packet
<6>[ 1100.298126] Bluetooth: Event header: evt 0x13 plen 5
<6>[ 1100.303375] Bluetooth: len 5 room 1078
<6>[ 1100.307403] Bluetooth: Complete data
<6>[ 1100.311218] Bluetooth: Event packet
<6>[ 1100.314941] Bluetooth: Event header: evt 0x13 plen 5
<6>[ 1100.320281] Bluetooth: hci0
<6>[ 1100.323272] Bluetooth: hdev cbe32980 len 7
<6>[ 1100.327606] Bluetooth: hci0 num_hndl 1
<6>[ 1100.331665] Bluetooth: hci0 acl 3 sco 4
<6>[ 1100.335723] Bluetooth: hci0
<6>[ 1100.338714] Bluetooth: conn (null) quote 0
<6>[ 1100.343139] Bluetooth: hci0
<6>[ 1100.346099] Bluetooth: conn (null) quote 0
<6>[ 1100.350463] Bluetooth: hci0
<6>[ 1100.353515] Bluetooth: conn (null) quote 0
<6>[ 1100.357849] Bluetooth: len 5 room 1078
<6>[ 1100.361846] Bluetooth: Complete data
<6>[ 1100.365722] Bluetooth: ACL packet
<6>[ 1100.369262] Bluetooth: ACL header: dlen 14
<6>[ 1100.373596] Bluetooth: hci0
<6>[ 1100.376586] Bluetooth: hdev cbe32980 len 7
<6>[ 1100.381011] Bluetooth: hci0 num_hndl 1
<6>[ 1100.384979] Bluetooth: hci0 acl 4 sco 4
<6>[ 1100.389038] Bluetooth: hci0
<6>[ 1100.392089] Bluetooth: conn (null) quote 0
<6>[ 1100.396453] Bluetooth: hci0
<6>[ 1100.399414] Bluetooth: conn (null) quote 0
<6>[ 1100.403839] Bluetooth: hci0
<6>[ 1100.406799] Bluetooth: conn (null) quote 0
<6>[ 1100.411163] Bluetooth: len 14 room 1076
<6>[ 1100.415283] Bluetooth: Complete data
<6>[ 1100.419097] Bluetooth: ACL packet
<6>[ 1100.422637] Bluetooth: ACL header: dlen 24
<6>[ 1100.427032] Bluetooth: hci0
<6>[ 1100.430023] Bluetooth: hdev cbe32980 len 18
<6>[ 1100.434448] Bluetooth: hci0 ACL data packet
<6>[ 1100.438934] Bluetooth: hci0 len 14 handle 0x1 flags 0x2
<6>[ 1100.444458] Bluetooth: conn d3a0f5c0 mode 0
<6>[ 1100.448913] Bluetooth: conn db5473c0 len 14 flags 0x2
<6>[ 1100.454284] Bluetooth: len 10, cid 0x0001
<6>[ 1100.458557] Bluetooth: conn db5473c0
<6>[ 1100.462341] Bluetooth: code 0x05 len 6 id 0x02
<6>[ 1100.467132] Bluetooth: scid 0x0040 flags 0x00 result 0x00
<6>[ 1100.472808] Bluetooth: sk d3832080, parent (null)
<6>[ 1100.477874] Bluetooth: sock d3832080 state 1
<6>[ 1100.482421] Bluetooth: len 24 room 1076
<6>[ 1100.487579] Bluetooth: sock ca817b08
<6>[ 1100.491485] Bluetooth: cmd 400448ca arg 0
<6>[ 1100.498565] Bluetooth: sk d3832080 state 1 socket (null)
<6>[ 1100.504699] Bluetooth: 0
<6>[ 1100.507415] Bluetooth: hci0 cbe32980
<6>[ 1100.511230] Bluetooth: hci0 err 0x13
<6>[ 1100.515014] Bluetooth: cache cbe32bc0
<6>[ 1100.518981] Bluetooth: hdev hci0
<6>[ 1100.522430] Bluetooth: hcon d3a0f5c0 reason 22
<6>[ 1100.527130] Bluetooth: hcon d3a0f5c0 conn db5473c0, err 103
<6>[ 1100.533081] Bluetooth: sock d3832080 state 1
<6>[ 1100.537597] Bluetooth: sk d3832080, conn db5473c0, err 103
<6>[ 1100.543487] Bluetooth: sk d3832080 state 9
<6>[ 1100.547821] Bluetooth: sk d3832080
<6>[ 1100.551452] Bluetooth: hcon d3a0f5c0 reason 22
<6>[ 1100.556213] Bluetooth: hci0 conn d3a0f5c0 handle 1
<6>[ 1100.561279] Bluetooth: conn d3a0f5c0
<1>[ 1100.566925] Unable to handle kernel paging request at virtual address
6b6b6b6b
<1>[ 1100.574584] pgd = c0004000
<1>[ 1100.577453] [6b6b6b6b] *pgd=00000000
<0>[ 1100.581420] Internal error: Oops: 5 [#1] PREEMPT
<0>[ 1100.586303] last sysfs file:
/sys/devices/system/cpu/cpu0/cpufreq/stats/time_in_state
<4>[ 1100.594573] Modules linked in: em_u32 sch_htb cls_u32 act_police
sch_ingress act_mirred ifb sec
<4>[ 1100.604522] CPU: 0 Tainted: G W (2.6.32.9-g09b2432-dirty
#1)
<4>[ 1100.611602] PC is at release_sock+0x60/0xf0
<4>[ 1100.616088] LR is at release_sock+0x18/0xf0
<4>[ 1101.576324] [<c0309930>] (release_sock+0x60/0xf0) from [<c03e9f40>]
(__l2cap_sock_close+0x8c/0x31c)
<4>[ 1101.585876] [<c03e9f40>] (__l2cap_sock_close+0x8c/0x31c) from
[<c03ed9b4>] (l2cap_sock_shutdown+0x5c/0xa0)
<4>[ 1101.596069] [<c03ed9b4>] (l2cap_sock_shutdown+0x5c/0xa0) from
[<c03eda2c>] (l2cap_sock_release+0x34/0x90)
<4>[ 1101.606170] [<c03eda2c>] (l2cap_sock_release+0x34/0x90) from
[<c0307ccc>] (sock_release+0x20/0xb0)
<4>[ 1101.615570] [<c0307ccc>] (sock_release+0x20/0xb0) from [<c0307d7c>]
(sock_close+0x20/0x2c)
<4>[ 1101.624267] [<c0307d7c>] (sock_close+0x20/0x2c) from [<c00c978c>]
(__fput+0x11c/0x218)
<4>[ 1101.632659] [<c00c978c>] (__fput+0x11c/0x218) from [<c00c65a8>]
(filp_close+0x6c/0x78)
<4>[ 1101.641052] [<c00c65a8>] (filp_close+0x6c/0x78) from [<c0068f38>]
(put_files_struct+0x88/0xf0)
<4>[ 1101.650085] [<c0068f38>] (put_files_struct+0x88/0xf0) from
[<c006a7bc>] (do_exit+0x1b0/0x698)
<4>[ 1101.659088] [<c006a7bc>] (do_exit+0x1b0/0x698) from [<c006ad54>]
(do_group_exit+0xb0/0xdc)
<4>[ 1101.667846] [<c006ad54>] (do_group_exit+0xb0/0xdc) from [<c006ad90>]
(sys_exit_group+0x10/0x18)
<4>[ 1101.677032] [<c006ad90>] (sys_exit_group+0x10/0x18) from [<c0034f40>]
(ret_fast_syscall+0x0/0x2c)
On Fri, Mar 19, 2010 at 2:03 PM, Andrei Emeltchenko <
[email protected]> wrote:
> Hi,
>
> On Tue, Mar 9, 2010 at 9:31 AM, Nick Pelly <[email protected]> wrote:
> > On Mon, Mar 8, 2010 at 11:19 PM, Ville Tervo <[email protected]>
> wrote:
> >> Tervo Ville (Nokia-D/Helsinki) wrote:
> >>>
> >>> l2cap socket status might change while rfcomm is processing frames. And
> >>> that makes rfcomm_process_rx to do double rfcomm_session_put() for
> incoming
> >>> session reference. We cannot use sk_state.
> >>>
> >>> Could you try with this patch if it helps to your problems also? My OPP
> >>> problems went away with this patch.
> >>>
> >>> I moved rfcomm_session_put() for incoming session to
> rfcomm_session_close
> >>> in order to get more clear _hold()/_put() pairs.
> >>>
> >>>
> >>
> >> Any comments about the patch in previous mail?
> >
> > Your patch looks sane to me, although I know enough of the Bluez
> > rfcomm state machine to know that I don't know it that well :)
>
> We have tested this patch and it looks to be working. Shall we apply it?
>
> Regards,
> Andrei
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bluetooth"
> in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>