Bluetooth AVRCP failure

I learned that the mysterious behavior of the AVRCP (audio/video remote control protocol) failure on my HTC G1 is actually systematic and repeatable. If the phone is sleeping when the Bluetooth device is powered on, AVRCP will not be setup correctly. However, if the phone is awake, the connection will proceed perfectly. Here is a side-by-side comparison of the logs for a successful setup (left) and a failure (right):
It appears that the failure occurs because the phone doesn't initiate the A2DP connection. Note the time differences between the "AT sent OK" and "Auto-connecting A2DP" for each scenario. I have posted this on the Cyanogenmod issues tracker:
http://code.google.com/p/cyanogenmod/issues/detail?id=611

I've also been looking through the Cyanogen code, but I haven't noticed anything yet that would cause the device's behavior to change based on whether it is sleeping or not.

More bluetooth a2dp debugging on Android Cyanogen

There are a few different failure modes that I have encountered, however these are the most obvious and annoying one:

12-09 17:56:53.949 D/BluetoothA2dpService( 944): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 0->1

12-09 17:57:01.453 E/BluetoothA2dpService.cpp( 944): onConnectSinkResult: D-Bus error: org.bluez.Error.Failed (Stream setup failed)
12-09 17:57:03.469 D/BluetoothA2dpService( 944): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 1->0




:10:40.214 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 0->1
12-11 18:10:40.214 E/BluetoothA2dpService.cpp( 99): onConnectSinkResult: D-Bus error: org.bluez.Error.Failed (%s)

12-11 18:10:50.574 D/BluetoothA2dpService( 99): state 00:02:76:64:F7:4A (/org/bluez/audio/device1) 1->0







12-22 14:48:39.111 D/AudioFlinger( 78): set output to A2DP
12-22 14:48:39.121 D/BluetoothA2dpService( 94): state 00:02:76:64:F7:4A (/org/bluez/audio/device0) 1->2
12-22 14:48:40.321 W/KeyCharacterMap( 148): Can't open keycharmap file
12-22 14:48:40.321 W/KeyCharacterMap( 148): Error loading keycharmap file '/system/usr/keychars/AVRCP.kcm.bin'. hw.keyboards.262149.devname='AVRCP'
12-22 14:48:40.321 W/KeyCharacterMap( 148): Using default keymap: /system/usr/keychars/qwerty.kcm.bin
12-22 14:48:40.391 W/Service ( 963): setForeground: ignoring old API call on com.android.music.MediaPlaybackService
12-22 14:48:41.403 W/AudioTrack( 78): obtainBuffer timed out (is the CPU pegged?) 0x58dd0 user=010c3b70, server=010c1370
12-22 14:48:41.403 E/A2dpAudioInterface( 78): a2dp_write failed err: -110
12-22 14:48:41.411 W/AudioFlinger( 78): write blocked for 1010 msecs
12-22 14:48:42.411 W/AudioTrack( 78): obtainBuffer timed out (is the CPU pegged?) 0x58dd0 user=010c4570, server=010c1d70
12-22 14:48:42.411 E/A2dpAudioInterface( 78): a2dp_write failed err: -110
12-22 14:48:42.421 W/AudioFlinger( 78): write blocked for 1010 msecs
12-22 14:48:43.431 W/AudioTrack( 78): obtainBuffer timed out (is the CPU pegged?) 0x58dd0 user=010c4f70, server=010c2770
12-22 14:48:43.431 E/A2dpAudioInterface( 78): a2dp_write failed err: -110
12-22 14:48:43.451 W/AudioFlinger( 78): write blocked for 1021 msecs
12-22 14:48:44.452 W/AudioTrack( 78): obtainBuffer timed out (is the CPU pegged?) 0x58dd0 user=010c5970, server=010c3170
12-22 14:48:44.462 E/A2dpAudioInterface( 78): a2dp_write failed err: -110
12-22 14:48:44.472 W/AudioFlinger( 78): write blocked for 1010 msecs
12-22 14:48:45.472 W/AudioTrack( 78): obtainBuffer timed out (is the CPU pegged?) 0x58dd0 user=010c6370, server=010c3b70
12-22 14:48:45.472 E/A2dpAudioInterface( 78): a2dp_write failed err: -110
12-22 14:48:45.482 W/AudioFlinger( 78): write blocked for 1009 msecs
12-22 14:48:45.721 D/dalvikvm( 938): GC freed 842 objects / 41408 bytes in 124ms
12-22 14:48:46.484 W/AudioTrack( 78): obtainBuffer timed out (is the CPU pegged?) 0x58dd0 user=010c6d70, server=010c4570

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

Installing Bluetooth audio in my car with a Motorola s705 Pt.2

After about two weeks of life with the Bluetooth audio system in my car, I'd say it has reached about %80 of its design expectations, and with a little tweaking, might be made perfect.

