All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH bluetooth-next] Fixes kernel panic in incomming l2cap connections with defer_setup
@ 2011-07-13 11:02 ilia.kolominsky
  2011-07-13 18:31 ` Gustavo Padovan
  0 siblings, 1 reply; 6+ messages in thread
From: ilia.kolominsky @ 2011-07-13 11:02 UTC (permalink / raw)
  To: linux-bluetooth; +Cc: Ilia Kolomisnky

From: Ilia Kolomisnky <iliak@ti.com>

Another fix considering incomming l2cap connections with
defer_setup enabled. In situations when incomming connection is
extracted with l2cap_sock_accept, it's bt_sock info will have
'parent' member zerroed, but 'parent' may be used unconditionally
in l2cap_conn_start() and l2cap_security_cfm() when defer_setup
is enabled.

Signed-off-by: Ilia Kolomisnky <iliak@ti.com>
---
 net/bluetooth/l2cap_core.c |    6 ++++--
 1 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/net/bluetooth/l2cap_core.c b/net/bluetooth/l2cap_core.c
index f7f8e2c..2ffa09b 100644
--- a/net/bluetooth/l2cap_core.c
+++ b/net/bluetooth/l2cap_core.c
@@ -763,7 +763,8 @@ static void l2cap_conn_start(struct l2cap_conn *conn)
 					struct sock *parent = bt_sk(sk)->parent;
 					rsp.result = cpu_to_le16(L2CAP_CR_PEND);
 					rsp.status = cpu_to_le16(L2CAP_CS_AUTHOR_PEND);
-					parent->sk_data_ready(parent, 0);
+					if (parent)
+						parent->sk_data_ready(parent, 0);
 
 				} else {
 					l2cap_state_change(chan, BT_CONFIG);
@@ -4150,7 +4151,8 @@ static int l2cap_security_cfm(struct hci_conn *hcon, u8 status, u8 encrypt)
 					struct sock *parent = bt_sk(sk)->parent;
 					res = L2CAP_CR_PEND;
 					stat = L2CAP_CS_AUTHOR_PEND;
-					parent->sk_data_ready(parent, 0);
+					if (parent)
+						parent->sk_data_ready(parent, 0);
 				} else {
 					l2cap_state_change(chan, BT_CONFIG);
 					res = L2CAP_CR_SUCCESS;
-- 
1.7.1


^ permalink raw reply related	[flat|nested] 6+ messages in thread

* Re: [PATCH bluetooth-next] Fixes kernel panic in incomming l2cap connections with defer_setup
  2011-07-13 11:02 [PATCH bluetooth-next] Fixes kernel panic in incomming l2cap connections with defer_setup ilia.kolominsky
@ 2011-07-13 18:31 ` Gustavo Padovan
  2011-07-14  9:01   ` Ilia, Kolominsky
  0 siblings, 1 reply; 6+ messages in thread
From: Gustavo Padovan @ 2011-07-13 18:31 UTC (permalink / raw)
  To: ilia.kolominsky; +Cc: linux-bluetooth, Ilia Kolomisnky

Hi Ilia,

* ilia.kolominsky@gmail.com <ilia.kolominsky@gmail.com> [2011-07-13 14:02:26 +0300]:

> From: Ilia Kolomisnky <iliak@ti.com>
> 
> Another fix considering incomming l2cap connections with
> defer_setup enabled. In situations when incomming connection is
> extracted with l2cap_sock_accept, it's bt_sock info will have
> 'parent' member zerroed, but 'parent' may be used unconditionally
> in l2cap_conn_start() and l2cap_security_cfm() when defer_setup
> is enabled.

I want to see a hcidump and kernel log with dynamic debug enabled first.
The fix might be somewhere else and not here.

	Gustavo

^ permalink raw reply	[flat|nested] 6+ messages in thread

* RE: [PATCH bluetooth-next] Fixes kernel panic in incomming l2cap connections with defer_setup
  2011-07-13 18:31 ` Gustavo Padovan
@ 2011-07-14  9:01   ` Ilia, Kolominsky
  2011-08-07 15:34     ` Question regarding SET_CONFIGURATION avdtp command handling Ilia, Kolominsky
  0 siblings, 1 reply; 6+ messages in thread
From: Ilia, Kolominsky @ 2011-07-14  9:01 UTC (permalink / raw)
  To: Gustavo Padovan; +Cc: linux-bluetooth

> -----Original Message-----
> From: Gustavo F. Padovan [mailto:pao@profusion.mobi] On Behalf Of
> Gustavo Padovan
> Sent: Wednesday, July 13, 2011 9:32 PM
> To: ilia.kolominsky@gmail.com
> Cc: linux-bluetooth@vger.kernel.org; Ilia, Kolominsky
> Subject: Re: [PATCH bluetooth-next] Fixes kernel panic in incomming
> l2cap connections with defer_setup
> 
> Hi Ilia,
> 
> * ilia.kolominsky@gmail.com <ilia.kolominsky@gmail.com> [2011-07-13
> 14:02:26 +0300]:
> 
> > From: Ilia Kolomisnky <iliak@ti.com>
> >
> > Another fix considering incomming l2cap connections with
> > defer_setup enabled. In situations when incomming connection is
> > extracted with l2cap_sock_accept, it's bt_sock info will have
> > 'parent' member zerroed, but 'parent' may be used unconditionally
> > in l2cap_conn_start() and l2cap_security_cfm() when defer_setup
> > is enabled.
> 
> I want to see a hcidump and kernel log with dynamic debug enabled
> first.
> The fix might be somewhere else and not here.
> 
> 	Gustavo

