2008-09-30 21:03:18

by Stuart Pook

[permalink] [raw]
Subject: bluez-4.9 + 2.6.27-rc8 + SCO headset -> bluetoothd: connect: Operation not permitted

Hi again

I just installed bluez-4.9 and linux 2.6.27-rc8 hoping that my
Jabra JX10 bluetooth headset would start working. Still no luck.
Bluetoothd says "connect: Operation not permitted (1)" and
aplay "BT_SETCONFIGURATION failed".

I also downloaded the 2.6.26-mh6 patches from
http://www.bluez.org/more-usb-driver-fixes-and-quirks/ and recompiled
another kernel. The kernel crashed twice (I only booted it twice) rather
quickly. I did get time to run aplay once and it gave the same errors
as shown here. The hcidump is almost exactly the same.

Er, what headsets do work? Please let me know. The Jabra JX10 "features
Bluetooth 2.0 and e-SCO for improved audio quality and MultiPoint
capability for connecting to 2 devices at once". Could that be
what is causing the problem?

I ran strace on bluetoothd and it appears that it is
"bind(25, {sa_family=AF_BLUETOOTH, sa_data="0\377\341A\f\0\310\261\v\270H\225d\271"...}, 8)"
that is returning -1 with errno set to EADDRINUSE

Please let me know if I should send these questions elsewhere.

thanks for any advice!
Stuart

Bluetoothd says:

bluetoothd: Accepted new client connection on unix socket (fd=23)
bluetoothd: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd: kernel auth requirements = 0x04
bluetoothd: stored link key type = 0x00
bluetoothd: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd: Received AT+BRSF=27
bluetoothd: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd: Received AT+CIND=?
bluetoothd: Received AT+CIND?
bluetoothd: Received AT+CMER=3, 0, 0, 1
bluetoothd: Event reporting (CMER): mode=3, ind=1
bluetoothd: HFP Service Level Connection established
bluetoothd: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd: connect: Operation not permitted (1)
bluetoothd: config failed
bluetoothd: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd: Unix client disconnected (fd=23)
bluetoothd: Received AT+VGS=00

% aplay -D JX10 lib/alarm.wav
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]

# hciconfig hci0 revision
hci0: Type: USB
BD Address: 00:0C:41:E1:FF:30 ACL MTU: 192:8 SCO MTU: 64:8
HCI 16.4
Chip version: BlueCore02-External
Max key size: 56 bit
SCO mapping: HCI
# hciconfig hci0 version
hci0: Type: USB
BD Address: 00:0C:41:E1:FF:30 ACL MTU: 192:8 SCO MTU: 64:8
HCI Ver: 1.1 (0x1) HCI Rev: 0x20d LMP Ver: 1.1 (0x1) LMP Subver: 0x20d
Manufacturer: Cambridge Silicon Radio (10)

HCI sniffer - Bluetooth packet analyzer ver 1.42
device: hci0 snap_len: 1028 filter: 0xffffffff
< HCI Command: Create Connection (0x01|0x0005) plen 13
bdaddr 00:1A:45:2F:49:98 ptype 0xcc18 rswitch 0x01 clkoffset 0x0000
Packet type: DM1 DM3 DM5 DH1 DH3 DH5
> HCI Event: Command Status (0x0f) plen 4
Create Connection (0x01|0x0005) status 0x00 ncmd 1
> HCI Event: Connect Complete (0x03) plen 11
status 0x00 handle 41 bdaddr 00:1A:45:2F:49:98 type ACL encrypt 0x00
< HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2
handle 41
> HCI Event: Command Status (0x0f) plen 4
Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 0
> HCI Event: Page Scan Repetition Mode Change (0x20) plen 7
bdaddr 00:1A:45:2F:49:98 mode 1
> HCI Event: Max Slots Change (0x1b) plen 3
handle 41 slots 5
> HCI Event: Command Status (0x0f) plen 4
Unknown (0x00|0x0000) status 0x00 ncmd 1
< HCI Command: Remote Name Request (0x01|0x0019) plen 10
bdaddr 00:1A:45:2F:49:98 mode 2 clkoffset 0x0000
> HCI Event: Command Status (0x0f) plen 4
Remote Name Request (0x01|0x0019) status 0x00 ncmd 1
> HCI Event: Read Remote Supported Features (0x0b) plen 11
status 0x00 handle 41
Features: 0xbf 0xfe 0x8b 0xf8 0x1b 0x18 0x00 0x80
< ACL data: handle 41 flags 0x02 dlen 10
L2CAP(s): Info req: type 2
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 16
L2CAP(s): Info rsp: type 2 result 0
Extended feature mask 0x0000
< ACL data: handle 41 flags 0x02 dlen 12
L2CAP(s): Connect req: psm 3 scid 0x0040
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 16
L2CAP(s): Connect rsp: dcid 0x0058 scid 0x0040 result 1 status 2
Connection pending - Authorization pending
> HCI Event: Remote Name Req Complete (0x07) plen 255
status 0x00 bdaddr 00:1A:45:2F:49:98 name 'Jabra JX10 series 2'
> HCI Event: Link Key Request (0x17) plen 6
bdaddr 00:1A:45:2F:49:98
< HCI Command: Link Key Request Reply (0x01|0x000b) plen 22
bdaddr 00:1A:45:2F:49:98 key F63331CE2D0DBCA190DC73C930CD6117
> HCI Event: Command Complete (0x0e) plen 10
Link Key Request Reply (0x01|0x000b) ncmd 1
status 0x00 bdaddr 00:1A:45:2F:49:98
> ACL data: handle 41 flags 0x02 dlen 16
L2CAP(s): Connect rsp: dcid 0x0058 scid 0x0040 result 0 status 0
Connection successful
< ACL data: handle 41 flags 0x02 dlen 16
L2CAP(s): Config req: dcid 0x0058 flags 0x00 clen 4
MTU 1013
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 14
L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 0
Success
> ACL data: handle 41 flags 0x02 dlen 16
L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4
MTU 1013
< ACL data: handle 41 flags 0x02 dlen 18
L2CAP(s): Config rsp: scid 0x0058 flags 0x00 result 0 clen 4
MTU 1013
< ACL data: handle 41 flags 0x02 dlen 8
L2CAP(d): cid 0x0058 len 4 [psm 3]
RFCOMM(s): SABM: cr 1 dlci 0 pf 1 ilen 0 fcs 0x1c
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 8
L2CAP(d): cid 0x0040 len 4 [psm 3]
RFCOMM(s): UA: cr 1 dlci 0 pf 1 ilen 0 fcs 0xd7
< ACL data: handle 41 flags 0x02 dlen 18
L2CAP(d): cid 0x0058 len 14 [psm 3]
RFCOMM(s): PN CMD: cr 1 dlci 0 pf 0 ilen 10 fcs 0x70 mcc_len 8
dlci 2 frame_type 0 credit_flow 15 pri 7 ack_timer 0
frame_size 1008 max_retrans 0 credits 7
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 18
L2CAP(d): cid 0x0040 len 14 [psm 3]
RFCOMM(s): PN RSP: cr 0 dlci 0 pf 0 ilen 10 fcs 0xaa mcc_len 8
dlci 2 frame_type 0 credit_flow 14 pri 7 ack_timer 0
frame_size 127 max_retrans 0 credits 0
< ACL data: handle 41 flags 0x02 dlen 8
L2CAP(d): cid 0x0058 len 4 [psm 3]
RFCOMM(s): SABM: cr 1 dlci 2 pf 1 ilen 0 fcs 0x59
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 8
L2CAP(d): cid 0x0040 len 4 [psm 3]
RFCOMM(s): UA: cr 1 dlci 2 pf 1 ilen 0 fcs 0x92
< ACL data: handle 41 flags 0x02 dlen 12
L2CAP(d): cid 0x0058 len 8 [psm 3]
RFCOMM(s): MSC CMD: cr 1 dlci 0 pf 0 ilen 4 fcs 0x70 mcc_len 2
dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 0 b2 0 b3 0 len 0
> ACL data: handle 41 flags 0x02 dlen 12
L2CAP(d): cid 0x0040 len 8 [psm 3]
RFCOMM(s): MSC CMD: cr 0 dlci 0 pf 0 ilen 4 fcs 0xaa mcc_len 2
dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 0 b1 0 b2 0 b3 0 len 0
< ACL data: handle 41 flags 0x02 dlen 12
L2CAP(d): cid 0x0058 len 8 [psm 3]
RFCOMM(s): MSC RSP: cr 1 dlci 0 pf 0 ilen 4 fcs 0x70 mcc_len 2
dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 0 b1 0 b2 0 b3 0 len 0
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 12
L2CAP(d): cid 0x0040 len 8 [psm 3]
RFCOMM(s): MSC RSP: cr 0 dlci 0 pf 0 ilen 4 fcs 0xaa mcc_len 2
dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 0 b2 0 b3 0 len 0
< ACL data: handle 41 flags 0x02 dlen 9
L2CAP(d): cid 0x0058 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 1 ilen 0 fcs 0x86 credits 33
> ACL data: handle 41 flags 0x02 dlen 9
L2CAP(d): cid 0x0040 len 5 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 0 fcs 0x5c credits 15
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 19
L2CAP(d): cid 0x0040 len 15 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 0 ilen 11 fcs 0x40
0000: 41 54 2b 42 52 53 46 3d 32 37 0d AT+BRSF=27.
< ACL data: handle 41 flags 0x02 dlen 19
L2CAP(d): cid 0x0058 len 15 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 11 fcs 0x9a
0000: 0d 0a 2b 42 52 53 46 3d 30 0d 0a ..+BRSF=0..
< ACL data: handle 41 flags 0x02 dlen 14
L2CAP(d): cid 0x0058 len 10 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 6 fcs 0x9a
0000: 0d 0a 4f 4b 0d 0a ..OK..
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 19
L2CAP(d): cid 0x0040 len 15 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 10 fcs 0x5c credits 2
0000: 41 54 2b 43 49 4e 44 3d 3f 0d AT+CIND=?.
< ACL data: handle 41 flags 0x02 dlen 135
L2CAP(d): cid 0x0058 len 131 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 127 fcs 0x9a
0000: 0d 0a 2b 43 49 4e 44 3a 28 22 62 61 74 74 63 68 ..+CIND:("battch
0010: 67 22 2c 28 30 2d 35 29 29 2c 28 22 73 69 67 6e g",(0-5)),("sign
0020: 61 6c 22 2c 28 30 2d 35 29 29 2c 28 22 73 65 72 al",(0-5)),("ser
0030: 76 69 63 65 22 2c 28 30 2c 31 29 29 2c 28 22 63 vice",(0,1)),("c
0040: 61 6c 6c 22 2c 28 30 2c 31 29 29 2c 28 22 63 61 all",(0,1)),("ca
0050: 6c 6c 73 65 74 75 70 22 2c 28 30 2d 33 29 29 2c llsetup",(0-3)),
0060: 28 22 63 61 6c 6c 68 65 6c 64 22 2c 28 30 2d 32 ("callheld",(0-2
0070: 29 29 2c 28 22 72 6f 61 6d 22 2c 28 30 2c 31 )),("roam",(0,1
< ACL data: handle 41 flags 0x02 dlen 12
L2CAP(d): cid 0x0058 len 8 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 4 fcs 0x9a
0000: 29 29 0d 0a ))..
< ACL data: handle 41 flags 0x02 dlen 14
L2CAP(d): cid 0x0058 len 10 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 6 fcs 0x9a
0000: 0d 0a 4f 4b 0d 0a ..OK..
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 18
L2CAP(d): cid 0x0040 len 14 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 9 fcs 0x5c credits 3
0000: 41 54 2b 43 49 4e 44 3f 0d AT+CIND?.
< ACL data: handle 41 flags 0x02 dlen 31
L2CAP(d): cid 0x0058 len 27 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 23 fcs 0x9a
0000: 0d 0a 2b 43 49 4e 44 3a 35 2c 35 2c 31 2c 30 2c ..+CIND:5,5,1,0,
0010: 30 2c 30 2c 30 0d 0a 0,0,0..
< ACL data: handle 41 flags 0x02 dlen 14
L2CAP(d): cid 0x0058 len 10 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 6 fcs 0x9a
0000: 0d 0a 4f 4b 0d 0a ..OK..
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 28
L2CAP(d): cid 0x0040 len 24 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 19 fcs 0x5c credits 2
0000: 41 54 2b 43 4d 45 52 3d 33 2c 20 30 2c 20 30 2c AT+CMER=3, 0, 0,
0010: 20 31 0d 1.
< ACL data: handle 41 flags 0x02 dlen 14
L2CAP(d): cid 0x0058 len 10 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 6 fcs 0x9a
0000: 0d 0a 4f 4b 0d 0a ..OK..
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 19
L2CAP(d): cid 0x0040 len 15 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 10 fcs 0x5c credits 1
0000: 41 54 2b 56 47 53 3d 30 30 0d AT+VGS=00.
< ACL data: handle 41 flags 0x02 dlen 14
L2CAP(d): cid 0x0058 len 10 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 6 fcs 0x9a
0000: 0d 0a 4f 4b 0d 0a ..OK..
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1


2008-10-07 05:34:38

by Johan Hedberg

[permalink] [raw]
Subject: Re: bluez/git + 2.6.27-rc8 + bluetoothd -> SIGSEGV

Hi Stuart,

On Oct 7, 2008, at 0:40, Stuart Pook wrote:
>>> :; grep ' -g' Makefile
>>> CFLAGS = -Wall -O2 -D_FORTIFY_SOURCE=2 -fPIC -g -O0
>> that is indeed strange. You should be able to get a proper backtrace.
>
> yes. I ran src/.libs/bluetoothd, it core dumped,
> but I still cannot get a reasonable backtrace. Weird.

Please do a "git pull". The segfault shouln't occur anymore (a
probable cause of it was a bug in common/glib-helper.c which Luiz
fixed yesterday). Also, if you have the chance come to the #bluez
channel on freenode where most bluez developers hang out (you'd have
e.g. found out about the fix much earlier that way).

Johan

2008-10-06 23:17:08

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez/git + 2.6.27-rc8 + Belkin F8T017 -> works with reset=1

hi Marcel

> I doubt it since it is not in yet. Show me the output of hciconfig -a
> for this so I can create a patch for it.

see below

> What is the exact model number of this one. Do you have to have a link
> to the product website by any chance.

Belkin
Bluetooth Adapter
Model: F8T017
FCC ID: K7SF8T017

When I ordered the dongle I ordered a F8T017ng but the "ng"
is not indicated on the dongle or on the packaging.

http://catalog.belkin.com/IWCatProductPage.process?Product_Id=454427
http://www.belkin.com/uk/support/article/?lid=enu&pid=F8T017ng&aid=10334&scid=0

: root@kooka; hciconfig -a
hci0: Type: USB
BD Address: 00:0A:3A:84:94:D9 ACL MTU: 1021:8 SCO MTU: 64:1
UP RUNNING
RX bytes:844 acl:0 sco:0 events:46 errors:0
TX bytes:2609 acl:0 sco:0 commands:46 errors:0
Features: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x79 0x83
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy: RSWITCH HOLD SNIFF PARK
Link mode: SLAVE ACCEPT
Name: 'kooka-0'
Class: 0x4a0104
Service Classes: Networking, Capturing, Telephony
Device Class: Computer, Desktop workstation
HCI Ver: 2.1 (0x4) HCI Rev: 0x5123 LMP Ver: 2.1 (0x4) LMP Subver: 0x420e
Manufacturer: Broadcom Corporation (15)

This dongle has a small button. I'm not sure yet but it seemed that
the dongle didn't want to work until I pressed the button.
I'll check next time.

thanks
Stuart

2008-10-06 22:40:55

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez/git + 2.6.27-rc8 + bluetoothd -> SIGSEGV

hello Marcel

>> :; grep ' -g' Makefile
>> CFLAGS = -Wall -O2 -D_FORTIFY_SOURCE=2 -fPIC -g -O0
>
> that is indeed strange. You should be able to get a proper backtrace.

yes. I ran src/.libs/bluetoothd, it core dumped,
but I still cannot get a reasonable backtrace. Weird.

I'm not sure that that running src/.libs/bluetoothd is correct.
src/.libs/bluetoothd will use the libbluetooth.so.3 installed in
/usr/local/lib. If I want to use the library in the source area
(as I have not installed this version of bluez) I should run
src/bluetoothd. It does the library magic to use the libraries
in the src area.

I did this and it still core dumps and gdb still cannot read the
core. Time to go to bed.

: root@kooka; src//bluetoothd -dn
bluetoothd[9997]: Bluetooth daemon
bluetoothd[9997]: Enabling debug information
bluetoothd[9997]: parsing main.conf
bluetoothd[9997]: offmode=NoScan
bluetoothd[9997]: discovto=0
bluetoothd[9997]: pageto=8192
bluetoothd[9997]: name=%h-%d
bluetoothd[9997]: class=0x000100
bluetoothd[9997]: inqmode=0
bluetoothd[9997]: Starting SDP server
bluetoothd[9997]: Loading plugins /home/stuart/ws/install/bluez/git/bluez/plugins
bluetoothd[9997]: /home/stuart/ws/install/bluez/git/bluez/plugins/audio.so
bluetoothd[9997]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory
bluetoothd[9997]: Unix socket created: 11
bluetoothd[9997]: Telephony plugin initialized
bluetoothd[9997]: HFP AG features: "Ability to reject a call" "Enhanced call status" "Extended Error Result Codes"
bluetoothd[9997]: /home/stuart/ws/install/bluez/git/bluez/plugins/serial.so
bluetoothd[9997]: /home/stuart/ws/install/bluez/git/bluez/plugins/hal.so
bluetoothd[9997]: /home/stuart/ws/install/bluez/git/bluez/plugins/service.so
bluetoothd[9997]: /home/stuart/ws/install/bluez/git/bluez/plugins/network.so
bluetoothd[9997]: Parsing /etc/bluetooth/network.conf failed: No such file or directory
bluetoothd[9997]: Config options: InterfacePrefix=bnep%d, PANU_Script=(null), GN_Script=(null), NAP_Script=(null), GN_Interface=pan0, NAP_Interface=pan1, Security=true
bluetoothd[9997]: bridge pan0 created
bluetoothd[9997]: /home/stuart/ws/install/bluez/git/bluez/plugins/input.so
bluetoothd[9997]: input.conf: Key file does not have key 'IdleTimeout'
bluetoothd[9997]: HCI dev 0 registered
bluetoothd[9997]: child 10014 forked
bluetoothd[9997]: HCI dev 0 up
bluetoothd[9997]: Adapter /org/bluez/hci0 without an address
bluetoothd[9997]: headset_server_probe: path /org/bluez/hci0
bluetoothd[9997]: Adding record with handle 0x10000
bluetoothd[9997]: Record pattern UUID 00000003-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001108-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001112-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001203-0000-1000-8000-00805f9
bluetoothd[9997]: Adding record with handle 0x10001
bluetoothd[9997]: Record pattern UUID 00000003-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 0000111e-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 0000111f-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001203-0000-1000-8000-00805f9
bluetoothd[9997]: a2dp_server_probe: path /org/bluez/hci0
bluetoothd[9997]: SEP 0xb90487d0 registered: type:0 codec:0 seid:1
bluetoothd[9997]: Adding record with handle 0x10002
bluetoothd[9997]: Record pattern UUID 00000019-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 0000110a-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 0000110d-0000-1000-8000-00805f9
bluetoothd[9997]: avrcp_server_probe: path /org/bluez/hci0
bluetoothd[9997]: Adding record with handle 0x10003
bluetoothd[9997]: Record pattern UUID 00000017-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 0000110c-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 0000110e-0000-1000-8000-00805f9
bluetoothd[9997]: Adding record with handle 0x10004
bluetoothd[9997]: Record pattern UUID 00000017-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 0000110e-0000-1000-8000-00805f9
bluetoothd[9997]: proxy_probe: path /org/bluez/hci0
bluetoothd[9997]: Registered interface org.bluez.SerialProxyManager on path /org/bluez/hci0
bluetoothd[9997]: service_probe: path /org/bluez/hci0
bluetoothd[9997]: Registered interface org.bluez.Service on path /org/bluez/hci0
bluetoothd[9997]: network_server_probe: path /org/bluez/hci0
bluetoothd[9997]: Adding record with handle 0x10005
bluetoothd[9997]: Record pattern UUID 0000000f-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001115-0000-1000-8000-00805f9
bluetoothd[9997]: register_server_record: got record id 0x10005
bluetoothd[9997]: Registered interface org.bluez.NetworkPeer on path /org/bluez/hci0
bluetoothd[9997]: network_server_probe: path /org/bluez/hci0
bluetoothd[9997]: Adding record with handle 0x10006
bluetoothd[9997]: Record pattern UUID 0000000f-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001117-0000-1000-8000-00805f9
bluetoothd[9997]: register_server_record: got record id 0x10006
bluetoothd[9997]: Registered interface org.bluez.NetworkHub on path /org/bluez/hci0
bluetoothd[9997]: network_server_probe: path /org/bluez/hci0
bluetoothd[9997]: Adding record with handle 0x10007
bluetoothd[9997]: Record pattern UUID 0000000f-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[9997]: Record pattern UUID 00001116-0000-1000-8000-00805f9
bluetoothd[9997]: register_server_record: got record id 0x10007
bluetoothd[9997]: Registered interface org.bluez.NetworkRouter on path /org/bluez/hci0
bluetoothd[9997]: Creating device /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[9997]: Probe drivers for /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[9997]: Found Headset record
bluetoothd[9997]: Discovered Headset service on RFCOMM channel 2
bluetoothd[9997]: Registered interface org.bluez.Headset on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[9997]: Found Hansfree record
bluetoothd[9997]: Discovered Handsfree service on RFCOMM channel 1
bluetoothd[9997]: headset_probe: path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[9997]: Registered interface org.bluez.Input on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[9997]: Creating device /org/bluez/hci0/dev_00_14_A7_74_D3_AF
bluetoothd[9997]: Creating device /org/bluez/hci0/dev_00_03_89_B7_F8_D3
bluetoothd[9997]: Creating device /org/bluez/hci0/dev_00_0A_94_94_4F_B3
bluetoothd[9997]: Creating device /org/bluez/hci0/dev_00_03_89_DC_5C_9F
bluetoothd[9997]: Creating device /org/bluez/hci0/dev_00_03_89_DC_FC_EC
bluetoothd[9997]: Creating device /org/bluez/hci0/dev_00_03_89_FE_E6_19
bluetoothd[9997]: Creating device /org/bluez/hci0/dev_00_0E_6D_8F_91_6A
bluetoothd[9997]: Creating device /org/bluez/hci0/dev_00_17_E5_E6_25_AB
bluetoothd[9997]: Creating device /org/bluez/hci0/dev_00_17_E5_16_88_6C
bluetoothd[9997]: Creating device /org/bluez/hci0/dev_00_17_E5_0C_EA_70
bluetoothd[9997]: Adapter /org/bluez/hci0 has been enabled
bluetoothd[9997]: Starting security manager 0
bluetoothd[9997]: child 10014 exited
bluetoothd[9997]: Computer is classified as desktop
bluetoothd[9997]: Current device class is 0x4a0100
bluetoothd[9997]: Setting 0x000104 for major/minor device class
bluetoothd[9997]: Accepted new client connection on unix socket (fd=23)
bluetoothd[9997]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[9997]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[9997]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[9997]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[9997]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[9997]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[9997]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[9997]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[9997]: kernel auth requirements = 0x04
bluetoothd[9997]: stored link key type = 0x00
bluetoothd[9997]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[9997]: Received AT+BRSF=27
bluetoothd[9997]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[9997]: Received AT+CIND=?
bluetoothd[9997]: Received AT+CIND?
bluetoothd[9997]: Received AT+CMER=3, 0, 0, 1
bluetoothd[9997]: Event reporting (CMER): mode=3, ind=1
bluetoothd[9997]: HFP Service Level Connection established
bluetoothd[9997]: telephony-dummy: device 0xb904d860 connected
bluetoothd[9997]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[9997]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[9997]: Received AT+VGS=14
bluetoothd[9997]: connect(): Connection timed out (110)
bluetoothd[9997]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[9997]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[9997]: Audio API: received BT_STREAMSTART_REQ
bluetoothd[9997]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[9997]: Audio API: sending BT_STREAMFD_IND
bluetoothd[9997]: unix_sendmsg_fd: Bad file descriptor(9)
bluetoothd[9997]: resume failed
bluetoothd[9997]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[9997]: Unix client disconnected (fd=23)
bluetoothd[9997]: No matching connection for handle 44
bluetoothd[9997]: Accepted new client connection on unix socket (fd=23)
bluetoothd[9997]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[9997]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[9997]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[9997]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[9997]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[9997]: connect(): Connection timed out (110)
bluetoothd[9997]: Unable to lock headset
bluetoothd[9997]: config failed
bluetoothd[9997]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[9997]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[9997]: Unix client disconnected (fd=23)
bluetoothd[9997]: No matching connection for handle 44
bluetoothd[9997]: Accepted new client connection on unix socket (fd=23)
bluetoothd[9997]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[9997]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[9997]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[9997]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[9997]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[9997]: Received AT+VGS=15
bluetoothd[9997]: Unix client disconnected (fd=23)
bluetoothd[9997]: telephony-dummy: device 0xb904d860 disconnected
bluetoothd[9997]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[9997]: Accepted new client connection on unix socket (fd=23)
bluetoothd[9997]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[9997]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[9997]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[9997]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[9997]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[9997]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[9997]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[9997]: Received AT+BRSF=27
bluetoothd[9997]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[9997]: Received AT+CIND=?
bluetoothd[9997]: Received AT+CIND?
bluetoothd[9997]: Received AT+CMER=3, 0, 0, 1
bluetoothd[9997]: Event reporting (CMER): mode=3, ind=1
bluetoothd[9997]: HFP Service Level Connection established
bluetoothd[9997]: telephony-dummy: device 0xb904d860 connected
bluetoothd[9997]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[9997]: connect: Operation not permitted (1)
bluetoothd[9997]: config failed
bluetoothd[9997]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[9997]: Unix client disconnected (fd=23)
bluetoothd[9997]: Received AT+VGS=15
bluetoothd[9997]: connect(): Connection timed out (110)
Segmentation fault (core dumped)

