Fix issue where focus is retained after call.

The new audio routing refactor code had an issue where the focus was
not released at the end of a call.  The root cause was that
CallAudioRouteController was not calling
`mCallAudioManager.notifyAudioOperationsComplete()` when focus goes
inactive.

The rest of the changes you see are just logging cleanups to standardize
how Audio/BT operations are logged so that external API calls are easy
to identify, and to add method names where they were missing in the
log statements.

Flag: com.android.server.telecom.flags.use_refactored_audio_route_switching
Fixes: 356920567
Test: Manually testing audio focus; ensured media playing resumes after
a call.
Test: Added new tests to the Telecom CUJ suite to cover audio focus loss
and gain during managed, self-managed and transactional voip incoming
and outgoing calls.
Test: Updated unit tests for CallAudioRouteController to ensure that we
signal audio operations complete to CallAudioManager when focus is lost.

Change-Id: I4deba2ee8224fa0de5348bf49f615ad45c1af361
diff --git a/src/com/android/server/telecom/AudioRoute.java b/src/com/android/server/telecom/AudioRoute.java
index 8a5e858..7ce9fcc 100644
--- a/src/com/android/server/telecom/AudioRoute.java
+++ b/src/com/android/server/telecom/AudioRoute.java
@@ -70,7 +70,7 @@
                 return;
             }
 
-            Log.i(this, "creating AudioRoute with type %s and address %s, retry count %d",
+            Log.i(this, "createRetry; type=%s, address=%s, retryCount=%d",
                     DEVICE_TYPE_STRINGS.get(type), bluetoothAddress, retryCount);
             AudioDeviceInfo routeInfo = null;
             List<AudioDeviceInfo> infos = audioManager.getAvailableCommunicationDevices();
@@ -239,7 +239,8 @@
     void onDestRouteAsPendingRoute(boolean active, PendingAudioRoute pendingAudioRoute,
             BluetoothDevice device, AudioManager audioManager,
             BluetoothRouteManager bluetoothRouteManager, boolean isScoAudioConnected) {
-        Log.i(this, "onDestRouteAsPendingRoute: active (%b), type (%d)", active, mAudioRouteType);
+        Log.i(this, "onDestRouteAsPendingRoute: active (%b), type (%s)", active,
+                DEVICE_TYPE_STRINGS.get(mAudioRouteType));
         if (pendingAudioRoute.isActive() && !active) {
             clearCommunicationDevice(pendingAudioRoute, bluetoothRouteManager, audioManager);
         } else if (active) {
@@ -281,8 +282,8 @@
                     if (result) {
                         pendingAudioRoute.setCommunicationDeviceType(mAudioRouteType);
                     }
-                    Log.i(this, "Result of setting communication device for audio "
-                            + "route (%s) - %b", this, result);
+                    Log.i(this, "onDestRouteAsPendingRoute: route=%s, "
+                            + "AudioManager#setCommunicationDevice()=%b", this, result);
                     break;
                 }
             }
@@ -380,11 +381,11 @@
 
         int result = BluetoothStatusCodes.SUCCESS;
         if (pendingAudioRoute.getCommunicationDeviceType() == TYPE_BLUETOOTH_SCO) {
-            Log.i(this, "Disconnecting SCO device.");
+            Log.i(this, "clearCommunicationDevice: Disconnecting SCO device.");
             result = bluetoothRouteManager.getDeviceManager().disconnectSco();
         } else {
-            Log.i(this, "Clearing communication device for audio type %d.",
-                    pendingAudioRoute.getCommunicationDeviceType());
+            Log.i(this, "clearCommunicationDevice: AudioManager#clearCommunicationDevice, type=%s",
+                    DEVICE_TYPE_STRINGS.get(pendingAudioRoute.getCommunicationDeviceType()));
             audioManager.clearCommunicationDevice();
         }
 
diff --git a/src/com/android/server/telecom/CallAudioModeStateMachine.java b/src/com/android/server/telecom/CallAudioModeStateMachine.java
index 3c9c6ac..cd1d6a3 100644
--- a/src/com/android/server/telecom/CallAudioModeStateMachine.java
+++ b/src/com/android/server/telecom/CallAudioModeStateMachine.java
@@ -288,12 +288,14 @@
                             .getCurrentLocallyRequestedCommunicationDevice());
                 }
                 if (mFeatureFlags.setAudioModeBeforeAbandonFocus()) {
+                    Log.i(this, "enter: AudioManager#setMode(MODE_NORMAL)");
                     mAudioManager.setMode(AudioManager.MODE_NORMAL);
                     mCallAudioManager.setCallAudioRouteFocusState(
                             CallAudioRouteStateMachine.NO_FOCUS);
                 } else {
                     mCallAudioManager.setCallAudioRouteFocusState(
                             CallAudioRouteStateMachine.NO_FOCUS);
+                    Log.i(this, "enter: AudioManager#setMode(MODE_NORMAL)");
                     mAudioManager.setMode(AudioManager.MODE_NORMAL);
                 }
                 mLocalLog.log("Mode MODE_NORMAL");
