2013-11-01 13:18:00

by Fabio Rossi

[permalink] [raw]
Subject: BUG in rfcomm_sock_getsockopt+0x128/0x200

I'm using the latest wireless-testing.git and I have found a problem, I get the
following kernel trace:

BUG: unable to handle kernel paging request at
00000009dd50350a
IP: [<ffffffff815b6768>]
rfcomm_sock_getsockopt+0x128/0x200
PGD
0
Oops: 0000 [#1] SMP
Modules linked in: vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) fglrx(PO)
ath5k ath mac80211 cfg80211
CPU: 2 PID: 1475 Comm: bluetoothd Tainted: P O 3.12.0-rc5-wl #4
Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS
1202 12/22/2010
task: ffff88032e9ce360 ti: ffff880330654000 task.ti: ffff880330654000
RIP: 0010:[<ffffffff815b6768>] [<ffffffff815b6768>]
rfcomm_sock_getsockopt+0x128/0x200
RSP: 0018:ffff880330655ed8 EFLAGS: 00010246
RAX: 00000009dd503502 RBX: 0000000000000003 RCX: 00007fff7b30e298
RDX: 0000000000000003 RSI: 0000000000000012 RDI: ffff8800bad88f00
RBP: ffff880330655f28 R08: 00007fff7b30e29c R09: ffff8803306734d8
R10: 00007fff7b30e298 R11: 0000000000000202 R12: ffff8800ba83ec00
R13: 00007fff7b30e298 R14: 0000000000000003 R15: 00007fff7b30e29c
FS: 00007f31c1d9d700(0000) GS:ffff88033fc80000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000009dd50350a CR3: 000000033048a000 CR4: 00000000000007e0
Stack:
ffff880330655f28 ffffffff815b5e2f ffff880330655f18 0002ffff81107bb6
0000000600000000 ffff8800bad88f00 0000000000000012 00007fff7b30e298
0000000000000003 00007fff7b30e29c ffff880330655f78 ffffffff814c6260
Call Trace:
[<ffffffff815b5e2f>] ? rfcomm_sock_setsockopt+0x5f/0x190
[<ffffffff814c6260>] SyS_getsockopt+0x60/0xb0
[<ffffffff815e5ba2>] system_call_fastpath+0x16/0x1b
Code: 02 00 00 00 0f 47 d0 4c 89 ef e8 94 f0 cc ff 83 f8 01 19 c9 f7 d1 83 e1
f2 e9 4b ff ff ff 0f 1f 44 00 00 49 8b 84 24 70 02 00 00 <4c> 8b 70 08 4c 89 c0
e8 4c f6 cc ff 85 c0 49 89 d7 b9 f2 ff ff
RIP [<ffffffff815b6768>] rfcomm_sock_getsockopt+0x128/0x200
RSP <ffff880330655ed8>
CR2: 00000009dd50350a
---[ end trace 6e62d73375e99d69 ]---

After bisecting the problem I found the following bad commit:

commit 94a86df01082557e2de45865e538d7fb6c46231c
Author: Marcel Holtmann <[email protected]>
Date: Sun Oct 13 10:34:02 2013 -0700

Bluetooth: Store RFCOMM address information in its own socket structure

The address information of RFCOMM sockets should be stored in its
own socket structure. Trying to generalize them is not helpful since
different transports have different address types.

Signed-off-by: Marcel Holtmann <[email protected]>
Signed-off-by: Johan Hedberg <[email protected]>

Fabio


2013-11-01 20:27:27

by Janusz Dziedzic

[permalink] [raw]
Subject: Re: BUG in rfcomm_sock_getsockopt+0x128/0x200

