Wednesday, December 9, 2009

Debugging Bluetooth A2DP on Cyanogen G1

UPDATE: The connection problem turns out to be related to AVRCP, not A2DP. For some reason, the phone will connect to the A2DP device perfectly (with AVRCP) if the phone is awake when the A2DP device is powered on. If the phone is sleeping when the A2DP device is powered on, the connection process is different and AVRCP is lost. A2DP will be connected, though.

See this thread:
http://code.google.com/p/cyanogenmod/issues/detail?id=611



So, I'm still having problems with getting a reliable AVRCP and A2DP connection with Cyanogenmod 4.2.7.1 on my G1.

Here is a log from a successful connection:
12-09 09:52:36.660 I/BT Audio Gateway( 150): connect notification!
[[[ Setting up phone audio connection ]]]
12-09 09:52:41.730 D/BluetoothA2dpService( 99): Auto-connecting A2DP to sink 00:02:76:64:F7:4A
12-09 09:52:41.730 D/BluetoothA2dpService( 99): connectSink(00:02:76:64:F7:4A)
12-09 09:52:41.750 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 0->1
12-09 09:52:42.220 I/CheckinService( 99): Checkin success
12-09 09:52:42.280 W/GoogleHttpClient( 99): Blocked by block_crash_reports: http://android.clients.google.com/crash
12-09 09:52:42.280 I/CheckinService( 99): Crash report blocked
12-09 09:52:46.276 I/EventHub( 99): New device: path=/dev/input/event5 name=AVRCP id=0x10005 (of 0x6) index=6 fd=118 classes=0x1
12-09 09:52:46.286 I/EventHub( 99): New keyboard: publicID=65541 device->id=65541 devname='AVRCP' propName='hw.keyboards.65541.devname' keylayout='/system/usr/keylayout/AVRCP.kl'
12-09 09:52:46.286 I/KeyInputQueue( 99): Device added: id=0x10005, name=AVRCP, classes=1
12-09 09:52:46.286 I/WindowManager( 99): Config changed: { scale=1.0 imsi=0/0 loc=en_US touch=3 keys=2/1/2 nav=3 orien=1 layout=18}
12-09 09:52:46.946 D/A2dpAudioInterface( 83): setParameter a2dp_sink_address,00:02:76:64:F7:4A
12-09 09:52:46.965 D/AudioFlinger( 83): set output to A2DP
12-09 09:52:46.975 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 1->2
12-09 09:53:07.738 D/dalvikvm( 99): GC freed 18113 objects / 1104992 bytes in 206ms
12-09 09:53:07.798 D/OpenSSLSessionImpl( 99): Freeing OpenSSL session
12-09 09:53:07.948 I/ActivityManager( 99): Start proc com.android.music for broadcast com.android.music/.MediaButtonIntentReceiver: pid=1803 uid=10017 gids={3002, 3001, 3003, 1015}
12-09 09:53:07.948 I/ActivityManager( 99): processNextBroadcast: waiting for ProcessRecord{43e9d498 1803:com.android.music/10017}
12-09 09:53:07.988 I/ActivityManager( 99): processNextBroadcast: waiting for ProcessRecord{43e9d498 1803:com.android.music/10017}
12-09 09:53:08.038 I/ActivityManager( 99): processNextBroadcast: waiting for ProcessRecord{43e9d498 1803:com.android.music/10017}
12-09 09:53:08.068 I/ActivityManager( 99): processNextBroadcast: waiting for ProcessRecord{43e9d498 1803:com.android.music/10017}
12-09 09:53:09.108 D/A2DP ( 83): bluetooth_start
12-09 09:53:09.108 E/A2DP ( 83): BT_START failed : I/O error(5)
12-09 09:53:09.108 D/A2DP ( 83): bluetooth_configure
12-09 09:53:09.108 D/A2DP ( 83): bluetooth_a2dp_hw_params sending configuration:
12-09 09:53:09.108 D/A2DP ( 83): channel_mode: JOINT STEREO
12-09 09:53:09.108 D/A2DP ( 83): frequency: 44100
12-09 09:53:09.108 D/A2DP ( 83): allocation_method: LOUDNESS
12-09 09:53:09.108 D/A2DP ( 83): subbands: 8
12-09 09:53:09.108 D/A2DP ( 83): block_length: 16
12-09 09:53:09.108 D/A2DP ( 83): min_bitpool: 2
12-09 09:53:09.108 D/A2DP ( 83): max_bitpool: 32
12-09 09:53:09.118 D/A2DP ( 83): MTU: 895
12-09 09:53:09.118 D/A2DP ( 83): frame_duration: 2902 us
12-09 09:53:09.118 D/A2DP ( 83): allocation=0
12-09 09:53:09.118 D/A2DP ( 83): subbands=1
12-09 09:53:09.118 D/A2DP ( 83): blocks=3
12-09 09:53:09.118 D/A2DP ( 83): bitpool=32
12-09 09:53:09.118 D/A2DP ( 83): bluetooth_start
12-09 09:53:09.168 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 2->4
12-09 09:53:13.505 D/KeyguardViewMediator( 99): wakeWhenReadyLocked(82)
12-09 09:53:13.505 D/KeyguardViewMediator( 99): handleWakeWhenReady(82)
12-09 09:53:13.515 D/KeyguardViewMediator( 99): pokeWakelock(5000)
12-09 09:53:13.535 D/Sensors ( 99): sensors=00000001, real=00000001
12-09 09:53:13.535 D/AKMD ( 88): Compass OPEN
12-09 09:53:13.695 I/Bluetooth AT sent( 150): +CIEV: 5,5
12-09 09:53:13.765 D/SurfaceFlinger( 99): Screen about to return, flinger = 0xff388
12-09 09:53:14.455 D/KeyguardViewMediator( 99): pokeWakelock(5000)
12-09 09:53:15.795 D/A2DP ( 83): a2dp_stop
12-09 09:53:15.795 D/A2DP ( 83): bluetooth_stop
12-09 09:53:15.855 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 4->2




