[pulseaudio-discuss] Bluetooth Headset Problem

Thu Sep 8 03:32:10 PDT 2011

Hi,

On Sat, Sep 3, 2011 at 5:16 PM, Colin Guthrie <gmane at colin.guthr.ie> wrote:
>> 4. Play a WAV with paplay:
>> paplay -p -v /afc/Noise.wav
>>
>> Opening a playback stream with sample specification 's16be 1ch 48000Hz'
>> and channel map 'mono'.
>>
>> Connection established..
>>
>> Stream successfully created.
>>
>> Buffer metrics: maxlength=4194304, tlength=192000, prebuf=190082,
>> minreq=1920
>>
>> Using sample spec 's16be 1ch 48000Hz', channel map 'mono'.
>>
>> Connected to device bto (2, not suspended).
>>
>> Time: 0.000 sec; Latency: 1407895 usec.
>>
>> Time: 0.000 sec; Latency: 1407895 usec.
>>
>> Time: 0.000 sec; Latency: 1407895 usec.
>>
>> Got signal, exiting.ency: 1407895 usec.
>>
>>
>>
>> Debug from Pulseaudio:
>>
>> I: client.c: Created 3 "Native client (UNIX socket client)"
>>
>> D: protocol-native.c: Protocol version: remote 16, local 16
>>
>> I: protocol-native.c: Got credentials: uid=0 gid=0 success=1
>>
>> D: protocol-native.c: SHM possible: no
>>
>> D: protocol-native.c: Negotiated SHM: no
>>
>> I: resampler.c: Using resampler 'speex-float-3'
>>
>> I: resampler.c: Using float32be as working format.
>>
>> I: resampler.c: Choosing speex quality setting 3.
>>
>> D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0,
>> base=2, prebuf=0, minreq=1 maxrewind=0
>>
>> D: memblockq.c: memblockq sanitized: maxlength=33554432,
>> tlength=33554432, base=2, prebuf=0, minreq=2 maxrewind=0
>>
>> I: sink-input.c: Created input 3 "/afc/Noise.wav" on bto with sample
>> spec s16be 1ch 48000Hz and channel map mono
>>
>> I: sink-input.c:     media.format = "WAV (Microsoft)"
>>
>> I: sink-input.c:     application.name = "paplay"
>>
>> I: sink-input.c:     media.name = "/afc/Noise.wav"
>>
>> I: sink-input.c:     native-protocol.peer = "UNIX socket client"
>>
>> I: sink-input.c:     native-protocol..version = "16"
>>
>> I: sink-input.c:     application.process.id = "4796"
>>
>> I: sink-input.c:     application.process.user = "root"
>>
>> I: sink-input.c:     application.process.host = "Viper"
>>
>> I: sink-input.c:     application.process.binary = "pacat"
>>
>> I: sink-input.c:     application.language = "C"
>>
>> I: sink-input.c:     application.process.machine_id =
>> "d63a8b34983dc07124730b71000003f9"
>>
>> I: protocol-native.c: Requested tlength=2000.00 ms, minreq=20.00 ms
>>
>> D: protocol-native.c: Traditional mode enabled, modifying sink usec only
>> for compat with minreq.
>>
>> D: memblockq.c: memblockq requested: maxlength=4194304, tlength=192000,
>> base=2, prebuf=190082, minreq=1920 maxrewind=0
>>
>> D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=192000,
>> base=2, prebuf=190082, minreq=1920 maxrewind=0
>>
>> I: protocol-native.c: Final latency 2128.00 ms = 1960.00 ms + 2*20.00 ms
>> + 128.00 ms
>>
>> D: protocol-native.c: Requesting rewind due to end of underrun.
>>
>> D: core.c: Hmm, no streams around, trying to vacuum.
>>
>> I: sink-input.c: Freeing input 3 "/afc/Noise.wav"
>>
>> I: client.c: Freed 3 "paplay"
>>
>> I: protocol-native.c: Connection died.
>>
>>
>>
>> Debug from bluez:
>>
>> bluetoothd[4776]: audio/headset.c:headset_set_state() State changed
>> /org/bluez/4776/hci0/dev_00_07_A4_EE_8F_03: HEADSET_STATE_DISCONNECTED
>> -> HEADSET_STATE_CONNECTING
>>
>> bluetoothd[4776]: plugins/hciops.c:link_key_request() hci0 dba
>> 00:07:A4:EE:8F:03
>>
>> bluetoothd[4776]: plugins/hciops.c:get_auth_info() hci0 dba
>> 00:07:A4:EE:8F:03
>>
>> bluetoothd[4776]: plugins/hciops.c:link_key_request() kernel auth
>> requirements = 0xff
>>
>> bluetoothd[4776]: plugins/hciops.c:link_key_request() Matching key found
>>
>> bluetoothd[4776]: plugins/hciops.c:link_key_request() link key type 0x00
>>
>> bluetoothd[4776]: plugins/hciops.c:conn_complete() status 0x00
>>
>> bluetoothd[4776]: src/adapter.c:adapter_get_device() 00:07:A4:EE:8F:03
>>
>> bluetoothd[4776]: plugins/hciops.c:bonding_complete() status 0x00
>>
>> bluetoothd[4776]: src/event.c:btd_event_bonding_complete() status 0x00
>>
>> bluetoothd[4776]: src/adapter.c:adapter_get_device() 00:07:A4:EE:8F:03
>>
>> bluetoothd[4776]: src/device.c:device_bonding_complete() bonding (nil)
>> status 0x00
>>
>> bluetoothd[4776]: plugins/hciops.c:remote_features_information() hci0
>> status 0
>>
>> bluetoothd[4776]: audio/headset.c:headset_set_channel() Discovered
>> Handsfree service on channel 2
>>
>> bluetoothd[4776]: audio/headset.c:rfcomm_connect()
>> /org/bluez/4776/hci0/dev_00_07_A4_EE_8F_03: Connecting to
>> 00:07:A4:EE:8F:03 channel 2
>>
>> bluetoothd[4776]: audio/headset.c:headset_connect_cb()
>> /org/bluez/4776/hci0/dev_00_07_A4_EE_8F_03: Connected to 00:07:A4:EE:8F:03
>>
>> bluetoothd[4776]: audio/headset.c:handle_event() Received AT+BRSF=26
>>
>> bluetoothd[4776]: audio/headset.c:print_hf_features() HFP HF features:
>> "Call waiting and 3-way calling" "Voice recognition activation" "Remote
>> volume control"
>>
>> bluetoothd[4776]: audio/headset.c:handle_event() Received AT+CIND=?
>>
>> bluetoothd[4776]: audio/headset.c:handle_event() Received AT+CIND?
>>
>> bluetoothd[4776]: audio/headset.c:handle_event() Received AT+CMER=3,0,0,1
>>
>> bluetoothd[4776]: audio/headset.c:event_reporting() Event reporting
>> (CMER): mode=3, ind=1
>>
>> bluetoothd[4776]: audio/headset.c:hfp_slc_complete() HFP Service Level
>> Connection established
>>
>> bluetoothd[4776]: audio/telephony.c:telephony_device_connected()
>> telephony-dummy: device 0x200b7738 connected
>>
>> bluetoothd[4776]: audio/headset.c:headset_set_state() State changed
>> /org/bluez/4776/hci0/dev_00_07_A4_EE_8F_03: HEADSET_STATE_CONNECTING ->
>> HEADSET_STATE_CONNECTED
>>
>> bluetoothd[4776]: audio/headset.c:handle_event() Received AT+VGS=15
>>
>> bluetoothd[4776]: audio/headset.c:headset_set_gain() Ignoring no-change
>> in speaker gain
>>
>> bluetoothd[4776]: audio/unix.c:server_cb() Accepted new client
>> connection on unix socket (fd=21)
>>
>> bluetoothd[4776]: audio/unix.c:client_cb() Audio API: BT_REQUEST <-
>> BT_GET_CAPABILITIES
>>
>> bluetoothd[4776]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE
>> -> BT_GET_CAPABILITIES
>>
>> bluetoothd[4776]: audio/unix.c:client_cb() Audio API: BT_REQUEST <-
>> BT_GET_CAPABILITIES
>>
>> bluetoothd[4776]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE
>> -> BT_GET_CAPABILITIES
>>
>> bluetoothd[4776]: audio/unix.c:client_cb() Audio API: BT_REQUEST <- BT_OPEN
>>
>> bluetoothd[4776]: audio/unix.c:handle_sco_open() open sco -
>> object=/org/bluez/4776/hci0/dev_00_07_A4_EE_8F_03 source=ANY
>> destination=ANY lock=readwrite
>>
>> bluetoothd[4776]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE
>> -> BT_OPEN
>>
>> bluetoothd[4776]: audio/unix.c:client_cb() Audio API: BT_REQUEST <-
>> BT_SET_CONFIGURATION
>>
>> bluetoothd[4776]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE
>> -> BT_SET_CONFIGURATION
>>
>> bluetoothd[4776]: audio/unix.c:client_cb() Audio API: BT_REQUEST <-
>> BT_START_STREAM
>>
>> bluetoothd[4776]: audio/headset.c:headset_set_state() State changed
>> /org/bluez/4776/hci0/dev_00_07_A4_EE_8F_03: HEADSET_STATE_CONNECTED ->
>> HEADSET_STATE_PLAY_IN_PROGRESS
>>
>> bluetoothd[4776]: audio/headset.c:sco_connect_cb() SCO socket opened for
>> headset /org/bluez/4776/hci0/dev_00_07_A4_EE_8F_03
>>
>> bluetoothd[4776]: audio/headset.c:sco_connect_cb() SCO fd=23
>>
>> bluetoothd[4776]: audio/unix.c:unix_ipc_sendmsg() Audio API: BT_RESPONSE
>> -> BT_START_STREAM
>>
>> bluetoothd[4776]: audio/unix.c:unix_ipc_sendmsg() Audio API:
>> BT_INDICATION -> BT_NEW_STREAM
>>
>> bluetoothd[4776]: audio/headset.c:headset_set_state() State changed
>> /org/bluez/4776/hci0/dev_00_07_A4_EE_8F_03:
>> HEADSET_STATE_PLAY_IN_PROGRESS -> HEADSET_STATE_PLAYING
>>
>> bluetoothd[4776]: audio/headset.c:headset_set_gain() Ignoring no-change
>> in speaker gain
>>
>> bluetoothd[4776]: audio/headset.c:headset_set_gain() Ignoring no-change
>> in microphone gain
>>
>>
>>
>> After that I'v changed the resampler method to trivial. Now paplays
>> returns with this:
>>
>> Opening a playback stream with sample specification 's16be 1ch 48000Hz'
>> and channel map 'mono'.
>>
>> Connection established.
>>
>> Stream successfully created.
>>
>> Buffer metrics: maxlength=4194304, tlength=192000, prebuf=190082,
>> minreq=1920
>>
>> Using sample spec 's16be 1ch 48000Hz', channel map 'mono'.
>>
>> Connected to device bto (2, not suspended).
>>
>> Failed to drain stream: Timeout95 usec.
>>
>> Playback stream drained.
>>
>> Draining connection to server.
>>
>>
>>
>> As you see paplay is unable to output audio data but I didn't see why?
>> Do somebody know what is the problem?
>>
>> CPU: PowerPC 603e (No FPU)
>> Linux: 2.6.24.6
>> Glibc: 2.5
>>
>> Pulseaudio system.pa (no other config files):
>>
>> load-module module-null-sink
>>
>> load-module module-oss sink_name=output source_name=input mmap=0
>>
>> load-module module-native-protocol-unix
>>
>> load-module module-native-protocol-tcp
>>
>> # load-module module-stream-restore
>>
>> # load-module module-rescue-streams
>>
>> # load-module module-always-sink
>>
>> # load-module module-suspend-on-idle
>>
>> load-module module-bluetooth-device profile=hsp
>> address=00:07:A4:EE:8F:03 auto_connect=1 sink_name=bto source_name=bti
>>
>> set-default-sink bto
>>
>> set-default-source input

It looks like you are using PCM routing to bto/bti devices, in that
cause make sure you have /etc/bluetooth/audio.conf to use PCM routing
instead of HCI (default), the signalling part seems ok meaning the SCO
link is connected so it appears something is wrong with bto
configuration, usually SCO sample spec is 8khz.

-- 
Luiz Augusto von Dentz