Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Skip to content

Bluetooth audio fails randomly on FP3 (different kinds of failure, see below)

  • /e/ version: 0.11
  • Device model(s): FP3

Summary

I've got an Urban Box 2 device which I regularly use with other phones and is known to work flawlessly (the device identifies itself with MAC address 95:66:88:3E:2A:CD).

When attempting to connect from my /e/ + FP3 phone, sometimes (but not always) it fails in a variety of different ways.

Today I've seen 3 different cases, which I document below in chronological order:

Problem 1

I powered on the UrbanBox, then selected it from the list of previously paired devices in my phone and tap to start a connection. UI displays the "Connnecting..." message but nothing happens. logcat below:

10-28 17:34:07.309   634   634 E ANDR-PERF-MPCTL: Active req limit reached, No optimizations performed
10-28 17:34:07.311   621   621 E QCOM PowerHAL: Failed to acquire lock.
10-28 17:34:07.311   634   634 E ANDR-PERF-MPCTL: Active req limit reached, No optimizations performed
10-28 17:34:07.312   621   621 E QCOM PowerHAL: Failed to acquire lock.
10-28 17:34:07.370 26693 26693 D BluetoothA2dp: connect(95:66:88:3E:2A:CD)
10-28 17:34:07.372 13692 18413 D A2dpService: connect(): 95:66:88:3E:2A:CD
10-28 17:34:07.375 26693 26693 D CachedBluetoothDevice: Command sent successfully:CONNECT Address:95:66:88:3E:2A:CD Profile:A2DP
10-28 17:34:07.376 13692 14096 D A2dpStateMachine: handleMessage: E msg.what=1
10-28 17:34:07.376 13692 14096 D A2dpStateMachine: processMsg: Disconnected
10-28 17:34:07.376 13692 14096 D A2dpStateMachine: Disconnected process message(95:66:88:3E:2A:CD): CONNECT
10-28 17:34:07.376 13692 14096 I A2dpStateMachine: Connecting to 95:66:88:3E:2A:CD
10-28 17:34:07.376 13692 14096 I BluetoothA2dpServiceJni: connectA2dpNative: sBluetoothA2dpInterface: 0x780045e4c0
10-28 17:34:07.376 13692 13745 I bt_btif_queue: queue_int_add: adding connection request: address=95:66:88:3e:2a:cd UUID=110A busy=false
10-28 17:34:07.376 13692 13745 I bt_btif_queue: btif_queue_connect_next: executing connection request: address=95:66:88:3e:2a:cd UUID=110A busy=false
10-28 17:34:07.377 13692 13745 I btif_av : BtifAvPeer *BtifAvSource::FindOrCreatePeer(const RawAddress &, tBTA_AV_HNDL): Create peer: peer_address=95:66:88:3e:2a:cd bta_handle=0x41 peer_id=0
10-28 17:34:07.377 13692 13745 W bt_btif : btif_av_get_peer_sep: No active peer found
10-28 17:34:07.377 13692 13745 I bt_btif_a2dp: btif_a2dp_on_idle: ## ON A2DP IDLE ## peer_sep = 1
10-28 17:34:07.377 13692 13745 W bt_btif : btif_av_get_peer_sep: No active peer found
10-28 17:34:07.377 13692 13745 I bt_btif_a2dp_source: btif_a2dp_source_on_idle: state=STATE_OFF
10-28 17:34:07.377 13692 13745 I bt_bta_av: BTA_AvOpen: peer 95:66:88:3e:2a:cd handle:0x41 use_rc=true sec_mask=0x12 uuid=0x110a
10-28 17:34:07.376 13692 14096 I A2dpService: okToConnect: device 95:66:88:3E:2A:CD isOutgoingRequest: true
10-28 17:34:07.377 13692 14026 I bt_bta_av: bta_av_save_addr: reset flags old_addr=00:00:00:00:00:00 new_addr=95:66:88:3e:2a:cd
10-28 17:34:07.377 13692 14096 D BluetoothAdapterService: isQuetModeEnabled() - Enabled = false
10-28 17:34:07.378 13692 14026 D bt_bta_av: SetAvdtpVersion: AVDTP version for 95:66:88:3e:2a:cd set to 0x100
10-28 17:34:07.378 13692 14026 I a2dp_api: A2DP_FindService: peer: 95:66:88:3e:2a:cd UUID: 0x110b
10-28 17:34:07.378 13692 13745 I btif_av : btif_report_connection_state: peer_address=95:66:88:3e:2a:cd state=1
10-28 17:34:07.378 13692 13745 I BluetoothA2dpServiceJni: bta2dp_connection_state_callback
10-28 17:34:07.379 13692 13745 D A2dpNativeInterface: onConnectionStateChanged: A2dpStackEvent {type:EVENT_TYPE_CONNECTION_STATE_CHANGED, device:95:66:88:3E:2A:CD, value1:CONNECTING}
10-28 17:34:07.379 13692 14096 D A2dpStateMachine: transitionTo: destState=Connecting
10-28 17:34:07.379 13692 14096 D A2dpStateMachine: handleMessage: new destination call exit/enter
10-28 17:34:07.380 13692 14096 D A2dpStateMachine: setupTempStateStackWithStatesToEnter: X mTempStateStackCount=1,curStateInfo: null
10-28 17:34:07.380 13692 14096 D A2dpStateMachine: invokeExitMethods: Disconnected
10-28 17:34:07.380 13692 14096 D A2dpStateMachine: Exit Disconnected(95:66:88:3E:2A:CD): CONNECT
10-28 17:34:07.380 13692 14096 D A2dpStateMachine: moveTempStackToStateStack: i=0,j=0
10-28 17:34:07.380 13692 14096 D A2dpStateMachine: moveTempStackToStateStack: X mStateStackTop=0,startingIndex=0,Top=Connecting
10-28 17:34:07.380 13692 14096 D A2dpStateMachine: invokeEnterMethods: Connecting
10-28 17:34:07.380 13692 14096 I A2dpStateMachine: Enter Connecting(95:66:88:3E:2A:CD): CONNECT
10-28 17:34:07.380 13692 14096 D A2dpStateMachine: Connection state 95:66:88:3E:2A:CD: DISCONNECTED->CONNECTING
10-28 17:34:07.382 13692 14096 D A2dpStateMachine: handleMessage: X
10-28 17:34:07.382 13692 14096 D A2dpStateMachine: handleMessage: E msg.what=101
10-28 17:34:07.382 13692 14096 D A2dpStateMachine: processMsg: Connecting
10-28 17:34:07.382 13692 14096 D A2dpStateMachine: Connecting process message(95:66:88:3E:2A:CD): STACK_EVENT
10-28 17:34:07.382 13692 14096 D A2dpStateMachine: Connecting: stack event: A2dpStackEvent {type:EVENT_TYPE_CONNECTION_STATE_CHANGED, device:95:66:88:3E:2A:CD, value1:CONNECTING}
10-28 17:34:07.383 13692 14096 D A2dpStateMachine: handleMessage: X
10-28 17:34:07.383 13719 13970 D CachedBluetoothDevice: onProfileStateChanged: profile A2DP, device=95:66:88:3E:2A:CD, newProfileState 1
10-28 17:34:07.384 13564 13579 D NetworkManagement: Uid 10123 restricted because of app standby mode
10-28 17:34:07.384 26693 26693 D CachedBluetoothDevice: onProfileStateChanged: profile A2DP, device=95:66:88:3E:2A:CD, newProfileState 1
10-28 17:34:07.384 13564 13579 D NetworkManagement: Uid 10041 restricted because of app standby mode
10-28 17:34:07.384 13564 13579 D NetworkManagement: Uid 10040 restricted because of app standby mode
10-28 17:34:07.385 13564 13579 D NetworkManagement: Uid 10029 restricted because of app standby mode
10-28 17:34:07.386 13692 13692 D AdapterProperties: PROFILE_CONNECTION_STATE_CHANGE: profile=2, device=95:66:88:3E:2A:CD, 0 -> 1
10-28 17:34:07.387 13692 13692 D AdapterProperties: ADAPTER_CONNECTION_STATE_CHANGE: 95:66:88:3E:2A:CD: 0 -> 1
10-28 17:34:07.392 13692 13692 I BluetoothPhonePolicy: processProfileStateChanged, device=95:66:88:3E:2A:CD, profile=2, 0 -> 1
10-28 17:34:07.398 13564 18967 D NetworkManagement: Uid 10123 restricted because of app standby mode
10-28 17:34:07.398 13564 18967 D NetworkManagement: Uid 10041 restricted because of app standby mode
10-28 17:34:07.398 13564 18967 D NetworkManagement: Uid 10040 restricted because of app standby mode
10-28 17:34:07.399 13564 18967 D NetworkManagement: Uid 10029 restricted because of app standby mode
10-28 17:34:07.399 13564 18967 D NetworkManagement: Uid 10123 restricted because of app standby mode
10-28 17:34:07.399 13564 18967 D NetworkManagement: Uid 10041 restricted because of app standby mode
10-28 17:34:07.399 13564 18967 D NetworkManagement: Uid 10040 restricted because of app standby mode
10-28 17:34:07.399 13564 18967 D NetworkManagement: Uid 10029 restricted because of app standby mode
10-28 17:34:12.311 13564 13589 E LightsService: Light requested not available on this device. 2