Here is the log from a connect-then-disconnect-then-reconnect (without AVRCP)
12-08 15:57:02.213 D/BluetoothA2dpService( 99): Auto-connecting A2DP to sink 00:02:76:64:F7:4A
12-08 15:57:02.213 D/BluetoothA2dpService( 99): connectSink(00:02:76:64:F7:4A)
12-08 15:57:02.223 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 0->1
12-08 15:57:02.553 I/ActivityManager( 99): Stopping service: com.android.calendar/.AlertService
12-08 15:57:02.593 I/ActivityManager( 99): Stopping service: com.android.mms/.transaction.SmsReceiverService
12-08 15:57:02.733 E/BluetoothA2dpService.cpp( 99): onConnectSinkResult: D-Bus error: org.bluez.Error.Failed (Stream setup failed)
12-08 15:57:03.393 I/BluetoothEventLoop( 99): Allowing incoming A2DP connection from 00:02:76:64:F7:4A
12-08 15:57:04.753 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 1->0
12-08 15:57:09.658 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 0->1
12-08 15:57:09.658 D/A2dpAudioInterface( 83): setParameter a2dp_sink_address,00:02:76:64:F7:4A
12-08 15:57:09.668 D/AudioFlinger( 83): set output to A2DP
12-08 15:57:09.718 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 1->2


Disabled phone audio, and now only have A2DP connection. AVRCP looks fine in log, but doesn't work at all:
12-09 09:57:51.661 I/BluetoothEventLoop( 99): Allowing incoming A2DP connection from 00:02:76:64:F7:4A
12-09 09:57:54.331 I/EventHub( 99): New device: path=/dev/input/event5 name=AVRCP id=0x10005 (of 0x6) index=6 fd=31 classes=0x1
12-09 09:57:54.341 I/EventHub( 99): New keyboard: publicID=65541 device->id=65541 devname='AVRCP' propName='hw.keyboards.65541.devname' keylayout='/system/usr/keylayout/AVRCP.kl'
12-09 09:57:54.341 I/KeyInputQueue( 99): Device added: id=0x10005, name=AVRCP, classes=1
12-09 09:57:54.351 I/WindowManager( 99): Config changed: { scale=1.0 imsi=0/0 loc=en_US touch=3 keys=2/1/2 nav=3 orien=1 layout=18}
12-09 09:57:54.551 D/dalvikvm( 99): GC freed 7743 objects / 388840 bytes in 208ms
12-09 09:57:58.261 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 0->1
12-09 09:57:58.371 D/A2dpAudioInterface( 83): setParameter a2dp_sink_address,00:02:76:64:F7:4A
12-09 09:57:58.381 D/A2DP ( 83): bluetooth_init
12-09 09:57:58.391 D/A2DP ( 83): bluetooth_configure
12-09 09:57:58.391 D/A2DP ( 83): bluetooth_a2dp_hw_params sending configuration:
12-09 09:57:58.391 D/A2DP ( 83): channel_mode: JOINT STEREO
12-09 09:57:58.391 D/A2DP ( 83): frequency: 44100
12-09 09:57:58.391 D/A2DP ( 83): allocation_method: LOUDNESS
12-09 09:57:58.391 D/A2DP ( 83): subbands: 8
12-09 09:57:58.391 D/A2DP ( 83): block_length: 16
12-09 09:57:58.391 D/A2DP ( 83): min_bitpool: 2
12-09 09:57:58.391 D/A2DP ( 83): max_bitpool: 32
12-09 09:57:58.421 D/A2DP ( 83): MTU: 895
12-09 09:57:58.421 D/A2DP ( 83): frame_duration: 2902 us
12-09 09:57:58.421 D/A2DP ( 83): allocation=0
12-09 09:57:58.421 D/A2DP ( 83): subbands=1
12-09 09:57:58.421 D/A2DP ( 83): blocks=3
12-09 09:57:58.421 D/A2DP ( 83): bitpool=32
12-09 09:57:58.421 D/AudioFlinger( 83): set output to A2DP
12-09 09:57:58.431 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 1->2

3 comments:

  1. I had a similar problem with my Motorola S9-HD. It was working well, but stopped working during a recent update. The key symptom (besides the music coming out the phone speaker instead of the headset), was that when I would long press on the bluetooth device and view the options, only the phone profile was listed.

    I turned off bluetooth and ran fix_permissions from the terminal emulator. Then after re-pairing the device when I selected options it listed the media profile, which was not selected. After I selected the checkbox, everything works great.

    Hope this helps.

    ReplyDelete
  2. Thanks for the tip. As it turned out, my problem was concerned with AVRCP (the remote control media buttons), not A2DP. Specifically, the AVRCP connection is not setup when a paired Bluetooth device is powered on, and the phone is sleeping. Everything is perfect if the phone is awake when the bluetooth device is switched on. Does this work for you: Phone is sleeping, turn on your bluetooth device, then press play on the device (not on the phone). Does it work?

    If you are at all curious, I've got the pertinent parts of the logs here:
    http://benkrasnow.blogspot.com/2009/12/bluetooth-avrcp-failure.html

    ReplyDelete
  3. I had the issue where: after I updated the ROM to Cyanogen 5.0.7, I was able to connect to my parrot bluetooth system, but it wasn't pulling the Address book or the call log. After following the advice from Anonymous (about fix_permissions), it worked properly.

    ReplyDelete