The #1 gripe: When the Motorola S705 is powered on (after I've started the car), the phone audio connects, immediately disconnects, then reconnects. In the process, the AVRCP protocol for remote-controlling the media player on the phone is lost. This means that I have to take the phone out of my pocket, load up the media player, then hit play. I know, it sounds like a really minor complaint, but the system would be a whole lot more enjoyable if I could just press a button on the dash and not fumble with the phone at all.

In order to fix this problem, I've installed the latest Cyanogen ROM. I've noticed a few threads that discuss A2DP and AVRCP reliability problems with android in general:
http://code.google.com/p/cyanogenmod/issues/detail?id=360
http://code.google.com/p/cyanogenmod/issues/detail?id=611

Both issues have been closed, but one person commented that he/she is still having problems with 4.2.1 after the issue was closed.

Today, I installed 4.2.7.1. I hopped in the car and was disappointed to see the same problem (loss of AVRCP after a botched connection). I hooked up the phone to my computer and ran ADB logcat to see if I could get more info about the error. After 30 power-off/power-on cycles, the Bluetooth connection was always established perfectly with AVRCP. Geez! Obviously, I don't know if it's really fixed or not.


I decided that I will sync the phone with my music collection via USB. Originally, I thought it would be cool to do it wirelessly and automatically, but it turned out to be very easy to just plug it in and sync with MediaMonkey. The program chooses a random selection from my music collection and fills the phone's SD card up to capacity. I sync about once per week.

The automatic power-on and power-off circuitry to control the Motorola S705 works perfectly.

Also, the audio quality is good, but not quite as great as I originally thought. It's true that bass and treble are not attenuated, but there are noticeable compression artifacts in the sound that are not present in the source MP3. Cymbals sound kind of fuzzy, scratchy-- like the sound is coming from under water. It's not bad, but it's probably not quite as good as a 128-bit MP3. It's still fine enough for listening in the car where road noise is present.

More later...

Installing Bluetooth audio in my car with a Motorola s705

I am nearly done with my project to create a seamless way of playing music that is stored on my computer in my car. I bought a Motorola s705, which is a Bluetooth audio receiver with headphone jack. It is capable of operating as a standard phone headset and also capable of receiving high-quality audio. First, let me review the s705 itself:

I easily paired the s705 with my HTC G1, and was able to play music through the s705 with no trouble. The sound quality was extremely good -- significantly better than the G1's own headphone adapter. It appears the high-pass filtering that the G1 uses on its own audio stream are thankfully not also used on the bluetooth high-quality audio stream. I could not hear any compression artifacts, and the sound quality remained top-notch as I walked up to about 15 feet away from the phone. I did not test the s705's battery life. I accidentally turned on the FM radio a few times, and I wish that feature could be disabled. The only negative thing is that the s705 and G1 sometimes do not connect to each other after being separated, then brought back together. Sometimes, they will only establish a phone audio connection and not a high-quality (A2DP) connection. Turning the phone off and on (or going into airplane mode and back) always fixes the problem. Turning the s705 off and on sometimes fixes the problem.



So after I decided the s705 would probably do the job, I took it apart (of course). I needed a way to remotely control the s705 power (to have it turn on everytime I started the car, and off when I shut car off), and also a way to allow it to charge its own battery while not running the car battery down.

In order to turn the s705 on or off, the power switch must be held down for three seconds. One side of the power switch would go high (about 4 volts) when the switch was pressed. Thus, I could control the device's power state by sending it a 4 volt pulse that lasted three seconds. My first plan was to use an Atmel AVR microcontroller and use a feedback circuit so that the AVR would know whether the unit was on or off. I had difficulty finding a reliable logic signal on the s705 circuit board that could be used as an on/off indicator. I was also having difficulty with the Atmel IDE that night, so I scrapped it, and decided to use two basic timer circuits (a 555 and 558 chip). The circuits send a pulse when the car turns on, and another pulse when the car turns off. It's possible for the device to become out of sync, but I don't think it will happen. The circuit uses a MOSFET whose gate is driven by a capacitor-resistor network and charged by the "on" signal from the car stereo. This way, the device will draw essentially zero current after the gate discharges and the MOSFET turns off. I've configured the capacitor value so that the circuit stays powered for 15 seconds after the car turns off.


I also wanted to sneak the audio wires out the back of the unit instead of using the headphone jack on top. I figured this would look a lot nicer when I mounted the unit on my car's dashboard.




I used the s705 shirt clip to attach it to an unused switch plate in my 1992 Honda Civic. It fits right next to the rear defroster switch.

The row of header pins have the following signals:
1. gnd
2. +12V always on from the battery
3. +5V signal from car stereo when the aux input is active
4. audio signal gnd
5. audio left
6. audio right

The audio connections go to my car stereo "aux input" which I described in another post:






The shirt clip was ABS plastic as was the switch dummy plate. I used some Weld-On #16 glue which will very securely bond ABS plastic.

It's a pretty clean installation. I've just finished it, and I'll let everyone know how it works in day-to-day use. So far, my tests in the driveway have been really great -- just step into the car and turn on the stereo, hit play on the s705, and the music starts. I don't even have to take the phone out of my pocket.