No need to abort the audio HAL / Bluetooth when failed to suspend

When the headset was disconnecting, the audio HAL may not be able to
suspend the stream successfully, and it is no need to abort the process
for such acceptable failure. This change also adds extra log messages
about HIDL status.

Bug: 127654107
Test: Play / pause music via the Bluetooth manually
Change-Id: I335fcf75708343c7971ebd97514fea5db50f17a0

1 files changed, 67 insertions, 106 deletions

diff --git a/audio_bluetooth_hw/device_port_proxy.cc b/audio_bluetooth_hw/device_port_proxy.cc
index 5b484b8a4..c7bf457cb 100644
--- a/audio_bluetooth_hw/device_port_proxy.cc
+++ b/audio_bluetooth_hw/device_port_proxy.cc
@@ -31,6 +31,8 @@ namespace android {
 namespace bluetooth {
 namespace audio {
 
+using android::base::StringPrintf;
+
 using ::android::bluetooth::audio::BluetoothAudioSessionControl;
 using ::android::hardware::bluetooth::audio::V2_0::BitsPerSample;
 using ::android::hardware::bluetooth::audio::V2_0::ChannelMode;
@@ -109,12 +111,11 @@ bool BluetoothAudioPortOut::SetUp(audio_devices_t devices) {
   auto control_result_cb = [port = this](uint16_t cookie, bool start_resp,
                                          const BluetoothAudioStatus& status) {
     if (!port->in_use()) {
-      LOG(ERROR) << ": BluetoothAudioPortOut is not in use";
+      LOG(ERROR) << "control_result_cb: BluetoothAudioPortOut is not in use";
       return;
     }
     if (port->cookie_ != cookie) {
-      LOG(ERROR) << "control_result_cb: proxy of device port (cookie=0x"
-                 << android::base::StringPrintf("%04hx", cookie)
+      LOG(ERROR) << "control_result_cb: proxy of device port (cookie=0x" << StringPrintf("%04hx", cookie)
                  << ") is corrupted";
       return;
     }
@@ -122,12 +123,11 @@ bool BluetoothAudioPortOut::SetUp(audio_devices_t devices) {
   };
   auto session_changed_cb = [port = this](uint16_t cookie) {
     if (!port->in_use()) {
-      LOG(ERROR) << ": BluetoothAudioPortOut is not in use";
+      LOG(ERROR) << "session_changed_cb: BluetoothAudioPortOut is not in use";
       return;
     }
     if (port->cookie_ != cookie) {
-      LOG(ERROR) << "session_changed_cb: proxy of device port (cookie=0x"
-                 << android::base::StringPrintf("%04hx", cookie)
+      LOG(ERROR) << "session_changed_cb: proxy of device port (cookie=0x" << StringPrintf("%04hx", cookie)
                  << ") is corrupted";
       return;
     }
@@ -138,8 +138,8 @@ bool BluetoothAudioPortOut::SetUp(audio_devices_t devices) {
       .session_changed_cb_ = session_changed_cb};
   cookie_ = BluetoothAudioSessionControl::RegisterControlResultCback(
       session_type_, cbacks);
-  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_)
-            << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_);
+  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+            << StringPrintf("%04hx", cookie_);
 
   return (cookie_ != android::bluetooth::audio::kObserversCookieUndefined);
 }
@@ -149,29 +149,23 @@ bool BluetoothAudioPortOut::init_session_type(audio_devices_t device) {
     case AUDIO_DEVICE_OUT_BLUETOOTH_A2DP:
     case AUDIO_DEVICE_OUT_BLUETOOTH_A2DP_HEADPHONES:
     case AUDIO_DEVICE_OUT_BLUETOOTH_A2DP_SPEAKER:
-      LOG(VERBOSE)
-          << __func__
-          << "device=AUDIO_DEVICE_OUT_BLUETOOTH_A2DP (HEADPHONES/SPEAKER) (0x"
-          << android::base::StringPrintf("%08x", device) << ")";
+      LOG(VERBOSE) << __func__ << ": device=AUDIO_DEVICE_OUT_BLUETOOTH_A2DP (HEADPHONES/SPEAKER) (0x"
+                   << StringPrintf("%08x", device) << ")";
       session_type_ = SessionType::A2DP_SOFTWARE_ENCODING_DATAPATH;
       break;
     case AUDIO_DEVICE_OUT_HEARING_AID:
-      LOG(VERBOSE) << __func__
-                   << "device=AUDIO_DEVICE_OUT_HEARING_AID (MEDIA/VOICE) (0x"
-                   << android::base::StringPrintf("%08x", device) << ")";
+      LOG(VERBOSE) << __func__ << ": device=AUDIO_DEVICE_OUT_HEARING_AID (MEDIA/VOICE) (0x"
+                   << StringPrintf("%08x", device) << ")";
       session_type_ = SessionType::HEARING_AID_SOFTWARE_ENCODING_DATAPATH;
       break;
     default:
-      LOG(ERROR) << __func__ << "unknown device=0x"
-                 << android::base::StringPrintf("%08x", device);
+      LOG(ERROR) << __func__ << ": unknown device=0x" << StringPrintf("%08x", device);
       return false;
   }
 
   if (!BluetoothAudioSessionControl::IsSessionReady(session_type_)) {
-    LOG(ERROR) << __func__ << "device=0x"
-               << android::base::StringPrintf("%08x", device)
-               << ", session_type=" << toString(session_type_)
-               << " is not ready";
+    LOG(ERROR) << __func__ << ": device=0x" << StringPrintf("%08x", device)
+               << ", session_type=" << toString(session_type_) << " is not ready";
     return false;
   }
   return true;
@@ -179,14 +173,13 @@ bool BluetoothAudioPortOut::init_session_type(audio_devices_t device) {
 
 void BluetoothAudioPortOut::TearDown() {
   if (!in_use()) {
-    LOG(ERROR) << __func__ << ": session_type=" << toString(session_type_)
-               << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-               << " unknown monitor";
+    LOG(ERROR) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+               << StringPrintf("%04hx", cookie_) << " unknown monitor";
     return;
   }
 
-  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_)
-            << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_);
+  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+            << StringPrintf("%04hx", cookie_);
   BluetoothAudioSessionControl::UnregisterControlResultCback(session_type_,
                                                              cookie_);
   cookie_ = android::bluetooth::audio::kObserversCookieUndefined;
@@ -200,9 +193,8 @@ void BluetoothAudioPortOut::ControlResultHandler(
   }
   std::unique_lock<std::mutex> port_lock(cv_mutex_);
   BluetoothStreamState previous_state = state_;
-  LOG(INFO) << "control_result_cb: session_type=" << toString(session_type_)
-            << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-            << ", previous_state=" << previous_state
+  LOG(INFO) << "control_result_cb: session_type=" << toString(session_type_) << ", cookie=0x"
+            << StringPrintf("%04hx", cookie_) << ", previous_state=" << previous_state
             << ", status=" << toString(status);
 
   switch (previous_state) {
@@ -210,12 +202,10 @@ void BluetoothAudioPortOut::ControlResultHandler(
       if (status == BluetoothAudioStatus::SUCCESS) {
         state_ = BluetoothStreamState::STARTED;
       } else {
-        // Set to standby since the stack may be busy switching
-        LOG(ERROR) << "control_result_cb: status=" << toString(status)
-                   << " failure for session_type=" << toString(session_type_)
-                   << ", cookie=0x"
-                   << android::base::StringPrintf("%04hx", cookie_)
-                   << ", previous_state=" << previous_state;
+        // Set to standby since the stack may be busy switching between outputs
+        LOG(WARNING) << "control_result_cb: status=" << toString(status)
+                     << " failure for session_type=" << toString(session_type_) << ", cookie=0x"
+                     << StringPrintf("%04hx", cookie_) << ", previous_state=" << previous_state;
         state_ = BluetoothStreamState::STANDBY;
       }
       break;
@@ -223,20 +213,17 @@ void BluetoothAudioPortOut::ControlResultHandler(
       if (status == BluetoothAudioStatus::SUCCESS) {
         state_ = BluetoothStreamState::STANDBY;
       } else {
-        // This should never fail and we need to recover
-        LOG(FATAL) << "control_result_cb: status=" << toString(status)
-                   << " failure for session_type=" << toString(session_type_)
-                   << ", cookie=0x"
-                   << android::base::StringPrintf("%04hx", cookie_)
-                   << ", previous_state=" << previous_state;
+        // It will be failed if the headset is disconnecting, and set to disable
+        // to wait for re-init again
+        LOG(WARNING) << "control_result_cb: status=" << toString(status)
+                     << " failure for session_type=" << toString(session_type_) << ", cookie=0x"
+                     << StringPrintf("%04hx", cookie_) << ", previous_state=" << previous_state;
         state_ = BluetoothStreamState::DISABLED;
       }
       break;
     default:
       LOG(ERROR) << "control_result_cb: unexpected status=" << toString(status)
-                 << " for session_type=" << toString(session_type_)
-                 << ", cookie=0x"
-                 << android::base::StringPrintf("%04hx", cookie_)
+                 << " for session_type=" << toString(session_type_) << ", cookie=0x" << StringPrintf("%04hx", cookie_)
                  << ", previous_state=" << previous_state;
       return;
   }
@@ -251,9 +238,8 @@ void BluetoothAudioPortOut::SessionChangedHandler() {
   }
   std::unique_lock<std::mutex> port_lock(cv_mutex_);
   BluetoothStreamState previous_state = state_;
-  LOG(INFO) << "session_changed_cb: session_type=" << toString(session_type_)
-            << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-            << ", previous_state=" << previous_state;
+  LOG(INFO) << "session_changed_cb: session_type=" << toString(session_type_) << ", cookie=0x"
+            << StringPrintf("%04hx", cookie_) << ", previous_state=" << previous_state;
   if (previous_state != BluetoothStreamState::DISABLED) {
     state_ = BluetoothStreamState::DISABLED;
   } else {
@@ -286,10 +272,8 @@ bool BluetoothAudioPortOut::LoadAudioConfig(audio_config_t* audio_cfg) const {
     return false;
   }
   const PcmParameters& pcm_cfg = hal_audio_cfg.pcmConfig();
-  LOG(VERBOSE) << __func__ << ": session_type=" << toString(session_type_)
-               << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-               << ", state=" << state_ << ", PcmConfig=[" << toString(pcm_cfg)
-               << "]";
+  LOG(VERBOSE) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+               << StringPrintf("%04hx", cookie_) << ", state=" << state_ << ", PcmConfig=[" << toString(pcm_cfg) << "]";
   if (pcm_cfg.sampleRate == SampleRate::RATE_UNKNOWN ||
       pcm_cfg.channelMode == ChannelMode::UNKNOWN ||
       pcm_cfg.bitsPerSample == BitsPerSample::BITS_UNKNOWN) {
@@ -306,30 +290,24 @@ bool BluetoothAudioPortOut::CondwaitState(BluetoothStreamState state) {
   std::unique_lock<std::mutex> port_lock(cv_mutex_);
   switch (state) {
     case BluetoothStreamState::STARTING:
-      LOG(VERBOSE) << __func__ << ": session_type=" << toString(session_type_)
-                   << ", cookie=0x"
-                   << android::base::StringPrintf("%04hx", cookie_)
-                   << " waiting for STARTED";
+      LOG(VERBOSE) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+                   << StringPrintf("%04hx", cookie_) << " waiting for STARTED";
       retval = internal_cv_.wait_for(
           port_lock, std::chrono::milliseconds(kMaxWaitingTimeMs),
           [this] { return this->state_ != BluetoothStreamState::STARTING; });
       retval = retval && state_ == BluetoothStreamState::STARTED;
       break;
     case BluetoothStreamState::SUSPENDING:
-      LOG(VERBOSE) << __func__ << ": session_type=" << toString(session_type_)
-                   << ", cookie=0x"
-                   << android::base::StringPrintf("%04hx", cookie_)
-                   << " waiting for SUSPENDED";
+      LOG(VERBOSE) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+                   << StringPrintf("%04hx", cookie_) << " waiting for SUSPENDED";
       retval = internal_cv_.wait_for(
           port_lock, std::chrono::milliseconds(kMaxWaitingTimeMs),
           [this] { return this->state_ != BluetoothStreamState::SUSPENDING; });
       retval = retval && state_ == BluetoothStreamState::STANDBY;
       break;
     default:
-      LOG(WARNING) << __func__ << ": session_type=" << toString(session_type_)
-                   << ", cookie=0x"
-                   << android::base::StringPrintf("%04hx", cookie_)
-                   << " waiting for KNOWN";
+      LOG(WARNING) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+                   << StringPrintf("%04hx", cookie_) << " waiting for KNOWN";
       return false;
   }
 
@@ -342,30 +320,25 @@ bool BluetoothAudioPortOut::Start() {
     return false;
   }
 
-  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_)
-            << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-            << ", state=" << state_ << " request";
+  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+            << StringPrintf("%04hx", cookie_) << ", state=" << state_ << " request";
   bool retval = false;
   if (state_ == BluetoothStreamState::STANDBY) {
     state_ = BluetoothStreamState::STARTING;
     if (BluetoothAudioSessionControl::StartStream(session_type_)) {
       retval = CondwaitState(BluetoothStreamState::STARTING);
     } else {
-      LOG(ERROR) << __func__ << ": session_type=" << toString(session_type_)
-                 << ", cookie=0x"
-                 << android::base::StringPrintf("%04hx", cookie_)
-                 << ", state=" << state_ << " Hal fails";
+      LOG(ERROR) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+                 << StringPrintf("%04hx", cookie_) << ", state=" << state_ << " Hal fails";
     }
   }
 
   if (retval) {
-    LOG(INFO) << __func__ << ": session_type=" << toString(session_type_)
-              << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-              << ", state=" << state_ << " done";
+    LOG(INFO) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+              << StringPrintf("%04hx", cookie_) << ", state=" << state_ << " done";
   } else {
-    LOG(ERROR) << __func__ << ": session_type=" << toString(session_type_)
-               << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-               << ", state=" << state_ << " failure";
+    LOG(ERROR) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+               << StringPrintf("%04hx", cookie_) << ", state=" << state_ << " failure";
   }
 
   return retval;  // false if any failure like timeout
@@ -377,30 +350,25 @@ bool BluetoothAudioPortOut::Suspend() {
     return false;
   }
 
-  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_)
-            << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-            << ", state=" << state_ << " request";
+  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+            << StringPrintf("%04hx", cookie_) << ", state=" << state_ << " request";
   bool retval = false;
   if (state_ == BluetoothStreamState::STARTED) {
     state_ = BluetoothStreamState::SUSPENDING;
     if (BluetoothAudioSessionControl::SuspendStream(session_type_)) {
       retval = CondwaitState(BluetoothStreamState::SUSPENDING);
     } else {
-      LOG(ERROR) << __func__ << ": session_type=" << toString(session_type_)
-                 << ", cookie=0x"
-                 << android::base::StringPrintf("%04hx", cookie_)
-                 << ", state=" << state_ << " Hal fails";
+      LOG(ERROR) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+                 << StringPrintf("%04hx", cookie_) << ", state=" << state_ << " Hal fails";
     }
   }
 
   if (retval) {
-    LOG(INFO) << __func__ << ": session_type=" << toString(session_type_)
-              << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-              << ", state=" << state_ << " done";
+    LOG(INFO) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+              << StringPrintf("%04hx", cookie_) << ", state=" << state_ << " done";
   } else {
-    LOG(ERROR) << __func__ << ": session_type=" << toString(session_type_)
-               << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-               << ", state=" << state_ << " failure";
+    LOG(ERROR) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+               << StringPrintf("%04hx", cookie_) << ", state=" << state_ << " failure";
   }
 
   return retval;  // false if any failure like timeout
@@ -411,14 +379,12 @@ void BluetoothAudioPortOut::Stop() {
     LOG(ERROR) << __func__ << ": BluetoothAudioPortOut is not in use";
     return;
   }
-  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_)
-            << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-            << ", state=" << state_ << " request";
+  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+            << StringPrintf("%04hx", cookie_) << ", state=" << state_ << " request";
   state_ = BluetoothStreamState::DISABLED;
   BluetoothAudioSessionControl::StopStream(session_type_);
-  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_)
-            << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-            << ", state=" << state_ << " done";
+  LOG(INFO) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+            << StringPrintf("%04hx", cookie_) << ", state=" << state_ << " done";
 }
 
 size_t BluetoothAudioPortOut::WriteData(const void* buffer,
@@ -437,14 +403,10 @@ bool BluetoothAudioPortOut::GetPresentationPosition(uint64_t* delay_ns,
   }
   bool retval = BluetoothAudioSessionControl::GetPresentationPosition(
       session_type_, delay_ns, bytes, timestamp);
-  LOG(VERBOSE) << __func__ << ": session_type=0x"
-               << android::base::StringPrintf("%02hhx", session_type_)
-               << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-               << ", state=" << state_ << ", delay=" << *delay_ns
-               << "ns, data=" << *bytes
-               << " bytes, timestamp=" << timestamp->tv_sec << "."
-               << android::base::StringPrintf("%09ld", timestamp->tv_nsec)
-               << "s";
+  LOG(VERBOSE) << __func__ << ": session_type=0x" << StringPrintf("%02hhx", session_type_) << ", cookie=0x"
+               << StringPrintf("%04hx", cookie_) << ", state=" << state_ << ", delay=" << *delay_ns
+               << "ns, data=" << *bytes << " bytes, timestamp=" << timestamp->tv_sec << "."
+               << StringPrintf("%09ld", timestamp->tv_nsec) << "s";
 
   return retval;
 }
@@ -455,9 +417,8 @@ void BluetoothAudioPortOut::UpdateMetadata(
     LOG(ERROR) << __func__ << ": BluetoothAudioPortOut is not in use";
     return;
   }
-  LOG(DEBUG) << __func__ << ": session_type=" << toString(session_type_)
-             << ", cookie=0x" << android::base::StringPrintf("%04hx", cookie_)
-             << ", state=" << state_ << ", " << source_metadata->track_count
+  LOG(DEBUG) << __func__ << ": session_type=" << toString(session_type_) << ", cookie=0x"
+             << StringPrintf("%04hx", cookie_) << ", state=" << state_ << ", " << source_metadata->track_count
              << " track(s)";
   if (source_metadata->track_count == 0) return;
   BluetoothAudioSessionControl::UpdateTracksMetadata(session_type_,