2013/11/1 Fabio Rossi <[email protected]>:
>>what socket option is your client program setting? Do you happen to know that.
> Would make it a lot easier to track this down.
>
> Hi Marcel,
> I'm using the bluetoothd daemon at startup and it crashes as soon as the
> dongle is inserted. To test the behaviour I removed the dongle and restart the
> daemon with
>
> # bluetoothd -n -d
>
> bluetoothd[4450]: Bluetooth daemon 4.101
> bluetoothd[4450]: src/main.c:parse_config() parsing main.conf
> bluetoothd[4450]: src/main.c:parse_config() discovto=0
> bluetoothd[4450]: src/main.c:parse_config() pairto=0
> bluetoothd[4450]: src/main.c:parse_config() pageto=8192
> bluetoothd[4450]: src/main.c:parse_config() auto_to=60
> bluetoothd[4450]: src/main.c:parse_config() name=%h-%d
> bluetoothd[4450]: src/main.c:parse_config() class=0x000100
> bluetoothd[4450]: src/main.c:parse_config() Key file does not have key
> 'DeviceID'
> bluetoothd[4450]: Starting SDP server
> bluetoothd[4450]: src/plugin.c:plugin_init() Loading builtin plugins
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading pnat plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading audio plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading input plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading serial plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading network plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading service plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading health plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading hciops plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading mgmtops plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading formfactor plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading storage plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading adaptername plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading wiimote plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading maemo6 plugin
> bluetoothd[4450]: src/plugin.c:plugin_init() Loading plugins
> /usr/lib64/bluetooth/plugins
> bluetoothd[4450]: plugins/service.c:register_interface() path
> /org/bluez/4450/any
> bluetoothd[4450]: plugins/service.c:register_interface() Registered interface
> org.bluez.Service on path /org/bluez/4450/any
> bluetoothd[4450]: plugins/maemo6.c:maemo6_init() init maemo6 plugin
> bluetoothd[4450]: health/hdp.c:hdp_manager_start() Starting Health manager
> bluetoothd[4450]: network/manager.c:read_config() /etc/bluetooth/network.conf:
> Key file does not have key 'DisableSecurity'
> bluetoothd[4450]: network/manager.c:read_config() Config options:
> Security=true
> bluetoothd[4450]: input/manager.c:input_manager_init() input.conf: Key file
> does not have key 'IdleTimeout'
> bluetoothd[4450]: audio/manager.c:audio_manager_init() audio.conf: Key file
> does not have key 'AutoConnect'
> bluetoothd[4450]: plugins/pnat.c:pnat_init() Setup Phonet AT (DUN) plugin
> bluetoothd[4450]: plugins/hciops.c:hciops_init()
> bluetoothd[4450]: Bluetooth Management interface initialized
> bluetoothd[4450]: Failed to open RFKILL control device
> bluetoothd[4450]: src/main.c:main() Entering main loop
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 12 bytes from
> management socket
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_cmd_complete()
> bluetoothd[4450]: plugins/mgmtops.c:read_version_complete() version 1 revision
> 4
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 11 bytes from
> management socket
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_cmd_complete()
>
> then I insert the dongle
>
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 6 bytes from
> management socket
> bluetoothd[4450]: plugins/mgmtops.c:add_controller() Added controller 0
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 289 bytes from
> management socket
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_cmd_complete()
> bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 addr 00:09:DD:XX:
> XX:XX version 3 manufacturer 10 class 0x000000
> bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 settings
> bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 name CSR - bc4
> bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 short name
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_remove_uuid() index 0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=1
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_read_bdaddr() index 0 addr 00:09:DD:
> XX:XX:XX
> bluetoothd[4450]: src/sdpd-database.c:sdp_init_services_list()
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_add_uuid() index 0
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_add_uuid() index 0
> bluetoothd[4450]: plugins/service.c:register_interface() path
> /org/bluez/4450/hci0
> bluetoothd[4450]: plugins/service.c:register_interface() Registered interface
> org.bluez.Service on path /org/bluez/4450/hci0
> bluetoothd[4450]: plugins/maemo6.c:mce_probe() path /org/bluez/4450/hci0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=2
> bluetoothd[4450]: network/manager.c:network_server_probe() path
> /org/bluez/4450/hci0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=3
> bluetoothd[4450]: network/server.c:server_register() Registered interface org.
> bluez.NetworkServer on path /org/bluez/4450/hci0
> bluetoothd[4450]: serial/manager.c:proxy_probe() path /org/bluez/4450/hci0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=4
> bluetoothd[4450]: serial/proxy.c:proxy_register() Registered interface org.
> bluez.SerialProxyManager on path /org/bluez/4450/hci0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=5
> bluetoothd[4450]: audio/manager.c:media_server_probe() path
> /org/bluez/4450/hci0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=6
> bluetoothd[4450]: audio/manager.c:audio_adapter_ref() 0x7f6c1794b2b0: ref=1
> bluetoothd[4450]: audio/manager.c:headset_server_probe() path
> /org/bluez/4450/hci0
> bluetoothd[4450]: audio/manager.c:audio_adapter_ref() 0x7f6c1794b2b0: ref=2
> bluetoothd[4450]: audio/manager.c:headset_server_init() audio.conf: Key file
> does not have key 'Master'
> Killed
>
> and I get the crash previously reported. If I use a working kernel the
> bluetooth daemon continues its startup and the next lines are
>
> bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Adding record with
> handle 0x10000
> bluetoothd[2322]: plugins/mgmtops.c:mgmt_add_uuid() index
> 0
> bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
> UUID 00000003-0000-1000-8000-00805f9
> bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
> UUID 00000100-0000-1000-8000-00805f9
> bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
> UUID 00001002-0000-1000-8000-00805f9
> bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
> UUID 00001108-0000-1000-8000-00805f9
> bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
> UUID 00001112-0000-1000-8000-00805f9
> bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
> UUID 00001203-0000-1000-8000-00805f9
> ... [ omitted ] ...
>
> Furthermore, comparing bluetoothd logs (working vs not working kernel) I have
> noticed the following difference:
>
> bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 addr 00:09:DD:XX:
> XX:XX version 3 manufacturer 10 class 0x000000
> bluetoothd[2322]: plugins/mgmtops.c:read_info_complete() hci0 addr 00:09:DD:XX:
> XX:XX version 3 manufacturer 10 class 0x5a0100
>
> so it seems the class is not properly initialized.
>
> The kernel is configured with
>
> CONFIG_BT=y
> CONFIG_BT_RFCOMM=y
> CONFIG_BT_RFCOMM_TTY=y
> CONFIG_BT_BNEP=y
> CONFIG_BT_HIDP=y
> CONFIG_BT_HCIBTUSB=y
> CONFIG_BT_HCIUART=y
>
> Let me know if I can help providing more info.
>

I see the same problem and same dump during laptop startup (Ubuntu 12.04 LTS).
As a workaround I had to disable BT in bios (Dell E4300) and remove
ar3k firmware (have two BT devices).

BR
Janusz

2013-11-01 21:39:57

by Marcel Holtmann

[permalink] [raw]
Subject: Re: BUG in rfcomm_sock_getsockopt+0x128/0x200

Hi Fabio,

