[pulseaudio-discuss] Fwd: Re: Bluetooth Headset Problem #2

Sat Oct 8 06:52:11 PDT 2011

Sorry, here are the attachments.

-------- Original Message --------
Subject: Re: Bluetooth Headset Problem
Date: Sat, 08 Oct 2011 14:11:31 +0200
 From: krisztian.kocsis at optimaster.eu
To: Luiz Augusto von Dentz <luiz.dentz at gmail.com>

Hello!

I didn't help!

Here is who I test it:

- Load kernel (2.6.24.6) modules: bluetooth, hci_usb, l2cap, rfcomm, 
sco
- Start bluez (4.96): bluetoothd -d -n (debug, foreground)
- Start simple-agent: simple-agent 0000
- Test device connection with: hcitool cc 00:07:A4:EE:8F:03 (already 
paired)
- Start pulseaudio (0.9.23): 
LD_LIBRARY_PATH=/afc/lib/pulse-0.9.23/modules /afc/bin/pulseaudio 
--system --high-priority --disallow-exit --log-target=stderr 
--use-pid-file --disable-shm -vvvvvvv
- Connect to headset: dbus-send --system --print-reply --dest=org.bluez 
/org/bluez/2848/hci0/dev_00_07_A4_EE_8F_03 org.bluez.Headset.Connect 
(dbus 1.4.14)
- Activate hsp profile: pactl set-card-profile 0 hsp
- Trying to play a WAV: paplay -p -v /afc/tmp/test.wav (hangs at Time: 
0.000s)
- Trying to play an MP3 with mpg123 (1.13.3): mpg123 -vvvvv -o pulse 
/afc/tmp/armin.mp3 (hangs at frame 6)

Did I miss some commands or actions which are required to play 
something on a headset?
I'v attached the config files of bluez and pulseaudio and the logs 
also.

BR,
Krisztian

On Thu, 8 Sep 2011 13:32:10 +0300, Luiz Augusto von Dentz wrote:
> 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.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: bluez.log
Type: text/x-log
Size: 24066 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20111008/531c63c1/attachment-0004.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: pulseaudio.log
Type: text/x-log
Size: 24088 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20111008/531c63c1/attachment-0005.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: mpg123.log
Type: text/x-log
Size: 5827 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20111008/531c63c1/attachment-0006.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: paplay.log
Type: text/x-log
Size: 432 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20111008/531c63c1/attachment-0007.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: bluetooth-audio.conf
Type: application/octet-stream
Size: 89 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20111008/531c63c1/attachment-0003.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: bluetooth-main.conf
Type: application/octet-stream
Size: 2421 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20111008/531c63c1/attachment-0004.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: pulse-system.pa
Type: application/octet-stream
Size: 786 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20111008/531c63c1/attachment-0005.obj>