* Bluetooth regression with headphones
@ 2011-09-13 1:33 Jeremy Fitzhardinge
2011-09-16 22:33 ` Jeremy Fitzhardinge
0 siblings, 1 reply; 7+ messages in thread
From: Jeremy Fitzhardinge @ 2011-09-13 1:33 UTC (permalink / raw)
To: padovan
Cc: Linux Kernel Mailing List, linux-bluetooth, linux-wireless,
Keith Packard
Hi all,
I reported a regression in connecting my Nokia BH-905i headphones in
June this year (https://lkml.org/lkml/2011/6/23/770), which was the same
problem Keith Packard reported in https://lkml.org/lkml/2011/6/9/63.
It was briefly fixed in
git://git.kernel.org/pub/scm/linux/kernel/git/padovan/bluetooth-2.6.git.
Unfortunately it regressed again by the time of the linux-3.0 release,
to something with similar symptoms: the headphones won't reliably
connect to my laptop unless I freshly re-pair them. However, unlike the
original bug, they will very occasionally connect normally, though I
don't know why.
This behaviour has been consistent since 3.0 up until the current
3.1-rc6 kernel.
What further information can I provide? How can I help debug this?
Thanks,
J
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: Bluetooth regression with headphones 2011-09-13 1:33 Bluetooth regression with headphones Jeremy Fitzhardinge @ 2011-09-16 22:33 ` Jeremy Fitzhardinge 2011-09-16 22:38 ` Jeremy Fitzhardinge 0 siblings, 1 reply; 7+ messages in thread From: Jeremy Fitzhardinge @ 2011-09-16 22:33 UTC (permalink / raw) To: padovan Cc: Linux Kernel Mailing List, linux-bluetooth, linux-wireless, Keith Packard On 09/12/2011 06:33 PM, Jeremy Fitzhardinge wrote: > Hi all, > > I reported a regression in connecting my Nokia BH-905i headphones in > June this year (https://lkml.org/lkml/2011/6/23/770), which was the same > problem Keith Packard reported in https://lkml.org/lkml/2011/6/9/63. > It was briefly fixed in > git://git.kernel.org/pub/scm/linux/kernel/git/padovan/bluetooth-2.6.git. > > Unfortunately it regressed again by the time of the linux-3.0 release, > to something with similar symptoms: the headphones won't reliably > connect to my laptop unless I freshly re-pair them. However, unlike the > original bug, they will very occasionally connect normally, though I > don't know why. > > This behaviour has been consistent since 3.0 up until the current > 3.1-rc6 kernel. > > What further information can I provide? How can I help debug this? I turned on debugging by running "bluetoothd -n -d", and got the following when trying to connect my headphones: Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_features_information() hci0 status 0 Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_name_information() hci0 status 0 Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1 Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:rfcomm_connect() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connecting to 00:0B:E4:A6:6C:0D channel 1 Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() hci0 dba 00:0B:E4:A6:6C:0D Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04 Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() Matching key found Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() link key type 0x04 Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:auth_complete() hci0 status 0 Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() status=00 Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() no pending auth request Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: Permission denied (13) Sep 16 15:30:50 saboo bluetoothd[22025]: Permission denied (13) Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_CONNECTING -> HEADSET_STATE_DISCONNECTED Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D Does this cast any light on what's going wrong? Thanks, J ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Bluetooth regression with headphones 2011-09-16 22:33 ` Jeremy Fitzhardinge @ 2011-09-16 22:38 ` Jeremy Fitzhardinge 2011-09-27 18:03 ` Jeremy Fitzhardinge 2011-09-29 17:47 ` Jeremy Fitzhardinge 0 siblings, 2 replies; 7+ messages in thread From: Jeremy Fitzhardinge @ 2011-09-16 22:38 UTC (permalink / raw) To: padovan Cc: Linux Kernel Mailing List, linux-bluetooth, linux-wireless, Keith Packard On 09/16/2011 03:33 PM, Jeremy Fitzhardinge wrote: > On 09/12/2011 06:33 PM, Jeremy Fitzhardinge wrote: >> Hi all, >> >> I reported a regression in connecting my Nokia BH-905i headphones in >> June this year (https://lkml.org/lkml/2011/6/23/770), which was the same >> problem Keith Packard reported in https://lkml.org/lkml/2011/6/9/63. >> It was briefly fixed in >> git://git.kernel.org/pub/scm/linux/kernel/git/padovan/bluetooth-2.6.git. >> >> Unfortunately it regressed again by the time of the linux-3.0 release, >> to something with similar symptoms: the headphones won't reliably >> connect to my laptop unless I freshly re-pair them. However, unlike the >> original bug, they will very occasionally connect normally, though I >> don't know why. >> >> This behaviour has been consistent since 3.0 up until the current >> 3.1-rc6 kernel. >> >> What further information can I provide? How can I help debug this? > I turned on debugging by running "bluetoothd -n -d", and got the > following when trying to connect my headphones: > > Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING > Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_features_information() hci0 status 0 > Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_name_information() hci0 status 0 > Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1 > Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:rfcomm_connect() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connecting to 00:0B:E4:A6:6C:0D channel 1 > Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() hci0 dba 00:0B:E4:A6:6C:0D > Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04 > Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() Matching key found > Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() link key type 0x04 > Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:auth_complete() hci0 status 0 > Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() status=00 > Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() no pending auth request > Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: Permission denied (13) > Sep 16 15:30:50 saboo bluetoothd[22025]: Permission denied (13) > Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_CONNECTING -> HEADSET_STATE_DISCONNECTED > Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > And I get this when I successfully re-pair and connect the headphones: Sep 16 15:36:30 saboo bluetoothd[22025]: Discovery session 0x7f1059478630 with :1.326 activated Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_start_inquiry() hci0 length 8 periodic 1 Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: Discovery session 0x7f1059478630 with :1.326 activated Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_ref() 0x7f1059478630: ref=1 Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_unref() 0x7f1059478630: ref=0 Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_remove() Discovery session 0x7f1059478630 with :1.326 deactivated Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_remove() Stopping discovery Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_stop_inquiry() hci0 Sep 16 15:36:35 saboo bluetoothd[22025]: Stopping discovery Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: Stopping discovery Sep 16 15:36:35 saboo bluetoothd[22025]: Inquiry Failed with status 0x12 Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: Inquiry Failed with status 0x12 Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_create_device() 00:0B:E4:A6:6C:0D Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_create() Creating device /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=1 Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:bonding_request_new() Requesting bonding for 00:0B:E4:A6:6C:0D Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:bonding_request_new() Temporary agent registered for 00:0B:E4:A6:6C:0D at :1.326:/org/bluez/agent/wizard Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_features_information() hci0 status 0 Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_name_information() hci0 status 0 Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() hci0 dba 00:0B:E4:A6:6C:0D Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x03 Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() Matching key not found Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:io_capa_request() hci0 IO capability request for 00:0B:E4:A6:6C:0D Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_get_io_cap() initial authentication requirement is 0x03 Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_get_io_cap() final authentication requirement is 0x03 Sep 16 15:36:44 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:io_capa_response() hci0 IO capability response from 00:0B:E4:A6:6C:0D Sep 16 15:36:44 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:user_confirm_request() hci0 Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() confirm IO capabilities are 0x01 Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() confirm authentication requirement is 0x03 Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() remote IO capabilities are 0x03 Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() remote authentication requirement is 0x02 Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() auto accept of confirmation Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_confirm_reply() hci0 dba 00:0B:E4:A6:6C:0D success 1 Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_request_authentication() Requesting agent authentication for 00:0B:E4:A6:6C:0D Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:simple_pairing_complete() hci0 status 0 Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_simple_pairing_complete() status=00 Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_notify() hci0 dba 00:0B:E4:A6:6C:0D type 4 Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() key type 0x04 old key type 0xff new key type 0x04 Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() local auth 0x03 and remote auth 0x02 Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() storing link key of type 0x04 Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:auth_complete() hci0 status 0 Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() status=00 Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=2 Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/agent.c:agent_release() Releasing agent :1.326, /org/bluez/agent/wizard Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_probe_drivers() Probing drivers for 00:0B:E4:A6:6C:0D Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/manager.c:serial_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: 0000111e-0000-1000-8000-00805f9b34fb Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/port.c:create_serial_device() Registered interface org.bluez.Serial on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/manager.c:serial_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: 00001108-0000-1000-8000-00805f9b34fb Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: input/manager.c:headset_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=3 Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: input/device.c:input_device_new() Registered interface org.bluez.Input on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=4 Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/device.c:audio_device_register() Registered interface org.bluez.Audio on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Headset record Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_init() Registered interface org.bluez.Headset on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Handsfree record Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Audio Sink Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_init() Registered interface org.bluez.AudioSink on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found AV Target Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:control_init() Registered interface org.bluez.Control on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found AV Remote Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_unref() 0x7f105947ef70: ref=3 Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1 Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:rfcomm_connect() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connecting to 00:0B:E4:A6:6C:0D channel 1 Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_connect_cb() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connected to 00:0B:E4:A6:6C:0D Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+BRSF=25 Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:print_hf_features() HFP HF features: "EC and/or NR function" "Voice recognition activation" "Remote volume control" Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CIND=? Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CIND? Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CMER=3, 0, 0, 1 Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:event_reporting() Event reporting (CMER): mode=3, ind=1 Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:hfp_slc_complete() HFP Service Level Connection established Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/telephony.c:telephony_device_connected() telephony-dummy: device 0x7f1059492390 connected Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_CONNECTING -> HEADSET_STATE_CONNECTED Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+VGS=10 Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+VGM=10 Sep 16 15:36:52 saboo bluetoothd[22025]: Badly formated or unrecognized command: AT+CSRSF=1,1,1,1,1,7 Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CSRSF=1,1,1,1,1,7 Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: Badly formated or unrecognized command: AT+CSRSF=1,1,1,1,1,7 Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=2 Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=3 Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_DISCONNECTED -> SINK_STATE_CONNECTING Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=2 Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling channel to 00:0B:E4:A6:6C:0D Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=895 Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_set_state() AVCTP Connecting Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() DISCOVER request succeeded Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 1 type 1 media 0 in use 0 Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 2 type 1 media 0 in use 0 Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 4 type 1 media 0 in use 0 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 1 type 1 media 0 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 2 type 1 media 0 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 4 type 1 media 0 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:discovery_complete() Discovery complete Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=3 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_ref() 0x7f105947e3f0: ref=1 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:a2dp_config() a2dp_config: selected SEP 0x7f1059476ad0 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_ref() 0x7f105947e3f0: ref=2 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_set_configuration() 0x7f105947b330: int_seid=1, acp_seid=1 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=1 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() SET_CONFIGURATION request succeeded Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setconf_cfm() Source 0x7f1059476ad0: Set_Configuration_Cfm Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: IDLE -> CONFIGURED Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_connect_cb() AVCTP: connected to 00:0B:E4:A6:6C:0D Sep 16 15:36:54 saboo kernel: [93473.952314] input: 00:0B:E4:A6:6C:0D as /devices/virtual/input/input31 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:init_uinput() AVRCP: uinput initialized for 00:0B:E4:A6:6C:0D Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_set_state() AVCTP Connected Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() OPEN request succeeded Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport channel to 00:0B:E4:A6:6C:0D Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:handle_transport_connect() sk 29, omtu 895, send buffer size 63488 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:open_cfm() Source 0x7f1059476ad0: Open_Cfm Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:stream_setup_complete() Stream successfully created Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=0 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_free() 0x7f105947e3f0 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=2 Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: CONFIGURED -> OPEN Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_CONNECTING -> SINK_STATE_CONNECTED Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:server_cb() Accepted new client connection on unix socket (fd=30) Sep 16 15:36:54 saboo rsyslogd-2177: imuxsock begins to drop messages from pid 22025 due to rate-limiting Sep 16 22:36:54 saboo rtkit-daemon[1543]: Successfully made thread 22178 of process 1866 (/usr/bin/pulseaudio) owned by '500' RT at priority 5. Sep 16 15:36:55 saboo rsyslogd-2177: imuxsock lost 52 messages from pid 22025 due to rate-limiting Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() START request succeeded Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:start_cfm() Source 0x7f1059476ad0: Start_Cfm Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_START_STREAM Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_NEW_STREAM Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=0 Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_free() 0x7f105947e3f0 Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=3 Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: OPEN -> STREAMING Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_CONNECTED -> SINK_STATE_PLAYING Thanks, J ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Bluetooth regression with headphones 2011-09-16 22:38 ` Jeremy Fitzhardinge @ 2011-09-27 18:03 ` Jeremy Fitzhardinge 2011-09-29 17:47 ` Jeremy Fitzhardinge 1 sibling, 0 replies; 7+ messages in thread From: Jeremy Fitzhardinge @ 2011-09-27 18:03 UTC (permalink / raw) To: padovan Cc: Linux Kernel Mailing List, linux-bluetooth, linux-wireless, Keith Packard Ping? On 09/16/2011 03:38 PM, Jeremy Fitzhardinge wrote: > On 09/16/2011 03:33 PM, Jeremy Fitzhardinge wrote: >> On 09/12/2011 06:33 PM, Jeremy Fitzhardinge wrote: >>> Hi all, >>> >>> I reported a regression in connecting my Nokia BH-905i headphones in >>> June this year (https://lkml.org/lkml/2011/6/23/770), which was the same >>> problem Keith Packard reported in https://lkml.org/lkml/2011/6/9/63. >>> It was briefly fixed in >>> git://git.kernel.org/pub/scm/linux/kernel/git/padovan/bluetooth-2.6.git. >>> >>> Unfortunately it regressed again by the time of the linux-3.0 release, >>> to something with similar symptoms: the headphones won't reliably >>> connect to my laptop unless I freshly re-pair them. However, unlike the >>> original bug, they will very occasionally connect normally, though I >>> don't know why. >>> >>> This behaviour has been consistent since 3.0 up until the current >>> 3.1-rc6 kernel. >>> >>> What further information can I provide? How can I help debug this? >> I turned on debugging by running "bluetoothd -n -d", and got the >> following when trying to connect my headphones: >> >> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING >> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_features_information() hci0 status 0 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_name_information() hci0 status 0 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:rfcomm_connect() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connecting to 00:0B:E4:A6:6C:0D channel 1 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() hci0 dba 00:0B:E4:A6:6C:0D >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() Matching key found >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() link key type 0x04 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:auth_complete() hci0 status 0 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() status=00 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() no pending auth request >> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: Permission denied (13) >> Sep 16 15:30:50 saboo bluetoothd[22025]: Permission denied (13) >> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_CONNECTING -> HEADSET_STATE_DISCONNECTED >> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >> > And I get this when I successfully re-pair and connect the headphones: > > Sep 16 15:36:30 saboo bluetoothd[22025]: Discovery session 0x7f1059478630 with :1.326 activated > Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_start_inquiry() hci0 length 8 periodic 1 > Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: Discovery session 0x7f1059478630 with :1.326 activated > Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_ref() 0x7f1059478630: ref=1 > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_unref() 0x7f1059478630: ref=0 > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_remove() Discovery session 0x7f1059478630 with :1.326 deactivated > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_remove() Stopping discovery > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_stop_inquiry() hci0 > Sep 16 15:36:35 saboo bluetoothd[22025]: Stopping discovery > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: Stopping discovery > Sep 16 15:36:35 saboo bluetoothd[22025]: Inquiry Failed with status 0x12 > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: Inquiry Failed with status 0x12 > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_create_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_create() Creating device /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=1 > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:bonding_request_new() Requesting bonding for 00:0B:E4:A6:6C:0D > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:bonding_request_new() Temporary agent registered for 00:0B:E4:A6:6C:0D at :1.326:/org/bluez/agent/wizard > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_features_information() hci0 status 0 > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_name_information() hci0 status 0 > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() hci0 dba 00:0B:E4:A6:6C:0D > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x03 > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() Matching key not found > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:io_capa_request() hci0 IO capability request for 00:0B:E4:A6:6C:0D > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_get_io_cap() initial authentication requirement is 0x03 > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_get_io_cap() final authentication requirement is 0x03 > Sep 16 15:36:44 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:io_capa_response() hci0 IO capability response from 00:0B:E4:A6:6C:0D > Sep 16 15:36:44 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:user_confirm_request() hci0 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() confirm IO capabilities are 0x01 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() confirm authentication requirement is 0x03 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() remote IO capabilities are 0x03 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() remote authentication requirement is 0x02 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() auto accept of confirmation > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_confirm_reply() hci0 dba 00:0B:E4:A6:6C:0D success 1 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_request_authentication() Requesting agent authentication for 00:0B:E4:A6:6C:0D > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:simple_pairing_complete() hci0 status 0 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_simple_pairing_complete() status=00 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_notify() hci0 dba 00:0B:E4:A6:6C:0D type 4 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() key type 0x04 old key type 0xff new key type 0x04 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() local auth 0x03 and remote auth 0x02 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() storing link key of type 0x04 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:auth_complete() hci0 status 0 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() status=00 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=2 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/agent.c:agent_release() Releasing agent :1.326, /org/bluez/agent/wizard > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_probe_drivers() Probing drivers for 00:0B:E4:A6:6C:0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/manager.c:serial_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: 0000111e-0000-1000-8000-00805f9b34fb > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/port.c:create_serial_device() Registered interface org.bluez.Serial on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/manager.c:serial_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: 00001108-0000-1000-8000-00805f9b34fb > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: input/manager.c:headset_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=3 > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: input/device.c:input_device_new() Registered interface org.bluez.Input on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=4 > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/device.c:audio_device_register() Registered interface org.bluez.Audio on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Headset record > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_init() Registered interface org.bluez.Headset on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Handsfree record > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Audio Sink > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_init() Registered interface org.bluez.AudioSink on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found AV Target > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:control_init() Registered interface org.bluez.Control on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found AV Remote > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_unref() 0x7f105947ef70: ref=3 > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1 > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:rfcomm_connect() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connecting to 00:0B:E4:A6:6C:0D channel 1 > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_connect_cb() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connected to 00:0B:E4:A6:6C:0D > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+BRSF=25 > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:print_hf_features() HFP HF features: "EC and/or NR function" "Voice recognition activation" "Remote volume control" > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CIND=? > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CIND? > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CMER=3, 0, 0, 1 > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:event_reporting() Event reporting (CMER): mode=3, ind=1 > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:hfp_slc_complete() HFP Service Level Connection established > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/telephony.c:telephony_device_connected() telephony-dummy: device 0x7f1059492390 connected > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_CONNECTING -> HEADSET_STATE_CONNECTED > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+VGS=10 > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+VGM=10 > Sep 16 15:36:52 saboo bluetoothd[22025]: Badly formated or unrecognized command: AT+CSRSF=1,1,1,1,1,7 > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CSRSF=1,1,1,1,1,7 > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: Badly formated or unrecognized command: AT+CSRSF=1,1,1,1,1,7 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=2 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=3 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_DISCONNECTED -> SINK_STATE_CONNECTING > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=2 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling channel to 00:0B:E4:A6:6C:0D > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=895 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_set_state() AVCTP Connecting > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() DISCOVER request succeeded > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 1 type 1 media 0 in use 0 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 2 type 1 media 0 in use 0 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 4 type 1 media 0 in use 0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 1 type 1 media 0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 2 type 1 media 0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 4 type 1 media 0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:discovery_complete() Discovery complete > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=3 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_ref() 0x7f105947e3f0: ref=1 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:a2dp_config() a2dp_config: selected SEP 0x7f1059476ad0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_ref() 0x7f105947e3f0: ref=2 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_set_configuration() 0x7f105947b330: int_seid=1, acp_seid=1 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=1 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() SET_CONFIGURATION request succeeded > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setconf_cfm() Source 0x7f1059476ad0: Set_Configuration_Cfm > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: IDLE -> CONFIGURED > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_connect_cb() AVCTP: connected to 00:0B:E4:A6:6C:0D > Sep 16 15:36:54 saboo kernel: [93473.952314] input: 00:0B:E4:A6:6C:0D as /devices/virtual/input/input31 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:init_uinput() AVRCP: uinput initialized for 00:0B:E4:A6:6C:0D > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_set_state() AVCTP Connected > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() OPEN request succeeded > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport channel to 00:0B:E4:A6:6C:0D > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:handle_transport_connect() sk 29, omtu 895, send buffer size 63488 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:open_cfm() Source 0x7f1059476ad0: Open_Cfm > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:stream_setup_complete() Stream successfully created > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_free() 0x7f105947e3f0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=2 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: CONFIGURED -> OPEN > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_CONNECTING -> SINK_STATE_CONNECTED > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:server_cb() Accepted new client connection on unix socket (fd=30) > Sep 16 15:36:54 saboo rsyslogd-2177: imuxsock begins to drop messages from pid 22025 due to rate-limiting > Sep 16 22:36:54 saboo rtkit-daemon[1543]: Successfully made thread 22178 of process 1866 (/usr/bin/pulseaudio) owned by '500' RT at priority 5. > Sep 16 15:36:55 saboo rsyslogd-2177: imuxsock lost 52 messages from pid 22025 due to rate-limiting > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() START request succeeded > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:start_cfm() Source 0x7f1059476ad0: Start_Cfm > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_START_STREAM > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_NEW_STREAM > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=0 > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_free() 0x7f105947e3f0 > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=3 > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: OPEN -> STREAMING > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_CONNECTED -> SINK_STATE_PLAYING > > Thanks, > J > ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Bluetooth regression with headphones 2011-09-16 22:38 ` Jeremy Fitzhardinge 2011-09-27 18:03 ` Jeremy Fitzhardinge @ 2011-09-29 17:47 ` Jeremy Fitzhardinge 2011-09-29 20:01 ` Gustavo Padovan 1 sibling, 1 reply; 7+ messages in thread From: Jeremy Fitzhardinge @ 2011-09-29 17:47 UTC (permalink / raw) To: padovan Cc: Linux Kernel Mailing List, linux-bluetooth, linux-wireless, Keith Packard, Waldemar Rymarkiewicz, Luiz Augusto von Dentz, Ilia Kolomisnky On 09/16/2011 03:38 PM, Jeremy Fitzhardinge wrote: > On 09/16/2011 03:33 PM, Jeremy Fitzhardinge wrote: >> On 09/12/2011 06:33 PM, Jeremy Fitzhardinge wrote: >>> Hi all, >>> >>> I reported a regression in connecting my Nokia BH-905i headphones in >>> June this year (https://lkml.org/lkml/2011/6/23/770), which was the same >>> problem Keith Packard reported in https://lkml.org/lkml/2011/6/9/63. >>> It was briefly fixed in >>> git://git.kernel.org/pub/scm/linux/kernel/git/padovan/bluetooth-2.6.git. >>> >>> Unfortunately it regressed again by the time of the linux-3.0 release, >>> to something with similar symptoms: the headphones won't reliably >>> connect to my laptop unless I freshly re-pair them. However, unlike the >>> original bug, they will very occasionally connect normally, though I >>> don't know why. >>> >>> This behaviour has been consistent since 3.0 up until the current >>> 3.1-rc6 kernel. >>> >>> What further information can I provide? How can I help debug this? >> I turned on debugging by running "bluetoothd -n -d", and got the >> following when trying to connect my headphones: >> >> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING >> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_features_information() hci0 status 0 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_name_information() hci0 status 0 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:rfcomm_connect() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connecting to 00:0B:E4:A6:6C:0D channel 1 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() hci0 dba 00:0B:E4:A6:6C:0D >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() Matching key found >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() link key type 0x04 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:auth_complete() hci0 status 0 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() status=00 >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() no pending auth request >> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: Permission denied (13) >> Sep 16 15:30:50 saboo bluetoothd[22025]: Permission denied (13) >> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_CONNECTING -> HEADSET_STATE_DISCONNECTED >> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >> > And I get this when I successfully re-pair and connect the headphones: > > Sep 16 15:36:30 saboo bluetoothd[22025]: Discovery session 0x7f1059478630 with :1.326 activated > Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_start_inquiry() hci0 length 8 periodic 1 > Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: Discovery session 0x7f1059478630 with :1.326 activated > Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_ref() 0x7f1059478630: ref=1 > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_unref() 0x7f1059478630: ref=0 > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_remove() Discovery session 0x7f1059478630 with :1.326 deactivated > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_remove() Stopping discovery > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_stop_inquiry() hci0 > Sep 16 15:36:35 saboo bluetoothd[22025]: Stopping discovery > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: Stopping discovery > Sep 16 15:36:35 saboo bluetoothd[22025]: Inquiry Failed with status 0x12 > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: Inquiry Failed with status 0x12 > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_create_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_create() Creating device /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=1 > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:bonding_request_new() Requesting bonding for 00:0B:E4:A6:6C:0D > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:bonding_request_new() Temporary agent registered for 00:0B:E4:A6:6C:0D at :1.326:/org/bluez/agent/wizard > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_features_information() hci0 status 0 > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_name_information() hci0 status 0 > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() hci0 dba 00:0B:E4:A6:6C:0D > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x03 > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() Matching key not found > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:io_capa_request() hci0 IO capability request for 00:0B:E4:A6:6C:0D > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_get_io_cap() initial authentication requirement is 0x03 > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_get_io_cap() final authentication requirement is 0x03 > Sep 16 15:36:44 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:io_capa_response() hci0 IO capability response from 00:0B:E4:A6:6C:0D > Sep 16 15:36:44 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:user_confirm_request() hci0 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() confirm IO capabilities are 0x01 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() confirm authentication requirement is 0x03 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() remote IO capabilities are 0x03 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() remote authentication requirement is 0x02 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() auto accept of confirmation > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_confirm_reply() hci0 dba 00:0B:E4:A6:6C:0D success 1 > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_request_authentication() Requesting agent authentication for 00:0B:E4:A6:6C:0D > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:simple_pairing_complete() hci0 status 0 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_simple_pairing_complete() status=00 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_notify() hci0 dba 00:0B:E4:A6:6C:0D type 4 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() key type 0x04 old key type 0xff new key type 0x04 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() local auth 0x03 and remote auth 0x02 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() storing link key of type 0x04 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:auth_complete() hci0 status 0 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() status=00 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=2 > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/agent.c:agent_release() Releasing agent :1.326, /org/bluez/agent/wizard > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_probe_drivers() Probing drivers for 00:0B:E4:A6:6C:0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/manager.c:serial_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: 0000111e-0000-1000-8000-00805f9b34fb > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/port.c:create_serial_device() Registered interface org.bluez.Serial on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/manager.c:serial_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: 00001108-0000-1000-8000-00805f9b34fb > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: input/manager.c:headset_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=3 > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: input/device.c:input_device_new() Registered interface org.bluez.Input on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=4 > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/device.c:audio_device_register() Registered interface org.bluez.Audio on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Headset record > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_init() Registered interface org.bluez.Headset on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Handsfree record > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Audio Sink > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_init() Registered interface org.bluez.AudioSink on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found AV Target > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:control_init() Registered interface org.bluez.Control on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found AV Remote > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_unref() 0x7f105947ef70: ref=3 > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1 > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:rfcomm_connect() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connecting to 00:0B:E4:A6:6C:0D channel 1 > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_connect_cb() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connected to 00:0B:E4:A6:6C:0D > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+BRSF=25 > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:print_hf_features() HFP HF features: "EC and/or NR function" "Voice recognition activation" "Remote volume control" > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CIND=? > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CIND? > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CMER=3, 0, 0, 1 > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:event_reporting() Event reporting (CMER): mode=3, ind=1 > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:hfp_slc_complete() HFP Service Level Connection established > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/telephony.c:telephony_device_connected() telephony-dummy: device 0x7f1059492390 connected > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_CONNECTING -> HEADSET_STATE_CONNECTED > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+VGS=10 > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+VGM=10 > Sep 16 15:36:52 saboo bluetoothd[22025]: Badly formated or unrecognized command: AT+CSRSF=1,1,1,1,1,7 > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CSRSF=1,1,1,1,1,7 > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: Badly formated or unrecognized command: AT+CSRSF=1,1,1,1,1,7 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=2 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=3 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_DISCONNECTED -> SINK_STATE_CONNECTING > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=2 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling channel to 00:0B:E4:A6:6C:0D > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=895 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_set_state() AVCTP Connecting > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() DISCOVER request succeeded > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 1 type 1 media 0 in use 0 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 2 type 1 media 0 in use 0 > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 4 type 1 media 0 in use 0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 1 type 1 media 0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 2 type 1 media 0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 4 type 1 media 0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:discovery_complete() Discovery complete > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=3 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_ref() 0x7f105947e3f0: ref=1 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:a2dp_config() a2dp_config: selected SEP 0x7f1059476ad0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_ref() 0x7f105947e3f0: ref=2 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_set_configuration() 0x7f105947b330: int_seid=1, acp_seid=1 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=1 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() SET_CONFIGURATION request succeeded > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setconf_cfm() Source 0x7f1059476ad0: Set_Configuration_Cfm > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: IDLE -> CONFIGURED > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_connect_cb() AVCTP: connected to 00:0B:E4:A6:6C:0D > Sep 16 15:36:54 saboo kernel: [93473.952314] input: 00:0B:E4:A6:6C:0D as /devices/virtual/input/input31 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:init_uinput() AVRCP: uinput initialized for 00:0B:E4:A6:6C:0D > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_set_state() AVCTP Connected > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() OPEN request succeeded > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport channel to 00:0B:E4:A6:6C:0D > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:handle_transport_connect() sk 29, omtu 895, send buffer size 63488 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:open_cfm() Source 0x7f1059476ad0: Open_Cfm > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:stream_setup_complete() Stream successfully created > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_free() 0x7f105947e3f0 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=2 > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: CONFIGURED -> OPEN > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_CONNECTING -> SINK_STATE_CONNECTED > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:server_cb() Accepted new client connection on unix socket (fd=30) > Sep 16 15:36:54 saboo rsyslogd-2177: imuxsock begins to drop messages from pid 22025 due to rate-limiting > Sep 16 22:36:54 saboo rtkit-daemon[1543]: Successfully made thread 22178 of process 1866 (/usr/bin/pulseaudio) owned by '500' RT at priority 5. > Sep 16 15:36:55 saboo rsyslogd-2177: imuxsock lost 52 messages from pid 22025 due to rate-limiting > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() START request succeeded > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:start_cfm() Source 0x7f1059476ad0: Start_Cfm > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_START_STREAM > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_NEW_STREAM > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=0 > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_free() 0x7f105947e3f0 > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=3 > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: OPEN -> STREAMING > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_CONNECTED -> SINK_STATE_PLAYING > > Thanks, > J I tried to bisect this with inconclusive results. Firstly, it was all working fine up until 13d39315 "Bluetooth: Map sec_level to link key requirements". This had a couple of known bugs fixed with 6fdf658c "Bluetooth: Fix L2CAP security check" and 33060542 "Bluetooth: Fix L2CAP connection establishment". When I cherry-picked just those onto 13d39315 it all seems to work well again. However, after that, it regresses again, and reconnection gets pretty unreliable. From bisection of a linearized history of the net/bluetooth changes, it appears that 60b83f57 "Bluetooth: Ignore key unauthenticated for high security" is at least part of the problem, and when I revert it from the bluetooth branch it seems to help; but when I revert it from an overall v3.1 linux.git head, it doesn't, so perhaps something else in there is also causing a problem. It seems clear that all the new stricter enforcement of security stuff is upsetting my headphone's reconnection, but I've reached the limit of how much I can diagnose this without some pointers, because I don't really know anything about bluetooth. How can I help fix this? Thanks, J ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Bluetooth regression with headphones 2011-09-29 17:47 ` Jeremy Fitzhardinge @ 2011-09-29 20:01 ` Gustavo Padovan 2011-09-30 4:52 ` Jeremy Fitzhardinge 0 siblings, 1 reply; 7+ messages in thread From: Gustavo Padovan @ 2011-09-29 20:01 UTC (permalink / raw) To: Jeremy Fitzhardinge Cc: Linux Kernel Mailing List, linux-bluetooth, linux-wireless, Keith Packard, Waldemar Rymarkiewicz, Luiz Augusto von Dentz, Ilia Kolomisnky Hi Jeremy, * Jeremy Fitzhardinge <jeremy@goop.org> [2011-09-29 10:47:37 -0700]: > On 09/16/2011 03:38 PM, Jeremy Fitzhardinge wrote: > > On 09/16/2011 03:33 PM, Jeremy Fitzhardinge wrote: > >> On 09/12/2011 06:33 PM, Jeremy Fitzhardinge wrote: > >>> Hi all, > >>> > >>> I reported a regression in connecting my Nokia BH-905i headphones in > >>> June this year (https://lkml.org/lkml/2011/6/23/770), which was the same > >>> problem Keith Packard reported in https://lkml.org/lkml/2011/6/9/63. > >>> It was briefly fixed in > >>> git://git.kernel.org/pub/scm/linux/kernel/git/padovan/bluetooth-2.6.git. > >>> > >>> Unfortunately it regressed again by the time of the linux-3.0 release, > >>> to something with similar symptoms: the headphones won't reliably > >>> connect to my laptop unless I freshly re-pair them. However, unlike the > >>> original bug, they will very occasionally connect normally, though I > >>> don't know why. > >>> > >>> This behaviour has been consistent since 3.0 up until the current > >>> 3.1-rc6 kernel. > >>> > >>> What further information can I provide? How can I help debug this? > >> I turned on debugging by running "bluetoothd -n -d", and got the > >> following when trying to connect my headphones: > >> > >> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING > >> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > >> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_features_information() hci0 status 0 > >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_name_information() hci0 status 0 > >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1 > >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:rfcomm_connect() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connecting to 00:0B:E4:A6:6C:0D channel 1 > >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() hci0 dba 00:0B:E4:A6:6C:0D > >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04 > >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() Matching key found > >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() link key type 0x04 > >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:auth_complete() hci0 status 0 > >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() status=00 > >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > >> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() no pending auth request > >> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: Permission denied (13) > >> Sep 16 15:30:50 saboo bluetoothd[22025]: Permission denied (13) > >> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_CONNECTING -> HEADSET_STATE_DISCONNECTED > >> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > >> > > And I get this when I successfully re-pair and connect the headphones: > > > > Sep 16 15:36:30 saboo bluetoothd[22025]: Discovery session 0x7f1059478630 with :1.326 activated > > Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_start_inquiry() hci0 length 8 periodic 1 > > Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: Discovery session 0x7f1059478630 with :1.326 activated > > Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_ref() 0x7f1059478630: ref=1 > > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_unref() 0x7f1059478630: ref=0 > > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_remove() Discovery session 0x7f1059478630 with :1.326 deactivated > > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_remove() Stopping discovery > > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_stop_inquiry() hci0 > > Sep 16 15:36:35 saboo bluetoothd[22025]: Stopping discovery > > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: Stopping discovery > > Sep 16 15:36:35 saboo bluetoothd[22025]: Inquiry Failed with status 0x12 > > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: Inquiry Failed with status 0x12 > > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_create_device() 00:0B:E4:A6:6C:0D > > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_create() Creating device /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=1 > > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:bonding_request_new() Requesting bonding for 00:0B:E4:A6:6C:0D > > Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:bonding_request_new() Temporary agent registered for 00:0B:E4:A6:6C:0D at :1.326:/org/bluez/agent/wizard > > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_features_information() hci0 status 0 > > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_name_information() hci0 status 0 > > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() hci0 dba 00:0B:E4:A6:6C:0D > > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x03 > > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() Matching key not found > > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:io_capa_request() hci0 IO capability request for 00:0B:E4:A6:6C:0D > > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D > > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_get_io_cap() initial authentication requirement is 0x03 > > Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_get_io_cap() final authentication requirement is 0x03 > > Sep 16 15:36:44 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:io_capa_response() hci0 IO capability response from 00:0B:E4:A6:6C:0D > > Sep 16 15:36:44 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:user_confirm_request() hci0 > > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D > > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() confirm IO capabilities are 0x01 > > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() confirm authentication requirement is 0x03 > > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() remote IO capabilities are 0x03 > > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() remote authentication requirement is 0x02 > > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() auto accept of confirmation > > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_confirm_reply() hci0 dba 00:0B:E4:A6:6C:0D success 1 > > Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_request_authentication() Requesting agent authentication for 00:0B:E4:A6:6C:0D > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:simple_pairing_complete() hci0 status 0 > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_simple_pairing_complete() status=00 > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_notify() hci0 dba 00:0B:E4:A6:6C:0D type 4 > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() key type 0x04 old key type 0xff new key type 0x04 > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() local auth 0x03 and remote auth 0x02 > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() storing link key of type 0x04 > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:auth_complete() hci0 status 0 > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() status=00 > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=2 > > Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/agent.c:agent_release() Releasing agent :1.326, /org/bluez/agent/wizard > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_probe_drivers() Probing drivers for 00:0B:E4:A6:6C:0D > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/manager.c:serial_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: 0000111e-0000-1000-8000-00805f9b34fb > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/port.c:create_serial_device() Registered interface org.bluez.Serial on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/manager.c:serial_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: 00001108-0000-1000-8000-00805f9b34fb > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: input/manager.c:headset_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=3 > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: input/device.c:input_device_new() Registered interface org.bluez.Input on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=4 > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/device.c:audio_device_register() Registered interface org.bluez.Audio on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Headset record > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_init() Registered interface org.bluez.Headset on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Handsfree record > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Audio Sink > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_init() Registered interface org.bluez.AudioSink on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found AV Target > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:control_init() Registered interface org.bluez.Control on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found AV Remote > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_unref() 0x7f105947ef70: ref=3 > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1 > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:rfcomm_connect() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connecting to 00:0B:E4:A6:6C:0D channel 1 > > Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_connect_cb() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connected to 00:0B:E4:A6:6C:0D > > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+BRSF=25 > > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:print_hf_features() HFP HF features: "EC and/or NR function" "Voice recognition activation" "Remote volume control" > > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CIND=? > > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CIND? > > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CMER=3, 0, 0, 1 > > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:event_reporting() Event reporting (CMER): mode=3, ind=1 > > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:hfp_slc_complete() HFP Service Level Connection established > > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/telephony.c:telephony_device_connected() telephony-dummy: device 0x7f1059492390 connected > > Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_CONNECTING -> HEADSET_STATE_CONNECTED > > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+VGS=10 > > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+VGM=10 > > Sep 16 15:36:52 saboo bluetoothd[22025]: Badly formated or unrecognized command: AT+CSRSF=1,1,1,1,1,7 > > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CSRSF=1,1,1,1,1,7 > > Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: Badly formated or unrecognized command: AT+CSRSF=1,1,1,1,1,7 > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=2 > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=3 > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_DISCONNECTED -> SINK_STATE_CONNECTING > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=2 > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling channel to 00:0B:E4:A6:6C:0D > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=895 > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_set_state() AVCTP Connecting > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() DISCOVER request succeeded > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 1 type 1 media 0 in use 0 > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 2 type 1 media 0 in use 0 > > Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 4 type 1 media 0 in use 0 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 1 type 1 media 0 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 2 type 1 media 0 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 4 type 1 media 0 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:discovery_complete() Discovery complete > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=3 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_ref() 0x7f105947e3f0: ref=1 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:a2dp_config() a2dp_config: selected SEP 0x7f1059476ad0 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_ref() 0x7f105947e3f0: ref=2 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_set_configuration() 0x7f105947b330: int_seid=1, acp_seid=1 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=1 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() SET_CONFIGURATION request succeeded > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setconf_cfm() Source 0x7f1059476ad0: Set_Configuration_Cfm > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: IDLE -> CONFIGURED > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_connect_cb() AVCTP: connected to 00:0B:E4:A6:6C:0D > > Sep 16 15:36:54 saboo kernel: [93473.952314] input: 00:0B:E4:A6:6C:0D as /devices/virtual/input/input31 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:init_uinput() AVRCP: uinput initialized for 00:0B:E4:A6:6C:0D > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_set_state() AVCTP Connected > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() OPEN request succeeded > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport channel to 00:0B:E4:A6:6C:0D > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:handle_transport_connect() sk 29, omtu 895, send buffer size 63488 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:open_cfm() Source 0x7f1059476ad0: Open_Cfm > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:stream_setup_complete() Stream successfully created > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=0 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_free() 0x7f105947e3f0 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=2 > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: CONFIGURED -> OPEN > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_CONNECTING -> SINK_STATE_CONNECTED > > Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:server_cb() Accepted new client connection on unix socket (fd=30) > > Sep 16 15:36:54 saboo rsyslogd-2177: imuxsock begins to drop messages from pid 22025 due to rate-limiting > > Sep 16 22:36:54 saboo rtkit-daemon[1543]: Successfully made thread 22178 of process 1866 (/usr/bin/pulseaudio) owned by '500' RT at priority 5. > > Sep 16 15:36:55 saboo rsyslogd-2177: imuxsock lost 52 messages from pid 22025 due to rate-limiting > > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() > > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() START request succeeded > > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:start_cfm() Source 0x7f1059476ad0: Start_Cfm > > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_START_STREAM > > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_NEW_STREAM > > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=0 > > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_free() 0x7f105947e3f0 > > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=3 > > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: OPEN -> STREAMING > > Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_CONNECTED -> SINK_STATE_PLAYING > > > > Thanks, > > J > > > I tried to bisect this with inconclusive results. > > Firstly, it was all working fine up until 13d39315 "Bluetooth: Map > sec_level to link key requirements". This had a couple of known bugs > fixed with 6fdf658c "Bluetooth: Fix L2CAP security check" and 33060542 > "Bluetooth: Fix L2CAP connection establishment". When I cherry-picked > just those onto 13d39315 it all seems to work well again. > > However, after that, it regresses again, and reconnection gets pretty > unreliable. From bisection of a linearized history of the net/bluetooth > changes, it appears that 60b83f57 "Bluetooth: Ignore key unauthenticated > for high security" is at least part of the problem, and when I revert it > from the bluetooth branch it seems to help; but when I revert it from an > overall v3.1 linux.git head, it doesn't, so perhaps something else in > there is also causing a problem. > > It seems clear that all the new stricter enforcement of security stuff > is upsetting my headphone's reconnection, but I've reached the limit of > how much I can diagnose this without some pointers, because I don't > really know anything about bluetooth. > > How can I help fix this? Can you send me the hcidump logs of both the working and not working scenarios? It helps a lot find issues. Gustavo ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Bluetooth regression with headphones 2011-09-29 20:01 ` Gustavo Padovan @ 2011-09-30 4:52 ` Jeremy Fitzhardinge 0 siblings, 0 replies; 7+ messages in thread From: Jeremy Fitzhardinge @ 2011-09-30 4:52 UTC (permalink / raw) To: Linux Kernel Mailing List, linux-bluetooth, linux-wireless, Keith Packard, Waldemar Rymarkiewicz, Luiz Augusto von Dentz, Ilia Kolomisnky [-- Attachment #1: Type: text/plain, Size: 25335 bytes --] On 09/29/2011 01:01 PM, Gustavo Padovan wrote: > Hi Jeremy, > > * Jeremy Fitzhardinge <jeremy@goop.org> [2011-09-29 10:47:37 -0700]: > >> On 09/16/2011 03:38 PM, Jeremy Fitzhardinge wrote: >>> On 09/16/2011 03:33 PM, Jeremy Fitzhardinge wrote: >>>> On 09/12/2011 06:33 PM, Jeremy Fitzhardinge wrote: >>>>> Hi all, >>>>> >>>>> I reported a regression in connecting my Nokia BH-905i headphones in >>>>> June this year (https://lkml.org/lkml/2011/6/23/770), which was the same >>>>> problem Keith Packard reported in https://lkml.org/lkml/2011/6/9/63. >>>>> It was briefly fixed in >>>>> git://git.kernel.org/pub/scm/linux/kernel/git/padovan/bluetooth-2.6.git. >>>>> >>>>> Unfortunately it regressed again by the time of the linux-3.0 release, >>>>> to something with similar symptoms: the headphones won't reliably >>>>> connect to my laptop unless I freshly re-pair them. However, unlike the >>>>> original bug, they will very occasionally connect normally, though I >>>>> don't know why. >>>>> >>>>> This behaviour has been consistent since 3.0 up until the current >>>>> 3.1-rc6 kernel. >>>>> >>>>> What further information can I provide? How can I help debug this? >>>> I turned on debugging by running "bluetoothd -n -d", and got the >>>> following when trying to connect my headphones: >>>> >>>> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING >>>> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >>>> Sep 16 15:30:47 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_features_information() hci0 status 0 >>>> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_name_information() hci0 status 0 >>>> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1 >>>> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:rfcomm_connect() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connecting to 00:0B:E4:A6:6C:0D channel 1 >>>> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() hci0 dba 00:0B:E4:A6:6C:0D >>>> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04 >>>> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() Matching key found >>>> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() link key type 0x04 >>>> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:auth_complete() hci0 status 0 >>>> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() status=00 >>>> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >>>> Sep 16 15:30:48 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() no pending auth request >>>> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: Permission denied (13) >>>> Sep 16 15:30:50 saboo bluetoothd[22025]: Permission denied (13) >>>> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_CONNECTING -> HEADSET_STATE_DISCONNECTED >>>> Sep 16 15:30:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >>>> >>> And I get this when I successfully re-pair and connect the headphones: >>> >>> Sep 16 15:36:30 saboo bluetoothd[22025]: Discovery session 0x7f1059478630 with :1.326 activated >>> Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_start_inquiry() hci0 length 8 periodic 1 >>> Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: Discovery session 0x7f1059478630 with :1.326 activated >>> Sep 16 15:36:30 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_ref() 0x7f1059478630: ref=1 >>> Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_unref() 0x7f1059478630: ref=0 >>> Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_remove() Discovery session 0x7f1059478630 with :1.326 deactivated >>> Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:session_remove() Stopping discovery >>> Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_stop_inquiry() hci0 >>> Sep 16 15:36:35 saboo bluetoothd[22025]: Stopping discovery >>> Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: Stopping discovery >>> Sep 16 15:36:35 saboo bluetoothd[22025]: Inquiry Failed with status 0x12 >>> Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: Inquiry Failed with status 0x12 >>> Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_create_device() 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_create() Creating device /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D >>> Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=1 >>> Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:bonding_request_new() Requesting bonding for 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:35 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:bonding_request_new() Temporary agent registered for 00:0B:E4:A6:6C:0D at :1.326:/org/bluez/agent/wizard >>> Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_features_information() hci0 status 0 >>> Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:remote_name_information() hci0 status 0 >>> Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() hci0 dba 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x03 >>> Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_request() Matching key not found >>> Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:io_capa_request() hci0 IO capability request for 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_get_io_cap() initial authentication requirement is 0x03 >>> Sep 16 15:36:42 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_get_io_cap() final authentication requirement is 0x03 >>> Sep 16 15:36:44 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:io_capa_response() hci0 IO capability response from 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:44 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:user_confirm_request() hci0 >>> Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() confirm IO capabilities are 0x01 >>> Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() confirm authentication requirement is 0x03 >>> Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() remote IO capabilities are 0x03 >>> Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() remote authentication requirement is 0x02 >>> Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_user_confirm() auto accept of confirmation >>> Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_confirm_reply() hci0 dba 00:0B:E4:A6:6C:0D success 1 >>> Sep 16 15:36:46 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_request_authentication() Requesting agent authentication for 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:simple_pairing_complete() hci0 status 0 >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_simple_pairing_complete() status=00 >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:link_key_notify() hci0 dba 00:0B:E4:A6:6C:0D type 4 >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:hciops_get_auth_info() hci0 dba 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() key type 0x04 old key type 0xff new key type 0x04 >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() local auth 0x03 and remote auth 0x02 >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_link_key_notify() storing link key of type 0x04 >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: plugins/hciops.c:auth_complete() hci0 status 0 >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/event.c:btd_event_bonding_process_complete() status=00 >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=2 >>> Sep 16 15:36:49 saboo bluetoothd[22025]: bluetoothd[22025]: src/agent.c:agent_release() Releasing agent :1.326, /org/bluez/agent/wizard >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:device_probe_drivers() Probing drivers for 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/manager.c:serial_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: 0000111e-0000-1000-8000-00805f9b34fb >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/port.c:create_serial_device() Registered interface org.bluez.Serial on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: serial/manager.c:serial_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: 00001108-0000-1000-8000-00805f9b34fb >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: input/manager.c:headset_probe() path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=3 >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: input/device.c:input_device_new() Registered interface org.bluez.Input on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/adapter.c:adapter_get_device() 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_ref() 0x7f105947ef70: ref=4 >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/device.c:audio_device_register() Registered interface org.bluez.Audio on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Headset record >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_init() Registered interface org.bluez.Headset on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Handsfree record >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found Audio Sink >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_init() Registered interface org.bluez.AudioSink on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found AV Target >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:control_init() Registered interface org.bluez.Control on path /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/manager.c:handle_uuid() Found AV Remote >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: src/device.c:btd_device_unref() 0x7f105947ef70: ref=3 >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1 >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:rfcomm_connect() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connecting to 00:0B:E4:A6:6C:0D channel 1 >>> Sep 16 15:36:50 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_connect_cb() /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: Connected to 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+BRSF=25 >>> Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:print_hf_features() HFP HF features: "EC and/or NR function" "Voice recognition activation" "Remote volume control" >>> Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CIND=? >>> Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CIND? >>> Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CMER=3, 0, 0, 1 >>> Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:event_reporting() Event reporting (CMER): mode=3, ind=1 >>> Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:hfp_slc_complete() HFP Service Level Connection established >>> Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/telephony.c:telephony_device_connected() telephony-dummy: device 0x7f1059492390 connected >>> Sep 16 15:36:51 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:headset_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: HEADSET_STATE_CONNECTING -> HEADSET_STATE_CONNECTED >>> Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+VGS=10 >>> Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+VGM=10 >>> Sep 16 15:36:52 saboo bluetoothd[22025]: Badly formated or unrecognized command: AT+CSRSF=1,1,1,1,1,7 >>> Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: audio/headset.c:handle_event() Received AT+CSRSF=1,1,1,1,1,7 >>> Sep 16 15:36:52 saboo bluetoothd[22025]: bluetoothd[22025]: Badly formated or unrecognized command: AT+CSRSF=1,1,1,1,1,7 >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=2 >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=3 >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_DISCONNECTED -> SINK_STATE_CONNECTING >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=2 >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling channel to 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=895 >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_set_state() AVCTP Connecting >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() DISCOVER request succeeded >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 1 type 1 media 0 in use 0 >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 2 type 1 media 0 in use 0 >>> Sep 16 15:36:53 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_discover_resp() seid 4 type 1 media 0 in use 0 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 1 type 1 media 0 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 2 type 1 media 0 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 4 type 1 media 0 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:discovery_complete() Discovery complete >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_ref() 0x7f105947b330: ref=3 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_ref() 0x7f105947e3f0: ref=1 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:a2dp_config() a2dp_config: selected SEP 0x7f1059476ad0 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_ref() 0x7f105947e3f0: ref=2 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_set_configuration() 0x7f105947b330: int_seid=1, acp_seid=1 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=1 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() SET_CONFIGURATION request succeeded >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setconf_cfm() Source 0x7f1059476ad0: Set_Configuration_Cfm >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: IDLE -> CONFIGURED >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_connect_cb() AVCTP: connected to 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:54 saboo kernel: [93473.952314] input: 00:0B:E4:A6:6C:0D as /devices/virtual/input/input31 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:init_uinput() AVRCP: uinput initialized for 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/control.c:avctp_set_state() AVCTP Connected >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() OPEN request succeeded >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport channel to 00:0B:E4:A6:6C:0D >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:handle_transport_connect() sk 29, omtu 895, send buffer size 63488 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:open_cfm() Source 0x7f1059476ad0: Open_Cfm >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:stream_setup_complete() Stream successfully created >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=0 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_free() 0x7f105947e3f0 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=2 >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: CONFIGURED -> OPEN >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_CONNECTING -> SINK_STATE_CONNECTED >>> Sep 16 15:36:54 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:server_cb() Accepted new client connection on unix socket (fd=30) >>> Sep 16 15:36:54 saboo rsyslogd-2177: imuxsock begins to drop messages from pid 22025 due to rate-limiting >>> Sep 16 22:36:54 saboo rtkit-daemon[1543]: Successfully made thread 22178 of process 1866 (/usr/bin/pulseaudio) owned by '500' RT at priority 5. >>> Sep 16 15:36:55 saboo rsyslogd-2177: imuxsock lost 52 messages from pid 22025 due to rate-limiting >>> Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:session_cb() >>> Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_parse_resp() START request succeeded >>> Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:start_cfm() Source 0x7f1059476ad0: Start_Cfm >>> Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_START_STREAM >>> Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_NEW_STREAM >>> Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_unref() 0x7f105947e3f0: ref=0 >>> Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/a2dp.c:setup_free() 0x7f105947e3f0 >>> Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_unref() 0x7f105947b330: ref=3 >>> Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: OPEN -> STREAMING >>> Sep 16 15:36:55 saboo bluetoothd[22025]: bluetoothd[22025]: audio/sink.c:sink_set_state() State changed /org/bluez/22025/hci0/dev_00_0B_E4_A6_6C_0D: SINK_STATE_CONNECTED -> SINK_STATE_PLAYING >>> >>> Thanks, >>> J >> >> I tried to bisect this with inconclusive results. >> >> Firstly, it was all working fine up until 13d39315 "Bluetooth: Map >> sec_level to link key requirements". This had a couple of known bugs >> fixed with 6fdf658c "Bluetooth: Fix L2CAP security check" and 33060542 >> "Bluetooth: Fix L2CAP connection establishment". When I cherry-picked >> just those onto 13d39315 it all seems to work well again. >> >> However, after that, it regresses again, and reconnection gets pretty >> unreliable. From bisection of a linearized history of the net/bluetooth >> changes, it appears that 60b83f57 "Bluetooth: Ignore key unauthenticated >> for high security" is at least part of the problem, and when I revert it >> from the bluetooth branch it seems to help; but when I revert it from an >> overall v3.1 linux.git head, it doesn't, so perhaps something else in >> there is also causing a problem. >> >> It seems clear that all the new stricter enforcement of security stuff >> is upsetting my headphone's reconnection, but I've reached the limit of >> how much I can diagnose this without some pointers, because I don't >> really know anything about bluetooth. >> >> How can I help fix this? > Can you send me the hcidump logs of both the working and not working > scenarios? It helps a lot find issues. > OK, here's some traces. These were all with a current linux.git tip of tree without rebooting. I got it to connect several times successfully, which is unusually frequent (perhaps its timing related and hcidump helped?). The two failures are once when initiating the connection from the headphones, and the other from within the gnome3 bluetooth gui. Thanks, J [-- Attachment #2: v3.1-successful-disconnect.txt --] [-- Type: text/plain, Size: 3201 bytes --] HCI sniffer - Bluetooth packet analyzer ver 2.0 device: hci0 snap_len: 1028 filter: 0xffffffffffffffff 2011-09-29 14:00:19.029654 > HCI Event: Inquiry Complete (0x01) plen 1 status 0x00 2011-09-29 14:00:24.734091 > ACL data: handle 12 flags 0x02 dlen 7 L2CAP(d): cid 0x0042 len 3 [psm 0] 0000: 10 0a 04 ... 2011-09-29 14:00:24.734835 < ACL data: handle 12 flags 0x00 dlen 6 0000: 02 00 43 00 12 0a ..C... 2011-09-29 14:00:24.734858 < HCI Command: Exit Sniff Mode (0x02|0x0004) plen 2 handle 12 2011-09-29 14:00:24.739573 > HCI Event: Max Slots Change (0x1b) plen 3 handle 12 slots 5 2011-09-29 14:00:24.740478 > HCI Event: Mode Change (0x14) plen 6 status 0x00 handle 12 mode 0x00 interval 0 Mode: Active 2011-09-29 14:00:24.741473 > HCI Event: Command Status (0x0f) plen 4 Exit Sniff Mode (0x02|0x0004) status 0x0c ncmd 1 Error: Command Disallowed 2011-09-29 14:00:24.875229 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(s): Disconn req: dcid 0x0041 scid 0x0044 2011-09-29 14:00:24.875533 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 07 0d 04 00 41 00 44 00 ........A.D. 2011-09-29 14:00:24.876466 > ACL data: handle 12 flags 0x02 dlen 8 L2CAP(d): cid 0x0040 len 4 [psm 0] 0000: 6b 53 01 06 kS.. 2011-09-29 14:00:24.876654 < ACL data: handle 12 flags 0x00 dlen 8 0000: 04 00 41 00 6b 73 01 2c ..A.ks., 2011-09-29 14:00:24.879561 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 14:00:24.984086 > ACL data: handle 12 flags 0x02 dlen 8 L2CAP(d): cid 0x0040 len 4 [psm 0] 0000: 03 53 01 fd .S.. 2011-09-29 14:00:24.984484 < ACL data: handle 12 flags 0x00 dlen 8 0000: 04 00 41 00 03 73 01 d7 ..A..s.. 2011-09-29 14:00:24.988485 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 14:00:25.016467 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(s): Disconn req: dcid 0x0043 scid 0x0045 2011-09-29 14:00:25.016675 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 07 0e 04 00 43 00 45 00 ........C.E. 2011-09-29 14:00:25.017711 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(s): Disconn req: dcid 0x0040 scid 0x0041 2011-09-29 14:00:25.017783 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 07 0f 04 00 40 00 41 00 ........@.A. 2011-09-29 14:00:25.022558 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 14:00:26.031508 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(s): Disconn req: dcid 0x0042 scid 0x0043 2011-09-29 14:00:26.032171 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 07 10 04 00 42 00 43 00 ........B.C. 2011-09-29 14:00:26.164538 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 1 2011-09-29 14:00:26.464548 > HCI Event: Disconn Complete (0x05) plen 4 status 0x00 handle 12 reason 0x13 Reason: Remote User Terminated Connection [-- Attachment #3: v3.1-failed-device-connect.txt --] [-- Type: text/plain, Size: 10625 bytes --] HCI sniffer - Bluetooth packet analyzer ver 2.0 device: hci0 snap_len: 1028 filter: 0xffffffffffffffff 2011-09-29 14:00:42.067241 > HCI Event: Inquiry Complete (0x01) plen 1 status 0x00 2011-09-29 14:00:48.223231 > HCI Event: Connect Request (0x04) plen 10 bdaddr 00:0B:E4:A6:6C:0D class 0x240404 type ACL 2011-09-29 14:00:48.223380 < HCI Command: Accept Connection Request (0x01|0x0009) plen 7 bdaddr 00:0B:E4:A6:6C:0D role 0x00 Role: Master 2011-09-29 14:00:48.225134 > HCI Event: Command Status (0x0f) plen 4 Accept Connection Request (0x01|0x0009) status 0x00 ncmd 1 2011-09-29 14:00:48.388140 > HCI Event: Role Change (0x12) plen 8 status 0x00 bdaddr 00:0B:E4:A6:6C:0D role 0x00 Role: Master 2011-09-29 14:00:48.555229 > HCI Event: Connect Complete (0x03) plen 11 status 0x00 handle 11 bdaddr 00:0B:E4:A6:6C:0D type ACL encrypt 0x00 2011-09-29 14:00:48.555476 < HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2 handle 11 2011-09-29 14:00:48.557128 > HCI Event: Command Status (0x0f) plen 4 Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 1 2011-09-29 14:00:48.558126 > HCI Event: Read Remote Supported Features (0x0b) plen 11 status 0x00 handle 11 Features: 0xff 0xfe 0x0f 0xc6 0x9b 0xff 0x59 0x83 2011-09-29 14:00:48.558234 < HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3 handle 11 page 1 2011-09-29 14:00:48.560131 > HCI Event: Command Status (0x0f) plen 4 Read Remote Extended Features (0x01|0x001c) status 0x00 ncmd 1 2011-09-29 14:00:48.566136 > HCI Event: Max Slots Change (0x1b) plen 3 handle 11 slots 5 2011-09-29 14:00:48.597222 > HCI Event: Read Remote Extended Features (0x23) plen 13 status 0x00 handle 11 page 1 max 1 Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 2011-09-29 14:00:48.597451 < HCI Command: Remote Name Request (0x01|0x0019) plen 10 bdaddr 00:0B:E4:A6:6C:0D mode 2 clkoffset 0x0000 2011-09-29 14:00:48.599227 > HCI Event: Command Status (0x0f) plen 4 Remote Name Request (0x01|0x0019) status 0x00 ncmd 1 2011-09-29 14:00:48.641497 > ACL data: handle 11 flags 0x02 dlen 12 L2CAP(s): Connect req: psm 1 scid 0x0040 2011-09-29 14:00:48.641628 < ACL data: handle 11 flags 0x00 dlen 16 0000: 0c 00 01 00 03 02 08 00 40 00 40 00 01 00 00 00 ........@.@..... 2011-09-29 14:00:48.641640 < ACL data: handle 11 flags 0x00 dlen 10 0000: 06 00 01 00 0a 01 02 00 02 00 .......... 2011-09-29 14:00:48.652867 > ACL data: handle 11 flags 0x02 dlen 16 L2CAP(s): Info rsp: type 2 result 0 Extended feature mask 0x0000 2011-09-29 14:00:48.652952 < ACL data: handle 11 flags 0x00 dlen 16 0000: 0c 00 01 00 03 02 08 00 40 00 40 00 00 00 00 00 ........@.@..... 2011-09-29 14:00:48.652962 < ACL data: handle 11 flags 0x00 dlen 12 0000: 08 00 01 00 04 02 04 00 40 00 00 00 ........@... 2011-09-29 14:00:48.657117 > HCI Event: Remote Name Req Complete (0x07) plen 255 status 0x00 bdaddr 00:0B:E4:A6:6C:0D name 'Nokia BH-905i' 2011-09-29 14:00:48.658129 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 2 2011-09-29 14:00:48.659123 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 2 2011-09-29 14:00:48.666690 > ACL data: handle 11 flags 0x02 dlen 16 L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4 MTU 48 2011-09-29 14:00:48.666912 < ACL data: handle 11 flags 0x00 dlen 18 0000: 0e 00 01 00 05 03 0a 00 40 00 00 00 00 00 01 02 ........@....... 0010: 30 00 0. 2011-09-29 14:00:48.667871 > ACL data: handle 11 flags 0x02 dlen 14 L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 0 Success 2011-09-29 14:00:48.701625 > ACL data: handle 11 flags 0x02 dlen 24 L2CAP(d): cid 0x0040 len 20 [psm 0] 0000: 06 00 01 00 0f 35 05 1a 00 00 11 1f 00 26 35 03 .....5.......&5. 0010: 09 00 04 00 .... 2011-09-29 14:00:48.701968 < ACL data: handle 11 flags 0x00 dlen 33 0000: 1d 00 40 00 07 00 01 00 18 00 15 35 13 35 11 09 ..@........5.5.. 0010: 00 04 35 0c 35 03 19 01 00 35 05 19 00 03 08 0d ..5.5....5...... 0020: 00 . 2011-09-29 14:00:48.706148 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 2 2011-09-29 14:00:48.736495 > ACL data: handle 11 flags 0x02 dlen 12 L2CAP(s): Disconn req: dcid 0x0040 scid 0x0040 2011-09-29 14:00:48.736574 < ACL data: handle 11 flags 0x00 dlen 12 0000: 08 00 01 00 07 04 04 00 40 00 40 00 ........@.@. 2011-09-29 14:00:48.879221 > HCI Event: Link Key Request (0x17) plen 6 bdaddr 00:0B:E4:A6:6C:0D 2011-09-29 14:00:48.879895 < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 bdaddr 00:0B:E4:A6:6C:0D key 08AB2E2A1319F534321C46393A25B42D 2011-09-29 14:00:48.887206 > HCI Event: Command Complete (0x0e) plen 10 Link Key Request Reply (0x01|0x000b) ncmd 1 status 0x00 bdaddr 00:0B:E4:A6:6C:0D 2011-09-29 14:00:48.914122 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 1 2011-09-29 14:00:48.981219 > HCI Event: Encrypt Change (0x08) plen 4 status 0x00 handle 11 encrypt 0x01 2011-09-29 14:00:48.984117 > ACL data: handle 11 flags 0x02 dlen 12 L2CAP(s): Connect req: psm 3 scid 0x0041 2011-09-29 14:00:48.984277 < ACL data: handle 11 flags 0x00 dlen 16 0000: 0c 00 01 00 03 05 08 00 40 00 41 00 00 00 00 00 ........@.A..... 2011-09-29 14:00:48.984286 < ACL data: handle 11 flags 0x00 dlen 16 0000: 0c 00 01 00 04 03 08 00 41 00 00 00 01 02 f5 03 ........A....... 2011-09-29 14:00:48.990122 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 2 2011-09-29 14:00:49.020425 > ACL data: handle 11 flags 0x02 dlen 16 L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4 MTU 895 2011-09-29 14:00:49.020601 < ACL data: handle 11 flags 0x00 dlen 18 0000: 0e 00 01 00 05 06 0a 00 41 00 00 00 00 00 01 02 ........A....... 0010: 7f 03 .. 2011-09-29 14:00:49.021667 > ACL data: handle 11 flags 0x02 dlen 18 L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 4 MTU 1013 2011-09-29 14:00:49.055368 > ACL data: handle 11 flags 0x02 dlen 8 L2CAP(d): cid 0x0040 len 4 [psm 0] 0000: 03 3f 01 1c .?.. 2011-09-29 14:00:49.055578 < ACL data: handle 11 flags 0x00 dlen 8 0000: 04 00 41 00 03 73 01 d7 ..A..s.. 2011-09-29 14:00:49.060224 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 2 2011-09-29 14:00:49.165464 > ACL data: handle 11 flags 0x02 dlen 18 L2CAP(d): cid 0x0040 len 14 [psm 0] 0000: 03 ef 15 83 11 1a f0 00 00 7e 00 00 00 70 .........~...p 2011-09-29 14:00:49.165779 < ACL data: handle 11 flags 0x00 dlen 18 0000: 0e 00 41 00 01 ef 15 81 11 1a e0 00 00 7e 00 00 ..A..........~.. 0010: 07 aa .. 2011-09-29 14:00:49.200392 > ACL data: handle 11 flags 0x02 dlen 8 L2CAP(d): cid 0x0040 len 4 [psm 0] 0000: 6b 3f 01 e7 k?.. 2011-09-29 14:00:49.200555 < HCI Command: Authentication Requested (0x01|0x0011) plen 2 handle 11 2011-09-29 14:00:49.202130 > HCI Event: Command Status (0x0f) plen 4 Authentication Requested (0x01|0x0011) status 0x00 ncmd 1 2011-09-29 14:00:49.203117 > HCI Event: Link Key Request (0x17) plen 6 bdaddr 00:0B:E4:A6:6C:0D 2011-09-29 14:00:49.203516 < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 bdaddr 00:0B:E4:A6:6C:0D key 08AB2E2A1319F534321C46393A25B42D 2011-09-29 14:00:49.215121 > HCI Event: Command Complete (0x0e) plen 10 Link Key Request Reply (0x01|0x000b) ncmd 1 status 0x00 bdaddr 00:0B:E4:A6:6C:0D 2011-09-29 14:00:49.241116 > HCI Event: Auth Complete (0x06) plen 3 status 0x00 handle 11 2011-09-29 14:00:49.241478 < ACL data: handle 11 flags 0x00 dlen 8 0000: 04 00 41 00 6b 73 01 2c ..A.ks., 2011-09-29 14:00:49.241508 < ACL data: handle 11 flags 0x00 dlen 12 0000: 08 00 41 00 01 ef 09 e3 05 6b 8d aa ..A......k.. 2011-09-29 14:00:49.310216 > HCI Event: Encryption Key Refresh Complete (0x30) plen 3 status 0x00 handle 11 2011-09-29 14:00:49.415139 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 1 2011-09-29 14:01:07.669939 > HCI Event: Inquiry Complete (0x01) plen 1 status 0x00 2011-09-29 14:01:28.153554 > HCI Event: Inquiry Complete (0x01) plen 1 status 0x00 2011-09-29 14:01:48.894509 > ACL data: handle 11 flags 0x02 dlen 8 L2CAP(d): cid 0x0040 len 4 [psm 0] 0000: 6b 53 01 06 kS.. 2011-09-29 14:01:48.894991 < ACL data: handle 11 flags 0x00 dlen 8 0000: 04 00 41 00 6b 73 01 2c ..A.ks., 2011-09-29 14:01:48.964261 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 2 2011-09-29 14:01:49.029557 > ACL data: handle 11 flags 0x02 dlen 8 L2CAP(d): cid 0x0040 len 4 [psm 0] 0000: 69 1f 01 ac i... 2011-09-29 14:01:49.030753 > ACL data: handle 11 flags 0x02 dlen 8 L2CAP(d): cid 0x0040 len 4 [psm 0] 0000: 03 53 01 fd .S.. 2011-09-29 14:01:49.031083 < ACL data: handle 11 flags 0x00 dlen 8 0000: 04 00 41 00 03 73 01 d7 ..A..s.. 2011-09-29 14:01:49.099600 > ACL data: handle 11 flags 0x02 dlen 8 L2CAP(d): cid 0x0040 len 4 [psm 0] 0000: 69 1f 01 ac i... 2011-09-29 14:01:49.101304 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 2 2011-09-29 14:01:49.170876 > ACL data: handle 11 flags 0x02 dlen 12 L2CAP(s): Disconn req: dcid 0x0040 scid 0x0041 2011-09-29 14:01:49.171015 < ACL data: handle 11 flags 0x00 dlen 12 0000: 08 00 01 00 07 07 04 00 40 00 41 00 ........@.A. 2011-09-29 14:01:49.415302 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 1 2011-09-29 14:01:49.654252 > HCI Event: Disconn Complete (0x05) plen 4 status 0x00 handle 11 reason 0x13 Reason: Remote User Terminated Connection 2011-09-29 14:01:49.917247 > HCI Event: Inquiry Complete (0x01) plen 1 status 0x00 2011-09-29 14:02:18.068927 > HCI Event: Inquiry Complete (0x01) plen 1 status 0x00 2011-09-29 14:02:44.944550 > HCI Event: Inquiry Complete (0x01) plen 1 status 0x00 [-- Attachment #4: v3.1-failed-host-connect.txt --] [-- Type: text/plain, Size: 6757 bytes --] HCI sniffer - Bluetooth packet analyzer ver 2.0 device: hci0 snap_len: 1028 filter: 0xffffffffffffffff 2011-09-29 14:03:09.257112 > HCI Event: Inquiry Complete (0x01) plen 1 status 0x00 2011-09-29 14:03:11.442616 < HCI Command: Create Connection (0x01|0x0005) plen 13 bdaddr 00:0B:E4:A6:6C:0D ptype 0xcc18 rswitch 0x01 clkoffset 0x0000 Packet type: DM1 DM3 DM5 DH1 DH3 DH5 2011-09-29 14:03:11.444074 > HCI Event: Command Status (0x0f) plen 4 Create Connection (0x01|0x0005) status 0x00 ncmd 1 2011-09-29 14:03:11.742155 > HCI Event: Connect Complete (0x03) plen 11 status 0x00 handle 11 bdaddr 00:0B:E4:A6:6C:0D type ACL encrypt 0x00 2011-09-29 14:03:11.742425 < HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2 handle 11 2011-09-29 14:03:11.744064 > HCI Event: Command Status (0x0f) plen 4 Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 1 2011-09-29 14:03:11.745064 > HCI Event: Read Remote Supported Features (0x0b) plen 11 status 0x00 handle 11 Features: 0xff 0xfe 0x0f 0xc6 0x9b 0xff 0x59 0x83 2011-09-29 14:03:11.745252 < HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3 handle 11 page 1 2011-09-29 14:03:11.747069 > HCI Event: Command Status (0x0f) plen 4 Read Remote Extended Features (0x01|0x001c) status 0x00 ncmd 1 2011-09-29 14:03:11.755067 > HCI Event: Page Scan Repetition Mode Change (0x20) plen 7 bdaddr 00:0B:E4:A6:6C:0D mode 1 2011-09-29 14:03:11.756061 > HCI Event: Max Slots Change (0x1b) plen 3 handle 11 slots 5 2011-09-29 14:03:11.803075 > HCI Event: Read Remote Extended Features (0x23) plen 13 status 0x00 handle 11 page 1 max 1 Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 2011-09-29 14:03:11.803217 < HCI Command: Remote Name Request (0x01|0x0019) plen 10 bdaddr 00:0B:E4:A6:6C:0D mode 2 clkoffset 0x0000 2011-09-29 14:03:11.803232 < ACL data: handle 11 flags 0x00 dlen 10 0000: 06 00 01 00 0a 01 02 00 02 00 .......... 2011-09-29 14:03:11.805141 > HCI Event: Command Status (0x0f) plen 4 Remote Name Request (0x01|0x0019) status 0x00 ncmd 1 2011-09-29 14:03:11.840072 > ACL data: handle 11 flags 0x02 dlen 16 L2CAP(s): Info rsp: type 2 result 0 Extended feature mask 0x0000 2011-09-29 14:03:11.840261 < ACL data: handle 11 flags 0x00 dlen 12 0000: 08 00 01 00 02 02 04 00 01 00 40 00 ..........@. 2011-09-29 14:03:11.849932 > ACL data: handle 11 flags 0x02 dlen 16 L2CAP(s): Connect rsp: dcid 0x0042 scid 0x0040 result 1 status 2 Connection pending - Authorization pending 2011-09-29 14:03:11.852481 > ACL data: handle 11 flags 0x02 dlen 16 L2CAP(s): Connect rsp: dcid 0x0042 scid 0x0040 result 0 status 0 Connection successful 2011-09-29 14:03:11.852645 < ACL data: handle 11 flags 0x00 dlen 12 0000: 08 00 01 00 04 03 04 00 42 00 00 00 ........B... 2011-09-29 14:03:11.856142 > HCI Event: Remote Name Req Complete (0x07) plen 255 status 0x00 bdaddr 00:0B:E4:A6:6C:0D name 'Nokia BH-905i' 2011-09-29 14:03:11.857059 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 2 2011-09-29 14:03:11.887445 > ACL data: handle 11 flags 0x02 dlen 14 L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 0 Success 2011-09-29 14:03:11.888677 > ACL data: handle 11 flags 0x02 dlen 16 L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4 MTU 48 2011-09-29 14:03:11.888916 < ACL data: handle 11 flags 0x00 dlen 18 0000: 0e 00 01 00 05 02 0a 00 42 00 00 00 00 00 01 02 ........B....... 0010: 30 00 0. 2011-09-29 14:03:11.888997 < ACL data: handle 11 flags 0x00 dlen 24 0000: 14 00 42 00 06 00 00 00 0f 35 03 19 11 1e ff ff ..B......5...... 0010: 35 05 0a 00 00 ff ff 00 5....... 2011-09-29 14:03:11.893061 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 2 2011-09-29 14:03:11.918808 > ACL data: handle 11 flags 0x02 dlen 52 L2CAP(d): cid 0x0040 len 48 [psm 0] 0000: 07 00 00 00 2b 00 26 36 00 5c 36 00 59 09 00 00 ....+.&6.\6.Y... 0010: 0a 00 01 00 00 09 00 01 35 06 19 11 1e 19 12 03 ........5....... 0020: 09 00 04 35 0c 35 03 19 01 00 35 05 19 02 00 39 ...5.5....5....9 2011-09-29 14:03:11.918996 < ACL data: handle 11 flags 0x00 dlen 26 0000: 16 00 42 00 06 00 01 00 11 35 03 19 11 1e ff ff ..B......5...... 0010: 35 05 0a 00 00 ff ff 02 00 39 5........9 2011-09-29 14:03:11.923083 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 2 2011-09-29 14:03:11.930055 > ACL data: handle 11 flags 0x02 dlen 52 L2CAP(d): cid 0x0040 len 48 [psm 0] 0000: 07 00 01 00 2b 00 26 00 03 08 01 09 00 06 35 09 ....+.&.......5. 0010: 09 65 6e 09 00 6a 09 01 00 09 00 09 35 08 35 06 .en..j......5.5. 0020: 19 11 1e 09 01 05 09 01 00 25 0f 48 61 02 00 13 .........%.Ha... 2011-09-29 14:03:11.930228 < ACL data: handle 11 flags 0x00 dlen 26 0000: 16 00 42 00 06 00 02 00 11 35 03 19 11 1e ff ff ..B......5...... 0010: 35 05 0a 00 00 ff ff 02 00 13 5......... 2011-09-29 14:03:11.964933 > ACL data: handle 11 flags 0x02 dlen 31 L2CAP(d): cid 0x0040 len 27 [psm 0] 0000: 07 00 02 00 16 00 13 6e 64 73 2d 46 72 65 65 20 .......nds-Free 0010: 75 6e 69 74 09 03 11 09 00 19 00 unit....... 2011-09-29 14:03:11.965287 < HCI Command: Authentication Requested (0x01|0x0011) plen 2 handle 11 2011-09-29 14:03:11.967056 > HCI Event: Command Status (0x0f) plen 4 Authentication Requested (0x01|0x0011) status 0x00 ncmd 1 2011-09-29 14:03:11.968080 > HCI Event: Link Key Request (0x17) plen 6 bdaddr 00:0B:E4:A6:6C:0D 2011-09-29 14:03:11.968322 < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 bdaddr 00:0B:E4:A6:6C:0D key 08AB2E2A1319F534321C46393A25B42D 2011-09-29 14:03:11.979080 > HCI Event: Command Complete (0x0e) plen 10 Link Key Request Reply (0x01|0x000b) ncmd 1 status 0x00 bdaddr 00:0B:E4:A6:6C:0D 2011-09-29 14:03:12.006084 > HCI Event: Auth Complete (0x06) plen 3 status 0x00 handle 11 2011-09-29 14:03:12.006161 < ACL data: handle 11 flags 0x00 dlen 12 0000: 08 00 01 00 02 04 04 00 03 00 41 00 ..........A. 2011-09-29 14:03:12.009052 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 11 packets 2 2011-09-29 14:03:12.015065 > ACL data: handle 11 flags 0x02 dlen 16 L2CAP(s): Connect rsp: dcid 0x0043 scid 0x0041 result 1 status 2 Connection pending - Authorization pending 2011-09-29 14:03:14.167024 > HCI Event: Disconn Complete (0x05) plen 4 status 0x00 handle 11 reason 0x05 Reason: Authentication Failure [-- Attachment #5: v3.1-successful.txt --] [-- Type: text/plain, Size: 30928 bytes --] HCI sniffer - Bluetooth packet analyzer ver 2.0 device: hci0 snap_len: 1028 filter: 0xffffffffffffffff 2011-09-29 13:59:22.971462 > HCI Event: Connect Request (0x04) plen 10 bdaddr 00:0B:E4:A6:6C:0D class 0x240404 type ACL 2011-09-29 13:59:22.971639 < HCI Command: Accept Connection Request (0x01|0x0009) plen 7 bdaddr 00:0B:E4:A6:6C:0D role 0x00 Role: Master 2011-09-29 13:59:22.973362 > HCI Event: Command Status (0x0f) plen 4 Accept Connection Request (0x01|0x0009) status 0x00 ncmd 1 2011-09-29 13:59:23.515454 > HCI Event: Role Change (0x12) plen 8 status 0x00 bdaddr 00:0B:E4:A6:6C:0D role 0x00 Role: Master 2011-09-29 13:59:23.783362 > HCI Event: Connect Complete (0x03) plen 11 status 0x00 handle 12 bdaddr 00:0B:E4:A6:6C:0D type ACL encrypt 0x00 2011-09-29 13:59:23.783681 < HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2 handle 12 2011-09-29 13:59:23.785359 > HCI Event: Command Status (0x0f) plen 4 Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 1 2011-09-29 13:59:23.786352 > HCI Event: Read Remote Supported Features (0x0b) plen 11 status 0x00 handle 12 Features: 0xff 0xfe 0x0f 0xc6 0x9b 0xff 0x59 0x83 2011-09-29 13:59:23.786467 < HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3 handle 12 page 1 2011-09-29 13:59:23.788355 > HCI Event: Command Status (0x0f) plen 4 Read Remote Extended Features (0x01|0x001c) status 0x00 ncmd 1 2011-09-29 13:59:23.853398 > HCI Event: Max Slots Change (0x1b) plen 3 handle 12 slots 5 2011-09-29 13:59:24.192436 > HCI Event: Read Remote Extended Features (0x23) plen 13 status 0x00 handle 12 page 1 max 1 Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 2011-09-29 13:59:24.192834 < HCI Command: Remote Name Request (0x01|0x0019) plen 10 bdaddr 00:0B:E4:A6:6C:0D mode 2 clkoffset 0x0000 2011-09-29 13:59:24.194388 > HCI Event: Command Status (0x0f) plen 4 Remote Name Request (0x01|0x0019) status 0x00 ncmd 1 2011-09-29 13:59:24.261146 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(s): Connect req: psm 1 scid 0x0040 2011-09-29 13:59:24.261453 < ACL data: handle 12 flags 0x00 dlen 16 0000: 0c 00 01 00 03 02 08 00 40 00 40 00 01 00 00 00 ........@.@..... 2011-09-29 13:59:24.261463 < ACL data: handle 12 flags 0x00 dlen 10 0000: 06 00 01 00 0a 01 02 00 02 00 .......... 2011-09-29 13:59:24.345420 > HCI Event: Remote Name Req Complete (0x07) plen 255 status 0x00 bdaddr 00:0B:E4:A6:6C:0D name 'Nokia BH-905i' 2011-09-29 13:59:24.346338 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:24.396251 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Info rsp: type 2 result 0 Extended feature mask 0x0000 2011-09-29 13:59:24.396390 < ACL data: handle 12 flags 0x00 dlen 16 0000: 0c 00 01 00 03 02 08 00 40 00 40 00 00 00 00 00 ........@.@..... 2011-09-29 13:59:24.396406 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 04 02 04 00 40 00 00 00 ........@... 2011-09-29 13:59:24.465349 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:24.531314 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4 MTU 48 2011-09-29 13:59:24.531621 < ACL data: handle 12 flags 0x00 dlen 18 0000: 0e 00 01 00 05 03 0a 00 40 00 00 00 00 00 01 02 ........@....... 0010: 30 00 0. 2011-09-29 13:59:24.532511 > ACL data: handle 12 flags 0x02 dlen 14 L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 0 Success 2011-09-29 13:59:24.668686 > ACL data: handle 12 flags 0x02 dlen 24 L2CAP(d): cid 0x0040 len 20 [psm 0] 0000: 06 00 01 00 0f 35 05 1a 00 00 11 1f 00 26 35 03 .....5.......&5. 0010: 09 00 04 00 .... 2011-09-29 13:59:24.669362 < ACL data: handle 12 flags 0x00 dlen 33 0000: 1d 00 40 00 07 00 01 00 18 00 15 35 13 35 11 09 ..@........5.5.. 0010: 00 04 35 0c 35 03 19 01 00 35 05 19 00 03 08 0d ..5.5....5...... 0020: 00 . 2011-09-29 13:59:24.737436 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:24.804964 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(s): Disconn req: dcid 0x0040 scid 0x0040 2011-09-29 13:59:24.805133 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 07 04 04 00 40 00 40 00 ........@.@. 2011-09-29 13:59:25.009388 > HCI Event: Link Key Request (0x17) plen 6 bdaddr 00:0B:E4:A6:6C:0D 2011-09-29 13:59:25.009956 < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 bdaddr 00:0B:E4:A6:6C:0D key 08AB2E2A1319F534321C46393A25B42D 2011-09-29 13:59:25.018340 > HCI Event: Command Complete (0x0e) plen 10 Link Key Request Reply (0x01|0x000b) ncmd 1 status 0x00 bdaddr 00:0B:E4:A6:6C:0D 2011-09-29 13:59:25.038329 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 1 2011-09-29 13:59:25.493371 > HCI Event: Encrypt Change (0x08) plen 4 status 0x00 handle 12 encrypt 0x01 2011-09-29 13:59:25.494822 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(s): Connect req: psm 3 scid 0x0041 2011-09-29 13:59:25.494924 < ACL data: handle 12 flags 0x00 dlen 16 0000: 0c 00 01 00 03 05 08 00 40 00 41 00 00 00 00 00 ........@.A..... 2011-09-29 13:59:25.494933 < ACL data: handle 12 flags 0x00 dlen 16 0000: 0c 00 01 00 04 03 08 00 41 00 00 00 01 02 f5 03 ........A....... 2011-09-29 13:59:25.565375 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:25.631295 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4 MTU 895 2011-09-29 13:59:25.631486 < ACL data: handle 12 flags 0x00 dlen 18 0000: 0e 00 01 00 05 06 0a 00 41 00 00 00 00 00 01 02 ........A....... 0010: 7f 03 .. 2011-09-29 13:59:25.632494 > ACL data: handle 12 flags 0x02 dlen 18 L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 4 MTU 1013 2011-09-29 13:59:25.768792 > ACL data: handle 12 flags 0x02 dlen 8 L2CAP(d): cid 0x0040 len 4 [psm 0] 0000: 03 3f 01 1c .?.. 2011-09-29 13:59:25.769182 < ACL data: handle 12 flags 0x00 dlen 8 0000: 04 00 41 00 03 73 01 d7 ..A..s.. 2011-09-29 13:59:25.837378 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:25.903662 > ACL data: handle 12 flags 0x02 dlen 18 L2CAP(d): cid 0x0040 len 14 [psm 0] 0000: 03 ef 15 83 11 1a f0 00 00 7e 00 00 00 70 .........~...p 2011-09-29 13:59:25.903961 < ACL data: handle 12 flags 0x00 dlen 18 0000: 0e 00 41 00 01 ef 15 81 11 1a e0 00 00 7e 00 00 ..A..........~.. 0010: 07 aa .. 2011-09-29 13:59:26.038581 > ACL data: handle 12 flags 0x02 dlen 8 L2CAP(d): cid 0x0040 len 4 [psm 0] 0000: 6b 3f 01 e7 k?.. 2011-09-29 13:59:26.038954 < HCI Command: Authentication Requested (0x01|0x0011) plen 2 handle 12 2011-09-29 13:59:26.041418 > HCI Event: Command Status (0x0f) plen 4 Authentication Requested (0x01|0x0011) status 0x00 ncmd 1 2011-09-29 13:59:26.042316 > HCI Event: Link Key Request (0x17) plen 6 bdaddr 00:0B:E4:A6:6C:0D 2011-09-29 13:59:26.042725 < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22 bdaddr 00:0B:E4:A6:6C:0D key 08AB2E2A1319F534321C46393A25B42D 2011-09-29 13:59:26.053328 > HCI Event: Command Complete (0x0e) plen 10 Link Key Request Reply (0x01|0x000b) ncmd 1 status 0x00 bdaddr 00:0B:E4:A6:6C:0D 2011-09-29 13:59:26.163412 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 1 2011-09-29 13:59:26.174328 > HCI Event: Auth Complete (0x06) plen 3 status 0x00 handle 12 2011-09-29 13:59:26.175519 < ACL data: handle 12 flags 0x00 dlen 8 0000: 04 00 41 00 6b 73 01 2c ..A.ks., 2011-09-29 13:59:26.175550 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 41 00 01 ef 09 e3 05 6b 8d aa ..A......k.. 2011-09-29 13:59:26.646333 > HCI Event: Encryption Key Refresh Complete (0x30) plen 3 status 0x00 handle 12 2011-09-29 13:59:26.715408 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:26.782530 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(d): cid 0x0040 len 8 [psm 0] 0000: 03 ef 09 e1 05 6b 8d 70 .....k.p 2011-09-29 13:59:26.783631 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(d): cid 0x0040 len 8 [psm 0] 0000: 03 ef 09 e3 05 6b 0d 70 .....k.p 2011-09-29 13:59:26.783766 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 41 00 01 ef 09 e1 05 6b 0d aa ..A......k.. 2011-09-29 13:59:26.783792 < ACL data: handle 12 flags 0x00 dlen 9 0000: 05 00 41 00 69 ff 01 21 22 ..A.i..!" 2011-09-29 13:59:26.785479 > ACL data: handle 12 flags 0x02 dlen 9 L2CAP(d): cid 0x0040 len 5 [psm 0] 0000: 6b ff 01 0f f8 k.... 2011-09-29 13:59:26.851236 > ACL data: handle 12 flags 0x02 dlen 19 L2CAP(d): cid 0x0040 len 15 [psm 0] 0000: 6b ef 17 41 54 2b 42 52 53 46 3d 32 35 0d e4 k..AT+BRSF=25.. 2011-09-29 13:59:26.851652 < ACL data: handle 12 flags 0x00 dlen 22 0000: 12 00 41 00 69 ef 1d 0d 0a 2b 42 52 53 46 3a 20 ..A.i....+BRSF: 0010: 33 35 32 0d 0a 3e 352..> 2011-09-29 13:59:26.851682 < ACL data: handle 12 flags 0x00 dlen 14 0000: 0a 00 41 00 69 ef 0d 0d 0a 4f 4b 0d 0a 3e ..A.i....OK..> 2011-09-29 13:59:26.854408 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:26.920406 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:27.053798 > ACL data: handle 12 flags 0x02 dlen 19 L2CAP(d): cid 0x0040 len 15 [psm 0] 0000: 6b ff 15 02 41 54 2b 43 49 4e 44 3d 3f 0d f8 k...AT+CIND=?.. 2011-09-29 13:59:27.054372 < ACL data: handle 12 flags 0x00 dlen 134 0000: 82 00 41 00 69 ef fd 0d 0a 2b 43 49 4e 44 3a 20 ..A.i....+CIND: 0010: 28 22 62 61 74 74 63 68 67 22 2c 28 30 2d 35 29 ("battchg",(0-5) 0020: 29 2c 28 22 73 69 67 6e 61 6c 22 2c 28 30 2d 35 ),("signal",(0-5 0030: 29 29 2c 28 22 73 65 72 76 69 63 65 22 2c 28 30 )),("service",(0 0040: 2c 31 29 29 2c 28 22 63 61 6c 6c 22 2c 28 30 2c ,1)),("call",(0, 0050: 31 29 29 2c 28 22 63 61 6c 6c 73 65 74 75 70 22 1)),("callsetup" 0060: 2c 28 30 2d 33 29 29 2c 28 22 63 61 6c 6c 68 65 ,(0-3)),("callhe 0070: 6c 64 22 2c 28 30 2d 32 29 29 2c 28 22 72 6f 61 ld",(0-2)),("roa 0080: 6d 22 2c 28 30 3e m",(0> 2011-09-29 13:59:27.054406 < ACL data: handle 12 flags 0x00 dlen 14 0000: 0a 00 41 00 69 ef 0d 2c 31 29 29 0d 0a 3e ..A.i..,1))..> 2011-09-29 13:59:27.054422 < ACL data: handle 12 flags 0x00 dlen 14 0000: 0a 00 41 00 69 ef 0d 0d 0a 4f 4b 0d 0a 3e ..A.i....OK..> 2011-09-29 13:59:27.124316 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:27.392520 > ACL data: handle 12 flags 0x02 dlen 18 L2CAP(d): cid 0x0040 len 14 [psm 0] 0000: 6b ff 13 03 41 54 2b 43 49 4e 44 3f 0d f8 k...AT+CIND?.. 2011-09-29 13:59:27.393100 < ACL data: handle 12 flags 0x00 dlen 32 0000: 1c 00 41 00 69 ef 31 0d 0a 2b 43 49 4e 44 3a 20 ..A.i.1..+CIND: 0010: 35 2c 35 2c 31 2c 30 2c 30 2c 30 2c 30 0d 0a 3e 5,5,1,0,0,0,0..> 2011-09-29 13:59:27.393167 < ACL data: handle 12 flags 0x00 dlen 14 0000: 0a 00 41 00 69 ef 0d 0d 0a 4f 4b 0d 0a 3e ..A.i....OK..> 2011-09-29 13:59:27.462316 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:27.729928 > ACL data: handle 12 flags 0x02 dlen 28 L2CAP(d): cid 0x0040 len 24 [psm 0] 0000: 6b ff 27 02 41 54 2b 43 4d 45 52 3d 33 2c 20 30 k.'.AT+CMER=3, 0 0010: 2c 20 30 2c 20 31 0d f8 , 0, 1.. 2011-09-29 13:59:27.731058 < ACL data: handle 12 flags 0x00 dlen 14 0000: 0a 00 41 00 69 ef 0d 0d 0a 4f 4b 0d 0a 3e ..A.i....OK..> 2011-09-29 13:59:27.798318 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:28.066289 > ACL data: handle 12 flags 0x02 dlen 19 L2CAP(d): cid 0x0040 len 15 [psm 0] 0000: 6b ff 15 01 41 54 2b 56 47 53 3d 31 30 0d f8 k...AT+VGS=10.. 2011-09-29 13:59:28.067001 < ACL data: handle 12 flags 0x00 dlen 14 0000: 0a 00 41 00 69 ef 0d 0d 0a 4f 4b 0d 0a 3e ..A.i....OK..> 2011-09-29 13:59:28.288307 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 1 2011-09-29 13:59:28.470030 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(s): Connect req: psm 1 scid 0x0042 2011-09-29 13:59:28.470274 < ACL data: handle 12 flags 0x00 dlen 16 0000: 0c 00 01 00 03 07 08 00 41 00 42 00 00 00 00 00 ........A.B..... 2011-09-29 13:59:28.470283 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 04 04 04 00 42 00 00 00 ........B... 2011-09-29 13:59:28.471531 > ACL data: handle 12 flags 0x02 dlen 19 L2CAP(d): cid 0x0040 len 15 [psm 0] 0000: 6b ff 15 01 41 54 2b 56 47 4d 3d 31 30 0d f8 k...AT+VGM=10.. 2011-09-29 13:59:28.472222 < ACL data: handle 12 flags 0x00 dlen 14 0000: 0a 00 41 00 69 ef 0d 0d 0a 4f 4b 0d 0a 3e ..A.i....OK..> 2011-09-29 13:59:28.540407 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:28.607586 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Config req: dcid 0x0041 flags 0x00 clen 4 MTU 48 2011-09-29 13:59:28.607779 < ACL data: handle 12 flags 0x00 dlen 18 0000: 0e 00 01 00 05 08 0a 00 42 00 00 00 00 00 01 02 ........B....... 0010: 30 00 0. 2011-09-29 13:59:28.608697 > ACL data: handle 12 flags 0x02 dlen 14 L2CAP(s): Config rsp: scid 0x0041 flags 0x00 result 0 clen 0 Success 2011-09-29 13:59:28.660505 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 02 05 04 00 19 00 42 00 ..........B. 2011-09-29 13:59:28.667286 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:28.736246 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Connect rsp: dcid 0x0043 scid 0x0042 result 1 status 2 Connection pending - Authorization pending 2011-09-29 13:59:28.737442 > ACL data: handle 12 flags 0x02 dlen 24 L2CAP(d): cid 0x0041 len 20 [psm 0] 0000: 06 00 01 00 0f 35 05 1a 00 00 11 1f 00 26 35 03 .....5.......&5. 0010: 09 00 09 00 .... 2011-09-29 13:59:28.737889 < ACL data: handle 12 flags 0x00 dlen 29 0000: 19 00 42 00 07 00 01 00 14 00 11 35 0f 35 0d 09 ..B........5.5.. 0010: 00 09 35 08 35 06 19 11 1e 09 01 05 00 ..5.5........ 2011-09-29 13:59:28.738773 > ACL data: handle 12 flags 0x02 dlen 30 L2CAP(d): cid 0x0040 len 26 [psm 0] 0000: 6b ff 2b 01 41 54 2b 43 53 52 53 46 3d 31 2c 31 k.+.AT+CSRSF=1,1 0010: 2c 31 2c 31 2c 31 2c 37 0d f8 ,1,1,1,7.. 2011-09-29 13:59:28.739223 < ACL data: handle 12 flags 0x00 dlen 17 0000: 0d 00 41 00 69 ef 13 0d 0a 45 52 52 4f 52 0d 0a ..A.i....ERROR.. 0010: 3e > 2011-09-29 13:59:28.742380 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:28.811276 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(s): Disconn req: dcid 0x0041 scid 0x0042 2011-09-29 13:59:28.811414 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 07 09 04 00 41 00 42 00 ........A.B. 2011-09-29 13:59:28.815306 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:28.883675 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Connect rsp: dcid 0x0043 scid 0x0042 result 0 status 0 Connection successful 2011-09-29 13:59:28.883787 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 04 06 04 00 43 00 00 00 ........C... 2011-09-29 13:59:28.884907 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Config req: dcid 0x0042 flags 0x00 clen 4 MTU 895 2011-09-29 13:59:28.885107 < ACL data: handle 12 flags 0x00 dlen 18 0000: 0e 00 01 00 05 0a 0a 00 43 00 00 00 00 00 01 02 ........C....... 0010: 7f 03 .. 2011-09-29 13:59:28.889299 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:28.956158 > ACL data: handle 12 flags 0x02 dlen 14 L2CAP(s): Config rsp: scid 0x0042 flags 0x00 result 0 clen 0 Success 2011-09-29 13:59:28.956657 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 02 07 04 00 17 00 41 00 ..........A. 2011-09-29 13:59:28.956714 < ACL data: handle 12 flags 0x00 dlen 6 0000: 02 00 43 00 e0 01 ..C... 2011-09-29 13:59:28.962336 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:29.028705 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Connect rsp: dcid 0x0044 scid 0x0041 result 1 status 2 Connection pending - Authorization pending 2011-09-29 13:59:29.098774 > ACL data: handle 12 flags 0x02 dlen 12 L2CAP(d): cid 0x0042 len 8 [psm 0] 0000: e2 01 04 08 08 08 10 08 ........ 2011-09-29 13:59:29.099421 < ACL data: handle 12 flags 0x00 dlen 7 0000: 03 00 43 00 f0 02 04 ..C.... 2011-09-29 13:59:29.114286 > HCI Event: Inquiry Complete (0x01) plen 1 status 0x00 2011-09-29 13:59:29.180018 > ACL data: handle 12 flags 0x02 dlen 20 L2CAP(d): cid 0x0042 len 16 [psm 0] 0000: f2 02 01 00 07 06 00 00 bf ff 02 35 04 02 02 00 ...........5.... 2011-09-29 13:59:29.180625 < ACL data: handle 12 flags 0x00 dlen 7 0000: 03 00 43 00 00 02 08 ..C.... 2011-09-29 13:59:29.184275 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:29.287590 > ACL data: handle 12 flags 0x02 dlen 20 L2CAP(d): cid 0x0042 len 16 [psm 0] 0000: 02 02 01 00 07 06 00 01 3f 07 ff fe 04 02 02 00 ........?....... 2011-09-29 13:59:29.288101 < ACL data: handle 12 flags 0x00 dlen 7 0000: 03 00 43 00 10 02 10 ..C.... 2011-09-29 13:59:29.369900 > ACL data: handle 12 flags 0x02 dlen 22 L2CAP(d): cid 0x0042 len 18 [psm 0] 0000: 12 02 01 00 07 08 00 02 c0 ff fc 90 00 00 04 02 ................ 0010: 02 00 .. 2011-09-29 13:59:29.370894 < ACL data: handle 12 flags 0x00 dlen 18 0000: 0e 00 43 00 20 03 04 04 01 00 07 06 00 00 21 15 ..C. .........!. 0010: 02 35 .5 2011-09-29 13:59:29.374270 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:29.452405 > ACL data: handle 12 flags 0x02 dlen 6 L2CAP(d): cid 0x0042 len 2 [psm 0] 0000: 22 03 ". 2011-09-29 13:59:29.453101 < ACL data: handle 12 flags 0x00 dlen 7 0000: 03 00 43 00 30 06 04 ..C.0.. 2011-09-29 13:59:29.510014 > ACL data: handle 12 flags 0x02 dlen 6 L2CAP(d): cid 0x0042 len 2 [psm 0] 0000: 32 06 2. 2011-09-29 13:59:29.510683 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 02 08 04 00 19 00 43 00 ..........C. 2011-09-29 13:59:29.514283 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:29.542489 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Connect rsp: dcid 0x0045 scid 0x0043 result 1 status 2 Connection pending - Authorization pending 2011-09-29 13:59:29.543659 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Connect rsp: dcid 0x0044 scid 0x0041 result 0 status 0 Connection successful 2011-09-29 13:59:29.543875 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 04 09 04 00 44 00 00 00 ........D... 2011-09-29 13:59:29.544885 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Config req: dcid 0x0041 flags 0x00 clen 4 MTU 895 2011-09-29 13:59:29.545008 < ACL data: handle 12 flags 0x00 dlen 18 0000: 0e 00 01 00 05 0b 0a 00 44 00 00 00 00 00 01 02 ........D....... 0010: 7f 03 .. 2011-09-29 13:59:29.549268 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:29.602516 > ACL data: handle 12 flags 0x02 dlen 14 L2CAP(s): Config rsp: scid 0x0041 flags 0x00 result 0 clen 0 Success 2011-09-29 13:59:30.067464 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Connect rsp: dcid 0x0045 scid 0x0043 result 0 status 0 Connection successful 2011-09-29 13:59:30.067868 < ACL data: handle 12 flags 0x00 dlen 12 0000: 08 00 01 00 04 0a 04 00 45 00 00 00 ........E... 2011-09-29 13:59:30.068804 > ACL data: handle 12 flags 0x02 dlen 16 L2CAP(s): Config req: dcid 0x0043 flags 0x00 clen 4 MTU 895 2011-09-29 13:59:30.068992 < ACL data: handle 12 flags 0x00 dlen 18 0000: 0e 00 01 00 05 0c 0a 00 45 00 00 00 00 00 01 02 ........E....... 0010: 7f 03 .. 2011-09-29 13:59:30.073327 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:30.112480 > ACL data: handle 12 flags 0x02 dlen 14 L2CAP(s): Config rsp: scid 0x0043 flags 0x00 result 0 clen 0 Success 2011-09-29 13:59:30.139095 < ACL data: handle 12 flags 0x00 dlen 7 0000: 03 00 43 00 40 07 04 ..C.@.. 2011-09-29 13:59:30.218650 > ACL data: handle 12 flags 0x02 dlen 6 L2CAP(d): cid 0x0042 len 2 [psm 0] 0000: 42 07 B. 2011-09-29 13:59:30.220117 < ACL data: handle 12 flags 0x00 dlen 850 0000: 4e 03 45 00 80 01 00 00 00 00 00 00 00 00 00 01 N.E............. 0010: 07 9c bd 35 7d 00 00 00 00 00 00 00 00 00 77 76 ...5}.........wv 0020: db 6e ed b6 db bb b6 db 77 6d b6 dd dd b6 db bb .n......wm...... 0030: 6d b6 ee ed b6 dd db 6d b7 77 6d b6 ee db 6d bb m......m.wm...m. 0040: bb 6d b7 76 db 6d dd db 6d bb b6 db 6e ee db 6d .m.v.m..m...n..m 0050: dd b6 db 77 76 db 6e ed b6 db bb b6 db 77 6d b6 ...wv.n......wm. 0060: dd dd b6 db bb 6d b6 ee ed b6 dd db 6d b7 77 6d .....m......m.wm 0070: b6 ee db 6d bb bb 6d b7 76 db 6d dd db 6d bb b6 ...m..m.v.m..m.. 0080: db 6e ee db 6d dd b6 db 9c bd 35 7d 00 00 00 00 .n..m.....5}.... 0090: 00 00 00 00 00 77 76 db 6e ed b6 db bb b6 db 77 .....wv.n......w 00a0: 6d b6 dd dd b6 db bb 6d b6 ee ed b6 dd db 6d b7 m......m......m. 00b0: 77 6d b6 ee db 6d bb bb 6d b7 76 db 6d dd db 6d wm...m..m.v.m..m 00c0: bb b6 db 6e ee db 6d dd b6 db 77 76 db 6e ed b6 ...n..m...wv.n.. 00d0: db bb b6 db 77 6d b6 dd dd b6 db bb 6d b6 ee ed ....wm......m... 00e0: b6 dd db 6d b7 77 6d b6 ee db 6d bb bb 6d b7 76 ...m.wm...m..m.v 00f0: db 6d dd db 6d bb b6 db 6e ee db 6d dd b6 db 9c .m..m...n..m.... 0100: bd 35 7d 00 00 00 00 00 00 00 00 00 77 76 db 6e .5}.........wv.n 0110: ed b6 db bb b6 db 77 6d b6 dd dd b6 db bb 6d b6 ......wm......m. 0120: ee ed b6 dd db 6d b7 77 6d b6 ee db 6d bb bb 6d .....m.wm...m..m 0130: b7 76 db 6d dd db 6d bb b6 db 6e ee db 6d dd b6 .v.m..m...n..m.. 0140: db 77 76 db 6e ed b6 db bb b6 db 77 6d b6 dd dd .wv.n......wm... 0150: b6 db bb 6d b6 ee ed b6 dd db 6d b7 77 6d b6 ee ...m......m.wm.. 0160: db 6d bb bb 6d b7 76 db 6d dd db 6d bb b6 db 6e .m..m.v.m..m...n 0170: ee db 6d dd b6 db 9c bd 35 7d 00 00 00 00 00 00 ..m.....5}...... 0180: 00 00 00 77 76 db 6e ed b6 db bb b6 db 77 6d b6 ...wv.n......wm. 0190: dd dd b6 db bb 6d b6 ee ed b6 dd db 6d b7 77 6d .....m......m.wm 01a0: b6 ee db 6d bb bb 6d b7 76 db 6d dd db 6d bb b6 ...m..m.v.m..m.. 01b0: db 6e ee db 6d dd b6 db 77 76 db 6e ed b6 db bb .n..m...wv.n.... 01c0: b6 db 77 6d b6 dd dd b6 db bb 6d b6 ee ed b6 dd ..wm......m..... 01d0: db 6d b7 77 6d b6 ee db 6d bb bb 6d b7 76 db 6d .m.wm...m..m.v.m 01e0: dd db 6d bb b6 db 6e ee db 6d dd b6 db 9c bd 35 ..m...n..m.....5 01f0: 7d 00 00 00 00 00 00 00 00 00 77 76 db 6e ed b6 }.........wv.n.. 0200: db bb b6 db 77 6d b6 dd dd b6 db bb 6d b6 ee ed ....wm......m... 0210: b6 dd db 6d b7 77 6d b6 ee db 6d bb bb 6d b7 76 ...m.wm...m..m.v 0220: db 6d dd db 6d bb b6 db 6e ee db 6d dd b6 db 77 .m..m...n..m...w 0230: 76 db 6e ed b6 db bb b6 db 77 6d b6 dd dd b6 db v.n......wm..... 0240: bb 6d b6 ee ed b6 dd db 6d b7 77 6d b6 ee db 6d .m......m.wm...m 0250: bb bb 6d b7 76 db 6d dd db 6d bb b6 db 6e ee db ..m.v.m..m...n.. 0260: 6d dd b6 db 9c bd 35 7d 00 00 00 00 00 00 00 00 m.....5}........ 0270: 00 77 76 db 6e ed b6 db bb b6 db 77 6d b6 dd dd .wv.n......wm... 0280: b6 db bb 6d b6 ee ed b6 dd db 6d b7 77 6d b6 ee ...m......m.wm.. 0290: db 6d bb bb 6d b7 76 db 6d dd db 6d bb b6 db 6e .m..m.v.m..m...n 02a0: ee db 6d dd b6 db 77 76 db 6e ed b6 db bb b6 db ..m...wv.n...... 02b0: 77 6d b6 dd dd b6 db bb 6d b6 ee ed b6 dd db 6d wm......m......m 02c0: b7 77 6d b6 ee db 6d bb bb 6d b7 76 db 6d dd db .wm...m..m.v.m.. 02d0: 6d bb b6 db 6e ee db 6d dd b6 db 9c bd 35 7d 00 m...n..m.....5}. 02e0: 00 00 00 00 00 00 00 00 77 76 db 6e ed b6 db bb ........wv.n.... 02f0: b6 db 77 6d b6 dd dd b6 db bb 6d b6 ee ed b6 dd ..wm......m..... 0300: db 6d b7 77 6d b6 ee db 6d bb bb 6d b7 76 db 6d .m.wm...m..m.v.m 0310: dd db 6d bb b6 db 6e ee db 6d dd b6 db 77 76 db ..m...n..m...wv. 0320: 6e ed b6 db bb b6 db 77 6d b6 dd dd b6 db bb 6d n......wm......m 0330: b6 ee ed b6 dd db 6d b7 77 6d b6 ee db 6d bb bb ......m.wm...m.. 0340: 6d b7 76 db 6d dd db 6d bb b6 db 6e ee db 6d dd m.v.m..m...n..m. 0350: b6 db .. 2011-09-29 13:59:30.227250 > HCI Event: Number of Completed Packets (0x13) plen 5 handle 12 packets 2 2011-09-29 13:59:30.240384 < ACL data: handle 12 flags 0x00 dlen 850 0000: 4e 03 45 00 80 01 00 01 00 00 03 80 00 00 00 01 N.E............. 0010: 07 9c bd 35 7d 00 00 00 00 00 00 00 00 00 77 76 ...5}.........wv 0020: db 6e ed b6 db bb b6 db 77 6d b6 dd dd b6 db bb .n......wm...... 0030: 6d b6 ee ed b6 dd db 6d b7 77 6d b6 ee db 6d bb m......m.wm...m. 0040: bb 6d b7 76 db 6d dd db 6d bb b6 db 6e ee db 6d .m.v.m..m...n..m 0050: dd b6 db 77 76 db 6e ed b6 db bb b6 db 77 6d b6 ...wv.n......wm. 0060: dd dd b6 db bb 6d b6 ee ed b6 dd db 6d b7 77 6d .....m......m.wm 0070: b6 ee db 6d bb bb 6d b7 76 db 6d dd db 6d bb b6 ...m..m.v.m..m.. 0080: db 6e ee db 6d dd b6 db 9c bd 35 7d 00 00 00 00 .n..m.....5}.... 0090: 00 00 00 00 00 77 76 db 6e ed b6 db bb b6 db 77 .....wv.n......w 00a0: 6d b6 dd dd b6 db bb 6d b6 ee ed b6 dd db 6d b7 m......m......m. 00b0: 77 6d b6 ee db 6d bb bb 6d b7 76 db 6d dd db 6d wm...m..m.v.m..m 00c0: bb b6 db 6e ee db 6d dd b6 db 77 76 db 6e ed b6 ...n..m...wv.n.. 00d0: db bb b6 db 77 6d b6 dd dd b6 db bb 6d b6 ee ed ....wm......m... 00e0: b6 dd db 6d b7 77 6d b6 ee db 6d bb bb 6d b7 76 ...m.wm...m..m.v 00f0: db 6d dd db 6d bb b6 db 6e ee db 6d dd b6 db 9c .m..m...n..m.... 0100: bd 35 7d 00 00 00 00 00 00 00 00 00 77 76 db 6e .5}.........wv.n 0110: ed b6 db bb b6 db 77 6d b6 dd dd b6 db bb 6d b6 ......wm......m. 0120: ee ed b6 dd db 6d b7 77 6d b6 ee db 6d bb bb 6d .....m.wm...m..m 0130: b7 76 db 6d dd db 6d bb b6 db 6e ee db 6d dd b6 .v.m..m...n..m.. 0140: db 77 76 db 6e ed b6 db bb b6 db 77 6d b6 dd dd .wv.n......wm... 0150: b6 db bb 6d b6 ee ed b6 dd db 6d b7 77 6d b6 ee ...m......m.wm.. 0160: db 6d bb bb 6d b7 76 db 6d dd db 6d bb b6 db 6e .m..m.v.m..m...n 0170: ee db 6d dd b6 db 9c bd 35 7d 00 00 00 00 00 00 ..m.....5}...... 0180: 00 00 00 77 76 db 6e ed b6 db bb b6 db 77 6d b6 ...wv.n......wm. 0190: dd dd b6 db bb 6d b6 ee ed b6 dd db 6d b7 77 6d .....m......m.wm 01a0: b6 ee db 6d bb bb 6d b7 76 db 6d dd db 6d bb b6 ...m..m.v.m..m.. 01b0: db 6e ee db 6d dd b6 db 77 76 db 6e ed b6 db bb .n..m...wv.n.... 01c0: b6 db 77 6d b6 dd dd b6 db bb 6d b6 ee ed b6 dd ..wm......m..... 01d0: db 6d b7 77 6d b6 ee db 6d bb bb 6d b7 76 db 6d .m.wm...m..m.v.m 01e0: dd db 6d bb b6 db 6e ee db 6d dd b6 db 9c bd 35 ..m...n..m.....5 01f0: 7d 00 00 00 00 00 00 00 00 00 77 76 db 6e ed b6 }.........wv.n.. 0200: db bb b6 db 77 6d b6 dd dd b6 db bb 6d b6 ee ed ....wm......m... 0210: b6 dd db 6d b7 77 6d b6 ee db 6d bb bb 6d b7 76 ...m.wm...m..m.v 0220: db 6d dd db 6d bb b6 db 6e ee db 6d dd b6 db 77 .m..m...n..m...w 0230: 76 db 6e ed b6 db bb b6 db 77 6d b6 dd dd b6 db v.n......wm..... 0240: bb 6d b6 ee ed b6 dd db 6d b7 77 6d b6 ee db 6d .m......m.wm...m 0250: bb bb 6d b7 76 db 6d dd db 6d bb b6 db 6e ee db ..m.v.m..m...n.. 0260: 6d dd b6 db 9c bd 35 7d 00 00 00 00 00 00 00 00 m.....5}........ 0270: 00 77 76 db 6e ed b6 db bb b6 db 77 6d b6 dd dd .wv.n......wm... 0280: b6 db bb 6d b6 ee ed b6 dd db 6d b7 77 6d b6 ee ...m......m.wm.. 0290: db 6d bb bb 6d b7 76 db 6d dd db 6d bb b6 db 6e .m..m.v.m..m...n 02a0: ee db 6d dd b6 db 77 76 db 6e ed b6 db bb b6 db ..m...wv.n...... 02b0: 77 6d b6 dd dd b6 db bb 6d b6 ee ed b6 dd db 6d wm......m......m 02c0: b7 77 6d b6 ee db 6d bb bb 6d b7 76 db 6d dd db .wm...m..m.v.m.. 02d0: 6d bb b6 db 6e ee db 6d dd b6 db 9c bd 35 7d 00 m...n..m.....5}. 02e0: 00 00 00 00 00 00 00 00 77 76 db 6e ed b6 db bb ........wv.n.... 02f0: b6 db 77 6d b6 dd dd b6 db bb 6d b6 ee ed b6 dd ..wm......m..... 0300: db 6d b7 77 6d b6 ee db 6d bb bb 6d b7 76 db 6d .m.wm...m..m.v.m 0310: dd db 6d bb b6 db 6e ee db 6d dd b6 db 77 76 db ..m...n..m...wv. 0320: 6e ed b6 db bb b6 db 77 6d b6 dd dd b6 db bb 6d n......wm......m 0330: b6 ee ed b6 dd db 6d b7 77 6d b6 ee db 6d bb bb ......m.wm...m.. 0340: 6d b7 76 db 6d dd db 6d bb b6 db 6e ee db 6d dd m.v.m..m...n..m. 0350: b6 db .. [...] ^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2011-09-30 4:52 UTC | newest] Thread overview: 7+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2011-09-13 1:33 Bluetooth regression with headphones Jeremy Fitzhardinge 2011-09-16 22:33 ` Jeremy Fitzhardinge 2011-09-16 22:38 ` Jeremy Fitzhardinge 2011-09-27 18:03 ` Jeremy Fitzhardinge 2011-09-29 17:47 ` Jeremy Fitzhardinge 2011-09-29 20:01 ` Gustavo Padovan 2011-09-30 4:52 ` Jeremy Fitzhardinge
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).