>> what socket option is your client program setting? Do you happen to know that.
> Would make it a lot easier to track this down.
>
> Hi Marcel,
> I'm using the bluetoothd daemon at startup and it crashes as soon as the
> dongle is inserted. To test the behaviour I removed the dongle and restart the
> daemon with
>
> # bluetoothd -n -d
>
> bluetoothd[4450]: Bluetooth daemon 4.101
> bluetoothd[4450]: src/main.c:parse_config() parsing main.conf
> bluetoothd[4450]: src/main.c:parse_config() discovto=0
> bluetoothd[4450]: src/main.c:parse_config() pairto=0
> bluetoothd[4450]: src/main.c:parse_config() pageto=8192
> bluetoothd[4450]: src/main.c:parse_config() auto_to=60
> bluetoothd[4450]: src/main.c:parse_config() name=%h-%d
> bluetoothd[4450]: src/main.c:parse_config() class=0x000100
> bluetoothd[4450]: src/main.c:parse_config() Key file does not have key
> 'DeviceID'
> bluetoothd[4450]: Starting SDP server
> bluetoothd[4450]: src/plugin.c:plugin_init() Loading builtin plugins
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading pnat plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading audio plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading input plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading serial plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading network plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading service plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading health plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading hciops plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading mgmtops plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading formfactor plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading storage plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading adaptername plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading wiimote plugin
> bluetoothd[4450]: src/plugin.c:add_plugin() Loading maemo6 plugin
> bluetoothd[4450]: src/plugin.c:plugin_init() Loading plugins
> /usr/lib64/bluetooth/plugins
> bluetoothd[4450]: plugins/service.c:register_interface() path
> /org/bluez/4450/any
> bluetoothd[4450]: plugins/service.c:register_interface() Registered interface
> org.bluez.Service on path /org/bluez/4450/any
> bluetoothd[4450]: plugins/maemo6.c:maemo6_init() init maemo6 plugin
> bluetoothd[4450]: health/hdp.c:hdp_manager_start() Starting Health manager
> bluetoothd[4450]: network/manager.c:read_config() /etc/bluetooth/network.conf:
> Key file does not have key 'DisableSecurity'
> bluetoothd[4450]: network/manager.c:read_config() Config options:
> Security=true
> bluetoothd[4450]: input/manager.c:input_manager_init() input.conf: Key file
> does not have key 'IdleTimeout'
> bluetoothd[4450]: audio/manager.c:audio_manager_init() audio.conf: Key file
> does not have key 'AutoConnect'
> bluetoothd[4450]: plugins/pnat.c:pnat_init() Setup Phonet AT (DUN) plugin
> bluetoothd[4450]: plugins/hciops.c:hciops_init()
> bluetoothd[4450]: Bluetooth Management interface initialized
> bluetoothd[4450]: Failed to open RFKILL control device
> bluetoothd[4450]: src/main.c:main() Entering main loop
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 12 bytes from
> management socket
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_cmd_complete()
> bluetoothd[4450]: plugins/mgmtops.c:read_version_complete() version 1 revision
> 4
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 11 bytes from
> management socket
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_cmd_complete()
>
> then I insert the dongle
>
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 6 bytes from
> management socket
> bluetoothd[4450]: plugins/mgmtops.c:add_controller() Added controller 0
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 289 bytes from
> management socket
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_cmd_complete()
> bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 addr 00:09:DD:XX:
> XX:XX version 3 manufacturer 10 class 0x000000
> bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 settings
> bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 name CSR - bc4
> bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 short name
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_remove_uuid() index 0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=1
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_read_bdaddr() index 0 addr 00:09:DD:
> XX:XX:XX
> bluetoothd[4450]: src/sdpd-database.c:sdp_init_services_list()
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_add_uuid() index 0
> bluetoothd[4450]: plugins/mgmtops.c:mgmt_add_uuid() index 0
> bluetoothd[4450]: plugins/service.c:register_interface() path
> /org/bluez/4450/hci0
> bluetoothd[4450]: plugins/service.c:register_interface() Registered interface
> org.bluez.Service on path /org/bluez/4450/hci0
> bluetoothd[4450]: plugins/maemo6.c:mce_probe() path /org/bluez/4450/hci0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=2
> bluetoothd[4450]: network/manager.c:network_server_probe() path
> /org/bluez/4450/hci0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=3
> bluetoothd[4450]: network/server.c:server_register() Registered interface org.
> bluez.NetworkServer on path /org/bluez/4450/hci0
> bluetoothd[4450]: serial/manager.c:proxy_probe() path /org/bluez/4450/hci0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=4
> bluetoothd[4450]: serial/proxy.c:proxy_register() Registered interface org.
> bluez.SerialProxyManager on path /org/bluez/4450/hci0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=5
> bluetoothd[4450]: audio/manager.c:media_server_probe() path
> /org/bluez/4450/hci0
> bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=6
> bluetoothd[4450]: audio/manager.c:audio_adapter_ref() 0x7f6c1794b2b0: ref=1
> bluetoothd[4450]: audio/manager.c:headset_server_probe() path
> /org/bluez/4450/hci0
> bluetoothd[4450]: audio/manager.c:audio_adapter_ref() 0x7f6c1794b2b0: ref=2
> bluetoothd[4450]: audio/manager.c:headset_server_init() audio.conf: Key file
> does not have key 'Master'
> Killed
>
> and I get the crash previously reported. If I use a working kernel the
> bluetooth daemon continues its startup and the next lines are

can you quickly test a kernel build from bluetooth-next tree. I would like to see if that crashes as well. Since I have been running that one for weeks and never saw this bug.

Regards

Marcel


2013-11-02 08:01:37

by Janusz Dziedzic

[permalink] [raw]
Subject: Re: BUG in rfcomm_sock_getsockopt+0x128/0x200