Problem 2

After experiencing problem 1, I exit the Settings app, start it again and tap the Connect button again. This time it doesn't get stuck, but displays "Connecting..." for a brief time (fraction of a second) and UI goes back to disconnected state. Logcat:

10-28 17:35:21.753   634   634 E ANDR-PERF-MPCTL: Active req limit reached, No optimizations performed
10-28 17:35:21.755 13564 13638 E LightsService: Light requested not available on this device. 2
10-28 17:35:21.755   621   621 E QCOM PowerHAL: Failed to acquire lock.
10-28 17:35:21.756   634   634 E ANDR-PERF-MPCTL: Active req limit reached, No optimizations performed
10-28 17:35:21.756   621   621 E QCOM PowerHAL: Failed to acquire lock.
10-28 17:35:21.824 26693 26693 D BluetoothA2dp: connect(95:66:88:3E:2A:CD)
10-28 17:35:21.826 13692 27047 D A2dpService: connect(): 95:66:88:3E:2A:CD
10-28 17:35:21.828 26693 26693 D CachedBluetoothDevice: Command sent successfully:CONNECT Address:95:66:88:3E:2A:CD Profile:A2DP
10-28 17:35:21.828 13692 14096 D A2dpStateMachine: handleMessage: E msg.what=1
10-28 17:35:21.828 13692 14096 D A2dpStateMachine: processMsg: Disconnected
10-28 17:35:21.829 13692 14096 D A2dpStateMachine: Disconnected process message(95:66:88:3E:2A:CD): CONNECT
10-28 17:35:21.829 13692 14096 I A2dpStateMachine: Connecting to 95:66:88:3E:2A:CD
10-28 17:35:21.829 13692 14096 I BluetoothA2dpServiceJni: connectA2dpNative: sBluetoothA2dpInterface: 0x780045e4c0
10-28 17:35:21.829 13692 14096 I A2dpService: okToConnect: device 95:66:88:3E:2A:CD isOutgoingRequest: true
10-28 17:35:21.829 13692 13745 I bt_btif_queue: queue_int_add: adding connection request: address=95:66:88:3e:2a:cd UUID=110A busy=false
10-28 17:35:21.829 13692 14096 D BluetoothAdapterService: isQuetModeEnabled() - Enabled = false
10-28 17:35:21.829 13692 13745 I bt_btif_queue: btif_queue_connect_next: executing connection request: address=95:66:88:3e:2a:cd UUID=110A busy=false
10-28 17:35:21.829 13692 13745 I btif_av : BtifAvPeer *BtifAvSource::FindOrCreatePeer(const RawAddress &, tBTA_AV_HNDL): Create peer: peer_address=95:66:88:3e:2a:cd bta_handle=0x41 peer_id=0
10-28 17:35:21.830 13692 13745 W bt_btif : btif_av_get_peer_sep: No active peer found
10-28 17:35:21.830 13692 13745 I bt_btif_a2dp: btif_a2dp_on_idle: ## ON A2DP IDLE ## peer_sep = 1
10-28 17:35:21.830 13692 13745 W bt_btif : btif_av_get_peer_sep: No active peer found
10-28 17:35:21.830 13692 13745 I bt_btif_a2dp_source: btif_a2dp_source_on_idle: state=STATE_OFF
10-28 17:35:21.830 13692 13745 I bt_bta_av: BTA_AvOpen: peer 95:66:88:3e:2a:cd handle:0x41 use_rc=true sec_mask=0x12 uuid=0x110a
10-28 17:35:21.830 13692 13745 I btif_av : btif_report_connection_state: peer_address=95:66:88:3e:2a:cd state=1
10-28 17:35:21.830 13692 14026 I bt_bta_av: bta_av_save_addr: reset flags old_addr=00:00:00:00:00:00 new_addr=95:66:88:3e:2a:cd
10-28 17:35:21.830 13692 13745 I BluetoothA2dpServiceJni: bta2dp_connection_state_callback
10-28 17:35:21.830 13692 14026 D bt_bta_av: SetAvdtpVersion: AVDTP version for 95:66:88:3e:2a:cd set to 0x100
10-28 17:35:21.830 13692 14026 I a2dp_api: A2DP_FindService: peer: 95:66:88:3e:2a:cd UUID: 0x110b
10-28 17:35:21.833 13692 14026 W bt_sdp  : SDP - Rcvd conn cnf with error: 0xc  CID 0x46
10-28 17:35:21.833 13692 14026 I a2dp_api: a2dp_sdp_cback: status: 65521
10-28 17:35:21.833 13692 14026 E bt_btif : bta_av_a2dp_sdp_cback: peer 95:66:88:3e:2a:cd A2DP service discovery failed
10-28 17:35:21.833 13692 14026 E bt_btif : bta_av_a2dp_sdp_cback: BTA_AV_SDP_DISC_FAIL_EVT: peer_addr=95:66:88:3e:2a:cd
10-28 17:35:21.833 13692 13745 D A2dpNativeInterface: onConnectionStateChanged: A2dpStackEvent {type:EVENT_TYPE_CONNECTION_STATE_CHANGED, device:95:66:88:3E:2A:CD, value1:CONNECTING}
10-28 17:35:21.833 13692 14026 D bt_bta_av: SetAvdtpVersion: AVDTP version for 95:66:88:3e:2a:cd set to 0x0
10-28 17:35:21.833 13692 14026 W bt_avp  : AVDT_ConnectReq: address=95:66:88:3e:2a:cd channel_index=0 sec_mask=0x12
10-28 17:35:21.834 13692 14026 W bt_avp  : AVDT_ConnectReq: address=95:66:88:3e:2a:cd result=0
10-28 17:35:21.836 13692 14026 I bt_bta_av: bta_av_conn_cback: conn_cback bd_addr: 95:66:88:3e:2a:cd
10-28 17:35:21.836 13692 14026 E bt_btif : bta_av_conn_failed: peer_addr=95:66:88:3e:2a:cd open_status=0
10-28 17:35:21.836 13692 14026 W bt_btif : bta_av_str_closed: peer 95:66:88:3e:2a:cd handle:65 open_status:3 chnl:64 co_started:0
10-28 17:35:21.836 13692 14026 W bt_btif : bta_dm_rm_cback:0, status:1
10-28 17:35:21.836 13692 14026 W bt_btif : bta_dm_act no entry for connected service cbs
10-28 17:35:21.836 13692 14026 I bt_bta_av: bta_av_cleanup peer 95:66:88:3e:2a:cd
10-28 17:35:21.836 13692 14026 D bt_bta_av: SetAvdtpVersion: AVDTP version for 95:66:88:3e:2a:cd set to 0x0
10-28 17:35:21.836 13692 14026 D bt_bta_av: SetAvdtpVersion: AVDTP version for 00:00:00:00:00:00 set to 0x0
10-28 17:35:21.836 13692 14026 W bt_btif : bta_av_rc_create: Skipping RC creation for the old AVRCP profile
10-28 17:35:21.836 13692 14026 I btif_av : virtual bool BtifAvStateMachine::StateOpening::ProcessEvent(uint32_t, void *): Peer 95:66:88:3e:2a:cd : event=BTA_AV_OPEN_EVT(0x2) flags=0x0(None) status=3(FAILED) edr=0x33
10-28 17:35:21.837 13692 14026 E bt_btif : get_connected_device: returning NULL
10-28 17:35:21.837 13692 14026 I chatty  : uid=1002(bluetooth) btu message loo identical 4 lines
10-28 17:35:21.837 13692 14026 E bt_btif : get_connected_device: returning NULL
10-28 17:35:21.837 13692 14026 I btif_av : btif_report_connection_state: peer_address=95:66:88:3e:2a:cd state=0
10-28 17:35:21.837 13692 14026 W bt_btif : btif_av_get_peer_sep: No active peer found
10-28 17:35:21.837 13692 14026 I bt_btif_a2dp: btif_a2dp_on_idle: ## ON A2DP IDLE ## peer_sep = 1
10-28 17:35:21.837 13692 14026 W bt_btif : btif_av_get_peer_sep: No active peer found
10-28 17:35:21.837 13692 14026 I bt_btif_a2dp_source: btif_a2dp_source_on_idle: state=STATE_OFF
10-28 17:35:21.837 13692 14026 E bt_btif : btif_rc_get_device_by_bda: device not found, returning NULL!
10-28 17:35:21.837 13692 14026 E bt_btif : btif_rc_check_handle_pending_play: p_dev NULL
10-28 17:35:21.837 13692 14026 I btif_av : DeleteIdlePeers: Deleting idle peer: 95:66:88:3e:2a:cd bta_handle=0x41
10-28 17:35:21.837 13692 14096 D A2dpStateMachine: transitionTo: destState=Connecting
10-28 17:35:21.837 13692 14096 D A2dpStateMachine: handleMessage: new destination call exit/enter
10-28 17:35:21.837 13692 14096 D A2dpStateMachine: setupTempStateStackWithStatesToEnter: X mTempStateStackCount=1,curStateInfo: null
10-28 17:35:21.837 13692 14096 D A2dpStateMachine: invokeExitMethods: Disconnected
10-28 17:35:21.837 13692 14096 D A2dpStateMachine: Exit Disconnected(95:66:88:3E:2A:CD): CONNECT
10-28 17:35:21.837 13692 14096 D A2dpStateMachine: moveTempStackToStateStack: i=0,j=0
10-28 17:35:21.837 13692 14096 D A2dpStateMachine: moveTempStackToStateStack: X mStateStackTop=0,startingIndex=0,Top=Connecting
10-28 17:35:21.837 13692 14096 D A2dpStateMachine: invokeEnterMethods: Connecting
10-28 17:35:21.837 13692 14096 I A2dpStateMachine: Enter Connecting(95:66:88:3E:2A:CD): CONNECT
10-28 17:35:21.837 13692 14096 D A2dpStateMachine: Connection state 95:66:88:3E:2A:CD: DISCONNECTED->CONNECTING
10-28 17:35:21.839 13692 14096 D A2dpStateMachine: handleMessage: X
10-28 17:35:21.839 13692 14096 D A2dpStateMachine: handleMessage: E msg.what=101
10-28 17:35:21.839 13692 14096 D A2dpStateMachine: processMsg: Connecting
10-28 17:35:21.839 13692 14096 D A2dpStateMachine: Connecting process message(95:66:88:3E:2A:CD): STACK_EVENT
10-28 17:35:21.840 13692 14096 D A2dpStateMachine: Connecting: stack event: A2dpStackEvent {type:EVENT_TYPE_CONNECTION_STATE_CHANGED, device:95:66:88:3E:2A:CD, value1:CONNECTING}
10-28 17:35:21.840 13692 14096 D A2dpStateMachine: handleMessage: X
10-28 17:35:21.842 13692 13692 D AdapterProperties: PROFILE_CONNECTION_STATE_CHANGE: profile=2, device=95:66:88:3E:2A:CD, 0 -> 1
10-28 17:35:21.842 13692 13692 D AdapterProperties: ADAPTER_CONNECTION_STATE_CHANGE: 95:66:88:3E:2A:CD: 0 -> 1
10-28 17:35:21.842 13719 13970 D CachedBluetoothDevice: onProfileStateChanged: profile A2DP, device=95:66:88:3E:2A:CD, newProfileState 1
10-28 17:35:21.842 13564 13579 D NetworkManagement: Uid 10123 restricted because of app standby mode
10-28 17:35:21.843 13564 13579 D NetworkManagement: Uid 10115 restricted because of app standby mode
10-28 17:35:21.843 13564 13579 D NetworkManagement: Uid 10064 restricted because of app standby mode
10-28 17:35:21.843 13564 13579 D NetworkManagement: Uid 10056 restricted because of app standby mode
10-28 17:35:21.843 13564 13579 D NetworkManagement: Uid 10042 restricted because of app standby mode
10-28 17:35:21.843 13564 13579 D NetworkManagement: Uid 10041 restricted because of app standby mode
10-28 17:35:21.843 13564 13579 D NetworkManagement: Uid 10040 restricted because of app standby mode
10-28 17:35:21.843 13564 13579 D NetworkManagement: Uid 10032 restricted because of app standby mode
10-28 17:35:21.843 26693 26693 D CachedBluetoothDevice: onProfileStateChanged: profile A2DP, device=95:66:88:3E:2A:CD, newProfileState 1
10-28 17:35:21.845 13692 13692 I BluetoothPhonePolicy: processProfileStateChanged, device=95:66:88:3E:2A:CD, profile=2, 0 -> 1
10-28 17:35:21.855 13692 13745 I BluetoothA2dpServiceJni: bta2dp_connection_state_callback
10-28 17:35:21.855 13692 13745 D A2dpNativeInterface: onConnectionStateChanged: A2dpStackEvent {type:EVENT_TYPE_CONNECTION_STATE_CHANGED, device:95:66:88:3E:2A:CD, value1:DISCONNECTED}
10-28 17:35:21.855 13692 13745 I bt_btif_queue: queue_int_advance: removing connection request: address=95:66:88:3e:2a:cd UUID=110A busy=true
10-28 17:35:21.855 13692 14096 D A2dpStateMachine: handleMessage: E msg.what=101
10-28 17:35:21.855 13692 14096 D A2dpStateMachine: processMsg: Connecting
10-28 17:35:21.855 13692 14096 D A2dpStateMachine: Connecting process message(95:66:88:3E:2A:CD): STACK_EVENT
10-28 17:35:21.855 13692 14096 D A2dpStateMachine: Connecting: stack event: A2dpStackEvent {type:EVENT_TYPE_CONNECTION_STATE_CHANGED, device:95:66:88:3E:2A:CD, value1:DISCONNECTED}
10-28 17:35:21.855 13692 14096 W A2dpStateMachine: Connecting device disconnected: 95:66:88:3E:2A:CD
10-28 17:35:21.855 13692 14096 D A2dpStateMachine: transitionTo: destState=Disconnected
10-28 17:35:21.856 13692 14096 D A2dpStateMachine: handleMessage: new destination call exit/enter
10-28 17:35:21.856 13692 14096 D A2dpStateMachine: setupTempStateStackWithStatesToEnter: X mTempStateStackCount=1,curStateInfo: null
10-28 17:35:21.856 13692 14096 D A2dpStateMachine: invokeExitMethods: Connecting
10-28 17:35:21.856 13692 14096 D A2dpStateMachine: Exit Connecting(95:66:88:3E:2A:CD): STACK_EVENT
10-28 17:35:21.856 13692 14096 D A2dpStateMachine: moveTempStackToStateStack: i=0,j=0
10-28 17:35:21.856 13692 14096 D A2dpStateMachine: moveTempStackToStateStack: X mStateStackTop=0,startingIndex=0,Top=Disconnected
10-28 17:35:21.856 13692 14096 D A2dpStateMachine: invokeEnterMethods: Disconnected
10-28 17:35:21.856 13692 14096 I A2dpStateMachine: Enter Disconnected(95:66:88:3E:2A:CD): STACK_EVENT
10-28 17:35:21.856 13692 14096 D A2dpStateMachine: Connection state 95:66:88:3E:2A:CD: CONNECTING->DISCONNECTED
10-28 17:35:21.857 13564 18959 D NetworkManagement: Uid 10123 restricted because of app standby mode
10-28 17:35:21.857 13564 18959 D NetworkManagement: Uid 10115 restricted because of app standby mode
10-28 17:35:21.857 13564 18959 D NetworkManagement: Uid 10064 restricted because of app standby mode
10-28 17:35:21.857 13564 18959 D NetworkManagement: Uid 10056 restricted because of app standby mode
10-28 17:35:21.857 13564 18959 D NetworkManagement: Uid 10042 restricted because of app standby mode
10-28 17:35:21.857 13564 18959 D NetworkManagement: Uid 10041 restricted because of app standby mode
10-28 17:35:21.857 13564 18959 D NetworkManagement: Uid 10040 restricted because of app standby mode
10-28 17:35:21.857 13564 18959 D NetworkManagement: Uid 10032 restricted because of app standby mode
10-28 17:35:21.858 13564 18959 D NetworkManagement: Uid 10123 restricted because of app standby mode
10-28 17:35:21.858 13564 18959 D NetworkManagement: Uid 10115 restricted because of app standby mode
10-28 17:35:21.858 13564 18959 D NetworkManagement: Uid 10064 restricted because of app standby mode
10-28 17:35:21.858 13564 18959 D NetworkManagement: Uid 10056 restricted because of app standby mode
10-28 17:35:21.858 13564 18959 D NetworkManagement: Uid 10042 restricted because of app standby mode
10-28 17:35:21.858 13564 18959 D NetworkManagement: Uid 10041 restricted because of app standby mode
10-28 17:35:21.858 13564 18959 D NetworkManagement: Uid 10040 restricted because of app standby mode
10-28 17:35:21.858 13564 18959 D NetworkManagement: Uid 10032 restricted because of app standby mode
10-28 17:35:21.859 13692 14096 D A2dpStateMachine: handleMessage: X
10-28 17:35:21.860 13692 13692 D AdapterProperties: PROFILE_CONNECTION_STATE_CHANGE: profile=2, device=95:66:88:3E:2A:CD, 1 -> 0
10-28 17:35:21.860 13564 13579 D NetworkManagement: Uid 10123 restricted because of app standby mode
10-28 17:35:21.860 13564 13579 D NetworkManagement: Uid 10115 restricted because of app standby mode
10-28 17:35:21.860 13692 13692 D AdapterProperties: ADAPTER_CONNECTION_STATE_CHANGE: 95:66:88:3E:2A:CD: 1 -> 0
10-28 17:35:21.860 13564 13579 D NetworkManagement: Uid 10064 restricted because of app standby mode
10-28 17:35:21.860 13564 13579 D NetworkManagement: Uid 10056 restricted because of app standby mode
10-28 17:35:21.860 13564 13579 D NetworkManagement: Uid 10042 restricted because of app standby mode
10-28 17:35:21.860 13564 13579 D NetworkManagement: Uid 10041 restricted because of app standby mode
10-28 17:35:21.860 13564 13579 D NetworkManagement: Uid 10040 restricted because of app standby mode
10-28 17:35:21.860 13564 13579 D NetworkManagement: Uid 10032 restricted because of app standby mode
10-28 17:35:21.861 13692 13692 I BluetoothPhonePolicy: processProfileStateChanged, device=95:66:88:3E:2A:CD, profile=2, 1 -> 0
10-28 17:35:21.862 13692 13692 I BluetoothPhonePolicy: processProfileStateChanged, device=95:66:88:3E:2A:CD, a2dpDisconnected=true, hsDisconnected=true
10-28 17:35:21.869 13564 19792 D NetworkManagement: Uid 10123 restricted because of app standby mode
10-28 17:35:21.869 13564 19792 D NetworkManagement: Uid 10115 restricted because of app standby mode
10-28 17:35:21.869 13564 19792 D NetworkManagement: Uid 10064 restricted because of app standby mode
10-28 17:35:21.869 13564 19792 D NetworkManagement: Uid 10056 restricted because of app standby mode
10-28 17:35:21.869 13564 19792 D NetworkManagement: Uid 10042 restricted because of app standby mode
10-28 17:35:21.869 13564 19792 D NetworkManagement: Uid 10041 restricted because of app standby mode
10-28 17:35:21.869 13564 19792 D NetworkManagement: Uid 10040 restricted because of app standby mode
10-28 17:35:21.869 13564 19792 D NetworkManagement: Uid 10032 restricted because of app standby mode
10-28 17:35:21.870 13564 19792 D NetworkManagement: Uid 10123 restricted because of app standby mode
10-28 17:35:21.870 13564 19792 D NetworkManagement: Uid 10115 restricted because of app standby mode
10-28 17:35:21.870 13564 19792 D NetworkManagement: Uid 10064 restricted because of app standby mode
10-28 17:35:21.870 13564 19792 D NetworkManagement: Uid 10056 restricted because of app standby mode
10-28 17:35:21.870 13564 19792 D NetworkManagement: Uid 10042 restricted because of app standby mode
10-28 17:35:21.870 13564 19792 D NetworkManagement: Uid 10041 restricted because of app standby mode
10-28 17:35:21.870 13564 19792 D NetworkManagement: Uid 10040 restricted because of app standby mode
10-28 17:35:21.870 13564 19792 D NetworkManagement: Uid 10032 restricted because of app standby mode
10-28 17:35:21.877 13719 13970 I LocalBluetoothProfileManager: Failed to connect A2DP device
10-28 17:35:21.877 13719 13970 D CachedBluetoothDevice: onProfileStateChanged: profile A2DP, device=95:66:88:3E:2A:CD, newProfileState 0
10-28 17:35:21.913 26693 26693 I LocalBluetoothProfileManager: Failed to connect A2DP device
10-28 17:35:21.913 26693 26693 D CachedBluetoothDevice: onProfileStateChanged: profile A2DP, device=95:66:88:3E:2A:CD, newProfileState 0