There can be a situation that seems wrong - double signaling
( call to parent->sk_data_ready() ) when defer_setup is enabled
Due to the following path in l2cap_conn_req():

if (conn->info_state & L2CAP_INFO_FEAT_MASK_REQ_DONE) {
	if (l2cap_check_security(chan)) {
		if (bt_sk(sk)->defer_setup) {
			l2cap_state_change(chan, BT_CONNECT2);
			result = L2CAP_CR_PEND;
			status = L2CAP_CS_AUTHOR_PEND;
			parent->sk_data_ready(parent, 0);

And so, the connection can be extracted and parent nulled,
Which latter will lead to kernel panic
in l2cap_security_cfm(). 

Do I get it right that the no double signaling should
happen?

Hcidump ( on target device ):
> HCI Event: Connect Request (0x04) plen 10
    bdaddr 00:16:94:09:D5:D1 class 0x240404 type ACL
< HCI Command: Accept Connection Request (0x01|0x0009) plen 7
    bdaddr 00:16:94:09:D5:D1 role 0x00
    Role: Master
> HCI Event: Command Status (0x0f) plen 4
    Accept Connection Request (0x01|0x0009) status 0x00 ncmd 1
> HCI Event: Role Change (0x12) plen 8
    status 0x00 bdaddr 00:16:94:09:D5:D1 role 0x00
    Role: Master
> HCI Event: Connect Complete (0x03) plen 11
    status 0x00 handle 1 bdaddr 00:16:94:09:D5:D1 type ACL encrypt 0x00
> HCI Event: Page Scan Repetition Mode Change (0x20) plen 7
    bdaddr 00:16:94:09:D5:D1 mode 1
< HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2
    handle 1
> HCI Event: Command Status (0x0f) plen 4
    Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 1
> HCI Event: Max Slots Change (0x1b) plen 3
    handle 1 slots 5
> HCI Event: Read Remote Supported Features (0x0b) plen 11
    status 0x00 handle 1
    Features: 0xff 0xfe 0x0f 0xc6 0x9b 0xbf 0x59 0x83
< HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3
    handle 1 page 1
> HCI Event: Command Status (0x0f) plen 4
    Read Remote Extended Features (0x01|0x001c) status 0x00 ncmd 1
> HCI Event: Read Remote Extended Features (0x23) plen 13
    status 0x00 handle 1 page 1 max 1
    Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
< HCI Command: Remote Name Request (0x01|0x0019) plen 10
    bdaddr 00:16:94:09:D5:D1 mode 2 clkoffset 0x0000
> HCI Event: Command Status (0x0f) plen 4
    Remote Name Request (0x01|0x0019) status 0x00 ncmd 1
> HCI Event: Remote Name Req Complete (0x07) plen 255
    status 0x00 bdaddr 00:16:94:09:D5:D1 name 'Sennheiser MM450'
> HCI Event: Link Key Request (0x17) plen 6
    bdaddr 00:16:94:09:D5:D1
< HCI Command: Link Key Request Reply (0x01|0x000b) plen 22
    bdaddr 00:16:94:09:D5:D1 key 2076411316B32F655BD4D52C555CBEEA
> HCI Event: Command Complete (0x0e) plen 10
    Link Key Request Reply (0x01|0x000b) ncmd 1
    status 0x00 bdaddr 00:16:94:09:D5:D1
> HCI Event: Encrypt Change (0x08) plen 4
    status 0x00 handle 1 encrypt 0x01
> ACL data: handle 1 flags 0x02 dlen 12
    L2CAP(s): Connect req: psm 25 scid 0x0045
< ACL data: handle 1 flags 0x00 dlen 16
    L2CAP(s): Connect rsp: dcid 0x0040 scid 0x0045 result 1 status 0
      Connection pending - No futher information available
< ACL data: handle 1 flags 0x00 dlen 10
    L2CAP(s): Info req: type 2
> HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 2
> ACL data: handle 1 flags 0x02 dlen 16
    L2CAP(s): Info rsp: type 2 result 0
      Extended feature mask 0x0000
< HCI Command: Authentication Requested (0x01|0x0011) plen 2
    handle 1
< ACL data: handle 1 flags 0x00 dlen 16
    L2CAP(s): Connect rsp: dcid 0x0040 scid 0x0045 result 1 status 1
      Connection pending - Authentication pending
> HCI Event: Command Status (0x0f) plen 4
    Authentication Requested (0x01|0x0011) status 0x00 ncmd 1
> HCI Event: Link Key Request (0x17) plen 6
    bdaddr 00:16:94:09:D5:D1
> HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 1
< ACL data: handle 1 flags 0x00 dlen 16
    L2CAP(s): Connect rsp: dcid 0x0040 scid 0x0045 result 0 status 0
      Connection successful
< ACL data: handle 1 flags 0x00 dlen 12
    L2CAP(s): Config req: dcid 0x0045 flags 0x00 clen 0
> HCI Event: Number of Completed Packets (0x13) plen 5
    handle 1 packets 2
< HCI Command: Link Key Request Reply (0x01|0x000b) plen 22
    bdaddr 00:16:94:09:D5:D1 key 2076411316B32F655BD4D52C555CBEEA
> HCI Event: Command Complete (0x0e) plen 10
    Link Key Request Reply (0x01|0x000b) ncmd 1
    status 0x00 bdaddr 00:16:94:09:D5:D1

--> Here comes  HCI Event: Auth Complete
Which triggers l2cap_seciruty_cfm which panics:

Unable to handle kernel NULL pointer dereference at virtual address 0000016c
pgd = c0004000
[0000016c] *pgd=00000000
Internal error: Oops: 17 [#1] PREEMPT SMP
last sysfs file: /sys/devices/system/cpu/cpu0/cpufreq/stats/time_in_state
Modules linked in: btwilink hidp rfcomm bluetooth gps_drv(C) fm_drv(C) st_drv
CPU: 0    Tainted: G         C   (2.6.35.7-00182-ga8b0d4f #1)
PC is at l2cap_security_cfm+0x1f0/0x2ac [bluetooth]
LR is at _raw_spin_lock+0x10/0x14
pc : [<bf02d79c>]    lr : [<c04ab96c>]    psr: 20000013
sp : efc47d90  ip : efc47d80  fp : efc47de4
r10: 00000001  r9 : ee95c400  r8 : eebc5824
r7 : ee95c430  r6 : 00000000  r5 : eebc5780  r4 : ee95c800
r3 : 0000001e  r2 : 00000040  r1 : 00000000  r0 : 00000000
Flags: nzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment kernel
Control: 10c53c7d  Table: aec0804a  DAC: 00000015

Backtrace:
[<bf02d5ac>] (l2cap_security_cfm+0x0/0x2ac [bluetooth]) from [<bf01f01c>] (hci_event_packet+0xc2c/0x4aa4 [bluetooth])
[<bf01e3f0>] (hci_event_packet+0x0/0x4aa4 [bluetooth]) from [<bf01a844>] (hci_rx_task+0xcc/0x27c [bluetooth])
[<bf01a778>] (hci_rx_task+0x0/0x27c [bluetooth]) from [<c008eee4>] (tasklet_action+0xa0/0x15c)
[<c008ee44>] (tasklet_action+0x0/0x15c) from [<c008f38c>] (__do_softirq+0x98/0x130)
 r7:00000101 r6:00000018 r5:00000001 r4:efc46000
[<c008f2f4>] (__do_softirq+0x0/0x130) from [<c008f524>] (do_softirq+0x4c/0x58)
[<c008f4d8>] (do_softirq+0x0/0x58) from [<c008f5e0>] (run_ksoftirqd+0xb0/0x1b4)
 r4:efc46000 r3:00000001
[<c008f530>] (run_ksoftirqd+0x0/0x1b4) from [<c009f2a8>] (kthread+0x84/0x8c)
 r7:00000000 r6:c008f530 r5:efc47fc4 r4:efc41f08
[<c009f224>] (kthread+0x0/0x8c) from [<c008cc84>] (do_exit+0x0/0x5f0)
 r7:00000013 r6:c008cc84 r5:c009f224 r4:efc41f08
Code: e3530000 0a000006 e5990194 e1a01006 (e590316c)
---[ end trace ddf7b97fcde50022 ]---
Kernel panic - not syncing: Fatal exception in interrupt


Regarding the dynamic debugging - that info do you need?
Is it BT_DBG() outputs?

Regards,
Ilia Kolominsky

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Question regarding SET_CONFIGURATION avdtp command handling
  2011-07-14  9:01   ` Ilia, Kolominsky
@ 2011-08-07 15:34     ` Ilia, Kolominsky
  2011-08-08 20:41       ` Peter Hurley
  2011-08-09 12:27       ` Luiz Augusto von Dentz
  0 siblings, 2 replies; 6+ messages in thread
From: Ilia, Kolominsky @ 2011-08-07 15:34 UTC (permalink / raw)
  To: linux-bluetooth

Hello!
Can anybody help me to understand the process of handling avdtp
SET_CONFIGURATION command in scenario when a2dp headset initializes
connection to linux machine? I see that the headset sends
SET_CONFIGURATION avdtp command (with appropriate SBC params),
but i cant find out how this ultimately translates to actual
configuration of a player (totem in my case).

What layers are involved in general?

I see that handling of the command follows the following path (approx.):
avdtp.c::sbc_setconf_ind()
	a2dp.c::auto_config()
		avdtp.c::avdtp_sep_set_state()
			a2dp.c::stream_state_changed()
			sink.c::stream_state_changed()
At no stage I am able to spot the actual configuration of the sbc...
(there should be probably some sort of d-bus messages, but, again,
I don’t see that neither SelectConfiguration nor SetConfiguration
from the media-api are used).

In addition, there is BT_SET_CONFIGURATION command that is handled
in unix.c (after SET_CONFIGURATION is handled); how does it fits
in the configuration picture?

Any info (or reference where it can be found) will be much
appreciated.

Thanks and regards.
	


Ilia Kolominsky
iliak@ti.com
Direct:  +972(9)7906231
Mobile: +972(54)909009

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: Question regarding SET_CONFIGURATION avdtp command handling
  2011-08-07 15:34     ` Question regarding SET_CONFIGURATION avdtp command handling Ilia, Kolominsky
@ 2011-08-08 20:41       ` Peter Hurley
  2011-08-09 12:27       ` Luiz Augusto von Dentz
  1 sibling, 0 replies; 6+ messages in thread
From: Peter Hurley @ 2011-08-08 20:41 UTC (permalink / raw)
  To: Ilia, Kolominsky; +Cc: linux-bluetooth

[-- Attachment #1: Type: text/plain, Size: 2148 bytes --]

On Sun, 2011-08-07 at 11:34 -0400, Ilia, Kolominsky wrote:
> Hello!
> Can anybody help me to understand the process of handling avdtp
> SET_CONFIGURATION command in scenario when a2dp headset initializes
> connection to linux machine? I see that the headset sends
> SET_CONFIGURATION avdtp command (with appropriate SBC params),
> but i cant find out how this ultimately translates to actual
> configuration of a player (totem in my case).
> 
> What layers are involved in general?
> 
> I see that handling of the command follows the following path (approx.):
> avdtp.c::sbc_setconf_ind()
> 	a2dp.c::auto_config()
> 		avdtp.c::avdtp_sep_set_state()
> 			a2dp.c::stream_state_changed()
> 			sink.c::stream_state_changed()
> At no stage I am able to spot the actual configuration of the sbc...
> (there should be probably some sort of d-bus messages, but, again,
> I don’t see that neither SelectConfiguration nor SetConfiguration
> from the media-api are used).
> 
> In addition, there is BT_SET_CONFIGURATION command that is handled
> in unix.c (after SET_CONFIGURATION is handled); how does it fits
> in the configuration picture?
> 
> Any info (or reference where it can be found) will be much
> appreciated.
> 
> Thanks and regards.

Hi Ilia,

I have no idea how totem interfaces to Bluez but I've attached a syslog
of a bt headset a2dp connect to PulseAudio (with debug output enabled
for both bluetoothd and pulseaudio).

As you can ascertain from the log, one of the subtleties of SEP handling
is that a previously established SEP configuration (selected by the
headset) is "magically found" much later by the client of the Audio API.
Look at the section of the log that starts with line 86,
  module-bluetooth-device.c: Connected to the bluetooth audio service
then further down @ line 124
  audio/a2dp.c:a2dp_config() a2dp_config: selected SEP 0x7fb87a885780

This is where the bluez a2dp code matches the client
BT_SET_CONFIGURATION request with the existing SEP.

Of course, this isn't the only establishment sequence but I think it
will help you get started.

Regards,
Peter Hurley

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: hs_connect.log --]
[-- Type: text/x-log; name="hs_connect.log", Size: 23394 bytes --]

Aug  8 16:16:59 THOR bluetoothd[1254]: plugins/hciops.c:link_key_request() hci0 dba 00:0D:FD:1E:99:30
Aug  8 16:16:59 THOR bluetoothd[1254]: plugins/hciops.c:get_auth_info() hci0 dba 00:0D:FD:1E:99:30
Aug  8 16:16:59 THOR bluetoothd[1254]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04
Aug  8 16:16:59 THOR bluetoothd[1254]: plugins/hciops.c:link_key_request() Matching key found
Aug  8 16:16:59 THOR bluetoothd[1254]: plugins/hciops.c:link_key_request() link key type 0x00
Aug  8 16:16:59 THOR bluetoothd[1254]: plugins/hciops.c:conn_complete() status 0x00
Aug  8 16:16:59 THOR bluetoothd[1254]: src/adapter.c:adapter_get_device() 00:0D:FD:1E:99:30
Aug  8 16:16:59 THOR bluetoothd[1254]: plugins/hciops.c:bonding_complete() status 0x00
Aug  8 16:16:59 THOR bluetoothd[1254]: src/event.c:btd_event_bonding_complete() status 0x00
Aug  8 16:16:59 THOR bluetoothd[1254]: src/adapter.c:adapter_get_device() 00:0D:FD:1E:99:30
Aug  8 16:16:59 THOR bluetoothd[1254]: src/device.c:device_bonding_complete() bonding (nil) status 0x00
Aug  8 16:16:59 THOR bluetoothd[1254]: plugins/hciops.c:remote_features_information() hci0 status 0
Aug  8 16:16:59 THOR pulseaudio[1762]: bluetooth-util.c: dbus: interface=org.bluez.Device, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:16:59 THOR pulseaudio[1762]: module-console-kit.c: dbus: interface=org.bluez.Device, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:16:59 THOR bluetoothd[1254]: plugins/hciops.c:remote_name_information() hci0 status 0
Aug  8 16:17:00 THOR bluetoothd[1254]: plugins/hciops.c:link_key_request() hci0 dba 00:0D:FD:1E:99:30
Aug  8 16:17:00 THOR bluetoothd[1254]: plugins/hciops.c:get_auth_info() hci0 dba 00:0D:FD:1E:99:30
Aug  8 16:17:00 THOR bluetoothd[1254]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04
Aug  8 16:17:00 THOR bluetoothd[1254]: plugins/hciops.c:link_key_request() Matching key found
Aug  8 16:17:00 THOR bluetoothd[1254]: plugins/hciops.c:link_key_request() link key type 0x00
Aug  8 16:17:00 THOR bluetoothd[1254]: plugins/hciops.c:auth_complete() hci0 status 0
Aug  8 16:17:00 THOR bluetoothd[1254]: plugins/hciops.c:bonding_complete() status 0x00
Aug  8 16:17:00 THOR bluetoothd[1254]: src/event.c:btd_event_bonding_complete() status 0x00
Aug  8 16:17:00 THOR bluetoothd[1254]: src/adapter.c:adapter_get_device() 00:0D:FD:1E:99:30
Aug  8 16:17:00 THOR bluetoothd[1254]: src/device.c:device_bonding_complete() bonding (nil) status 0x00
Aug  8 16:17:00 THOR bluetoothd[1254]: audio/headset.c:headset_set_state() State changed /org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING
Aug  8 16:17:00 THOR bluetoothd[1254]: audio/headset.c:headset_connect_cb() /org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30: Connected to 00:0D:FD:1E:99:30
Aug  8 16:17:00 THOR pulseaudio[1762]: bluetooth-util.c: dbus: interface=org.bluez.Headset, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:00 THOR pulseaudio[1762]: module-console-kit.c: dbus: interface=org.bluez.Headset, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:00 THOR pulseaudio[1762]: bluetooth-util.c: dbus: interface=org.bluez.Audio, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:00 THOR pulseaudio[1762]: module-console-kit.c: dbus: interface=org.bluez.Audio, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:01 THOR bluetoothd[1254]: audio/headset.c:handle_event() Received AT+BRSF=27
Aug  8 16:17:01 THOR bluetoothd[1254]: audio/headset.c:print_hf_features() HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control" 
Aug  8 16:17:01 THOR CRON[3204]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug  8 16:17:01 THOR bluetoothd[1254]: audio/headset.c:handle_event() Received AT+CIND=?
Aug  8 16:17:01 THOR bluetoothd[1254]: audio/headset.c:handle_event() Received AT+CIND?
Aug  8 16:17:02 THOR bluetoothd[1254]: audio/headset.c:handle_event() Received AT+CMER=3, 0, 0, 1
Aug  8 16:17:02 THOR bluetoothd[1254]: audio/headset.c:event_reporting() Event reporting (CMER): mode=3, ind=1
Aug  8 16:17:02 THOR bluetoothd[1254]: audio/headset.c:hfp_slc_complete() HFP Service Level Connection established
Aug  8 16:17:02 THOR bluetoothd[1254]: audio/telephony.c:telephony_device_connected() telephony-dummy: device 0x7fb87a88e250 connected
Aug  8 16:17:02 THOR bluetoothd[1254]: audio/headset.c:headset_set_state() State changed /org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30: HEADSET_STATE_CONNECTING -> HEADSET_STATE_CONNECTED
Aug  8 16:17:02 THOR pulseaudio[1762]: bluetooth-util.c: dbus: interface=org.bluez.Headset, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:02 THOR pulseaudio[1762]: module-console-kit.c: dbus: interface=org.bluez.Headset, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:02 THOR pulseaudio[1762]: bluetooth-util.c: dbus: interface=org.bluez.Headset, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:02 THOR pulseaudio[1762]: module-console-kit.c: dbus: interface=org.bluez.Headset, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:03 THOR bluetoothd[1254]: audio/headset.c:handle_event() Received AT+VGS=15
Aug  8 16:17:03 THOR bluetoothd[1254]: audio/headset.c:headset_set_gain() Ignoring no-change in speaker gain
Aug  8 16:17:03 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_confirm_cb() AVDTP: incoming connect from 00:0D:FD:1E:99:30
Aug  8 16:17:03 THOR bluetoothd[1254]: audio/sink.c:sink_set_state() State changed /org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30: SINK_STATE_DISCONNECTED -> SINK_STATE_CONNECTING
Aug  8 16:17:03 THOR pulseaudio[1762]: bluetooth-util.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:03 THOR pulseaudio[1762]: module-console-kit.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling channel to 00:0D:FD:1E:99:30
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=895
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:session_cb() 
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_parse_cmd() Received DISCOVER_CMD
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:session_cb() 
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_parse_cmd() Received  GET_CAPABILITIES_CMD
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/a2dp.c:sbc_getcap_ind() Source 0x7fb87a885780: Get_Capability_Ind
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:session_cb() 
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_parse_cmd() Received SET_CONFIGURATION_CMD
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/a2dp.c:sbc_setconf_ind() Source 0x7fb87a885780: Set_Configuration_Ind
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_ref() 0x7fb87a88edd0: ref=2
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/a2dp.c:setup_ref() 0x7fb87a894cb0: ref=1
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_ref() 0x7fb87a88edd0: ref=3
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: IDLE -> CONFIGURED
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/a2dp.c:setup_unref() 0x7fb87a894cb0: ref=0
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/a2dp.c:setup_free() 0x7fb87a894cb0
Aug  8 16:17:04 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_unref() 0x7fb87a88edd0: ref=2
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:session_cb() 
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_parse_cmd() Received OPEN_CMD
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/a2dp.c:open_ind() Source 0x7fb87a885780: Open_Ind
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_confirm_cb() AVDTP: incoming connect from 00:0D:FD:1E:99:30
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport channel to 00:0D:FD:1E:99:30
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:handle_transport_connect() Flushable packets enabled
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:handle_transport_connect() sk 38, omtu 672, send buffer size 63488
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: CONFIGURED -> OPEN
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/sink.c:sink_set_state() State changed /org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30: SINK_STATE_CONNECTING -> SINK_STATE_CONNECTED
Aug  8 16:17:05 THOR pulseaudio[1762]: bluetooth-util.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:05 THOR pulseaudio[1762]: module-console-kit.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:05 THOR pulseaudio[1762]: bluetooth-util.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:05 THOR pulseaudio[1762]: module-console-kit.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:05 THOR pulseaudio[1762]: bluetooth-util.c: dbus: interface=org.bluez.Audio, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-discover.c: Loading module-bluetooth-device address="00:0D:FD:1E:99:30" path="/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30"
Aug  8 16:17:05 THOR pulseaudio[1762]: module-card-restore.c: Restoring profile for card bluez_card.00_0D_FD_1E_99_30.
Aug  8 16:17:05 THOR pulseaudio[1762]: card.c: Created 3 "bluez_card.00_0D_FD_1E_99_30"
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Connected to the bluetooth audio service
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Sending BT_REQUEST -> BT_GET_CAPABILITIES
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Trying to receive message from audio service...
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:server_cb() Accepted new client connection on unix socket (fd=39)
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:client_cb() Audio API: BT_REQUEST <- BT_GET_CAPABILITIES
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_ref() 0x7fb87a88edd0: ref=3
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:session_cb() 
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_parse_resp() DISCOVER request succeeded
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_discover_resp() seid 1 type 1 media 0 in use 1
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_discover_resp() seid 2 type 1 media 0 in use 1
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:session_cb() 
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_get_capabilities_resp() seid 1 type 1 media 0
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:print_sbc() Media Codec: SBC Channel Modes: Mono DualChannel Stereo JointStereo Frequencies: 16Khz 32Khz 44.1Khz 48Khz  Subbands: 4 8  Blocks: 4 8 12 16  Bitpool: 2-44
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:a2dp_append_codec() Append configured seid 1 - length 13 - total 181
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_GET_CAPABILITIES
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Received BT_RESPONSE <- BT_GET_CAPABILITIES
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Payload size is 13 6
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Sending BT_REQUEST -> BT_GET_CAPABILITIES
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Trying to receive message from audio service...
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:client_cb() Audio API: BT_REQUEST <- BT_GET_CAPABILITIES
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:print_sbc() Media Codec: SBC Channel Modes: JointStereo Frequencies: 44.1Khz  Subbands: 8  Blocks: 16  Bitpool: 2-44
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:a2dp_append_codec() Append configured seid 1 - length 13 - total 181
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_GET_CAPABILITIES
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Received BT_RESPONSE <- BT_GET_CAPABILITIES
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Payload size is 13 6
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Got device capabilities
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Sending BT_REQUEST -> BT_OPEN
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Trying to receive message from audio service...
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:client_cb() Audio API: BT_REQUEST <- BT_OPEN
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:handle_a2dp_open() open a2dp - object=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30 source=ANY destination=ANY lock=write
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/a2dp.c:a2dp_sep_lock() SEP 0x7fb87a885780 locked
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_OPEN
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Received BT_RESPONSE <- BT_OPEN
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Sending BT_REQUEST -> BT_SET_CONFIGURATION
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Trying to receive message from audio service...
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:client_cb() Audio API: BT_REQUEST <- BT_SET_CONFIGURATION
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:print_sbc() Media Codec: SBC Channel Modes: JointStereo Frequencies: 44.1Khz  Subbands: 8  Blocks: 16  Bitpool: 2-44
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/a2dp.c:a2dp_config() a2dp_config: selected SEP 0x7fb87a885780
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_ref() 0x7fb87a88edd0: ref=4
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/a2dp.c:setup_ref() 0x7fb87a894cb0: ref=1
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/a2dp.c:a2dp_config() Configuration match: resuming
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_SET_CONFIGURATION
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/a2dp.c:setup_unref() 0x7fb87a894cb0: ref=0
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/a2dp.c:setup_free() 0x7fb87a894cb0
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_unref() 0x7fb87a88edd0: ref=3
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Received BT_RESPONSE <- BT_SET_CONFIGURATION
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: SBC parameters:
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: #011allocation=0
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: #011subbands=1
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: #011blocks=3
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: #011bitpool=44
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Connection to the device configured
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Got the stream socket
Aug  8 16:17:05 THOR pulseaudio[1762]: module-device-restore.c: Restoring volume for sink bluez_sink.00_0D_FD_1E_99_30.
Aug  8 16:17:05 THOR pulseaudio[1762]: module-device-restore.c: Restoring mute state for sink bluez_sink.00_0D_FD_1E_99_30.
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c: Created sink 3 "bluez_sink.00_0D_FD_1E_99_30" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     bluetooth.protocol = "a2dp"
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     device.description = "Motorola S9-HD"
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     device.string = "00:0D:FD:1E:99:30"
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     device.api = "bluez"
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     device.class = "sound"
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     device.bus = "bluetooth"
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     device.form_factor = "headset"
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     bluez.path = "/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30"
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     bluez.class = "0x240404"
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     bluez.name = "Motorola S9-HD"
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     device.icon_name = "audio-headset-bluetooth"
Aug  8 16:17:05 THOR pulseaudio[1762]: sink.c:     device.intended_roles = "phone"
Aug  8 16:17:05 THOR pulseaudio[1762]: module-device-restore.c: Restoring mute state for source bluez_sink.00_0D_FD_1E_99_30.monitor.
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c: Created source 4 "bluez_sink.00_0D_FD_1E_99_30.monitor" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c:     device.description = "Monitor of Motorola S9-HD"
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c:     device.class = "monitor"
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c:     device.string = "00:0D:FD:1E:99:30"
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c:     device.api = "bluez"
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c:     device.bus = "bluetooth"
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c:     device.form_factor = "headset"
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c:     bluez.path = "/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30"
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c:     bluez.class = "0x240404"
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c:     bluez.name = "Motorola S9-HD"
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c:     device.icon_name = "audio-headset-bluetooth"
Aug  8 16:17:05 THOR pulseaudio[1762]: source.c:     device.intended_roles = "phone"
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: IO Thread starting up
Aug  8 16:17:05 THOR rtkit-daemon[1766]: Successfully made thread 3206 of process 1762 (n/a) owned by '1000' RT at priority 5.
Aug  8 16:17:05 THOR rtkit-daemon[1766]: Supervising 4 threads of 1 processes of 1 users.
Aug  8 16:17:05 THOR pulseaudio[1762]: core-util.c: RealtimeKit worked.
Aug  8 16:17:05 THOR pulseaudio[1762]: core-util.c: Successfully enabled SCHED_RR scheduling for thread, with priority 5.
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Sending BT_REQUEST -> BT_START_STREAM
Aug  8 16:17:05 THOR pulseaudio[1762]: module-bluetooth-device.c: Trying to receive message from audio service...
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/unix.c:client_cb() Audio API: BT_REQUEST <- BT_START_STREAM
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_ref() 0x7fb87a88edd0: ref=4
Aug  8 16:17:05 THOR bluetoothd[1254]: audio/a2dp.c:setup_ref() 0x7fb87a89c590: ref=1
Aug  8 16:17:06 THOR bluetoothd[1254]: audio/avdtp.c:session_cb() 
Aug  8 16:17:06 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_parse_resp() START request succeeded
Aug  8 16:17:06 THOR bluetoothd[1254]: audio/a2dp.c:start_cfm() Source 0x7fb87a885780: Start_Cfm
Aug  8 16:17:06 THOR bluetoothd[1254]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_START_STREAM
Aug  8 16:17:06 THOR bluetoothd[1254]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE -> BT_NEW_STREAM
Aug  8 16:17:06 THOR bluetoothd[1254]: audio/a2dp.c:setup_unref() 0x7fb87a89c590: ref=0
Aug  8 16:17:06 THOR bluetoothd[1254]: audio/a2dp.c:setup_free() 0x7fb87a89c590
Aug  8 16:17:06 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_unref() 0x7fb87a88edd0: ref=3
Aug  8 16:17:06 THOR bluetoothd[1254]: audio/avdtp.c:avdtp_sep_set_state() stream state changed: OPEN -> STREAMING
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c: Received BT_RESPONSE <- BT_START_STREAM
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c: Trying to receive message from audio service...
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c: Received BT_RESPONSE <- BT_NEW_STREAM
Aug  8 16:17:06 THOR bluetoothd[1254]: audio/sink.c:sink_set_state() State changed /org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30: SINK_STATE_CONNECTED -> SINK_STATE_PLAYING
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c: Stream properly set up, we're ready to roll!
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c:    u->sink   = 0x162a360
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c:    u->source = (nil)
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c:    pollfd    = 0x15b4990
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c:    pollfd->revents = 0
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c:    sink_is_linked = 0
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c: **** started_at not initialized ****
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c: Using SBC encoder implementation: MMX
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c:    block_size=3072  frame_length=101  codesize=512
Aug  8 16:17:06 THOR pulseaudio[1762]: module-suspend-on-idle.c: Sink bluez_sink.00_0D_FD_1E_99_30 becomes idle, timeout in 5 seconds.
Aug  8 16:17:06 THOR pulseaudio[1762]: module.c: Loaded "module-bluetooth-device" (index: #23; argument: "address="00:0D:FD:1E:99:30" path="/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30"").
Aug  8 16:17:06 THOR pulseaudio[1762]: module-console-kit.c: dbus: interface=org.bluez.Audio, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:06 THOR pulseaudio[1762]: bluetooth-util.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:06 THOR pulseaudio[1762]: module-console-kit.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:06 THOR pulseaudio[1762]: bluetooth-util.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:06 THOR pulseaudio[1762]: module-console-kit.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged
Aug  8 16:17:06 THOR pulseaudio[1762]: module-bluetooth-device.c: dbus: interface=org.bluez.AudioSink, path=/org/bluez/1249/hci0/dev_00_0D_FD_1E_99_30, member=PropertyChanged


^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: Question regarding SET_CONFIGURATION avdtp command handling
  2011-08-07 15:34     ` Question regarding SET_CONFIGURATION avdtp command handling Ilia, Kolominsky
  2011-08-08 20:41       ` Peter Hurley
@ 2011-08-09 12:27       ` Luiz Augusto von Dentz
  1 sibling, 0 replies; 6+ messages in thread
From: Luiz Augusto von Dentz @ 2011-08-09 12:27 UTC (permalink / raw)
  To: Ilia, Kolominsky; +Cc: linux-bluetooth

Hi,

2011/8/7 Ilia, Kolominsky <iliak@ti.com>:
> Hello!
> Can anybody help me to understand the process of handling avdtp
> SET_CONFIGURATION command in scenario when a2dp headset initializes
> connection to linux machine? I see that the headset sends
> SET_CONFIGURATION avdtp command (with appropriate SBC params),
> but i cant find out how this ultimately translates to actual
> configuration of a player (totem in my case).
>
> What layers are involved in general?
>
> I see that handling of the command follows the following path (approx.):
> avdtp.c::sbc_setconf_ind()
>        a2dp.c::auto_config()

If it went to sbc_setconf_ind it probably means the system is not
using Media API, so it auto configure but at this point nobody is
using it.

>                avdtp.c::avdtp_sep_set_state()
>                        a2dp.c::stream_state_changed()
>                        sink.c::stream_state_changed()

This will eventually wakeup interested process that need to connect
over unix socket (see audio/unix.c) to acquire the fd.

> At no stage I am able to spot the actual configuration of the sbc...
> (there should be probably some sort of d-bus messages, but, again,
> I don’t see that neither SelectConfiguration nor SetConfiguration
> from the media-api are used).

As I said according to your traces it is picking a bluetoothd internal
sep, so in that case it won't call SetConfiguration instead it will
auto configure using the local sep. Note that it could be you enabled
the Media API but forgot to disable the unix socket (Disable=Socket),
in that case you can have a mix of bluetoothd internal sep and
external seps (registered via Media API).

> In addition, there is BT_SET_CONFIGURATION command that is handled
> in unix.c (after SET_CONFIGURATION is handled); how does it fits
> in the configuration picture?

This is the old API, in this case the client is using our internal ipc
BT_SET_CONFIGURATION command to set its configuration, this could
match the current configuration (if it doesn't it does CLOSE and
SET_CONFIGURATION again).

> Any info (or reference where it can be found) will be much
> appreciated.

You can use test/simple-endpoint to emulate an MediaEndpoint (make
sure PulseAudio don't interfere), for the old API (not recommended)
you can take a look at test/ipctest.c

-- 
Luiz Augusto von Dentz

^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2011-08-09 12:27 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2011-07-13 11:02 [PATCH bluetooth-next] Fixes kernel panic in incomming l2cap connections with defer_setup ilia.kolominsky
2011-07-13 18:31 ` Gustavo Padovan
2011-07-14  9:01   ` Ilia, Kolominsky
2011-08-07 15:34     ` Question regarding SET_CONFIGURATION avdtp command handling Ilia, Kolominsky
2011-08-08 20:41       ` Peter Hurley
2011-08-09 12:27       ` Luiz Augusto von Dentz

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.