2013/11/2 Marcel Holtmann <[email protected]>:
> Hi Fabio,
>
>>> can you quickly test a kernel build from bluetooth-next tree. I would like to
>> see if that crashes as well. Since I have been running that one for weeks and
>> never saw this bug.
>>
>> here is the same problem with bluetooth-next.git
>>
>> BUG: unable to handle kernel paging request at 00000009dd503502
>> IP: [<ffffffff815b1868>] rfcomm_sock_getsockopt+0x128/0x200
>> PGD 0
>> Oops: 0000 [#1] SMP
>> Modules linked in: ath5k ath mac80211 cfg80211
>> CPU: 2 PID: 1459 Comm: bluetoothd Not tainted 3.11.0-133163-gcebd830 #2
>> Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS
>> 1202 12/22/2010
>> task: ffff8803304106a0 ti: ffff88033046a000 task.ti: ffff88033046a000
>> RIP: 0010:[<ffffffff815b1868>] [<ffffffff815b1868>]
>> rfcomm_sock_getsockopt+0x128/0x200
>> RSP: 0018:ffff88033046bed8 EFLAGS: 00010246
>> RAX: 00000009dd503502 RBX: 0000000000000003 RCX: 00007fffa2ed5548
>> RDX: 0000000000000003 RSI: 0000000000000012 RDI: ffff88032fd37480
>> RBP: ffff88033046bf28 R08: 00007fffa2ed554c R09: ffff88032f5707d8
>> R10: 00007fffa2ed5548 R11: 0000000000000202 R12: ffff880330bbd000
>> R13: 00007fffa2ed5548 R14: 0000000000000003 R15: 00007fffa2ed554c
>> FS: 00007fc44cfac700(0000) GS:ffff88033fc80000(0000) knlGS:0000000000000000
>> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> CR2: 00000009dd503502 CR3: 00000003304c2000 CR4: 00000000000007e0
>> Stack:
>> ffff88033046bf28 ffffffff815b0f2f ffff88033046bf18 0002ffff81105ef6
>> 0000000600000000 ffff88032fd37480 0000000000000012 00007fffa2ed5548
>> 0000000000000003 00007fffa2ed554c ffff88033046bf78 ffffffff814c0380
>> Call Trace:
>> [<ffffffff815b0f2f>] ? rfcomm_sock_setsockopt+0x5f/0x190
>> [<ffffffff814c0380>] SyS_getsockopt+0x60/0xb0
>> [<ffffffff815e0852>] system_call_fastpath+0x16/0x1b
>> Code: 02 00 00 00 0f 47 d0 4c 89 ef e8 74 13 cd ff 83 f8 01 19 c9 f7 d1 83 e1
>> f2 e9 4b ff ff ff 0f 1f 44 00 00 49 8b 84 24 70 02 00 00 <4c> 8b 30 4c 89 c0 e8
>> 2d 19 cd ff 85 c0 49 89 d7 b9 f2 ff ff ff
>> RIP [<ffffffff815b1868>] rfcomm_sock_getsockopt+0x128/0x200
>> RSP <ffff88033046bed8>
>> CR2: 00000009dd503502
>> ---[ end trace 719ace9ee57b7a58 ]---
>
> I finally managed to reproduce it. It does not always happen. And strangely enough I can only trigger it when enabling experimental features of bluetoothd with -E command line switch.
>
> But I have no idea why your bisecting points to that specific commit. And more important it used to work just fine (see below). However I can tell you what makes the code crash.
>
> 0x1313 is in rfcomm_sock_getsockopt (net/bluetooth/rfcomm/sock.c:743).
> 738
> 739 static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname, char __user *optval, int __user *optlen)
> 740 {
> 741 struct sock *sk = sock->sk;
> 742 struct rfcomm_conninfo cinfo;
> 743 struct l2cap_conn *conn = l2cap_pi(sk)->chan->conn;
> 744 int len, err = 0;
> 745 u32 opt;
> 746
> 747 BT_DBG("sk %p", sk);
>
> The l2cap_pi(sk) is fully broken. That is an rfcomm_pi(sk). The commit that broke this is actually from an earlier time. I have this one:
>
> commit 8c1d787be4b62d2d1b6f04953eca4bcf7c839d44
> Author: Gustavo F. Padovan <[email protected]>
> Date: Wed Apr 13 20:23:55 2011 -0300
>
> Bluetooth: Move conn to struct l2cap_chan
>
> diff --git a/net/bluetooth/rfcomm/sock.c b/net/bluetooth/rfcomm/sock.c
> index 66cc1f0c3df8..386cfaffd4b7 100644
> --- a/net/bluetooth/rfcomm/sock.c
> +++ b/net/bluetooth/rfcomm/sock.c
> @@ -743,6 +743,7 @@ static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname, char __u
> struct sock *sk = sock->sk;
> struct sock *l2cap_sk;
> struct rfcomm_conninfo cinfo;
> + struct l2cap_conn *conn = l2cap_pi(sk)->chan->conn;
> int len, err = 0;
> u32 opt;
>
> @@ -787,8 +788,8 @@ static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname, char __u
>
> l2cap_sk = rfcomm_pi(sk)->dlc->session->sock->sk;
>
> - cinfo.hci_handle = l2cap_pi(l2cap_sk)->conn->hcon->handle;
> - memcpy(cinfo.dev_class, l2cap_pi(l2cap_sk)->conn->hcon->dev_class, 3);
> + cinfo.hci_handle = conn->hcon->handle;
> + memcpy(cinfo.dev_class, conn->hcon->dev_class, 3);
>
> The conversion is clearly wrong since we used to have a l2cap_sk that was pointing to the right socket.
>
> This should have blown up month ago and not just with the latest changes we have done to the L2CAP layer. Anyhow, you can try this small change and see if it fixes things for you.
>
> diff --git a/net/bluetooth/rfcomm/sock.c b/net/bluetooth/rfcomm/sock.c
> index c4d3d423f89b..0be7619c5e5e 100644
> --- a/net/bluetooth/rfcomm/sock.c
> +++ b/net/bluetooth/rfcomm/sock.c
> @@ -739,8 +739,9 @@ static int rfcomm_sock_setsockopt(struct socket *sock, int level, int optname, c
> static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname, char __user *optval, int __user *optlen)
> {
> struct sock *sk = sock->sk;
> + struct sock *l2cap_sk;
> + struct l2cap_conn *conn;
> struct rfcomm_conninfo cinfo;
> - struct l2cap_conn *conn = l2cap_pi(sk)->chan->conn;
> int len, err = 0;
> u32 opt;
>
> @@ -783,6 +784,9 @@ static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname, char __u
> break;
> }
>
> + l2cap_sk = rfcomm_pi(sk)->dlc->session->sock->sk;
> + conn = l2cap_pi(l2cap_sk)->chan->conn;
> +
> memset(&cinfo, 0, sizeof(cinfo));
> cinfo.hci_handle = conn->hcon->handle;
> memcpy(cinfo.dev_class, conn->hcon->dev_class, 3);
>
Hello,

With this patch I don't see startup dump anymore. Thanks.

BR
Janusz

2013-11-01 13:30:37

by Marcel Holtmann

[permalink] [raw]
Subject: Re: BUG in rfcomm_sock_getsockopt+0x128/0x200

Hi Fabio,

> I'm using the latest wireless-testing.git and I have found a problem, I get the
> following kernel trace:
>
> BUG: unable to handle kernel paging request at
> 00000009dd50350a
> IP: [<ffffffff815b6768>]
> rfcomm_sock_getsockopt+0x128/0x200
> PGD
> 0
> Oops: 0000 [#1] SMP
> Modules linked in: vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) fglrx(PO)
> ath5k ath mac80211 cfg80211
> CPU: 2 PID: 1475 Comm: bluetoothd Tainted: P O 3.12.0-rc5-wl #4
> Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS
> 1202 12/22/2010
> task: ffff88032e9ce360 ti: ffff880330654000 task.ti: ffff880330654000
> RIP: 0010:[<ffffffff815b6768>] [<ffffffff815b6768>]
> rfcomm_sock_getsockopt+0x128/0x200
> RSP: 0018:ffff880330655ed8 EFLAGS: 00010246
> RAX: 00000009dd503502 RBX: 0000000000000003 RCX: 00007fff7b30e298
> RDX: 0000000000000003 RSI: 0000000000000012 RDI: ffff8800bad88f00
> RBP: ffff880330655f28 R08: 00007fff7b30e29c R09: ffff8803306734d8
> R10: 00007fff7b30e298 R11: 0000000000000202 R12: ffff8800ba83ec00
> R13: 00007fff7b30e298 R14: 0000000000000003 R15: 00007fff7b30e29c
> FS: 00007f31c1d9d700(0000) GS:ffff88033fc80000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00000009dd50350a CR3: 000000033048a000 CR4: 00000000000007e0
> Stack:
> ffff880330655f28 ffffffff815b5e2f ffff880330655f18 0002ffff81107bb6
> 0000000600000000 ffff8800bad88f00 0000000000000012 00007fff7b30e298
> 0000000000000003 00007fff7b30e29c ffff880330655f78 ffffffff814c6260
> Call Trace:
> [<ffffffff815b5e2f>] ? rfcomm_sock_setsockopt+0x5f/0x190
> [<ffffffff814c6260>] SyS_getsockopt+0x60/0xb0
> [<ffffffff815e5ba2>] system_call_fastpath+0x16/0x1b
> Code: 02 00 00 00 0f 47 d0 4c 89 ef e8 94 f0 cc ff 83 f8 01 19 c9 f7 d1 83 e1
> f2 e9 4b ff ff ff 0f 1f 44 00 00 49 8b 84 24 70 02 00 00 <4c> 8b 70 08 4c 89 c0
> e8 4c f6 cc ff 85 c0 49 89 d7 b9 f2 ff ff
> RIP [<ffffffff815b6768>] rfcomm_sock_getsockopt+0x128/0x200
> RSP <ffff880330655ed8>
> CR2: 00000009dd50350a
> ---[ end trace 6e62d73375e99d69 ]?

what socket option is your client program setting? Do you happen to know that. Would make it a lot easier to track this down.

Regards

Marcel


2013-11-02 01:59:15

by Marcel Holtmann

[permalink] [raw]
Subject: Re: BUG in rfcomm_sock_getsockopt+0x128/0x200

Hi Fabio,

>> can you quickly test a kernel build from bluetooth-next tree. I would like to
> see if that crashes as well. Since I have been running that one for weeks and
> never saw this bug.
>
> here is the same problem with bluetooth-next.git
>
> BUG: unable to handle kernel paging request at 00000009dd503502
> IP: [<ffffffff815b1868>] rfcomm_sock_getsockopt+0x128/0x200
> PGD 0
> Oops: 0000 [#1] SMP
> Modules linked in: ath5k ath mac80211 cfg80211
> CPU: 2 PID: 1459 Comm: bluetoothd Not tainted 3.11.0-133163-gcebd830 #2
> Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS
> 1202 12/22/2010
> task: ffff8803304106a0 ti: ffff88033046a000 task.ti: ffff88033046a000
> RIP: 0010:[<ffffffff815b1868>] [<ffffffff815b1868>]
> rfcomm_sock_getsockopt+0x128/0x200
> RSP: 0018:ffff88033046bed8 EFLAGS: 00010246
> RAX: 00000009dd503502 RBX: 0000000000000003 RCX: 00007fffa2ed5548
> RDX: 0000000000000003 RSI: 0000000000000012 RDI: ffff88032fd37480
> RBP: ffff88033046bf28 R08: 00007fffa2ed554c R09: ffff88032f5707d8
> R10: 00007fffa2ed5548 R11: 0000000000000202 R12: ffff880330bbd000
> R13: 00007fffa2ed5548 R14: 0000000000000003 R15: 00007fffa2ed554c
> FS: 00007fc44cfac700(0000) GS:ffff88033fc80000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00000009dd503502 CR3: 00000003304c2000 CR4: 00000000000007e0
> Stack:
> ffff88033046bf28 ffffffff815b0f2f ffff88033046bf18 0002ffff81105ef6
> 0000000600000000 ffff88032fd37480 0000000000000012 00007fffa2ed5548
> 0000000000000003 00007fffa2ed554c ffff88033046bf78 ffffffff814c0380
> Call Trace:
> [<ffffffff815b0f2f>] ? rfcomm_sock_setsockopt+0x5f/0x190
> [<ffffffff814c0380>] SyS_getsockopt+0x60/0xb0
> [<ffffffff815e0852>] system_call_fastpath+0x16/0x1b
> Code: 02 00 00 00 0f 47 d0 4c 89 ef e8 74 13 cd ff 83 f8 01 19 c9 f7 d1 83 e1
> f2 e9 4b ff ff ff 0f 1f 44 00 00 49 8b 84 24 70 02 00 00 <4c> 8b 30 4c 89 c0 e8
> 2d 19 cd ff 85 c0 49 89 d7 b9 f2 ff ff ff
> RIP [<ffffffff815b1868>] rfcomm_sock_getsockopt+0x128/0x200
> RSP <ffff88033046bed8>
> CR2: 00000009dd503502
> ---[ end trace 719ace9ee57b7a58 ]---

I finally managed to reproduce it. It does not always happen. And strangely enough I can only trigger it when enabling experimental features of bluetoothd with -E command line switch.

But I have no idea why your bisecting points to that specific commit. And more important it used to work just fine (see below). However I can tell you what makes the code crash.

0x1313 is in rfcomm_sock_getsockopt (net/bluetooth/rfcomm/sock.c:743).
738
739 static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname, char __user *optval, int __user *optlen)
740 {
741 struct sock *sk = sock->sk;
742 struct rfcomm_conninfo cinfo;
743 struct l2cap_conn *conn = l2cap_pi(sk)->chan->conn;
744 int len, err = 0;
745 u32 opt;
746
747 BT_DBG("sk %p", sk);

The l2cap_pi(sk) is fully broken. That is an rfcomm_pi(sk). The commit that broke this is actually from an earlier time. I have this one:

commit 8c1d787be4b62d2d1b6f04953eca4bcf7c839d44
Author: Gustavo F. Padovan <[email protected]>
Date: Wed Apr 13 20:23:55 2011 -0300

Bluetooth: Move conn to struct l2cap_chan

diff --git a/net/bluetooth/rfcomm/sock.c b/net/bluetooth/rfcomm/sock.c
index 66cc1f0c3df8..386cfaffd4b7 100644
--- a/net/bluetooth/rfcomm/sock.c
+++ b/net/bluetooth/rfcomm/sock.c
@@ -743,6 +743,7 @@ static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname, char __u
struct sock *sk = sock->sk;
struct sock *l2cap_sk;
struct rfcomm_conninfo cinfo;
+ struct l2cap_conn *conn = l2cap_pi(sk)->chan->conn;
int len, err = 0;
u32 opt;

@@ -787,8 +788,8 @@ static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname, char __u

l2cap_sk = rfcomm_pi(sk)->dlc->session->sock->sk;

- cinfo.hci_handle = l2cap_pi(l2cap_sk)->conn->hcon->handle;
- memcpy(cinfo.dev_class, l2cap_pi(l2cap_sk)->conn->hcon->dev_class, 3);
+ cinfo.hci_handle = conn->hcon->handle;
+ memcpy(cinfo.dev_class, conn->hcon->dev_class, 3);

The conversion is clearly wrong since we used to have a l2cap_sk that was pointing to the right socket.

This should have blown up month ago and not just with the latest changes we have done to the L2CAP layer. Anyhow, you can try this small change and see if it fixes things for you.

diff --git a/net/bluetooth/rfcomm/sock.c b/net/bluetooth/rfcomm/sock.c
index c4d3d423f89b..0be7619c5e5e 100644
--- a/net/bluetooth/rfcomm/sock.c
+++ b/net/bluetooth/rfcomm/sock.c
@@ -739,8 +739,9 @@ static int rfcomm_sock_setsockopt(struct socket *sock, int level, int optname, c
static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname, char __user *optval, int __user *optlen)
{
struct sock *sk = sock->sk;
+ struct sock *l2cap_sk;
+ struct l2cap_conn *conn;
struct rfcomm_conninfo cinfo;
- struct l2cap_conn *conn = l2cap_pi(sk)->chan->conn;
int len, err = 0;
u32 opt;

@@ -783,6 +784,9 @@ static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname, char __u
break;
}

+ l2cap_sk = rfcomm_pi(sk)->dlc->session->sock->sk;
+ conn = l2cap_pi(l2cap_sk)->chan->conn;
+
memset(&cinfo, 0, sizeof(cinfo));
cinfo.hci_handle = conn->hcon->handle;
memcpy(cinfo.dev_class, conn->hcon->dev_class, 3);

Regards

Marcel


2013-11-01 15:22:07

by Fabio Rossi

[permalink] [raw]
Subject: Re: BUG in rfcomm_sock_getsockopt+0x128/0x200

>what socket option is your client program setting? Do you happen to know that.
Would make it a lot easier to track this down.

Hi Marcel,
I'm using the bluetoothd daemon at startup and it crashes as soon as the
dongle is inserted. To test the behaviour I removed the dongle and restart the
daemon with

# bluetoothd -n -d

bluetoothd[4450]: Bluetooth daemon 4.101
bluetoothd[4450]: src/main.c:parse_config() parsing main.conf
bluetoothd[4450]: src/main.c:parse_config() discovto=0
bluetoothd[4450]: src/main.c:parse_config() pairto=0
bluetoothd[4450]: src/main.c:parse_config() pageto=8192
bluetoothd[4450]: src/main.c:parse_config() auto_to=60
bluetoothd[4450]: src/main.c:parse_config() name=%h-%d
bluetoothd[4450]: src/main.c:parse_config() class=0x000100
bluetoothd[4450]: src/main.c:parse_config() Key file does not have key
'DeviceID'
bluetoothd[4450]: Starting SDP server
bluetoothd[4450]: src/plugin.c:plugin_init() Loading builtin plugins
bluetoothd[4450]: src/plugin.c:add_plugin() Loading pnat plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading audio plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading input plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading serial plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading network plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading service plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading health plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading hciops plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading mgmtops plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading formfactor plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading storage plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading adaptername plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading wiimote plugin
bluetoothd[4450]: src/plugin.c:add_plugin() Loading maemo6 plugin
bluetoothd[4450]: src/plugin.c:plugin_init() Loading plugins
/usr/lib64/bluetooth/plugins
bluetoothd[4450]: plugins/service.c:register_interface() path
/org/bluez/4450/any
bluetoothd[4450]: plugins/service.c:register_interface() Registered interface
org.bluez.Service on path /org/bluez/4450/any
bluetoothd[4450]: plugins/maemo6.c:maemo6_init() init maemo6 plugin
bluetoothd[4450]: health/hdp.c:hdp_manager_start() Starting Health manager
bluetoothd[4450]: network/manager.c:read_config() /etc/bluetooth/network.conf:
Key file does not have key 'DisableSecurity'
bluetoothd[4450]: network/manager.c:read_config() Config options:
Security=true
bluetoothd[4450]: input/manager.c:input_manager_init() input.conf: Key file
does not have key 'IdleTimeout'
bluetoothd[4450]: audio/manager.c:audio_manager_init() audio.conf: Key file
does not have key 'AutoConnect'
bluetoothd[4450]: plugins/pnat.c:pnat_init() Setup Phonet AT (DUN) plugin
bluetoothd[4450]: plugins/hciops.c:hciops_init()
bluetoothd[4450]: Bluetooth Management interface initialized
bluetoothd[4450]: Failed to open RFKILL control device
bluetoothd[4450]: src/main.c:main() Entering main loop
bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 12 bytes from
management socket
bluetoothd[4450]: plugins/mgmtops.c:mgmt_cmd_complete()
bluetoothd[4450]: plugins/mgmtops.c:read_version_complete() version 1 revision
4
bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 11 bytes from
management socket
bluetoothd[4450]: plugins/mgmtops.c:mgmt_cmd_complete()

then I insert the dongle

bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 6 bytes from
management socket
bluetoothd[4450]: plugins/mgmtops.c:add_controller() Added controller 0
bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() cond 1
bluetoothd[4450]: plugins/mgmtops.c:mgmt_event() Received 289 bytes from
management socket
bluetoothd[4450]: plugins/mgmtops.c:mgmt_cmd_complete()
bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 addr 00:09:DD:XX:
XX:XX version 3 manufacturer 10 class 0x000000
bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 settings
bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 name CSR - bc4
bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 short name
bluetoothd[4450]: plugins/mgmtops.c:mgmt_remove_uuid() index 0
bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=1
bluetoothd[4450]: plugins/mgmtops.c:mgmt_read_bdaddr() index 0 addr 00:09:DD:
XX:XX:XX
bluetoothd[4450]: src/sdpd-database.c:sdp_init_services_list()
bluetoothd[4450]: plugins/mgmtops.c:mgmt_add_uuid() index 0
bluetoothd[4450]: plugins/mgmtops.c:mgmt_add_uuid() index 0
bluetoothd[4450]: plugins/service.c:register_interface() path
/org/bluez/4450/hci0
bluetoothd[4450]: plugins/service.c:register_interface() Registered interface
org.bluez.Service on path /org/bluez/4450/hci0
bluetoothd[4450]: plugins/maemo6.c:mce_probe() path /org/bluez/4450/hci0
bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=2
bluetoothd[4450]: network/manager.c:network_server_probe() path
/org/bluez/4450/hci0
bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=3
bluetoothd[4450]: network/server.c:server_register() Registered interface org.
bluez.NetworkServer on path /org/bluez/4450/hci0
bluetoothd[4450]: serial/manager.c:proxy_probe() path /org/bluez/4450/hci0
bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=4
bluetoothd[4450]: serial/proxy.c:proxy_register() Registered interface org.
bluez.SerialProxyManager on path /org/bluez/4450/hci0
bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=5
bluetoothd[4450]: audio/manager.c:media_server_probe() path
/org/bluez/4450/hci0
bluetoothd[4450]: src/adapter.c:btd_adapter_ref() 0x7f6c1794a800: ref=6
bluetoothd[4450]: audio/manager.c:audio_adapter_ref() 0x7f6c1794b2b0: ref=1
bluetoothd[4450]: audio/manager.c:headset_server_probe() path
/org/bluez/4450/hci0
bluetoothd[4450]: audio/manager.c:audio_adapter_ref() 0x7f6c1794b2b0: ref=2
bluetoothd[4450]: audio/manager.c:headset_server_init() audio.conf: Key file
does not have key 'Master'
Killed

and I get the crash previously reported. If I use a working kernel the
bluetooth daemon continues its startup and the next lines are

bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Adding record with
handle 0x10000
bluetoothd[2322]: plugins/mgmtops.c:mgmt_add_uuid() index
0
bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
UUID 00000003-0000-1000-8000-00805f9
bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
UUID 00000100-0000-1000-8000-00805f9
bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
UUID 00001002-0000-1000-8000-00805f9
bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
UUID 00001108-0000-1000-8000-00805f9
bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
UUID 00001112-0000-1000-8000-00805f9
bluetoothd[2322]: src/sdpd-service.c:add_record_to_server() Record pattern
UUID 00001203-0000-1000-8000-00805f9
... [ omitted ] ...

Furthermore, comparing bluetoothd logs (working vs not working kernel) I have
noticed the following difference:

bluetoothd[4450]: plugins/mgmtops.c:read_info_complete() hci0 addr 00:09:DD:XX:
XX:XX version 3 manufacturer 10 class 0x000000
bluetoothd[2322]: plugins/mgmtops.c:read_info_complete() hci0 addr 00:09:DD:XX:
XX:XX version 3 manufacturer 10 class 0x5a0100

so it seems the class is not properly initialized.

The kernel is configured with

CONFIG_BT=y
CONFIG_BT_RFCOMM=y
CONFIG_BT_RFCOMM_TTY=y
CONFIG_BT_BNEP=y
CONFIG_BT_HIDP=y
CONFIG_BT_HCIBTUSB=y
CONFIG_BT_HCIUART=y

Let me know if I can help providing more info.

Best regards,
Fabio

2013-11-02 12:06:22

by Fabio Rossi

[permalink] [raw]
Subject: Re: BUG in rfcomm_sock_getsockopt+0x128/0x200

Hi Marcel,

>I finally managed to reproduce it. It does not always happen. And strangely
enough I can only trigger it when enabling experimental features of bluetoothd
with -E command line switch.
>
>But I have no idea why your bisecting points to that specific commit. And
more important it used to work just fine (see below). However I can tell you
what makes the code crash.
>
>0x1313 is in rfcomm_sock_getsockopt (net/bluetooth/rfcomm/sock.c:743).
>738
>739 static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname,
char __user *optval, int __user *optlen)
>740 {
>741 struct sock *sk = sock->sk;
>742 struct rfcomm_conninfo cinfo;
>743 struct l2cap_conn *conn = l2cap_pi(sk)->chan->conn;
>744 int len, err = 0;
>745 u32 opt;
>746
>747 BT_DBG("sk %p", sk);
>
>The l2cap_pi(sk) is fully broken. That is an rfcomm_pi(sk). The commit that
broke this is actually from an earlier time. I have this one:
>
>commit 8c1d787be4b62d2d1b6f04953eca4bcf7c839d44
>Author: Gustavo F. Padovan <[email protected]>
>Date: Wed Apr 13 20:23:55 2011 -0300
>
> Bluetooth: Move conn to struct l2cap_chan
>
>diff --git a/net/bluetooth/rfcomm/sock.c b/net/bluetooth/rfcomm/sock.c
>index 66cc1f0c3df8..386cfaffd4b7 100644
>--- a/net/bluetooth/rfcomm/sock.c
>+++ b/net/bluetooth/rfcomm/sock.c
>@@ -743,6 +743,7 @@ static int rfcomm_sock_getsockopt_old(struct socket
*sock, int optname, char __u
> struct sock *sk = sock->sk;
> struct sock *l2cap_sk;
> struct rfcomm_conninfo cinfo;
>+ struct l2cap_conn *conn = l2cap_pi(sk)->chan->conn;
> int len, err = 0;
> u32 opt;
>
>@@ -787,8 +788,8 @@ static int rfcomm_sock_getsockopt_old(struct socket
*sock, int optname, char __u
>
> l2cap_sk = rfcomm_pi(sk)->dlc->session->sock->sk;
>
>- cinfo.hci_handle = l2cap_pi(l2cap_sk)->conn->hcon->handle;
>- memcpy(cinfo.dev_class, l2cap_pi(l2cap_sk)->conn->hcon-
>dev_class, 3);
>+ cinfo.hci_handle = conn->hcon->handle;
>+ memcpy(cinfo.dev_class, conn->hcon->dev_class, 3);
>
>The conversion is clearly wrong since we used to have a l2cap_sk that was
pointing to the right socket.
>
>This should have blown up month ago and not just with the latest changes we
have done to the L2CAP layer. Anyhow, you can try this small change and see if
it fixes things for you.
>
>diff --git a/net/bluetooth/rfcomm/sock.c b/net/bluetooth/rfcomm/sock.c
>index c4d3d423f89b..0be7619c5e5e 100644
>--- a/net/bluetooth/rfcomm/sock.c
>+++ b/net/bluetooth/rfcomm/sock.c
>@@ -739,8 +739,9 @@ static int rfcomm_sock_setsockopt(struct socket *sock,
int level, int optname, c
> static int rfcomm_sock_getsockopt_old(struct socket *sock, int optname, char
__user *optval, int __user *optlen)
> {
> struct sock *sk = sock->sk;
>+ struct sock *l2cap_sk;
>+ struct l2cap_conn *conn;
> struct rfcomm_conninfo cinfo;
>- struct l2cap_conn *conn = l2cap_pi(sk)->chan->conn;
> int len, err = 0;
> u32 opt;
>
>@@ -783,6 +784,9 @@ static int rfcomm_sock_getsockopt_old(struct socket
*sock, int optname, char __u
> break;
> }
>
>+ l2cap_sk = rfcomm_pi(sk)->dlc->session->sock->sk;
>+ conn = l2cap_pi(l2cap_sk)->chan->conn;
>+
> memset(&cinfo, 0, sizeof(cinfo));
> cinfo.hci_handle = conn->hcon->handle;
> memcpy(cinfo.dev_class, conn->hcon->dev_class, 3);
>
>Regards

This patch solves the issue, I don't see the crash anymore.

Thanks,
Fabio


2013-11-02 01:12:42

by Fabio Rossi

[permalink] [raw]
Subject: Re: BUG in rfcomm_sock_getsockopt+0x128/0x200

>can you quickly test a kernel build from bluetooth-next tree. I would like to
see if that crashes as well. Since I have been running that one for weeks and
never saw this bug.
>
>Regards
>
>Marcel

Hi Marcel,
here is the same problem with bluetooth-next.git

BUG: unable to handle kernel paging request at 00000009dd503502
IP: [<ffffffff815b1868>] rfcomm_sock_getsockopt+0x128/0x200
PGD 0
Oops: 0000 [#1] SMP
Modules linked in: ath5k ath mac80211 cfg80211
CPU: 2 PID: 1459 Comm: bluetoothd Not tainted 3.11.0-133163-gcebd830 #2
Hardware name: System manufacturer System Product Name/P6T DELUXE V2, BIOS
1202 12/22/2010
task: ffff8803304106a0 ti: ffff88033046a000 task.ti: ffff88033046a000
RIP: 0010:[<ffffffff815b1868>] [<ffffffff815b1868>]
rfcomm_sock_getsockopt+0x128/0x200
RSP: 0018:ffff88033046bed8 EFLAGS: 00010246
RAX: 00000009dd503502 RBX: 0000000000000003 RCX: 00007fffa2ed5548
RDX: 0000000000000003 RSI: 0000000000000012 RDI: ffff88032fd37480
RBP: ffff88033046bf28 R08: 00007fffa2ed554c R09: ffff88032f5707d8
R10: 00007fffa2ed5548 R11: 0000000000000202 R12: ffff880330bbd000
R13: 00007fffa2ed5548 R14: 0000000000000003 R15: 00007fffa2ed554c
FS: 00007fc44cfac700(0000) GS:ffff88033fc80000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000009dd503502 CR3: 00000003304c2000 CR4: 00000000000007e0
Stack:
ffff88033046bf28 ffffffff815b0f2f ffff88033046bf18 0002ffff81105ef6
0000000600000000 ffff88032fd37480 0000000000000012 00007fffa2ed5548
0000000000000003 00007fffa2ed554c ffff88033046bf78 ffffffff814c0380
Call Trace:
[<ffffffff815b0f2f>] ? rfcomm_sock_setsockopt+0x5f/0x190
[<ffffffff814c0380>] SyS_getsockopt+0x60/0xb0
[<ffffffff815e0852>] system_call_fastpath+0x16/0x1b
Code: 02 00 00 00 0f 47 d0 4c 89 ef e8 74 13 cd ff 83 f8 01 19 c9 f7 d1 83 e1
f2 e9 4b ff ff ff 0f 1f 44 00 00 49 8b 84 24 70 02 00 00 <4c> 8b 30 4c 89 c0 e8
2d 19 cd ff 85 c0 49 89 d7 b9 f2 ff ff ff
RIP [<ffffffff815b1868>] rfcomm_sock_getsockopt+0x128/0x200
RSP <ffff88033046bed8>
CR2: 00000009dd503502
---[ end trace 719ace9ee57b7a58 ]---

Regards,
Fabio