Problem 3

After experiencing problem 2, I restarted the UrbanBox, which didn't change anything (still experiencing problem 2).

Then I disabled Bluetooth in my phone, and re-enabled it. Immediately, the phone connects to UrbanBox. I check my audio player app (Spotify) and it reports it's playing, but I can't hear anything.

When I look at logcat, it's repeatedly (several times per second) printing the same error sequence (it's probably out of order as I can't tell where the sequence starts or ends):

10-28 17:38:15.169 27222 27261 I btif_av : virtual bool BtifAvStateMachine::StateOpened::ProcessEvent(uint32_t, void *): Peer 95:66:88:3e:2a:cd : event=BTA_AV_START_EVT(0x4) status=1 suspending=54 initiator=1 flags=0x4(PENDING_START)
10-28 17:38:15.169 27222 27261 I bt_btif_a2dp: btif_a2dp_on_started: ## ON A2DP STARTED ## peer 95:66:88:3e:2a:cd pending_start:true p_av_start:0x7813a8a138
10-28 17:38:15.169 27222 27261 I bt_btif_a2dp: btif_a2dp_on_started: peer 95:66:88:3e:2a:cd pending_start:true status:1 suspending:false initiator:true
10-28 17:38:15.169 27222 27261 E bt_btif_a2dp: btif_a2dp_on_started: peer 95:66:88:3e:2a:cd A2DP start request failed: status = 1
10-28 17:38:15.169 27222 27261 W bt_btif : btif_a2dp_command_ack: ## a2dp ack : A2DP_CTRL_CMD_START, status 1 ##
10-28 17:38:15.169 13438 27305 E bt_a2dp_hw: a2dp_command: A2DP COMMAND A2DP_CTRL_CMD_START error 1
10-28 17:38:15.169 13438 27305 E bt_a2dp_hw: start_audio_datapath: Audiopath start failed (status -1)
10-28 17:38:15.190 13438 27305 I bt_a2dp_hw: start_audio_datapath: state 5
10-28 17:38:15.190 27222 27296 W bt_btif : btif_a2dp_recv_ctrl_data: a2dp-ctrl-cmd : A2DP_CTRL_CMD_START
10-28 17:38:15.190 27222 27296 I btif_av : btif_av_stream_ready: Peer 95:66:88:3e:2a:cd : state=2, flags=0x0(None)
10-28 17:38:15.191 27222 27296 I btif_av : btif_av_stream_start
10-28 17:38:15.191 27222 27296 W bt_btif : btif_a2dp_recv_ctrl_data: a2dp-ctrl-cmd : A2DP_CTRL_CMD_START DONE
10-28 17:38:15.191 27222 27261 I btif_av : virtual bool BtifAvStateMachine::StateOpened::ProcessEvent(uint32_t, void *): Peer 95:66:88:3e:2a:cd : event=BTIF_AV_START_STREAM_REQ_EVT(0x1b) flags=0x0(None)
10-28 17:38:15.191 27222 27261 I bt_bta_av: BTA_AvStart: handle=65
10-28 17:38:15.191 27222 27261 I bt_bta_av: bta_av_do_start: peer 95:66:88:3e:2a:cd sco_occupied:false role:0x0 started:false wait:0x0
10-28 17:38:15.191 27222 27261 W bt_btif : bta_dm_rm_cback:2, status:7
10-28 17:38:15.191 27222 27261 I bt_bta_av: bta_av_do_start: peer 95:66:88:3e:2a:cd start requested: sco_occupied:false role:0x10 started:false wait:0x0
10-28 17:38:15.221 27222 27261 E bt_btif : bta_av_start_failed: peer 95:66:88:3e:2a:cd handle:65 audio_open_cnt:1 started:false co_started:0
10-28 17:38:15.221 27222 27261 W bt_btif : bta_dm_rm_cback:2, status:6
10-28 17:38:15.221 27222 27261 E bt_bta_av: notify_start_failed: peer 95:66:88:3e:2a:cd role:0x10 channel:64 handle:0x41
10-28 17:38:15.221 27222 27261 I btif_av : virtual bool BtifAvStateMachine::StateOpened::ProcessEvent(uint32_t, void *): Peer 95:66:88:3e:2a:cd : event=BTA_AV_START_EVT(0x4) status=1 suspending=54 initiator=1 flags=0x4(PENDING_START)
10-28 17:38:15.221 27222 27261 I bt_btif_a2dp: btif_a2dp_on_started: ## ON A2DP STARTED ## peer 95:66:88:3e:2a:cd pending_start:true p_av_start:0x7813ad2f78
10-28 17:38:15.221 27222 27261 I bt_btif_a2dp: btif_a2dp_on_started: peer 95:66:88:3e:2a:cd pending_start:true status:1 suspending:false initiator:true
10-28 17:38:15.222 27222 27261 E bt_btif_a2dp: btif_a2dp_on_started: peer 95:66:88:3e:2a:cd A2DP start request failed: status = 1
10-28 17:38:15.222 27222 27261 W bt_btif : btif_a2dp_command_ack: ## a2dp ack : A2DP_CTRL_CMD_START, status 1 ##
10-28 17:38:15.222 13438 27305 E bt_a2dp_hw: a2dp_command: A2DP COMMAND A2DP_CTRL_CMD_START error 1
10-28 17:38:15.222 13438 27305 E bt_a2dp_hw: start_audio_datapath: Audiopath start failed (status -1)
10-28 17:38:15.243 13438 27305 I bt_a2dp_hw: start_audio_datapath: state 5
10-28 17:38:15.243 27222 27296 W bt_btif : btif_a2dp_recv_ctrl_data: a2dp-ctrl-cmd : A2DP_CTRL_CMD_START
10-28 17:38:15.243 27222 27296 I btif_av : btif_av_stream_ready: Peer 95:66:88:3e:2a:cd : state=2, flags=0x0(None)
10-28 17:38:15.243 27222 27296 I btif_av : btif_av_stream_start
10-28 17:38:15.243 27222 27296 W bt_btif : btif_a2dp_recv_ctrl_data: a2dp-ctrl-cmd : A2DP_CTRL_CMD_START DONE
10-28 17:38:15.244 27222 27261 I btif_av : virtual bool BtifAvStateMachine::StateOpened::ProcessEvent(uint32_t, void *): Peer 95:66:88:3e:2a:cd : event=BTIF_AV_START_STREAM_REQ_EVT(0x1b) flags=0x0(None)
10-28 17:38:15.244 27222 27261 I bt_bta_av: BTA_AvStart: handle=65
10-28 17:38:15.244 27222 27261 I bt_bta_av: bta_av_do_start: peer 95:66:88:3e:2a:cd sco_occupied:false role:0x0 started:false wait:0x0
10-28 17:38:15.244 27222 27261 W bt_btif : bta_dm_rm_cback:2, status:7
10-28 17:38:15.244 27222 27261 I bt_bta_av: bta_av_do_start: peer 95:66:88:3e:2a:cd start requested: sco_occupied:false role:0x10 started:false wait:0x0
10-28 17:38:15.274 27222 27261 E bt_btif : bta_av_start_failed: peer 95:66:88:3e:2a:cd handle:65 audio_open_cnt:1 started:false co_started:0
10-28 17:38:15.275 27222 27261 W bt_btif : bta_dm_rm_cback:2, status:6
10-28 17:38:15.275 27222 27261 E bt_bta_av: notify_start_failed: peer 95:66:88:3e:2a:cd role:0x10 channel:64 handle:0x41
10-28 17:38:15.275 27222 27261 I btif_av : virtual bool BtifAvStateMachine::StateOpened::ProcessEvent(uint32_t, void *): Peer 95:66:88:3e:2a:cd : event=BTA_AV_START_EVT(0x4) status=1 suspending=54 initiator=1 flags=0x4(PENDING_START)
10-28 17:38:15.275 27222 27261 I bt_btif_a2dp: btif_a2dp_on_started: ## ON A2DP STARTED ## peer 95:66:88:3e:2a:cd pending_start:true p_av_start:0x7813a8a168
10-28 17:38:15.275 27222 27261 I bt_btif_a2dp: btif_a2dp_on_started: peer 95:66:88:3e:2a:cd pending_start:true status:1 suspending:false initiator:true
10-28 17:38:15.275 27222 27261 E bt_btif_a2dp: btif_a2dp_on_started: peer 95:66:88:3e:2a:cd A2DP start request failed: status = 1
10-28 17:38:15.275 27222 27261 W bt_btif : btif_a2dp_command_ack: ## a2dp ack : A2DP_CTRL_CMD_START, status 1 ##
10-28 17:38:15.275 13438 27305 E bt_a2dp_hw: a2dp_command: A2DP COMMAND A2DP_CTRL_CMD_START error 1
10-28 17:38:15.275 13438 27305 E bt_a2dp_hw: start_audio_datapath: Audiopath start failed (status -1)
10-28 17:38:15.296 13438 27305 I bt_a2dp_hw: start_audio_datapath: state 5
10-28 17:38:15.297 27222 27296 W bt_btif : btif_a2dp_recv_ctrl_data: a2dp-ctrl-cmd : A2DP_CTRL_CMD_START
10-28 17:38:15.297 27222 27296 I btif_av : btif_av_stream_ready: Peer 95:66:88:3e:2a:cd : state=2, flags=0x0(None)
10-28 17:38:15.297 27222 27296 I btif_av : btif_av_stream_start
10-28 17:38:15.297 27222 27296 W bt_btif : btif_a2dp_recv_ctrl_data: a2dp-ctrl-cmd : A2DP_CTRL_CMD_START DONE
10-28 17:38:15.297 27222 27261 I btif_av : virtual bool BtifAvStateMachine::StateOpened::ProcessEvent(uint32_t, void *): Peer 95:66:88:3e:2a:cd : event=BTIF_AV_START_STREAM_REQ_EVT(0x1b) flags=0x0(None)

Workaround

What did solve the problem is to shutdown UrbanBox, shutdown Bluetooth in the phone, then start UrbanBox, then start Bluetooth in the phone.

Edited by Robert B.