Pause on bluetooth disconnect

[lumpadump]

Hi! In "Headset Preferences" I have "Auto Play/Pause" selected. Pausing works fine with wired headphones, but if I use my bluetooth headphones over A2DP, playback continues after disconnecting my headphones. Am I missing an option for bluetooth headsets somewhere or is this just not implemented?

[GoneMAD]

auto pause/play is supposed to work for bluetooth as well (the only thing i've ever tested with was my car bluetooth tho). What device do you have?

[GoneMAD]

try out the beta i just posted, i write some stuff out to the system log whenever a plug/unplug/connect/disconnect happens which you can view with an app like alogcat

if you could disconnect and get it to reproduce.. then send the logcat logs to me.. i can maybe see why its not pausing

[lumpadump]

Hi! Thanks for the reply.

I'm using a Galaxy Nexus (toro) with AOKP build 37, and my headphones are a pair of Sony DR-BT50's.

I installed the beta and cleared app data just in case it was a settings issue. I found with the beta that it does pause on bluetooth disconnect, but it takes a long time to do so (~20 seconds after turning off the headset). Perhaps it was doing this all along and I was just being impatient. With a regular wired pair, it's immediate.

In any case, here's the logcat output, first with the bluetooth headphones:

--------- beginning of /dev/log/main
05-29 14:02:23.491 D/dalvikvm(  219): GC_EXPLICIT freed 758K, 31% free 23365K/33603K, paused 3ms+7ms
--------- beginning of /dev/log/system
05-29 14:02:23.522 W/InputManagerService(  219): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@4166ea58
05-29 14:02:29.757 W/BT HSHFP(  404): RFCOMM poll() returned  success (1), but with an unexpected revents bitmask: 0x18
05-29 14:02:29.757 I/Bluetooth HeadsetBase(  404): headset read error 5
05-29 14:02:29.765 D/Bluetooth HSHFP(  404): Device: 00:24:BE:8A:31:AA Headset  state2 -> 0
05-29 14:02:29.765 W/EventHub(  219): Received unexpected epoll event 0x00000018 for device AVRCP.
05-29 14:02:29.765 W/EventHub(  219): Received unexpected epoll event 0x00000018 for device AVRCP.
05-29 14:02:29.765 I/EventHub(  219): Removing device '/dev/input/event6' due to inotify event
05-29 14:02:29.765 I/EventHub(  219): Removed device: path=/dev/input/event6 name=AVRCP id=22 fd=215 classes=0x80000001
05-29 14:02:29.772 I/BluetoothDeviceProfileState(  219): Entering IncomingHandsfree state with: 51
05-29 14:02:29.772 I/BluetoothDeviceProfileState(  219): Entering ACL Connected state with: 102
05-29 14:02:29.827 I/InputReader(  219): Device removed: id=22, name='AVRCP', sources=0x00000101
05-29 14:02:30.530 D/BluetoothA2dpService(  219): A2DP: onSinkPropertyChanged newState is: 0 mPlayingA2dpDevice: 00:24:BE:8A:31:AA
05-29 14:02:30.538 D/BluetoothA2dpService(  219): A2DP state : device: 00:24:BE:8A:31:AA State:2->0
05-29 14:02:30.538 W/AudioTrack(11031): dead IAudioTrack, creating a new one from obtainBuffer() TID 11297
05-29 14:02:30.538 W/AudioSystem(11031): ioConfigChanged() closing unknow output! 2377
05-29 14:02:30.546 D/BluetoothAdapterStateMachine(  219): BluetoothOn process message: 52
05-29 14:02:30.546 D/BluetoothService(  219): CONNECTION_STATE_CHANGE: 00:24:BE:8A:31:AA: 2 -> 0
05-29 14:02:30.554 W/AudioSystem(11031): ioConfigChanged() closing unknow output! 2376
05-29 14:02:30.554 D/A2DP    (  130): a2dp_stop
05-29 14:02:30.554 D/A2DP    (  130): bluetooth_stop
05-29 14:02:30.554 E/A2DP    (  130): BT_STOP_STREAM failed : I/O error(5)
05-29 14:02:30.554 D/A2DP    (  130): a2dp_cleanup
05-29 14:02:30.554 D/A2DP    (  130): bluetooth_close
05-29 14:02:30.554 D/A2DP    (  130): a2dp_thread finished
05-29 14:02:30.608 I/BluetoothDeviceProfileState(  219): Entering IncomingA2dp state with: 53
05-29 14:02:30.608 I/BluetoothDeviceProfileState(  219): Entering ACL Connected state with: 102
05-29 14:02:30.624 W/AudioTrack(11031): dead IAudioTrack, already restored TID 11895
05-29 14:02:50.679 D/BluetoothEventLoop(  219): Device property changed: 00:24:BE:8A:31:AA property: Connected value: false
05-29 14:02:50.679 I/HeadsetBcastReceiver(11031): Headset action: android.bluetooth.device.action.ACL_DISCONNECTED
05-29 14:02:50.733 I/AudioService(  219):  AudioFocus  abandonAudioFocus() from [e-mail]$1@40ecfcf0

This is with a standard pair of 3.5mm headphones.

--------- beginning of /dev/log/system
05-29 14:06:42.819 W/InputManagerService(  219): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@41193320
05-29 14:06:45.757 V/WiredAccessoryObserver(  219): Headset UEVENT: {SUBSYSTEM=switch, SWITCH_STATE=0, DEVPATH=/devices/virtual/switch/h2w, SEQNUM=40453, ACTION=change, SWITCH_NAME=h2w}
05-29 14:06:45.757 V/WiredAccessoryObserver(  219): newState = 0, headsetState = 0,mHeadsetState = 2
05-29 14:06:46.757 V/WiredAccessoryObserver(  219): Intent.ACTION_HEADSET_PLUG: state: 0 name: h2w mic: 0
--------- beginning of /dev/log/main
05-29 14:06:46.765 I/HeadsetBcastReceiver(11031): Headset action: android.intent.action.HEADSET_PLUG
05-29 14:06:46.882 D/dalvikvm(  219): GC_EXPLICIT freed 1857K, 31% free 23454K/33603K, paused 10ms+12ms
05-29 14:06:46.882 I/AudioService(  219):  AudioFocus  abandonAudioFocus() from [e-mail]$1@40ecfcf0


For what it's worth, BeyondPod pauses immediately on disconnect, so here's the output from BeyondPod with my bluetooth headphones. I know it's not related to GMMP, but it might be a clue as to what signal BP is using.

--------- beginning of /dev/log/system
05-29 14:14:36.491 W/InputManagerService(  219): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@415626e0
--------- beginning of /dev/log/main
05-29 14:14:44.983 W/EventHub(  219): Received unexpected epoll event 0x00000018 for device AVRCP.
05-29 14:14:44.983 W/EventHub(  219): Received unexpected epoll event 0x00000018 for device AVRCP.
05-29 14:14:44.983 I/EventHub(  219): Removing device '/dev/input/event6' due to inotify event
05-29 14:14:44.983 I/EventHub(  219): Removed device: path=/dev/input/event6 name=AVRCP id=23 fd=285 classes=0x80000001
05-29 14:14:44.991 W/BT HSHFP(  404): RFCOMM poll() returned  success (1), but with an unexpected revents bitmask: 0x18
05-29 14:14:44.991 I/Bluetooth HeadsetBase(  404): headset read error 5
05-29 14:14:44.991 D/Bluetooth HSHFP(  404): Device: 00:24:BE:8A:31:AA Headset  state2 -> 0
05-29 14:14:44.991 I/BluetoothDeviceProfileState(  219): Entering IncomingHandsfree state with: 51
05-29 14:14:44.999 I/BluetoothDeviceProfileState(  219): Entering ACL Connected state with: 102
05-29 14:14:45.022 I/InputReader(  219): Device removed: id=23, name='AVRCP', sources=0x00000101
05-29 14:14:45.749 D/BluetoothA2dpService(  219): A2DP: onSinkPropertyChanged newState is: 0 mPlayingA2dpDevice: 00:24:BE:8A:31:AA
05-29 14:14:45.749 D/BluetoothA2dpService(  219): A2DP state : device: 00:24:BE:8A:31:AA State:2->0
05-29 14:14:45.749 D/BluetoothAdapterStateMachine(  219): BluetoothOn process message: 52
05-29 14:14:45.749 V/BeyondPod(12506): ****** Media button receiver got event: android.media.AUDIO_BECOMING_NOISY  (17.11 s. since last trace)   [MediaButtonIntentReceiver]
05-29 14:14:45.749 V/BeyondPod(12506): ***========> Media button receiver executing action: pause  (0 ms. since last trace)   [MediaButtonIntentReceiver]
05-29 14:14:45.749 V/BeyondPod(12506): ===########### MovieView Instances:0  (1 ms. since last trace)   [BeyondPodApplication]
05-29 14:14:45.757 W/AudioTrack(  130): dead IAudioTrack, creating a new one from obtainBuffer() TID 12544
05-29 14:14:45.757 W/AudioSystem(  130): ioConfigChanged() closing unknow output! 2419
05-29 14:14:45.757 D/BluetoothService(  219): CONNECTION_STATE_CHANGE: 00:24:BE:8A:31:AA: 2 -> 0
05-29 14:14:45.757 V/BeyondPod(12506): *** Sending Pause command to the player...  (8 ms. since last trace)   [MediaButtonIntentReceiver]
05-29 14:14:45.757 V/BeyondPod(12506): Service autoshutdown scheduled from onStart  (0 ms. since last trace)   [MediaPlaybackService]
05-29 14:14:45.757 V/BeyondPod(12506): *** PlaybackSertvice received Command: pause, Option: null  (0 ms. since last trace)   [MediaPlaybackService]
05-29 14:14:45.772 W/AudioSystem(  130): ioConfigChanged() closing unknow output! 2418
05-29 14:14:45.827 D/A2DP    (  130): a2dp_stop
05-29 14:14:45.827 D/A2DP    (  130): bluetooth_stop
05-29 14:14:45.827 E/A2DP    (  130): BT_STOP_STREAM failed : I/O error(5)
05-29 14:14:45.827 D/A2DP    (  130): a2dp_cleanup
05-29 14:14:45.827 D/A2DP    (  130): bluetooth_close
05-29 14:14:45.827 D/A2DP    (  130): a2dp_thread finished
05-29 14:14:45.835 I/BluetoothDeviceProfileState(  219): Entering IncomingA2dp state with: 53
05-29 14:14:45.835 I/BluetoothDeviceProfileState(  219): Entering ACL Connected state with: 102
05-29 14:14:45.835 V/BeyondPod(12506): *** Player Paused!  (77 ms. since last trace)   [MediaPlaybackService]
05-29 14:14:45.843 V/BeyondPod(12506): Updating the Remote Control Client playback state to: 2  (4 ms. since last trace)   [RemoteControlClientHelper]
05-29 14:14:45.843 V/BeyondPod(12506): Scrobbling track Intent { act=mobi.beyondpod.action.PLAYBACK_STATUS (has extras) }  (1 ms. since last trace)   [CoreHelper]
05-29 14:14:45.843 V/BeyondPod(12506): Service autoshutdown scheduled from gotoIdleState  (1 ms. since last trace)   [MediaPlaybackService]
05-29 14:14:45.843 V/BeyondPod(12506): Repository save started...  (1 ms. since last trace)   [FeedRepository]
05-29 14:14:45.851 V/BeyondPod(12506): Saving track record for: Episode 1 – Unleashed  (11 ms. since last trace)   [DatabaseHelper]
05-29 14:14:45.929 V/BeyondPod(12506): Repository save completed!  (75 ms. since last trace)   [FeedRepository]
05-29 14:14:59.046 D/dalvikvm(11031): GC_CONCURRENT freed 1336K, 29% free 8426K/11779K, paused 6ms+13ms
05-29 14:15:00.476 D/dalvikvm(11076): GC_CONCURRENT freed 412K, 48% free 2713K/5187K, paused 2ms+4ms
05-29 14:15:05.882 D/BluetoothEventLoop(  219): Device property changed: 00:24:BE:8A:31:AA property: Connected value: false
05-29 14:15:05.890 I/HeadsetBcastReceiver(11031): Headset action: android.bluetooth.device.action.ACL_DISCONNECTED
05-29 14:15:06.319 I/Gmail   (11184): MainSyncRequestProto: lowestBkwdConvoId: 0, highestHandledServerOp: 569058, normalSync: true
05-29 14:15:08.882 D/dalvikvm(11184): GC_CONCURRENT freed 1364K, 36% free 6668K/10307K, paused 1ms+5ms
05-29 14:15:09.202 D/dalvikvm(11184): GC_CONCURRENT freed 1546K, 37% free 6543K/10307K, paused 2ms+4ms
05-29 14:15:09.413 D/dalvikvm(11184): GC_EXPLICIT freed 46K, 37% free 6528K/10307K, paused 7ms+8ms
05-29 14:15:09.421 I/Gmail   (11184): MainSyncRequestProto: lowestBkwdConvoId: 0, highestHandledServerOp: 569106, normalSync: true
05-29 14:15:09.554 D/dalvikvm(  219): GC_EXPLICIT freed 1640K, 31% free 23453K/33603K, paused 3ms+8ms


Let me know if there is any other information that I can provide. And thanks for your help!

[GoneMAD]

looks like its something in AOKP that is delaying the event of disconnect from being broadcasted

05-29 14:02:30.546 D/BluetoothService( 219): CONNECTION_STATE_CHANGE: 00:24:BE:8A:31:AA: 2 -> 0

that appears to be when you disconnected bluetooth

05-29 14:02:50.679 D/BluetoothEventLoop( 219): Device property changed: 00:24:BE:8A:31:AA property: Connected value: false
05-29 14:02:50.679 I/HeadsetBcastReceiver(11031): Headset action: android.bluetooth.device.action.ACL_DISCONNECTED

HeadsetBcastReceiver is when GMMP receives the disconnect event from the OS. So there is a 20 second gap between the disconnect and the event being sent

[lumpadump]

Hmm... that's weird. I wonder why it's doing that. Maybe I'll go back to stock temporarily and see if it happens there too.

Also, I edited my previous post with some output from BeyondPod. It pauses immediately, so it might be looking for a different cue and might be useful.

[GoneMAD]

thanks

Beyond pod might be using one of the newer apis to detect the bluetooth disconnect. Most likely android.bluetooth.a2dp.profile.action.CONNECTION_STATE_CHANGED which looks like it was added in honeycomb

I'll add in to listen for that event instead of ACL_DISCONNECT for devices that support it and see if that works any better

[lumpadump]

Sounds great, thanks!

I tried it on the stock Verizon ROM as well and the 20 second delay exists there as well. Presumably it's something that's recently changed in AOSP Android since I don't have the issue with my OG Droid (I just checked it and it works fine).

[GoneMAD]

yeah probably was from something changed in aosp

is aokp based off of 4.0.4?

[lumpadump]

May 29, 2012 14:47:06 GMT -5 GoneMAD said:

is aokp based off of 4.0.4?

Yep, it's been on 4.0.4 for I think about a month now.

[GoneMAD]

try beta 2 to see if that speeds up the pause at all

[lumpadump]

Thanks for your reply. I thought I had posted what I'm about to earlier but apparently forgot. Beta 2 fixed it :-)

[GoneMAD]

awesome