@@ -347,11 +349,14 @@
                             + args.toString());
                     return HANDLED;
                 case AUDIO_OPERATIONS_COMPLETE:
-                    Log.i(LOG_TAG, "Abandoning audio focus: now UNFOCUSED");
                     if (mFeatureFlags.telecomResolveHiddenDependencies()) {
                         if (mCurrentAudioFocusRequest != null) {
+                            Log.i(this, "AudioOperationsComplete: "
+                                    + "AudioManager#abandonAudioFocusRequest(); now unfocused");
                             mAudioManager.abandonAudioFocusRequest(mCurrentAudioFocusRequest);
                             mCurrentAudioFocusRequest = null;
+                        } else {
+                            Log.i(this, "AudioOperationsComplete: already unfocused");
                         }
                     } else {
                         mAudioManager.abandonAudioFocusForCall();
@@ -377,6 +382,7 @@
             mLocalLog.log("Enter AUDIO_PROCESSING");
             if (mIsInitialized) {
                 mCallAudioManager.setCallAudioRouteFocusState(CallAudioRouteStateMachine.NO_FOCUS);
+                Log.i(this, "enter: AudioManager#setMode(MODE_AUDIO_PROCESSING)");
                 mAudioManager.setMode(NEW_AUDIO_MODE_FOR_AUDIO_PROCESSING);
                 mLocalLog.log("Mode MODE_CALL_SCREENING");
                 mMostRecentMode = NEW_AUDIO_MODE_FOR_AUDIO_PROCESSING;
@@ -431,7 +437,8 @@
                     transitionTo(mStreamingFocusState);
                     return HANDLED;
                 case AUDIO_OPERATIONS_COMPLETE:
-                    Log.i(LOG_TAG, "Abandoning audio focus: now AUDIO_PROCESSING");
+                    Log.i(LOG_TAG, "AudioManager#abandonAudioFocusRequest: now "
+                            + "AUDIO_PROCESSING");
                     if (mFeatureFlags.telecomResolveHiddenDependencies()) {
                         if (mCurrentAudioFocusRequest != null) {
                             mAudioManager.abandonAudioFocusRequest(mCurrentAudioFocusRequest);
@@ -466,6 +473,7 @@
                 if (mCallAudioManager.startRinging()) {
                     if (mFeatureFlags.telecomResolveHiddenDependencies()) {
                         mCurrentAudioFocusRequest = RING_AUDIO_FOCUS_REQUEST;
+                        Log.i(this, "tryStartRinging: AudioManager#requestAudioFocus(RING)");
                         mAudioManager.requestAudioFocus(RING_AUDIO_FOCUS_REQUEST);
                     } else {
                         mAudioManager.requestAudioFocusForCall(
@@ -474,6 +482,7 @@
                     // Do not set MODE_RINGTONE if we were previously in the CALL_SCREENING mode --
                     // this trips up the audio system.
                     if (mAudioManager.getMode() != AudioManager.MODE_CALL_SCREENING) {
+                        Log.i(this, "enter: AudioManager#setMode(MODE_RINGTONE)");
                         mAudioManager.setMode(AudioManager.MODE_RINGTONE);
                         mLocalLog.log("Mode MODE_RINGTONE");
                     }
@@ -569,11 +578,13 @@
             mLocalLog.log("Enter SIM_CALL");
             if (mFeatureFlags.telecomResolveHiddenDependencies()) {
                 mCurrentAudioFocusRequest = CALL_AUDIO_FOCUS_REQUEST;
+                Log.i(this, "enter: AudioManager#requestAudioFocus(CALL)");
                 mAudioManager.requestAudioFocus(CALL_AUDIO_FOCUS_REQUEST);
             } else {
                 mAudioManager.requestAudioFocusForCall(AudioManager.STREAM_VOICE_CALL,
                         AudioManager.AUDIOFOCUS_GAIN_TRANSIENT);
             }
+            Log.i(this, "enter: AudioManager#setMode(MODE_IN_CALL)");
             mAudioManager.setMode(AudioManager.MODE_IN_CALL);
             mLocalLog.log("Mode MODE_IN_CALL");
             mMostRecentMode = AudioManager.MODE_IN_CALL;
@@ -657,11 +668,13 @@
             mLocalLog.log("Enter VOIP_CALL");
             if (mFeatureFlags.telecomResolveHiddenDependencies()) {
                 mCurrentAudioFocusRequest = CALL_AUDIO_FOCUS_REQUEST;
+                Log.i(this, "enter: AudioManager#requestAudioFocus(CALL)");
                 mAudioManager.requestAudioFocus(CALL_AUDIO_FOCUS_REQUEST);
             } else {
                 mAudioManager.requestAudioFocusForCall(AudioManager.STREAM_VOICE_CALL,
                         AudioManager.AUDIOFOCUS_GAIN_TRANSIENT);
             }
+            Log.i(this, "enter: AudioManager#setMode(MODE_IN_COMMUNICATION)");
             mAudioManager.setMode(AudioManager.MODE_IN_COMMUNICATION);
             mLocalLog.log("Mode MODE_IN_COMMUNICATION");
             mMostRecentMode = AudioManager.MODE_IN_COMMUNICATION;
@@ -740,6 +753,7 @@
             Log.i(LOG_TAG, "Audio focus entering streaming state");
             mLocalLog.log("Enter Streaming");
             mLocalLog.log("Mode MODE_COMMUNICATION_REDIRECT");
+            Log.i(this, "enter: AudioManager#setMode(MODE_COMMUNICATION_REDIRECT");
             mAudioManager.setMode(AudioManager.MODE_COMMUNICATION_REDIRECT);
             mMostRecentMode = AudioManager.MODE_NORMAL;
             mCallAudioManager.setCallAudioRouteFocusState(CallAudioRouteStateMachine.ACTIVE_FOCUS);
@@ -817,11 +831,13 @@
             mLocalLog.log("Enter TONE/HOLDING");
             if (mFeatureFlags.telecomResolveHiddenDependencies()) {
                 mCurrentAudioFocusRequest = CALL_AUDIO_FOCUS_REQUEST;
+                Log.i(this, "enter: AudioManager#requestAudioFocus(CALL)");
                 mAudioManager.requestAudioFocus(CALL_AUDIO_FOCUS_REQUEST);
             } else {
                 mAudioManager.requestAudioFocusForCall(AudioManager.STREAM_VOICE_CALL,
                         AudioManager.AUDIOFOCUS_GAIN_TRANSIENT);
             }
+            Log.i(this, "enter: AudioManager#setMode(%d)", mMostRecentMode);
             mAudioManager.setMode(mMostRecentMode);
             mLocalLog.log("Mode " + mMostRecentMode);
             mCallAudioManager.setCallAudioRouteFocusStateForEndTone();
diff --git a/src/com/android/server/telecom/CallAudioRouteController.java b/src/com/android/server/telecom/CallAudioRouteController.java
index 5fb4a3a..d6ee722 100644
--- a/src/com/android/server/telecom/CallAudioRouteController.java
+++ b/src/com/android/server/telecom/CallAudioRouteController.java
@@ -789,6 +789,10 @@
         switch (focus) {
             case NO_FOCUS -> {
                 if (mIsActive) {
+                    // Notify the CallAudioModeStateMachine that audio operations are complete so
+                    // that we can relinquish audio focus.
+                    mCallAudioManager.notifyAudioOperationsComplete();
+
                     // Reset mute state after call ends.
                     handleMuteChanged(false);
                     // Route back to inactive route.
diff --git a/src/com/android/server/telecom/bluetooth/BluetoothDeviceManager.java b/src/com/android/server/telecom/bluetooth/BluetoothDeviceManager.java
index c6fd9ae..0f27dad 100644
--- a/src/com/android/server/telecom/bluetooth/BluetoothDeviceManager.java
+++ b/src/com/android/server/telecom/bluetooth/BluetoothDeviceManager.java
@@ -430,7 +430,8 @@
                 return mBluetoothHeadset;
             } catch (TimeoutException | InterruptedException | ExecutionException e) {
                 // ignore
-                Log.w(this, "Acquire BluetoothHeadset service failed due to: " + e);
+                Log.w(this, "getBluetoothHeadset: Acquire BluetoothHeadset service failed due to: "
+                        + e);
                 return null;
             }
         } else {
@@ -483,7 +484,7 @@
             LinkedHashMap<String, BluetoothDevice> targetDeviceMap;
             if (deviceType == DEVICE_TYPE_LE_AUDIO) {
                 if (mBluetoothLeAudioService == null) {
-                    Log.w(this, "LE audio service null when receiving device added broadcast");
+                    Log.w(this, "onDeviceConnected: LE audio service null");
                     return;
                 }
                 /* Check if group is known. */
@@ -497,7 +498,7 @@
                 targetDeviceMap = mLeAudioDevicesByAddress;
             } else if (deviceType == DEVICE_TYPE_HEARING_AID) {
                 if (mBluetoothHearingAid == null) {
-                    Log.w(this, "Hearing aid service null when receiving device added broadcast");
+                    Log.w(this, "onDeviceConnected: Hearing aid service null");
                     return;
                 }
                 long hiSyncId = mBluetoothHearingAid.getHiSyncId(device);
@@ -505,18 +506,18 @@
                 targetDeviceMap = mHearingAidDevicesByAddress;
             } else if (deviceType == DEVICE_TYPE_HEADSET) {
                 if (getBluetoothHeadset() == null) {
-                    Log.w(this, "Headset service null when receiving device added broadcast");
+                    Log.w(this, "onDeviceConnected: Headset service null");
                     return;
                 }
                 targetDeviceMap = mHfpDevicesByAddress;
             } else {
-                Log.w(this, "Device: " + device.getAddress() + " with invalid type: "
-                            + getDeviceTypeString(deviceType));
+                Log.w(this, "onDeviceConnected: Device: %s; invalid type %s", device.getAddress(),
+                        getDeviceTypeString(deviceType));
                 return;
             }
             if (!targetDeviceMap.containsKey(device.getAddress())) {
-                Log.i(this, "Adding device with address: " + device + " and devicetype="
-                        + getDeviceTypeString(deviceType));
+                Log.i(this, "onDeviceConnected: Adding device with address: %s and devicetype=%s",
+                        device, getDeviceTypeString(deviceType));
                 targetDeviceMap.put(device.getAddress(), device);
                 mBluetoothRouteManager.onDeviceAdded(device.getAddress());
             }
@@ -542,13 +543,13 @@
             } else if (deviceType == DEVICE_TYPE_HEADSET) {
                 targetDeviceMap = mHfpDevicesByAddress;
             } else {
-                Log.w(this, "Device: " + device.getAddress() + " with invalid type: "
-                            + getDeviceTypeString(deviceType));
+                Log.w(this, "onDeviceDisconnected: Device: %s with invalid type: %s",
+                        device.getAddress(), getDeviceTypeString(deviceType));
                 return;
             }
             if (targetDeviceMap.containsKey(device.getAddress())) {
-                Log.i(this, "Removing device with address: " + device + " and devicetype="
-                        + getDeviceTypeString(deviceType));
+                Log.i(this, "onDeviceDisconnected: Removing device with address: %s, devicetype=%s",
+                        device, getDeviceTypeString(deviceType));
                 targetDeviceMap.remove(device.getAddress());
                 mBluetoothRouteManager.onDeviceLost(device.getAddress());
             }
@@ -569,9 +570,10 @@
     public int disconnectSco() {
         int result = BluetoothStatusCodes.ERROR_UNKNOWN;
         if (getBluetoothHeadset() == null) {
-            Log.w(this, "Trying to disconnect audio but no headset service exists.");
+            Log.w(this, "disconnectSco: Trying to disconnect audio but no headset service exists.");
         } else {
             result = mBluetoothHeadset.disconnectAudio();
+            Log.i(this, "disconnectSco: BluetoothHeadset#disconnectAudio()=%b", result);
         }
         return result;
     }
@@ -605,6 +607,7 @@
         if (audioDeviceInfo != null && audioDeviceInfo.getType()
                 == AudioDeviceInfo.TYPE_BLE_HEADSET) {
             mBluetoothRouteManager.onAudioLost(audioDeviceInfo.getAddress());
+            Log.i(this, "clearLeAudioCommunicationDevice: audioManager#clearCommunicationDevice");
             mAudioManager.clearCommunicationDevice();
         }
     }
@@ -629,32 +632,33 @@
         AudioDeviceInfo audioDeviceInfo = mAudioManager.getCommunicationDevice();
         if (audioDeviceInfo != null && audioDeviceInfo.getType()
                 == AudioDeviceInfo.TYPE_HEARING_AID) {
+            Log.i(this, "clearHearingAidCommunicationDevice: "
+                    + "audioManager#clearCommunicationDevice");
             mAudioManager.clearCommunicationDevice();
         }
     }
 
     public boolean setLeAudioCommunicationDevice() {
-        Log.i(this, "setLeAudioCommunicationDevice");
-
         if (mLeAudioSetAsCommunicationDevice) {
-            Log.i(this, "setLeAudioCommunicationDevice already set");
+            Log.i(this, "setLeAudioCommunicationDevice: already set");
             return true;
         }
 
         if (mAudioManager == null) {
-            Log.w(this, " mAudioManager is null");
+            Log.w(this, "setLeAudioCommunicationDevice: mAudioManager is null");
             return false;
         }
 
         AudioDeviceInfo bleHeadset = null;
         List<AudioDeviceInfo> devices = mAudioManager.getAvailableCommunicationDevices();
         if (devices.size() == 0) {
-            Log.w(this, " No communication devices available.");
+            Log.w(this, "setLeAudioCommunicationDevice: No communication devices available.");
             return false;
         }
 
         for (AudioDeviceInfo device : devices) {
-            Log.i(this, " Available device type:  " + device.getType());
+            Log.d(this, "setLeAudioCommunicationDevice: Available device type:  "
+                    + device.getType());
             if (device.getType() == AudioDeviceInfo.TYPE_BLE_HEADSET) {
                 bleHeadset = device;
                 break;
@@ -662,7 +666,7 @@
         }
 
         if (bleHeadset == null) {
-            Log.w(this, " No bleHeadset device available");
+            Log.w(this, "setLeAudioCommunicationDevice: No bleHeadset device available");
             return false;
         }
 
@@ -672,9 +676,11 @@
         // Turn BLE_OUT_HEADSET ON.
         boolean result = mAudioManager.setCommunicationDevice(bleHeadset);
         if (!result) {
-            Log.w(this, " Could not set bleHeadset device");
+            Log.w(this, "setLeAudioCommunicationDevice: AudioManager#setCommunicationDevice(%s)=%b;"
+                    + " Could not set bleHeadset device", bleHeadset, result);
         } else {
-            Log.i(this, " bleHeadset device set");
+            Log.i(this, "setLeAudioCommunicationDevice: "
+                    + "AudioManager#setCommunicationDevice(%s)=%b", bleHeadset, result);
             mBluetoothRouteManager.onAudioOn(bleHeadset.getAddress());
             mLeAudioSetAsCommunicationDevice = true;
             mLeAudioDevice = bleHeadset.getAddress();
@@ -683,27 +689,26 @@
     }
 
     public boolean setHearingAidCommunicationDevice() {
-        Log.i(this, "setHearingAidCommunicationDevice");
-
         if (mHearingAidSetAsCommunicationDevice) {
-            Log.i(this, "mHearingAidSetAsCommunicationDevice already set");
+            Log.i(this, "setHearingAidCommunicationDevice: already set");
             return true;
         }
 
         if (mAudioManager == null) {
-            Log.w(this, " mAudioManager is null");
+            Log.w(this, "setHearingAidCommunicationDevice: mAudioManager is null");
             return false;
         }
 
         AudioDeviceInfo hearingAid = null;
         List<AudioDeviceInfo> devices = mAudioManager.getAvailableCommunicationDevices();
         if (devices.size() == 0) {
-            Log.w(this, " No communication devices available.");
+            Log.w(this, "setHearingAidCommunicationDevice: No communication devices available.");
             return false;
         }
 
         for (AudioDeviceInfo device : devices) {
-            Log.i(this, " Available device type:  " + device.getType());
+            Log.d(this, "setHearingAidCommunicationDevice: Available device type: "
+                    + device.getType());
             if (device.getType() == AudioDeviceInfo.TYPE_HEARING_AID) {
                 hearingAid = device;
                 break;
@@ -711,7 +716,7 @@
         }
 
         if (hearingAid == null) {
-            Log.w(this, " No hearingAid device available");
+            Log.w(this, "setHearingAidCommunicationDevice: No hearingAid device available");
             return false;
         }
 
@@ -721,9 +726,12 @@
         // Turn hearing aid ON.
         boolean result = mAudioManager.setCommunicationDevice(hearingAid);
         if (!result) {
-            Log.w(this, " Could not set hearingAid device");
+            Log.w(this, "setHearingAidCommunicationDevice: "
+                    + "AudioManager#setCommunicationDevice(%s)=%b; Could not set HA device",
+                    hearingAid, result);
         } else {
-            Log.i(this, " hearingAid device set");
+            Log.i(this, "setHearingAidCommunicationDevice: "
+                            + "AudioManager#setCommunicationDevice(%s)=%b", hearingAid, result);
             mHearingAidDevice = hearingAid.getAddress();
             mHearingAidSetAsCommunicationDevice = true;
         }
@@ -734,64 +742,77 @@
         AudioDeviceInfo deviceInfo = null;
         List<AudioDeviceInfo> devices = mAudioManager.getAvailableCommunicationDevices();
         if (devices.size() == 0) {
-            Log.w(this, " No communication devices available.");
+            Log.w(this, "setCommunicationDeviceForAddress: No communication devices available.");
             return false;
         }
 
         for (AudioDeviceInfo device : devices) {
-            Log.i(this, " Available device type:  " + device.getType());
+            Log.d(this, "setCommunicationDeviceForAddress: Available device type: "
+                    + device.getType());
             if (device.getAddress().equals(address)) {
                 deviceInfo = device;
                 break;
             }
         }
 
-        return deviceInfo != null && (mAudioManager.getCommunicationDevice().equals(deviceInfo)
-                || mAudioManager.setCommunicationDevice(deviceInfo));
+        if (deviceInfo == null) {
+            Log.w(this, "setCommunicationDeviceForAddress: Device %s not found.", address);
+            return false;
+        }
+        if (mAudioManager.getCommunicationDevice().equals(deviceInfo)) {
+            Log.i(this, "setCommunicationDeviceForAddress: Device %s already active.", address);
+            return true;
+        }
+        boolean success = mAudioManager.setCommunicationDevice(deviceInfo);
+        Log.i(this, "setCommunicationDeviceForAddress: "
+                + "AudioManager#setCommunicationDevice(%s)=%b", deviceInfo, success);
+        return success;
     }
 
     // Connect audio to the bluetooth device at address, checking to see whether it's
     // le audio, hearing aid or a HFP device, and using the proper BT API.
     public boolean connectAudio(String address, boolean switchingBtDevices) {
         int callProfile = BluetoothProfile.LE_AUDIO;
-        Log.i(this, "Telecomm connecting audio to device: " + address);
         BluetoothDevice device = null;
         if (mLeAudioDevicesByAddress.containsKey(address)) {
-            Log.i(this, "Telecomm found LE Audio device for address: " + address);
+            Log.i(this, "connectAudio: found LE Audio device for address: %s", address);
             if (mBluetoothLeAudioService == null) {
-                Log.w(this, "Attempting to turn on audio when the le audio service is null");
+                Log.w(this, "connectAudio: Attempting to turn on audio when the le audio service "
+                        + "is null");
                 return false;
             }
             device = mLeAudioDevicesByAddress.get(address);
             callProfile = BluetoothProfile.LE_AUDIO;
         } else if (mHearingAidDevicesByAddress.containsKey(address)) {
-            Log.i(this, "Telecomm found hearing aid device for address: " + address);
             if (mBluetoothHearingAid == null) {
-                Log.w(this, "Attempting to turn on audio when the hearing aid service is null");
+                Log.w(this, "connectAudio: Attempting to turn on audio when the hearing aid "
+                        + "service is null");
                 return false;
             }
+            Log.i(this, "connectAudio: found hearing aid device for address: %s", address);
             device = mHearingAidDevicesByAddress.get(address);
             callProfile = BluetoothProfile.HEARING_AID;
         } else if (mHfpDevicesByAddress.containsKey(address)) {
-            Log.i(this, "Telecomm found HFP device for address: " + address);
             if (getBluetoothHeadset() == null) {
-                Log.w(this, "Attempting to turn on audio when the headset service is null");
+                Log.w(this, "connectAudio: Attempting to turn on audio when the headset service "
+                        + "is null");
                 return false;
             }
+            Log.i(this, "connectAudio: found HFP device for address: %s", address);
             device = mHfpDevicesByAddress.get(address);
             callProfile = BluetoothProfile.HEADSET;
         }
 
         if (device == null) {
-            Log.w(this, "No active profiles for Bluetooth address=" + address);
+            Log.w(this, "No active profiles for Bluetooth address: %s", address);
             return false;
         }
 
         Bundle preferredAudioProfiles = mBluetoothAdapter.getPreferredAudioProfiles(device);
         if (preferredAudioProfiles != null && !preferredAudioProfiles.isEmpty()
             && preferredAudioProfiles.getInt(BluetoothAdapter.AUDIO_MODE_DUPLEX) != 0) {
-            Log.i(this, "Preferred duplex profile for device=" + address + " is "
-                + preferredAudioProfiles.getInt(BluetoothAdapter.AUDIO_MODE_DUPLEX));
+            Log.i(this, "connectAudio: Preferred duplex profile for device=% is %d", address,
+                preferredAudioProfiles.getInt(BluetoothAdapter.AUDIO_MODE_DUPLEX));
             callProfile = preferredAudioProfiles.getInt(BluetoothAdapter.AUDIO_MODE_DUPLEX);
         }
 
@@ -828,20 +849,24 @@
             boolean success = mBluetoothAdapter.setActiveDevice(device,
                 BluetoothAdapter.ACTIVE_DEVICE_PHONE_CALL);
             if (!success) {
-                Log.w(this, "Couldn't set active device to %s", address);
+                Log.w(this, "connectAudio: Couldn't set active device to %s", address);
                 return false;
             }
+            Log.i(this, "connectAudio: BluetoothAdapter#setActiveDevice(%s)", address);
             if (getBluetoothHeadset() != null) {
                 int scoConnectionRequest = mBluetoothHeadset.connectAudio();
+                Log.i(this, "connectAudio: BluetoothHeadset#connectAudio()=%d",
+                        scoConnectionRequest);
                 return scoConnectionRequest == BluetoothStatusCodes.SUCCESS ||
                         scoConnectionRequest
                                 == BluetoothStatusCodes.ERROR_AUDIO_DEVICE_ALREADY_CONNECTED;
             } else {
-                Log.w(this, "Couldn't find bluetooth headset service");
+                Log.w(this, "connectAudio: Couldn't find bluetooth headset service");
                 return false;
             }
         } else {
-            Log.w(this, "Attempting to turn on audio for a disconnected device");
+            Log.w(this, "connectAudio: Attempting to turn on audio for disconnected device %s",
+                    address);
             return false;
         }
     }
@@ -864,8 +889,8 @@
         Bundle preferredAudioProfiles = mBluetoothAdapter.getPreferredAudioProfiles(device);
         if (preferredAudioProfiles != null && !preferredAudioProfiles.isEmpty()
                 && preferredAudioProfiles.getInt(BluetoothAdapter.AUDIO_MODE_DUPLEX) != 0) {
-            Log.i(this, "Preferred duplex profile for device=" + address + " is "
-                    + preferredAudioProfiles.getInt(BluetoothAdapter.AUDIO_MODE_DUPLEX));
+            Log.i(this, "connectAudio: Preferred duplex profile for device=%s is %d", address,
+                    preferredAudioProfiles.getInt(BluetoothAdapter.AUDIO_MODE_DUPLEX));
             callProfile = preferredAudioProfiles.getInt(BluetoothAdapter.AUDIO_MODE_DUPLEX);
         }
 
@@ -876,20 +901,23 @@
             boolean success = mBluetoothAdapter.setActiveDevice(device,
                     BluetoothAdapter.ACTIVE_DEVICE_PHONE_CALL);
             if (!success) {
-                Log.w(this, "Couldn't set active device to %s", address);
+                Log.w(this, "connectAudio: Couldn't set active device to %s", address);
                 return false;
             }
             if (getBluetoothHeadset() != null) {
                 int scoConnectionRequest = mBluetoothHeadset.connectAudio();
+                Log.i(this, "connectaudio: BluetoothHeadset#connectAudio()=%d",
+                        scoConnectionRequest);
                 return scoConnectionRequest == BluetoothStatusCodes.SUCCESS ||
                         scoConnectionRequest
                                 == BluetoothStatusCodes.ERROR_AUDIO_DEVICE_ALREADY_CONNECTED;
             } else {
-                Log.w(this, "Couldn't find bluetooth headset service");
+                Log.w(this, "connectAudio: Couldn't find bluetooth headset service");
                 return false;
             }
         } else {
-            Log.w(this, "Attempting to turn on audio for a disconnected device");
+            Log.w(this, "connectAudio: Attempting to turn on audio for a disconnected device %s",
+                    address);
             return false;
         }
     }
@@ -909,6 +937,8 @@
         if (mBluetoothHearingAidActiveDeviceCache != null) {
             mBluetoothAdapter.setActiveDevice(mBluetoothHearingAidActiveDeviceCache,
                     BluetoothAdapter.ACTIVE_DEVICE_ALL);
+            Log.i(this, "restoreHearingAidDevice: BluetoothAdapter#setActiveDevice(%s)",
+                    mBluetoothHearingAidActiveDeviceCache.getAddress());
             mBluetoothHearingAidActiveDeviceCache = null;
         }
     }
@@ -921,7 +951,6 @@
     }
 
     public boolean isInbandRingEnabled(BluetoothDevice bluetoothDevice) {
-        Log.i(this, "isInbandRingEnabled: device: " + bluetoothDevice);
         if (mBluetoothRouteManager.isCachedLeAudioDevice(bluetoothDevice)) {
             if (mBluetoothLeAudioService == null) {
                 Log.i(this, "isInbandRingingEnabled: no leaudio service available.");
@@ -934,7 +963,10 @@
                 Log.i(this, "isInbandRingingEnabled: no headset service available.");
                 return false;
             }
-            return mBluetoothHeadset.isInbandRingingEnabled();
+            boolean isEnabled = mBluetoothHeadset.isInbandRingingEnabled();
+            Log.i(this, "isInbandRingEnabled: device: %s, isEnabled: %b", bluetoothDevice,
+                    isEnabled);
+            return isEnabled;
         }
     }
 
diff --git a/tests/src/com/android/server/telecom/tests/CallAudioRouteControllerTest.java b/tests/src/com/android/server/telecom/tests/CallAudioRouteControllerTest.java
index f8cc857..1ef72f5 100644
--- a/tests/src/com/android/server/telecom/tests/CallAudioRouteControllerTest.java
+++ b/tests/src/com/android/server/telecom/tests/CallAudioRouteControllerTest.java
@@ -59,6 +59,7 @@
 import android.bluetooth.BluetoothDevice;
 import android.bluetooth.BluetoothLeAudio;
 import android.media.AudioDeviceInfo;
+import android.media.AudioFocusRequest;
 import android.media.AudioManager;
 import android.media.IAudioService;
 import android.media.audiopolicy.AudioProductStrategy;
@@ -368,6 +369,11 @@
         assertTrue(mController.isActive());
 
         mController.sendMessageWithSessionInfo(SWITCH_FOCUS, NO_FOCUS, 0);
+        // Ensure we tell the CallAudioManager that audio operations are done so that we can ensure
+        // audio focus is relinquished.
+        verify(mCallAudioManager, timeout(TEST_TIMEOUT)).notifyAudioOperationsComplete();
+
+        // Ensure the BT device is disconnected.
         verify(mBluetoothDeviceManager, timeout(TEST_TIMEOUT).atLeastOnce()).disconnectSco();
         assertFalse(mController.isActive());
     }
@@ -613,6 +619,9 @@
                 anyInt(), anyString());
         verify(mCallsManager, timeout(TEST_TIMEOUT).atLeastOnce()).onCallAudioStateChanged(
                 any(CallAudioState.class), eq(expectedState));
+        // Ensure we tell the CallAudioManager that audio operations are done so that we can ensure
+        // audio focus is relinquished.
+        verify(mCallAudioManager, timeout(TEST_TIMEOUT)).notifyAudioOperationsComplete();
     }
 
     @SmallTest