Bug 11514
| Summary: | bluetooth headset works with 2.6.26, only hisses with 2.6.27-rc5 | ||
|---|---|---|---|
| Product: | Drivers | Reporter: | Stuart Pook (kernel6org) |
| Component: | Bluetooth | Assignee: | drivers_bluetooth (drivers_bluetooth) |
| Status: | RESOLVED OBSOLETE | ||
| Severity: | normal | CC: | alan, kernel6org, Martin.Jansa, pozsy, someone |
| Priority: | P1 | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Kernel Version: | 2.6.27-rc8 | Subsystem: | |
| Regression: | Yes | Bisected commit-id: | |
| Attachments: |
output from hcidump during aplay on 2.6.27-rc5
messages from bluetoothd on 2.6.27-rc5 during aplay hcidump during aplay on 2.6.26-1-686 messages from bluetoothd during aplay on 2.6.26 output from hcidump -X -V during aplay on 2.6.27-rc5 hcidump -XV during aplay on 2.6.26 (Debian) |
||
|
Description
Stuart Pook
2008-09-07 03:33:22 UTC
Created attachment 17649 [details]
output from hcidump during aplay on 2.6.27-rc5
I captured the output of "hcidump | uniq -c" while running "bluetoothd -dn" and "aplay -D JX10 alarm.wav". While aplay was running I also pressed on the volume up and down buttons on my headset. After 40 seconds bluetoothd said "connect(): Connection timed out (110)" and aplay said "Unable to install hw params".
Created attachment 17650 [details]
messages from bluetoothd on 2.6.27-rc5 during aplay
This is what bluetoothd (bluez-4.4) wrote to /var/log/daemon.log when I ran "aplay -D JX10 alarm.wav". I logged the aplay command as well. Note the 40 seconds between the connection and the "Connection timed out". Duing these 40 seconds (see the previous attachment) lots of packets were received from the headset.
Reply-To: akpm@linux-foundation.org (switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface). On Sun, 7 Sep 2008 03:33:23 -0700 (PDT) bugme-daemon@bugzilla.kernel.org wrote: > http://bugzilla.kernel.org/show_bug.cgi?id=11514 > > Summary: bluetooth headset works with 2.6.26, only hisses with > 2.6.27-rc5 > Product: Drivers > Version: 2.5 > KernelVersion: 2.6.27-rc5 > Platform: All > OS/Version: Linux > Tree: Mainline > Status: NEW > Severity: normal > Priority: P1 > Component: Bluetooth > AssignedTo: drivers_bluetooth@kernel-bugs.osdl.org > ReportedBy: kernel6org@pook.es > > > Latest working kernel version: 2.6.26-1-686 (Debian) > Earliest failing kernel version: 2.6.27-rc5 (vanilla) A post-2.6.26 regression. > Distribution: Debian > Hardware Environment: Intel Core2 Duo CPU E6550 > Software Environment: Debian unstable + bluez-4.4 > Problem Description: my Jabra JX10 bluetooth works with 2.6.26-1-686 and > bluez-4.4. With 2.6.27-rc5 (btusb) it only hisses. > > Steps to reproduce: install bluez-4.4 http://www.bluez.org/ and > add the following to ~/.asoundrc > pcm.JX10 { > type bluetooth > device "00:1A:45:2F:49:98" # Jabra JX10 series 2 > } > as root run bluetoothd -dn > run aplay -D JX10 alarm.wav > > with 2.6.26-1-686 I could hear the music, now I just hear a soft hiss during > 40 > seconds and then get an error message. > > hcitool shows 2 connections during the 40 seconds: > :; hcitool con > Connections: > < SCO 00:1A:45:2F:49:98 handle 44 state 1 lm SLAVE > < ACL 00:1A:45:2F:49:98 handle 41 state 1 lm MASTER > > In /var/log/kern.log > > Sep 7 12:16:08 kooka kernel: [ 1250.901715] Bluetooth: SCO (Voice Link) ver > 0.6 > Sep 7 12:16:08 kooka kernel: [ 1250.901719] Bluetooth: SCO socket layer > initialized > > in /var/log/kern.log I sometimes see > hci_scodata_packet: hci0 SCO packet for unknown connection handle 44 > btusb_isoc_complete: hci0 corrupted SCO packet > > :; aplay -vvv -D JX10 lib/alarm.wav > 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] > > bluetoothd says > > bluetoothd[4944]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: > HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS > bluetoothd[4944]: Received AT+VGS=15 > bluetoothd[4944]: connect(): Connection timed out (110) > bluetoothd[4944]: Audio API: sending BT_SETCONFIGURATION_RSP > bluetoothd[4944]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: > HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED > > :; /usr/local/sbin/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) > :; /usr/local/sbin/hciconfig hci0 > hci0: Type: USB > BD Address: 00:0C:41:E1:FF:30 ACL MTU: 192:8 SCO MTU: 64:8 > UP RUNNING > RX bytes:666323 acl:16 sco:13034 events:64 errors:0 > TX bytes:910 acl:19 sco:0 commands:33 errors:0 > :; /usr/local/sbin/hciconfig hci0 features > hci0: Type: USB > BD Address: 00:0C:41:E1:FF:30 ACL MTU: 192:8 SCO MTU: 64:8 > Features: 0xff 0xff 0x0f 0x00 0x00 0x00 0x00 0x00 > <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> > :; lsusb | grep Blue > Bus 001 Device 003: ID 0a12:0001 Cambridge Silicon Radio, Ltd Bluetooth > Dongle > (HCI mode) > :; hcitool info $JX10 > Requesting information ... > BD Address: 00:1A:45:2F:49:98 > Device Name: Jabra JX10 series 2 > LMP Version: 2.0 (0x3) LMP Subversion: 0x106e > Manufacturer: Cambridge Silicon Radio (10) > Features: 0xbf 0xfe 0x8b 0xf8 0x1b 0x18 0x00 0x80 > <3-slot packets> <5-slot packets> <encryption> <slot offset> > <timing accuracy> <role switch> <sniff mode> <RSSI> > <channel quality> <SCO link> <HV2 packets> <HV3 packets> > <u-law log> <A-law log> <CVSD> <paging scheme> > <transparent SCO> <broadcast encrypt> <enhanced iscan> > <interlaced iscan> <interlaced pscan> <inquiry with RSSI> > <extended SCO> <EV4 packets> <EV5 packets> <AFH cap. slave> > <AFH class. slave> <AFH cap. master> <AFH class. master> > <extended features> > :; sdptool records 00:1A:45:2F:49:98 > Service Name: Hands-Free unit > Service RecHandle: 0x10000 > Service Class ID List: > "Handsfree" (0x111e) > "Generic Audio" (0x1203) > Protocol Descriptor List: > "L2CAP" (0x0100) > "RFCOMM" (0x0003) > Channel: 1 > Language Base Attr List: > code_ISO639: 0x656e > encoding: 0x6a > base_offset: 0x100 > Profile Descriptor List: > "Handsfree" (0x111e) > Version: 0x0105 > > Service Name: Headset > Service RecHandle: 0x10001 > Service Class ID List: > "Headset" (0x1108) > "Generic Audio" (0x1203) > Protocol Descriptor List: > "L2CAP" (0x0100) > "RFCOMM" (0x0003) > Channel: 2 > Language Base Attr List: > code_ISO639: 0x656e > encoding: 0x6a > base_offset: 0x100 > Profile Descriptor List: > "Headset" (0x1108) > Version: 0x0100 > > :; lsmod | grep usb > usb_storage 77960 1 > snd_usb_audio 72288 0 > snd_usb_lib 15168 1 snd_usb_audio > snd_rawmidi 20512 2 snd_usb_lib,snd_seq_midi > snd_hwdep 8004 1 snd_usb_audio > usbhid 37924 0 > hid 35660 1 usbhid > ff_memless 6216 1 usbhid > btusb 11864 3 > bluetooth 49184 9 sco,bnep,rfcomm,l2cap,btusb > snd_pcm 64708 2 snd_usb_audio,snd_hda_intel > snd 47480 10 > > snd_usb_audio,snd_seq_oss,snd_seq,snd_rawmidi,snd_seq_device,snd_hwdep,snd_hda_intel,snd_mixer_oss,snd_pcm,snd_timer > > :; lsmod | grep hcd > uhci_hcd 20816 0 > > Note that I have removed ehci_hcd because it seems to cause problems with > 2.6.27-rc5. More on that later :-( > Created attachment 17651 [details]
hcidump during aplay on 2.6.26-1-686
So that you can compare 2.6.26 and 2.6.27-rc5, this is what hcidump saw during an aplay on my 2.6.26-1-686 kernel. There were lots of SCO data packets in each direction and I heard the music! I was using bluez-4.4 here as well.
Created attachment 17652 [details]
messages from bluetoothd during aplay on 2.6.26
This is what bluetoothd said when playing on 2.6.26. On 2.6.26 the headset works (but not all the time) and I can hear the music.
On 07/09/08 13:01, Andrew Morton wrote:
> A post-2.6.26 regression.
yes. I read the change log for 2.6.27-rc6 and it doesn't seem to address my
problem. Should I try it anyway?
I forgot to mention that my bluetooth dongle is a USB
ID 0a12:0001 Cambridge Silicon Radio, Ltd Bluetooth Dongle (HCI mode)
# hciconfig -a
hci0: Type: USB
BD Address: 00:0C:41:E1:FF:30 ACL MTU: 192:8 SCO MTU: 64:8
UP RUNNING
RX bytes:3713306 acl:72248 sco:0 events:299153 errors:0
TX bytes:2985713 acl:109155 sco:0 commands:157763 errors:0
Features: 0xff 0xff 0x0f 0x00 0x00 0x00 0x00 0x00
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: 0x0a0000
Service Classes: Networking, Capturing
Device Class: Miscellaneous,
HCI Ver: 1.1 (0x1) HCI Rev: 0x20d LMP Ver: 1.1 (0x1) LMP Subver: 0x20d
Manufacturer: Cambridge Silicon Radio (10)
If I can help in finding a solution to this problem please let me know!
Stuart
Created attachment 17958 [details] output from hcidump -X -V during aplay on 2.6.27-rc5 This is the output from hcidump -X -V when I ran aplay under 2.6.27-rc5. (I had to remove some of the outpot from the middle of the file to make it fit under the 1000KB limit). I didn't hear any sound and got the error message: :; logcommand aplay -D JX10 alarm.wav Playing WAVE '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] My ~/.asoundrc now contains pcm.JX10 { type bluetooth device "00:1A:45:2F:49:98" # Jabra JX10 series 2 } ctl.JX10 { type bluetooth } The dumo starts with: 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 0x0046 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 0x0046 scid 0x0040 result 0 status 0 Connection successful < ACL data: handle 41 flags 0x02 dlen 16 L2CAP(s): Config req: dcid 0x0046 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 0x0046 flags 0x00 result 0 clen 4 MTU 1013 < ACL data: handle 41 flags 0x02 dlen 8 L2CAP(d): cid 0x0046 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 0x0046 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 0x0046 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 0x0046 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 0x0046 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 0x0046 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 0x0046 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 0x0046 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 0x0046 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 0x0046 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 0x0046 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 0x0046 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 0x0046 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 0x0046 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 30 0d AT+VGS=10. < ACL data: handle 41 flags 0x02 dlen 14 L2CAP(d): cid 0x0046 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 44 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 44 flags 0x00 dlen 48 0000: 51 00 51 00 51 00 51 00 51 00 51 00 51 00 51 00 Q.Q.Q.Q.Q.Q.Q.Q. 0010: 51 00 51 00 51 00 51 00 51 00 51 00 51 00 51 2c Q.Q.Q.Q.Q.Q.Q.Q, 0020: 00 30 35 2c 35 2c 35 2c 35 2c 35 2c 35 2c 35 2c .05,5,5,5,5,5,5, This is what was written into /var/log/daemon.log while I ran aplay. Sep 22 21:37:42 kooka bluetoothd[32442]: Bluetooth daemon Sep 22 21:37:42 kooka bluetoothd[32442]: Enabling debug information Sep 22 21:37:42 kooka bluetoothd[32442]: parsing main.conf Sep 22 21:37:42 kooka bluetoothd[32442]: offmode=NoScan Sep 22 21:37:42 kooka bluetoothd[32442]: discovto=0 Sep 22 21:37:42 kooka bluetoothd[32442]: pageto=8192 Sep 22 21:37:42 kooka bluetoothd[32442]: name=%h-%d Sep 22 21:37:42 kooka bluetoothd[32442]: class=0x000100 Sep 22 21:37:42 kooka bluetoothd[32442]: inqmode=0 Sep 22 21:37:42 kooka bluetoothd[32442]: Starting SDP server Sep 22 21:37:42 kooka bluetoothd[32442]: Adding rec : 0xb892da80 Sep 22 21:37:42 kooka bluetoothd[32442]: with handle : 0x1 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding rec : 0xb892fa90 Sep 22 21:37:42 kooka bluetoothd[32442]: with handle : 0x0 Sep 22 21:37:42 kooka bluetoothd[32442]: Service classes 0x00 Sep 22 21:37:42 kooka bluetoothd[32442]: Loading plugins /usr/local/lib/bluetooth/plugins Sep 22 21:37:42 kooka bluetoothd[32442]: /usr/local/lib/bluetooth/plugins/audio.so Sep 22 21:37:42 kooka bluetoothd[32442]: Parsing /etc/bluetooth/audio.conf failed: No such file or directory Sep 22 21:37:42 kooka bluetoothd[32442]: Unix socket created: 11 Sep 22 21:37:42 kooka bluetoothd[32442]: Telephony plugin initialized Sep 22 21:37:42 kooka bluetoothd[32442]: HFP AG features: (none) Sep 22 21:37:42 kooka bluetoothd[32442]: /usr/local/lib/bluetooth/plugins/serial.so Sep 22 21:37:42 kooka bluetoothd[32442]: /usr/local/lib/bluetooth/plugins/service.so Sep 22 21:37:42 kooka bluetoothd[32442]: /usr/local/lib/bluetooth/plugins/network.so Sep 22 21:37:42 kooka bluetoothd[32442]: Parsing /etc/bluetooth/network.conf failed: No such file or directory Sep 22 21:37:42 kooka bluetoothd[32442]: Config options: InterfacePrefix=bnep%d, PANU_Script=(null), GN_Script=(null), NAP_Script=(null), GN_Interface=pan0, NAP_Interface=pan1, Security=true Sep 22 21:37:42 kooka bluetoothd[32442]: bridge pan0 created Sep 22 21:37:42 kooka bluetoothd[32442]: /usr/local/lib/bluetooth/plugins/input.so Sep 22 21:37:42 kooka bluetoothd[32442]: input.conf: Key file does not have key 'IdleTimeout' Sep 22 21:37:42 kooka bluetoothd[32442]: HCI dev 0 registered Sep 22 21:37:42 kooka bluetoothd[32442]: HCI dev 0 already up Sep 22 21:37:42 kooka bluetoothd[32442]: headset_server_probe: path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: Couldn't find record for : 0x10000 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding record with handle 0x10000 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding rec : 0xb8932460 Sep 22 21:37:42 kooka bluetoothd[32442]: with handle : 0x10000 Sep 22 21:37:42 kooka bluetoothd[32442]: Service classes 0x00 Sep 22 21:37:42 kooka bluetoothd[32442]: Couldn't find record for : 0x10001 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding record with handle 0x10001 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding rec : 0xb8930588 Sep 22 21:37:42 kooka bluetoothd[32442]: with handle : 0x10001 Sep 22 21:37:42 kooka bluetoothd[32442]: Service classes 0x00 Sep 22 21:37:42 kooka bluetoothd[32442]: a2dp_server_probe: path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: SEP 0xb8930b68 registered: type:0 codec:0 seid:1 Sep 22 21:37:42 kooka bluetoothd[32442]: Couldn't find record for : 0x10002 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding record with handle 0x10002 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding rec : 0xb8930870 Sep 22 21:37:42 kooka bluetoothd[32442]: with handle : 0x10002 Sep 22 21:37:42 kooka bluetoothd[32442]: Service classes 0x08 Sep 22 21:37:42 kooka bluetoothd[32442]: avrcp_server_probe: path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: Couldn't find record for : 0x10003 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding record with handle 0x10003 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding rec : 0xb8930848 Sep 22 21:37:42 kooka bluetoothd[32442]: with handle : 0x10003 Sep 22 21:37:42 kooka bluetoothd[32442]: Service classes 0x08 Sep 22 21:37:42 kooka bluetoothd[32442]: Couldn't find record for : 0x10004 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding record with handle 0x10004 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding rec : 0xb89325b0 Sep 22 21:37:42 kooka bluetoothd[32442]: with handle : 0x10004 Sep 22 21:37:42 kooka bluetoothd[32442]: Service classes 0x08 Sep 22 21:37:42 kooka bluetoothd[32442]: proxy_probe: path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: Registered interface org.bluez.SerialProxyManager on path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: service_probe: path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: Registered interface org.bluez.Service on path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: network_server_probe: path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: Couldn't find record for : 0x10005 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding record with handle 0x10005 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding rec : 0xb89335b0 Sep 22 21:37:42 kooka bluetoothd[32442]: with handle : 0x10005 Sep 22 21:37:42 kooka bluetoothd[32442]: Service classes 0x0a Sep 22 21:37:42 kooka bluetoothd[32442]: register_server_record: got record id 0x10005 Sep 22 21:37:42 kooka bluetoothd[32442]: Registered interface org.bluez.NetworkPeer on path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: network_server_probe: path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: Couldn't find record for : 0x10006 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding record with handle 0x10006 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding rec : 0xb8933bd8 Sep 22 21:37:42 kooka bluetoothd[32442]: with handle : 0x10006 Sep 22 21:37:42 kooka bluetoothd[32442]: Service classes 0x0a Sep 22 21:37:42 kooka bluetoothd[32442]: register_server_record: got record id 0x10006 Sep 22 21:37:42 kooka bluetoothd[32442]: Registered interface org.bluez.NetworkHub on path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: network_server_probe: path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: Couldn't find record for : 0x10007 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding record with handle 0x10007 Sep 22 21:37:42 kooka bluetoothd[32442]: Adding rec : 0xb8934200 Sep 22 21:37:42 kooka bluetoothd[32442]: with handle : 0x10007 Sep 22 21:37:42 kooka bluetoothd[32442]: Service classes 0x0a Sep 22 21:37:42 kooka bluetoothd[32442]: register_server_record: got record id 0x10007 Sep 22 21:37:42 kooka bluetoothd[32442]: Registered interface org.bluez.NetworkRouter on path /org/bluez/hci0 Sep 22 21:37:42 kooka bluetoothd[32442]: Creating device /org/bluez/hci0/dev_00_1A_45_2F_49_98 Sep 22 21:37:42 kooka bluetoothd[32442]: Probe drivers for /org/bluez/hci0/dev_00_1A_45_2F_49_98 Sep 22 21:37:42 kooka bluetoothd[32442]: Found Headset record Sep 22 21:37:42 kooka bluetoothd[32442]: Discovered Headset service on RFCOMM channel 2 Sep 22 21:37:42 kooka bluetoothd[32442]: Registered interface org.bluez.Headset on path /org/bluez/hci0/dev_00_1A_45_2F_49_98 Sep 22 21:37:42 kooka bluetoothd[32442]: Found Hansfree record Sep 22 21:37:42 kooka bluetoothd[32442]: Discovered Handsfree service on RFCOMM channel 1 Sep 22 21:37:42 kooka bluetoothd[32442]: headset_probe: path /org/bluez/hci0/dev_00_1A_45_2F_49_98 Sep 22 21:37:42 kooka bluetoothd[32442]: Registered interface org.bluez.Input on path /org/bluez/hci0/dev_00_1A_45_2F_49_98 Sep 22 21:37:42 kooka bluetoothd[32442]: Creating device /org/bluez/hci0/dev_00_14_A7_74_D3_AF Sep 22 21:37:42 kooka bluetoothd[32442]: Creating device /org/bluez/hci0/dev_00_03_89_B7_F8_D3 Sep 22 21:37:42 kooka bluetoothd[32442]: Creating device /org/bluez/hci0/dev_00_0A_94_94_4F_B3 Sep 22 21:37:42 kooka bluetoothd[32442]: Creating device /org/bluez/hci0/dev_00_03_89_DC_5C_9F Sep 22 21:37:42 kooka bluetoothd[32442]: Creating device /org/bluez/hci0/dev_00_03_89_DC_FC_EC Sep 22 21:37:42 kooka bluetoothd[32442]: Creating device /org/bluez/hci0/dev_00_03_89_FE_E6_19 Sep 22 21:37:42 kooka bluetoothd[32442]: Creating device /org/bluez/hci0/dev_00_0E_6D_8F_91_6A Sep 22 21:37:42 kooka bluetoothd[32442]: Creating device /org/bluez/hci0/dev_00_17_E5_E6_25_AB Sep 22 21:37:42 kooka bluetoothd[32442]: Creating device /org/bluez/hci0/dev_00_17_E5_16_88_6C Sep 22 21:37:42 kooka bluetoothd[32442]: Creating device /org/bluez/hci0/dev_00_17_E5_0C_EA_70 Sep 22 21:37:42 kooka bluetoothd[32442]: Adapter /org/bluez/hci0 has been enabled Sep 22 21:37:42 kooka bluetoothd[32442]: Starting security manager 0 Sep 22 21:37:42 kooka bluetoothd[32442]: child 32445 exited Sep 22 21:37:42 kooka bluetoothd[32442]: child 32446 exited Sep 22 21:39:27 kooka hcidump: hcidump -X -V Sep 22 21:39:37 kooka aplay: aplay -D JX10 alarm.wav Sep 22 21:39:37 kooka bluetoothd[32442]: Accepted new client connection on unix socket (fd=21) Sep 22 21:39:37 kooka bluetoothd[32442]: Audio API: received BT_GETCAPABILITIES_REQ Sep 22 21:39:37 kooka bluetoothd[32442]: Audio API: sending BT_GETCAPABILITIES_RSP Sep 22 21:39:37 kooka bluetoothd[32442]: Audio API: received BT_SETCONFIGURATION_REQ Sep 22 21:39:37 kooka bluetoothd[32442]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2 Sep 22 21:39:37 kooka bluetoothd[32442]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1 Sep 22 21:39:37 kooka bluetoothd[32442]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS Sep 22 21:39:41 kooka bluetoothd[32442]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98) Sep 22 21:39:41 kooka bluetoothd[32442]: kernel auth requirements = 0x00 Sep 22 21:39:41 kooka bluetoothd[32442]: stored link key type = 0x00 Sep 22 21:39:42 kooka bluetoothd[32442]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98 Sep 22 21:39:42 kooka bluetoothd[32442]: Received AT+BRSF=27 Sep 22 21:39:42 kooka bluetoothd[32442]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control" Sep 22 21:39:42 kooka bluetoothd[32442]: Received AT+CIND=? Sep 22 21:39:43 kooka bluetoothd[32442]: Received AT+CIND? Sep 22 21:39:43 kooka bluetoothd[32442]: Received AT+CMER=3, 0, 0, 1 Sep 22 21:39:43 kooka bluetoothd[32442]: Event reporting (CMER): mode=3, ind=1 Sep 22 21:39:43 kooka bluetoothd[32442]: HFP Service Level Connection established Sep 22 21:39:43 kooka bluetoothd[32442]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED Sep 22 21:39:43 kooka bluetoothd[32442]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS Sep 22 21:39:44 kooka bluetoothd[32442]: Received AT+VGS=10 Sep 22 21:40:19 kooka bluetoothd[32442]: Received AT+VGS=12 Sep 22 21:40:23 kooka bluetoothd[32442]: Received AT+VGS=14 Sep 22 21:40:23 kooka bluetoothd[32442]: connect(): Connection timed out (110) Sep 22 21:40:23 kooka bluetoothd[32442]: Audio API: sending BT_SETCONFIGURATION_RSP Sep 22 21:40:23 kooka bluetoothd[32442]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED Sep 22 21:40:23 kooka bluetoothd[32442]: Audio API: received BT_STREAMSTART_REQ Sep 22 21:40:23 kooka bluetoothd[32442]: Audio API: sending BT_STREAMSTART_RSP Sep 22 21:40:23 kooka bluetoothd[32442]: Audio API: sending BT_STREAMFD_IND Sep 22 21:40:23 kooka bluetoothd[32442]: unix_sendmsg_fd: Bad file descriptor(9) Sep 22 21:40:23 kooka bluetoothd[32442]: resume failed Sep 22 21:40:23 kooka bluetoothd[32442]: Audio API: sending BT_STREAMSTART_RSP Sep 22 21:40:23 kooka bluetoothd[32442]: Unix client disconnected (fd=21) Sep 22 21:40:23 kooka bluetoothd[32442]: No matching connection for handle 44 Running a aplay a second time gives a slightly different message from bluetoothd bluetoothd[32442]: Accepted new client connection on unix socket (fd=21) bluetoothd[32442]: Audio API: received BT_GETCAPABILITIES_REQ bluetoothd[32442]: Audio API: sending BT_GETCAPABILITIES_RSP bluetoothd[32442]: Audio API: received BT_SETCONFIGURATION_REQ bluetoothd[32442]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2 bluetoothd[32442]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECTED -> HEADSET_STATE_PLAY_IN_PROGRESS bluetoothd[32442]: connect(): Connection timed out (110) bluetoothd[32442]: Unable to lock headset bluetoothd[32442]: config failed bluetoothd[32442]: Audio API: sending BT_SETCONFIGURATION_RSP bluetoothd[32442]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_CONNECTED bluetoothd[32442]: Unix client disconnected (fd=21) bluetoothd[32442]: No matching connection for handle 44 Created attachment 18107 [details]
hcidump -XV during aplay on 2.6.26 (Debian)
aplay works using bluez-4.4 on 2.6.26-1-686 from Debian. This attachement is what hcidump saw while using aplay to play my .wav file.
Aplay doesn't work with bluez-4.7 on 2.6.26-1-686 from Debian. Bluetoothd from 4.7 says:
bluetoothd[12297]: Accepted new client connection on unix socket (fd=23)
bluetoothd[12297]: Audio API: received BT_GETCAPABILITIES_REQ
bluetoothd[12297]: Audio API: sending BT_GETCAPABILITIES_RSP
bluetoothd[12297]: Audio API: received BT_SETCONFIGURATION_REQ
bluetoothd[12297]: config sco - device = 00:1A:45:2F:49:98 access_mode = 2
bluetoothd[12297]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connecting to 00:1A:45:2F:49:98 channel 1
bluetoothd[12297]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECT_IN_PROGRESS
bluetoothd[12297]: adapter_get_device(00:1A:45:2F:49:98)
bluetoothd[12297]: link_key_request (sba=00:0C:41:E1:FF:30, dba=00:1A:45:2F:49:98)
bluetoothd[12297]: kernel auth requirements = 0x00
bluetoothd[12297]: stored link key type = 0x00
bluetoothd[12297]: /org/bluez/hci0/dev_00_1A_45_2F_49_98: Connected to 00:1A:45:2F:49:98
bluetoothd[12297]: Received AT+BRSF=27
bluetoothd[12297]: HFP HF features: "EC and/or NR function" "Call waiting and 3-way calling" "Voice recognition activation" "Remote volume control"
bluetoothd[12297]: Received AT+CIND=?
bluetoothd[12297]: Received AT+CIND?
bluetoothd[12297]: Received AT+CMER=3, 0, 0, 1
bluetoothd[12297]: Event reporting (CMER): mode=3, ind=1
bluetoothd[12297]: HFP Service Level Connection established
bluetoothd[12297]: State changed /org/bluez/hci0/dev_00_1A_45_2F_49_98: HEADSET_STATE_CONNECT_IN_PROGRESS -> HEADSET_STATE_CONNECTED
bluetoothd[12297]: connect: Operation not permitted (1)
bluetoothd[12297]: config failed
bluetoothd[12297]: Audio API: sending BT_SETCONFIGURATION_RSP
bluetoothd[12297]: Unix client disconnected (fd=23)
bluetoothd[12297]: Received AT+VGS=00
aplay says
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]
On 07/09/08 13:01, Andrew Morton wrote: >> Latest working kernel version: 2.6.26-1-686 (Debian) >> Earliest failing kernel version: 2.6.27-rc5 (vanilla) > A post-2.6.26 regression. 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. The Jabra JX10 "features Bluetooth 2.0 and e-SCO for improved audio quality and MultiPoint capability for connecting to 2 devices at once" and I am using an old Bluetooth 1.2 Linksys USBBT100 USB dongle. 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 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 I have the same problem with similar BT dongle with different headset.
jama ~ # hciconfig -a
hci0: Type: USB
BD Address: 00:11:09:E6:3C:EA ACL MTU: 192:8 SCO MTU: 64:8
UP RUNNING PSCAN ISCAN
RX bytes:1313 acl:0 sco:0 events:39 errors:0
TX bytes:418 acl:0 sco:0 commands:39 errors:0
Features: 0xff 0xff 0x8f 0x78 0x18 0x18 0x00 0x80
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy: RSWITCH HOLD SNIFF PARK
Link mode: SLAVE ACCEPT
Name: 'jama-0'
Class: 0x0a0104
Service Classes: Networking, Capturing
Device Class: Computer, Desktop workstation
HCI Ver: 1.2 (0x2) HCI Rev: 0x570 LMP Ver: 1.2 (0x2) LMP Subver: 0x570
Manufacturer: Cambridge Silicon Radio (10)
I'll attach headset identification later from home. Also if you need more information like hcidumps from Stuart, let me know.
Kernel versions 2.6.27-rc* and its the same in final 2.6.27.
Is this still present in modern kernels ? |