:; gdb src/.libs/bluetoothd core
GNU gdb 6.8-debian
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "i486-linux-gnu"...

warning: core file may not match specified executable file.
Core was generated by `/home/stuart/ws/install/bluez/git/bluez/src/.libs/lt-bluetoothd -dn'.
Program terminated with signal 11, Segmentation fault.
[New process 9997]
#0 0xb7c4da16 in ?? ()
(gdb) quit
:; ls /home/stuart/ws/install/bluez/git/bluez/src/.libs
bluetoothd lt-bluetoothd
:; gdb /home/stuart/ws/install/bluez/git/bluez/src/.libs/lt-bluetoothd core
GNU gdb 6.8-debian
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "i486-linux-gnu"...
Core was generated by `/home/stuart/ws/install/bluez/git/bluez/src/.libs/lt-bluetoothd -dn'.
Program terminated with signal 11, Segmentation fault.
[New process 9997]
#0 0xb7c4da16 in ?? ()
(gdb) where
#0 0xb7c4da16 in ?? ()
#1 0xb7c5f1e3 in ?? ()
#2 0xb7dceda5 in ?? ()
#3 0x0000006e in ?? ()
#4 0xb7df3afa in ?? ()
#5 0xbff5c4b0 in ?? ()
#6 0xbff5c472 in ?? ()
#7 0x00000010 in ?? ()
#8 0xb7deaff4 in ?? ()
#9 0xb904d860 in ?? ()
#10 0xb904dcb0 in ?? ()
#11 0x00000000 in ?? ()

2008-10-06 22:38:54

by Marcel Holtmann

[permalink] [raw]
Subject: Re: bluez/git + 2.6.27-rc8 + Belkin F8T017 -> Can't read class of adapter

Hi Stuart,

> I hope that the quirk will make it into 2.6.27.
>
> :; cat /proc/bus/usb/devices
>
> T: Bus=01 Lev=02 Prnt=03 Port=02 Cnt=03 Dev#= 6 Spd=12 MxCh= 0
> D: Ver= 2.00 Cls=e0(unk. ) Sub=01 Prot=01 MxPS=64 #Cfgs= 1
> P: Vendor=050d ProdID=0017 Rev= 2.91
> S: Manufacturer=Broadcom Corp
> S: Product=BLUETOOTH USB +EDR ADAPTER Class 1 v2.1 UHE
> S: SerialNumber=000A3A8494D9
> C:* #Ifs= 4 Cfg#= 1 Atr=a0 MxPwr= 2mA
> I:* If#= 0 Alt= 0 #EPs= 3 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
> E: Ad=81(I) Atr=03(Int.) MxPS= 16 Ivl=1ms
> E: Ad=82(I) Atr=02(Bulk) MxPS= 64 Ivl=0ms
> E: Ad=02(O) Atr=02(Bulk) MxPS= 64 Ivl=0ms
> I:* If#= 1 Alt= 0 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
> E: Ad=83(I) Atr=01(Isoc) MxPS= 0 Ivl=1ms
> E: Ad=03(O) Atr=01(Isoc) MxPS= 0 Ivl=1ms
> I: If#= 1 Alt= 1 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
> E: Ad=83(I) Atr=01(Isoc) MxPS= 9 Ivl=1ms
> E: Ad=03(O) Atr=01(Isoc) MxPS= 9 Ivl=1ms
> I: If#= 1 Alt= 2 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
> E: Ad=83(I) Atr=01(Isoc) MxPS= 17 Ivl=1ms
> E: Ad=03(O) Atr=01(Isoc) MxPS= 17 Ivl=1ms
> I: If#= 1 Alt= 3 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
> E: Ad=83(I) Atr=01(Isoc) MxPS= 32 Ivl=1ms
> E: Ad=03(O) Atr=01(Isoc) MxPS= 32 Ivl=1ms
> I: If#= 1 Alt= 4 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
> E: Ad=83(I) Atr=01(Isoc) MxPS= 64 Ivl=1ms
> E: Ad=03(O) Atr=01(Isoc) MxPS= 64 Ivl=1ms
> I: If#= 1 Alt= 5 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
> E: Ad=83(I) Atr=01(Isoc) MxPS= 64 Ivl=1ms
> E: Ad=03(O) Atr=01(Isoc) MxPS= 64 Ivl=1ms
> I:* If#= 2 Alt= 0 #EPs= 2 Cls=ff(vend.) Sub=ff Prot=ff Driver=(none)
> E: Ad=84(I) Atr=02(Bulk) MxPS= 32 Ivl=0ms
> E: Ad=04(O) Atr=02(Bulk) MxPS= 32 Ivl=0ms
> I:* If#= 3 Alt= 0 #EPs= 0 Cls=fe(app. ) Sub=01 Prot=00 Driver=(none)

I doubt it since it is not in yet. Show me the output of hciconfig -a
for this so I can create a patch for it.

What is the exact model number of this one. Do you have to have a link
to the product website by any chance.

Regards

Marcel



2008-10-06 21:55:10

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez/git + 2.6.27-rc8 + Belkin F8T017 -> Can't read class of adapter

hi Marcel

> loas btusb or hci_usb with reset=1 and show me the content
> of /proc/bus/usb/devices to add a permanent quirk.

I forgot to "hciconfig hci0 down", that's why I had to reboot.

: root@kooka; modprobe -v btusb reset=1
insmod /lib/modules/2.6.27-rc8/kernel/drivers/bluetooth/btusb.ko reset=1

I suppose that I have to repair my headset (though bluetoothd doesn't say this)
to get it to work with this new dongle. Time to install bluez-gnome-1.8. I had
to use bluetooth-wizard to pair with the device. Running aplay did not make
bluetooth-applet open and ask me to pair (even though I had the headset in
pairing mode).

My Jabra JX10 Series II headset now works. It even works with the VoIP
client twinkle http://www.twinklephone.com/.

Many thanks! Extra!

I hope that the quirk will make it into 2.6.27.

:; cat /proc/bus/usb/devices

T: Bus=08 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=480 MxCh= 6
B: Alloc= 0/800 us ( 0%), #Int= 0, #Iso= 0
D: Ver= 2.00 Cls=09(hub ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1
P: Vendor=1d6b ProdID=0002 Rev= 2.06
S: Manufacturer=Linux 2.6.27-rc8 ehci_hcd
S: Product=EHCI Host Controller
S: SerialNumber=0000:00:1d.7
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 4 Ivl=256ms

T: Bus=07 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=12 MxCh= 2
B: Alloc= 0/900 us ( 0%), #Int= 0, #Iso= 0
D: Ver= 1.10 Cls=09(hub ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1
P: Vendor=1d6b ProdID=0001 Rev= 2.06
S: Manufacturer=Linux 2.6.27-rc8 uhci_hcd
S: Product=UHCI Host Controller
S: SerialNumber=0000:00:1d.2
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 2 Ivl=255ms

T: Bus=06 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=12 MxCh= 2
B: Alloc= 0/900 us ( 0%), #Int= 0, #Iso= 0
D: Ver= 1.10 Cls=09(hub ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1
P: Vendor=1d6b ProdID=0001 Rev= 2.06
S: Manufacturer=Linux 2.6.27-rc8 uhci_hcd
S: Product=UHCI Host Controller
S: SerialNumber=0000:00:1d.1
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 2 Ivl=255ms

T: Bus=05 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=12 MxCh= 2
B: Alloc= 0/900 us ( 0%), #Int= 0, #Iso= 0
D: Ver= 1.10 Cls=09(hub ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1
P: Vendor=1d6b ProdID=0001 Rev= 2.06
S: Manufacturer=Linux 2.6.27-rc8 uhci_hcd
S: Product=UHCI Host Controller
S: SerialNumber=0000:00:1d.0
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 2 Ivl=255ms

T: Bus=04 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=480 MxCh= 6
B: Alloc= 4/800 us ( 1%), #Int= 8, #Iso= 0
D: Ver= 2.00 Cls=09(hub ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1
P: Vendor=1d6b ProdID=0002 Rev= 2.06
S: Manufacturer=Linux 2.6.27-rc8 ehci_hcd
S: Product=EHCI Host Controller
S: SerialNumber=0000:00:1a.7
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 4 Ivl=256ms

T: Bus=04 Lev=01 Prnt=01 Port=00 Cnt=01 Dev#= 2 Spd=480 MxCh= 4
D: Ver= 2.00 Cls=09(hub ) Sub=00 Prot=02 MxPS=64 #Cfgs= 1
P: Vendor=0424 ProdID=2504 Rev= 0.01
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 2mA
I: If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=01 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 1 Ivl=256ms
I:* If#= 0 Alt= 1 #EPs= 1 Cls=09(hub ) Sub=00 Prot=02 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 1 Ivl=256ms

T: Bus=04 Lev=02 Prnt=02 Port=00 Cnt=01 Dev#= 5 Spd=12 MxCh= 3
D: Ver= 1.10 Cls=09(hub ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=05ac ProdID=1003 Rev= 4.10
S: Manufacturer=Mitsumi Electric
S: Product=Hub in Apple Extended USB Keyboard
C:* #Ifs= 1 Cfg#= 1 Atr=a0 MxPwr= 50mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 1 Ivl=255ms

T: Bus=04 Lev=03 Prnt=05 Port=01 Cnt=01 Dev#= 9 Spd=1.5 MxCh= 0
D: Ver= 1.10 Cls=00(>ifc ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=045e ProdID=0040 Rev= 3.00
S: Manufacturer=Microsoft
S: Product=Microsoft 3-Button Mouse with IntelliEye(TM)
C:* #Ifs= 1 Cfg#= 1 Atr=a0 MxPwr=100mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=03(HID ) Sub=01 Prot=02 Driver=usbhid
E: Ad=81(I) Atr=03(Int.) MxPS= 4 Ivl=10ms

T: Bus=04 Lev=03 Prnt=05 Port=02 Cnt=02 Dev#= 10 Spd=12 MxCh= 0
D: Ver= 1.10 Cls=00(>ifc ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=05ac ProdID=020b Rev= 4.10
S: Manufacturer=Mitsumi Electric
S: Product=Apple Extended USB Keyboard
C:* #Ifs= 2 Cfg#= 1 Atr=a0 MxPwr= 50mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=03(HID ) Sub=01 Prot=01 Driver=usbhid
E: Ad=81(I) Atr=03(Int.) MxPS= 8 Ivl=10ms
I:* If#= 1 Alt= 0 #EPs= 1 Cls=03(HID ) Sub=00 Prot=00 Driver=usbhid
E: Ad=82(I) Atr=03(Int.) MxPS= 4 Ivl=10ms

T: Bus=04 Lev=01 Prnt=01 Port=04 Cnt=02 Dev#= 3 Spd=480 MxCh= 4
D: Ver= 2.00 Cls=09(hub ) Sub=00 Prot=02 MxPS=64 #Cfgs= 1
P: Vendor=050d ProdID=0231 Rev= 0.07
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr=100mA
I: If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=01 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 1 Ivl=256ms
I:* If#= 0 Alt= 1 #EPs= 1 Cls=09(hub ) Sub=00 Prot=02 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 1 Ivl=256ms

T: Bus=04 Lev=02 Prnt=03 Port=01 Cnt=01 Dev#= 6 Spd=12 MxCh= 0
D: Ver= 1.00 Cls=00(>ifc ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=0a92 ProdID=0071 Rev= 1.00
S: Manufacturer=AUDIOTRAK
S: Product=MAYA7.1 USB
C:* #Ifs= 2 Cfg#= 1 Atr=80 MxPwr=250mA
I:* If#= 0 Alt= 0 #EPs= 0 Cls=01(audio) Sub=01 Prot=00 Driver=snd-usb-audio
I:* If#= 1 Alt= 0 #EPs= 0 Cls=01(audio) Sub=02 Prot=00 Driver=snd-usb-audio
I: If#= 1 Alt= 1 #EPs= 1 Cls=01(audio) Sub=02 Prot=00 Driver=snd-usb-audio
E: Ad=01(O) Atr=09(Isoc) MxPS= 768 Ivl=1ms

T: Bus=04 Lev=02 Prnt=03 Port=02 Cnt=02 Dev#= 7 Spd=12 MxCh= 3
D: Ver= 1.10 Cls=09(hub ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=2222 ProdID=0200 Rev= 0.01
S: Manufacturer=Macally
S: Product=Macally iKey
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr=100mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 1 Ivl=255ms

T: Bus=04 Lev=03 Prnt=07 Port=00 Cnt=01 Dev#= 11 Spd=12 MxCh= 0
D: Ver= 1.10 Cls=00(>ifc ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=2222 ProdID=0003 Rev= 0.01
S: Manufacturer=Macally
S: Product=Macally iKey
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=03(HID ) Sub=01 Prot=01 Driver=usbhid
E: Ad=81(I) Atr=03(Int.) MxPS= 8 Ivl=10ms

T: Bus=04 Lev=02 Prnt=03 Port=03 Cnt=03 Dev#= 8 Spd=12 MxCh= 0
D: Ver= 1.10 Cls=ff(vend.) Sub=00 Prot=ff MxPS= 8 #Cfgs= 1
P: Vendor=04a9 ProdID=220d Rev= 1.00
S: Manufacturer=Canon
S: Product=CanoScan
C:* #Ifs= 1 Cfg#= 1 Atr=a0 MxPwr=500mA
I:* If#= 0 Alt= 0 #EPs= 3 Cls=ff(vend.) Sub=00 Prot=ff Driver=(none)
E: Ad=81(I) Atr=03(Int.) MxPS= 1 Ivl=16ms
E: Ad=82(I) Atr=02(Bulk) MxPS= 64 Ivl=0ms
E: Ad=03(O) Atr=02(Bulk) MxPS= 64 Ivl=0ms

T: Bus=03 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=12 MxCh= 2
B: Alloc= 0/900 us ( 0%), #Int= 2, #Iso= 0
D: Ver= 1.10 Cls=09(hub ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1
P: Vendor=1d6b ProdID=0001 Rev= 2.06
S: Manufacturer=Linux 2.6.27-rc8 uhci_hcd
S: Product=UHCI Host Controller
S: SerialNumber=0000:00:1a.2
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 2 Ivl=255ms

T: Bus=03 Lev=01 Prnt=01 Port=01 Cnt=01 Dev#= 2 Spd=12 MxCh= 4
D: Ver= 1.01 Cls=09(hub ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=05e3 ProdID=0604 Rev= 0.12
S: Product=USB Hub
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr=100mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 1 Ivl=255ms

T: Bus=03 Lev=02 Prnt=02 Port=01 Cnt=01 Dev#= 3 Spd=12 MxCh= 0
D: Ver= 1.10 Cls=00(>ifc ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1
P: Vendor=0d8c ProdID=000c Rev= 1.00
S: Product=C-Media USB Headphone Set
C:* #Ifs= 4 Cfg#= 1 Atr=a0 MxPwr=100mA
I:* If#= 0 Alt= 0 #EPs= 0 Cls=01(audio) Sub=01 Prot=00 Driver=snd-usb-audio
I:* If#= 1 Alt= 0 #EPs= 0 Cls=01(audio) Sub=02 Prot=00 Driver=snd-usb-audio
I: If#= 1 Alt= 1 #EPs= 1 Cls=01(audio) Sub=02 Prot=00 Driver=snd-usb-audio
E: Ad=01(O) Atr=09(Isoc) MxPS= 200 Ivl=1ms
I:* If#= 2 Alt= 0 #EPs= 0 Cls=01(audio) Sub=02 Prot=00 Driver=snd-usb-audio
I: If#= 2 Alt= 1 #EPs= 1 Cls=01(audio) Sub=02 Prot=00 Driver=snd-usb-audio
E: Ad=82(I) Atr=05(Isoc) MxPS= 100 Ivl=1ms
I:* If#= 3 Alt= 0 #EPs= 1 Cls=03(HID ) Sub=00 Prot=00 Driver=usbhid
E: Ad=83(I) Atr=03(Int.) MxPS= 4 Ivl=32ms

T: Bus=03 Lev=02 Prnt=02 Port=02 Cnt=02 Dev#= 4 Spd=12 MxCh= 0
D: Ver= 1.10 Cls=00(>ifc ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=10d6 ProdID=1100 Rev= 1.00
S: Product=USB 2.0(FS) FLASH DISK
S: SerialNumber=USB 2.0(FS) FLASH DISK
C:* #Ifs= 1 Cfg#= 1 Atr=80 MxPwr=100mA
I:* If#= 0 Alt= 0 #EPs= 2 Cls=08(stor.) Sub=05 Prot=50 Driver=usb-storage
E: Ad=01(O) Atr=02(Bulk) MxPS= 64 Ivl=0ms
E: Ad=82(I) Atr=02(Bulk) MxPS= 64 Ivl=0ms

T: Bus=02 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=12 MxCh= 2
B: Alloc= 0/900 us ( 0%), #Int= 0, #Iso= 0
D: Ver= 1.10 Cls=09(hub ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1
P: Vendor=1d6b ProdID=0001 Rev= 2.06
S: Manufacturer=Linux 2.6.27-rc8 uhci_hcd
S: Product=UHCI Host Controller
S: SerialNumber=0000:00:1a.1
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 2 Ivl=255ms

T: Bus=01 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=12 MxCh= 2
B: Alloc= 27/900 us ( 3%), #Int= 4, #Iso= 0
D: Ver= 1.10 Cls=09(hub ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1
P: Vendor=1d6b ProdID=0001 Rev= 2.06
S: Manufacturer=Linux 2.6.27-rc8 uhci_hcd
S: Product=UHCI Host Controller
S: SerialNumber=0000:00:1a.0
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 2 Ivl=255ms

T: Bus=01 Lev=01 Prnt=01 Port=01 Cnt=01 Dev#= 3 Spd=12 MxCh= 3
D: Ver= 2.00 Cls=09(hub ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=0a5c ProdID=4500 Rev= 1.00
S: Manufacturer=Broadcom
S: Product=BCM2046B1
C:* #Ifs= 1 Cfg#= 1 Atr=a0 MxPwr= 94mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
E: Ad=81(I) Atr=03(Int.) MxPS= 1 Ivl=255ms

T: Bus=01 Lev=02 Prnt=03 Port=00 Cnt=01 Dev#= 4 Spd=12 MxCh= 0
D: Ver= 2.00 Cls=00(>ifc ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=0a5c ProdID=4502 Rev= 1.00
C:* #Ifs= 1 Cfg#= 1 Atr=a0 MxPwr= 2mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=03(HID ) Sub=01 Prot=01 Driver=usbhid
E: Ad=81(I) Atr=03(Int.) MxPS= 8 Ivl=10ms

T: Bus=01 Lev=02 Prnt=03 Port=01 Cnt=02 Dev#= 5 Spd=12 MxCh= 0
D: Ver= 2.00 Cls=00(>ifc ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
P: Vendor=0a5c ProdID=4503 Rev= 1.00
C:* #Ifs= 1 Cfg#= 1 Atr=a0 MxPwr= 2mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=03(HID ) Sub=01 Prot=02 Driver=usbhid
E: Ad=81(I) Atr=03(Int.) MxPS= 4 Ivl=10ms

T: Bus=01 Lev=02 Prnt=03 Port=02 Cnt=03 Dev#= 6 Spd=12 MxCh= 0
D: Ver= 2.00 Cls=e0(unk. ) Sub=01 Prot=01 MxPS=64 #Cfgs= 1
P: Vendor=050d ProdID=0017 Rev= 2.91
S: Manufacturer=Broadcom Corp
S: Product=BLUETOOTH USB +EDR ADAPTER Class 1 v2.1 UHE
S: SerialNumber=000A3A8494D9
C:* #Ifs= 4 Cfg#= 1 Atr=a0 MxPwr= 2mA
I:* If#= 0 Alt= 0 #EPs= 3 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
E: Ad=81(I) Atr=03(Int.) MxPS= 16 Ivl=1ms
E: Ad=82(I) Atr=02(Bulk) MxPS= 64 Ivl=0ms
E: Ad=02(O) Atr=02(Bulk) MxPS= 64 Ivl=0ms
I:* If#= 1 Alt= 0 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
E: Ad=83(I) Atr=01(Isoc) MxPS= 0 Ivl=1ms
E: Ad=03(O) Atr=01(Isoc) MxPS= 0 Ivl=1ms
I: If#= 1 Alt= 1 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
E: Ad=83(I) Atr=01(Isoc) MxPS= 9 Ivl=1ms
E: Ad=03(O) Atr=01(Isoc) MxPS= 9 Ivl=1ms
I: If#= 1 Alt= 2 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
E: Ad=83(I) Atr=01(Isoc) MxPS= 17 Ivl=1ms
E: Ad=03(O) Atr=01(Isoc) MxPS= 17 Ivl=1ms
I: If#= 1 Alt= 3 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
E: Ad=83(I) Atr=01(Isoc) MxPS= 32 Ivl=1ms
E: Ad=03(O) Atr=01(Isoc) MxPS= 32 Ivl=1ms
I: If#= 1 Alt= 4 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
E: Ad=83(I) Atr=01(Isoc) MxPS= 64 Ivl=1ms
E: Ad=03(O) Atr=01(Isoc) MxPS= 64 Ivl=1ms
I: If#= 1 Alt= 5 #EPs= 2 Cls=e0(unk. ) Sub=01 Prot=01 Driver=btusb
E: Ad=83(I) Atr=01(Isoc) MxPS= 64 Ivl=1ms
E: Ad=03(O) Atr=01(Isoc) MxPS= 64 Ivl=1ms
I:* If#= 2 Alt= 0 #EPs= 2 Cls=ff(vend.) Sub=ff Prot=ff Driver=(none)
E: Ad=84(I) Atr=02(Bulk) MxPS= 32 Ivl=0ms
E: Ad=04(O) Atr=02(Bulk) MxPS= 32 Ivl=0ms
I:* If#= 3 Alt= 0 #EPs= 0 Cls=fe(app. ) Sub=01 Prot=00 Driver=(none)

: root@kooka; src/.libs/bluetoothd -dn
bluetoothd[4605]: Bluetooth daemon
bluetoothd[4605]: Enabling debug information
bluetoothd[4605]: parsing main.conf
bluetoothd[4605]: offmode=NoScan
bluetoothd[4605]: discovto=0
bluetoothd[4605]: pageto=8192
bluetoothd[4605]: name=%h-%d
bluetoothd[4605]: class=0x000100
bluetoothd[4605]: inqmode=0
bluetoothd[4605]: Starting SDP server
bluetoothd[4605]: Loading plugins /home/stuart/ws/install/bluez/git/bluez/plugins
bluetoothd[4605]: /home/stuart/ws/install/bluez/git/bluez/plugins/audio.so
bluetoothd[4605]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory
bluetoothd[4605]: Unix socket created: 11
bluetoothd[4605]: Telephony plugin initialized
bluetoothd[4605]: HFP AG features: "Ability to reject a call" "Enhanced call status" "Extended Error Result Codes"
bluetoothd[4605]: /home/stuart/ws/install/bluez/git/bluez/plugins/serial.so
bluetoothd[4605]: /home/stuart/ws/install/bluez/git/bluez/plugins/hal.so
bluetoothd[4605]: /home/stuart/ws/install/bluez/git/bluez/plugins/service.so
bluetoothd[4605]: /home/stuart/ws/install/bluez/git/bluez/plugins/network.so
bluetoothd[4605]: Parsing /etc/bluetooth/network.conf failed: No such file or directory
bluetoothd[4605]: Config options: InterfacePrefix=bnep%d, PANU_Script=(null), GN_Script=(null), NAP_Script=(null), GN_Interface=pan0, NAP_Interface=pan1, Security=true
bluetoothd[4605]: bridge pan0 created
bluetoothd[4605]: /home/stuart/ws/install/bluez/git/bluez/plugins/input.so
bluetoothd[4605]: input.conf: Key file does not have key 'IdleTimeout'
bluetoothd[4605]: HCI dev 0 registered
bluetoothd[4605]: child 4614 forked
bluetoothd[4605]: HCI dev 0 already up
bluetoothd[4605]: headset_server_probe: path /org/bluez/hci0
bluetoothd[4605]: Adding record with handle 0x10000
bluetoothd[4605]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 00001108-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 00001112-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 00001203-0000-1000-8000-00805f9
bluetoothd[4605]: Adding record with handle 0x10001
bluetoothd[4605]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 0000111e-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 0000111f-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 00001203-0000-1000-8000-00805f9
bluetoothd[4605]: a2dp_server_probe: path /org/bluez/hci0
bluetoothd[4605]: SEP 0xb8ec4790 registered: type:0 codec:0 seid:1
bluetoothd[4605]: Adding record with handle 0x10002
bluetoothd[4605]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 0000110a-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 0000110d-0000-1000-8000-00805f9
bluetoothd[4605]: avrcp_server_probe: path /org/bluez/hci0
bluetoothd[4605]: Adding record with handle 0x10003
bluetoothd[4605]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 0000110c-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 0000110e-0000-1000-8000-00805f9
bluetoothd[4605]: Adding record with handle 0x10004
bluetoothd[4605]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 0000110e-0000-1000-8000-00805f9
bluetoothd[4605]: proxy_probe: path /org/bluez/hci0
bluetoothd[4605]: Registered interface org.bluez.SerialProxyManager on path /org/bluez/hci0
bluetoothd[4605]: service_probe: path /org/bluez/hci0
bluetoothd[4605]: Registered interface org.bluez.Service on path /org/bluez/hci0
bluetoothd[4605]: network_server_probe: path /org/bluez/hci0
bluetoothd[4605]: Adding record with handle 0x10005
bluetoothd[4605]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 00001115-0000-1000-8000-00805f9
bluetoothd[4605]: register_server_record: got record id 0x10005
bluetoothd[4605]: Registered interface org.bluez.NetworkPeer on path /org/bluez/hci0
bluetoothd[4605]: network_server_probe: path /org/bluez/hci0
bluetoothd[4605]: Adding record with handle 0x10006
bluetoothd[4605]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 00001117-0000-1000-8000-00805f9
bluetoothd[4605]: register_server_record: got record id 0x10006
bluetoothd[4605]: Registered interface org.bluez.NetworkHub on path /org/bluez/hci0
bluetoothd[4605]: network_server_probe: path /org/bluez/hci0
bluetoothd[4605]: Adding record with handle 0x10007
bluetoothd[4605]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4605]: Record pattern UUID 00001116-0000-1000-8000-00805f9
bluetoothd[4605]: register_server_record: got record id 0x10007
bluetoothd[4605]: Registered interface org.bluez.NetworkRouter on path /org/bluez/hci0
bluetoothd[4605]: Adapter /org/bluez/hci0 has been enabled
bluetoothd[4605]: Starting security manager 0
bluetoothd[4605]: child 4614 exited
bluetoothd[4605]: Computer is classified as desktop
bluetoothd[4605]: Current device class is 0x4a0104
bluetoothd[4605]: Setting 0x000104 for major/minor device class
bluetoothd[4605]: Accepted new client connection on unix socket (fd=23)
bluetoothd[4605]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[4605]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[4605]: Unix client disconnected (fd=23)
bluetoothd[4605]: Accepted new client connection on unix socket (fd=23)
bluetoothd[4605]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[4605]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[4605]: Unix client disconnected (fd=23)
bluetoothd[4605]: Accepted new client connection on unix socket (fd=23)
bluetoothd[4605]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[4605]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[4605]: Unix client disconnected (fd=23)
bluetoothd[4605]: Accepted new client connection on unix socket (fd=23)
bluetoothd[4605]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[4605]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[4605]: Unix client disconnected (fd=23)
bluetoothd[4605]: Accepted new client connection on unix socket (fd=23)
bluetoothd[4605]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[4605]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[4605]: Unix client disconnected (fd=23)

2008-10-06 21:21:46

by Marcel Holtmann

[permalink] [raw]
Subject: Re: bluez/git + 2.6.27-rc8 + SCO headset -> SIGSEGV

Hi Stuart,

> >>> however could you try to get a backtrace with gdb as well since it seems
> >>> that valgrind either distorts or hides some errors.
> >> I guess that I have forgotten how to use gdb because the backtrace
> >> doesn't tell me much. Or perhaps I have to recompile with "-g".
> > if you use ./bootstrap-configure it will automatically enable it. If not
> > then give --enable-debug to configure. And make sure you do a make clean
> > before that.
>
> This what I did (from history)
>
> 17 git clone git://git.kernel.org/pub/scm/bluetooth/bluez.git && cd bluez && ./bootstrap-configure && make
> 18 ./bootstrap-configure && make
>
> I ran the bootstrap-configure twice because I had to install gtk-doc.
>
> :; grep ' -g' Makefile
> CFLAGS = -Wall -O2 -D_FORTIFY_SOURCE=2 -fPIC -g -O0

that is indeed strange. You should be able to get a proper backtrace.

> I thus think that I did compile with -g and that I cannot get a stack trace
> because someone has written all over the stack.
>
> [I'm trying to remove btusb but I think that I'll need a reboot
> :; lsmod | grep btusb
> btusb 12056 11465
> bluetooth 49632 1 btusb
> ]

Normally hciconfig hci0 down and killing bluetoothd should be enough.

Regards

Marcel



2008-10-06 21:10:49

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez/git + 2.6.27-rc8 + SCO headset -> SIGSEGV

hi Marcel

>>> however could you try to get a backtrace with gdb as well since it seems
>>> that valgrind either distorts or hides some errors.
>> I guess that I have forgotten how to use gdb because the backtrace
>> doesn't tell me much. Or perhaps I have to recompile with "-g".
> if you use ./bootstrap-configure it will automatically enable it. If not
> then give --enable-debug to configure. And make sure you do a make clean
> before that.

This what I did (from history)

17 git clone git://git.kernel.org/pub/scm/bluetooth/bluez.git && cd bluez && ./bootstrap-configure && make
18 ./bootstrap-configure && make

I ran the bootstrap-configure twice because I had to install gtk-doc.

:; grep ' -g' Makefile
CFLAGS = -Wall -O2 -D_FORTIFY_SOURCE=2 -fPIC -g -O0

I thus think that I did compile with -g and that I cannot get a stack trace
because someone has written all over the stack.

[I'm trying to remove btusb but I think that I'll need a reboot
:; lsmod | grep btusb
btusb 12056 11465
bluetooth 49632 1 btusb
]

Stuart

2008-10-06 21:03:10

by Marcel Holtmann

[permalink] [raw]
Subject: Re: bluez/git + 2.6.27-rc8 + SCO headset -> SIGSEGV

Hi Stuart,

> > however could you try to get a backtrace with gdb as well since it seems
> > that valgrind either distorts or hides some errors.
>
> I guess that I have forgotten how to use gdb because the backtrace
> doesn't tell me much. Or perhaps I have to recompile with "-g".

if you use ./bootstrap-configure it will automatically enable it. If not
then give --enable-debug to configure. And make sure you do a make clean
before that.

Regards

Marcel



2008-10-06 20:56:06

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez/git + 2.6.27-rc8 + SCO headset -> SIGSEGV

hi Johan

> however could you try to get a backtrace with gdb as well since it seems
> that valgrind either distorts or hides some errors.

I guess that I have forgotten how to use gdb because the backtrace
doesn't tell me much. Or perhaps I have to recompile with "-g".

: root@kooka; gdb src/.libs/bluetoothd
GNU gdb 6.8-debian
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "i486-linux-gnu"...
(gdb) run -dn
Starting program: /ws/stuart/install/bluez/git/bluez/src/.libs/bluetoothd -dn
bluetoothd[4220]: Bluetooth daemon
bluetoothd[4220]: Enabling debug information
bluetoothd[4220]: parsing main.conf
bluetoothd[4220]: offmode=NoScan
bluetoothd[4220]: discovto=0
bluetoothd[4220]: pageto=8192
bluetoothd[4220]: name=%h-%d
bluetoothd[4220]: class=0x000100
bluetoothd[4220]: inqmode=0
bluetoothd[4220]: Starting SDP server
bluetoothd[4220]: Loading plugins /home/stuart/ws/install/bluez/git/bluez/plugins
bluetoothd[4220]: /home/stuart/ws/install/bluez/git/bluez/plugins/audio.so
bluetoothd[4220]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory
bluetoothd[4220]: Unix socket created: 13
bluetoothd[4220]: Telephony plugin initialized
bluetoothd[4220]: HFP AG features: "Ability to reject a call" "Enhanced call status" "Extended Error Result Codes"
bluetoothd[4220]: /home/stuart/ws/install/bluez/git/bluez/plugins/serial.so
bluetoothd[4220]: /home/stuart/ws/install/bluez/git/bluez/plugins/hal.so
bluetoothd[4220]: /home/stuart/ws/install/bluez/git/bluez/plugins/service.so
bluetoothd[4220]: /home/stuart/ws/install/bluez/git/bluez/plugins/network.so
bluetoothd[4220]: Parsing /etc/bluetooth/network.conf failed: No such file or directory
bluetoothd[4220]: Config options: InterfacePrefix=bnep%d, PANU_Script=(null), GN_Script=(null), NAP_Script=(null), GN_Interface=pan0, NAP_Interface=pan1, Security=true
bluetoothd[4220]: Can't create GN bridge
bluetoothd[4220]: /home/stuart/ws/install/bluez/git/bluez/plugins/input.so
bluetoothd[4220]: input.conf: Key file does not have key 'IdleTimeout'
bluetoothd[4220]: HCI dev 0 registered
bluetoothd[4220]: child 4223 forked
bluetoothd[4220]: HCI dev 0 already up
bluetoothd[4220]: headset_server_probe: path /org/bluez/hci0
bluetoothd[4220]: Adding record with handle 0x10000
bluetoothd[4220]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 00001108-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 00001112-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 00001203-0000-1000-8000-00805f9
bluetoothd[4220]: Adding record with handle 0x10001
bluetoothd[4220]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 0000111e-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 0000111f-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 00001203-0000-1000-8000-00805f9
bluetoothd[4220]: a2dp_server_probe: path /org/bluez/hci0
bluetoothd[4220]: SEP 0xb90df780 registered: type:0 codec:0 seid:1
bluetoothd[4220]: Adding record with handle 0x10002
bluetoothd[4220]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 0000110a-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 0000110d-0000-1000-8000-00805f9
bluetoothd[4220]: avrcp_server_probe: path /org/bluez/hci0
bluetoothd[4220]: Adding record with handle 0x10003
bluetoothd[4220]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 0000110c-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 0000110e-0000-1000-8000-00805f9
bluetoothd[4220]: Adding record with handle 0x10004
bluetoothd[4220]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 0000110e-0000-1000-8000-00805f9
bluetoothd[4220]: proxy_probe: path /org/bluez/hci0
bluetoothd[4220]: Registered interface org.bluez.SerialProxyManager on path /org/bluez/hci0
bluetoothd[4220]: service_probe: path /org/bluez/hci0
bluetoothd[4220]: Registered interface org.bluez.Service on path /org/bluez/hci0
bluetoothd[4220]: network_server_probe: path /org/bluez/hci0
bluetoothd[4220]: Adding record with handle 0x10005
bluetoothd[4220]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 00001115-0000-1000-8000-00805f9
bluetoothd[4220]: register_server_record: got record id 0x10005
bluetoothd[4220]: Registered interface org.bluez.NetworkPeer on path /org/bluez/hci0
bluetoothd[4220]: network_server_probe: path /org/bluez/hci0
bluetoothd[4220]: Adding record with handle 0x10006
bluetoothd[4220]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 00001117-0000-1000-8000-00805f9
bluetoothd[4220]: register_server_record: got record id 0x10006
bluetoothd[4220]: Registered interface org.bluez.NetworkHub on path /org/bluez/hci0
bluetoothd[4220]: network_server_probe: path /org/bluez/hci0
bluetoothd[4220]: Adding record with handle 0x10007
bluetoothd[4220]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[4220]: Record pattern UUID 00001116-0000-1000-8000-00805f9
bluetoothd[4220]: register_server_record: got record id 0x10007
bluetoothd[4220]: Registered interface org.bluez.NetworkRouter on path /org/bluez/hci0
bluetoothd[4220]: Creating device /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[4220]: Probe drivers for /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[4220]: Found Headset record
bluetoothd[4220]: Discovered Headset service on RFCOMM channel 2
bluetoothd[4220]: Registered interface org.bluez.Headset on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[4220]: Found Hansfree record
bluetoothd[4220]: Discovered Handsfree service on RFCOMM channel 1
bluetoothd[4220]: headset_probe: path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[4220]: Registered interface org.bluez.Input on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[4220]: Creating device /org/bluez/hci0/dev_00_14_A7_74_D3_AF
bluetoothd[4220]: Creating device /org/bluez/hci0/dev_00_03_89_B7_F8_D3
bluetoothd[4220]: Creating device /org/bluez/hci0/dev_00_0A_94_94_4F_B3
bluetoothd[4220]: Creating device /org/bluez/hci0/dev_00_03_89_DC_5C_9F
bluetoothd[4220]: Creating device /org/bluez/hci0/dev_00_03_89_DC_FC_EC
bluetoothd[4220]: Creating device /org/bluez/hci0/dev_00_03_89_FE_E6_19
bluetoothd[4220]: Creating device /org/bluez/hci0/dev_00_0E_6D_8F_91_6A
bluetoothd[4220]: Creating device /org/bluez/hci0/dev_00_17_E5_E6_25_AB
bluetoothd[4220]: Creating device /org/bluez/hci0/dev_00_17_E5_16_88_6C
bluetoothd[4220]: Creating device /org/bluez/hci0/dev_00_17_E5_0C_EA_70
bluetoothd[4220]: Adapter /org/bluez/hci0 has been enabled
bluetoothd[4220]: Starting security manager 0
bluetoothd[4220]: child 4223 exited
bluetoothd[4220]: Computer is classified as desktop
bluetoothd[4220]: Current device class is 0x4a0104
bluetoothd[4220]: Setting 0x000104 for major/minor device class
bluetoothd[4220]: Accepted new client connection on unix socket (fd=25)
bluetoothd[4220]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[4220]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[4220]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[4220]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[4220]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[4220]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[4220]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[4220]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[4220]: kernel auth requirements = 0x04
bluetoothd[4220]: stored link key type = 0x00
bluetoothd[4220]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[4220]: Received AT+BRSF=27
bluetoothd[4220]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[4220]: Received AT+CIND=?
bluetoothd[4220]: Received AT+CIND?
bluetoothd[4220]: Received AT+CMER=3, 0, 0, 1
bluetoothd[4220]: Event reporting (CMER): mode=3, ind=1
bluetoothd[4220]: HFP Service Level Connection established
bluetoothd[4220]: telephony-dummy: device 0xb90e45f0 connected
bluetoothd[4220]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[4220]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[4220]: Received AT+VGS=15
bluetoothd[4220]: connect(): Connection timed out (110)
bluetoothd[4220]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[4220]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[4220]: Audio API: received BT_STREAMSTART_REQ
bluetoothd[4220]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[4220]: Audio API: sending BT_STREAMFD_IND
bluetoothd[4220]: unix_sendmsg_fd: Bad file descriptor(9)
bluetoothd[4220]: resume failed
bluetoothd[4220]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[4220]: Unix client disconnected (fd=25)
bluetoothd[4220]: No matching connection for handle 45
bluetoothd[4220]: Accepted new client connection on unix socket (fd=25)
bluetoothd[4220]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[4220]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[4220]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[4220]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[4220]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[4220]: Unix client disconnected (fd=25)
bluetoothd[4220]: telephony-dummy: device 0xb90e45f0 disconnected
bluetoothd[4220]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[4220]: Accepted new client connection on unix socket (fd=25)
bluetoothd[4220]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[4220]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[4220]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[4220]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[4220]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[4220]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[4220]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[4220]: Received AT+BRSF=27
bluetoothd[4220]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[4220]: Received AT+CIND=?
bluetoothd[4220]: Received AT+CIND?
bluetoothd[4220]: Received AT+CMER=3, 0, 0, 1
bluetoothd[4220]: Event reporting (CMER): mode=3, ind=1
bluetoothd[4220]: HFP Service Level Connection established
bluetoothd[4220]: telephony-dummy: device 0xb90e45f0 connected
bluetoothd[4220]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[4220]: connect: Operation not permitted (1)
bluetoothd[4220]: config failed
bluetoothd[4220]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[4220]: Unix client disconnected (fd=25)
bluetoothd[4220]: Received AT+VGS=15
bluetoothd[4220]: connect(): Connection timed out (110)

Program received signal SIGSEGV, Segmentation fault.
0xb7deda16 in ?? ()
(gdb) where
#0 0xb7deda16 in ?? ()
#1 0xb7dff1e3 in ?? ()
#2 0xb7f6eda5 in ?? ()
#3 0x0000006e in ?? ()
#4 0xb80319e4 in ?? ()
#5 0xb7f9e86c in ?? ()
#6 0xbfff8d1b in ?? ()
#7 0xbfff8d16 in ?? ()
#8 0xb7f8aff4 in ?? ()
#9 0xb90e45f0 in ?? ()
#10 0xb90e4a40 in ?? ()
#11 0x00000000 in ?? ()
(gdb) bt
#0 0xb7deda16 in ?? ()
#1 0xb7dff1e3 in ?? ()
#2 0xb7f6eda5 in ?? ()
#3 0x0000006e in ?? ()
#4 0xb80319e4 in ?? ()
#5 0xb7f9e86c in ?? ()
#6 0xbfff8d1b in ?? ()
#7 0xbfff8d16 in ?? ()
#8 0xb7f8aff4 in ?? ()
#9 0xb90e45f0 in ?? ()
#10 0xb90e4a40 in ?? ()
#11 0x00000000 in ?? ()


2008-10-06 20:45:44

by Marcel Holtmann

[permalink] [raw]
Subject: Re: bluez/git + 2.6.27-rc8 + Belkin F8T017 -> Can't read class of adapter

Hi Stuart,

> > Why your application gives up prematurely is still unclear to me.
>
> I must admit this what interests me most.
>
> I wondered if it was by old USBBT100 Bluetooth dongle that is causing
> my problems. I thus bought a Belkin F8T017 (Bluetooth v2.1 Class I).
> It works even less than my old Linksys USBBT100.
>
> bluetoothd (from git) says:
>
> bluetoothd[3517]: HCI dev 0 up
> bluetoothd[3517]: Can't read class of adapter on /org/bluez/hci0: Input/output error (5)

loas btusb or hci_usb with reset=1 and show me the content
of /proc/bus/usb/devices to add a permanent quirk.

Regards

Marcel



2008-10-06 20:39:12

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez/git + 2.6.27-rc8 + Belkin F8T017 -> Can't read class of adapter

hi Johan

> Why your application gives up prematurely is still unclear to me.

I must admit this what interests me most.

I wondered if it was by old USBBT100 Bluetooth dongle that is causing
my problems. I thus bought a Belkin F8T017 (Bluetooth v2.1 Class I).
It works even less than my old Linksys USBBT100.

bluetoothd (from git) says:

bluetoothd[3517]: HCI dev 0 up
bluetoothd[3517]: Can't read class of adapter on /org/bluez/hci0: Input/output error (5)

When I unplugged the dongle, bluetoothd also said

bluetoothd[3517]: proxy_remove: path /org/bluez/hci0
process 3517: arguments to dbus_connection_unref() were incorrect, assertion "connection != NULL" failed in file dbus-connection.c line 2645.
This is normally a bug in some application using the D-Bus library.

This dongle appears to contain a hub, a keyboard and a mouse!

Oct 6 21:57:36 kooka kernel: [85228.696180] usb 1-2: new full speed USB device using uhci_hcd and address 9
Oct 6 21:57:36 kooka kernel: [85228.873638] usb 1-2: configuration #1 chosen from 1 choice
Oct 6 21:57:36 kooka kernel: [85228.876578] hub 1-2:1.0: USB hub found
Oct 6 21:57:36 kooka kernel: [85228.878555] hub 1-2:1.0: 3 ports detected
Oct 6 21:57:36 kooka kernel: [85229.104656] usb 1-2: New USB device found, idVendor=0a5c, idProduct=4500
Oct 6 21:57:36 kooka kernel: [85229.104662] usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Oct 6 21:57:36 kooka kernel: [85229.104665] usb 1-2: Product: BCM2046B1
Oct 6 21:57:36 kooka kernel: [85229.104666] usb 1-2: Manufacturer: Broadcom
Oct 6 21:57:37 kooka kernel: [85229.181563] usb 1-2.1: new full speed USB device using uhci_hcd and address 10
Oct 6 21:57:37 kooka kernel: [85229.303641] usb 1-2.1: configuration #1 chosen from 1 choice
Oct 6 21:57:37 kooka kernel: [85229.309775] input: HID 0a5c:4502 as /class/input/input17
Oct 6 21:57:37 kooka kernel: [85229.340573] input,hidraw4: USB HID v1.11 Keyboard [HID 0a5c:4502] on usb-0000:00:1a.0-2.1
Oct 6 21:57:37 kooka kernel: [85229.340669] usb 1-2.1: New USB device found, idVendor=0a5c, idProduct=4502
Oct 6 21:57:37 kooka kernel: [85229.340671] usb 1-2.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Oct 6 21:57:37 kooka kernel: [85229.413569] usb 1-2.2: new full speed USB device using uhci_hcd and address 11
Oct 6 21:57:37 kooka kernel: [85229.533664] usb 1-2.2: configuration #1 chosen from 1 choice
Oct 6 21:57:37 kooka kernel: [85229.540840] input: HID 0a5c:4503 as /class/input/input18
Oct 6 21:57:37 kooka kernel: [85229.580070] input,hidraw6: USB HID v1.11 Mouse [HID 0a5c:4503] on usb-0000:00:1a.0-2.2
Oct 6 21:57:37 kooka kernel: [85229.580166] usb 1-2.2: New USB device found, idVendor=0a5c, idProduct=4503
Oct 6 21:57:37 kooka kernel: [85229.580168] usb 1-2.2: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Oct 6 21:57:37 kooka kernel: [85229.657571] usb 1-2.3: new full speed USB device using uhci_hcd and address 12
Oct 6 21:57:37 kooka kernel: [85229.794657] usb 1-2.3: configuration #1 chosen from 1 choice
Oct 6 21:57:37 kooka kernel: [85229.797922] usb 1-2.3: New USB device found, idVendor=050d, idProduct=0017
Oct 6 21:57:37 kooka kernel: [85229.797926] usb 1-2.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Oct 6 21:57:37 kooka kernel: [85229.797928] usb 1-2.3: Product: BLUETOOTH USB +EDR ADAPTER Class 1 v2.1 UHE
Oct 6 21:57:37 kooka kernel: [85229.797930] usb 1-2.3: Manufacturer: Broadcom Corp
Oct 6 21:57:37 kooka kernel: [85229.797932] usb 1-2.3: SerialNumber: 000A3A8494D9

:; hciconfig -a
hci0: Type: USB
BD Address: 00:0A:3A:84:94:D9 ACL MTU: 1021:8 SCO MTU: 64:1
UP RUNNING
RX bytes:299 acl:0 sco:0 events:25 errors:0
TX bytes:344 acl:0 sco:0 commands:25 errors:0
Features: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x79 0x83
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy:
Link mode: SLAVE ACCEPT
Can't read local name on hci0: Input/output error (5)
:; hciconfig hci0 commands
hci0: Type: USB
BD Address: 00:0A:3A:84:94:D9 ACL MTU: 1021:8 SCO MTU: 64:1
Commands: Octet 0 = 0xff (Bit 0 1 2 3 4 5 6 7)
Octet 1 = 0xff (Bit 0 1 2 3 4 5 6 7)
Octet 2 = 0xff (Bit 0 1 2 3 4 5 6 7)
Octet 3 = 0x03 (Bit 0 1)
Octet 4 = 0xfe (Bit 1 2 3 4 5 6 7)
Octet 5 = 0xff (Bit 0 1 2 3 4 5 6 7)
Octet 6 = 0xef (Bit 0 1 2 3 5 6 7)
Octet 7 = 0xff (Bit 0 1 2 3 4 5 6 7)
Octet 8 = 0xff (Bit 0 1 2 3 4 5 6 7)
Octet 9 = 0xff (Bit 0 1 2 3 4 5 6 7)
Octet 10 = 0xef (Bit 0 1 2 3 5 6 7)
Octet 11 = 0x1f (Bit 0 1 2 3 4)
Octet 12 = 0xf2 (Bit 1 4 5 6 7)
Octet 13 = 0x0f (Bit 0 1 2 3)
Octet 14 = 0xe8 (Bit 3 5 6 7)
Octet 15 = 0xfe (Bit 1 2 3 4 5 6 7)
Octet 16 = 0x3f (Bit 0 1 2 3 4 5)
Octet 17 = 0xf7 (Bit 0 1 2 4 5 6 7)
Octet 18 = 0x8f (Bit 0 1 2 3 7)
Octet 19 = 0xff (Bit 0 1 2 3 4 5 6 7)
Octet 20 = 0x0c (Bit 2 3)
'Inquiry' 'Inquiry Cancel' 'Periodic Inquiry Mode'
'Exit Periodic Inquiry Mode' 'Create Connection' 'Disconnect'
'Add SCO Connection' 'Cancel Create Connection'
'Accept Connection Request' 'Reject Connection Request'
'Link Key Request Reply' 'Link Key Request Negative Reply'
'PIN Code Request Reply' 'PIN Code Request Negative Reply'
'Change Connection Packet Type' 'Authentication Requested'
'Set Connection Encryption' 'Change Connection Link Key'
'Master Link Key' 'Remote Name Request' 'Cancel Remote Name Request'
'Read Remote Supported Features' 'Read Remote Extended Features'
'Read Remote Version Information' 'Read Clock Offset'
'Read LMP Handle' 'Hold Mode' 'Sniff Mode' 'Exit Sniff Mode'
'Park State' 'Exit Park State' 'QoS Setup' 'Role Discovery'
'Switch Role' 'Read Link Policy Settings' 'Write Link Policy Settings'
'Read Default Link Policy Settings'
'Write Default Link Policy Settings' 'Flow Specification'
'Set Event Mask' 'Reset' 'Set Event Filter' 'Flush' 'Read PIN Type'
'Write PIN Type' 'Read Stored Link Key' 'Write Stored Link Key'
'Delete Stored Link Key' 'Write Local Name' 'Read Local Name'
'Read Connection Accept Timeout' 'Write Connection Accept Timeout'
'Read Page Timeout' 'Write Page Timeout' 'Read Scan Enable'
'Write Scan Enable' 'Read Page Scan Activity'
'Write Page Scan Activity' 'Read Inquiry Scan Activity'
'Write Inquiry Scan Activity' 'Read Authentication Enable'
'Write Authentication Enable' 'Read Encryption Mode'
'Write Encryption Mode' 'Read Class Of Device' 'Write Class Of Device'
'Read Voice Setting' 'Write Voice Setting'
'Read Automatic Flush Timeout' 'Write Automatic Flush Timeout'
'Read Num Broadcast Retransmissions'
'Write Num Broadcast Retransmissions' 'Read Hold Mode Activity'
'Write Hold Mode Activity' 'Read Transmit Power Level'
'Read Synchronous Flow Control Enable'
'Set Host Controller To Host Flow Control' 'Host Buffer Size'
'Host Number Of Completed Packets' 'Read Link Supervision Timeout'
'Write Link Supervision Timeout' 'Read Number of Supported IAC'
'Read Current IAC LAP' 'Write Current IAC LAP'
'Set AFH Channel Classification' 'Read Inquiry Scan Type'
'Write Inquiry Scan Type' 'Read Inquiry Mode' 'Write Inquiry Mode'
'Read Page Scan Type' 'Write Page Scan Type'
'Read AFH Channel Assessment Mode' 'Write AFH Channel Assessment Mode'
'Read Local Version Information' 'Read Local Supported Features'
'Read Local Extended Features' 'Read Buffer Size' 'Read BD ADDR'
'Read Failed Contact Counter' 'Reset Failed Contact Counter'
'Get Link Quality' 'Read RSSI' 'Read AFH Channel Map' 'Read BD Clock'
'Read Loopback Mode' 'Write Loopback Mode'
'Enable Device Under Test Mode' 'Setup Synchronous Connection'
'Accept Synchronous Connection' 'Reject Synchronous Connection'
'Read Extended Inquiry Response' 'Write Extended Inquiry Response'
'Refresh Encryption Key' 'Sniff Subrating' 'Read Simple Pairing Mode'
'Write Simple Pairing Mode' 'Read Local OOB Data'
'Read Inquiry Transmit Power Level'
'Write Inquiry Transmit Power Level'
'Read Default Erroneous Data Reporting'
'Write Default Erroneous Data Reporting' 'IO Capability Request Reply'
'User Confirmation Request Reply'
'User Confirmation Request Negative Reply'
'User Passkey Request Reply' 'User Passkey Request Negative Reply'
'Remote OOB Data Request Reply' 'Write Simple Pairing Debug Mode'
'Enhanced Flush' 'Remote OOB Data Request Negative Reply'
'Send Keypress Notification' 'IO Capabilities Response Negative Reply'
:; hciconfig hci0 features
hci0: Type: USB
BD Address: 00:0A:3A:84:94:D9 ACL MTU: 1021:8 SCO MTU: 64:1
Features page 0: 0xff 0xff 0x8f 0xfe 0x9b 0xff 0x79 0x83
<3-slot packets> <5-slot packets> <encryption> <slot offset>
<timing accuracy> <role switch> <hold mode> <sniff mode>
<park state> <RSSI> <channel quality> <SCO link> <HV2 packets>
<HV3 packets> <u-law log> <A-law log> <CVSD> <paging scheme>
<power control> <transparent SCO> <broadcast encrypt>
<EDR ACL 2 Mbps> <EDR ACL 3 Mbps> <enhanced iscan>
<interlaced iscan> <interlaced pscan> <inquiry with RSSI>
<extended SCO> <EV4 packets> <EV5 packets> <AFH cap. slave>
<AFH class. slave> <3-slot EDR ACL> <5-slot EDR ACL>
<sniff subrating> <pause encryption> <AFH cap. master>
<AFH class. master> <EDR eSCO 2 Mbps> <EDR eSCO 3 Mbps>
<3-slot EDR eSCO> <extended inquiry> <simple pairing>
<encapsulated PDU> <err. data report> <non-flush flag> <LSTO>
<inquiry TX power> <extended features>
Features page 1: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
:; hciconfig hci0 version
hci0: Type: USB
BD Address: 00:0A:3A:84:94:D9 ACL MTU: 1021:8 SCO MTU: 64:1
HCI Ver: 2.1 (0x4) HCI Rev: 0x5123 LMP Ver: 2.1 (0x4) LMP Subver: 0x420e
Manufacturer: Broadcom Corporation (15)
:; hciconfig hci0 revision
hci0: Type: USB
BD Address: 00:0A:3A:84:94:D9 ACL MTU: 1021:8 SCO MTU: 64:1
Firmware 35.66 / 14
:; lsusb -s 001:
Bus 001 Device 012: ID 050d:0017 Belkin Components
Bus 001 Device 011: ID 0a5c:4503 Broadcom Corp.
Bus 001 Device 010: ID 0a5c:4502 Broadcom Corp.
Bus 001 Device 009: ID 0a5c:4500 Broadcom Corp.
Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
:; aplay -D JX10 ~/lib/alarm.wav
ALSA lib pcm_bluetooth.c:1619:(bluetooth_init) BT_GETCAPABILITIES failed : Input/output error(5)
aplay: main:564: audio open error: Input/output error

: root@kooka; valgrind src/.libs/bluetoothd -dn
==3517== Memcheck, a memory error detector.
==3517== Copyright (C) 2002-2007, and GNU GPL'd, by Julian Seward et al.
==3517== Using LibVEX rev 1854, a library for dynamic binary translation.
==3517== Copyright (C) 2004-2007, and GNU GPL'd, by OpenWorks LLP.
==3517== Using valgrind-3.3.1-Debian, a dynamic binary instrumentation framework.
==3517== Copyright (C) 2000-2007, and GNU GPL'd, by Julian Seward et al.
==3517== For more details, rerun with: -v
==3517==
bluetoothd[3517]: Bluetooth daemon
bluetoothd[3517]: Enabling debug information
bluetoothd[3517]: parsing main.conf
bluetoothd[3517]: offmode=NoScan
bluetoothd[3517]: discovto=0
bluetoothd[3517]: pageto=8192
bluetoothd[3517]: name=%h-%d
bluetoothd[3517]: class=0x000100
bluetoothd[3517]: inqmode=0
bluetoothd[3517]: Starting SDP server
bluetoothd[3517]: Loading plugins /home/stuart/ws/install/bluez/git/bluez/plugins
bluetoothd[3517]: /home/stuart/ws/install/bluez/git/bluez/plugins/audio.so
bluetoothd[3517]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory
bluetoothd[3517]: Unix socket created: 11
bluetoothd[3517]: Telephony plugin initialized
bluetoothd[3517]: HFP AG features: "Ability to reject a call" "Enhanced call status" "Extended Error Result Codes"
bluetoothd[3517]: /home/stuart/ws/install/bluez/git/bluez/plugins/serial.so
bluetoothd[3517]: /home/stuart/ws/install/bluez/git/bluez/plugins/hal.so
bluetoothd[3517]: /home/stuart/ws/install/bluez/git/bluez/plugins/service.so
bluetoothd[3517]: /home/stuart/ws/install/bluez/git/bluez/plugins/network.so
bluetoothd[3517]: Parsing /etc/bluetooth/network.conf failed: No such file or directory
bluetoothd[3517]: Config options: InterfacePrefix=bnep%d, PANU_Script=(null), GN_Script=(null), NAP_Script=(null), GN_Interface=pan0, NAP_Interface=pan1, Security=true
==3517== Warning: noted but unhandled ioctl 0x89a0 with no size/direction hints
==3517== This could cause spurious value errors to appear.
==3517== See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
bluetoothd[3517]: Can't create GN bridge
bluetoothd[3517]: /home/stuart/ws/install/bluez/git/bluez/plugins/input.so
bluetoothd[3517]: input.conf: Key file does not have key 'IdleTimeout'
bluetoothd[3517]: HCI dev 0 registered
bluetoothd[3517]: child 3518 forked
bluetoothd[3517]: HCI dev 0 up
bluetoothd[3517]: Can't read class of adapter on /org/bluez/hci0: Input/output error (5)
bluetoothd[3517]: Starting security manager 0
==3518==
==3518== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 104 from 2)
==3518== malloc/free: in use at exit: 30,412 bytes in 352 blocks.
==3518== malloc/free: 751 allocs, 399 frees, 292,193 bytes allocated.
==3518== For counts of detected errors, rerun with: -v
==3518== searching for pointers to 352 not-freed blocks.
==3518== checked 146,352 bytes.
==3518==
==3518== LEAK SUMMARY:
==3518== definitely lost: 0 bytes in 0 blocks.
==3518== possibly lost: 744 bytes in 3 blocks.
==3518== still reachable: 29,668 bytes in 349 blocks.
==3518== suppressed: 0 bytes in 0 blocks.
==3518== Rerun with --leak-check=full to see details of leaked memory.
bluetoothd[3517]: child 3518 exited
bluetoothd[3517]: Accepted new client connection on unix socket (fd=16)
bluetoothd[3517]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[3517]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[3517]: Unix client disconnected (fd=16)
bluetoothd[3517]: HCI dev 0 down
bluetoothd[3517]: headset_server_remove: path /org/bluez/hci0
bluetoothd[3517]: a2dp_server_remove: path /org/bluez/hci0
bluetoothd[3517]: avrcp_server_remove: path /org/bluez/hci0
bluetoothd[3517]: proxy_remove: path /org/bluez/hci0
process 3517: arguments to dbus_connection_unref() were incorrect, assertion "connection != NULL" failed in file dbus-connection.c line 2645.
This is normally a bug in some application using the D-Bus library.
bluetoothd[3517]: service_remove: path /org/bluez/hci0
bluetoothd[3517]: network_server_remove: path /org/bluez/hci0
bluetoothd[3517]: network_server_remove: path /org/bluez/hci0
bluetoothd[3517]: network_server_remove: path /org/bluez/hci0
bluetoothd[3517]: Adapter /org/bluez/hci0 has been disabled
bluetoothd[3517]: Stopping security manager 0
bluetoothd[3517]: HCI dev 0 unregistered
bluetoothd[3517]: Unregister path: /org/bluez/hci0
bluetoothd[3517]: Removing adapter /org/bluez/hci0
bluetoothd[3517]: HCI dev 0 registered
bluetoothd[3517]: child 3787 forked
bluetoothd[3517]: HCI dev 0 up
bluetoothd[3517]: Can't read class of adapter on /org/bluez/hci0: Input/output error (5)
bluetoothd[3517]: Starting security manager 0
==3787==
==3787== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 104 from 2)
==3787== malloc/free: in use at exit: 30,422 bytes in 353 blocks.
==3787== malloc/free: 927 allocs, 574 frees, 501,820 bytes allocated.
==3787== For counts of detected errors, rerun with: -v
==3787== searching for pointers to 353 not-freed blocks.
==3787== checked 146,624 bytes.
==3787==
==3787== LEAK SUMMARY:
==3787== definitely lost: 0 bytes in 0 blocks.
==3787== possibly lost: 744 bytes in 3 blocks.
==3787== still reachable: 29,678 bytes in 350 blocks.
==3787== suppressed: 0 bytes in 0 blocks.
==3787== Rerun with --leak-check=full to see details of leaked memory.
bluetoothd[3517]: child 3787 exited
bluetoothd[3517]: Accepted new client connection on unix socket (fd=17)
bluetoothd[3517]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[3517]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[3517]: Unix client disconnected (fd=17)


2008-10-06 20:31:17

by Johan Hedberg

[permalink] [raw]
Subject: Re: bluez-4.11 + 2.6.27-rc8 + SCO headset -> Invalid read of size 4

Hi Stuart,

On Oct 6, 2008, at 21:56, Stuart Pook wrote:
>> I think I managed to fix the segfault issue. The valgrind backtrace
>> was actually misleading/incorrect but I managed to get a proper one
>> with gdb. Could you try the latest git and see if the segfault is
>> gone?
>
> I still have the segfault. But it took a little longer this time.

Actually it's a different issue than the original segfault (see later
in this email).

> I'm a git beginner. Is there a git command that gives me the "version"
> of what "git clone" retrieved so that you exactly what code I have?

You won't have any specific version but just the latest development
tree. Be sure to run "git pull" every now and then to make sure you
get the latest changes.

> bluetoothd[2451]: connect(): Connection timed out (110)
> ==2451== Invalid read of size 4
> ==2451== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
> ==2451== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/
> libdbus-1.so.3.4.0)
> ==2451== by 0x49155C0: dbus_message_new_error (in /usr/lib/
> libdbus-1.so.3.4.0)
> ==2451== by 0x15677: error_common_reply (error.c:42)
> ==2451== by 0x4ED900D: error_connection_attempt_failed (headset.c:
> 175)
> ==2451== by 0x4ED9A3B: sco_connect_cb (headset.c:468)

This is a different trace than the original one. The original one went
through rfcomm_connect_cb while this one goes through sco_connect_cb,
i.e. you've already got the (RFCOMM) control connection up and are
trying to establish the audio (SCO) connection. I will investigate it,
however could you try to get a backtrace with gdb as well since it
seems that valgrind either distorts or hides some errors.

Johan




2008-10-06 19:56:52

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez-4.11 + 2.6.27-rc8 + SCO headset -> Invalid read of size 4

hi Johan

> I think I managed to fix the segfault issue. The valgrind backtrace was
> actually misleading/incorrect but I managed to get a proper one with
> gdb. Could you try the latest git and see if the segfault is gone?

I still have the segfault. But it took a little longer this time.

I'm a git beginner. Is there a git command that gives me the "version"
of what "git clone" retrieved so that you exactly what code I have?

bluetoothd[2451]: connect(): Connection timed out (110)
==2451== Invalid read of size 4
==2451== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==2451== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==2451== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==2451== by 0x15677: error_common_reply (error.c:42)
==2451== by 0x4ED900D: error_connection_attempt_failed (headset.c:175)
==2451== by 0x4ED9A3B: sco_connect_cb (headset.c:468)
==2451== by 0x26074: connect_cb (glib-helper.c:707)
==2451== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0xAA93: main (main.c:750)
==2451== Address 0x464c45b3 is not stack'd, malloc'd or (recently) free'd

:; while sleep 15; do aplay -D JX10 lib/alarm.wav ; done
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
^CAborted by signal Interrupt...
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
^CAborted by signal Interrupt...
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
^CAborted by signal Interrupt...
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
bt_audio_service_open: connect() failed: Connection refused (111)
aplay: main:564: audio open error: Connection refused
: root@kooka; valgrind src/.libs/bluetoothd -dn
==2451== Memcheck, a memory error detector.
==2451== Copyright (C) 2002-2007, and GNU GPL'd, by Julian Seward et al.
==2451== Using LibVEX rev 1854, a library for dynamic binary translation.
==2451== Copyright (C) 2004-2007, and GNU GPL'd, by OpenWorks LLP.
==2451== Using valgrind-3.3.1-Debian, a dynamic binary instrumentation framework.
==2451== Copyright (C) 2000-2007, and GNU GPL'd, by Julian Seward et al.
==2451== For more details, rerun with: -v
==2451==
bluetoothd[2451]: Bluetooth daemon
bluetoothd[2451]: Enabling debug information
bluetoothd[2451]: parsing main.conf
bluetoothd[2451]: offmode=NoScan
bluetoothd[2451]: discovto=0
bluetoothd[2451]: pageto=8192
bluetoothd[2451]: name=%h-%d
bluetoothd[2451]: class=0x000100
bluetoothd[2451]: inqmode=0
bluetoothd[2451]: Starting SDP server
bluetoothd[2451]: Loading plugins /home/stuart/ws/install/bluez/git/bluez/plugins
bluetoothd[2451]: /home/stuart/ws/install/bluez/git/bluez/plugins/audio.so
bluetoothd[2451]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory
bluetoothd[2451]: Unix socket created: 11
bluetoothd[2451]: Telephony plugin initialized
bluetoothd[2451]: HFP AG features: "Ability to reject a call" "Enhanced call status" "Extended Error Result Codes"
bluetoothd[2451]: /home/stuart/ws/install/bluez/git/bluez/plugins/serial.so
bluetoothd[2451]: /home/stuart/ws/install/bluez/git/bluez/plugins/hal.so
bluetoothd[2451]: /home/stuart/ws/install/bluez/git/bluez/plugins/service.so
bluetoothd[2451]: /home/stuart/ws/install/bluez/git/bluez/plugins/network.so
bluetoothd[2451]: Parsing /etc/bluetooth/network.conf failed: No such file or directory
bluetoothd[2451]: Config options: InterfacePrefix=bnep%d, PANU_Script=(null), GN_Script=(null), NAP_Script=(null), GN_Interface=pan0, NAP_Interface=pan1, Security=true
==2451== Warning: noted but unhandled ioctl 0x89a0 with no size/direction hints
==2451== This could cause spurious value errors to appear.
==2451== See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
bluetoothd[2451]: Can't create GN bridge
bluetoothd[2451]: /home/stuart/ws/install/bluez/git/bluez/plugins/input.so
bluetoothd[2451]: input.conf: Key file does not have key 'IdleTimeout'
bluetoothd[2451]: HCI dev 0 registered
bluetoothd[2451]: child 2452 forked
bluetoothd[2451]: HCI dev 0 already up
bluetoothd[2451]: headset_server_probe: path /org/bluez/hci0
bluetoothd[2451]: Adding record with handle 0x10000
bluetoothd[2451]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 00001108-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 00001112-0000-1000-8000-00805f9
==2452==
==2452== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 104 from 2)
bluetoothd[2451]: Record pattern UUID 00001203-0000-1000-8000-00805f9
==2452== malloc/free: in use at exit: 30,412 bytes in 352 blocks.
==2452== malloc/free: 751 allocs, 399 frees, 292,193 bytes allocated.
==2452== For counts of detected errors, rerun with: -v
==2452== searching for pointers to 352 not-freed blocks.
==2452== checked 146,352 bytes.
==2452==
==2452== LEAK SUMMARY:
==2452== definitely lost: 0 bytes in 0 blocks.
==2452== possibly lost: 744 bytes in 3 blocks.
==2452== still reachable: 29,668 bytes in 349 blocks.
==2452== suppressed: 0 bytes in 0 blocks.
==2452== Rerun with --leak-check=full to see details of leaked memory.
bluetoothd[2451]: Adding record with handle 0x10001
bluetoothd[2451]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 0000111e-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 0000111f-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 00001203-0000-1000-8000-00805f9
bluetoothd[2451]: a2dp_server_probe: path /org/bluez/hci0
bluetoothd[2451]: SEP 0x4b42690 registered: type:0 codec:0 seid:1
bluetoothd[2451]: Adding record with handle 0x10002
bluetoothd[2451]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 0000110a-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 0000110d-0000-1000-8000-00805f9
bluetoothd[2451]: avrcp_server_probe: path /org/bluez/hci0
bluetoothd[2451]: Adding record with handle 0x10003
bluetoothd[2451]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 0000110c-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 0000110e-0000-1000-8000-00805f9
bluetoothd[2451]: Adding record with handle 0x10004
bluetoothd[2451]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 0000110e-0000-1000-8000-00805f9
bluetoothd[2451]: proxy_probe: path /org/bluez/hci0
bluetoothd[2451]: Registered interface org.bluez.SerialProxyManager on path /org/bluez/hci0
bluetoothd[2451]: service_probe: path /org/bluez/hci0
bluetoothd[2451]: Registered interface org.bluez.Service on path /org/bluez/hci0
bluetoothd[2451]: network_server_probe: path /org/bluez/hci0
bluetoothd[2451]: Adding record with handle 0x10005
bluetoothd[2451]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 00001115-0000-1000-8000-00805f9
bluetoothd[2451]: register_server_record: got record id 0x10005
bluetoothd[2451]: Registered interface org.bluez.NetworkPeer on path /org/bluez/hci0
bluetoothd[2451]: network_server_probe: path /org/bluez/hci0
bluetoothd[2451]: Adding record with handle 0x10006
bluetoothd[2451]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 00001117-0000-1000-8000-00805f9
bluetoothd[2451]: register_server_record: got record id 0x10006
bluetoothd[2451]: Registered interface org.bluez.NetworkHub on path /org/bluez/hci0
bluetoothd[2451]: network_server_probe: path /org/bluez/hci0
bluetoothd[2451]: Adding record with handle 0x10007
bluetoothd[2451]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[2451]: Record pattern UUID 00001116-0000-1000-8000-00805f9
bluetoothd[2451]: register_server_record: got record id 0x10007
bluetoothd[2451]: Registered interface org.bluez.NetworkRouter on path /org/bluez/hci0
bluetoothd[2451]: Creating device /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[2451]: Probe drivers for /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[2451]: Found Headset record
bluetoothd[2451]: Discovered Headset service on RFCOMM channel 2
bluetoothd[2451]: Registered interface org.bluez.Headset on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[2451]: Found Hansfree record
bluetoothd[2451]: Discovered Handsfree service on RFCOMM channel 1
bluetoothd[2451]: headset_probe: path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[2451]: Registered interface org.bluez.Input on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[2451]: Creating device /org/bluez/hci0/dev_00_14_A7_74_D3_AF
bluetoothd[2451]: Creating device /org/bluez/hci0/dev_00_03_89_B7_F8_D3
bluetoothd[2451]: Creating device /org/bluez/hci0/dev_00_0A_94_94_4F_B3
bluetoothd[2451]: Creating device /org/bluez/hci0/dev_00_03_89_DC_5C_9F
bluetoothd[2451]: Creating device /org/bluez/hci0/dev_00_03_89_DC_FC_EC
bluetoothd[2451]: Creating device /org/bluez/hci0/dev_00_03_89_FE_E6_19
bluetoothd[2451]: Creating device /org/bluez/hci0/dev_00_0E_6D_8F_91_6A
bluetoothd[2451]: Creating device /org/bluez/hci0/dev_00_17_E5_E6_25_AB
bluetoothd[2451]: Creating device /org/bluez/hci0/dev_00_17_E5_16_88_6C
bluetoothd[2451]: Creating device /org/bluez/hci0/dev_00_17_E5_0C_EA_70
bluetoothd[2451]: Adapter /org/bluez/hci0 has been enabled
bluetoothd[2451]: Starting security manager 0
bluetoothd[2451]: child 2452 exited
bluetoothd[2451]: Computer is classified as desktop
bluetoothd[2451]: Current device class is 0x4a0104
bluetoothd[2451]: Setting 0x000104 for major/minor device class
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[2451]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[2451]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[2451]: kernel auth requirements = 0x04
bluetoothd[2451]: stored link key type = 0x00
bluetoothd[2451]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[2451]: Received AT+BRSF=27
bluetoothd[2451]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[2451]: Received AT+CIND=?
bluetoothd[2451]: Received AT+CIND?
bluetoothd[2451]: Received AT+CMER=3, 0, 0, 1
bluetoothd[2451]: Event reporting (CMER): mode=3, ind=1
bluetoothd[2451]: HFP Service Level Connection established
bluetoothd[2451]: telephony-dummy: device 0x4b9f950 connected
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: Received AT+VGS=15
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Audio API: received BT_STREAMSTART_REQ
bluetoothd[2451]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[2451]: Audio API: sending BT_STREAMFD_IND
bluetoothd[2451]: unix_sendmsg_fd: Bad file descriptor(9)
bluetoothd[2451]: resume failed
bluetoothd[2451]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 45
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 45
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: telephony-dummy: device 0x4b9f950 disconnected
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[2451]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: telephony-dummy: device 0x4b9f950 connected
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 45
bluetoothd[2451]: Received AT+BRSF=27
bluetoothd[2451]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[2451]: Received AT+CIND=?
bluetoothd[2451]: Received AT+CIND?
bluetoothd[2451]: Received AT+CMER=3, 0, 0, 1
bluetoothd[2451]: Event reporting (CMER): mode=3, ind=1
bluetoothd[2451]: Received AT+VGS=15
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 45
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: No matching connection for handle 45
bluetoothd[2451]: telephony-dummy: device 0x4b9f950 disconnected
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_DISCONNECTED
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[2451]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[2451]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[2451]: kernel auth requirements = 0x04
bluetoothd[2451]: stored link key type = 0x00
bluetoothd[2451]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[2451]: Received AT+BRSF=27
bluetoothd[2451]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[2451]: Received AT+CIND=?
bluetoothd[2451]: Received AT+CIND?
bluetoothd[2451]: Received AT+CMER=3, 0, 0, 1
bluetoothd[2451]: Event reporting (CMER): mode=3, ind=1
bluetoothd[2451]: HFP Service Level Connection established
bluetoothd[2451]: telephony-dummy: device 0x4b9f950 connected
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: Received AT+VGS=15
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 41
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 41
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 41
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 41
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 41
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 41
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 41
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 41
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 41
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: connect(): Connection timed out (110)
bluetoothd[2451]: Unable to lock headset
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: No matching connection for handle 41
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: telephony-dummy: device 0x4b9f950 disconnected
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[2451]: Accepted new client connection on unix socket (fd=23)
bluetoothd[2451]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[2451]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[2451]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[2451]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[2451]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[2451]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[2451]: Received AT+BRSF=27
bluetoothd[2451]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[2451]: Received AT+CIND=?
bluetoothd[2451]: Received AT+CIND?
bluetoothd[2451]: Received AT+CMER=3, 0, 0, 1
bluetoothd[2451]: Event reporting (CMER): mode=3, ind=1
bluetoothd[2451]: HFP Service Level Connection established
bluetoothd[2451]: telephony-dummy: device 0x4b9f950 connected
bluetoothd[2451]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[2451]: connect: Operation not permitted (1)
bluetoothd[2451]: config failed
bluetoothd[2451]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[2451]: Unix client disconnected (fd=23)
bluetoothd[2451]: Received AT+VGS=15
bluetoothd[2451]: connect(): Connection timed out (110)
==2451== Invalid read of size 4
==2451== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==2451== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==2451== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==2451== by 0x15677: error_common_reply (error.c:42)
==2451== by 0x4ED900D: error_connection_attempt_failed (headset.c:175)
==2451== by 0x4ED9A3B: sco_connect_cb (headset.c:468)
==2451== by 0x26074: connect_cb (glib-helper.c:707)
==2451== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0xAA93: main (main.c:750)
==2451== Address 0x464c45b3 is not stack'd, malloc'd or (recently) free'd
==2451==
==2451== Process terminating with default action of signal 11 (SIGSEGV)
==2451== Access not within mapped region at address 0x464C45B3
==2451== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==2451== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==2451== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==2451== by 0x15677: error_common_reply (error.c:42)
==2451== by 0x4ED900D: error_connection_attempt_failed (headset.c:175)
==2451== by 0x4ED9A3B: sco_connect_cb (headset.c:468)
==2451== by 0x26074: connect_cb (glib-helper.c:707)
==2451== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==2451== by 0xAA93: main (main.c:750)
==2451==
==2451== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 104 from 2)
==2451== malloc/free: in use at exit: 47,875 bytes in 882 blocks.
==2451== malloc/free: 4,077 allocs, 3,195 frees, 3,448,435 bytes allocated.
==2451== For counts of detected errors, rerun with: -v
==2451== searching for pointers to 882 not-freed blocks.
==2451== checked 162,236 bytes.
==2451==
==2451== LEAK SUMMARY:
==2451== definitely lost: 1,292 bytes in 19 blocks.
==2451== possibly lost: 864 bytes in 4 blocks.
==2451== still reachable: 45,719 bytes in 859 blocks.
==2451== suppressed: 0 bytes in 0 blocks.
==2451== Rerun with --leak-check=full to see details of leaked memory.
Segmentation fault



2008-10-06 18:38:55

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez-4.11 + 2.6.27-rc8 + SCO headset -> Invalid read of size 4

hi Johan

> I think I managed to fix the segfault issue. The valgrind backtrace was
> actually misleading/incorrect but I managed to get a proper one with
> gdb.

I ran bluetoothd 4.11 from the source directory and the error message is
in fact different. Do you know why?

> Could you try the latest git and see if the segfault is gone?

next step!

> Unfortunately this still leaves you with the original issue of your
> player bailing out too early.

yes :-(

bluetoothd[15350]: connect(): Connection timed out (110)
==15350== Invalid read of size 4
==15350== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x1361D: error_common_reply (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x4ED9D2C: error_connection_attempt_failed (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x4EDA117: sco_connect_cb (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x2165E: connect_cb (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0xA410: main (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== Address 0x464c45b3 is not stack'd, malloc'd or (recently) free'd

:; while sleep 15; do aplay -D JX10 lib/alarm.wav ; done
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
^CAborted by signal Interrupt...
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
bt_audio_service_open: connect() failed: Connection refused (111)
aplay: main:564: audio open error: Connection refused

: root@kooka; valgrind bluez-4.11/src/.libs/bluetoothd -dn
==15350== Memcheck, a memory error detector.
==15350== Copyright (C) 2002-2007, and GNU GPL'd, by Julian Seward et al.
==15350== Using LibVEX rev 1854, a library for dynamic binary translation.
==15350== Copyright (C) 2004-2007, and GNU GPL'd, by OpenWorks LLP.
==15350== Using valgrind-3.3.1-Debian, a dynamic binary instrumentation framework.
==15350== Copyright (C) 2000-2007, and GNU GPL'd, by Julian Seward et al.
==15350== For more details, rerun with: -v
==15350==
bluetoothd[15350]: Bluetooth daemon
bluetoothd[15350]: Enabling debug information
bluetoothd[15350]: parsing main.conf
bluetoothd[15350]: offmode=NoScan
bluetoothd[15350]: discovto=0
bluetoothd[15350]: pageto=8192
bluetoothd[15350]: name=%h-%d
bluetoothd[15350]: class=0x000100
bluetoothd[15350]: inqmode=0
bluetoothd[15350]: Starting SDP server
bluetoothd[15350]: Loading plugins /usr/local/lib/bluetooth/plugins
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/audio.so
bluetoothd[15350]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory
bluetoothd[15350]: Unix socket created: 11
bluetoothd[15350]: Telephony plugin initialized
bluetoothd[15350]: HFP AG features: "Ability to reject a call" "Enhanced call status" "Extended Error Result Codes"
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/serial.so
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/hal.so
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/service.so
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/network.so
bluetoothd[15350]: Parsing /etc/bluetooth/network.conf failed: No such file or directory
bluetoothd[15350]: Config options: InterfacePrefix=bnep%d, PANU_Script=(null), GN_Script=(null), NAP_Script=(null), GN_Interface=pan0, NAP_Interface=pan1, Security=true
==15350== Warning: noted but unhandled ioctl 0x89a0 with no size/direction hints
==15350== This could cause spurious value errors to appear.
==15350== See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
bluetoothd[15350]: bridge pan0 created
bluetoothd[15350]: /usr/local/lib/bluetooth/plugins/input.so
bluetoothd[15350]: input.conf: Key file does not have key 'IdleTimeout'
bluetoothd[15350]: HCI dev 0 registered
bluetoothd[15350]: child 15359 forked
bluetoothd[15350]: HCI dev 0 already up
==15359==
==15359== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 84 from 2)
==15359== malloc/free: in use at exit: 30,100 bytes in 352 blocks.
==15359== malloc/free: 751 allocs, 399 frees, 290,809 bytes allocated.
==15359== For counts of detected errors, rerun with: -v
==15359== searching for pointers to 352 not-freed blocks.
bluetoothd[15350]: headset_server_probe: path /org/bluez/hci0
==15359== checked 146,028 bytes.
==15359==
==15359== LEAK SUMMARY:
==15359== definitely lost: 0 bytes in 0 blocks.
==15359== possibly lost: 744 bytes in 3 blocks.
==15359== still reachable: 29,356 bytes in 349 blocks.
==15359== suppressed: 0 bytes in 0 blocks.
==15359== Rerun with --leak-check=full to see details of leaked memory.
bluetoothd[15350]: Adding record with handle 0x10000
bluetoothd[15350]: Adding record with handle 0x10001
bluetoothd[15350]: a2dp_server_probe: path /org/bluez/hci0
bluetoothd[15350]: SEP 0x4b31198 registered: type:0 codec:0 seid:1
bluetoothd[15350]: Adding record with handle 0x10002
bluetoothd[15350]: avrcp_server_probe: path /org/bluez/hci0
bluetoothd[15350]: Adding record with handle 0x10003
bluetoothd[15350]: Adding record with handle 0x10004
bluetoothd[15350]: proxy_probe: path /org/bluez/hci0
bluetoothd[15350]: Registered interface org.bluez.SerialProxyManager on path /org/bluez/hci0
bluetoothd[15350]: service_probe: path /org/bluez/hci0
bluetoothd[15350]: Registered interface org.bluez.Service on path /org/bluez/hci0
bluetoothd[15350]: network_server_probe: path /org/bluez/hci0
bluetoothd[15350]: Adding record with handle 0x10005
bluetoothd[15350]: register_server_record: got record id 0x10005
bluetoothd[15350]: Registered interface org.bluez.NetworkPeer on path /org/bluez/hci0
bluetoothd[15350]: network_server_probe: path /org/bluez/hci0
bluetoothd[15350]: Adding record with handle 0x10006
bluetoothd[15350]: register_server_record: got record id 0x10006
bluetoothd[15350]: Registered interface org.bluez.NetworkHub on path /org/bluez/hci0
bluetoothd[15350]: network_server_probe: path /org/bluez/hci0
bluetoothd[15350]: Adding record with handle 0x10007
bluetoothd[15350]: register_server_record: got record id 0x10007
bluetoothd[15350]: Registered interface org.bluez.NetworkRouter on path /org/bluez/hci0
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15350]: Probe drivers for /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15350]: Found Headset record
bluetoothd[15350]: Discovered Headset service on RFCOMM channel 2
bluetoothd[15350]: Registered interface org.bluez.Headset on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15350]: Found Hansfree record
bluetoothd[15350]: Discovered Handsfree service on RFCOMM channel 1
bluetoothd[15350]: headset_probe: path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15350]: Registered interface org.bluez.Input on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_14_A7_74_D3_AF
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_03_89_B7_F8_D3
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_0A_94_94_4F_B3
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_03_89_DC_5C_9F
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_03_89_DC_FC_EC
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_03_89_FE_E6_19
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_0E_6D_8F_91_6A
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_17_E5_E6_25_AB
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_17_E5_16_88_6C
bluetoothd[15350]: Creating device /org/bluez/hci0/dev_00_17_E5_0C_EA_70
bluetoothd[15350]: Adapter /org/bluez/hci0 has been enabled
bluetoothd[15350]: Starting security manager 0
bluetoothd[15350]: child 15359 exited
bluetoothd[15350]: Computer is classified as desktop
bluetoothd[15350]: Current device class is 0x4a0104
bluetoothd[15350]: Setting 0x000104 for major/minor device class
bluetoothd[15350]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15350]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15350]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15350]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15350]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15350]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15350]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[15350]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[15350]: kernel auth requirements = 0x04
bluetoothd[15350]: stored link key type = 0x00
bluetoothd[15350]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[15350]: Received AT+BRSF=27
bluetoothd[15350]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[15350]: Received AT+CIND=?
bluetoothd[15350]: Received AT+CIND?
bluetoothd[15350]: Received AT+CMER=3, 0, 0, 1
bluetoothd[15350]: Event reporting (CMER): mode=3, ind=1
bluetoothd[15350]: HFP Service Level Connection established
bluetoothd[15350]: telephony-dummy: device 0x4b70708 connected
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[15350]: Received AT+VGS=15
bluetoothd[15350]: connect(): Connection timed out (110)
bluetoothd[15350]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[15350]: Audio API: received BT_STREAMSTART_REQ
bluetoothd[15350]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[15350]: Audio API: sending BT_STREAMFD_IND
bluetoothd[15350]: unix_sendmsg_fd: Bad file descriptor(9)
bluetoothd[15350]: resume failed
bluetoothd[15350]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[15350]: Unix client disconnected (fd=23)
bluetoothd[15350]: No matching connection for handle 45
bluetoothd[15350]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15350]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15350]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15350]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15350]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[15350]: Unix client disconnected (fd=23)
bluetoothd[15350]: telephony-dummy: device 0x4b70708 disconnected
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[15350]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15350]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15350]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15350]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15350]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15350]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15350]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[15350]: Received AT+BRSF=27
bluetoothd[15350]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[15350]: Received AT+CIND=?
bluetoothd[15350]: Received AT+CIND?
bluetoothd[15350]: Received AT+CMER=3, 0, 0, 1
bluetoothd[15350]: Event reporting (CMER): mode=3, ind=1
bluetoothd[15350]: HFP Service Level Connection established
bluetoothd[15350]: telephony-dummy: device 0x4b70708 connected
bluetoothd[15350]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[15350]: connect: Operation not permitted (1)
bluetoothd[15350]: config failed
bluetoothd[15350]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[15350]: Unix client disconnected (fd=23)
bluetoothd[15350]: Received AT+VGS=15
bluetoothd[15350]: connect(): Connection timed out (110)
==15350== Invalid read of size 4
==15350== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x1361D: error_common_reply (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x4ED9D2C: error_connection_attempt_failed (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x4EDA117: sco_connect_cb (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x2165E: connect_cb (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0xA410: main (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== Address 0x464c45b3 is not stack'd, malloc'd or (recently) free'd
==15350==
==15350== Process terminating with default action of signal 11 (SIGSEGV)
==15350== Access not within mapped region at address 0x464C45B3
==15350== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==15350== by 0x1361D: error_common_reply (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x4ED9D2C: error_connection_attempt_failed (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x4EDA117: sco_connect_cb (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15350== by 0x2165E: connect_cb (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==15350== by 0xA410: main (in /ws/stuart/install/bluez/bluez-4.11/src/.libs/bluetoothd)
==15350==
==15350== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 84 from 2)
==15350== malloc/free: in use at exit: 46,531 bytes in 869 blocks.
==15350== malloc/free: 2,715 allocs, 1,846 frees, 1,361,168 bytes allocated.
==15350== For counts of detected errors, rerun with: -v
==15350== searching for pointers to 869 not-freed blocks.
==15350== checked 162,032 bytes.
==15350==
==15350== LEAK SUMMARY:
==15350== definitely lost: 204 bytes in 3 blocks.
==15350== possibly lost: 864 bytes in 4 blocks.
==15350== still reachable: 45,463 bytes in 862 blocks.
==15350== suppressed: 0 bytes in 0 blocks.
==15350== Rerun with --leak-check=full to see details of leaked memory.
Segmentation fault


2008-10-06 10:52:29

by Johan Hedberg

[permalink] [raw]
Subject: Re: bluez-4.11 + 2.6.27-rc8 + SCO headset -> Invalid read of size 4

Hi Stuart,

I think I managed to fix the segfault issue. The valgrind backtrace
was actually misleading/incorrect but I managed to get a proper one
with gdb. Could you try the latest git and see if the segfault is
gone? Unfortunately this still leaves you with the original issue of
your player bailing out too early.

Johan

2008-10-06 08:47:35

by Johan Hedberg

[permalink] [raw]
Subject: Re: bluez-4.11 + 2.6.27-rc8 + SCO headset -> Invalid read of size 4

Hi Stuart,

On Oct 5, 2008, at 22:07, Stuart Pook wrote:
> bluetoothd[15123]: connect(): Connection timed out (110)
> ==15123== Invalid read of size 4
> ==15123== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
> ==15123== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/
> libdbus-1.so.3.4.0)
> ==15123== by 0x49155C0: dbus_message_new_error (in /usr/lib/
> libdbus-1.so.3.4.0)
> ==15123== by 0x1361D: error_common_reply (in /usr/local/stow/
> bluez-4.11/sbin/bluetoothd)
> ==15123== by 0x4ED9D2C: error_connection_attempt_failed (in /usr/
> local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
> ==15123== by 0x4EDAEA2: rfcomm_connect_cb (in /usr/local/stow/
> bluez-4.11/lib/bluetooth/plugins/audio.so)
> ==15123== by 0x2165E: connect_cb (in /usr/local/stow/bluez-4.11/
> sbin/bluetoothd)
> ==15123== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
> ==15123== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/
> libglib-2.0.so.0.1600.6)
> ==15123== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
> ==15123== by 0x4881D71: g_main_loop_run (in /usr/lib/
> libglib-2.0.so.0.1600.6)
> ==15123== by 0xA410: main (in /usr/local/stow/bluez-4.11/sbin/
> bluetoothd)
> ==15123== Address 0x464c45b3 is not stack'd, malloc'd or (recently)
> free'd

Thanks for the valgrind report. It definitely gives some hints at
what's going on. Apparently there's a bug in one error handling code
path of the rfcomm_connect_cb function. The weird thing here is that
the code path (which calls error_connection_attempt_failed) should
only be taken if the connection attempt was triggered by a D-Bus
message which is not the case for you (it's the alsa sound player that
triggers it, right?). I fixed some issues related to the connection
handling in git but none of it seemed to be directly related to the
backtrace you gave. Could you give the current git a try (git clone
git://git.kernel.org/pub/scm/bluetooth/bluez.git; cd bluez; ./
bootstrap-configure && make)? Also, try to run bluetoothd directly
from the source tree (src/.libs/bluetoothd) so that valgrind can pick
up the correct file names and line numbers as well.

Regarding why this code path is taken, it seems like your alsa
application gives up before the bluetooth connection has been created.
When bluetoothd sees that the alsa client exited it calls close() on
the connecting RFCOMM socket which in effect terminates the connection
creation and causes rfcomm_connect_cb to be called with an error code.
Why your application gives up prematurely is still unclear to me.

Johan



2008-10-05 20:07:11

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez-4.11 + 2.6.27-rc8 + SCO headset -> Invalid read of size 4

>> Sometimes bluetoothd segfaults.
> That's something more serious. Could you please try to produce a
> backtrace, either with gdb or valgrind. Thanks!

valgrind is easy

BTW, all the files in /usr/local/stow/bluez-4.11 are symlinked
into /usr/local using stow.

I can get this error by running "aplay -D JX10 lib/alarm.wav"
a few times with a 15 second delay before killing aplay with
control-C. It happened three times tonight.

Let me know if I can help in any other way.

This is the interesting output from valgrind:

bluetoothd[15123]: connect(): Connection timed out (110)
==15123== Invalid read of size 4
==15123== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==15123== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==15123== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==15123== by 0x1361D: error_common_reply (in /usr/local/stow/bluez-4.11/sbin/bluetoothd)
==15123== by 0x4ED9D2C: error_connection_attempt_failed (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15123== by 0x4EDAEA2: rfcomm_connect_cb (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15123== by 0x2165E: connect_cb (in /usr/local/stow/bluez-4.11/sbin/bluetoothd)
==15123== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0xA410: main (in /usr/local/stow/bluez-4.11/sbin/bluetoothd)
==15123== Address 0x464c45b3 is not stack'd, malloc'd or (recently) free'd

This what I ran (note where I typed control-C twice)

:; while sleep 15; do aplay -D JX10 lib/alarm.wav ; done
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
^CAborted by signal Interrupt...
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
ALSA lib pcm_bluetooth.c:464:(bluetooth_hsp_hw_params) BT_SETCONFIGURATION failed : Input/output error(5)
aplay: set_params:979: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S16_LE
SUBFORMAT: STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 8000
PERIOD_TIME: 125000
PERIOD_SIZE: 1000
PERIOD_BYTES: 2000
PERIODS: 4
BUFFER_TIME: 500000
BUFFER_SIZE: 4000
BUFFER_BYTES: 8000
TICK_TIME: [0 0]
Playing WAVE 'lib/alarm.wav' : Signed 16 bit Little Endian, Rate 8000 Hz, Mono
^CAborted by signal Interrupt...
bt_audio_service_open: connect() failed: Connection refused (111)
aplay: main:564: audio open error: Connection refused

Here is the complete log:

: root@kooka; valgrind /usr/local/sbin/bluetoothd -dn
==15123== Memcheck, a memory error detector.
==15123== Copyright (C) 2002-2007, and GNU GPL'd, by Julian Seward et al.
==15123== Using LibVEX rev 1854, a library for dynamic binary translation.
==15123== Copyright (C) 2004-2007, and GNU GPL'd, by OpenWorks LLP.
==15123== Using valgrind-3.3.1-Debian, a dynamic binary instrumentation framework.
==15123== Copyright (C) 2000-2007, and GNU GPL'd, by Julian Seward et al.
==15123== For more details, rerun with: -v
==15123==
bluetoothd[15123]: Bluetooth daemon
bluetoothd[15123]: Enabling debug information
bluetoothd[15123]: parsing main.conf
bluetoothd[15123]: offmode=NoScan
bluetoothd[15123]: discovto=0
bluetoothd[15123]: pageto=8192
bluetoothd[15123]: name=%h-%d
bluetoothd[15123]: class=0x000100
bluetoothd[15123]: inqmode=0
bluetoothd[15123]: Starting SDP server
bluetoothd[15123]: Loading plugins /usr/local/lib/bluetooth/plugins
bluetoothd[15123]: /usr/local/lib/bluetooth/plugins/audio.so
bluetoothd[15123]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory
bluetoothd[15123]: Unix socket created: 11
bluetoothd[15123]: Telephony plugin initialized
bluetoothd[15123]: HFP AG features: "Ability to reject a call" "Enhanced call status" "Extended Error Result Codes"
bluetoothd[15123]: /usr/local/lib/bluetooth/plugins/serial.so
bluetoothd[15123]: /usr/local/lib/bluetooth/plugins/hal.so
bluetoothd[15123]: /usr/local/lib/bluetooth/plugins/service.so
bluetoothd[15123]: /usr/local/lib/bluetooth/plugins/network.so
bluetoothd[15123]: Parsing /etc/bluetooth/network.conf failed: No such file or directory
bluetoothd[15123]: Config options: InterfacePrefix=bnep%d, PANU_Script=(null), GN_Script=(null), NAP_Script=(null), GN_Interface=pan0, NAP_Interface=pan1, Security=true
==15123== Warning: noted but unhandled ioctl 0x89a0 with no size/direction hints
==15123== This could cause spurious value errors to appear.
==15123== See README_MISSING_SYSCALL_OR_IOCTL for guidance on writing a proper wrapper.
bluetoothd[15123]: bridge pan0 created
bluetoothd[15123]: /usr/local/lib/bluetooth/plugins/input.so
bluetoothd[15123]: input.conf: Key file does not have key 'IdleTimeout'
bluetoothd[15123]: HCI dev 0 registered
bluetoothd[15123]: child 15132 forked
bluetoothd[15123]: HCI dev 0 already up
bluetoothd[15123]: headset_server_probe: path /org/bluez/hci0
bluetoothd[15123]: Adding record with handle 0x10000
==15132==
==15132== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 84 from 2)
==15132== malloc/free: in use at exit: 30,100 bytes in 352 blocks.
==15132== malloc/free: 751 allocs, 399 frees, 290,809 bytes allocated.
==15132== For counts of detected errors, rerun with: -v
==15132== searching for pointers to 352 not-freed blocks.
==15132== checked 145,996 bytes.
==15132==
==15132== LEAK SUMMARY:
==15132== definitely lost: 0 bytes in 0 blocks.
==15132== possibly lost: 744 bytes in 3 blocks.
==15132== still reachable: 29,356 bytes in 349 blocks.
==15132== suppressed: 0 bytes in 0 blocks.
==15132== Rerun with --leak-check=full to see details of leaked memory.
bluetoothd[15123]: Adding record with handle 0x10001
bluetoothd[15123]: a2dp_server_probe: path /org/bluez/hci0
bluetoothd[15123]: SEP 0x4b311d0 registered: type:0 codec:0 seid:1
bluetoothd[15123]: Adding record with handle 0x10002
bluetoothd[15123]: avrcp_server_probe: path /org/bluez/hci0
bluetoothd[15123]: Adding record with handle 0x10003
bluetoothd[15123]: Adding record with handle 0x10004
bluetoothd[15123]: proxy_probe: path /org/bluez/hci0
bluetoothd[15123]: Registered interface org.bluez.SerialProxyManager on path /org/bluez/hci0
bluetoothd[15123]: service_probe: path /org/bluez/hci0
bluetoothd[15123]: Registered interface org.bluez.Service on path /org/bluez/hci0
bluetoothd[15123]: network_server_probe: path /org/bluez/hci0
bluetoothd[15123]: Adding record with handle 0x10005
bluetoothd[15123]: register_server_record: got record id 0x10005
bluetoothd[15123]: Registered interface org.bluez.NetworkPeer on path /org/bluez/hci0
bluetoothd[15123]: network_server_probe: path /org/bluez/hci0
bluetoothd[15123]: Adding record with handle 0x10006
bluetoothd[15123]: register_server_record: got record id 0x10006
bluetoothd[15123]: Registered interface org.bluez.NetworkHub on path /org/bluez/hci0
bluetoothd[15123]: network_server_probe: path /org/bluez/hci0
bluetoothd[15123]: Adding record with handle 0x10007
bluetoothd[15123]: register_server_record: got record id 0x10007
bluetoothd[15123]: Registered interface org.bluez.NetworkRouter on path /org/bluez/hci0
bluetoothd[15123]: Creating device /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15123]: Probe drivers for /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15123]: Found Headset record
bluetoothd[15123]: Discovered Headset service on RFCOMM channel 2
bluetoothd[15123]: Registered interface org.bluez.Headset on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15123]: Found Hansfree record
bluetoothd[15123]: Discovered Handsfree service on RFCOMM channel 1
bluetoothd[15123]: headset_probe: path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15123]: Registered interface org.bluez.Input on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[15123]: Creating device /org/bluez/hci0/dev_00_14_A7_74_D3_AF
bluetoothd[15123]: Creating device /org/bluez/hci0/dev_00_03_89_B7_F8_D3
bluetoothd[15123]: Creating device /org/bluez/hci0/dev_00_0A_94_94_4F_B3
bluetoothd[15123]: Creating device /org/bluez/hci0/dev_00_03_89_DC_5C_9F
bluetoothd[15123]: Creating device /org/bluez/hci0/dev_00_03_89_DC_FC_EC
bluetoothd[15123]: Creating device /org/bluez/hci0/dev_00_03_89_FE_E6_19
bluetoothd[15123]: Creating device /org/bluez/hci0/dev_00_0E_6D_8F_91_6A
bluetoothd[15123]: Creating device /org/bluez/hci0/dev_00_17_E5_E6_25_AB
bluetoothd[15123]: Creating device /org/bluez/hci0/dev_00_17_E5_16_88_6C
bluetoothd[15123]: Creating device /org/bluez/hci0/dev_00_17_E5_0C_EA_70
bluetoothd[15123]: Adapter /org/bluez/hci0 has been enabled
bluetoothd[15123]: Starting security manager 0
bluetoothd[15123]: child 15132 exited
bluetoothd[15123]: Computer is classified as desktop
bluetoothd[15123]: Current device class is 0x4a0104
bluetoothd[15123]: Setting 0x000104 for major/minor device class
bluetoothd[15123]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15123]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15123]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15123]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15123]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15123]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15123]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[15123]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[15123]: kernel auth requirements = 0x04
bluetoothd[15123]: stored link key type = 0x00
bluetoothd[15123]: connect(): Connection timed out (110)
bluetoothd[15123]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[15123]: telephony-dummy: device 0x4b707b0 disconnected
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[15123]: Audio API: received BT_STREAMSTART_REQ
bluetoothd[15123]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[15123]: Audio API: sending BT_STREAMFD_IND
bluetoothd[15123]: unix_sendmsg_fd: Bad file descriptor(9)
bluetoothd[15123]: resume failed
bluetoothd[15123]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[15123]: Unix client disconnected (fd=23)
bluetoothd[15123]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15123]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15123]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15123]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15123]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15123]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15123]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[15123]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[15123]: kernel auth requirements = 0x04
bluetoothd[15123]: stored link key type = 0x00
bluetoothd[15123]: connect(): Connection reset by peer (104)
bluetoothd[15123]: Unable to lock headset
bluetoothd[15123]: config failed
bluetoothd[15123]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[15123]: telephony-dummy: device 0x4b707b0 disconnected
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[15123]: Unix client disconnected (fd=23)
bluetoothd[15123]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15123]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15123]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15123]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15123]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15123]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15123]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[15123]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[15123]: kernel auth requirements = 0x04
bluetoothd[15123]: stored link key type = 0x00
bluetoothd[15123]: connect(): Connection timed out (110)
bluetoothd[15123]: Unable to lock headset
bluetoothd[15123]: config failed
bluetoothd[15123]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[15123]: telephony-dummy: device 0x4b707b0 disconnected
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[15123]: Unix client disconnected (fd=23)
bluetoothd[15123]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15123]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15123]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15123]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15123]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15123]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15123]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[15123]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[15123]: kernel auth requirements = 0x04
bluetoothd[15123]: stored link key type = 0x00
bluetoothd[15123]: Unix client disconnected (fd=23)
bluetoothd[15123]: telephony-dummy: device 0x4b707b0 disconnected
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[15123]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15123]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15123]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15123]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15123]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15123]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15123]: connect(): Connection timed out (110)
bluetoothd[15123]: Unable to lock headset
bluetoothd[15123]: config failed
bluetoothd[15123]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[15123]: telephony-dummy: device 0x4b707b0 disconnected
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[15123]: Unix client disconnected (fd=23)
bluetoothd[15123]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15123]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15123]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15123]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15123]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15123]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15123]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[15123]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[15123]: kernel auth requirements = 0x04
bluetoothd[15123]: stored link key type = 0x00
bluetoothd[15123]: connect(): Connection timed out (110)
bluetoothd[15123]: Unable to lock headset
bluetoothd[15123]: config failed
bluetoothd[15123]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[15123]: telephony-dummy: device 0x4b707b0 disconnected
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[15123]: Unix client disconnected (fd=23)
bluetoothd[15123]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15123]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15123]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15123]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15123]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15123]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15123]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[15123]: connect(): Connection timed out (110)
bluetoothd[15123]: Unable to lock headset
bluetoothd[15123]: config failed
bluetoothd[15123]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[15123]: telephony-dummy: device 0x4b707b0 disconnected
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[15123]: Unix client disconnected (fd=23)
bluetoothd[15123]: Accepted new client connection on unix socket (fd=23)
bluetoothd[15123]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[15123]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[15123]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[15123]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[15123]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[15123]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[15123]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[15123]: kernel auth requirements = 0x04
bluetoothd[15123]: stored link key type = 0x00
bluetoothd[15123]: Unix client disconnected (fd=23)
bluetoothd[15123]: telephony-dummy: device 0x4b707b0 disconnected
bluetoothd[15123]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[15123]: connect(): Connection timed out (110)
==15123== Invalid read of size 4
==15123== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==15123== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==15123== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==15123== by 0x1361D: error_common_reply (in /usr/local/stow/bluez-4.11/sbin/bluetoothd)
==15123== by 0x4ED9D2C: error_connection_attempt_failed (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15123== by 0x4EDAEA2: rfcomm_connect_cb (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15123== by 0x2165E: connect_cb (in /usr/local/stow/bluez-4.11/sbin/bluetoothd)
==15123== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0xA410: main (in /usr/local/stow/bluez-4.11/sbin/bluetoothd)
==15123== Address 0x464c45b3 is not stack'd, malloc'd or (recently) free'd
==15123==
==15123== Process terminating with default action of signal 11 (SIGSEGV)
==15123== Access not within mapped region at address 0x464C45B3
==15123== at 0x490CBF3: (within /usr/lib/libdbus-1.so.3.4.0)
==15123== by 0x4911DD1: dbus_message_get_sender (in /usr/lib/libdbus-1.so.3.4.0)
==15123== by 0x49155C0: dbus_message_new_error (in /usr/lib/libdbus-1.so.3.4.0)
==15123== by 0x1361D: error_common_reply (in /usr/local/stow/bluez-4.11/sbin/bluetoothd)
==15123== by 0x4ED9D2C: error_connection_attempt_failed (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15123== by 0x4EDAEA2: rfcomm_connect_cb (in /usr/local/stow/bluez-4.11/lib/bluetooth/plugins/audio.so)
==15123== by 0x2165E: connect_cb (in /usr/local/stow/bluez-4.11/sbin/bluetoothd)
==15123== by 0x48B465C: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0x487E1B7: g_main_context_dispatch (in /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0x4881852: (within /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0x4881D71: g_main_loop_run (in /usr/lib/libglib-2.0.so.0.1600.6)
==15123== by 0xA410: main (in /usr/local/stow/bluez-4.11/sbin/bluetoothd)
==15123==
==15123== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 84 from 2)
==15123== malloc/free: in use at exit: 46,759 bytes in 872 blocks.
==15123== malloc/free: 3,266 allocs, 2,394 frees, 1,953,427 bytes allocated.
==15123== For counts of detected errors, rerun with: -v
==15123== searching for pointers to 872 not-freed blocks.
==15123== checked 161,856 bytes.
==15123==
==15123== LEAK SUMMARY:
==15123== definitely lost: 594 bytes in 10 blocks.
==15123== possibly lost: 744 bytes in 3 blocks.
==15123== still reachable: 45,421 bytes in 859 blocks.
==15123== suppressed: 0 bytes in 0 blocks.
==15123== Rerun with --leak-check=full to see details of leaked memory.
Segmentation fault


2008-10-05 19:17:21

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez-4.11 + 2.6.27-rc8 + SCO headset -> bluetoothd: connect(): Connection timed out (110)

HCI sniffer - Bluetooth packet analyzer ver 1.42
device: hci0 snap_len: 1028 filter: 0xffffffff
< HCI Command: Create Connection (0x01|0x0005) plen 13
bdaddr 00:1A:45:2F:49:98 ptype 0xcc18 rswitch 0x01 clkoffset 0x0000
Packet type: DM1 DM3 DM5 DH1 DH3 DH5
> HCI Event: Command Status (0x0f) plen 4
Create Connection (0x01|0x0005) status 0x00 ncmd 1
> HCI Event: Connect Complete (0x03) plen 11
status 0x00 handle 41 bdaddr 00:1A:45:2F:49:98 type ACL encrypt 0x00
< HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2
handle 41
> HCI Event: Command Status (0x0f) plen 4
Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 0
> HCI Event: Page Scan Repetition Mode Change (0x20) plen 7
bdaddr 00:1A:45:2F:49:98 mode 1
> HCI Event: Max Slots Change (0x1b) plen 3
handle 41 slots 5
> HCI Event: Command Status (0x0f) plen 4
Unknown (0x00|0x0000) status 0x00 ncmd 1
< HCI Command: Remote Name Request (0x01|0x0019) plen 10
bdaddr 00:1A:45:2F:49:98 mode 2 clkoffset 0x0000
> HCI Event: Command Status (0x0f) plen 4
Remote Name Request (0x01|0x0019) status 0x00 ncmd 1
> HCI Event: Read Remote Supported Features (0x0b) plen 11
status 0x00 handle 41
Features: 0xbf 0xfe 0x8b 0xf8 0x1b 0x18 0x00 0x80
< ACL data: handle 41 flags 0x02 dlen 10
L2CAP(s): Info req: type 2
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 16
L2CAP(s): Info rsp: type 2 result 0
Extended feature mask 0x0000
< ACL data: handle 41 flags 0x02 dlen 12
L2CAP(s): Connect req: psm 3 scid 0x0040
> ACL data: handle 41 flags 0x02 dlen 16
L2CAP(s): Connect rsp: dcid 0x0050 scid 0x0040 result 1 status 2
Connection pending - Authorization pending
> HCI Event: Remote Name Req Complete (0x07) plen 255
status 0x00 bdaddr 00:1A:45:2F:49:98 name 'Jabra JX10 series 2'
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Link Key Request (0x17) plen 6
bdaddr 00:1A:45:2F:49:98
< HCI Command: Link Key Request Reply (0x01|0x000b) plen 22
bdaddr 00:1A:45:2F:49:98 key F63331CE2D0DBCA190DC73C930CD6117
> HCI Event: Command Complete (0x0e) plen 10
Link Key Request Reply (0x01|0x000b) ncmd 1
status 0x00 bdaddr 00:1A:45:2F:49:98
> ACL data: handle 41 flags 0x02 dlen 16
L2CAP(s): Connect rsp: dcid 0x0050 scid 0x0040 result 0 status 0
Connection successful
< ACL data: handle 41 flags 0x02 dlen 16
L2CAP(s): Config req: dcid 0x0050 flags 0x00 clen 4
MTU 1013
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 14
L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 0
Success
> ACL data: handle 41 flags 0x02 dlen 16
L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4
MTU 1013
< ACL data: handle 41 flags 0x02 dlen 18
L2CAP(s): Config rsp: scid 0x0050 flags 0x00 result 0 clen 4
MTU 1013
< ACL data: handle 41 flags 0x02 dlen 8
L2CAP(d): cid 0x0050 len 4 [psm 3]
RFCOMM(s): SABM: cr 1 dlci 0 pf 1 ilen 0 fcs 0x1c
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 8
L2CAP(d): cid 0x0040 len 4 [psm 3]
RFCOMM(s): UA: cr 1 dlci 0 pf 1 ilen 0 fcs 0xd7
< ACL data: handle 41 flags 0x02 dlen 18
L2CAP(d): cid 0x0050 len 14 [psm 3]
RFCOMM(s): PN CMD: cr 1 dlci 0 pf 0 ilen 10 fcs 0x70 mcc_len 8
dlci 2 frame_type 0 credit_flow 15 pri 7 ack_timer 0
frame_size 1008 max_retrans 0 credits 7
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 18
L2CAP(d): cid 0x0040 len 14 [psm 3]
RFCOMM(s): PN RSP: cr 0 dlci 0 pf 0 ilen 10 fcs 0xaa mcc_len 8
dlci 2 frame_type 0 credit_flow 14 pri 7 ack_timer 0
frame_size 127 max_retrans 0 credits 0
< ACL data: handle 41 flags 0x02 dlen 8
L2CAP(d): cid 0x0050 len 4 [psm 3]
RFCOMM(s): SABM: cr 1 dlci 2 pf 1 ilen 0 fcs 0x59
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 8
L2CAP(d): cid 0x0040 len 4 [psm 3]
RFCOMM(s): UA: cr 1 dlci 2 pf 1 ilen 0 fcs 0x92
< ACL data: handle 41 flags 0x02 dlen 12
L2CAP(d): cid 0x0050 len 8 [psm 3]
RFCOMM(s): MSC CMD: cr 1 dlci 0 pf 0 ilen 4 fcs 0x70 mcc_len 2
dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 0 b2 0 b3 0 len 0
> ACL data: handle 41 flags 0x02 dlen 12
L2CAP(d): cid 0x0040 len 8 [psm 3]
RFCOMM(s): MSC CMD: cr 0 dlci 0 pf 0 ilen 4 fcs 0xaa mcc_len 2
dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 0 b1 0 b2 0 b3 0 len 0
< ACL data: handle 41 flags 0x02 dlen 12
L2CAP(d): cid 0x0050 len 8 [psm 3]
RFCOMM(s): MSC RSP: cr 1 dlci 0 pf 0 ilen 4 fcs 0x70 mcc_len 2
dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 0 b1 0 b2 0 b3 0 len 0
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 12
L2CAP(d): cid 0x0040 len 8 [psm 3]
RFCOMM(s): MSC RSP: cr 0 dlci 0 pf 0 ilen 4 fcs 0xaa mcc_len 2
dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 0 b2 0 b3 0 len 0
< ACL data: handle 41 flags 0x02 dlen 9
L2CAP(d): cid 0x0050 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 1 ilen 0 fcs 0x86 credits 33
> ACL data: handle 41 flags 0x02 dlen 9
L2CAP(d): cid 0x0040 len 5 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 0 fcs 0x5c credits 15
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 19
L2CAP(d): cid 0x0040 len 15 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 0 ilen 11 fcs 0x40
0000: 41 54 2b 42 52 53 46 3d 32 37 0d AT+BRSF=27.
< ACL data: handle 41 flags 0x02 dlen 21
L2CAP(d): cid 0x0050 len 17 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 13 fcs 0x9a
0000: 0d 0a 2b 42 52 53 46 3d 33 35 32 0d 0a ..+BRSF=352..
< ACL data: handle 41 flags 0x02 dlen 14
L2CAP(d): cid 0x0050 len 10 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 6 fcs 0x9a
0000: 0d 0a 4f 4b 0d 0a ..OK..
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 19
L2CAP(d): cid 0x0040 len 15 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 10 fcs 0x5c credits 2
0000: 41 54 2b 43 49 4e 44 3d 3f 0d AT+CIND=?.
< ACL data: handle 41 flags 0x02 dlen 135
L2CAP(d): cid 0x0050 len 131 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 127 fcs 0x9a
0000: 0d 0a 2b 43 49 4e 44 3a 28 22 62 61 74 74 63 68 ..+CIND:("battch
0010: 67 22 2c 28 30 2d 35 29 29 2c 28 22 73 69 67 6e g",(0-5)),("sign
0020: 61 6c 22 2c 28 30 2d 35 29 29 2c 28 22 73 65 72 al",(0-5)),("ser
0030: 76 69 63 65 22 2c 28 30 2c 31 29 29 2c 28 22 63 vice",(0,1)),("c
0040: 61 6c 6c 22 2c 28 30 2c 31 29 29 2c 28 22 63 61 all",(0,1)),("ca
0050: 6c 6c 73 65 74 75 70 22 2c 28 30 2d 33 29 29 2c llsetup",(0-3)),
0060: 28 22 63 61 6c 6c 68 65 6c 64 22 2c 28 30 2d 32 ("callheld",(0-2
0070: 29 29 2c 28 22 72 6f 61 6d 22 2c 28 30 2c 31 )),("roam",(0,1
< ACL data: handle 41 flags 0x02 dlen 12
L2CAP(d): cid 0x0050 len 8 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 4 fcs 0x9a
0000: 29 29 0d 0a ))..
< ACL data: handle 41 flags 0x02 dlen 14
L2CAP(d): cid 0x0050 len 10 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 6 fcs 0x9a
0000: 0d 0a 4f 4b 0d 0a ..OK..
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 18
L2CAP(d): cid 0x0040 len 14 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 9 fcs 0x5c credits 3
0000: 41 54 2b 43 49 4e 44 3f 0d AT+CIND?.
< ACL data: handle 41 flags 0x02 dlen 31
L2CAP(d): cid 0x0050 len 27 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 23 fcs 0x9a
0000: 0d 0a 2b 43 49 4e 44 3a 35 2c 35 2c 31 2c 30 2c ..+CIND:5,5,1,0,
0010: 30 2c 30 2c 30 0d 0a 0,0,0..
< ACL data: handle 41 flags 0x02 dlen 14
L2CAP(d): cid 0x0050 len 10 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 6 fcs 0x9a
0000: 0d 0a 4f 4b 0d 0a ..OK..
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> ACL data: handle 41 flags 0x02 dlen 28
L2CAP(d): cid 0x0040 len 24 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 19 fcs 0x5c credits 2
0000: 41 54 2b 43 4d 45 52 3d 33 2c 20 30 2c 20 30 2c AT+CMER=3, 0, 0,
0010: 20 31 0d 1.
< HCI Command: Add SCO Connection (0x01|0x0007) plen 4
handle 41 ptype 0x00e0
Packet type: HV1 HV2 HV3
< ACL data: handle 41 flags 0x02 dlen 14
L2CAP(d): cid 0x0050 len 10 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 6 fcs 0x9a
0000: 0d 0a 4f 4b 0d 0a ..OK..
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Command Status (0x0f) plen 4
Add SCO Connection (0x01|0x0007) status 0x00 ncmd 1
> HCI Event: Max Slots Change (0x1b) plen 3
handle 41 slots 1
> ACL data: handle 41 flags 0x02 dlen 17
> ACL data: handle 41 flags 0x01 dlen 2
L2CAP(d): cid 0x0040 len 15 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 10 fcs 0x5c credits 1
0000: 41 54 2b 56 47 53 3d 31 32 0d AT+VGS=12.
< ACL data: handle 41 flags 0x02 dlen 14
L2CAP(d): cid 0x0050 len 10 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 2 pf 0 ilen 6 fcs 0x9a
0000: 0d 0a 4f 4b 0d 0a ..OK..
> HCI Event: Number of Completed Packets (0x13) plen 5
handle 41 packets 1
> HCI Event: Connect Complete (0x03) plen 11
status 0x00 handle 45 bdaddr 00:1A:45:2F:49:98 type SCO encrypt 0x00
> HCI Event: Max Slots Change (0x1b) plen 3
handle 41 slots 3
> SCO data: handle 45 flags 0x00 dlen 48
0000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
> SCO data: handle 45 flags 0x00 dlen 48
0000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
> SCO data: handle 45 flags 0x00 dlen 48
0000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
> SCO data: handle 45 flags 0x00 dlen 48
0000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
> SCO data: handle 45 flags 0x00 dlen 48
0000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
> SCO data: handle 45 flags 0x00 dlen 48
0000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
> SCO data: handle 45 flags 0x00 dlen 48
0000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
> SCO data: handle 45 flags 0x00 dlen 48
0000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
> SCO data: handle 45 flags 0x00 dlen 48
0000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[.........]
0000: 08 00 51 00 4d 00 f2 ff cf ff 09 00 2b 00 e7 ff ..Q.M.......+...
0010: a2 ff bc ff 1f 00 22 00 e4 ff e9 ff e2 ff 05 00 ......".........
0020: 31 00 13 00 02 00 f5 ff 1f 00 44 00 e5 ff b2 ff 1.........D.....
> SCO data: handle 45 flags 0x00 dlen 48
0000: c2 ff c3 ff ef ff fd ff 03 00 1b 00 1e 00 33 00 ..............3.
0010: 0e 00 ce ff d6 ff cd ff fb ff 50 00 08 00 e8 ff ..........P.....
0020: 12 00 e7 ff 05 00 1a 00 f3 ff fc ff e7 ff e7 ff ................
< HCI Command: Disconnect (0x01|0x0006) plen 3
handle 45 reason 0x13
Reason: Remote User Terminated Connection
> HCI Event: Command Status (0x0f) plen 4
Disconnect (0x01|0x0006) status 0x00 ncmd 1
> SCO data: handle 45 flags 0x00 dlen 48
0000: f0 ff c3 ff ab ff dc ff 22 00 1f 00 18 00 0f 00 ........".......
0010: dd ff d8 ff fb ff 24 00 21 00 20 00 47 00 15 00 ......$.!. .G...
0020: cb ff a7 ff cd ff 2d 00 f8 ff d8 ff 08 00 d6 ff ......-.........
> SCO data: handle 45 flags 0x00 dlen 48
0000: f5 ff 1c 00 fd ff 36 00 2a 00 f3 ff 1c 00 03 00 ......6.*.......
0010: d9 ff 02 00 0b 00 0a 00 fd ff d3 ff d2 ff db ff ................
0020: e8 ff 0a 00 2a 00 2f 00 0e 00 bc ff b3 ff 10 00 ....*./.........
> SCO data: handle 45 flags 0x00 dlen 48
0000: dc ff c7 ff 23 00 e2 ff ca ff f4 ff f0 ff fe ff ....#...........
0010: f6 ff 0c 00 22 00 1d 00 13 00 13 00 2a 00 04 00 ....".......*...
0020: 08 00 2a 00 fa ff e3 ff e5 ff 1a 00 3c 00 f1 ff ..*.........<...
> SCO data: handle 45 flags 0x00 dlen 48
0000: ff ff 0a 00 c4 ff ed ff 14 00 b8 ff 8c ff fb ff ................
0010: 09 00 b4 ff f4 ff 0a 00 c3 ff e3 ff 1a 00 03 00 ................
0020: d8 ff ec ff fe ff 08 00 33 00 0b 00 07 00 47 00 ........3.....G.
> SCO data: handle 45 flags 0x00 dlen 48
0000: 0a 00 df ff 14 00 27 00 32 00 24 00 fd ff ff ff ......'.2.$.....
0010: 02 00 ed ff c5 ff a6 ff c6 ff 02 00 e8 ff c5 ff ................
0020: fb ff f5 ff e5 ff 05 00 0f 00 06 00 df ff 0e 00 ................
> SCO data: handle 45 flags 0x00 dlen 48
0000: 45 00 17 00 0d 00 fa ff d8 ff f4 ff 1d 00 47 00 E.............G.
0010: 39 00 03 00 da ff df ff 00 00 ea ff fe ff 18 00 9...............
0020: cd ff c3 ff e3 ff cc ff d0 ff fd ff 17 00 12 00 ................
> HCI Event: Disconn Complete (0x05) plen 4
status 0x00 handle 45 reason 0x16
Reason: Connection Terminated by Local Host
> SCO data: handle 45 flags 0x00 dlen 48
0000: 13 00 f3 ff d6 ff 01 00 21 00 16 00 04 00 00 00 ........!.......
0010: f5 ff fe ff 24 00 ec ff d3 ff 15 00 fc ff e7 ff ....$...........
0020: 00 00 fa ff f1 ff 0a 00 2f 00 ef ff b6 ff c1 ff ......../.......
> SCO data: handle 45 flags 0x00 dlen 48
0000: 9e ff 0f 00 93 00 01 00 c7 ff 21 00 12 00 2e 00 ..........!.....
0010: 96 ff 24 ff 9d 01 ab 00 0d fd 79 00 8e 00 fc fe ..$.......y.....
0020: e4 03 c3 ff 07 fd d7 00 4b fe f5 ff 2a 00 3d fe ........K...*.=.
> HCI Event: Max Slots Change (0x1b) plen 3
handle 41 slots 5


Attachments:
2.6.27-rc8-bluez-4.11.txt-trim (15.78 kB)

2008-10-05 17:50:43

by Johan Hedberg

[permalink] [raw]
Subject: Re: bluez-4.11 + 2.6.27-rc8 + SCO headset -> bluetoothd: connect(): Connection timed out (110)


On Oct 5, 2008, at 1:24, Stuart Pook wrote:
> not for me :-( I am once again getting the "aplay: set_params:979:
> Unable to install hw params:" message after a 40 second delay.
>
> The headset hisses softly to me during these 40 seconds.
>
> The error message from bluetoothd is "connect(): Connection timed
> out (110)"

This seems to be some other error than the one that was fixed in 4.11.
Could you try to get a hcidump of when this happens. It might be able
to tell more about what's going on.

> Sometimes bluetoothd segfaults.

That's something more serious. Could you please try to produce a
backtrace, either with gdb or valgrind. Thanks!

Johan

2008-10-04 23:24:14

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez-4.11 + 2.6.27-rc8 + SCO headset -> bluetoothd: connect(): Connection timed out (110)

Hi Marcel

On 04/10/08 13:51, Marcel Holtmann wrote:
>>> There is a regression on bluetoothd daemon, we introduce a SCO socket
>>> listen recently which is causing the problem, although it seem that
>>> the driver is also cooperating with the problem.
>> ok. Thanks for the information. Would installing bluez-4.10 help?
> I will release 4.11 over the weekend and that should fix it.

not for me :-( I am once again getting the "aplay: set_params:979:
Unable to install hw params:" message after a 40 second delay.

The headset hisses softly to me during these 40 seconds.

The error message from bluetoothd is "connect(): Connection timed out (110)"

Sometimes bluetoothd segfaults.

Would you like to see the output of hcidump?

Oct 5 01:08:44 kooka bluetoothd[21788]: Bluetooth daemon
Oct 5 01:08:44 kooka bluetoothd[21788]: Enabling debug information
Oct 5 01:08:44 kooka bluetoothd[21788]: parsing main.conf
Oct 5 01:08:44 kooka bluetoothd[21788]: offmode=NoScan
Oct 5 01:08:44 kooka bluetoothd[21788]: discovto=0
Oct 5 01:08:44 kooka bluetoothd[21788]: pageto=8192
Oct 5 01:08:44 kooka bluetoothd[21788]: name=%h-%d
Oct 5 01:08:44 kooka bluetoothd[21788]: class=0x000100
Oct 5 01:08:44 kooka bluetoothd[21788]: inqmode=0
Oct 5 01:08:44 kooka bluetoothd[21788]: Starting SDP server
Oct 5 01:08:44 kooka bluetoothd[21788]: Loading plugins /usr/local/lib/bluetooth/plugins
Oct 5 01:08:44 kooka bluetoothd[21788]: /usr/local/lib/bluetooth/plugins/audio.so
Oct 5 01:08:44 kooka bluetoothd[21788]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory
Oct 5 01:08:44 kooka bluetoothd[21788]: Unix socket created: 11
Oct 5 01:08:44 kooka bluetoothd[21788]: Telephony plugin initialized
Oct 5 01:08:44 kooka bluetoothd[21788]: HFP AG features: "Ability to reject a call" "Enhanced call status" "Extended Error Result Codes"
Oct 5 01:08:44 kooka bluetoothd[21788]: /usr/local/lib/bluetooth/plugins/serial.so
Oct 5 01:08:44 kooka bluetoothd[21788]: /usr/local/lib/bluetooth/plugins/hal.so
Oct 5 01:08:44 kooka bluetoothd[21788]: /usr/local/lib/bluetooth/plugins/service.so
Oct 5 01:08:44 kooka bluetoothd[21788]: /usr/local/lib/bluetooth/plugins/network.so
Oct 5 01:08:44 kooka bluetoothd[21788]: Parsing /etc/bluetooth/network.conf failed: No such file or directory
Oct 5 01:08:44 kooka bluetoothd[21788]: Config options: InterfacePrefix=bnep%d, PANU_Script=(null), GN_Script=(null), NAP_Script=(null), GN_Interface=pan0, NAP_Interface=pan1, Security=true
Oct 5 01:08:44 kooka bluetoothd[21788]: bridge pan0 created
Oct 5 01:08:44 kooka bluetoothd[21788]: /usr/local/lib/bluetooth/plugins/input.so
Oct 5 01:08:44 kooka bluetoothd[21788]: input.conf: Key file does not have key 'IdleTimeout'
Oct 5 01:08:44 kooka bluetoothd[21788]: HCI dev 0 registered
Oct 5 01:08:44 kooka bluetoothd[21788]: child 21791 forked
Oct 5 01:08:44 kooka bluetoothd[21788]: HCI dev 0 already up
Oct 5 01:08:44 kooka bluetoothd[21788]: headset_server_probe: path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: Adding record with handle 0x10000
Oct 5 01:08:44 kooka bluetoothd[21788]: Adding record with handle 0x10001
Oct 5 01:08:44 kooka bluetoothd[21788]: a2dp_server_probe: path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: SEP 0xb9818800 registered: type:0 codec:0 seid:1
Oct 5 01:08:44 kooka bluetoothd[21788]: Adding record with handle 0x10002
Oct 5 01:08:44 kooka bluetoothd[21788]: avrcp_server_probe: path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: Adding record with handle 0x10003
Oct 5 01:08:44 kooka bluetoothd[21788]: Adding record with handle 0x10004
Oct 5 01:08:44 kooka bluetoothd[21788]: proxy_probe: path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: Registered interface org.bluez.SerialProxyManager on path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: service_probe: path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: Registered interface org.bluez.Service on path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: network_server_probe: path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: Adding record with handle 0x10005
Oct 5 01:08:44 kooka bluetoothd[21788]: register_server_record: got record id 0x10005
Oct 5 01:08:44 kooka bluetoothd[21788]: Registered interface org.bluez.NetworkPeer on path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: network_server_probe: path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: Adding record with handle 0x10006
Oct 5 01:08:44 kooka bluetoothd[21788]: register_server_record: got record id 0x10006
Oct 5 01:08:44 kooka bluetoothd[21788]: Registered interface org.bluez.NetworkHub on path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: network_server_probe: path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: Adding record with handle 0x10007
Oct 5 01:08:44 kooka bluetoothd[21788]: register_server_record: got record id 0x10007
Oct 5 01:08:44 kooka bluetoothd[21788]: Registered interface org.bluez.NetworkRouter on path /org/bluez/hci0
Oct 5 01:08:44 kooka bluetoothd[21788]: Creating device /org/bluez/hci0/dev_00_1A_45_2F_49_98
Oct 5 01:08:44 kooka bluetoothd[21788]: Probe drivers for /org/bluez/hci0/dev_00_1A_45_2F_49_98
Oct 5 01:08:44 kooka bluetoothd[21788]: Found Headset record
Oct 5 01:08:44 kooka bluetoothd[21788]: Discovered Headset service on RFCOMM channel 2
Oct 5 01:08:44 kooka bluetoothd[21788]: Registered interface org.bluez.Headset on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
Oct 5 01:08:44 kooka bluetoothd[21788]: Found Hansfree record
Oct 5 01:08:44 kooka bluetoothd[21788]: Discovered Handsfree service on RFCOMM channel 1
Oct 5 01:08:44 kooka bluetoothd[21788]: headset_probe: path /org/bluez/hci0/dev_00_1A_45_2F_49_98
Oct 5 01:08:44 kooka bluetoothd[21788]: Registered interface org.bluez.Input on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
Oct 5 01:08:44 kooka bluetoothd[21788]: Creating device /org/bluez/hci0/dev_00_14_A7_74_D3_AF
Oct 5 01:08:44 kooka bluetoothd[21788]: Creating device /org/bluez/hci0/dev_00_03_89_B7_F8_D3
Oct 5 01:08:44 kooka bluetoothd[21788]: Creating device /org/bluez/hci0/dev_00_0A_94_94_4F_B3
Oct 5 01:08:44 kooka bluetoothd[21788]: Creating device /org/bluez/hci0/dev_00_03_89_DC_5C_9F
Oct 5 01:08:44 kooka bluetoothd[21788]: Creating device /org/bluez/hci0/dev_00_03_89_DC_FC_EC
Oct 5 01:08:44 kooka bluetoothd[21788]: Creating device /org/bluez/hci0/dev_00_03_89_FE_E6_19
Oct 5 01:08:44 kooka bluetoothd[21788]: Creating device /org/bluez/hci0/dev_00_0E_6D_8F_91_6A
Oct 5 01:08:44 kooka bluetoothd[21788]: Creating device /org/bluez/hci0/dev_00_17_E5_E6_25_AB
Oct 5 01:08:44 kooka bluetoothd[21788]: Creating device /org/bluez/hci0/dev_00_17_E5_16_88_6C
Oct 5 01:08:44 kooka bluetoothd[21788]: Creating device /org/bluez/hci0/dev_00_17_E5_0C_EA_70
Oct 5 01:08:44 kooka bluetoothd[21788]: Adapter /org/bluez/hci0 has been enabled
Oct 5 01:08:44 kooka bluetoothd[21788]: Starting security manager 0
Oct 5 01:08:44 kooka bluetoothd[21788]: child 21791 exited
Oct 5 01:08:44 kooka bluetoothd[21788]: Computer is classified as desktop
Oct 5 01:08:44 kooka bluetoothd[21788]: Current device class is 0x4a0104
Oct 5 01:08:44 kooka bluetoothd[21788]: Setting 0x000104 for major/minor device class
Oct 5 01:09:03 kooka bluetoothd[21788]: Accepted new client connection on unix socket (fd=23)
Oct 5 01:09:03 kooka bluetoothd[21788]: Audio API: received BT_GETCAPABILITIES_REQ
Oct 5 01:09:03 kooka bluetoothd[21788]: Audio API: sending BT_GETCAPABILITIES_RSP
Oct 5 01:09:03 kooka bluetoothd[21788]: Audio API: received BT_SETCONFIGURATION_REQ
Oct 5 01:09:03 kooka bluetoothd[21788]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
Oct 5 01:09:03 kooka bluetoothd[21788]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
Oct 5 01:09:03 kooka bluetoothd[21788]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
Oct 5 01:09:06 kooka bluetoothd[21788]: adapter_get_device(00:1A:45:2F:49:98)
Oct 5 01:09:07 kooka bluetoothd[21788]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
Oct 5 01:09:07 kooka bluetoothd[21788]: kernel auth requirements = 0x04
Oct 5 01:09:07 kooka bluetoothd[21788]: stored link key type = 0x00
Oct 5 01:09:07 kooka bluetoothd[21788]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
Oct 5 01:09:07 kooka bluetoothd[21788]: Received AT+BRSF=27
Oct 5 01:09:07 kooka bluetoothd[21788]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
Oct 5 01:09:08 kooka bluetoothd[21788]: Received AT+CIND=?
Oct 5 01:09:08 kooka bluetoothd[21788]: Received AT+CIND?
Oct 5 01:09:08 kooka bluetoothd[21788]: Received AT+CMER=3, 0, 0, 1
Oct 5 01:09:08 kooka bluetoothd[21788]: Event reporting (CMER): mode=3, ind=1
Oct 5 01:09:08 kooka bluetoothd[21788]: HFP Service Level Connection established
Oct 5 01:09:08 kooka bluetoothd[21788]: telephony-dummy: device 0xb981d4f8 connected
Oct 5 01:09:08 kooka bluetoothd[21788]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
Oct 5 01:09:08 kooka bluetoothd[21788]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
Oct 5 01:09:08 kooka bluetoothd[21788]: Received AT+VGS=15
Oct 5 01:09:48 kooka bluetoothd[21788]: connect(): Connection timed out (110)
Oct 5 01:09:48 kooka bluetoothd[21788]: Audio API: sending BT_SETCONFIGURATION_RSP
Oct 5 01:09:48 kooka bluetoothd[21788]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
Oct 5 01:09:48 kooka bluetoothd[21788]: Audio API: received BT_STREAMSTART_REQ
Oct 5 01:09:48 kooka bluetoothd[21788]: Audio API: sending BT_STREAMSTART_RSP
Oct 5 01:09:48 kooka bluetoothd[21788]: Audio API: sending BT_STREAMFD_IND
Oct 5 01:09:48 kooka bluetoothd[21788]: unix_sendmsg_fd: Bad file descriptor(9)
Oct 5 01:09:48 kooka bluetoothd[21788]: resume failed
Oct 5 01:09:48 kooka bluetoothd[21788]: Audio API: sending BT_STREAMSTART_RSP
Oct 5 01:09:48 kooka bluetoothd[21788]: Unix client disconnected (fd=23)
Oct 5 01:09:48 kooka bluetoothd[21788]: No matching connection for handle 49

bluetoothd[22825]: Bluetooth daemon
bluetoothd[22825]: Enabling debug information
bluetoothd[22825]: parsing main.conf
bluetoothd[22825]: offmode=NoScan
bluetoothd[22825]: discovto=0
bluetoothd[22825]: pageto=8192
bluetoothd[22825]: name=%h-%d
bluetoothd[22825]: class=0x000100
bluetoothd[22825]: inqmode=0
bluetoothd[22825]: Starting SDP server
bluetoothd[22825]: Loading plugins /usr/local/lib/bluetooth/plugins
bluetoothd[22825]: /usr/local/lib/bluetooth/plugins/audio.so
bluetoothd[22825]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory
bluetoothd[22825]: Unix socket created: 11
bluetoothd[22825]: Telephony plugin initialized
bluetoothd[22825]: HFP AG features: "Ability to reject a call" "Enhanced call status" "Extended Error Result Codes"
bluetoothd[22825]: /usr/local/lib/bluetooth/plugins/serial.so
bluetoothd[22825]: /usr/local/lib/bluetooth/plugins/hal.so
bluetoothd[22825]: /usr/local/lib/bluetooth/plugins/service.so
bluetoothd[22825]: /usr/local/lib/bluetooth/plugins/network.so
bluetoothd[22825]: Parsing /etc/bluetooth/network.conf failed: No such file or directory
bluetoothd[22825]: Config options: InterfacePrefix=bnep%d, PANU_Script=(null), GN_Script=(null), NAP_Script=(null), GN_Interface=pan0, NAP_Interface=pan1, Security=true
bluetoothd[22825]: bridge pan0 created
bluetoothd[22825]: /usr/local/lib/bluetooth/plugins/input.so
bluetoothd[22825]: input.conf: Key file does not have key 'IdleTimeout'
bluetoothd[22825]: HCI dev 0 registered
bluetoothd[22825]: child 22828 forked
bluetoothd[22825]: HCI dev 0 already up
bluetoothd[22825]: headset_server_probe: path /org/bluez/hci0
bluetoothd[22825]: Adding record with handle 0x10000
bluetoothd[22825]: Adding record with handle 0x10001
bluetoothd[22825]: a2dp_server_probe: path /org/bluez/hci0
bluetoothd[22825]: SEP 0xb8a9b818 registered: type:0 codec:0 seid:1
bluetoothd[22825]: Adding record with handle 0x10002
bluetoothd[22825]: avrcp_server_probe: path /org/bluez/hci0
bluetoothd[22825]: Adding record with handle 0x10003
bluetoothd[22825]: Adding record with handle 0x10004
bluetoothd[22825]: proxy_probe: path /org/bluez/hci0
bluetoothd[22825]: Registered interface org.bluez.SerialProxyManager on path /org/bluez/hci0
bluetoothd[22825]: service_probe: path /org/bluez/hci0
bluetoothd[22825]: Registered interface org.bluez.Service on path /org/bluez/hci0
bluetoothd[22825]: network_server_probe: path /org/bluez/hci0
bluetoothd[22825]: Adding record with handle 0x10005
bluetoothd[22825]: register_server_record: got record id 0x10005
bluetoothd[22825]: Registered interface org.bluez.NetworkPeer on path /org/bluez/hci0
bluetoothd[22825]: network_server_probe: path /org/bluez/hci0
bluetoothd[22825]: Adding record with handle 0x10006
bluetoothd[22825]: register_server_record: got record id 0x10006
bluetoothd[22825]: Registered interface org.bluez.NetworkHub on path /org/bluez/hci0
bluetoothd[22825]: network_server_probe: path /org/bluez/hci0
bluetoothd[22825]: Adding record with handle 0x10007
bluetoothd[22825]: register_server_record: got record id 0x10007
bluetoothd[22825]: Registered interface org.bluez.NetworkRouter on path /org/bluez/hci0
bluetoothd[22825]: Creating device /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[22825]: Probe drivers for /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[22825]: Found Headset record
bluetoothd[22825]: Discovered Headset service on RFCOMM channel 2
bluetoothd[22825]: Registered interface org.bluez.Headset on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[22825]: Found Hansfree record
bluetoothd[22825]: Discovered Handsfree service on RFCOMM channel 1
bluetoothd[22825]: headset_probe: path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[22825]: Registered interface org.bluez.Input on path /org/bluez/hci0/dev_00_1A_45_2F_49_98
bluetoothd[22825]: Creating device /org/bluez/hci0/dev_00_14_A7_74_D3_AF
bluetoothd[22825]: Creating device /org/bluez/hci0/dev_00_03_89_B7_F8_D3
bluetoothd[22825]: Creating device /org/bluez/hci0/dev_00_0A_94_94_4F_B3
bluetoothd[22825]: Creating device /org/bluez/hci0/dev_00_03_89_DC_5C_9F
bluetoothd[22825]: Creating device /org/bluez/hci0/dev_00_03_89_DC_FC_EC
bluetoothd[22825]: Creating device /org/bluez/hci0/dev_00_03_89_FE_E6_19
bluetoothd[22825]: Creating device /org/bluez/hci0/dev_00_0E_6D_8F_91_6A
bluetoothd[22825]: Creating device /org/bluez/hci0/dev_00_17_E5_E6_25_AB
bluetoothd[22825]: Creating device /org/bluez/hci0/dev_00_17_E5_16_88_6C
bluetoothd[22825]: Creating device /org/bluez/hci0/dev_00_17_E5_0C_EA_70
bluetoothd[22825]: Adapter /org/bluez/hci0 has been enabled
bluetoothd[22825]: Starting security manager 0
bluetoothd[22825]: child 22828 exited
bluetoothd[22825]: Computer is classified as desktop
bluetoothd[22825]: Current device class is 0x4a0104
bluetoothd[22825]: Setting 0x000104 for major/minor device class
bluetoothd[22825]: Accepted new client connection on unix socket (fd=23)
bluetoothd[22825]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[22825]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[22825]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[22825]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[22825]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[22825]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[22825]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[22825]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[22825]: kernel auth requirements = 0x04
bluetoothd[22825]: stored link key type = 0x00
bluetoothd[22825]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[22825]: Received AT+BRSF=27
bluetoothd[22825]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[22825]: Received AT+CIND=?
bluetoothd[22825]: Received AT+CIND?
bluetoothd[22825]: Received AT+CMER=3, 0, 0, 1
bluetoothd[22825]: Event reporting (CMER): mode=3, ind=1
bluetoothd[22825]: HFP Service Level Connection established
bluetoothd[22825]: telephony-dummy: device 0xb8aa0518 connected
bluetoothd[22825]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[22825]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[22825]: Received AT+VGS=15
bluetoothd[22825]: connect(): Connection timed out (110)
bluetoothd[22825]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[22825]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[22825]: Audio API: received BT_STREAMSTART_REQ
bluetoothd[22825]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[22825]: Audio API: sending BT_STREAMFD_IND
bluetoothd[22825]: unix_sendmsg_fd: Bad file descriptor(9)
bluetoothd[22825]: resume failed
bluetoothd[22825]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[22825]: Unix client disconnected (fd=23)
bluetoothd[22825]: No matching connection for handle 53
bluetoothd[22825]: Accepted new client connection on unix socket (fd=23)
bluetoothd[22825]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[22825]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[22825]: Unix client disconnected (fd=23)
bluetoothd[22825]: Accepted new client connection on unix socket (fd=23)
bluetoothd[22825]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[22825]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[22825]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[22825]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[22825]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[22825]: Unix client disconnected (fd=23)
bluetoothd[22825]: telephony-dummy: device 0xb8aa0518 disconnected
bluetoothd[22825]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_DISCONNECTED
bluetoothd[22825]: connect(): Connection timed out (110)
Segmentation fault

2008-10-04 11:51:08

by Marcel Holtmann

[permalink] [raw]
Subject: Re: bluez-4.9 + 2.6.27-rc8 + SCO headset -> bluetoothd: connect: Operation not permitted

Hi Stuart,

> > There is a regression on bluetoothd daemon, we introduce a SCO socket
> > listen recently which is causing the problem, although it seem that
> > the driver is also cooperating with the problem.
>
> ok. Thanks for the information. Would installing bluez-4.10 help?

I will release 4.11 over the weekend and that should fix it.

Regards

Marcel



2008-10-04 11:25:27

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez-4.9 + 2.6.27-rc8 + SCO headset -> bluetoothd: connect: Operation not permitted

On 04/10/08 05:47, Luiz Augusto von Dentz wrote:
> There is a regression on bluetoothd daemon, we introduce a SCO socket
> listen recently which is causing the problem, although it seem that
> the driver is also cooperating with the problem.

ok. Thanks for the information. Would installing bluez-4.10 help?

Or would changing my USB blueooth dongle help? I have an old Bluetooth
1.2 Linksys USBBT100 dongle but have ordered a BELKIN F8T017ng
(Bluetooth v2.1 + EDR + Class I) which should arrive in a few days.
Perhaps it will work better though it appears that kernel 2.6.27-rc8
does not include the required quirks (2.6.26-mh6 crashes for me).

I'm keen to get a Bluetooth headset working for VoIP so I could also
change my headset if necessary. My Jabra JX10 Series II is however quite
recent so I'd hope to be able to get it to work.

thanks
Stuart

2008-10-04 03:47:10

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: bluez-4.9 + 2.6.27-rc8 + SCO headset -> bluetoothd: connect: Operation not permitted

There is a regression on bluetoothd daemon, we introduce a SCO socket
listen recently which is causing the problem, although it seem that
the driver is also cooperating with the problem.


--
Luiz Augusto von Dentz
Engenheiro de Computa??o

2008-10-01 17:30:39

by Stuart Pook

[permalink] [raw]
Subject: Re: bluez-4.9 + 2.6.27-rc8 + SCO headset -> bluetoothd: connect: Operation not permitted

On 01/10/08 01:26, David Sainty wrote:
> Stuart Pook wrote:
>> Er, what headsets do work? Please let me know. The Jabra JX10 "features
>> Bluetooth 2.0 and e-SCO for improved audio quality and MultiPoint
>> capability for connecting to 2 devices at once". Could that be
>> what is causing the problem?
> I use a Sony DR-BT20NX stereo headset, with both my kneetop and my phone
> attached (they don't play at once, but the phone can interrupt the audio
> playback). It works great! (*)

I'd like to use my headset to do VoIP via my PC. Do you do that or is
the communication just from your PC to the headset?

I wonder if my problems are due to my old dongle. I have an old
Bluetooth 1.2 Linksys USBBT100 USB dongle. Perhaps it has problems
talking to my Bluetooth 2.0 headset.

I would like a class I Bluetooth 2.x USB dongle. Does anyone have any
suggestions? I could buy a Belkin F8T012fr1 (class I & v2.0) or a Belkin
F8T017ng (class I & v2.1). http://www.bluez.org/ mentions the F8T016 and
its required quirks. I suppose that the F8T017ng is just the class I
version. Would it require the same quirks I wonder?

Stuart

2008-09-30 23:26:18

by David Sainty

[permalink] [raw]
Subject: Re: bluez-4.9 + 2.6.27-rc8 + SCO headset -> bluetoothd: connect: Operation not permitted

Stuart Pook wrote:
> Er, what headsets do work? Please let me know. The Jabra JX10 "features
> Bluetooth 2.0 and e-SCO for improved audio quality and MultiPoint
> capability for connecting to 2 devices at once". Could that be
> what is causing the problem?
I use a Sony DR-BT20NX stereo headset, with both my kneetop and my phone
attached (they don't play at once, but the phone can interrupt the audio
playback). It works great! (*)

(* with the minor flaw that if I walk away out of range of my kneetop,
even when paused, the audio connection is irretrievably broken and I
need to restart the player)



2008-12-09 12:23:56

by sreevani medhahal

[permalink] [raw]
Subject: Re: bluez-4.22 + twinkle -> Unable to lock headset

Hi,
I too face the similar issue with Skype. Is there any workaround to
sort this issue.
contents of asoundrc:
Headset used Planetronics:P590
pcm.bluetooth {
type bluetooth
device 00:19:7F:22:B7:8A
profile "voice"
}

version of Bluez used:4.17
kernel:2.6.27

Snippet of the /var/log/messages
Dec 9 14:34:07 training01 bluetoothd[15235]: Accepted new client
connection on unix socket (fd=25)
Dec 9 14:34:07 training01 bluetoothd[15235]: Audio API: received
BT_GETCAPABILITIES_REQ
Dec 9 14:34:07 training01 bluetoothd[15235]: Audio API: sending
BT_GETCAPABILITIES_RSP
Dec 9 14:34:07 training01 bluetoothd[15235]: Unix client disconnected (fd=25)
Dec 9 14:34:07 training01 bluetoothd[15235]: Accepted new client
connection on unix socket (fd=25)
Dec 9 14:34:07 training01 bluetoothd[15235]: Audio API: received
BT_GETCAPABILITIES_REQ
Dec 9 14:34:07 training01 bluetoothd[15235]: Audio API: sending
BT_GETCAPABILITIES_RSP
Dec 9 14:34:07 training01 bluetoothd[15235]: Audio API: received
BT_SETCONFIGURATION_REQ
Dec 9 14:34:07 training01 bluetoothd[15235]: config sco - device =
00:19:7F:22:B7:8A access_mode = 2
Dec 9 14:34:07 training01 bluetoothd[15235]: State changed
/org/bluez/hci0/dev_00_19_7F_22_B7_8A: HEADSET_STATE_CONNECTED ->
HEADSET_STATE_PLAY_IN_PROGRESS
Dec 9 14:34:47 training01 bluetoothd[15235]: connect(): Connection
timed out (110)
Dec 9 14:34:47 training01 bluetoothd[15235]: Unable to lock headset
Dec 9 14:34:47 training01 bluetoothd[15235]: config failed
Dec 9 14:34:47 training01 bluetoothd[15235]: Audio API: sending
BT_SETCONFIGURATION_RSP

Regards,
Sreevani M
On Tue, Dec 9, 2008 at 12:12 AM, Luiz Augusto von Dentz
<[email protected]> wrote:
> You basically already answer your question, if arecord -D JX10 -f
> S16_LE | aplay -D JX10 -f S16_LE does work, twinkle should work too.
> The problem seems to be that twinkle leaves the connection open and
> attempt to acquire the lock again and again, this is probably a bad
> use of alsa API by twinkle as snd_pcm_prepare should not be called
> more than once.
>
> --
> Luiz Augusto von Dentz
> Engenheiro de Computa??o
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bluetooth" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>

2008-12-08 18:42:23

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: bluez-4.22 + twinkle -> Unable to lock headset

You basically already answer your question, if arecord -D JX10 -f
S16_LE | aplay -D JX10 -f S16_LE does work, twinkle should work too.
The problem seems to be that twinkle leaves the connection open and
attempt to acquire the lock again and again, this is probably a bad
use of alsa API by twinkle as snd_pcm_prepare should not be called
more than once.

--
Luiz Augusto von Dentz
Engenheiro de Computa??o

2008-12-06 12:15:02

by Stuart Pook

[permalink] [raw]
Subject: bluez-4.22 + twinkle -> Unable to lock headset

Hi all

I have been getting the dreaded "Unable to lock headset" message with bluez-4.18 so I decided to upgrade to bluez-4.22. Now I get the message even more often, in fact I can no longer telephone at all using twinkle (1.3.2).

I use bluetooth to make VoIP calls with my Jabra JX10 headset and to connect to my Nokia E65 mobile phone to backup it up. The connection to my phone still works. I can play music using "aplay -D JX10" and do echo tests using "arecord -D JX10 -f S16_LE|aplay -D JX10 -f S16_LE". However using twinkle always fails with the messages "Cannot access the speaker (ALSA: JX10)" and "Cannot access the microphone (ALSA: JX10)". The log window contains "Critical: Opening ALSA driver failed: snd_pcm_prepare failed: Input/output error".

What does "Unable to lock headset" mean?

I have just downgraded to bluez-4.18 and can now make a few calls before I get "Unable to lock headset" & "config failed". When I do get this message I have to restart bluetoothd.

I have a Belkin F8T017 USB adapter and am running linux 2.6.28-rc6.

My /etc/bluetooth/main.conf contains

[General]
DisablePlugins = network,input,serial
Name = %h-%d
Class = 0x000100
DiscoverableTimeout = 0
PageTimeout = 8192
OffMode = NoScan
DiscoverSchedulerInterval = 0

Should I remove anything or add something (to prohibit incoming connections for example)?

thanks!
Stuart

: root@kooka; /usr/local/stow/bluez-4.22/sbin/bluetoothd -dn
bluetoothd[13986]: Bluetooth daemon
bluetoothd[13986]: Enabling debug information
bluetoothd[13986]: parsing main.conf
bluetoothd[13986]: discovto=0
bluetoothd[13986]: Key file does not have key 'PairableTimeout'
bluetoothd[13986]: pageto=8192
bluetoothd[13986]: name=%h-%d
bluetoothd[13986]: class=0x000100
bluetoothd[13986]: inqmode=0
bluetoothd[13986]: Starting SDP server
bluetoothd[13986]: Loading plugins /usr/local/lib/bluetooth/plugins
bluetoothd[13986]: register_interface: path /org/bluez/13986/any
bluetoothd[13986]: Registered interface org.bluez.Service on path /org/bluez/13986/any
bluetoothd[13986]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory
bluetoothd[13986]: Unix socket created: 11
bluetoothd[13986]: Telephony plugin initialized
bluetoothd[13986]: HFP AG features: "Ability to reject a call" "Enhanced call status" "Extended Error Result Codes"
bluetoothd[13986]: HCI dev 0 registered
bluetoothd[13986]: child 13987 forked
bluetoothd[13986]: HCI dev 0 already up
bluetoothd[13986]: Starting security manager 0
bluetoothd[13986]: register_interface: path /org/bluez/13986/hci0
bluetoothd[13986]: Registered interface org.bluez.Service on path /org/bluez/13986/hci0
bluetoothd[13986]: headset_server_probe: path /org/bluez/13986/hci0
bluetoothd[13986]: Adding record with handle 0x10000
bluetoothd[13986]: Record pattern UUID 00000003-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00001108-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00001112-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00001203-0000-1000-8000-00805f9
bluetoothd[13986]: Adding record with handle 0x10001
bluetoothd[13986]: Record pattern UUID 00000003-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 0000111e-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 0000111f-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00001203-0000-1000-8000-00805f9
bluetoothd[13986]: a2dp_server_probe: path /org/bluez/13986/hci0
bluetoothd[13986]: SEP 0xb9e0fb08 registered: type:0 codec:0 seid:1
bluetoothd[13986]: Adding record with handle 0x10002
bluetoothd[13986]: Record pattern UUID 00000019-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 0000110a-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 0000110d-0000-1000-8000-00805f9
bluetoothd[13986]: avrcp_server_probe: path /org/bluez/13986/hci0
bluetoothd[13986]: Adding record with handle 0x10003
bluetoothd[13986]: Record pattern UUID 00000017-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 0000110c-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 0000110e-0000-1000-8000-00805f9
bluetoothd[13986]: Adding record with handle 0x10004
bluetoothd[13986]: Record pattern UUID 00000017-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00000100-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 00001002-0000-1000-8000-00805f9
bluetoothd[13986]: Record pattern UUID 0000110e-0000-1000-8000-00805f9
bluetoothd[13986]: Creating device /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98
bluetoothd[13986]: Probe drivers for /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98
bluetoothd[13986]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[13986]: Found Headset record
bluetoothd[13986]: Discovered Headset service on RFCOMM channel 2
bluetoothd[13986]: Registered interface org.bluez.Headset on path /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98
bluetoothd[13986]: Found Handsfree record
bluetoothd[13986]: Discovered Handsfree service on RFCOMM channel 1
bluetoothd[13986]: Creating device /org/bluez/13986/hci0/dev_00_17_E5_0C_EA_70
bluetoothd[13986]: Probe drivers for /org/bluez/13986/hci0/dev_00_17_E5_0C_EA_70
bluetoothd[13986]: adapter_get_device(00:17:E5:0C:EA:70)
bluetoothd[13986]: audio handle_uuid: server not enabled for 00001112-0000-1000-8000-00805f9b34fb (0x1112)
bluetoothd[13986]: audio handle_uuid: server not enabled for 0000111f-0000-1000-8000-00805f9b34fb (0x111f)
bluetoothd[13986]: Found AV Target
bluetoothd[13986]: Registered interface org.bluez.Control on path /org/bluez/13986/hci0/dev_00_17_E5_0C_EA_70
bluetoothd[13986]: Found AV Target
bluetoothd[13986]: Adapter /org/bluez/13986/hci0 has been enabled
bluetoothd[13986]: child 13987 exited
bluetoothd[13986]: Computer is classified as desktop
bluetoothd[13986]: Current device class is 0x480104
bluetoothd[13986]: Setting 0x000104 for major/minor device class
bluetoothd[13986]: Agent registered for hci0 at :1.232:/org/bluez/agent/hci0

# here I try to telephone using twinkle

bluetoothd[13986]: Accepted new client connection on unix socket (fd=14)
bluetoothd[13986]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[13986]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[13986]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[13986]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[13986]: /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[13986]: State changed /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[13986]: /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[13986]: Received AT+BRSF=27
bluetoothd[13986]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[13986]: Received AT+CIND=?
bluetoothd[13986]: Received AT+CIND?
bluetoothd[13986]: Received AT+CMER=3, 0, 0, 1
bluetoothd[13986]: Event reporting (CMER): mode=3, ind=1
bluetoothd[13986]: HFP Service Level Connection established
bluetoothd[13986]: telephony-dummy: device 0xb9e11300 connected
bluetoothd[13986]: State changed /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[13986]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[13986]: Audio API: received BT_STREAMSTART_REQ
bluetoothd[13986]: State changed /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[13986]: SCO socket opened for headset /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98
bluetoothd[13986]: SCO fd=20
bluetoothd[13986]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[13986]: Audio API: sending BT_STREAMFD_IND
bluetoothd[13986]: State changed /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_PLAYING
bluetoothd[13986]: Audio API: received BT_STREAMSTART_REQ
bluetoothd[13986]: Unable to lock headset
bluetoothd[13986]: headset_resume_complete: resume failed
bluetoothd[13986]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[13986]: Unix client disconnected (fd=14)
bluetoothd[13986]: State changed /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAYING -> HEADSET_STATE_CONNECTED
bluetoothd[13986]: Accepted new client connection on unix socket (fd=14)
bluetoothd[13986]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[13986]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[13986]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[13986]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[13986]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[13986]: Audio API: received BT_STREAMSTART_REQ
bluetoothd[13986]: State changed /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS
bluetoothd[13986]: SCO socket opened for headset /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98
bluetoothd[13986]: SCO fd=20
bluetoothd[13986]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[13986]: Audio API: sending BT_STREAMFD_IND
bluetoothd[13986]: State changed /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_PLAYING
bluetoothd[13986]: Audio API: received BT_STREAMSTART_REQ
bluetoothd[13986]: Unable to lock headset
bluetoothd[13986]: headset_resume_complete: resume failed
bluetoothd[13986]: Audio API: sending BT_STREAMSTART_RSP
bluetoothd[13986]: Unix client disconnected (fd=14)
bluetoothd[13986]: State changed /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAYING -> HEADSET_STATE_CONNECTED
bluetoothd[13986]: No matching connection for handle 6
bluetoothd[13986]: Received AT+VGS=06
bluetoothd[13986]: telephony-dummy: device 0xb9e11300 disconnected
bluetoothd[13986]: State changed /org/bluez/13986/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_DISCONNECTED